tempesta icon indicating copy to clipboard operation
tempesta copied to clipboard

Tempesta fails with concurrent or several h2 PUT requests

Open RomanBelozerov opened this issue 3 years ago • 1 comments

Tempesta fails when:

  • received several requests curl -k --http2-prior-knowledge -X PUT -d '0' https://127.0.0.1:443/[1-5]
  • concurrent sending of requests

DMESG

[ 9101.347536] ------------[ cut here ]------------
[ 9101.347556] WARNING: CPU: 3 PID: 13008 at /root/tempesta/fw/hpack.c:1243 tfw_hpack_decode+0x1c5f/0x1c70 [tempesta_fw]
[ 9101.347557] Modules linked in: tempesta_fw(OE) tempesta_db(OE) tempesta_tls(OE) tempesta_lib(OE) nfnetlink_queue nfnetlink_log nfnetlink cfg80211 sha256_ssse3 sha512_ssse3 rfcomm bnep vsock_loopback vmw_vsock_virtio_transport_common vmw_vsock_vmci_transport vsock nls_iso8859_1 intel_rapl_msr intel_rapl_common crct10dif_pclmul ghash_clmulni_intel aesni_intel snd_ens1371 snd_ac97_codec crypto_simd gameport cryptd ac97_bus glue_helper snd_pcm btusb btrtl snd_seq_midi btbcm snd_seq_midi_event btintel snd_rawmidi bluetooth snd_seq snd_seq_device snd_timer joydev input_leds snd ecdh_generic ecc serio_raw vmw_balloon vmw_vmci soundcore sch_fq_codel vmwgfx mac_hid ttm drm_kms_helper cec rc_core fb_sys_fops syscopyarea sysfillrect sysimgblt ipmi_devintf ipmi_msghandler drm msr parport_pc ppdev lp parport pstore_blk ramoops reed_solomon pstore_zone efi_pstore ip_tables x_tables autofs4 hid_generic usbhid hid mptspi mptscsih mptbase psmouse ahci crc32_pclmul e1000 libahci scsi_transport_spi i2c_piix4
[ 9101.347598]  pata_acpi [last unloaded: tempesta_lib]
[ 9101.347601] CPU: 3 PID: 13008 Comm: curl Kdump: loaded Tainted: G        W  OE     5.10.35+ #1
[ 9101.347602] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 11/12/2020
[ 9101.347610] RIP: 0010:tfw_hpack_decode+0x1c5f/0x1c70 [tempesta_fw]
[ 9101.347611] Code: 89 cf 48 8b 45 a8 4c 89 ee 48 29 d7 48 c1 e6 0a 4c 89 c2 4c 01 cf 48 01 c6 48 c1 e7 05 48 01 c7 e8 76 ad d5 ff e9 ab fc ff ff <0f> 0b 41 bc fe ff ff ff e9 c4 ec ff ff 0f 1f 40 00 0f 1f 44 00 00
[ 9101.347612] RSP: 0018:ffffbc7640548850 EFLAGS: 00010216
[ 9101.347613] RAX: 0000000000000042 RBX: 0000000000000029 RCX: ffffa04df425b089
[ 9101.347614] RDX: 0000000000000054 RSI: 0000000000005550 RDI: ffffa04df3e2b027
[ 9101.347614] RBP: ffffbc76405488d8 R08: ffffa04df425b087 R09: 0000000000000040
[ 9101.347615] R10: ffffa04df3e2b020 R11: 0000000000000570 R12: 00000000ffffffff
[ 9101.347616] R13: ffffa04dd7d02ec0 R14: ffffa04df15b6020 R15: ffffa04dcfe53098
[ 9101.347617] FS:  00007f5130ec3f80(0000) GS:ffffa04ff5ec0000(0000) knlGS:0000000000000000
[ 9101.347617] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 9101.347618] CR2: 0000558559fa5e58 CR3: 00000000311a0001 CR4: 0000000000770ee0
[ 9101.347625] PKRU: 55555554
[ 9101.347626] Call Trace:
[ 9101.347627]  <IRQ>
[ 9101.347636]  tfw_h2_parse_req+0x51/0x1c0 [tempesta_fw]
[ 9101.347642]  ss_skb_process+0xf6/0x140 [tempesta_fw]
[ 9101.347647]  ? tfw_http_parse_req+0xe190/0xe190 [tempesta_fw]
[ 9101.347653]  ? tfw_http_parse_req+0xe190/0xe190 [tempesta_fw]
[ 9101.347658]  tfw_http_req_process+0x7f/0x960 [tempesta_fw]
[ 9101.347661]  ? alloc_pages_current+0x87/0xe0
[ 9101.347663]  ? __get_free_pages+0x11/0x40
[ 9101.347668]  ? tfw_pool_alloc_pages+0x47/0x50 [tempesta_fw]
[ 9101.347673]  ? __tfw_pool_new+0x2d/0x70 [tempesta_fw]
[ 9101.347677]  tfw_http_msg_process_generic+0x197/0x670 [tempesta_fw]
[ 9101.347682]  ? ss_skb_chop_head_tail+0xbb/0x1d0 [tempesta_fw]
[ 9101.347687]  ? ss_skb_process+0xf6/0x140 [tempesta_fw]
[ 9101.347691]  tfw_h2_frame_process+0x308/0x440 [tempesta_fw]
[ 9101.347696]  tfw_http_msg_process+0x42/0x50 [tempesta_fw]
[ 9101.347700]  tfw_connection_recv+0x59/0xa0 [tempesta_fw]
[ 9101.347704]  tfw_tls_connection_recv+0x19d/0x380 [tempesta_fw]
[ 9101.347709]  ss_tcp_process_data+0x1e7/0x3f0 [tempesta_fw]
[ 9101.347714]  ss_tcp_data_ready+0x44/0xb0 [tempesta_fw]
[ 9101.347717]  tcp_data_ready+0x2b/0xd0
[ 9101.347718]  tcp_rcv_established+0x5a7/0x670
[ 9101.347720]  tcp_v4_do_rcv+0x140/0x200
[ 9101.347721]  tcp_v4_rcv+0xcfd/0xe10
[ 9101.347722]  ip_protocol_deliver_rcu+0x30/0x1b0
[ 9101.347723]  ip_local_deliver_finish+0x48/0x60
[ 9101.347724]  ip_local_deliver+0x72/0x110
[ 9101.347729]  ? tfw_ipv4_nf_hook+0xb9/0x130 [tempesta_fw]
[ 9101.347730]  ip_rcv_finish+0x87/0xa0
[ 9101.347731]  ip_rcv+0xcc/0xe0
[ 9101.347732]  ? ip_rcv_finish_core.isra.0+0x420/0x420
[ 9101.347734]  __netif_receive_skb_one_core+0x88/0xa0
[ 9101.347735]  __netif_receive_skb+0x18/0x60
[ 9101.347736]  process_backlog+0xa9/0x160
[ 9101.347737]  net_rx_action+0x13e/0x390
[ 9101.347739]  __do_softirq+0xd9/0x291
[ 9101.347741]  asm_call_irq_on_stack+0xf/0x20
[ 9101.347742]  </IRQ>
[ 9101.347743]  do_softirq_own_stack+0x3d/0x50
[ 9101.347745]  do_softirq.part.0+0x46/0x50
[ 9101.347746]  __local_bh_enable_ip+0x50/0x60
[ 9101.347747]  ip_finish_output2+0x1ab/0x590
[ 9101.347749]  ? __cgroup_bpf_run_filter_skb+0x3c3/0x3d0
[ 9101.347751]  __ip_finish_output+0xd8/0x220
[ 9101.347751]  ip_finish_output+0x2d/0xb0
[ 9101.347752]  ip_output+0x7a/0x100
[ 9101.347753]  ? ip_finish_output+0x2d/0xb0
[ 9101.347754]  ip_local_out+0x3d/0x50
[ 9101.347755]  __ip_queue_xmit+0x17a/0x470
[ 9101.347757]  ? get_page_from_freelist+0xed8/0x1100
[ 9101.347758]  ip_queue_xmit+0x15/0x20
[ 9101.347759]  __tcp_transmit_skb+0xa94/0xc90
[ 9101.347760]  tcp_write_xmit+0x453/0x1350
[ 9101.347761]  __tcp_push_pending_frames+0x37/0x100
[ 9101.347762]  tcp_push+0xfc/0x100
[ 9101.347764]  tcp_sendmsg_locked+0xd36/0xe70
[ 9101.347765]  tcp_sendmsg+0x2d/0x50
[ 9101.347766]  inet_sendmsg+0x43/0x70
[ 9101.347768]  sock_sendmsg+0x5e/0x70
[ 9101.347769]  sock_write_iter+0x93/0xf0
[ 9101.347771]  new_sync_write+0x192/0x1b0
[ 9101.347772]  vfs_write+0x1ca/0x280
[ 9101.347773]  ksys_write+0xb1/0xe0
[ 9101.347774]  __x64_sys_write+0x1a/0x20
[ 9101.347775]  do_syscall_64+0x38/0x90
[ 9101.347776]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 9101.347778] RIP: 0033:0x7f51322e62f7
[ 9101.347779] Code: 75 05 48 83 c4 58 c3 e8 f7 33 ff ff 0f 1f 80 00 00 00 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
[ 9101.347779] RSP: 002b:00007ffddf5db4d8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 9101.347780] RAX: ffffffffffffffda RBX: 0000000000000036 RCX: 00007f51322e62f7
[ 9101.347781] RDX: 0000000000000036 RSI: 0000558559fa1da3 RDI: 0000000000000005
[ 9101.347781] RBP: 0000558559f60ad0 R08: 0000000000000001 R09: 0000000000000008
[ 9101.347782] R10: 0000558559fa1da5 R11: 0000000000000246 R12: 0000558559fa1da3
[ 9101.347782] R13: 0000000000000036 R14: 0000558559f5ee20 R15: 0000000000000000
[ 9101.347784] ---[ end trace 50b1b7ebb7b42b2f ]---
[ 9101.347785] net_ratelimit: 3923 callbacks suppressed
[ 9101.347786] [tempesta fw] Warning: failed to parse request: 127.0.0.1
[ 9101.347792] ------------[ cut here ]------------
[ 9101.347798] WARNING: CPU: 3 PID: 13008 at /root/tempesta/fw/http_stream.c:89 tfw_h2_stream_fsm+0x12d/0x2b0 [tempesta_fw]
[ 9101.347798] Modules linked in: tempesta_fw(OE) tempesta_db(OE) tempesta_tls(OE) tempesta_lib(OE) nfnetlink_queue nfnetlink_log nfnetlink cfg80211 sha256_ssse3 sha512_ssse3 rfcomm bnep vsock_loopback vmw_vsock_virtio_transport_common vmw_vsock_vmci_transport vsock nls_iso8859_1 intel_rapl_msr intel_rapl_common crct10dif_pclmul ghash_clmulni_intel aesni_intel snd_ens1371 snd_ac97_codec crypto_simd gameport cryptd ac97_bus glue_helper snd_pcm btusb btrtl snd_seq_midi btbcm snd_seq_midi_event btintel snd_rawmidi bluetooth snd_seq snd_seq_device snd_timer joydev input_leds snd ecdh_generic ecc serio_raw vmw_balloon vmw_vmci soundcore sch_fq_codel vmwgfx mac_hid ttm drm_kms_helper cec rc_core fb_sys_fops syscopyarea sysfillrect sysimgblt ipmi_devintf ipmi_msghandler drm msr parport_pc ppdev lp parport pstore_blk ramoops reed_solomon pstore_zone efi_pstore ip_tables x_tables autofs4 hid_generic usbhid hid mptspi mptscsih mptbase psmouse ahci crc32_pclmul e1000 libahci scsi_transport_spi i2c_piix4
[ 9101.347819]  pata_acpi [last unloaded: tempesta_lib]
[ 9101.347821] CPU: 3 PID: 13008 Comm: curl Kdump: loaded Tainted: G        W  OE     5.10.35+ #1
[ 9101.347822] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 11/12/2020
[ 9101.347826] RIP: 0010:tfw_h2_stream_fsm+0x12d/0x2b0 [tempesta_fw]
[ 9101.347827] Code: 89 a0 01 00 00 0f 0b 83 f8 06 74 6b 83 f8 07 75 f4 45 31 c0 41 80 fd 02 0f 84 56 ff ff ff 41 80 fd 09 0f 85 46 ff ff ff eb 8c <0f> 0b 41 b8 03 00 00 00 e9 3d ff ff ff 41 b8 03 00 00 00 e9 3c ff
[ 9101.347828] RSP: 0018:ffffbc7640548530 EFLAGS: 00010293
[ 9101.347829] RAX: 0000000000000002 RBX: ffffa04dd7d02ec0 RCX: 0000000000000001
[ 9101.347829] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffffa04dd7d02ef0
[ 9101.347830] RBP: ffffbc7640548560 R08: ffffbc764054857c R09: 0000000000000000
[ 9101.347830] R10: 0000000000000002 R11: 0000000000000000 R12: ffffa04dd7d02ef0
[ 9101.347831] R13: 0000000000000001 R14: 0000000000000001 R15: 0000000000000001
[ 9101.347832] FS:  00007f5130ec3f80(0000) GS:ffffa04ff5ec0000(0000) knlGS:0000000000000000
[ 9101.347832] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 9101.347833] CR2: 0000558559fa5e58 CR3: 00000000311a0001 CR4: 0000000000770ee0
[ 9101.347839] PKRU: 55555554
[ 9101.347839] Call Trace:
[ 9101.347840]  <IRQ>
[ 9101.347844]  tfw_h2_stream_id_close+0xe7/0x110 [tempesta_fw]
[ 9101.347849]  tfw_h2_prep_resp+0x95/0x310 [tempesta_fw]
[ 9101.347850]  ? alloc_pages_current+0x87/0xe0
[ 9101.347855]  tfw_h2_send_resp+0x5c/0xb0 [tempesta_fw]
[ 9101.347859]  tfw_h2_send_err_resp+0x9a/0xc0 [tempesta_fw]
[ 9101.347864]  tfw_http_cli_error_resp_and_log+0x3cd/0x440 [tempesta_fw]
[ 9101.347869]  ? tfw_http_parse_req+0xe190/0xe190 [tempesta_fw]
[ 9101.347874]  tfw_http_req_process+0xf6/0x960 [tempesta_fw]
[ 9101.347875]  ? alloc_pages_current+0x87/0xe0
[ 9101.347876]  ? __get_free_pages+0x11/0x40
[ 9101.347880]  ? tfw_pool_alloc_pages+0x47/0x50 [tempesta_fw]
[ 9101.347884]  ? __tfw_pool_new+0x2d/0x70 [tempesta_fw]
[ 9101.347889]  tfw_http_msg_process_generic+0x197/0x670 [tempesta_fw]
[ 9101.347893]  ? ss_skb_chop_head_tail+0xbb/0x1d0 [tempesta_fw]
[ 9101.347898]  ? ss_skb_process+0xf6/0x140 [tempesta_fw]
[ 9101.347902]  tfw_h2_frame_process+0x308/0x440 [tempesta_fw]
[ 9101.347906]  tfw_http_msg_process+0x42/0x50 [tempesta_fw]
[ 9101.347911]  tfw_connection_recv+0x59/0xa0 [tempesta_fw]
[ 9101.347914]  tfw_tls_connection_recv+0x19d/0x380 [tempesta_fw]
[ 9101.347919]  ss_tcp_process_data+0x1e7/0x3f0 [tempesta_fw]
[ 9101.347924]  ss_tcp_data_ready+0x44/0xb0 [tempesta_fw]
[ 9101.347925]  tcp_data_ready+0x2b/0xd0
[ 9101.347926]  tcp_rcv_established+0x5a7/0x670
[ 9101.347927]  tcp_v4_do_rcv+0x140/0x200
[ 9101.347928]  tcp_v4_rcv+0xcfd/0xe10
[ 9101.347929]  ip_protocol_deliver_rcu+0x30/0x1b0
[ 9101.347930]  ip_local_deliver_finish+0x48/0x60
[ 9101.347931]  ip_local_deliver+0x72/0x110
[ 9101.347936]  ? tfw_ipv4_nf_hook+0xb9/0x130 [tempesta_fw]
[ 9101.347937]  ip_rcv_finish+0x87/0xa0
[ 9101.347938]  ip_rcv+0xcc/0xe0
[ 9101.347938]  ? ip_rcv_finish_core.isra.0+0x420/0x420
[ 9101.347940]  __netif_receive_skb_one_core+0x88/0xa0
[ 9101.347941]  __netif_receive_skb+0x18/0x60
[ 9101.347941]  process_backlog+0xa9/0x160
[ 9101.347942]  net_rx_action+0x13e/0x390
[ 9101.347944]  __do_softirq+0xd9/0x291
[ 9101.347945]  asm_call_irq_on_stack+0xf/0x20
[ 9101.347946]  </IRQ>
[ 9101.347946]  do_softirq_own_stack+0x3d/0x50
[ 9101.347947]  do_softirq.part.0+0x46/0x50
[ 9101.347948]  __local_bh_enable_ip+0x50/0x60
[ 9101.347949]  ip_finish_output2+0x1ab/0x590
[ 9101.347950]  ? __cgroup_bpf_run_filter_skb+0x3c3/0x3d0
[ 9101.347951]  __ip_finish_output+0xd8/0x220
[ 9101.347952]  ip_finish_output+0x2d/0xb0
[ 9101.347953]  ip_output+0x7a/0x100
[ 9101.347954]  ? ip_finish_output+0x2d/0xb0
[ 9101.347955]  ip_local_out+0x3d/0x50
[ 9101.347956]  __ip_queue_xmit+0x17a/0x470
[ 9101.347957]  ? get_page_from_freelist+0xed8/0x1100
[ 9101.347958]  ip_queue_xmit+0x15/0x20
[ 9101.347959]  __tcp_transmit_skb+0xa94/0xc90
[ 9101.347960]  tcp_write_xmit+0x453/0x1350
[ 9101.347961]  __tcp_push_pending_frames+0x37/0x100
[ 9101.347962]  tcp_push+0xfc/0x100
[ 9101.347964]  tcp_sendmsg_locked+0xd36/0xe70
[ 9101.347965]  tcp_sendmsg+0x2d/0x50
[ 9101.347966]  inet_sendmsg+0x43/0x70
[ 9101.347967]  sock_sendmsg+0x5e/0x70
[ 9101.347968]  sock_write_iter+0x93/0xf0
[ 9101.347969]  new_sync_write+0x192/0x1b0
[ 9101.347970]  vfs_write+0x1ca/0x280
[ 9101.347971]  ksys_write+0xb1/0xe0
[ 9101.347972]  __x64_sys_write+0x1a/0x20
[ 9101.347973]  do_syscall_64+0x38/0x90
[ 9101.347974]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 9101.347975] RIP: 0033:0x7f51322e62f7
[ 9101.347975] Code: 75 05 48 83 c4 58 c3 e8 f7 33 ff ff 0f 1f 80 00 00 00 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
[ 9101.347976] RSP: 002b:00007ffddf5db4d8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 9101.347977] RAX: ffffffffffffffda RBX: 0000000000000036 RCX: 00007f51322e62f7
[ 9101.347977] RDX: 0000000000000036 RSI: 0000558559fa1da3 RDI: 0000000000000005
[ 9101.347978] RBP: 0000558559f60ad0 R08: 0000000000000001 R09: 0000000000000008
[ 9101.347978] R10: 0000558559fa1da5 R11: 0000000000000246 R12: 0000558559fa1da3
[ 9101.347979] R13: 0000000000000036 R14: 0000558559f5ee20 R15: 0000000000000000
[ 9101.347980] ---[ end trace 50b1b7ebb7b42b30 ]---

Testing

Test to reproduce: long_body.test_long_request.H2PutRequestTest1k

RomanBelozerov avatar Oct 05 '22 12:10 RomanBelozerov

All the warnings appear in https://github.com/tempesta-tech/tempesta/issues/1387

krizhanovsky avatar Oct 05 '22 14:10 krizhanovsky

Fix is ready and would be merged as part of #1705 .

s0nx avatar Oct 16 '22 22:10 s0nx