Hello,
Today, there was no internet connectivity from my asus58U on OpenWrt 19.07.7 r11306-c4a6851c72
From the dmesg logs that i could grab from ssh , it appears to be some OOM issue.
[ 32.451400] br-lan: port 2(wlan1) entered forwarding state
[ 59.090215] ath10k_ahb a000000.wifi: Invalid VHT mcs 15 peer stats
[ 2894.944017] ath10k_ahb a000000.wifi: Invalid peer id 5 or peer stats buffer, peer: (null) sta: (null)
[143985.276019] pppoe-wan: renamed from ppp0
[236491.388268] ess_edma c080000.edma: eth1: GMAC Link is down
[236501.788439] ess_edma c080000.edma: eth1: GMAC Link is up with phy_speed=100
[236518.427379] ess_edma c080000.edma: eth1: GMAC Link is down
[236519.467488] ess_edma c080000.edma: eth1: GMAC Link is up with phy_speed=100
[236522.538118] pppoe-wan: renamed from ppp0
[236523.023573] pppoe-wan: renamed from ppp0
[338992.174588] ath10k_ahb a800000.wifi: Invalid legacy rate 26 peer stats
[808449.140516] ath10k_ahb a000000.wifi: failed to increase tx pending count: -16, dropping
[808449.157018] ath10k_ahb a000000.wifi: failed to increase tx pending count: -16, dropping
[808449.173028] ath10k_ahb a000000.wifi: failed to increase tx pending count: -16, dropping
[808538.474444] ath10k_ahb a000000.wifi: failed to increase tx pending count: -16, dropping
[808543.668918] ath10k_ahb a000000.wifi: failed to increase tx pending count: -16, dropping
[808546.805940] kthreadd invoked oom-killer: gfp_mask=0x15080c0(GFP_KERNEL_ACCOUNT|__GFP_ZERO), nodemask=(null), order=1, oom_score_adj=0
[808546.806003] CPU: 2 PID: 2 Comm: kthreadd Not tainted 4.14.221 #0
[808546.816930] Hardware name: Generic DT based system
[808546.823192] Function entered at [<c030e2a8>] from [<c030a7a8>]
[808546.827870] Function entered at [<c030a7a8>] from [<c0741e74>]
[808546.833773] Function entered at [<c0741e74>] from [<c03a27a0>]
[808546.839675] Function entered at [<c03a27a0>] from [<c03a1acc>]
[808546.845577] Function entered at [<c03a1acc>] from [<c03a2680>]
[808546.851479] Function entered at [<c03a2680>] from [<c03a69c8>]
[808546.857383] Function entered at [<c03a69c8>] from [<c031b830>]
[808546.863285] Function entered at [<c031b830>] from [<c031ce8c>]
[808546.869188] Function entered at [<c031ce8c>] from [<c031d110>]
[808546.875091] Function entered at [<c031d110>] from [<c0339624>]
[808546.880995] Function entered at [<c0339624>] from [<c03074a8>]
[808546.887162] Mem-Info:
[808546.892814] active_anon:507 inactive_anon:14 isolated_anon:0
[808546.892814] active_file:91 inactive_file:118 isolated_file:0
[808546.892814] unevictable:0 dirty:0 writeback:0 unstable:0
[808546.892814] slab_reclaimable:554 slab_unreclaimable:3365
[808546.892814] mapped:3 shmem:70 pagetables:73 bounce:0
[808546.892814] free:4076 free_pcp:57 free_cma:0
[808546.905231] Node 0 active_anon:2028kB inactive_anon:56kB active_file:364kB inactive_file:472kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:12kB dirty:0kB writeback:0kB shmem:280kB writeback_tmp:0kB unstable:0kB all_unreclaimable? yes
[808546.927511] Normal free:16468kB min:16384kB low:20480kB high:24576kB active_anon:2028kB inactive_anon:56kB active_file:376kB inactive_file:492kB unevictable:0kB writepending:0kB present:129024kB managed:121004kB mlocked:0kB kernel_stack:712kB pagetables:292kB bounce:0kB free_pcp:40kB local_pcp:40kB free_cma:0kB
[808546.954959] lowmem_reserve[]: 0 0 0
[808546.977195] Normal: 102*4kB (UME) 260*8kB (UME) 157*16kB (UME) 69*32kB (UME) 27*64kB (ME) 5*128kB (UME) 1*256kB (M) 5*512kB (ME) 2*1024kB (UM) 1*2048kB (U) 0*4096kB = 16488kB
[808546.980836] 300 total pagecache pages
[808546.996200] 0 pages in swap cache
[808547.000012] Swap cache stats: add 0, delete 0, find 0/0
[808547.003388] Free swap = 0kB
[808547.008862] Total swap = 0kB
[808547.011718] 32256 pages RAM
[808547.014667] 0 pages HighMem/MovableOnly
[808547.017632] 2005 pages reserved
[808547.021527] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name
[808547.024769] [ 157] 0 157 256 24 5 0 0 0 ubusd
[808547.033189] [ 158] 0 158 176 7 4 0 0 0 askfirst
[808547.041780] [ 175] 0 175 204 8 3 0 0 0 urngd
[808547.050808] [ 544] 0 544 258 32 5 0 0 0 logd
[808547.059402] [ 575] 0 575 491 62 6 0 0 0 rpcd
[808547.068085] [ 672] 0 672 211 6 3 0 0 0 dropbear
[808547.076664] [ 729] 0 729 389 43 4 0 0 0 netifd
[808547.085618] [ 768] 0 768 312 27 5 0 0 0 odhcpd
[808547.094564] [ 798] 0 798 226 14 3 0 0 0 netserver
[808547.103325] [ 830] 0 830 288 34 5 0 0 0 uhttpd
[808547.112093] [ 1190] 0 1190 271 13 4 0 0 0 ntpd
[808547.121120] [ 1655] 0 1655 431 39 4 0 0 0 hostapd
[808547.129543] [ 1670] 0 1670 427 31 5 0 0 0 hostapd
[808547.138483] [ 1714] 453 1714 306 35 4 0 0 0 dnsmasq
[808547.147338] [ 7067] 0 7067 210 7 3 0 0 0 odhcp6c
[808547.156179] [ 7214] 0 7214 265 31 5 0 0 0 pppd
[808547.165045] Out of memory: Kill process 575 (rpcd) score 2 or sacrifice child
[808547.173561] Killed process 575 (rpcd) total-vm:1964kB, anon-rss:240kB, file-rss:8kB, shmem-rss:0kB
[808550.693572] kthreadd invoked oom-killer: gfp_mask=0x15080c0(GFP_KERNEL_ACCOUNT|__GFP_ZERO), nodemask=(null), order=1, oom_score_adj=0
[808550.693637] CPU: 3 PID: 2 Comm: kthreadd Not tainted 4.14.221 #0
[808550.704565] Hardware name: Generic DT based system
[808550.710828] Function entered at [<c030e2a8>] from [<c030a7a8>]
[808550.715505] Function entered at [<c030a7a8>] from [<c0741e74>]
[808550.721408] Function entered at [<c0741e74>] from [<c03a27a0>]
[808550.727309] Function entered at [<c03a27a0>] from [<c03a1acc>]
[808550.733209] Function entered at [<c03a1acc>] from [<c03a2680>]
[808550.739117] Function entered at [<c03a2680>] from [<c03a69c8>]
[808550.745015] Function entered at [<c03a69c8>] from [<c031b830>]
[808550.750920] Function entered at [<c031b830>] from [<c031ce8c>]
[808550.756822] Function entered at [<c031ce8c>] from [<c031d110>]
[808550.762724] Function entered at [<c031d110>] from [<c0339624>]
[808550.768626] Function entered at [<c0339624>] from [<c03074a8>]
[808550.774599] Mem-Info:
[808550.780462] active_anon:447 inactive_anon:14 isolated_anon:0
[808550.780462] active_file:132 inactive_file:160 isolated_file:0
[808550.780462] unevictable:0 dirty:0 writeback:0 unstable:0
[808550.780462] slab_reclaimable:561 slab_unreclaimable:3454
[808550.780462] mapped:12 shmem:70 pagetables:68 bounce:0
[808550.780462] free:3945 free_pcp:6 free_cma:0
[808550.792860] Node 0 active_anon:1788kB inactive_anon:56kB active_file:528kB inactive_file:656kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:48kB dirty:0kB writeback:0kB shmem:280kB writeback_tmp:0kB unstable:0kB all_unreclaimable? yes
[808550.815146] Normal free:15748kB min:16384kB low:20480kB high:24576kB active_anon:1788kB inactive_anon:56kB active_file:528kB inactive_file:688kB unevictable:0kB writepending:0kB present:129024kB managed:121004kB mlocked:0kB kernel_stack:728kB pagetables:272kB bounce:0kB free_pcp:24kB local_pcp:0kB free_cma:0kB
[808550.842684] lowmem_reserve[]: 0 0 0
[808550.864911] Normal: 59*4kB (UME) 220*8kB (UME) 142*16kB (ME) 72*32kB (ME) 29*64kB (UME) 8*128kB (UME) 1*256kB (M) 6*512kB (UME) 1*1024kB (M) 1*2048kB (U) 0*4096kB = 15852kB
[808550.868487] 374 total pagecache pages
[808550.883834] 0 pages in swap cache
[808550.887473] Swap cache stats: add 0, delete 0, find 0/0
[808550.890847] Free swap = 0kB
[808550.896310] Total swap = 0kB
[808550.899191] 32256 pages RAM
[808550.902128] 0 pages HighMem/MovableOnly
[808550.905081] 2005 pages reserved
[808550.909009] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name
[808550.912226] [ 157] 0 157 256 22 5 0 0 0 ubusd
[808550.920658] [ 158] 0 158 176 7 4 0 0 0 askfirst
[808550.929250] [ 175] 0 175 204 8 3 0 0 0 urngd
[808550.938277] [ 544] 0 544 258 32 5 0 0 0 logd
[808550.946851] [ 672] 0 672 211 6 3 0 0 0 dropbear
[808550.955559] [ 729] 0 729 389 43 4 0 0 0 netifd
[808550.964486] [ 768] 0 768 312 27 5 0 0 0 odhcpd
[808550.973436] [ 798] 0 798 226 14 3 0 0 0 netserver
[808550.982203] [ 830] 0 830 288 34 5 0 0 0 uhttpd
[808550.990963] [ 1190] 0 1190 271 13 4 0 0 0 ntpd
[808550.999988] [ 1655] 0 1655 431 39 4 0 0 0 hostapd
[808551.008408] [ 1670] 0 1670 427 31 5 0 0 0 hostapd
[808551.017355] [ 1714] 453 1714 306 35 4 0 0 0 dnsmasq
[808551.026191] [ 7067] 0 7067 210 7 3 0 0 0 odhcp6c
[808551.035060] [ 7214] 0 7214 265 31 5 0 0 0 pppd
[808551.043916] Out of memory: Kill process 729 (netifd) score 1 or sacrifice child
[808551.052433] Killed process 7214 (pppd) total-vm:1060kB, anon-rss:124kB, file-rss:0kB, shmem-rss:0kB
[808560.988609] ath10k_ahb a000000.wifi: failed to increase tx pending count: -16, dropping
[808576.581129] ath10k_ahb a000000.wifi: failed to increase tx pending count: -16, dropping
Can anyone point out what could be the reason of this issue from these logs?
It appears to be not enough to know the reason, but i might be wrong being not experienced in debugging these issues..
Are there any more logs that i could collect in future if this reappears?
Just to mention, one thing thats not normal is that since yesterday, i am doing a rsync of about 100GB of data from one pc to another over LAN. Which is a slow process, and has been happening since last 12 hrs. And the rsync process also had closed unexpectedly when i encountered this oom issue:
rsync: connection unexpectedly closed (23581395707 bytes received so far) [receiver]
rsync error: error in rsync protocol data stream (code 12) at io.c(235) [receiver=3.1.3]
rsync: connection unexpectedly closed (37201 bytes received so far) [generator]
rsync error: unexplained error (code 255) at io.c(235) [generator=3.1.3]
Could this stress of continuous data transfer be the reason behind this?
PS: also, on visiting luci, i got this message on browser:
/usr/lib/lua/luci/dispatcher.lua:426: /etc/config/luci seems to be corrupt, unable to find section 'main'
Thanks.