Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

WARNING in skb_release_head_state #2230

Open
const-t opened this issue Sep 2, 2024 · 4 comments
Open

WARNING in skb_release_head_state #2230

const-t opened this issue Sep 2, 2024 · 4 comments
Assignees
@EvgeniiMekhanik
Labels
bug
Milestone
0.8 - Beta

Comments

@const-t
Copy link
Contributor

const-t commented Sep 2, 2024

During analyzing CI logs found the WARNING.

Faced on tests: t_stress.test_stress.RequestStress.test_http_post_request

Aug 30 16:25:26 192.168.50.130 [83945.935414] WARNING: CPU: 0 PID: 0 at net/core/skbuff.c:896 skb_release_head_state+0x81/0x90
Aug 30 16:25:26 192.168.50.130 [83945.935414] Modules linked in: tempesta_fw(OE) tempesta_db(OE) tempesta_tls(OE) tempesta_lib(OE) xt_mark nft_compat tcp_diag inet_diag veth sha256_ssse3 sha512_ssse3 tls vhost_vsock vmw_vsock_virtio_transport_common vhost vhost_iotlb vsock nft_masq nft_counter nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 bridge stp llc nf_tables nfnetlink sch_fq_codel kvm_amd ccp kvm binfmt_misc joydev input_leds mac_hid serio_raw qemu_fw_cfg netconsole dm_multipath scsi_dh_rdac scsi_dh_emc scsi_dh_alua ramoops msr reed_solomon efi_pstore ip_tables x_tables autofs4 btrfs blake2b_generic zstd_compress raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multipath linear hid_generic usbhid hid crct10dif_pclmul crc32_pclmul bochs_drm drm_vram_helper drm_ttm_helper ghash_clmulni_intel aesni_intel crypto_simd ttm drm_kms_helper cryptd glue_helper syscopyarea sysfillrect sysimgblt fb_sys_fops cec psmouse virtio_scsi virtio_net drm
Aug 30 16:25:26 192.168.50.130 [83945.935445]  net_failover failover pata_acpi i2c_piix4 floppy [last unloaded: tempesta_lib]
Aug 30 16:25:26 192.168.50.130 [83945.935451] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G           OE     5.10.35.tfw-1d07dc5 #1
Aug 30 16:25:26 192.168.50.130 [83945.935452] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
Aug 30 16:25:26 192.168.50.130 [83945.935453] RIP: 0010:skb_release_head_state+0x81/0x90
Aug 30 16:25:26 192.168.50.130 [83945.935454] Code: 75 0e 5b 5d c3 e8 df 3a 0a 00 80 7b 7f 00 74 f2 48 8b bb e0 00 00 00 e8 5d e6 ff ff 5b 5d c3 48 83 e7 fe e8 f1 20 02 00 eb 9b <0f> 0b eb b7 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55 48
Aug 30 16:25:26 192.168.50.130 [83945.935454] RSP: 0018:ffffab1980003640 EFLAGS: 00010006
Aug 30 16:25:26 192.168.50.130 [83945.935455] RAX: ffffffffb0e31d90 RBX: ffff8a1eba977868 RCX: ffff8a1df3e03000
Aug 30 16:25:26 192.168.50.130 [83945.935456] RDX: 0000000000010000 RSI: 0000000000000001 RDI: 0000000000000000
Aug 30 16:25:26 192.168.50.130 [83945.935457] RBP: ffffab1980003648 R08: 0000000000000001 R09: ffffffffb0abcc00
Aug 30 16:25:26 192.168.50.130 [83945.935457] R10: ffff8a1d659e3100 R11: 0000000000000001 R12: ffff8a1eba977868
Aug 30 16:25:26 192.168.50.130 [83945.935458] R13: 00000000000027da R14: ffff8a1df201c800 R15: 0000000000000001
Aug 30 16:25:26 192.168.50.130 [83945.935458] FS:  0000000000000000(0000) GS:ffff8a1ef7c00000(0000) knlGS:0000000000000000
Aug 30 16:25:26 192.168.50.130 [83945.935459] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 30 16:25:26 192.168.50.130 [83945.935459] CR2: 00007f5087f0ddd0 CR3: 0000000128858006 CR4: 0000000000770ef0
Aug 30 16:25:26 192.168.50.130 [83945.935460] PKRU: 55555554
Aug 30 16:25:26 192.168.50.130 [83945.935460] Call Trace:
Aug 30 16:25:26 192.168.50.130 [83945.935460]  <IRQ>
Aug 30 16:25:26 192.168.50.130 [83945.935461]  skb_release_all+0x13/0x30
Aug 30 16:25:26 192.168.50.130 [83945.935461]  napi_consume_skb+0xb3/0x1b0
Aug 30 16:25:26 192.168.50.130 [83945.935462]  free_old_xmit_skbs+0x4e/0xd0 [virtio_net]
Aug 30 16:25:26 192.168.50.130 [83945.935462]  virtnet_poll_tx+0x87/0x100 [virtio_net]
Aug 30 16:25:26 192.168.50.130 [83945.935463]  netpoll_poll_dev+0xc7/0x180
Aug 30 16:25:26 192.168.50.130 [83945.935463]  netpoll_send_skb+0x194/0x270
Aug 30 16:25:26 192.168.50.130 [83945.935464]  netpoll_send_udp+0x2b2/0x3d0
Aug 30 16:25:26 192.168.50.130 [83945.935464]  write_msg+0xd9/0xf0 [netconsole]
Aug 30 16:25:26 192.168.50.130 [83945.935464]  console_unlock+0x3c3/0x510
Aug 30 16:25:26 192.168.50.130 [83945.935465]  wake_up_klogd_work_func+0x40/0x60
Aug 30 16:25:26 192.168.50.130 [83945.935465]  irq_work_single+0x34/0x50
Aug 30 16:25:26 192.168.50.130 [83945.935466]  irq_work_run_list+0x31/0x40
Aug 30 16:25:26 192.168.50.130 [83945.935466]  irq_work_run+0x2c/0x30
Aug 30 16:25:26 192.168.50.130 [83945.935466]  __sysvec_irq_work+0x30/0xa0
Aug 30 16:25:26 192.168.50.130 [83945.935467]  sysvec_irq_work+0x38/0x90
Aug 30 16:25:26 192.168.50.130 [83945.935467]  asm_sysvec_irq_work+0x12/0x20
Aug 30 16:25:26 192.168.50.130 [83945.935468] RIP: 0010:_raw_spin_unlock_irqrestore+0x15/0x20
Aug 30 16:25:26 192.168.50.130 [83945.935469] Code: ff 7f 5b 44 89 f0 41 5c 41 5d 41 5e 41 5f 5d c3 cc cc cc cc cc 0f 1f 44 00 00 55 48 89 e5 e8 66 11 57 ff 66 90 48 89 f7 57 9d <0f> 1f 44 00 00 5d c3 0f 1f 40 00 0f 1f 44 00 00 55 49 89 f8 b8 00
Aug 30 16:25:26 192.168.50.130 [83945.935469] RSP: 0018:ffffab1980003a58 EFLAGS: 00000206
Aug 30 16:25:26 192.168.50.130 [83945.935470] RAX: 0000000000000001 RBX: ffffab1980003b58 RCX: 0000000000000027
Aug 30 16:25:26 192.168.50.130 [83945.935471] RDX: 0000000000000001 RSI: 0000000000000206 RDI: 0000000000000206
Aug 30 16:25:26 192.168.50.130 [83945.935471] RBP: ffffab1980003a58 R08: ffff8a1ef7c18a40 R09: 0000000100104e5b
Aug 30 16:25:26 192.168.50.130 [83945.935472] R10: 0000000000000001 R11: ffffffffb1a6c468 R12: ffffffffb1cdae00
Aug 30 16:25:26 192.168.50.130 [83945.935472] R13: 0000000000000001 R14: ffffffffb152d8a0 R15: 0000000000000206
Aug 30 16:25:26 192.168.50.130 [83945.935473]  ___ratelimit+0xad/0x110
Aug 30 16:25:26 192.168.50.130 [83945.935473]  net_ratelimit+0x1c/0x20
Aug 30 16:25:26 192.168.50.130 [83945.935474]  tfw_http_send_err_resp+0xe0/0x100 [tempesta_fw]
Aug 30 16:25:26 192.168.50.130 [83945.935474]  tfw_http_req_zap_error+0x4d/0xd0 [tempesta_fw]
Aug 30 16:25:26 192.168.50.130 [83945.935474]  tfw_http_conn_repair+0x2c1/0xb20 [tempesta_fw]
Aug 30 16:25:26 192.168.50.130 [83945.935475]  ? __sk_dst_check+0x35/0x70
Aug 30 16:25:26 192.168.50.130 [83945.935475]  ? kvm_clock_get_cycles+0x11/0x20
Aug 30 16:25:26 192.168.50.130 [83945.935476]  tfw_connection_repair+0x25/0x30 [tempesta_fw]
Aug 30 16:25:26 192.168.50.130 [83945.935476]  tfw_sock_srv_connect_complete+0x103/0x110 [tempesta_fw]
Aug 30 16:25:26 192.168.50.130 [83945.935477]  ss_tcp_state_change+0xf2/0x240 [tempesta_fw]
Aug 30 16:25:26 192.168.50.130 [83945.935477]  tcp_rcv_state_process+0x64b/0x1120
Aug 30 16:25:26 192.168.50.130 [83945.935478]  ? security_sock_rcv_skb+0x2f/0x50
Aug 30 16:25:26 192.168.50.130 [83945.935478]  ? tcp_v4_inbound_md5_hash+0x4e/0x160
Aug 30 16:25:26 192.168.50.130 [83945.935479]  tcp_v4_do_rcv+0xc4/0x200
Aug 30 16:25:26 192.168.50.130 [83945.935479]  tcp_v4_rcv+0xcfd/0xe10
Aug 30 16:25:26 192.168.50.130 [83945.935479]  ip_protocol_deliver_rcu+0x30/0x1b0
Aug 30 16:25:26 192.168.50.130 [83945.935480]  ip_local_deliver_finish+0x48/0x60
Aug 30 16:25:26 192.168.50.130 [83945.935480]  ip_local_deliver+0xfa/0x110
Aug 30 16:25:26 192.168.50.130 [83945.935481]  ? ip_protocol_deliver_rcu+0x1b0/0x1b0
Aug 30 16:25:26 192.168.50.130 [83945.935481]  ip_rcv_finish+0x87/0xa0
Aug 30 16:25:26 192.168.50.130 [83945.935481]  ip_rcv+0xcc/0xe0
Aug 30 16:25:26 192.168.50.130 [83945.935482]  ? ip_rcv_finish_core.isra.0+0x420/0x420
Aug 30 16:25:26 192.168.50.130 [83945.935482]  __netif_receive_skb_one_core+0x88/0xa0
Aug 30 16:25:26 192.168.50.130 [83945.935483]  __netif_receive_skb+0x18/0x60
Aug 30 16:25:26 192.168.50.130 [83945.935483]  process_backlog+0xa9/0x160
Aug 30 16:25:26 192.168.50.130 [83945.935483]  net_rx_action+0x13e/0x390
Aug 30 16:25:26 192.168.50.130 [83945.935484]  __do_softirq+0xd9/0x291
Aug 30 16:25:26 192.168.50.130 [83945.935484]  asm_call_irq_on_stack+0x12/0x20
Aug 30 16:25:26 192.168.50.130 [83945.935485]  </IRQ>
Aug 30 16:25:26 192.168.50.130 [83945.935485]  do_softirq_own_stack+0x3d/0x50
Aug 30 16:25:26 192.168.50.130 [83945.935485]  irq_exit_rcu+0xa4/0xb0
Aug 30 16:25:26 192.168.50.130 [83945.935486]  sysvec_call_function_single+0x3d/0x90
Aug 30 16:25:26 192.168.50.130 [83945.935486]  asm_sysvec_call_function_single+0x12/0x20
Aug 30 16:25:26 192.168.50.130 [83945.935487] RIP: 0010:native_safe_halt+0xe/0x10
Aug 30 16:25:26 192.168.50.130 [83945.935488] Code: 7b ff ff ff eb bd cc cc cc cc cc cc e9 07 00 00 00 0f 00 2d c6 9e 47 00 f4 c3 66 90 e9 07 00 00 00 0f 00 2d b6 9e 47 00 fb f4 <c3> cc 0f 1f 44 00 00 55 48 89 e5 53 65 8b 15 3f ed 07 4f 0f 1f 44
Aug 30 16:25:26 192.168.50.130 [83945.935488] RSP: 0018:ffffffffb1a03e28 EFLAGS: 00000212
Aug 30 16:25:26 192.168.50.130 [83945.935489] RAX: ffffffffb0f92690 RBX: 0000000000000000 RCX: ffff8a1ef7c2cdc0
Aug 30 16:25:26 192.168.50.130 [83945.935490] RDX: 000000000b753a0e RSI: 00004c590e29fb71 RDI: 0000000000000082
Aug 30 16:25:26 192.168.50.130 [83945.935490] RBP: ffffffffb1a03e30 R08: 000000cd42e4dffb R09: 00004c590ee11671
Aug 30 16:25:26 192.168.50.130 [83945.935492] R10: 0000000000000007 R11: 000000000000001f R12: ffffffffb1a13940
Aug 30 16:25:26 192.168.50.130 [83945.935493] R13: ffffffffb1a13940 R14: 0000000000000000 R15: 0000000000000000
Aug 30 16:25:26 192.168.50.130 [83945.935494]  ? __cpuidle_text_start+0x8/0x8
Aug 30 16:25:26 192.168.50.130 [83945.935495]  ? default_idle+0xe/0x20
Aug 30 16:25:26 192.168.50.130 [83945.935496]  arch_cpu_idle+0x15/0x20
Aug 30 16:25:26 192.168.50.130 [83945.935498]  default_idle_call+0x38/0xc0
Aug 30 16:25:26 192.168.50.130 [83945.935499]  do_idle+0x1f8/0x260
Aug 30 16:25:26 192.168.50.130 [83945.935500]  cpu_startup_entry+0x20/0x30
Aug 30 16:25:26 192.168.50.130 [83945.935501]  rest_init+0xb8/0xba
Aug 30 16:25:26 192.168.50.130 [83945.935502]  arch_call_rest_init+0xe/0x1b
Aug 30 16:25:26 192.168.50.130 [83945.935503]  start_kernel+0x5a3/0x5c5
Aug 30 16:25:26 192.168.50.130 [83945.935504]  x86_64_start_reservations+0x24/0x26
Aug 30 16:25:26 192.168.50.130 [83945.935505]  x86_64_start_kernel+0x75/0x79
Aug 30 16:25:26 192.168.50.130 [83945.935506]  secondary_startup_64_no_verify+0xb0/0xbb
Aug 30 16:25:26 192.168.50.130 [83945.935508] ---[ end trace 64f2943cac41bf1c ]---
@const-t const-t added the bug label Sep 2, 2024
@const-t const-t added this to the 0.9 - LA milestone Sep 2, 2024
@EvgeniiMekhanik EvgeniiMekhanik self-assigned this Sep 13, 2024
@ai-tmpst
Copy link
Contributor

Looks this is not the fault of Tempesta FW but a virtio-net bug.
There are a couple of links with discussions of this:
https://lists.linbit.com/pipermail/drbd-user/2009-October/012826.html
https://marc.info/?l=linux-netdev&m=125542939211671

@krizhanovsky
Copy link
Contributor

Both the links are 15 years old, so didn't netconsole fix this? I'm not sure if we should work on the upsream fix for this...

@ai-tmpst
Copy link
Contributor

I think there is not the same bug but a similar one.
dev_kfree_skb_any() call was replaced by napi_consume_skb(). It looks like the function takes into account its context and can be called from IRQ, but in this case something went wrong and __kfree_skb() was executed leading to the warning.

free_old_xmit_skbs
	napi_consume_skb
		__kfree_skb
			skb_release_all
				skb_release_head_state

In any case I don't think it relates to Tempesta FW and we shouldn't fix it.

@EvgeniiMekhanik
Copy link
Contributor

I look this warning a lot of times when I run new flood tests on remote. It seems we should check that:

  • skb which causes warning is not pass through Tempesta FW code.
  • Check what is this skb and why it have destructor?
  • Releasing of this skb is called from Tempesta code! (see trace (seems from console unlock from irq context))

@krizhanovsky krizhanovsky modified the milestones: 0.9 - LA, 0.8 - Beta Nov 19, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@EvgeniiMekhanik EvgeniiMekhanik

Labels
bug
Projects
None yet
Milestone
0.8 - Beta
Development

No branches or pull requests
4 participants
@krizhanovsky @const-t @EvgeniiMekhanik @ai-tmpst