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.

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

Crash on converting mixed headers from h1 to h2 #1408

Closed
vankoven opened this issue May 13, 2020 · 2 comments · Fixed by #1450
Closed

Crash on converting mixed headers from h1 to h2 #1408

vankoven opened this issue May 13, 2020 · 2 comments · Fixed by #1450
Assignees
Milestone

Comments

@vankoven
Copy link
Contributor

Scope

Configure backend to send headers in mixed order: put header B between two headers A. e.g.:

location /short_headers {
	add_header X-Extra-Data1 "q";
	add_header X-Extra-Data2 "q";
	add_header X-Extra-Data1 "q";
	root /srv/http ;
}

The crash will happen once the message is converted from h1 to h2. This may happen in two places:

  • saving responses to cache (headers are stored in native h2 format)
  • forward to h2 client

The issue doesn't reproduced if h2 request contains mixed headers orders.
Probably related to #1387

Testing

Currently we have very limited h2 test coverage, only basic GET/POST request. It's possible to extend them, but more sophisticated fussing test is required.

Logs

Crash on caching:

------------[ cut here ]------------
[  680.957333] kernel BUG at /home/user/qtc/release/tempesta/tempesta_db/core/htrie.c:636!
[  680.962458] invalid opcode: 0000 [#1] SMP PTI
[  680.963866] Modules linked in: tempesta_fw(O) tempesta_db(O) sha256_ssse3 sha512_ssse3 sha512_generic ccm tempesta_tls(O) tempesta_lib(O) kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul iTCO_wdt iTCO_vendor_support snd_hda_codec_generic snd_hda_intel snd_hda_codec ghash_clmulni_intel snd_hda_core snd_hwdep snd_pcm snd_timer virtio_balloon snd sg soundcore virtio_console evdev serio_raw pcspkr virtio_gpu lpc_ich ttm mfd_core binfmt_misc drm_kms_helper button drm shpchp ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 fscrypto ecb aesni_intel crypto_simd cryptd glue_helper aes_x86_64 crc32c_generic sr_mod cdrom virtio_blk virtio_net crc32c_intel psmouse ahci libahci libata i2c_i801 ehci_pci virtio_pci sym53c8xx scsi_transport_spi uhci_hcd ehci_hcd scsi_mod virtio_ring virtio usbcore usb_common
[  680.966427] CPU: 0 PID: 550 Comm: nginx Tainted: G           O    4.14.0-tempesta-kmemleak-amd64 #1 Debian 4.14.32-tfw7-1
[  680.966427] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS ?-20191223_100556-anatol 04/01/2014
[  680.966427] task: ffff8a5876510f00 task.stack: ffffb922012e4000
[  680.966427] RIP: 0010:tdb_htrie_extend_rec+0x7c/0x90 [tempesta_db]
[  680.966427] RSP: 0018:ffff8a58e5403518 EFLAGS: 00010246
[  680.966427] RAX: 0000000000000000 RBX: ffff8a58d1405300 RCX: ffff8a58d1405380
[  680.966427] RDX: 0000000000005380 RSI: 0000000000000000 RDI: ffffffffc0742cc6
[  680.966427] RBP: ffff8a58d1400000 R08: 0000000000000000 R09: ffffffffc08112f0
[  680.966427] R10: 0000000000000000 R11: 000000000000002e R12: ffff8a58bcbc4100
[  680.966427] R13: 0000000000000000 R14: 0000000000000006 R15: 0000000000000006
[  680.966427] FS:  00007fb0d64ac740(0000) GS:ffff8a58e5400000(0000) knlGS:0000000000000000
[  680.966427] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  680.966427] CR2: 000055bce7ebf000 CR3: 000000007f40e005 CR4: 00000000003606f0
[  680.966427] Call Trace:
[  680.966427]  <IRQ>
[  680.966427]  __tfw_cache_strcpy.isra.9+0x98/0x140 [tempesta_fw]
[  680.966427]  ? tfw_cache_build_resp_hdr+0x170/0x170 [tempesta_fw]
[  680.966427]  tfw_cache_h2_copy_str+0x77/0xd0 [tempesta_fw]
[  680.966427]  tfw_cache_copy_resp+0xb84/0x1240 [tempesta_fw]
[  680.966427]  ? tdb_alloc_data+0xf7/0x150 [tempesta_db]
[  680.966427]  __cache_add_node+0xb1/0xe0 [tempesta_fw]
[  680.966427]  ? tfw_h2_resp_add_loc_hdrs+0xa0/0xa0 [tempesta_fw]
[  680.966427]  ? tfw_h2_resp_add_loc_hdrs+0xa0/0xa0 [tempesta_fw]
[  680.966427]  tfw_cache_do_action+0x354/0xe20 [tempesta_fw]
[  680.966427]  ? __hdr_name_cmp+0x140/0x320 [tempesta_fw]
[  680.966427]  ? frang_resp_handler+0x162/0x3a0 [tempesta_fw]
[  680.966427]  ? frang_resp_handler+0x162/0x3a0 [tempesta_fw]
[  680.966427]  ? tfw_http_msg_hdr_close+0x1be/0x200 [tempesta_fw]
[  680.966427]  ? tfw_h2_resp_add_loc_hdrs+0xa0/0xa0 [tempesta_fw]
[  680.966427]  tfw_cache_process+0xbc/0x2a0 [tempesta_fw]
[  680.966427]  ? tfw_gfsm_move+0x14b/0x180 [tempesta_fw]
[  680.966427]  ? kvm_clock_get_cycles+0x1a/0x20
[  680.966427]  tfw_http_resp_cache+0xe1/0x150 [tempesta_fw]
[  680.966427]  tfw_http_msg_process_generic+0x893/0xd10 [tempesta_fw]
[  680.966427]  ? eth_header+0x25/0xc0
[  680.966427]  ? pg_skb_alloc+0x253/0x470
[  680.966427]  tfw_http_msg_process+0x84/0xc0 [tempesta_fw]
[  680.966427]  __gfsm_fsm_exec+0x56/0x90 [tempesta_fw]
[  680.966427]  ? consume_skb+0x27/0x80
[  680.966427]  tfw_connection_recv+0x41/0x60 [tempesta_fw]
[  680.966427]  ? tfw_connection_send+0x30/0x30 [tempesta_fw]
[  680.966427]  ss_tcp_process_data+0x1ea/0x480 [tempesta_fw]
[  680.966427]  ? update_load_avg+0x40d/0x580
[  680.966427]  ss_tcp_data_ready+0x43/0x90 [tempesta_fw]
[  680.966427]  tcp_data_queue+0x4f5/0xc50
[  680.966427]  tcp_rcv_established+0x27c/0x570
[  680.966427]  tcp_v4_do_rcv+0x129/0x1d0
[  680.966427]  tcp_v4_rcv+0x947/0xa50
[  680.966427]  ip_local_deliver_finish+0x9a/0x1c0
[  680.966427]  ip_local_deliver+0x6b/0xe0
[  680.966427]  ? nf_hook_slow+0x43/0xc0
[  680.966427]  ip_rcv+0x289/0x3c0
[  680.966427]  ? inet_del_offload+0x40/0x40
[  680.966427]  __netif_receive_skb_core+0x84f/0xb30
[  680.966427]  ? blk_mq_free_request+0xfe/0x110
[  680.966427]  ? process_backlog+0xa3/0x160
[  680.966427]  process_backlog+0xa3/0x160
[  680.966427]  net_rx_action+0x28e/0x3f0
[  680.966427]  __do_softirq+0x10f/0x2a8
[  680.966427]  do_softirq_own_stack+0x2a/0x40
[  680.966427]  </IRQ>
[  680.966427]  do_softirq.part.17+0x3d/0x50
[  680.966427]  __local_bh_enable_ip+0x55/0x60
[  680.966427]  ip_finish_output2+0x1b3/0x3b0
[  680.966427]  ? ip_output+0x71/0xe0
[  680.966427]  ip_output+0x71/0xe0
[  680.966427]  ? ip_queue_xmit+0x5c/0x3b0
[  680.966427]  tcp_transmit_skb+0x535/0x9c0
[  680.966427]  tcp_write_xmit+0x223/0x11c0
[  680.966427]  ? _copy_from_iter_full+0x93/0x230
[  680.966427]  __tcp_push_pending_frames+0x2d/0xd0
[  680.966427]  tcp_sendmsg_locked+0x68e/0xe60
[  680.966427]  tcp_sendmsg+0x27/0x40
[  680.966427]  sock_sendmsg+0x36/0x40
[  680.966427]  sock_write_iter+0x87/0x100
[  680.966427]  do_iter_readv_writev+0x11b/0x190
[  680.966427]  do_iter_write+0x80/0x190
[  680.966427]  vfs_writev+0x98/0x110
[  680.966427]  ? do_writev+0x5e/0xf0
[  680.966427]  do_writev+0x5e/0xf0
[  680.966427]  ? SyS_pread64+0x90/0xb0
[  680.966427]  do_syscall_64+0x8d/0x120
[  680.966427]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[  680.966427] RIP: 0033:0x7fb0d4de4fe4
[  680.966427] RSP: 002b:00007ffdc4bb66a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000014
[  680.966427] RAX: ffffffffffffffda RBX: 00007fb0d64802c8 RCX: 00007fb0d4de4fe4
[  680.966427] RDX: 0000000000000002 RSI: 00007ffdc4bb6760 RDI: 0000000000000008
[  680.966427] RBP: 000055bce9ec2ab8 R08: 000055bce9ec2ba0 R09: 00007ffdc4bb6770
[  680.966427] R10: 000055bce9ea4d50 R11: 0000000000000246 R12: 00007ffdc4bb6740
[  680.966427] R13: 000055bce7f0048c R14: 000000007fffefff R15: 0000000000000157
[  680.966427] Code: c0 75 1e 8b 73 0c 85 f6 7e 21 48 c1 ea 07 f0 0f b1 53 08 85 c0 75 e5 48 83 c4 18 48 89 c8 5b 5d c3 c1 e0 07 48 8d 5c 05 00 eb d1 <0f> 0b 0f 0b 31 c9 eb e4 66 90 66 2e 0f 1f 84 00 00 00 00 00 0f 
[  680.966427] RIP: tdb_htrie_extend_rec+0x7c/0x90 [tempesta_db] RSP: ffff8a58e5403518

Coudn't reproduce the crash on the same short response right away, but seen it multiple times. Anyway h2 clients complain about h2 frame content:

nghttp --color -vvvvvvn   https://192.168.122.12/short_headers/hello
[  0.010] Connected
[WARNING] Certificate verification failed: Hostname mismatch
The negotiated protocol: h2
[  0.018] send SETTINGS frame <length=12, flags=0x00, stream_id=0>
          (niv=2)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):65535]
[  0.018] send PRIORITY frame <length=5, flags=0x00, stream_id=3>
          (dep_stream_id=0, weight=201, exclusive=0)
[  0.018] send PRIORITY frame <length=5, flags=0x00, stream_id=5>
          (dep_stream_id=0, weight=101, exclusive=0)
[  0.018] send PRIORITY frame <length=5, flags=0x00, stream_id=7>
          (dep_stream_id=0, weight=1, exclusive=0)
[  0.019] send PRIORITY frame <length=5, flags=0x00, stream_id=9>
          (dep_stream_id=7, weight=1, exclusive=0)
[  0.019] send PRIORITY frame <length=5, flags=0x00, stream_id=11>
          (dep_stream_id=3, weight=1, exclusive=0)
[  0.019] send HEADERS frame <length=53, flags=0x25, stream_id=13>
          ; END_STREAM | END_HEADERS | PRIORITY
          (padlen=0, dep_stream_id=11, weight=16, exclusive=0)
          ; Open new stream
          :method: GET
          :path: /short_headers/hello
          :scheme: https
          :authority: 192.168.122.12
          accept: */*
          accept-encoding: gzip, deflate
          user-agent: nghttp2/1.40.0
[  0.019] recv SETTINGS frame <length=6, flags=0x00, stream_id=0>
          (niv=1)
          [SETTINGS_INITIAL_WINDOW_SIZE(0x04):2147483647]
[  0.019] recv WINDOW_UPDATE frame <length=4, flags=0x00, stream_id=0>
          (window_size_increment=2147418112)
[  0.019] recv SETTINGS frame <length=0, flags=0x01, stream_id=0>
          ; ACK
          (niv=0)
[  0.019] send SETTINGS frame <length=0, flags=0x01, stream_id=0>
          ; ACK
          (niv=0)
[  0.019] recv (stream_id=13) :status: 200
[  0.019] recv (stream_id=13) date: Wed, 13 May 2020 11:48:51 GMT
[  0.019] recv (stream_id=13) content-type: application/octet-stream
[  0.019] recv (stream_id=13) content-length: 14
[  0.019] recv (stream_id=13) last-modified: Wed, 13 May 2020 10:23:51 GMT
[  0.019] recv (stream_id=13) etag: "5ebbcab7-e"
[  0.019] recv (stream_id=13) via: 1.1 distant_server
[  0.019] [ERROR] Invalid HTTP header field was received: frame type: 1, stream: 13, name: [X-Extra-Data1], value: [q]
[  0.019] [INVALID; error=Invalid HTTP header field was received] recv HEADERS frame <length=225, flags=0x04, stream_id=13>
          ; END_HEADERS
          (padlen=0)
          ; First response header
[  0.019] send RST_STREAM frame <length=4, flags=0x00, stream_id=13>
          (error_code=PROTOCOL_ERROR(0x01))
[  0.019] send GOAWAY frame <length=8, flags=0x00, stream_id=0>
          (last_stream_id=0, error_code=NO_ERROR(0x00), opaque_data(0)=[])

Crash on bigger responses constructed the same way:

------------[ cut here ]------------
[ 2600.627354] kernel BUG at /home/user/qtc/release/tempesta/tempesta_fw/hpack.c:2646!
[ 2600.629827] invalid opcode: 0000 [#1] SMP PTI
[ 2600.630476] Modules linked in: tempesta_fw(O) tempesta_db(O) tempesta_tls(O) tempesta_lib(O) sha256_ssse3 sha512_ssse3 sha512_generic ccm kvm_intel iTCO_wdt iTCO_vendor_support binfmt_misc kvm irqbypass crct10dif_pclmul crc32_pclmul snd_hda_codec_generic snd_hda_intel ghash_clmulni_intel snd_hda_codec sg snd_hda_core snd_hwdep virtio_balloon snd_pcm snd_timer snd soundcore virtio_console pcspkr serio_raw virtio_gpu ttm lpc_ich mfd_core evdev drm_kms_helper drm shpchp button ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 fscrypto ecb aesni_intel crypto_simd cryptd glue_helper aes_x86_64 crc32c_generic sr_mod cdrom virtio_blk virtio_net crc32c_intel psmouse ahci libahci sym53c8xx libata i2c_i801 scsi_transport_spi ehci_pci uhci_hcd ehci_hcd scsi_mod virtio_pci usbcore virtio_ring virtio usb_common
[ 2600.633799]  [last unloaded: tempesta_lib]
[ 2600.633799] CPU: 0 PID: 555 Comm: nginx Tainted: G           O    4.14.0-tempesta-kmemleak-amd64 #1 Debian 4.14.32-tfw7-1
[ 2600.633799] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS ?-20191223_100556-anatol 04/01/2014
[ 2600.633799] task: ffff9b017c103c00 task.stack: ffffbc7540b58000
[ 2600.633799] RIP: 0010:tfw_hpack_rbtree_erase+0x67b/0x700 [tempesta_fw]
[ 2600.633799] RSP: 0018:ffff9b01a5403758 EFLAGS: 00010286
[ 2600.633799] RAX: 0000000000000070 RBX: ffff9b0152bb0058 RCX: 0000000000000038
[ 2600.633799] RDX: ffff9b0152bb0058 RSI: 0000000000000070 RDI: ffff9b017c17b1a8
[ 2600.633799] RBP: ffffffffffffffff R08: ffff9b0152bb0020 R09: ffff9b0152bb0058
[ 2600.633799] R10: 000000000000015f R11: 00000000000001f8 R12: ffff9b017c17b1b0
[ 2600.633799] R13: 0000000000000000 R14: ffff9b017c17b1a8 R15: ffff9b017c17b190
[ 2600.633799] FS:  00007f79e6972740(0000) GS:ffff9b01a5400000(0000) knlGS:0000000000000000
[ 2600.633799] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2600.633799] CR2: 000055d61a4ee000 CR3: 000000007be98005 CR4: 00000000003606f0
[ 2600.633799] Call Trace:
[ 2600.633799]  <IRQ>
[ 2600.633799]  tfw_hpack_add_node+0x24b/0x540 [tempesta_fw]
[ 2600.633799]  tfw_hpack_encode+0x1079/0x12a0 [tempesta_fw]
[ 2600.633799]  tfw_http_resp_cache_cb+0x366/0x610 [tempesta_fw]
[ 2600.633799]  ? netif_rx_internal+0x12a/0x140
[ 2600.633799]  ? tfw_h2_resp_add_loc_hdrs+0xa0/0xa0 [tempesta_fw]
[ 2600.633799]  tfw_cache_process+0x72/0x2a0 [tempesta_fw]
[ 2600.633799]  ? tfw_gfsm_move+0x14b/0x180 [tempesta_fw]
[ 2600.633799]  ? kvm_clock_get_cycles+0x1a/0x20
[ 2600.633799]  tfw_http_resp_cache+0xe1/0x150 [tempesta_fw]
[ 2600.633799]  tfw_http_msg_process_generic+0x893/0xd10 [tempesta_fw]
[ 2600.633799]  ? __dev_queue_xmit+0x2ec/0x7d0
[ 2600.633799]  ? pg_skb_alloc+0x253/0x470
[ 2600.633799]  tfw_http_msg_process+0x84/0xc0 [tempesta_fw]
[ 2600.633799]  __gfsm_fsm_exec+0x56/0x90 [tempesta_fw]
[ 2600.633799]  ? consume_skb+0x27/0x80
[ 2600.633799]  tfw_connection_recv+0x41/0x60 [tempesta_fw]
[ 2600.633799]  ? tfw_connection_send+0x30/0x30 [tempesta_fw]
[ 2600.633799]  ss_tcp_process_data+0x1ea/0x480 [tempesta_fw]
[ 2600.633799]  ? tcp_transmit_skb+0x535/0x9c0
[ 2600.633799]  ss_tcp_data_ready+0x43/0x90 [tempesta_fw]
[ 2600.633799]  tcp_rcv_established+0x4d2/0x570
[ 2600.633799]  tcp_v4_do_rcv+0x129/0x1d0
[ 2600.633799]  tcp_v4_rcv+0x947/0xa50
[ 2600.633799]  ip_local_deliver_finish+0x9a/0x1c0
[ 2600.633799]  ip_local_deliver+0x6b/0xe0
[ 2600.633799]  ? nf_hook_slow+0x43/0xc0
[ 2600.633799]  ip_rcv+0x289/0x3c0
[ 2600.633799]  ? inet_del_offload+0x40/0x40
[ 2600.633799]  __netif_receive_skb_core+0x84f/0xb30
[ 2600.633799]  ? blk_mq_free_request+0xfe/0x110
[ 2600.633799]  ? process_backlog+0xa3/0x160
[ 2600.633799]  process_backlog+0xa3/0x160
[ 2600.633799]  net_rx_action+0x28e/0x3f0
[ 2600.633799]  __do_softirq+0x10f/0x2a8
[ 2600.633799]  do_softirq_own_stack+0x2a/0x40
[ 2600.633799]  </IRQ>
[ 2600.633799]  do_softirq.part.17+0x3d/0x50
[ 2600.633799]  __local_bh_enable_ip+0x55/0x60
[ 2600.633799]  ip_finish_output2+0x1b3/0x3b0
[ 2600.633799]  ? ip_output+0x71/0xe0
[ 2600.633799]  ip_output+0x71/0xe0
[ 2600.633799]  ? ip_queue_xmit+0x5c/0x3b0
[ 2600.633799]  tcp_transmit_skb+0x535/0x9c0
[ 2600.633799]  tcp_write_xmit+0x223/0x11c0
[ 2600.633799]  ? _copy_from_iter_full+0x93/0x230
[ 2600.633799]  __tcp_push_pending_frames+0x2d/0xd0
[ 2600.633799]  tcp_sendmsg_locked+0x68e/0xe60
[ 2600.633799]  tcp_sendmsg+0x27/0x40
[ 2600.633799]  sock_sendmsg+0x36/0x40
[ 2600.633799]  sock_write_iter+0x87/0x100
[ 2600.633799]  do_iter_readv_writev+0x11b/0x190
[ 2600.633799]  do_iter_write+0x80/0x190
[ 2600.633799]  vfs_writev+0x98/0x110
[ 2600.633799]  ? do_writev+0x5e/0xf0
[ 2600.633799]  do_writev+0x5e/0xf0
[ 2600.633799]  ? SyS_pread64+0x90/0xb0
[ 2600.633799]  do_syscall_64+0x8d/0x120
[ 2600.633799]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[ 2600.633799] RIP: 0033:0x7f79e52aafe4
[ 2600.633799] RSP: 002b:00007fff44257aa8 EFLAGS: 00000246 ORIG_RAX: 0000000000000014
[ 2600.633799] RAX: ffffffffffffffda RBX: 00007f79e69462c8 RCX: 00007f79e52aafe4
[ 2600.633799] RDX: 0000000000000001 RSI: 00007fff44257b60 RDI: 000000000000000b
[ 2600.633799] RBP: 000055d61a4ece10 R08: 000055d61a4ecdf0 R09: 00007fff44257b60
[ 2600.633799] R10: 000055d61a4ced50 R11: 0000000000000246 R12: 00007fff44257b40
[ 2600.633799] R13: 000055d6198cd48c R14: 000000007fffefff R15: 000000000000000e
[ 2600.633799] Code: 48 29 c8 4d 85 c0 48 c7 c1 ff ff ff ff 48 0f 44 c1 66 89 43 0c e9 9d fa ff ff 0f 0b 41 b9 ff ff ff ff 31 c9 e9 25 fb ff ff 0f 0b <0f> 0b 48 85 d2 74 59 41 89 d1 48 89 d1 45 29 d1 66 44 89 48 0c 
[ 2600.633799] RIP: tfw_hpack_rbtree_erase+0x67b/0x700 [tempesta_fw] RSP: ffff9b01a5403758
@vankoven
Copy link
Contributor Author

I can assure that #1450 fixes a crash on serving cached responses for me with the configuration provided in the original issue message. But in the chat we discussed that crash on forwarded is hard to reproduce. Today I run into it with the following configuration:

Tempesta: at branch #1450 (the branch fixes only cache.c so should also be reproducible on current master). Configuration:

server 127.0.0.1:8080;

listen 443 proto=h2;
listen 80;

tls_certificate /home/user/cert/tfw-root.crt;
tls_certificate_key /home/user/cert/tfw-root.key;
tls_match_any_server_name;

A block was added to backend configuration (nginx in my case):

	location /long_headers {
		add_header x-extra-data "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data1 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data2 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data3 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data3 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data4 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data4 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data5 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data5 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data6 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data6 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data7 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data7 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data8 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data8 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data9 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data9 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data1 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		add_header x-extra-data1 "qwertyuiopasdfghjklzxcvbnmqqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmqwertyuiopasdfghjklzxcvbnmwertyuiopasdfghjklzxcvbnm";
		root /srv/http ;
	}

Just make a single request:

% SSLKEYLOGFILE=/tmp/ssl_keys curl  -kv https://192.168.122.12/long_headers/hello
*   Trying 192.168.122.12:443...
* Connected to 192.168.122.12 (192.168.122.12) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: none
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-ECDSA-AES128-GCM-SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=US; ST=Washington,; L=Seattle; O=Tempesta Technologies Inc.; [email protected]
*  start date: Feb 18 14:43:21 2020 GMT
*  expire date: Feb 17 14:43:21 2021 GMT
*  issuer: C=US; ST=Washington,; L=Seattle; O=Tempesta Technologies Inc.; [email protected]
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x558935629a70)
> GET /long_headers/hello HTTP/2
> Host: 192.168.122.12
> user-agent: curl/7.72.0
> accept: */*
> 
* Connection state changed (MAX_CONCURRENT_STREAMS == 4294967295)!
* OpenSSL SSL_read: Connection reset by peer, errno 104
* Failed receiving HTTP2 data
* OpenSSL SSL_write: Broken pipe, errno 32
* Failed sending HTTP2 data
* Connection #0 to host 192.168.122.12 left intact
curl: (56) OpenSSL SSL_read: Connection reset by peer, errno 104

hello is just a file with Hello world! string.

Tempesta crashes on this test case:

[  913.841559] kernel BUG at /home/user/qtc/release/tempesta/tempesta_fw/hpack.c:2646!
[  913.843210] invalid opcode: 0000 [#1] SMP PTI
[  913.844804] Modules linked in: tempesta_fw(O) tempesta_db(O) sha256_ssse3 sha512_ssse3 sha512_generic ccm tempesta_tls(O) tempesta_lib(O) kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul iTCO_wdt iTCO_vendor_support snd_hda_codec_generic snd_hda_intel snd_hda_codec snd_hda_core snd_hwdep ghash_clmulni_intel virtio_gpu ttm snd_pcm drm_kms_helper intel_rapl_perf snd_timer pcspkr evdev serio_raw snd soundcore lpc_ich mfd_core sg virtio_balloon virtio_console drm button shpchp binfmt_misc ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 fscrypto ecb aesni_intel crypto_simd cryptd glue_helper aes_x86_64 crc32c_generic sr_mod cdrom virtio_net virtio_blk psmouse crc32c_intel ahci libahci sym53c8xx ehci_pci i2c_i801 uhci_hcd libata ehci_hcd usbcore usb_common scsi_transport_spi virtio_pci virtio_ring
[  913.847181]  scsi_mod virtio
[  913.847181] CPU: 1 PID: 869 Comm: nginx Tainted: G           O    4.14.0-tempesta-kmemleak-amd64 #1 Debian 4.14.32-tfw7-1
[  913.847181] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS ArchLinux 1.14.0-1 04/01/2014
[  913.847181] task: ffff8c45815b9e00 task.stack: ffff98f840a0c000
[  913.847181] RIP: 0010:tfw_hpack_rbtree_erase+0x67b/0x700 [tempesta_fw]
[  913.847181] RSP: 0018:ffff8c45a5503618 EFLAGS: 00010286
[  913.847181] RAX: 0000000000000070 RBX: ffff8c457d206058 RCX: 0000000000000038
[  913.847181] RDX: ffff8c457d206058 RSI: 0000000000000070 RDI: ffff8c457d3d8790
[  913.847181] RBP: ffffffffffffffff R08: ffff8c457d206020 R09: ffff8c457d206058
[  913.847181] R10: 000000000000015f R11: 0000000000000220 R12: ffff8c457d3d8798
[  913.847181] R13: 0000000000000000 R14: ffff8c457d3d8790 R15: ffff8c457d3d8778
[  913.847181] FS:  00007f7843098740(0000) GS:ffff8c45a5500000(0000) knlGS:0000000000000000
[  913.847181] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  913.847181] CR2: 000055686fcde000 CR3: 000000007d84a002 CR4: 00000000003606e0
[  913.847181] Call Trace:
[  913.847181]  <IRQ>
[  913.847181]  tfw_hpack_add_node+0x24b/0x540 [tempesta_fw]
[  913.847181]  tfw_hpack_encode+0x1079/0x12a0 [tempesta_fw]
[  913.847181]  tfw_http_resp_cache_cb+0x366/0x5f0 [tempesta_fw]
[  913.847181]  ? __alloc_pages_nodemask+0xfa/0x250
[  913.847181]  ? tfw_http_conn_drop+0x280/0x280 [tempesta_fw]
[  913.847181]  ? tfw_http_conn_drop+0x280/0x280 [tempesta_fw]
[  913.847181]  tfw_cache_do_action+0x3a4/0xf00 [tempesta_fw]
[  913.847181]  ? tfw_hash_str_len+0x14c/0x160 [tempesta_fw]
[  913.847181]  ? tfw_http_conn_drop+0x280/0x280 [tempesta_fw]
[  913.847181]  ? tfw_http_req_key_calc+0xb9/0xf0 [tempesta_fw]
[  913.847181]  ? tfw_http_conn_drop+0x280/0x280 [tempesta_fw]
[  913.847181]  tfw_cache_process+0xbc/0x2a0 [tempesta_fw]
[  913.847181]  ? tfw_gfsm_move+0x14b/0x180 [tempesta_fw]
[  913.847181]  ? kvm_clock_get_cycles+0x1a/0x20
[  913.847181]  tfw_http_resp_cache+0x146/0x180 [tempesta_fw]
[  913.847181]  tfw_http_msg_process_generic+0x88e/0xd10 [tempesta_fw]
[  913.847181]  ? __alloc_pages_nodemask+0xfa/0x250
[  913.847181]  ? pg_skb_alloc+0x253/0x470
[  913.847181]  tfw_http_msg_process+0x84/0xc0 [tempesta_fw]
[  913.847181]  __gfsm_fsm_exec+0x56/0x90 [tempesta_fw]
[  913.847181]  ? consume_skb+0x27/0x80
[  913.847181]  tfw_connection_recv+0x41/0x60 [tempesta_fw]
[  913.847181]  ? tfw_connection_send+0x30/0x30 [tempesta_fw]
[  913.847181]  ss_tcp_process_data+0x1ea/0x480 [tempesta_fw]
[  913.847181]  ? tcp_transmit_skb+0x535/0x9c0
[  913.847181]  ss_tcp_data_ready+0x43/0x90 [tempesta_fw]
[  913.847181]  tcp_rcv_established+0x4d2/0x570
[  913.847181]  tcp_v4_do_rcv+0x129/0x1d0
[  913.847181]  tcp_v4_rcv+0x947/0xa50
[  913.847181]  ip_local_deliver_finish+0x9a/0x1c0
[  913.847181]  ip_local_deliver+0x6b/0xe0
[  913.847181]  ? enqueue_task_fair+0x6b/0x6b0
[  913.847181]  ? nf_hook_slow+0x43/0xc0
[  913.847181]  ip_rcv+0x289/0x3c0
[  913.847181]  ? inet_del_offload+0x40/0x40
[  913.847181]  __netif_receive_skb_core+0x84f/0xb30
[  913.847181]  ? autoremove_wake_function+0x2a/0x50
[  913.847181]  ? process_backlog+0xa3/0x160
[  913.847181]  process_backlog+0xa3/0x160
[  913.847181]  net_rx_action+0x28e/0x3f0
[  913.847181]  ? blk_update_request+0x91/0x2d0
[  913.847181]  __do_softirq+0x10f/0x2a8
[  913.847181]  do_softirq_own_stack+0x2a/0x40
[  913.847181]  </IRQ>
[  913.847181]  do_softirq.part.17+0x3d/0x50
[  913.847181]  __local_bh_enable_ip+0x55/0x60
[  913.847181]  ip_finish_output2+0x1b3/0x3b0
[  913.847181]  ? ip_output+0x71/0xe0
[  913.847181]  ip_output+0x71/0xe0
[  913.847181]  ? ip_queue_xmit+0x5c/0x3b0
[  913.847181]  tcp_transmit_skb+0x535/0x9c0
[  913.847181]  tcp_write_xmit+0x223/0x11c0
[  913.847181]  __tcp_push_pending_frames+0x2d/0xd0
[  913.847181]  do_tcp_sendpages+0x580/0x600
[  913.847181]  tcp_sendpage_locked+0x72/0x80
[  913.847181]  tcp_sendpage+0x3d/0x60
[  913.847181]  ? direct_splice_actor+0x40/0x40
[  913.847181]  inet_sendpage+0x3f/0xe0
[  913.847181]  kernel_sendpage+0x1a/0x30
[  913.847181]  sock_sendpage+0x26/0x30
[  913.847181]  pipe_to_sendpage+0x62/0x90
[  913.847181]  __splice_from_pipe+0x118/0x1a0
[  913.847181]  ? direct_splice_actor+0x40/0x40
[  913.847181]  splice_from_pipe+0x5b/0x90
[  913.847181]  direct_splice_actor+0x35/0x40
[  913.847181]  splice_direct_to_actor+0xe9/0x210
[  913.847181]  ? do_splice_from+0x30/0x30
[  913.847181]  do_splice_direct+0x95/0xd0
[  913.847181]  do_sendfile+0x1c9/0x3a0
[  913.847181]  SyS_sendfile64+0x58/0xb0
[  913.847181]  do_syscall_64+0x8d/0x120
[  913.847181]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[  913.847181] RIP: 0033:0x7f7841e7dbea
[  913.847181] RSP: 002b:00007fff018d3748 EFLAGS: 00000246 ORIG_RAX: 0000000000000028
[  913.847181] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f7841e7dbea
[  913.847181] RDX: 00007fff018d37a8 RSI: 000000000000000d RDI: 000000000000000c
[  913.847181] RBP: 000055686fcd4fb8 R08: 0000000000000000 R09: 0000000000000000
[  913.847181] R10: 000000000000000e R11: 0000000000000246 R12: 000055686fcd4e08
[  913.847181] R13: 000000000000000e R14: 00007fff018d37b0 R15: 00007f784306c2c8
[  913.847181] Code: 48 29 c8 4d 85 c0 48 c7 c1 ff ff ff ff 48 0f 44 c1 66 89 43 0c e9 9d fa ff ff 0f 0b 41 b9 ff ff ff ff 31 c9 e9 25 fb ff ff 0f 0b <0f> 0b 48 85 d2 74 59 41 89 d1 48 89 d1 45 29 d1 66 44 89 48 0c 
[  913.847181] RIP: tfw_hpack_rbtree_erase+0x67b/0x700 [tempesta_fw] RSP: ffff8c45a5503618
[    0.000000] Tempesta: cannot allocate 256 continous huge pages at node 0
[    0.000000] Tempesta: cannot vmalloc area of 536870912 bytes at node 0

@krizhanovsky
Copy link
Contributor

The Nginx configuration is quite fancy, shouldn't we add it to the functional tests?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants