RUT-240 waking the oom-killer due ot memory exhaustion?

lmvlmv · October 5, 2023, 3:26pm

Hi,

I have a RUT240 that has a 4g conection and is running some basic failover and local DHCP.
I had some previous issues with the router apprently “hanging” and rebooting for no reason, so moved the logs to write to the storage rather than memory.

DUring a possible failure I managed to log in to the router and found the load up at around 17. logread -f showed the kernel out of memeory killer (see below).

What could cause this kind of memory pressure? This router is doing nothing out of the ordinary…

Leon

OOM log:

Thu Oct 5 16:18:54 2023 daemon.notice hostapd: nl80211: nl80211_recv_beacons->nl_recvmsgs failed: -5
Thu Oct 5 16:18:55 2023 daemon.notice wpa_supplicant[1811]: wlan0: CTRL-EVENT-BEACON-LOSS
Thu Oct 5 16:18:55 2023 daemon.notice wpa_supplicant[1811]: nl80211: wpa_driver_nl80211_event_receive->nl_recvmsgs failed: -5
Thu Oct 5 16:19:07 2023 user.info mwan3track[19246]: Check (ping) success for target “8.8.4.4” on interface mob1s1a1 (wwan0). Current score: 0
Thu Oct 5 16:19:09 2023 user.notice mwan3track[19246]: Interface mob1s1a1 (wwan0) is connecting
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173853.988455] sh invoked oom-killer: gfp_mask=0x400dc0(GFP_KERNEL_ACCOUNT|__GFP_ZERO), order=1, oom_score_adj=0
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173853.997782] CPU: 0 PID: 7492 Comm: sh Not tainted 5.4.229 #0
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.002920] Stack : 804b82c4 804b82a4 804b78d4 810d1c64 00000000 00000000 00000000 00000000
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.012209] 00000000 00000000 00000000 00000000 00000000 00000001 810d1c18 d29290db
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.019611] 810d1cb0 00000000 00000000 00000000 00000038 804482e4 342e3232 39202330
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.029534] 20436f6d 00000000 00000001 6d3a2073 80000000 810d1dec 827032e0 804f3e98
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.039695] 7fffffff 804f3d30 ffffffff 80000000 00000000 d29290db 00000000 80640000
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.047169] …
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.050166] Call Trace:
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.050213] [<804482e4>] 0x804482e4
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.056805] [<80068d98>] 0x80068d98
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.058928] [<80068da0>] 0x80068da0
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.062757] [<800f6edc>] 0x800f6edc
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.067252] [<800f7340>] 0x800f7340
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.069698] [<800f7b2c>] 0x800f7b2c
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.073221] [<8010e16c>] 0x8010e16c
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.076755] [<80125d04>] 0x80125d04
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.081043] [<8012a4bc>] 0x8012a4bc
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.083995] [<8007b0f8>] 0x8007b0f8
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.088028] [<80085a5c>] 0x80085a5c
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.091120] [<80086cac>] 0x80086cac
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.094547] [<8007bf78>] 0x8007bf78
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.099768] [<80087cc4>] 0x80087cc4
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.102741] [<8007c15c>] 0x8007c15c
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.106581] [<8006cd4c>] 0x8006cd4c
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.109103] [<8007f500>] 0x8007f500
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.113427]
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.114130] Mem-Info:
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.117365] active_anon:4508 inactive_anon:49 isolated_anon:0
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.117365] active_file:363 inactive_file:352 isolated_file:43
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.117365] unevictable:0 dirty:0 writeback:0 unstable:0
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.117365] slab_reclaimable:414 slab_unreclaimable:2367
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.117365] mapped:309 shmem:92 pagetables:327 bounce:0
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.117365] free:1934 free_pcp:16 free_cma:0
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.151598] Node 0 active_anon:18032kB inactive_anon:196kB active_file:1452kB inactive_file:1408kB unevictable:0kB isolated(anon):0kB isolated(file):172kB mapped:1236kB dirty:0kB writeback:0kB shmem:368kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.175509] Normal free:7820kB min:6656kB low:7168kB high:7680kB active_anon:18032kB inactive_anon:196kB active_file:1452kB inactive_file:1408kB unevictable:0kB writepending:0kB present:65536kB managed:59908kB mlocked:0kB kernel_stack:944kB pagetables:1308kB bounce:0kB free_pcp:64kB local_pcp:64kB free_cma:0kB
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.203797] lowmem_reserve: 0 0
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.205856] Normal: 2724kB (UMH) 2488kB (UMH) 23716kB (UEH) 2632kB (UH) 264kB (UH) 0128kB 0256kB 0512kB 01024kB 02048kB 0*4096kB = 7824kB
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.220742] 834 total pagecache pages
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.223325] 16384 pages RAM
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.226067] 0 pages HighMem/MovableOnly
Thu Oct 5 16:20:06 2023 kern.warn kernel: [173854.230620] 1407 pages reserved
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.233788] Tasks state (memory values in pages):
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.237871] [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.247999] [ 636] 81 636 335 54 16384 0 0 ubusd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.255677] [ 637] 0 637 238 13 16384 0 0 askfirst
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.265078] [ 671] 0 671 264 17 16384 0 0 urngd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.272692] [ 1459] 514 1459 611 77 20480 0 0 logd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.280286] [ 1460] 0 1460 592 34 16384 0 0 logread
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.289452] [ 1461] 0 1461 673 116 20480 0 0 logread
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.298067] [ 1592] 0 1592 459 106 20480 0 0 netifd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.306533] [ 1810] 0 1810 1146 131 24576 0 0 hostapd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.313762] [ 1811] 0 1811 1136 100 20480 0 0 wpa_supplicant
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.324897] [ 1866] 0 1866 1069 145 28672 0 0 rpcd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.332016] [ 1924] 0 1924 528 51 16384 0 0 gsmd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.340700] [ 1980] 0 1980 554 41 16384 0 0 modem_trackd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.350136] [ 2148] 0 2148 858 59 20480 0 0 mobifd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.358139] [ 2224] 0 2224 1425 392 24576 0 0 uhttpd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.366606] [ 2279] 0 2279 763 211 20480 0 0 vuci
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.386569] [ 2346] 0 2346 375 23 16384 0 0 dropbear
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.394867] [ 2413] 0 2413 446 119 16384 0 0 event_server
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.403901] [ 2484] 0 2484 412 135 16384 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.412498] [ 2518] 0 2518 412 20 16384 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.420315] [ 3238] 0 3238 439 81 20480 0 0 port_eventsd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.428016] [ 3345] 453 3345 352 124 16384 0 0 dnsmasq
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.437062] [ 3357] 0 3357 344 27 16384 0 0 dnsmasq
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.445716] [ 3472] 0 3472 371 55 24576 0 0 odhcpd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.453174] [ 3583] 0 3583 481 49 16384 0 0 ip_blockd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.464305] [ 4381] 0 4381 385 27 16384 0 0 iomand
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.472392] [ 5300] 0 5300 959 108 24576 0 0 mdcollectd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.480588] [ 5665] 0 5665 575 54 12288 0 0 ledman
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.489074] [ 7576] 0 7576 918 55 24576 0 0 quota_limit
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.499800] [ 7673] 0 7673 1173 83 24576 0 0 rms_mqtt
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.510955] [ 19246] 0 19246 459 71 20480 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.518627] [ 19247] 0 19247 457 180 20480 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.526310] [ 19248] 0 19248 457 69 20480 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.535047] [ 19249] 0 19249 484 95 16384 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.541693] [ 19250] 0 19250 485 96 20480 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.550384] [ 19402] 0 19402 471 34 20480 0 0 ip
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.560004] [ 19403] 0 19403 488 98 20480 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.568476] [ 19411] 0 19411 471 34 16384 0 0 ip
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.575941] [ 19412] 0 19412 492 100 16384 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.584498] [ 6087] 0 6087 270 18 16384 0 0 odhcp6c
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.592799] [ 13298] 0 13298 412 22 12288 0 0 udhcpc
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.602123] [ 21847] 0 21847 413 24 12288 0 0 crond
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.609453] [ 25117] 0 25117 412 22 16384 0 0 sleep
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.618139] [ 26306] 0 26306 412 22 12288 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.626036] [ 26334] 0 26334 412 22 16384 0 0 udhcpc
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.634577] [ 31721] 0 31721 498 33 20480 0 0 ntpclient
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.643569] [ 32106] 0 32106 1147 77 24576 0 0 mqtt_pub
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.651309] [ 5666] 0 5666 398 29 20480 0 0 dropbear
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.660180] [ 5824] 0 5824 412 22 16384 0 0 ash
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.668395] [ 6270] 0 6270 522 101 20480 0 0 subscribe.lua
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.676769] [ 6502] 0 6502 2021 819 24576 0 0 uhttpd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.686502] [ 7147] 0 7147 1603 474 24576 0 0 uhttpd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.693935] [ 7149] 0 7149 1803 380 24576 0 0 uhttpd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.703043] [ 7320] 0 7320 592 34 16384 0 0 logread
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.711625] [ 7476] 0 7476 423 33 20480 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.719327] [ 7492] 0 7492 478 204 20480 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.728301] [ 7498] 0 7498 412 22 12288 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.735386] [ 7512] 0 7512 412 19 12288 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.744158] [ 7516] 0 7516 436 46 16384 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.752321] [ 7519] 0 7519 412 21 16384 0 0 grep
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.759185] [ 7520] 0 7520 412 22 16384 0 0 awk
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.768727] [ 7524] 0 7524 412 22 16384 0 0 tr
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.776670] [ 7530] 0 7530 413 143 12288 0 0 sleep
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.784580] [ 7531] 0 7531 412 157 12288 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.792540] [ 7532] 0 7532 412 138 16384 0 0 ls
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.799667] [ 7533] 0 7533 412 161 16384 0 0 sleep
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.808777] [ 7564] 0 7564 376 117 16384 0 0 multiple_ap.sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.817709] [ 7565] 0 7565 412 129 16384 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.824845] [ 7566] 0 7566 457 174 20480 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.834063] [ 7567] 0 7567 289 107 16384 0 0 ping
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.841766] [ 7568] 0 7568 412 139 12288 0 0 df
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.850041] [ 7569] 0 7569 288 3 16384 0 0 grep
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.858026] [ 7570] 0 7570 1425 434 24576 0 0 uhttpd
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.866026] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),task=uhttpd,pid=6502,uid=0
Thu Oct 5 16:20:06 2023 kern.err kernel: [173854.874815] Out of memory: Killed process 6502 (uhttpd) total-vm:8084kB, anon-rss:3244kB, file-rss:28kB, shmem-rss:4kB, UID:0 pgtables:24kB oom_score_adj:0

Daumantas · October 6, 2023, 6:31am

Hello,

Do you by any chance have any custom scripts running on the device?
It seems like the following processes use the most RAM of the device:

Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.510955] [ 19246] 0 19246 459 71 20480 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.518627] [ 19247] 0 19247 457 180 20480 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.526310] [ 19248] 0 19248 457 69 20480 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.535047] [ 19249] 0 19249 484 95 16384 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.541693] [ 19250] 0 19250 485 96 20480 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.550384] [ 19402] 0 19402 471 34 20480 0 0 ip
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.560004] [ 19403] 0 19403 488 98 20480 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.568476] [ 19411] 0 19411 471 34 16384 0 0 ip
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.575941] [ 19412] 0 19412 492 100 16384 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.584498] [ 6087] 0 6087 270 18 16384 0 0 odhcp6c
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.592799] [ 13298] 0 13298 412 22 12288 0 0 udhcpc
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.602123] [ 21847] 0 21847 413 24 12288 0 0 crond
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.609453] [ 25117] 0 25117 412 22 16384 0 0 sleep
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.618139] [ 26306] 0 26306 412 22 12288 0 0 sh
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.626036] [ 26334] 0 26334 412 22 16384 0 0 udhcpc
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.634577] [ 31721] 0 31721 498 33 20480 0 0 ntpclient
Thu Oct 5 16:20:06 2023 kern.info kernel: [173854.643569] [ 32106] 0 32106 1147 77 24576 0 0 mqtt_pub

I’m not certain what the sh “services” are, but if you’re using any custom scripts, I’d suggest reviewing them if there are no issues. Other than that, I’d suggest updating the firmware to the latest, factory resetting the device, reconfiguring it, and checking if the issue reoccurs.
I’d also suggest disabling processes that are not being used. For example, I/O and MQTT Publisher are enabled.
Logging to the flash memory should not be needed, as it will decrease the lifetime of the Flash memory, and the logs do not take up much space.
Let me know how it goes.

Best regards,

lmvlmv · October 6, 2023, 7:56am

Logging to desk was enabled to try to see why the router was rebooting. Now we’re fairly sure it something memory related (I presume the oom killer eventually kills something critical and triggers a reboot/panic) I’ll turn that off.

mqtt is now disabled.

No custom scripts configured. A ps shows what I guess is normal system activity for sh

 2541 root      1648 S    /bin/sh /usr/sbin/log_rotation.sh -l /usr/var/log/messages -m / -t 24 -s 256000
 3139 root      1828 S    /bin/sh /usr/sbin/mwan3track mob1s1a1
 3140 root      1828 S    /bin/sh /usr/sbin/mwan3track OrchardNetBak
 3141 root      1824 S    /bin/sh /usr/sbin/mwan3track wan
 3142 root      1924 S    /bin/sh /usr/sbin/mwan3rtmon ipv4
 3143 root      1924 S    /bin/sh /usr/sbin/mwan3rtmon ipv6
 3339 root      1960 S    /bin/sh /usr/sbin/mwan3rtmon ipv4
 3349 root      1944 S    /bin/sh /usr/sbin/mwan3rtmon ipv6
 4966 root      1648 S    -ash
 6225 root      1648 S    /bin/sh /usr/bin/qmuxtrack /dev/cdc-wdm0 17

Firmware is latest and this router was recently reset to default before I started configuring it in the current setup.

I’ll see if this has any more reboots.

Leon

Daumantas · October 6, 2023, 8:17am

Sure, will be awaiting any news.
Just an FYI, htop is a quite good utility for monitoring memory usage. It can be installed by running the following commands:

opkg update #ignore the few unreachable repositories
opkg install htop

Best regards,

lmvlmv · October 11, 2023, 8:36am

So far so good. Looks like the MQTT service might have been a contributing factor somehow. After removing that and reverting the logging change (only made that for diagnostics) it seems to be stable again.

Leon

system · October 20, 2023, 3:26pm

This topic was automatically closed after 15 days. New replies are no longer allowed.