Page MenuHomeVyOS Platform

Intel QAT causes CPU runaway/stall with ipsec VPN
Open, NormalPublicBUG

Description

I had a stall/deadlock seemingly take down my system this morning. I’m on a custom build forked off of 1.5 rolling somewhere around March 10th. Seems to be something around xfrm4_input so may be related to ipsec VPN/VTI interfaces
10:02
I had been testing some code around reloading the ipsec daemon when DHCP IPs change. That action itself doesn’t seem to be related (as far as I can tell, there was no DHCP renew around the time the CPU started spinning out of control), but could be some internal bug in strongswan where repeated reload actions don’t clean up correctly or something.
Notably there are a lot of logs around sending dead-peer detection to one particular peer right before the stall detection starts kicking in.

Mar 18 16:44:56 lcn-router kernel: rcu: INFO: rcu_preempt self-detected stall on CPU
Mar 18 16:44:56 lcn-router kernel: rcu:         4-....: (17 GPs behind) idle=59b4/1/0x4000000000000000 softirq=1266>
Mar 18 16:44:56 lcn-router kernel: rcu:         (t=588507 jiffies g=7635657 q=24585 ncpus=12)
Mar 18 16:44:56 lcn-router kernel: CPU: 4 PID: 145 Comm: kworker/4:1H Tainted: G        W  O L     6.6.21-amd64-vyo>
Mar 18 16:44:56 lcn-router kernel: Hardware name: Supermicro Super Server/A2SDi-TP8F, BIOS 1.4 01/29/2021
Mar 18 16:44:56 lcn-router kernel: Workqueue: adf_pf_resp_wq_0 adf_response_handler_wq [intel_qat]
Mar 18 16:44:56 lcn-router kernel: RIP: 0010:native_queued_spin_lock_slowpath+0x65/0x2b0
Mar 18 16:44:56 lcn-router kernel: Code: 77 77 f0 0f ba 2b 08 0f 92 c2 8b 03 0f b6 d2 c1 e2 08 30 e4 09 d0 3d ff 00>
Mar 18 16:44:56 lcn-router kernel: RSP: 0018:ffffa932801dcb00 EFLAGS: 00000202
Mar 18 16:44:56 lcn-router kernel: RAX: 0000000000000001 RBX: ffff9851c789f04c RCX: ffff9851c789f048
Mar 18 16:44:56 lcn-router kernel: RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffff9851c789f04c
Mar 18 16:44:56 lcn-router kernel: RBP: ffffa932801dcb98 R08: 00000000f51784c0 R09: 0000000000000002
Mar 18 16:44:56 lcn-router kernel: R10: 0000000000000005 R11: ffff9851b4213908 R12: ffff985200187700
Mar 18 16:44:56 lcn-router kernel: R13: 0000000000000002 R14: ffff9851c789f000 R15: ffff9851c789f04c
Mar 18 16:44:56 lcn-router kernel: FS:  0000000000000000(0000) GS:ffff9854efb00000(0000) knlGS:0000000000000000
Mar 18 16:44:56 lcn-router kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar 18 16:44:56 lcn-router kernel: CR2: 00007fa140001828 CR3: 0000000103e34000 CR4: 00000000003506e0
Mar 18 16:44:56 lcn-router kernel: Call Trace:
Mar 18 16:44:56 lcn-router kernel:  <IRQ>
Mar 18 16:44:56 lcn-router kernel:  ? rcu_dump_cpu_stacks+0xbf/0x100
Mar 18 16:44:56 lcn-router kernel:  ? rcu_sched_clock_irq+0x652/0x1160
Mar 18 16:44:56 lcn-router kernel:  ? nohz_balance_exit_idle+0x11/0xc0
Mar 18 16:44:56 lcn-router kernel:  ? account_process_tick+0x26/0x140
Mar 18 16:44:56 lcn-router kernel:  ? update_process_times+0x5d/0x90
Mar 18 16:44:56 lcn-router kernel:  ? tick_sched_timer+0x7a/0xb0
Mar 18 16:44:56 lcn-router kernel:  ? __pfx_tick_sched_timer+0x10/0x10
Mar 18 16:44:56 lcn-router kernel:  ? __hrtimer_run_queues+0x10d/0x2a0
Mar 18 16:44:56 lcn-router kernel:  ? hrtimer_interrupt+0xf9/0x230
Mar 18 16:44:56 lcn-router kernel:  ? __sysvec_apic_timer_interrupt+0x69/0x170
Mar 18 16:44:56 lcn-router kernel:  ? sysvec_apic_timer_interrupt+0x39/0xb0
Mar 18 16:44:56 lcn-router kernel:  ? asm_sysvec_apic_timer_interrupt+0x16/0x20
Mar 18 16:44:56 lcn-router kernel:  ? native_queued_spin_lock_slowpath+0x65/0x2b0
Mar 18 16:44:56 lcn-router kernel:  _raw_spin_lock+0x2b/0x40
Mar 18 16:44:56 lcn-router kernel:  xfrm_input+0x1ef/0x1210
Mar 18 16:44:56 lcn-router kernel:  xfrm4_esp_rcv+0x2f/0x70
Mar 18 16:44:56 lcn-router kernel:  ip_protocol_deliver_rcu+0x187/0x190
Mar 18 16:44:56 lcn-router kernel:  ip_local_deliver_finish+0x6d/0x90
Mar 18 16:44:56 lcn-router kernel:  ip_sublist_rcv_finish+0x79/0x90
Mar 18 16:44:56 lcn-router kernel:  ip_sublist_rcv+0x190/0x230
Mar 18 16:44:56 lcn-router kernel:  ? __pfx_ip_rcv_finish+0x10/0x10
Mar 18 16:44:56 lcn-router kernel:  ip_list_rcv+0x134/0x160
Mar 18 16:44:56 lcn-router kernel:  __netif_receive_skb_list_core+0x299/0x2c0
Mar 18 16:44:56 lcn-router kernel:  netif_receive_skb_list_internal+0x1ac/0x2e0
Mar 18 16:44:56 lcn-router kernel:  napi_complete_done+0x69/0x1a0
Mar 18 16:44:56 lcn-router kernel:  igc_poll+0x62f/0x1790 [igc]
Mar 18 16:44:56 lcn-router kernel:  __napi_poll+0x26/0x1b0
Mar 18 16:44:56 lcn-router kernel:  net_rx_action+0x147/0x2c0
Mar 18 16:44:56 lcn-router kernel:  __do_softirq+0xeb/0x2ef
Mar 18 16:44:56 lcn-router kernel:  __irq_exit_rcu+0x71/0xc0
Mar 18 16:44:56 lcn-router kernel:  common_interrupt+0xa5/0xc0
Mar 18 16:44:56 lcn-router kernel:  </IRQ>
Mar 18 16:44:56 lcn-router kernel:  <TASK>
Mar 18 16:44:56 lcn-router kernel:  asm_common_interrupt+0x22/0x40
Mar 18 16:44:56 lcn-router kernel: RIP: 0010:xfrm_replay_recheck+0x0/0x90
Mar 18 16:44:56 lcn-router kernel: Code: 83 f8 01 74 0a 83 f8 02 74 0a e9 9b f8 ff ff e9 e6 f6 ff ff e9 a1 f7 ff ff>
Mar 18 16:44:56 lcn-router kernel: RSP: 0018:ffffa93280acfd88 EFLAGS: 00000202
Mar 18 16:44:56 lcn-router kernel: RAX: 0000000000000004 RBX: 00000000b1000000 RCX: ffff98518cba0000
Mar 18 16:44:56 lcn-router kernel: RDX: 00000000b1000000 RSI: ffff985200187d00 RDI: ffff9851c789f000
Mar 18 16:44:56 lcn-router kernel: RBP: ffffa93280acfdf0 R08: 0000000000000004 R09: 0000000000000004
Mar 18 16:44:56 lcn-router kernel: R10: ffffffffaf6060e0 R11: ffffffffafe0ecc0 R12: ffff985200187d00
Mar 18 16:44:56 lcn-router kernel: R13: 0000000000000002 R14: ffff9851c789f000 R15: ffff9851c789f04c
Mar 18 16:44:56 lcn-router kernel:  xfrm_input+0x4ca/0x1210
Mar 18 16:44:56 lcn-router kernel:  qat_alg_callback+0x18/0x30 [intel_qat]
Mar 18 16:44:56 lcn-router kernel:  adf_handle_response+0x40/0xc0 [intel_qat]
Mar 18 16:44:56 lcn-router kernel:  adf_response_handler_wq+0x6c/0xc0 [intel_qat]
Mar 18 16:44:56 lcn-router kernel:  process_one_work+0x16f/0x340
Mar 18 16:44:56 lcn-router kernel:  worker_thread+0x272/0x390
Mar 18 16:44:56 lcn-router kernel:  ? preempt_count_add+0x65/0xa0
Mar 18 16:44:56 lcn-router kernel:  ? __pfx_worker_thread+0x10/0x10
Mar 18 16:44:56 lcn-router kernel:  kthread+0xee/0x120
Mar 18 16:44:56 lcn-router kernel:  ? __pfx_kthread+0x10/0x10
Mar 18 16:44:56 lcn-router kernel:  ret_from_fork+0x2b/0x40
Mar 18 16:44:56 lcn-router kernel:  ? __pfx_kthread+0x10/0x10
Mar 18 16:44:56 lcn-router kernel:  ret_from_fork_asm+0x1b/0x30
Mar 18 16:44:56 lcn-router kernel:  </TASK>

Details

Version
Fork of 1.5-rolling-202403100025
Is it a breaking change?
Unspecified (possibly destroys the router)
Issue type
Bug (incorrect behavior)

Event Timeline

Viacheslav triaged this task as Normal priority.Mar 27 2024, 5:05 PM
Viacheslav added a project: VyOS 1.5 Circinus.

Offending driver is intel_qat - try disabling QAT first.

My system finally crashed again today. I found a workload that generates enough traffic over the VPN to reliably re-produce.

It does appear to be QAT. After disabling QAT it crashed again, but disabling QAT then rebooting with QAT never enabled seems to have it stable again.

lucasec renamed this task from CPU runaway/stall possibly related to Strongswan to Intel QAT causes CPU runaway/stall with ipsec VPN.Apr 14 2024, 11:36 PM

I was hoping some combination of the newer QAT driver 4.24 and newer kernel in the latest rolling releases might fix this... but seemingly not.

Given that this stall occurs in "xfrm_input", it may be unique to using the ipsec offload in combination with VTI interfaces.

I have the same problem, disable QAT also worked in my case. QAT drivers before 4.24 are working. So VyOS 1.4.0 is also affected

I've seen this a few times on the most recent 1.5x rolling releases. So far every stack trace has included the xfrm_input kernel function, so this tells me it is likely specific to when QAT is combined with the VTI feature (which switched from the vti interface type to xfrm type in 1.4).

Thanks for the empirical confirmation on 1.4.0 though. This is obviously a dangerous regression (since it tends to sporadically take down the entire router after weeks of stable runtime).

This issue appears to persist. I have been trying to run QAT with 8970 cards, and I am also running into this issue. Ultimately I have two separate instances of VyOS which exhibit the same lockup issue (separate hardware and locations). The frequency of the locks ups is far more frequent than what lucasec mentioned. Anywhere in the 12 hour range after a reboot the system crashes.

I was seeing this issue with the 4.24.0-00005 driver and ultimately upgraded to 4.27.0-00006 which exhibits the same issue.

The installs I am running are from the 202501060800 nightly build.

While I am interested in a resolution of this, I must say my forte does not lie in troubleshooting interrupts/spin lock issues within kernel modules, but if anyone has any changes they would like to have implemented and tested, I have the hardware to do so.

Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.626750] vmxnet3 0000:13:00.0 eth1: NETDEV WATCHDOG: CPU: 1: transmit queue 2 timed out 12347449 ms
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.629901] vmxnet3 0000:13:00.0 eth1: tx hang
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.632882] rcu: INFO: rcu_sched detected expedited stalls on CPUs/tasks: { 0-.... } 12343656 jiffies s: 545 root: 0x1/.
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.635987] rcu: blocking rcu_node structures (internal RCU debug):
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639006] Sending NMI from CPU 1 to CPUs 0:
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639036] NMI backtrace for cpu 0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639040] CPU: 0 PID: 56 Comm: kworker/0:1H Tainted: G           O L     6.6.69-vyos #1
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639046] Hardware name: VMware, Inc. VMware7,1/440BX Desktop Reference Platform, BIOS VMW71.00V.18227214.B64.2106252220 06/25/2021
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639050] Workqueue: adf_vf_resp_wq_ adf_response_handler_wq [intel_qat]
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639162] RIP: 0010:native_queued_spin_lock_slowpath+0x2b/0x260
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639173] Code: 55 41 54 55 53 48 89 fb 66 90 ba 01 00 00 00 8b 03 85 c0 75 13 f0 0f b1 13 85 c0 75 f2 5b 5d 41 5c 41 5d c3 cc cc cc cc f3 90 <eb> e3 81 fe 00 01 00 00 74 4a 81 fe ff 00 00 00 77 77 f0 0f ba 2b
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639177] RSP: 0018:ffffb44d80003ae8 EFLAGS: 00000202
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639182] RAX: 0000000000000001 RBX: ffff8ce4b44af34c RCX: ffff8ce4b44af348
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639186] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff8ce4b44af34c
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639189] RBP: ffffb44d80003b78 R08: 0000000069d34ec2 R09: 000000000000000a
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639193] R10: 0000000000000004 R11: ffff8ce4848f33c8 R12: 0000000000000002
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639197] R13: 000000000000000a R14: ffff8ce4b44af34c R15: ffff8ce4b44af300
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639201] FS:  0000000000000000(0000) GS:ffff8ce4bbc00000(0000) knlGS:0000000000000000
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639205] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639209] CR2: 0000559076aec3c0 CR3: 0000000105c50003 CR4: 00000000003706f0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639218] Call Trace:
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639221]  <NMI>
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639238]  ? nmi_cpu_backtrace+0x95/0x110
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639245]  ? nmi_cpu_backtrace_handler+0x8/0x10
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639253]  ? nmi_handle+0x4e/0x120
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639261]  ? default_do_nmi+0x44/0x250
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639267]  ? exc_nmi+0xfe/0x130
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639273]  ? end_repeat_nmi+0x16/0x67
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639286]  ? native_queued_spin_lock_slowpath+0x2b/0x260
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639294]  ? native_queued_spin_lock_slowpath+0x2b/0x260
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639302]  ? native_queued_spin_lock_slowpath+0x2b/0x260
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639310]  </NMI>
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639311]  <IRQ>
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639314]  _raw_spin_lock+0x19/0x20
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639320]  xfrm_input+0x1dc/0x11f0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639333]  xfrm6_rcv_encap+0xec/0x1e0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639344]  ? __pfx_xfrm6_udp_encap_rcv+0x10/0x10
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639352]  udpv6_queue_rcv_one_skb+0x259/0x520
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639361]  udp6_unicast_rcv_skb+0x40/0xa0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639369]  ip6_protocol_deliver_rcu+0x181/0x480
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639377]  ip6_input_finish+0x35/0x60
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639384]  ip6_sublist_rcv_finish+0x54/0x90
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639392]  ip6_sublist_rcv+0x236/0x2d0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639399]  ? __pfx_ip6_rcv_finish+0x10/0x10
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639407]  ipv6_list_rcv+0x136/0x160
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639416]  __netif_receive_skb_list_core+0x1f1/0x2c0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639429]  netif_receive_skb_list_internal+0x1a7/0x2d0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639437]  napi_complete_done+0x69/0x1a0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639443]  vmxnet3_poll_rx_only+0x7b/0xa0 [vmxnet3]
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639480]  __napi_poll+0x23/0x1a0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639485]  net_rx_action+0x141/0x2c0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639490]  ? __napi_schedule+0xa7/0xb0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639498]  handle_softirqs+0xd2/0x280
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639505]  __irq_exit_rcu+0x68/0x90
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639509]  common_interrupt+0x7a/0xa0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639515]  </IRQ>
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639516]  <TASK>
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639518]  asm_common_interrupt+0x22/0x40
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639526] RIP: 0010:netlink_has_listeners+0x2e/0x60
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639535] Code: 03 00 00 a8 01 74 44 0f b7 87 04 02 00 00 48 8d 14 40 48 8d 04 90 31 d2 48 c1 e0 04 48 03 05 39 d8 d3 00 48 8b 88 90 00 00 00 <48> 85 c9 74 15 83 ee 01 3b b0 9c 00 00 00 73 0a 31 d2 48 0f a3 71
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639540] RSP: 0018:ffffb44d8069fd48 EFLAGS: 00000282
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639543] RAX: ffff8ce4803ca4e0 RBX: ffff8ce4b44af300 RCX: ffff8ce4b442b540
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639547] RDX: 0000000000000000 RSI: 0000000000000005 RDI: ffff8ce4b234a000
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639551] RBP: ffffb44d8069fdf0 R08: 0000000000000000 R09: 0000000000004bb7
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639554] R10: 0000000000000010 R11: ffffffff86427f80 R12: 00000000b74b0000
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639558] R13: 000000000000000a R14: ffff8ce4b44af34c R15: ffff8ce4b44af300
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639565]  ? skb_copy_bits+0x1da/0x210
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639571]  xfrm_replay_advance+0xf8/0x360
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639582]  xfrm_input+0x4ce/0x11f0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639592]  qat_alg_callback+0x15/0x30 [intel_qat]
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639711]  adf_handle_response+0x3d/0xc0 [intel_qat]
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639815]  adf_response_handler_wq+0x6c/0xc0 [intel_qat]
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639928]  process_one_work+0x175/0x310
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639936]  worker_thread+0x279/0x3a0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639944]  ? __pfx_worker_thread+0x10/0x10
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639949]  kthread+0xc4/0xf0
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639959]  ? __pfx_kthread+0x10/0x10
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639968]  ret_from_fork+0x28/0x40
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639974]  ? __pfx_kthread+0x10/0x10
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639983]  ret_from_fork_asm+0x1b/0x30
Jan 25 23:41:26 SB-VyOSVPN01 kernel: [13816.639995]  </TASK>

lockup.png (837×1 px, 260 KB)