search

tempesta-tech / tempesta-test

Test suite for Tempesta FW
11 stars 4 forks source link

disable failing `h2spec` test #296

Closed nickzaev closed 2 years ago

nickzaev commented 2 years ago

After adding tests to h2spec covering Stream ID values, the test that is supposed to ensure that Stream ID values are not reused is failing for about 2 out of 10 times. This behavior is always reproduced in the same way. After starting Tempesta and running that test for the first time, there will be a trace in dmesg (which is basically the first bullet of https://github.com/tempesta-tech/tempesta/issues/1387):

[Thu Aug 25 17:54:48 2022] ------------[ cut here ]------------
[Thu Aug 25 17:54:48 2022] WARNING: CPU: 0 PID: 228365 at /root/tempesta/fw/http.c:6495 tfw_http_msg_process_generic+0x409/0x670 [tempesta_fw]
[Thu Aug 25 17:54:48 2022] Modules linked in: tempesta_fw(OE) tempesta_db(OE) tempesta_tls(OE) tempesta_lib(OE) sha256_ssse3 sha512_ssse3 dm_multipath scsi_dh_rdac scsi_dh_emc scsi_dh_alua input_leds joydev serio_raw mac_hid qemu_fw_cfg sch_fq_codel msr i
p_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 ghash_clmulni_
intel aesni_intel crypto_simd cryptd glue_helper bochs_drm drm_vram_helper drm_ttm_helper ttm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops psmouse cec virtio_net net_failover failover drm virtio_scsi i2c_piix4 pata_acpi floppy [last unload
ed: tempesta_lib]
[Thu Aug 25 17:54:48 2022] CPU: 0 PID: 228365 Comm: h2spec Tainted: G        W  OE     5.10.35+ #1
[Thu Aug 25 17:54:48 2022] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
[Thu Aug 25 17:54:48 2022] RIP: 0010:tfw_http_msg_process_generic+0x409/0x670 [tempesta_fw]
[Thu Aug 25 17:54:48 2022] Code: 98 00 00 00 44 8b 95 70 ff ff ff a8 10 0f 84 72 fd ff ff e9 08 ff ff ff 4c 89 63 10 4d 89 24 24 4d 89 64 24 08 e9 6d fc ff ff <0f> 0b 41 ba ea ff ff ff e9 4e fd ff ff e8 05 89 ff ff 49 89 47 40
[Thu Aug 25 17:54:48 2022] RSP: 0018:ffff97b4c0003a58 EFLAGS: 00010246
[Thu Aug 25 17:54:48 2022] RAX: 0000000000000000 RBX: ffff8a3fd7b20000 RCX: 0000000000000000
[Thu Aug 25 17:54:48 2022] RDX: ffff8a3ff4644a00 RSI: 0000000000000000 RDI: ffff8a3fd7b20000
[Thu Aug 25 17:54:48 2022] RBP: ffff97b4c0003af8 R08: ffff8a3ff4644a00 R09: ffff97b4c0003aa8
[Thu Aug 25 17:54:48 2022] R10: 0000000000000009 R11: 0000000000000000 R12: 0000000000000000
[Thu Aug 25 17:54:48 2022] R13: ffff8a3fd7b206f8 R14: 0000000000000000 R15: 0000000000000000
[Thu Aug 25 17:54:48 2022] FS:  00007fdd54ff4740(0000) GS:ffff8a407bc00000(0000) knlGS:0000000000000000
[Thu Aug 25 17:54:48 2022] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[Thu Aug 25 17:54:48 2022] CR2: 0000000000b3ae04 CR3: 0000000093754000 CR4: 00000000003506f0
[Thu Aug 25 17:54:48 2022] Call Trace:
[Thu Aug 25 17:54:48 2022]  <IRQ>
[Thu Aug 25 17:54:48 2022]  ? ss_skb_chop_head_tail+0xbb/0x1d0 [tempesta_fw]
[Thu Aug 25 17:54:48 2022]  ? ss_skb_process+0xf6/0x140 [tempesta_fw]
[Thu Aug 25 17:54:48 2022]  tfw_h2_frame_process+0x308/0x440 [tempesta_fw]
[Thu Aug 25 17:54:48 2022]  tfw_http_msg_process+0x37/0x40 [tempesta_fw]
[Thu Aug 25 17:54:48 2022]  tfw_connection_recv+0x59/0xa0 [tempesta_fw]
[Thu Aug 25 17:54:48 2022]  tfw_tls_connection_recv+0x19d/0x380 [tempesta_fw]
[Thu Aug 25 17:54:48 2022]  ss_tcp_process_data+0x1e6/0x3f0 [tempesta_fw]
[Thu Aug 25 17:54:48 2022]  ss_tcp_data_ready+0x4e/0x90 [tempesta_fw]
[Thu Aug 25 17:54:48 2022]  tcp_data_ready+0x2b/0xd0
[Thu Aug 25 17:54:48 2022]  tcp_rcv_established+0x5a7/0x670
[Thu Aug 25 17:54:48 2022]  tcp_v4_do_rcv+0x140/0x200
[Thu Aug 25 17:54:48 2022]  tcp_v4_rcv+0xcfd/0xe10
[Thu Aug 25 17:54:48 2022]  ip_protocol_deliver_rcu+0x30/0x1b0
[Thu Aug 25 17:54:48 2022]  ip_local_deliver_finish+0x48/0x60
[Thu Aug 25 17:54:48 2022]  ip_local_deliver+0x72/0x110
[Thu Aug 25 17:54:48 2022]  ? tfw_ipv4_nf_hook+0xce/0x150 [tempesta_fw]
[Thu Aug 25 17:54:48 2022]  ip_rcv_finish+0x87/0xa0
[Thu Aug 25 17:54:48 2022]  ip_rcv+0xcc/0xe0
[Thu Aug 25 17:54:48 2022]  ? ip_rcv_finish_core.isra.0+0x420/0x420
[Thu Aug 25 17:54:48 2022]  __netif_receive_skb_one_core+0x88/0xa0
[Thu Aug 25 17:54:48 2022]  __netif_receive_skb+0x18/0x60
[Thu Aug 25 17:54:48 2022]  process_backlog+0xa9/0x160
[Thu Aug 25 17:54:48 2022]  net_rx_action+0x13e/0x390
[Thu Aug 25 17:54:48 2022]  __do_softirq+0xd9/0x291
[Thu Aug 25 17:54:48 2022]  asm_call_irq_on_stack+0x12/0x20
[Thu Aug 25 17:54:48 2022]  </IRQ>
[Thu Aug 25 17:54:48 2022]  do_softirq_own_stack+0x3d/0x50
[Thu Aug 25 17:54:48 2022]  do_softirq.part.0+0x46/0x50
[Thu Aug 25 17:54:48 2022]  __local_bh_enable_ip+0x50/0x60
[Thu Aug 25 17:54:48 2022]  ip_finish_output2+0x1ab/0x590
[Thu Aug 25 17:54:48 2022]  ? __cgroup_bpf_run_filter_skb+0x3c3/0x3d0
[Thu Aug 25 17:54:48 2022]  __ip_finish_output+0xd8/0x220
[Thu Aug 25 17:54:48 2022]  ip_finish_output+0x2d/0xb0
[Thu Aug 25 17:54:48 2022]  ip_output+0x7a/0x100
[Thu Aug 25 17:54:48 2022]  ip_local_out+0x3d/0x50
[Thu Aug 25 17:54:48 2022]  __ip_queue_xmit+0x17a/0x470
[Thu Aug 25 17:54:48 2022]  ip_queue_xmit+0x15/0x20
[Thu Aug 25 17:54:48 2022]  __tcp_transmit_skb+0xa20/0xbe0
[Thu Aug 25 17:54:48 2022]  tcp_write_xmit+0x453/0x1350
[Thu Aug 25 17:54:48 2022]  __tcp_push_pending_frames+0x37/0x100
[Thu Aug 25 17:54:48 2022]  tcp_push+0xfc/0x100
[Thu Aug 25 17:54:48 2022]  tcp_sendmsg_locked+0xd36/0xe70
[Thu Aug 25 17:54:48 2022]  tcp_sendmsg+0x2d/0x50
[Thu Aug 25 17:54:48 2022]  inet_sendmsg+0x43/0x70
[Thu Aug 25 17:54:48 2022]  sock_sendmsg+0x5e/0x70
[Thu Aug 25 17:54:48 2022]  sock_write_iter+0x93/0xf0
[Thu Aug 25 17:54:48 2022]  new_sync_write+0x192/0x1b0
[Thu Aug 25 17:54:48 2022]  vfs_write+0x185/0x250
[Thu Aug 25 17:54:48 2022]  ksys_write+0xb1/0xe0
[Thu Aug 25 17:54:48 2022]  __x64_sys_write+0x1a/0x20
[Thu Aug 25 17:54:48 2022]  do_syscall_64+0x38/0x90
[Thu Aug 25 17:54:48 2022]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Thu Aug 25 17:54:48 2022] RIP: 0033:0x4a7f20
[Thu Aug 25 17:54:48 2022] Code: 8b 7c 24 10 48 8b 74 24 18 48 8b 54 24 20 49 c7 c2 00 00 00 00 49 c7 c0 00 00 00 00 49 c7 c1 00 00 00 00 48 8b 44 24 08 0f 05 <48> 3d 01 f0 ff ff 76 20 48 c7 44 24 28 ff ff ff ff 48 c7 44 24 30
[Thu Aug 25 17:54:48 2022] RSP: 002b:000000c0000ccd60 EFLAGS: 00000202 ORIG_RAX: 0000000000000001
[Thu Aug 25 17:54:48 2022] RAX: ffffffffffffffda RBX: 000000c000034500 RCX: 00000000004a7f20
[Thu Aug 25 17:54:48 2022] RDX: 000000000000002a RSI: 000000c000148000 RDI: 0000000000000003
[Thu Aug 25 17:54:48 2022] RBP: 000000c0000ccdb0 R08: 0000000000000000 R09: 0000000000000000
[Thu Aug 25 17:54:48 2022] R10: 0000000000000000 R11: 0000000000000202 R12: 000000007bfb43c5
[Thu Aug 25 17:54:48 2022] R13: 000000000000000a R14: 0000000000000046 R15: 0000000000000100
[Thu Aug 25 17:54:48 2022] ---[ end trace 65f4a5140a321cc3 ]---

Note that the test always passes (at least I've tried for about 50 times) on the first run, then if we don't restart Tempesta, whenever there's a warning:

[Thu Aug 25 18:01:50 2022] [tempesta tls] Warning: [::ffff:127.0.0.1] Bad TLS alert

the test will fail with the message from h2spec:

Hypertext Transfer Protocol Version 2 (HTTP/2)
  5. Streams and Multiplexing
    5.1. Stream States
      5.1.1. Stream Identifiers
        × 4: Sends stream identifier that has already been used
          -> The endpoint MUST response with a connection error of type PROTOCOL_ERROR.
             Expected: GOAWAY Frame (Error Code: PROTOCOL_ERROR)
                       Connection closed
               Actual: DATA Frame (length:1379, flags:0x01, stream_id:5)