kernel OOM on rpi 4B every night at the same time

Discussion about U-Boot and the kernel.

kernel OOM on rpi 4B every night at the same time

Postby darkfoon » Thu Jun 04, 2020 7:33 am

Hello, nightly at or around midnight, local time, I observe what looks like a kernel OOM that causes the OOM Killer to go and kill the daemon using the most memory, dnscrypt-proxy. However, there is plenty of memory free (over 1 GB) when this occurs. And the nightly timing is somewhat suspect.
It started occurring a few months ago after whole system update, which also updated the kernel.

I believe this is a kernel issue since I have a USB NIC attached to this raspberry Pi 4B, and the stack trace shows a usbnet module.

Here is the listing from journalctl -r showing the kernel stack exception (read from the bottom up):
$this->bbcode_second_pass_code('', 'Jun 04 00:00:12 hostnamehostna systemd[1]: dnscrypt-proxy.service: Failed with result 'signal'.
Jun 04 00:00:12 hostnamehostna systemd[1]: dnscrypt-proxy.service: Main process exited, code=killed, status=9/KILL
Jun 04 00:00:12 hostnamehostna kernel: oom_reaper: reaped process 348 (dnscrypt-proxy), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Jun 04 00:00:12 hostnamehostna kernel: Out of memory: Killed process 348 (dnscrypt-proxy) total-vm:903976kB, anon-rss:16040kB, file-rss:5788kB, shmem-rss:0kB, UID:62582 pgtables:140kB oom_score_adj:0
Jun 04 00:00:12 hostnamehostna kernel: oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/,task=dnscrypt-proxy,pid=348,uid=62582
Jun 04 00:00:12 hostnamehostna kernel: [ 25824] 0 25824 2774 2001 45056 0 0 mandb
Jun 04 00:00:12 hostnamehostna kernel: [ 25796] 975 25796 570 56 24576 0 0 dhcpcd
Jun 04 00:00:12 hostnamehostna kernel: [ 25792] 975 25792 570 56 24576 0 0 dhcpcd
Jun 04 00:00:12 hostnamehostna kernel: [ 25787] 975 25787 570 51 24576 0 0 dhcpcd
Jun 04 00:00:12 hostnamehostna kernel: [ 25786] 0 25786 570 361 24576 0 0 dhcpcd
Jun 04 00:00:12 hostnamehostna kernel: [ 25785] 975 25785 783 571 28672 0 0 dhcpcd
Jun 04 00:00:12 hostnamehostna kernel: [ 25754] 1001 25754 920 750 28672 0 0 bash
Jun 04 00:00:12 hostnamehostna kernel: [ 25753] 1001 25753 3619 1048 49152 0 0 sshd
Jun 04 00:00:12 hostnamehostna kernel: [ 25748] 1001 25748 9945 919 73728 0 0 (sd-pam)
Jun 04 00:00:12 hostnamehostna kernel: [ 25747] 1001 25747 4194 1992 53248 0 0 systemd
Jun 04 00:00:12 hostnamehostna kernel: [ 25744] 0 25744 3619 1613 49152 0 0 sshd
Jun 04 00:00:12 hostnamehostna kernel: [ 410] 977 410 5326 3371 69632 0 0 dnsmasq
Jun 04 00:00:12 hostnamehostna kernel: [ 407] 0 407 492 339 32768 0 0 agetty
Jun 04 00:00:12 hostnamehostna kernel: [ 406] 0 406 1004 356 28672 0 0 agetty
Jun 04 00:00:12 hostnamehostna kernel: [ 406] 0 406 1004 356 28672 0 0 agetty
Jun 04 00:00:12 hostnamehostna kernel: [ 396] 0 396 1940 1183 36864 0 -1000 sshd
Jun 04 00:00:12 hostnamehostna kernel: [ 357] 974 357 3477 721 40960 0 0 chronyd
Jun 04 00:00:12 hostnamehostna kernel: [ 353] 0 353 3916 1569 57344 0 0 systemd-logind
Jun 04 00:00:12 hostnamehostna kernel: [ 348] 62582 348 225994 5457 143360 0 0 dnscrypt-proxy
Jun 04 00:00:12 hostnamehostna kernel: [ 346] 81 346 3002 1046 49152 0 -900 dbus-daemon
Jun 04 00:00:12 hostnamehostna kernel: [ 345] 0 345 836 460 28672 0 0 crond
Jun 04 00:00:12 hostnamehostna kernel: [ 340] 0 340 13947 1159 81920 0 0 rngd
Jun 04 00:00:12 hostnamehostna kernel: [ 301] 0 301 6826 1686 57344 0 -1000 systemd-udevd
Jun 04 00:00:12 hostnamehostna kernel: [ 293] 0 293 3102 235 36864 0 0 lvmetad
Jun 04 00:00:12 hostnamehostna kernel: [ 287] 0 287 28459 13908 208896 0 -250 systemd-journal
Jun 04 00:00:12 hostnamehostna kernel: [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name
Jun 04 00:00:12 hostnamehostna kernel: Tasks state (memory values in pages):
Jun 04 00:00:12 hostnamehostna kernel: 16384 pages cma reserved
Jun 04 00:00:12 hostnamehostna kernel: 33400 pages reserved
Jun 04 00:00:12 hostnamehostna kernel: 828928 pages HighMem/MovableOnly
Jun 04 00:00:12 hostnamehostna kernel: 1025536 pages RAM
Jun 04 00:00:12 hostnamehostna kernel: Total swap = 0kB
Jun 04 00:00:12 hostnamehostna kernel: Free swap = 0kB
Jun 04 00:00:12 hostnamehostna kernel: Swap cache stats: add 0, delete 0, find 0/0
Jun 04 00:00:12 hostnamehostna kernel: 0 pages in swap cache
Jun 04 00:00:12 hostnamehostna kernel: 309609 total pagecache pages
Jun 04 00:00:12 hostnamehostna kernel: HighMem: 247*4kB (UM) 100*8kB (UM) 56*16kB (UM) 30*32kB (UM) 9*64kB (UM) 0*128kB 1*256kB (M) 1*512kB (U) 1*1024kB (M) 2*2048kB (UM) 618*4096kB (UM) = 2541436kB
Jun 04 00:00:12 hostnamehostna kernel: DMA: 23*4kB (HC) 1943*8kB (UEHC) 39*16kB (HC) 12*32kB (HC) 4*64kB (HC) 2*128kB (C) 1*256kB (C) 0*512kB 1*1024kB (C) 0*2048kB 15*4096kB (C) = 79876kB
Jun 04 00:00:12 hostnamehostna kernel: lowmem_reserve[]: 0 0 0 0
Jun 04 00:00:12 hostnamehostna kernel: HighMem free:2541116kB min:512kB low:4868kB high:9224kB active_anon:32452kB inactive_anon:188kB active_file:89680kB inactive_file:641592kB unevictable:0kB writepending:420kB present:3315712kB managed:3315712kB mlocked:0kB kernel_stack:0kB pagetables:1124kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Jun 04 00:00:12 hostnamehostna kernel: lowmem_reserve[]: 0 0 3238 3238
Jun 04 00:00:12 hostnamehostna kernel: DMA free:80028kB min:3040kB low:3800kB high:4560kB active_anon:0kB inactive_anon:0kB active_file:245824kB inactive_file:268884kB unevictable:0kB writepending:2960kB present:786432kB managed:652832kB mlocked:0kB kernel_stack:1288kB pagetables:0kB bounce:0kB free_pcp:1220kB local_pcp:680kB free_cma:63204kB
Jun 04 00:00:12 hostnamehostna kernel: Node 0 active_anon:32452kB inactive_anon:188kB active_file:335548kB inactive_file:910520kB unevictable:0kB isolated(anon):0kB isolated(file):56kB mapped:56664kB dirty:3528kB writeback:0kB shmem:436kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
Jun 04 00:00:12 hostnamehostna kernel: active_anon:8113 inactive_anon:47 isolated_anon:0
active_file:83887 inactive_file:227630 isolated_file:14
unevictable:0 dirty:882 writeback:0 unstable:0
slab_reclaimable:6774 slab_unreclaimable:5914
mapped:14166 shmem:109 pagetables:281 bounce:0
free:655348 free_pcp:260 free_cma:15801
Jun 04 00:00:12 hostnamehostna kernel: Mem-Info:
Jun 04 00:00:12 hostnamehostna kernel: 7fe0: 00000000 00000000 00000000 00000000 00000013 00000000
Jun 04 00:00:12 hostnamehostna kernel: 7fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Jun 04 00:00:12 hostnamehostna kernel: 7fa0: 00000000 00000000 00000000 00000000
Jun 04 00:00:12 hostnamehostna kernel: Exception stack(0xc9d67fb0 to 0xc9d67ff8)
Jun 04 00:00:12 hostnamehostna kernel: [<c024ec5c>] (kthread) from [<c02010d8>] (ret_from_fork+0x14/0x3c)
Jun 04 00:00:12 hostnamehostna kernel: [<c0248e04>] (worker_thread) from [<c024ec5c>] (kthread+0x128/0x154)
Jun 04 00:00:12 hostnamehostna kernel: [<c0248a20>] (process_one_work) from [<c0248e04>] (worker_thread+0x4c/0x528)
Jun 04 00:00:12 hostnamehostna kernel: [<c09f43b4>] (usbnet_deferred_kevent) from [<c0248a20>] (process_one_work+0x1f0/0x588)
Jun 04 00:00:12 hostnamehostna kernel: [<c09f41d8>] (rx_submit) from [<c09f43b4>] (usbnet_deferred_kevent+0x84/0x31c)
Jun 04 00:00:12 hostnamehostna kernel: [<c0b7f768>] (__netdev_alloc_skb) from [<c09f41d8>] (rx_submit+0xcc/0x224)
Jun 04 00:00:12 hostnamehostna kernel: [<c0b7d778>] (__alloc_skb) from [<c0b7f768>] (__netdev_alloc_skb+0x38/0x178)
Jun 04 00:00:12 hostnamehostna kernel: [<c0b7d6c8>] (__kmalloc_reserve.constprop.0) from [<c0b7d778>] (__alloc_skb+0x6c/0x15c)
Jun 04 00:00:12 hostnamehostna kernel: [<c03a0a3c>] (kmalloc_order_trace) from [<c0b7d6c8>] (__kmalloc_reserve.constprop.0+0x20/0x64)
Jun 04 00:00:12 hostnamehostna kernel: [<c03a09f0>] (kmalloc_order) from [<c03a0a3c>] (kmalloc_order_trace+0x1c/0xf4)
Jun 04 00:00:12 hostnamehostna kernel: [<c03c8810>] (__alloc_pages_nodemask) from [<c03a09f0>] (kmalloc_order+0x1c/0x4c)
Jun 04 00:00:12 hostnamehostna kernel: [<c037dea8>] (out_of_memory) from [<c03c8810>] (__alloc_pages_nodemask+0xc00/0x1264)
Jun 04 00:00:12 hostnamehostna kernel: [<c037d5a0>] (oom_kill_process) from [<c037dea8>] (out_of_memory+0x10c/0x338)
Jun 04 00:00:12 hostnamehostna kernel: [<c037e1b0>] (dump_header) from [<c037d5a0>] (oom_kill_process+0x188/0x194)
Jun 04 00:00:12 hostnamehostna kernel: [<c0cd0378>] (dump_stack) from [<c037e1b0>] (dump_header+0x54/0x204)
Jun 04 00:00:12 hostnamehostna kernel: [<c020c6fc>] (show_stack) from [<c0cd0378>] (dump_stack+0x94/0xb4)
Jun 04 00:00:12 hostnamehostna kernel: [<c0211424>] (unwind_backtrace) from [<c020c6fc>] (show_stack+0x10/0x14)
Jun 04 00:00:12 hostnamehostna kernel: Workqueue: events usbnet_deferred_kevent
Jun 04 00:00:12 hostnamehostna kernel: Hardware name: BCM2711
Jun 04 00:00:12 hostnamehostna kernel: CPU: 0 PID: 25741 Comm: kworker/0:1 Tainted: G C 5.4.42-1-ARCH #1
Jun 04 00:00:12 hostnamehostna kernel: kworker/0:1 invoked oom-killer: gfp_mask=0xc2cc0(GFP_KERNEL|__GFP_NOWARN|__GFP_COMP|__GFP_NOMEMALLOC), order=3, oom_score_adj=0')

The output from uname -a:$this->bbcode_second_pass_code('', 'Linux hostnamehostna 5.4.42-1-ARCH #1 SMP PREEMPT Tue May 26 01:49:01 UTC 2020 armv7l GNU/Linux
')

The output from lsusb:$this->bbcode_second_pass_code('', 'Bus 002 Device 002: ID 0b95:1790 ASIX Electronics Corp. AX88179 Gigabit Ethernet
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 002: ID 2109:3431 VIA Labs, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
')

The output from lsmod:$this->bbcode_second_pass_code('', 'Module Size Used by
ip6t_REJECT 16384 4
nf_reject_ipv6 16384 1 ip6t_REJECT
ip6t_rpfilter 16384 1
ip6table_nat 16384 0
ip6table_mangle 16384 1
ip6table_raw 16384 0
nf_log_ipv6 16384 11
ip6table_filter 16384 1
ip6_tables 28672 26 ip6table_mangle,ip6table_filter,ip6table_raw,ip6table_nat
xt_tcpudp 16384 24
xt_MASQUERADE 16384 1
xt_recent 24576 2
xt_comment 16384 30
ipt_REJECT 16384 4
nf_reject_ipv4 16384 1 ipt_REJECT
xt_addrtype 16384 32
iptable_nat 16384 1
xt_mark 16384 2
iptable_mangle 16384 1
xt_hashlimit 20480 24
xt_CT 16384 0
iptable_raw 16384 0
xt_multiport 16384 2
xt_conntrack 16384 33
nfnetlink_log 20480 0
xt_NFLOG 16384 0
nf_log_ipv4 16384 13
nf_log_common 16384 2 nf_log_ipv6,nf_log_ipv4
xt_LOG 16384 24
nf_nat_tftp 16384 0
nf_nat_snmp_basic 16384 0
nf_conntrack_snmp 16384 1 nf_nat_snmp_basic
nf_nat_sip 20480 0
nf_nat_pptp 16384 0
nf_nat_irc 16384 0
nf_nat_h323 16384 0
nf_nat_ftp 16384 0
nf_nat_amanda 16384 0
ts_kmp 16384 6
nf_conntrack_amanda 16384 1 nf_nat_amanda
nf_nat 45056 10 nf_nat_pptp,nf_nat_h323,nf_nat_sip,nf_nat_irc,xt_MASQUERADE,iptable_nat,nf_nat_ftp,nf_nat_amanda,ip6table_nat,nf_nat_tftp
nf_conntrack_sane 16384 0
nf_conntrack_tftp 16384 1 nf_nat_tftp
nf_conntrack_sip 32768 1 nf_nat_sip
nf_conntrack_pptp 16384 1 nf_nat_pptp
nf_conntrack_netlink 45056 0
nfnetlink 16384 2 nfnetlink_log,nf_conntrack_netlink
nf_conntrack_netbios_ns 16384 0
nf_conntrack_broadcast 16384 2 nf_conntrack_snmp,nf_conntrack_netbios_ns
nf_conntrack_irc 16384 1 nf_nat_irc
nf_conntrack_h323 53248 1 nf_nat_h323
nf_conntrack_ftp 16384 1 nf_nat_ftp
nf_conntrack 131072 24 nf_nat_pptp,nf_conntrack_sip,nf_conntrack_snmp,nf_conntrack_irc,nf_nat_h323,nf_conntrack_ftp,nf_nat_snmp_basic,nf_nat_sip,nf_conntrack_tftp,nf_nat_irc,xt_MASQUERADE,nf_conntrack_pptp,nf_conntrack_amanda,nf_conntrack_broadcast,nf_nat_ftp,nf_conntrack_sane,nf_nat_amanda,nf_conntrack_netlink,nf_conntrack_netbios_ns,xt_CT,nf_conntrack_h323,xt_conntrack,nf_nat_tftp,nf_nat
nf_defrag_ipv4 16384 1 nf_conntrack
iptable_filter 16384 1
cfg80211 704512 0
8021q 32768 0
garp 16384 1 8021q
stp 16384 1 garp
mrp 20480 1 8021q
llc 16384 2 garp,stp
bcm2835_codec 36864 0
bcm2835_v4l2 49152 0
bcm2835_isp 32768 0
v4l2_mem2mem 28672 1 bcm2835_codec
bcm2835_mmal_vchiq 28672 3 bcm2835_isp,bcm2835_codec,bcm2835_v4l2
videobuf2_dma_contig 20480 2 bcm2835_isp,bcm2835_codec
videobuf2_vmalloc 16384 1 bcm2835_v4l2
videobuf2_memops 16384 2 videobuf2_dma_contig,videobuf2_vmalloc
videobuf2_v4l2 24576 4 bcm2835_isp,bcm2835_codec,bcm2835_v4l2,v4l2_mem2mem
videobuf2_common 53248 5 bcm2835_isp,bcm2835_codec,bcm2835_v4l2,v4l2_mem2mem,videobuf2_v4l2
videodev 225280 6 bcm2835_isp,bcm2835_codec,videobuf2_common,bcm2835_v4l2,v4l2_mem2mem,videobuf2_v4l2
mc 36864 6 bcm2835_isp,bcm2835_codec,videobuf2_common,videodev,v4l2_mem2mem,videobuf2_v4l2
raspberrypi_hwmon 16384 0
hwmon 28672 1 raspberrypi_hwmon
iproc_rng200 16384 0
rpivid_mem 16384 0
uio_pdrv_genirq 16384 0
uio 20480 1 uio_pdrv_genirq
sch_fq_codel 20480 7
bcm2835_rng 16384 0
rng_core 16384 3 iproc_rng200,bcm2835_rng
drm 434176 0
drm_panel_orientation_quirks 16384 1 drm
ip_tables 28672 6 iptable_mangle,iptable_filter,iptable_raw,iptable_nat
x_tables 32768 23 xt_comment,xt_hashlimit,xt_LOG,xt_multiport,ipt_REJECT,iptable_mangle,ip_tables,ip6t_rpfilter,iptable_filter,xt_mark,xt_tcpudp,iptable_raw,xt_MASQUERADE,ip6t_REJECT,ip6table_mangle,xt_recent,ip6table_filter,xt_addrtype,xt_CT,ip6table_raw,xt_conntrack,ip6_tables,xt_NFLOG
ipv6 475136 59 ip6t_rpfilter,nf_reject_ipv6,ip6table_mangle
nf_defrag_ipv6 16384 2 nf_conntrack,ipv6')

Has anyone else seen this? Is there something I can do to fix this/investigate why this is happening?

If there is more diagnostic information I could collect, let me know and I'll do my best to collect it. This device is running as a firewall/router, so uptime is somewhat important to me.

Given how this happens at almost the same time every night, I wonder if there's a killer packet that is sent from my ISP that is causing this, or some other kind of attack, since this device is internet-facing.
darkfoon
 
Posts: 1
Joined: Thu Jun 04, 2020 7:16 am

Return to U-Boot/Kernel

Who is online

Users browsing this forum: No registered users and 2 guests