[Solved] OpenWrt 18.06.5 on TP-Link TL-WR741N/ND v4 - Out Of Memory Crash

Installing and Using OpenWrt
1

Hi,

I'm running:
OpenWrt 18.06.5 r7897-9d401013fc / LuCI openwrt-18.06 branch (git-19.309.48729-bc17ef6)
on:
TP-Link TL-WR741N/ND v4 - Atheros AR9330 rev 1
and while troubleshooting some WiFi clients, with one LuCi session active, showing Status>Overview, and one SSH session on the router running logread -a, I got an OOM crash (apparently LuCi) and couldn't recover, had to power cycle the router.
It's a standard installation, no extra packages, just IPv6 disabled and a few (50) custom iptables rules added & saved.
On the same router, some 18.06.x ( x=2 ?) versions ago, I recall I wasn't able to save a port forwarding rule because the overlay was apparently full. It worked after restarting the router. It never happened with newer OpenWRT releases and the overlay usually has ~70kB free (it stays like that).
Here is the OOM I was able to capture on the SSH console:

Wed Dec 11 22:37:58 2019 daemon.err uhttpd[1176]: luci: accepted login on / for root from 192.168.1.10
Wed Dec 11 22:39:51 2019 daemon.notice netifd: Network device 'wlan0' link is down
Wed Dec 11 22:39:51 2019 daemon.notice netifd: Interface 'wifi' has link connectivity loss
Wed Dec 11 22:39:52 2019 daemon.notice netifd: Interface 'wifi' is now down
Wed Dec 11 22:39:52 2019 daemon.notice netifd: Interface 'wifi' is disabled
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.893819] odhcpd invoked oom-killer: gfp_mask=0x24201ca(GFP_HIGHUSER_MOVABLE|__GFP_COLD), nodemask=0, order=0, oom_score_adj=0
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.904172] CPU: 0 PID: 3613 Comm: odhcpd Not tainted 4.9.198 #0
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.910301] Stack : 80487522 00000034 00000000 00000001 00000000 00000000 00000000 00000000
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.918774]         00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.927281]         00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.935787]         00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.944296]         00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.952802]         ...
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.955407] Call Trace:
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.957858] [<8006ab8c>] 0x8006ab8c
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.961491] [<8006ab8c>] 0x8006ab8c
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.965155] [<8011713c>] 0x8011713c
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.968835] [<800dbd40>] 0x800dbd40
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.972427] [<800ebb2c>] 0x800ebb2c
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.976096] [<800dc604>] 0x800dc604
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.979722] [<800dfd04>] 0x800dfd04
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.983386] [<800da914>] 0x800da914
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.987035] [<800b4558>] 0x800b4558
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.990661] [<800fb218>] 0x800fb218
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.994312] [<800fe9c8>] 0x800fe9c8
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.997968] [<80159520>] 0x80159520
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.001627] [<80070ebc>] 0x80070ebc
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.005287] [<800a1014>] 0x800a1014
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.008885] [<8009d038>] 0x8009d038
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.012532] [<8009c85c>] 0x8009c85c
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.016202] [<803b00f0>] 0x803b00f0
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.019824] [<8015a99c>] 0x8015a99c
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.023472] [<80065ce0>] 0x80065ce0
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.027139]
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.028758] Mem-Info:
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.031226] active_anon:1474 inactive_anon:82 isolated_anon:0
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.031226]  active_file:159 inactive_file:200 isolated_file:0
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.031226]  unevictable:0 dirty:0 writeback:0 unstable:0
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.031226]  slab_reclaimable:162 slab_unreclaimable:2176
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.031226]  mapped:19 shmem:250 pagetables:106 bounce:0
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.031226]  free:255 free_pcp:0 free_cma:0
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.064049] Node 0 active_anon:5896kB inactive_anon:328kB active_file:636kB inactive_file:800kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:76kB dirty:0kB writeback:0kB shmem:1000kB writeback_tmp:0kB unstable:0kB pages_scanned:29976 all_unreclaimable? yes
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.088281] Normal free:1020kB min:1024kB low:1280kB high:1536kB active_anon:5896kB inactive_anon:328kB active_file:636kB inactive_file:800kB unevictable:0kB writepending:0kB present:32768kB managed:27828kB mlocked:0kB slab_reclaimable:648kB slab_unreclaimable:8704kB kernel_stack:448kB pagetables:424kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.119576] lowmem_reserve[]: 0 0
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.123032] Normal: 255*4kB (UE) 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1020kB
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.133970] 609 total pagecache pages
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.137813] 0 pages in swap cache
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.141266] Swap cache stats: add 0, delete 0, find 0/0
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.146656] Free swap  = 0kB
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.149680] Total swap = 0kB
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.152719] 8192 pages RAM
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.155599] 0 pages HighMem/MovableOnly
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334721.159575] 1235 pages reserved
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.162877] [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.171599] [  465]     0   465      298       18       4       0        0             0 ubusd
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.180349] [  466]     0   466      225       10       3       0        0             0 askfirst
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.189383] [  756]     0   756      321       48       4       0        0             0 logd
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.198064] [  775]     0   775      399       29       4       0        0             0 rpcd
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.206744] [ 1084]     0  1084      430       50       4       0        0             0 netifd
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.215598] [ 1176]     0  1176      334       32       4       0        0             0 uhttpd
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.224435] [ 1473]     0  1473      266       10       3       0        0             0 dropbear
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.233481] [ 3613]     0  3613      357       29       4       0        0             0 odhcpd
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.242336] [25647]   453 25647      329       24       4       0        0             0 dnsmasq
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.251276] [ 8751]     0  8751      303       34       4       0        0             0 pppd
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.259950] [ 8941]     0  8941      277       19       3       0        0             0 dropbear
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.268994] [ 8942]     0  8942      300       11       3       0        0             0 ash
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.277578] [ 8988]     0  8988      336       22       3       0        0             0 logread
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.286517] [ 9034]     0  9034      353       64       3       0        0             0 sh
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.295025] [ 9040]     0  9040      357       70       4       0        0             0 sh
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.303514] [ 9074]     0  9074      353       63       3       0        0             0 sh
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.312040] [ 9075]     0  9075      353       63       3       0        0             0 sh
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.320547] [ 9076]     0  9076      300       10       3       0        0             0 grep
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.329221] [ 9077]     0  9077      300       10       3       0        0             0 grep
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.337907] [ 9078]     0  9078      301       11       3       0        0             0 awk
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.346502] [ 9079]     0  9079      270       17       5       0        0             0 iw
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.355007] [ 9088]     0  9088      328       38       3       0        0             0 sh
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.363499] [ 9090]     0  9090      745      243       6       0        0             0 luci
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.372197] [ 9091]     0  9091      737      239       5       0        0             0 luci
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.380876] [ 9092]     0  9092      740      242       5       0        0             0 luci
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.389550] [ 9093]     0  9093      379       14       4       0        0             0 modprobe
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.398586] [ 9097]     0  9097      264        8       4       0        0             0 basename
Wed Dec 11 22:40:57 2019 kern.info kernel: [2334721.407612] [ 9098]     0  9098      740      242       5       0        0             0 luci
Wed Dec 11 22:40:57 2019 kern.err kernel: [2334721.416284] Out of memory: Kill process 9090 (luci) score 34 or sacrifice child
Wed Dec 11 22:40:57 2019 kern.err kernel: [2334721.423748] Killed process 9090 (luci) total-vm:2980kB, anon-rss:944kB, file-rss:28kB, shmem-rss:0kB
Wed Dec 11 22:42:10 2019 user.notice mac80211: Failed command: iw phy phy0 set antenna all all
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.708966] netifd invoked oom-killer: gfp_mask=0x24201ca(GFP_HIGHUSER_MOVABLE|__GFP_COLD), nodemask=0, order=0, oom_score_adj=0
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.719299] CPU: 0 PID: 1084 Comm: netifd Not tainted 4.9.198 #0
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.725445] Stack : 80487522 00000034 00000000 00000001 00000000 00000000 00000000 00000000
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.733913]         00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.742423]         00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.750928]         00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.759435]         00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.767942]         ...
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.770546] Call Trace:
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.772999] [<8006ab8c>] 0x8006ab8c
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.776648] [<8006ab8c>] 0x8006ab8c
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.780276] [<8011713c>] 0x8011713c
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.783974] [<800dbd40>] 0x800dbd40
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.787586] [<800ebb2c>] 0x800ebb2c
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.791215] [<800dc604>] 0x800dc604
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.794879] [<800dfd04>] 0x800dfd04
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.798560] [<800da914>] 0x800da914
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.802151] [<800b4558>] 0x800b4558
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.805835] [<800fb218>] 0x800fb218
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.809469] [<800fe9c8>] 0x800fe9c8
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.813087] [<80159520>] 0x80159520
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.816793] [<80070ebc>] 0x80070ebc
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.820394] [<8009d038>] 0x8009d038
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.824025] [<8009c85c>] 0x8009c85c
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.827691] [<8015a99c>] 0x8015a99c
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.831319] [<800b6cb8>] 0x800b6cb8
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.834982] [<80065ce0>] 0x80065ce0
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.838614]
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.840252] Mem-Info:
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.842719] active_anon:1414 inactive_anon:81 isolated_anon:0
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.842719]  active_file:175 inactive_file:227 isolated_file:0
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.842719]  unevictable:0 dirty:0 writeback:0 unstable:0
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.842719]  slab_reclaimable:165 slab_unreclaimable:2191
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.842719]  mapped:48 shmem:248 pagetables:98 bounce:0
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.842719]  free:255 free_pcp:0 free_cma:0
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.875459] Node 0 active_anon:5656kB inactive_anon:324kB active_file:700kB inactive_file:908kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:192kB dirty:0kB writeback:0kB shmem:992kB writeback_tmp:0kB unstable:0kB pages_scanned:30608 all_unreclaimable? yes
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.899689] Normal free:1020kB min:1024kB low:1280kB high:1536kB active_anon:5656kB inactive_anon:324kB active_file:700kB inactive_file:908kB unevictable:0kB writepending:0kB present:32768kB managed:27828kB mlocked:0kB slab_reclaimable:660kB slab_unreclaimable:8764kB kernel_stack:440kB pagetables:392kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.930982] lowmem_reserve[]: 0 0
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.934438] Normal: 255*4kB (UE) 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1020kB
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.945376] 650 total pagecache pages
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.949201] 0 pages in swap cache
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.952671] Swap cache stats: add 0, delete 0, find 0/0
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.958065] Free swap  = 0kB
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.961088] Total swap = 0kB
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.964126] 8192 pages RAM
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.967005] 0 pages HighMem/MovableOnly
Wed Dec 11 22:43:06 2019 kern.warn kernel: [2334846.970982] 1235 pages reserved
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334846.974284] [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334846.983007] [  465]     0   465      298       26       4       0        0             0 ubusd
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334846.991763] [  466]     0   466      225       10       3       0        0             0 askfirst
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.000790] [  756]     0   756      321       48       4       0        0             0 logd
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.009464] [  775]     0   775      399       29       4       0        0             0 rpcd
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.018150] [ 1084]     0  1084      430       55       4       0        0             0 netifd
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.027006] [ 1176]     0  1176      334       31       4       0        0             0 uhttpd
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.035859] [ 1473]     0  1473      266       10       3       0        0             0 dropbear
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.044888] [ 3613]     0  3613      357       38       4       0        0             0 odhcpd
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.053725] [25647]   453 25647      329       33       4       0        0             0 dnsmasq
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.062685] [ 8751]     0  8751      303       53       4       0        0             0 pppd
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.071364] [ 8941]     0  8941      277       20       3       0        0             0 dropbear
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.080384] [ 8942]     0  8942      300       11       3       0        0             0 ash
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.088994] [ 8988]     0  8988      336       22       3       0        0             0 logread
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.097926] [ 9034]     0  9034      356       68       3       0        0             0 sh
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.106432] [ 9040]     0  9040      366       79       4       0        0             0 sh
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.114940] [ 9179]     0  9179      310       21       3       0        0             0 sh
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.123429] [ 9188]     0  9188      398       22       3       0        0             0 hostapd
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.132387] [ 9190]     0  9190      312       23       3       0        0             0 sh
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.140895] [ 9197]     0  9197      725      254       5       0        0             0 luci
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.149568] [ 9198]     0  9198      722      222       4       0        0             0 luci
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.158255] [ 9199]     0  9199      725      237       4       0        0             0 luci
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.166937] [ 9200]     0  9200      335       39       4       0        0             0 ubus
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.175616] [ 9204]     0  9204      300       13       3       0        0             0 sed
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.184193] [ 9205]     0  9205      264       16       3       0        0             0 sysctl
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.193065] [ 9206]     0  9206      300       10       4       0        0             0 logger
Wed Dec 11 22:43:06 2019 kern.info kernel: [2334847.201920] [ 9207]     0  9207      264       19       3       0        0             0 dnsmasq
Wed Dec 11 22:43:06 2019 kern.err kernel: [2334847.210852] Out of memory: Kill process 9197 (luci) score 36 or sacrifice child
Wed Dec 11 22:43:06 2019 kern.err kernel: [2334847.218326] Killed process 9197 (luci) total-vm:2900kB, anon-rss:876kB, file-rss:140kB, shmem-rss:0kB
Wed Dec 11 22:43:09 2019 daemon.info dnsmasq[25647]: exiting on receipt of SIGTERM
Wed Dec 11 22:43:10 2019 daemon.info procd: Instance dnsmasq::cfg01411c pid 25647 not stopped on SIGTERM, sending SIGKILL instead
Wed Dec 11 22:43:12 2019 daemon.err hostapd: Configuration file: /var/run/hostapd-phy0.conf
Wed Dec 11 22:43:26 2019 daemon.info dnsmasq[9211]: started, version 2.80 cachesize 150
Wed Dec 11 22:43:26 2019 daemon.info dnsmasq[9211]: compile time options: IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP no-DHCPv6 no-Lua TFTP no-conntrack no-ipset no-auth no-DNSSEC no-ID loop-detect inotify dumpfile

I suspected the log file could have been the cause for the OOM, there were some frequent provider issues recently with the PPPoE connection I use - constantly disconnecting - log records about it, and spent some time checking where/how it gets saved. Failed so far to understand anything (absolutely no clue what memory it uses, where is it stored (if any log file exists), etc.) about it from the following links:
https://openwrt.org/docs/guide-user/base-system/log.essentials
https://openwrt.org/docs/guide-user/perf_and_log/log.messages
Actually, the only detail I could understand and verify is that the logd is launched with the option -S 64 and that there was a logd bug, not respecting the defined size limit, that was resolved (hopefully).
https://dev.archive.openwrt.org/ticket/14227.html

Some system details that could be of interest, captured after the reboot:

# ps w
  PID USER       VSZ STAT COMMAND
    1 root      1548 S    /sbin/procd
    2 root         0 SW   [kthreadd]
    3 root         0 SW   [ksoftirqd/0]
    5 root         0 SW<  [kworker/0:0H]
    7 root         0 SW<  [lru-add-drain]
    8 root         0 SW   [kworker/u2:1]
   76 root         0 SW   [oom_reaper]
   77 root         0 SW<  [writeback]
   79 root         0 SW   [kcompactd0]
   80 root         0 SW<  [crypto]
   81 root         0 SW<  [bioset]
   83 root         0 SW<  [kblockd]
   98 root         0 SW<  [watchdogd]
  111 root         0 SW   [kworker/0:1]
  118 root         0 SW   [kswapd0]
  178 root         0 SW   [spi0]
  214 root         0 SW<  [bioset]
  220 root         0 SW<  [bioset]
  226 root         0 SW<  [bioset]
  231 root         0 SW<  [bioset]
  237 root         0 SW<  [bioset]
  243 root         0 SW<  [bioset]
  331 root         0 SW<  [ipv6_addrconf]
  339 root         0 SW<  [kworker/0:1H]
  402 root         0 SWN  [jffs2_gcd_mtd3]
  464 root      1188 S    /sbin/ubusd
  465 root       900 S    /sbin/askfirst /bin/ash --login
  531 root         0 SW<  [cfg80211]
  659 root      1224 S    /sbin/logd -S 64
  678 root      1528 S    /sbin/rpcd
  987 root      1720 S    /sbin/netifd
 1024 root      1420 S    /usr/sbin/odhcpd
 1079 root      1336 S    /usr/sbin/uhttpd -f -h /www -r wrt -x /cgi-bin -t 60 -T 30 -A 1 -n 3 -R -p 0.0.0.0:80
 1347 root      1064 S    /usr/sbin/dropbear -F -P /var/run/dropbear.1.pid -p 192.168.1.1:22 -K 300 -T 3
 1478 root      1708 S    /usr/sbin/hostapd -s -P /var/run/wifi-phy0.pid -B /var/run/hostapd-phy0.conf
 1702 dnsmasq   1316 S    /usr/sbin/dnsmasq -C /var/etc/dnsmasq.conf.cfg01411c -k -x /var/run/dnsmasq/dnsmasq.cfg01411c.pid
 2235 root         0 SW   [kworker/0:0]
 2571 root      1212 S    /usr/sbin/pppd nodetach ipparam wan ifname pppoe-wan lcp-echo-interval 1 lcp-echo-failure 5 lcp-echo-adap
 2608 root         0 SW   [kworker/u2:0]
 3803 root      1108 S    /usr/sbin/dropbear -F -P /var/run/dropbear.1.pid -p 192.168.1.1:22 -K 300 -T 3
 3804 root      1208 S    -ash
 3834 root      1200 R    ps w

 # df -hT
Filesystem           Type            Size      Used Available Use% Mounted on
/dev/root            squashfs        2.3M      2.3M         0 100% /rom
tmpfs                tmpfs          13.6M    452.0K     13.1M   3% /tmp
/dev/mtdblock3       jffs2         320.0K    248.0K     72.0K  78% /overlay
overlayfs:/overlay   overlay       320.0K    248.0K     72.0K  78% /
tmpfs                tmpfs         512.0K         0    512.0K   0% /dev

# du -s -h /tmp/
452.0K  /tmp/

# free -h
             total       used       free     shared    buffers     cached
Mem:         27828      21704       6124        452       2232       6808
-/+ buffers/cache:      12664      15164
Swap:            0          0          0

Any help appreciated.

Thanks!

Note:
I know it's an obsolete 4/32 router and I'm constantly looking to upgrade it with some 8/64 or even 16/128. The problem is, there are no such OpenWRT compatible routers available and for instance TP-Link, the ones that are "abundantly" present, are releasing weird and incompatible new routers constantly (like A5, A7Archer ... instead of C5 C7). I'd like to add that I'm looking for routers in the price range of 50-80 EUR, over that I rather buy an x86 system and turn it myself into a router/GW with a full-fledged Linux.

2

Disabling LuCI and uhttpd will likely decrease the memory load.

I have seen some evidence that just having the page open measurably reduces throughput on an Archer C7v2. I haven't quantified that.

2 Likes
3

Thanks for your reply.

I can confirm that having a LuCi session active (open in a browser window) will definitely reduce throughput on this router, especially when watching the Realtime Graphs and I can estimate the overhead/impact at ~20%-30%

I never had any issues with the memory load for LuCi until now, actually never had any memory issues at all on OpenWRT and I'm not sure I should blame LuCi for the OOM. Unfortunately, I'm not able to reproduce the issue and have no info about the state of the mem usage before the OOM occurred. Still suspecting the LOG, but as already mentioned, I have no clue about it ( where is it cached/stored) and unable to monitor its size.
Disabling LuCi might be an option, but then, LuCi is the reason I use OpenWRT, it makes life way more easier. CLI commands I hate (too many, hard to remember and limited to the implementation), I rather do it "The Linux Way" with shell commands, conf files and updating/restarting the services/processes on my own, but for that I'll need a full-fledged Linux...

4

By default, the log is managed in a ring buffer in memory. I believe the default is 64 kB. When the log gets "long", it starts dropping the earliest entries.

I understand the desire for LuCI. Perhaps a compromise would be to disable it (which I think you can do through the GUI), then enable it when you need it with, I believe

/etc/init.d/uhttpd enable
/etc/init.d/uhttpd start
2 Likes
5

Thanks again!

Will keep on monitoring the system and if I'll get "lucky" again with an OOM, maybe I'll be also able to learn how to reproduce it.
Meanwhile, just looking again over the OOM log I provided in my OP, found out that the WiFi connection went south first (why? didn't touch its settings) and then odhcpd crashed.

Wed Dec 11 22:37:58 2019 daemon.err uhttpd[1176]: luci: accepted login on / for root from 192.168.1.10
Wed Dec 11 22:39:51 2019 daemon.notice netifd: Network device 'wlan0' link is down
Wed Dec 11 22:39:51 2019 daemon.notice netifd: Interface 'wifi' has link connectivity loss
Wed Dec 11 22:39:52 2019 daemon.notice netifd: Interface 'wifi' is now down
Wed Dec 11 22:39:52 2019 daemon.notice netifd: Interface 'wifi' is disabled
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.893819] odhcpd invoked oom-killer: gfp_mask=0x24201ca(GFP_HIGHUSER_MOVABLE|__GFP_COLD), nodemask=0, order=0, oom_score_adj=0
Wed Dec 11 22:40:57 2019 kern.warn kernel: [2334720.904172] CPU: 0 PID: 3613 Comm: odhcpd Not tainted 4.9.198 #0
6

OOM is never a graceful thing, in my experience. Totally guessing as to a possible scenario, the kernel might have gotten a memory-allocation request from the wireless that it couldn’t fulfill, the wireless dealt with it by dropping the link, then LuCI piled on and the kernel killed odhcpd to try to stay alive.

1 Like
7

These will "drop in" upgrade to a 64 MB RAM chip-- tricky soldering but no other hardware changes needed. The ar71xx builds will use the extra RAM directly but I don't know about ath79.

1 Like
8

@jeff
I was troubleshooting a failed WiFi connection on a Raspberry Pi, it didn't want to authenticate and receive the IP configuration from OpenWRT. In the meantime I was checking if OpenWRT is sane with an Android phone (repeatedly connecting/disconnecting on WiFi). During this I was monitoring the LuCI webpage Status>Overview, waiting for the Raspberry Pi Wifi interface to pop up and went on and opened a SSH session to do tail de log (logread -f) internally on OpenWRT.
Back to the LuCI page, still playing around with the Android a few times on WiFi, until also the Android didn't want to connect anymore. It's then i noticed the OOM in the SSH console.
OpenWRT was still running, I had internet on my desktop (the system I worked on), but I couldn't control the OpenWRT anymore (LuCI crashed and the SSH console froze). I observed the LEDs on the OpenWRT router blinking very slow and considered to power-cycle it.
Usually I'm doing the easy stuff through LuCI and only when trying some more advanced config I open SSH. Now I had both open, eating extra RAM and maybe that triggered the OOM. I'll try to reproduce it when I have some more time, but I can live with only one "config interface" (LuCI or SSH) and never both :slight_smile:

@mk24
I have no problems with soldering a new RAM chip, I had that in mind and also upgrading the flash chip, but couldn't find compatible chips. When I first got this router, some years ago, loaded OpenWRT 15 on it, and also exposed the USB pins on the Atheros SoC, only to learn that I'll need to rebuild the OpenWRT image. I now already own 4 such TL-WR741N second-hand routers and very happy with them, a pity that they won't be able to run the upcoming OpenWRT 19 and I'll have to retire them. Frankly, I don't need more than 100Mbit on the WAN. Currently I have a FTTH connection, gigabit capable, on basic rate, limited at 100M and I don't plan to upgrade it. The costs for 1Gbit are 6x what I pay now and the real speed 300-500Mbps. Doesn't make any sense.

...
I might start using the Raspberry boards I own (a bunch) for OpenWRT, connected to a dumb switch, don't really need VLAN functionality. But that's a subject for another thread, asking to compile the usual USB Ethernet & WiFi drivers in the OpenWRT image by default.

9

This topic was automatically closed 10 days after the last reply. New replies are no longer allowed.