Kernel Error: Out of memory

bartje · October 31, 2022, 8:10pm

Hello,

I just had this crazy thing where all my 5Ghz devices where disconnected from my network for a couple or minutes(don't know the exact time). using VPN on my phone I found that all 2.4Ghz devices where still accessible. And for somehow 5G was visible enough so devices wouldn't swap over to 2.4.

So I opened the log and found an "Out of memory" exception and "hostapd" to be killed. I also see this is the process consuming the most memory, so that makes sence. But I don't know if it's supposed to take this much memory or not.

is there a way to prevent this issue from happening?
my log is below,

Mon Oct 31 20:47:17 2022 daemon.info hostapd: wlan0: STA fa:9e:84:01:a2:60 IEEE 802.11: disassociated
Mon Oct 31 20:47:18 2022 daemon.info hostapd: wlan0: STA fa:9e:84:01:a2:60 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.055634] hostapd invoked oom-killer: gfp_mask=0x100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.065902] CPU: 0 PID: 1185 Comm: hostapd Not tainted 5.10.146 #0
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.072574] Stack : 00000840 800bf418 80750000 80651520 00000000 00000000 00000000 00000000
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.081650]         00000000 00000000 00000000 00000000 00000000 00000001 82071bc8 e8abde73
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.090520]         82071c60 00000000 00000000 82071a70 00000038 80326544 00000000 ffffffea
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.099465]         000000da 82071a7c 000000da 806e1a88 82071ba8 80629d88 80000000 00000000
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.108472]         00000000 00000000 00100cca 00000840 00000000 8038c494 00000000 808a0000
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.117261]         ...
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.119892] Call Trace:
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.119903] [<800bf418>] 0x800bf418
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.126244] [<80326544>] 0x80326544
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.129960] [<8038c494>] 0x8038c494
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.133670] [<8006697c>] 0x8006697c
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.137441] [<80066984>] 0x80066984
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.141182] [<801523d8>] 0x801523d8
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.144880] [<80152c64>] 0x80152c64
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.148662] [<80153610>] 0x80153610
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.152395] [<801963f0>] 0x801963f0
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.156104] [<8014efe0>] 0x8014efe0
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.160002] [<80150df0>] 0x80150df0
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.163931] [<803235e4>] 0x803235e4
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.167657] [<8017b0b4>] 0x8017b0b4
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.171416] [<80180720>] 0x80180720
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.175118] [<8006fe64>] 0x8006fe64
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.178993] [<800752ec>] 0x800752ec
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.182817]
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.184473] Mem-Info:
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.186937] active_anon:286 inactive_anon:594 isolated_anon:0
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.186937]  active_file:0 inactive_file:171 isolated_file:0
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.186937]  unevictable:0 dirty:0 writeback:0
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.186937]  slab_reclaimable:297 slab_unreclaimable:2288
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.186937]  mapped:2 shmem:279 pagetables:87 bounce:0
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.186937]  free:4093 free_pcp:41 free_cma:0
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.219401] Node 0 active_anon:1144kB inactive_anon:2376kB active_file:0kB inactive_file:684kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:8kB dirty:0kB writeback:0kB shmem:1116kB writeback_tmp:0kB kernel_stack:360kB all_unreclaimable? yes
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.243127] Normal free:16372kB min:16384kB low:20480kB high:24576kB reserved_highatomic:0KB active_anon:1144kB inactive_anon:2376kB active_file:0kB inactive_file:684kB unevictable:0kB writepending:0kB present:131072kB managed:122324kB mlocked:0kB pagetables:348kB bounce:0kB free_pcp:164kB local_pcp:164kB free_cma:0kB
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.272600] lowmem_reserve[]: 0 0
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.276265] Normal: 63*4kB (UME) 89*8kB (UME) 51*16kB (UME) 26*32kB (UME) 9*64kB (ME) 5*128kB (UM) 3*256kB (UME) 5*512kB (UME) 3*1024kB (UME) 3*2048kB (M) 0*4096kB = 16372kB
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.292538] 450 total pagecache pages
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.296413] 0 pages in swap cache
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.300059] Swap cache stats: add 0, delete 0, find 0/0
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.305541] Free swap  = 0kB
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.308605] Total swap = 0kB
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.311687] 32768 pages RAM
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.314832] 0 pages HighMem/MovableOnly
Mon Oct 31 20:48:17 2022 kern.warn kernel: [614895.318883] 2187 pages reserved
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.322255] Tasks state (memory values in pages):
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.327435] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.336489] [    551]    81   551      345       28    20480        0             0 ubusd
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.345210] [    552]     0   552      249       10    20480        0             0 askfirst
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.354081] [    587]     0   587      277       14    16384        0             0 urngd
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.362728] [    921]   514   921      335       37    20480        0             0 logd
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.371347] [    988]     0   988      578       88    16384        0             0 rpcd
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.379949] [   1053]     0  1053      302       12    20480        0             0 dropbear
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.388827] [   1157]     0  1157      664       25    16384        0             0 hostapd
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.397669] [   1158]     0  1158      664       26    16384        0             0 wpa_supplicant
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.407323] [   1183]   101  1183     1106       29    24576        0             0 wpa_supplicant
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.416892] [   1185]   101  1185     1184      102    20480        0             0 hostapd
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.425691] [   1224]     0  1224      454       39    20480        0             0 netifd
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.434504] [   1281]     0  1281      381       27    20480        0             0 odhcpd
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.443207] [   1401]     0  1401     1050       69    24576        0             0 uhttpd
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.451952] [   1867]     0  1867      327       11    16384        0             0 udhcpc
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.460761] [   5139]     0  5139      664       26    20480        0             0 ntpd
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.469369] [   5141]   123  5141      327       11    20480        0             0 ntpd
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.477890] [  10623]     0 10623      306       20    20480        0             0 luci
Mon Oct 31 20:48:17 2022 kern.info kernel: [614895.486431] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),global_oom,task_memcg=/,task=hostapd,pid=1185,uid=101
Mon Oct 31 20:48:17 2022 kern.err kernel: [614895.498519] Out of memory: Killed process 1185 (hostapd) total-vm:4736kB, anon-rss:404kB, file-rss:4kB, shmem-rss:0kB, UID:101 pgtables:20kB oom_score_adj:0
Mon Oct 31 20:48:17 2022 kern.info kernel: [614897.592205] oom_reaper: reaped process 1185 (hostapd), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Mon Oct 31 20:48:17 2022 kern.info kernel: [614897.806077] br-lan: port 3(wlan0) entered disabled state
Mon Oct 31 20:48:17 2022 kern.info kernel: [614898.895903] br-lan: port 2(wlan1) entered disabled state
Mon Oct 31 20:48:18 2022 daemon.warn netifd: Wireless device 'radio0' setup failed, retry=3
Mon Oct 31 20:48:18 2022 daemon.notice netifd: Network device 'wlan0' link is down
Mon Oct 31 20:48:18 2022 daemon.warn netifd: Wireless device 'radio1' setup failed, retry=3
Mon Oct 31 20:48:18 2022 daemon.notice netifd: Network device 'wlan1' link is down
Mon Oct 31 20:48:21 2022 daemon.notice netifd: radio1 (10626): Command failed: Not found
Mon Oct 31 20:48:21 2022 kern.info kernel: [614902.641086] br-lan: port 2(wlan1) entered disabled state
Mon Oct 31 20:48:21 2022 daemon.notice netifd: radio0 (10625): Command failed: Not found
Mon Oct 31 20:48:21 2022 kern.warn kernel: [614902.778100] ath10k_pci 0000:00:00.0: peer-unmap-event: unknown peer id 1
Mon Oct 31 20:48:21 2022 kern.warn kernel: [614902.785922] ath10k_pci 0000:00:00.0: peer-unmap-event: unknown peer id 1
Mon Oct 31 20:48:21 2022 kern.warn kernel: [614902.792994] ath10k_pci 0000:00:00.0: peer-unmap-event: unknown peer id 1
Mon Oct 31 20:48:21 2022 kern.info kernel: [614903.041832] br-lan: port 3(wlan0) entered disabled state
Mon Oct 31 20:48:21 2022 kern.info kernel: [614903.056224] device wlan1 left promiscuous mode
Mon Oct 31 20:48:21 2022 kern.info kernel: [614903.060966] br-lan: port 2(wlan1) entered disabled state
Mon Oct 31 20:48:22 2022 kern.info kernel: [614903.315616] device wlan0 left promiscuous mode
Mon Oct 31 20:48:22 2022 kern.info kernel: [614903.320360] br-lan: port 3(wlan0) entered disabled state
Mon Oct 31 20:48:22 2022 daemon.notice netifd: Wireless device 'radio1' is now down
Mon Oct 31 20:48:22 2022 daemon.notice netifd: Wireless device 'radio0' is now down
Mon Oct 31 20:48:23 2022 daemon.notice netifd: lan (1867): udhcpc: sending renew to server 192.168.180.10
Mon Oct 31 20:48:23 2022 daemon.notice netifd: lan (1867): udhcpc: lease of 192.168.180.6 obtained from 192.168.180.10, lease time 86400
Mon Oct 31 20:48:24 2022 user.info : luci: accepted login on / for root from 192.168.180.149

d687r02j8g · October 31, 2022, 8:18pm

What device are you using?

What services are you running on the device?

bartje · October 31, 2022, 8:44pm

my device is
"TP-Link Deco M4R v1" actually v2, but it needs to be flashed using the same image.
and services

root@OpenWrt6:~# service
Usage: service <service> [command]
/etc/init.d/boot                   enabled         stopped
/etc/init.d/bootcount              enabled         stopped
/etc/init.d/cron                   enabled         stopped
/etc/init.d/done                   enabled         stopped
/etc/init.d/dropbear               enabled         running
/etc/init.d/firewall               enabled         stopped
/etc/init.d/gpio_switch            enabled         stopped
/etc/init.d/led                    enabled         stopped
/etc/init.d/log                    enabled         running
/etc/init.d/network                enabled         running
/etc/init.d/odhcpd                 enabled         running
/etc/init.d/rpcd                   enabled         running
/etc/init.d/sysctl                 enabled         stopped
/etc/init.d/sysfixtime             enabled         stopped
/etc/init.d/sysntpd                enabled         running
/etc/init.d/system                 enabled         stopped
/etc/init.d/ucitrack               enabled         stopped
/etc/init.d/uhttpd                 enabled         running
/etc/init.d/umount                 enabled         stopped
/etc/init.d/urandom_seed           enabled         stopped
/etc/init.d/urngd                  enabled         running
/etc/init.d/wpad                   enabled         running
root@OpenWrt6:~#

where I actually thought I disabled "odhcpd" but apparently not.
I have a local dhcp server so I don't need dhcp caching on my AP's

d687r02j8g · October 31, 2022, 9:07pm

What version of openwrt are you running?

How much memory does your device have free? Can you either post a screenshot of the memory section of the Luci status page or SSH to your device and post the output of the free command.

The oom killed hostpad because your device ran out of memory.

bartje · October 31, 2022, 9:23pm

I run OpenWrt 22.03.2 and the device has 128MB of memory for as far as I can see.

here is a screenshot of the current status page,
but here nothing is wrong with it.
and free shows me

root@OpenWrt6:~# free
              total        used        free      shared  buff/cache   available
Mem:         122324       38472       73764        1116       10088       53688
Swap:             0           0           0
root@OpenWrt6:~#