We have a server that is typically running for 6 months between reboots to upgrade kernel. In other words, it's very stable and has been running for 4 years like that. Recently, we've had an unexpected hangup/crash-reboot. Upon that, a new kernel was loaded but the situation re-occured. Then a new kernel was loaded again (we install all apt upgrades including new PVE kernels very frequently, so whenever a reboot happens, new kernel is used).
Upon enabling journald persistance (it wasn't enabled at first for some reason - which may not be PVE's fault), we found that there are two symptoms:
1. Around 15 seconds before the crash/lockup, the "Proxmox VE replication runner" started. We don't use clustering/HA/replication, it's a standalone/single node.
2. The call trace for kernel panic typically refers to ipset
Some additional facts:
- We use firewall feature in PVE on this host but the number of rules is very log (20 total or so). Another host that does not use Firewall features does not crash.
- Load is always "healthy" (1 - 2). The host is never overloaded or attacked.
- All containers are unprivileged. 12 containers running, 1 KVM machine.
Here are a few crash logs, from most recent to oldest
Upon enabling journald persistance (it wasn't enabled at first for some reason - which may not be PVE's fault), we found that there are two symptoms:
1. Around 15 seconds before the crash/lockup, the "Proxmox VE replication runner" started. We don't use clustering/HA/replication, it's a standalone/single node.
2. The call trace for kernel panic typically refers to ipset
Some additional facts:
- We use firewall feature in PVE on this host but the number of rules is very log (20 total or so). Another host that does not use Firewall features does not crash.
- Load is always "healthy" (1 - 2). The host is never overloaded or attacked.
- All containers are unprivileged. 12 containers running, 1 KVM machine.
Here are a few crash logs, from most recent to oldest
Code:
root@pve:~# journalctl -b -1
Dec 26 18:47:00 pve systemd[1]: Starting Proxmox VE replication runner...
Dec 26 18:47:01 pve CRON[28187]: pam_unix(cron:session): session opened for user root by (uid=0)
Dec 26 18:47:01 pve CRON[28188]: (root) CMD (/usr/local/rtm/bin/rtm 22 > /dev/null 2> /dev/null)
Dec 26 18:47:01 pve CRON[28187]: pam_unix(cron:session): session closed for user root
Dec 26 18:47:01 pve systemd[1]: Started Proxmox VE replication runner.
Dec 26 18:47:24 pve kernel: watchdog: BUG: soft lockup - CPU#7 stuck for 22s! [ipset:26626]
Dec 26 18:47:24 pve kernel: Modules linked in: ip6t_rpfilter ebtable_nat ebtable_broute ip6table_nat nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw iptable_nat nf_nat_ipv4 nf
Dec 26 18:47:24 pve kernel: cryptd snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic ppdev eeepc_wmi asus_wmi wmi_bmof sparse_keymap intel_cstate intel_rapl_perf i915 snd_h
Dec 26 18:47:24 pve kernel: megaraid_sas
Dec 26 18:47:24 pve kernel: CPU: 7 PID: 26626 Comm: ipset Tainted: P O L 4.15.18-9-pve #1
Dec 26 18:47:24 pve kernel: Hardware name: System manufacturer System Product Name/P8H77-M PRO, BIOS 1401 08/20/2013
Dec 26 18:47:24 pve kernel: RIP: 0010:ip_set_range_to_cidr+0x12/0x49 [ip_set]
Dec 26 18:47:24 pve kernel: RSP: 0018:ffffb30161067810 EFLAGS: 00000213 ORIG_RAX: ffffffffffffff11
Dec 26 18:47:24 pve kernel: RAX: 0000000080000000 RBX: ffffb30161067850 RCX: 000000000ab3973a
Dec 26 18:47:24 pve kernel: RDX: ffffb3016106784f RSI: 00000000ffffffff RDI: 000000000ab3973a
Dec 26 18:47:24 pve kernel: RBP: ffffb301610678c0 R08: ffffffffc0a51b00 R09: 0000000000000000
Dec 26 18:47:24 pve kernel: R10: 0000000000000021 R11: ffffb30161067848 R12: 0000000000000001
Dec 26 18:47:24 pve kernel: R13: 00000000ffffffff R14: ffff9818669b6780 R15: 000000000ab39739
Dec 26 18:47:24 pve kernel: FS: 00007fd1d0247740(0000) GS:ffff98199fbc0000(0000) knlGS:0000000000000000
Dec 26 18:47:24 pve kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Dec 26 18:47:24 pve kernel: CR2: 00007f4e382223a0 CR3: 00000007dbd90002 CR4: 00000000001606e0
Dec 26 18:47:24 pve kernel: Call Trace:
Dec 26 18:47:24 pve kernel: ? hash_net4_uadt+0x200/0x330 [ip_set_hash_net]
Dec 26 18:47:24 pve kernel: ? hash_net6_add+0x800/0x800 [ip_set_hash_net]
Dec 26 18:47:24 pve kernel: call_ad+0xc4/0x220 [ip_set]
Dec 26 18:47:24 pve kernel: ? hash_net6_uadt+0x200/0x200 [ip_set_hash_net]
Dec 26 18:47:24 pve kernel: ? call_ad+0xc4/0x220 [ip_set]
Dec 26 18:47:24 pve kernel: ? validate_nla+0x15b/0x240
Dec 26 18:47:24 pve kernel: ? nla_parse+0xaa/0x140
Dec 26 18:47:24 pve kernel: ip_set_uadd+0x23c/0x2a0 [ip_set]
Dec 26 18:47:24 pve kernel: nfnetlink_rcv_msg+0x240/0x260 [nfnetlink]
Dec 26 18:47:24 pve kernel: ? nfnetlink_net_exit_batch+0x70/0x70 [nfnetlink]
Dec 26 18:47:24 pve kernel: netlink_rcv_skb+0xd9/0x110
Dec 26 18:47:24 pve kernel: nfnetlink_rcv+0x6c/0x72a [nfnetlink]
Dec 26 18:47:24 pve kernel: ? __slab_alloc+0x20/0x40
Dec 26 18:47:24 pve kernel: ? __kmalloc_node_track_caller+0x1f8/0x2b0
Dec 26 18:47:24 pve kernel: ? __alloc_skb+0x87/0x1c0
Dec 26 18:47:24 pve kernel: ? __netlink_lookup+0xd9/0x140
Dec 26 18:47:24 pve kernel: netlink_unicast+0x19c/0x240
Dec 26 18:47:24 pve kernel: netlink_sendmsg+0x2d7/0x3d0
Dec 26 18:47:24 pve kernel: sock_sendmsg+0x3e/0x50
Dec 26 18:47:24 pve kernel: SYSC_sendto+0x101/0x190
Dec 26 18:47:24 pve kernel: ? __secure_computing+0x3f/0x100
Dec 26 18:47:24 pve kernel: ? syscall_trace_enter+0xca/0x2e0
Dec 26 18:47:24 pve kernel: SyS_sendto+0xe/0x10
Dec 26 18:47:24 pve kernel: do_syscall_64+0x73/0x130
Dec 26 18:47:24 pve kernel: entry_SYSCALL_64_after_hwframe+0x3d/0xa2
Dec 26 18:47:24 pve kernel: RIP: 0033:0x7fd1d034708b
Dec 26 18:47:24 pve kernel: RSP: 002b:00007ffe189e6578 EFLAGS: 00000246 ORIG_RAX: 000000000000002c
Dec 26 18:47:24 pve kernel: RAX: ffffffffffffffda RBX: 000055cb33a5af70 RCX: 00007fd1d034708b
Dec 26 18:47:24 pve kernel: RDX: 00000000000004dc RSI: 000055cb33a58c78 RDI: 0000000000000003
Dec 26 18:47:24 pve kernel: RBP: 000055cb33a58c78 R08: 00007fd1d0412000 R09: 000000000000000c
Dec 26 18:47:24 pve kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000001000
Dec 26 18:47:24 pve kernel: R13: 000055cb3308c137 R14: 000055cb3308c13f R15: 0000000000000000
Dec 26 18:47:24 pve kernel: Code: 48 8d 4d f7 0f b6 f2 48 89 c2 e8 4a fe ff ff eb c2 e8 13 b9 a3 fa 0f 1f 00 0f 1f 44 00 00 55 49 c7 c0 00 1b a5 c0 b8 00 00 00 80 <b9> 01 00 00 00 48 89
Dec 26 18:48:03 pve systemd[1]: Starting Proxmox VE replication runner...
Dec 26 18:48:21 pve CRON[28585]: pam_unix(cron:session): session opened for user root by (uid=0)
Code:
root@pve:~# journalctl -b -2
Dec 20 18:21:00 pve systemd[1]: Starting Proxmox VE replication runner...
Dec 20 18:21:01 pve CRON[13307]: pam_unix(cron:session): session opened for user root by (uid=0)
Dec 20 18:21:01 pve CRON[13308]: (root) CMD (/usr/local/rtm/bin/rtm 22 > /dev/null 2> /dev/null)
Dec 20 18:21:02 pve CRON[13307]: pam_unix(cron:session): session closed for user root
Dec 20 18:21:02 pve systemd[1]: Started Proxmox VE replication runner.
Dec 20 18:21:36 pve pvestatd[1836]: status update time (5.419 seconds)
Dec 20 18:22:00 pve systemd[1]: Starting Proxmox VE replication runner...
Dec 20 18:22:01 pve CRON[13836]: pam_unix(cron:session): session opened for user root by (uid=0)
Dec 20 18:22:01 pve CRON[13837]: (root) CMD (/usr/local/rtm/bin/rtm 22 > /dev/null 2> /dev/null)
Dec 20 18:22:05 pve CRON[13836]: pam_unix(cron:session): session closed for user root
Dec 20 18:22:29 pve pvestatd[1836]: got timeout
Dec 20 18:22:36 pve sshd[13958]: Did not receive identification string from 182.254.227.182 port 7109
Dec 20 18:23:12 pve pve-ha-lrm[1982]: loop take too long (57 seconds)
Dec 20 18:23:12 pve CRON[13963]: pam_unix(cron:session): session opened for user root by (uid=0)
Dec 20 18:23:18 pve CRON[13976]: (root) CMD (/usr/local/rtm/bin/rtm 22 > /dev/null 2> /dev/null)
Dec 20 18:24:18 pve kernel: INFO: task ipset:13217 blocked for more than 120 seconds.
Dec 20 18:24:24 pve kernel: Tainted: P O L 4.15.18-9-pve #1
Dec 20 18:24:31 pve kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 20 18:24:34 pve kernel: ipset D 0 13217 1829 0x00000000
Dec 20 18:24:34 pve kernel: Call Trace:
Dec 20 18:24:34 pve kernel: __schedule+0x3e0/0x870
Dec 20 18:24:34 pve kernel: schedule+0x36/0x80
Dec 20 18:24:34 pve kernel: schedule_preempt_disabled+0xe/0x10
Dec 20 18:24:34 pve kernel: __mutex_lock.isra.2+0x2b1/0x4e0
Dec 20 18:24:34 pve kernel: ? mem_cgroup_commit_charge+0x82/0x540
Dec 20 18:24:34 pve kernel: ? lru_cache_add_active_or_unevictable+0x36/0xb0
Dec 20 18:24:34 pve kernel: __mutex_lock_slowpath+0x13/0x20
Dec 20 18:24:47 pve kernel: ? __mutex_lock_slowpath+0x13/0x20
Dec 20 18:24:48 pve kernel: mutex_lock+0x2f/0x40
Dec 20 18:24:50 pve kernel: nfnetlink_rcv_msg+0x1ab/0x260 [nfnetlink]
Dec 20 18:25:08 pve kernel: ? nfnetlink_net_exit_batch+0x70/0x70 [nfnetlink]
Dec 20 18:25:13 pve kernel: netlink_rcv_skb+0xd9/0x110
Dec 20 18:25:24 pve kernel: nfnetlink_rcv+0x6c/0x72a [nfnetlink]
Dec 20 18:25:27 pve kernel: ? walk_system_ram_range+0xb2/0xe0
Dec 20 18:25:28 pve kernel: ? memcg_kmem_charge_memcg+0x7d/0xa0
Dec 20 18:25:40 pve kernel: ? _cond_resched+0x1a/0x50
Dec 20 18:25:44 pve kernel: ? __kmalloc_node_track_caller+0x1f8/0x2b0
Dec 20 18:25:53 pve kernel: ? __alloc_skb+0x87/0x1c0
Dec 20 18:26:07 pve kernel: ? __netlink_lookup+0xd9/0x140
Dec 20 18:26:09 pve kernel: netlink_unicast+0x19c/0x240
Dec 20 18:26:19 pve kernel: netlink_sendmsg+0x2d7/0x3d0
Dec 20 18:26:24 pve kernel: sock_sendmsg+0x3e/0x50
Dec 20 18:26:27 pve kernel: SYSC_sendto+0x101/0x190
Code:
root@pve:~# journalctl -b -4
Dec 10 17:37:00 pve systemd[1]: Starting Proxmox VE replication runner...
Dec 10 17:37:01 pve sshd[31389]: Connection closed by 182.254.227.182 port 10465 [preauth]
Dec 10 17:37:01 pve CRON[31398]: pam_unix(cron:session): session opened for user root by (uid=0)
Dec 10 17:37:01 pve CRON[31399]: (root) CMD (/usr/local/rtm/bin/rtm 22 > /dev/null 2> /dev/null)
Dec 10 17:37:01 pve CRON[31398]: pam_unix(cron:session): session closed for user root
Dec 10 17:37:01 pve systemd[1]: Started Proxmox VE replication runner.
...skipping...
Dec 10 17:37:19 pve kernel: ? __kmalloc_node_track_caller+0x1f8/0x2b0
Dec 10 17:37:19 pve kernel: ? __alloc_skb+0x87/0x1c0
Dec 10 17:37:19 pve kernel: ? __netlink_lookup+0xd9/0x140
Dec 10 17:37:19 pve kernel: netlink_unicast+0x19c/0x240
Dec 10 17:37:19 pve kernel: netlink_sendmsg+0x2d7/0x3d0
Dec 10 17:37:19 pve kernel: sock_sendmsg+0x3e/0x50
Dec 10 17:37:19 pve kernel: SYSC_sendto+0x101/0x190
Dec 10 17:37:19 pve kernel: ? __secure_computing+0x3f/0x100
Dec 10 17:37:19 pve kernel: ? syscall_trace_enter+0xca/0x2e0
Dec 10 17:37:19 pve kernel: SyS_sendto+0xe/0x10
Dec 10 17:37:19 pve kernel: do_syscall_64+0x73/0x130
Dec 10 17:37:19 pve kernel: entry_SYSCALL_64_after_hwframe+0x3d/0xa2
Dec 10 17:37:19 pve kernel: RIP: 0033:0x7f507c89108b
Dec 10 17:37:19 pve kernel: RSP: 002b:00007ffd935277f8 EFLAGS: 00000246 ORIG_RAX: 000000000000002c
Dec 10 17:37:19 pve kernel: RAX: ffffffffffffffda RBX: 0000557cacbd5f70 RCX: 00007f507c89108b
Dec 10 17:37:19 pve kernel: RDX: 00000000000002c0 RSI: 0000557cacbd3c78 RDI: 0000000000000003
Dec 10 17:37:19 pve kernel: RBP: 0000557cacbd3c78 R08: 00007f507c95c000 R09: 000000000000000c
Dec 10 17:37:19 pve kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000001000
Dec 10 17:37:19 pve kernel: R13: 0000557cab980137 R14: 0000557cab98013f R15: 0000000000000000
Dec 10 17:37:19 pve kernel: Code: 89 50 0e 41 0f b6 45 42 a8 01 74 1a 48 8b 45 c0 49 03 5d 68 8b 40 28 85 c0 0f 85 e2 02 00 00 48 c7 03 00 00 00 00 f0 4d 0f ab 27 <49> 83 f9 fe 74 23 48 8b 7d 98
Dec 10 17:37:26 pve sshd[31583]: Invalid user suraj from 40.68.187.59 port 41904
Dec 10 17:37:26 pve sshd[31583]: input_userauth_request: invalid user suraj [preauth]
Dec 10 17:37:26 pve sshd[31583]: pam_unix(sshd:auth): check pass; user unknown
Dec 10 17:37:26 pve sshd[31583]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=40.68.187.59
Dec 10 17:37:28 pve sshd[31585]: Invalid user test3 from 191.179.16.4 port 44897
Dec 10 17:37:28 pve sshd[31585]: input_userauth_request: invalid user test3 [preauth]
Dec 10 17:37:28 pve sshd[31585]: pam_unix(sshd:auth): check pass; user unknown
Dec 10 17:37:28 pve sshd[31585]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=191.179.16.4
Dec 10 17:37:28 pve sshd[31583]: Failed password for invalid user suraj from 40.68.187.59 port 41904 ssh2
Dec 10 17:37:28 pve sshd[31583]: Received disconnect from 40.68.187.59 port 41904:11: Bye Bye [preauth]
Dec 10 17:37:28 pve sshd[31583]: Disconnected from 40.68.187.59 port 41904 [preauth]
Dec 10 17:37:31 pve sshd[31585]: Failed password for invalid user test3 from 191.179.16.4 port 44897 ssh2
Dec 10 17:37:32 pve sshd[31585]: Received disconnect from 191.179.16.4 port 44897:11: Bye Bye [preauth]
Dec 10 17:37:32 pve sshd[31585]: Disconnected from 191.179.16.4 port 44897 [preauth]
Dec 10 17:37:53 pve sshd[31701]: Did not receive identification string from 190.0.10.138 port 58266
Dec 10 17:38:05 pve systemd[1]: Starting Proxmox VE replication runner...
Dec 10 17:38:40 pve kernel: INFO: task ipset:30810 blocked for more than 120 seconds.
Dec 10 17:38:41 pve kernel: Tainted: P O L 4.15.18-9-pve #1
Dec 10 17:39:01 pve kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 10 17:39:02 pve kernel: ipset D 0 30810 1830 0x00000000
Dec 10 17:39:06 pve kernel: Call Trace:
Dec 10 17:39:17 pve kernel: __schedule+0x3e0/0x870
Dec 10 17:39:20 pve kernel: schedule+0x36/0x80
Dec 10 17:39:27 pve kernel: schedule_preempt_disabled+0xe/0x10
Dec 10 17:39:30 pve kernel: __mutex_lock.isra.2+0x2b1/0x4e0
Dec 10 17:39:35 pve kernel: ? mem_cgroup_commit_charge+0x82/0x540
...skipping...
Dec 10 17:37:19 pve kernel: ? __kmalloc_node_track_caller+0x1f8/0x2b0
Dec 10 17:37:19 pve kernel: ? __alloc_skb+0x87/0x1c0
Dec 10 17:37:19 pve kernel: ? __netlink_lookup+0xd9/0x140
Dec 10 17:37:19 pve kernel: netlink_unicast+0x19c/0x240
Dec 10 17:37:19 pve kernel: netlink_sendmsg+0x2d7/0x3d0
Dec 10 17:37:19 pve kernel: sock_sendmsg+0x3e/0x50
Dec 10 17:37:19 pve kernel: SYSC_sendto+0x101/0x190
Dec 10 17:37:19 pve kernel: ? __secure_computing+0x3f/0x100
Dec 10 17:37:19 pve kernel: ? syscall_trace_enter+0xca/0x2e0
Dec 10 17:37:19 pve kernel: SyS_sendto+0xe/0x10
Dec 10 17:37:19 pve kernel: do_syscall_64+0x73/0x130
Dec 10 17:37:19 pve kernel: entry_SYSCALL_64_after_hwframe+0x3d/0xa2
Dec 10 17:37:19 pve kernel: RIP: 0033:0x7f507c89108b
Dec 10 17:37:19 pve kernel: RSP: 002b:00007ffd935277f8 EFLAGS: 00000246 ORIG_RAX: 000000000000002c
Dec 10 17:37:19 pve kernel: RAX: ffffffffffffffda RBX: 0000557cacbd5f70 RCX: 00007f507c89108b
Dec 10 17:37:19 pve kernel: RDX: 00000000000002c0 RSI: 0000557cacbd3c78 RDI: 0000000000000003
Dec 10 17:37:19 pve kernel: RBP: 0000557cacbd3c78 R08: 00007f507c95c000 R09: 000000000000000c
Dec 10 17:37:19 pve kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000001000
Dec 10 17:37:19 pve kernel: R13: 0000557cab980137 R14: 0000557cab98013f R15: 0000000000000000
Dec 10 17:37:19 pve kernel: Code: 89 50 0e 41 0f b6 45 42 a8 01 74 1a 48 8b 45 c0 49 03 5d 68 8b 40 28 85 c0 0f 85 e2 02 00 00 48 c7 03 00 00 00 00 f0 4d 0f ab 27 <49> 83 f9 fe 74 23 48 8b 7d 98
Dec 10 17:37:26 pve sshd[31583]: Invalid user suraj from 40.68.187.59 port 41904
Dec 10 17:37:26 pve sshd[31583]: input_userauth_request: invalid user suraj [preauth]
Dec 10 17:37:26 pve sshd[31583]: pam_unix(sshd:auth): check pass; user unknown
Dec 10 17:37:26 pve sshd[31583]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=40.68.187.59
Dec 10 17:37:28 pve sshd[31585]: Invalid user test3 from 191.179.16.4 port 44897
Dec 10 17:37:28 pve sshd[31585]: input_userauth_request: invalid user test3 [preauth]
Dec 10 17:37:28 pve sshd[31585]: pam_unix(sshd:auth): check pass; user unknown
Dec 10 17:37:28 pve sshd[31585]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=191.179.16.4
Dec 10 17:37:28 pve sshd[31583]: Failed password for invalid user suraj from 40.68.187.59 port 41904 ssh2
Dec 10 17:37:28 pve sshd[31583]: Received disconnect from 40.68.187.59 port 41904:11: Bye Bye [preauth]
Dec 10 17:37:28 pve sshd[31583]: Disconnected from 40.68.187.59 port 41904 [preauth]
Dec 10 17:37:31 pve sshd[31585]: Failed password for invalid user test3 from 191.179.16.4 port 44897 ssh2
Dec 10 17:37:32 pve sshd[31585]: Received disconnect from 191.179.16.4 port 44897:11: Bye Bye [preauth]
Dec 10 17:37:32 pve sshd[31585]: Disconnected from 191.179.16.4 port 44897 [preauth]
Dec 10 17:37:53 pve sshd[31701]: Did not receive identification string from 190.0.10.138 port 58266
Dec 10 17:38:05 pve systemd[1]: Starting Proxmox VE replication runner...
Dec 10 17:38:40 pve kernel: INFO: task ipset:30810 blocked for more than 120 seconds.
Dec 10 17:38:41 pve kernel: Tainted: P O L 4.15.18-9-pve #1
Dec 10 17:39:01 pve kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 10 17:39:02 pve kernel: ipset D 0 30810 1830 0x00000000
Dec 10 17:39:06 pve kernel: Call Trace:
Dec 10 17:39:17 pve kernel: __schedule+0x3e0/0x870
Dec 10 17:39:20 pve kernel: schedule+0x36/0x80
Dec 10 17:39:27 pve kernel: schedule_preempt_disabled+0xe/0x10
Dec 10 17:39:30 pve kernel: __mutex_lock.isra.2+0x2b1/0x4e0
Dec 10 17:39:35 pve kernel: ? mem_cgroup_commit_charge+0x82/0x540