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

Multiple TLS Warn_ons are triggered on h2 (http2 over tls) #1376

Closed
vankoven opened this issue Dec 29, 2019 · 2 comments
Closed

Multiple TLS Warn_ons are triggered on h2 (http2 over tls) #1376

vankoven opened this issue Dec 29, 2019 · 2 comments
Assignees
@avbelov23
Labels
bug h2 TLS Tempesta TLS module and related issues
Milestone
0.7 - HTTP/2

Comments

@vankoven
Copy link
Contributor 

[   88.705109] [tempesta tls] Warning: chunked key - fall back to copy (total length 258, chunk length 53, max copy 1024)
[   88.711491] ------------[ cut here ]------------
[   88.713405] WARNING: CPU: 1 PID: 0 at /home/user/qtc/release/tempesta/tempesta_fw/tls.c:216 tfw_tls_tcp_propagate_dseq+0x2b/0x40 [tempesta_fw]
[   88.715415] 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 iTCO_wdt iTCO_vendor_support crc32_pclmul ghash_clmulni_intel snd_hda_codec_generic snd_hda_intel binfmt_misc snd_hda_codec snd_hda_core evdev pcspkr snd_hwdep serio_raw sg snd_pcm virtio_gpu snd_timer snd soundcore virtio_balloon ttm virtio_console drm_kms_helper lpc_ich mfd_core 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 ahci libahci crc32c_intel sym53c8xx scsi_transport_spi libata psmouse i2c_i801 ehci_pci scsi_mod uhci_hcd ehci_hcd virtio_pci virtio_ring virtio usbcore usb_common
[   88.715415] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G           O    4.14.0-tempesta-amd64 #1 Debian 4.14.32-tfw7-1
[   88.715415] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS ?-20191013_105130-anatol 04/01/2014
[   88.715415] task: ffff8a1f4fbc1e00 task.stack: ffffb5b340688000
[   88.715415] RIP: 0010:tfw_tls_tcp_propagate_dseq+0x2b/0x40 [tempesta_fw]
[   88.715415] RSP: 0018:ffff8a1f65503ae0 EFLAGS: 00010297
[   88.715415] RAX: ffff8a1f548f2600 RBX: 000000000000045e RCX: 0000000000000007
[   88.715415] RDX: 000000002f83ca92 RSI: ffff8a1f548f2000 RDI: ffff8a1f527e1ad8
[   88.715415] RBP: ffff8a1f548f2000 R08: 0000000000000001 R09: ffff8a1f548f2600
[   88.715415] R10: 0000000000000000 R11: 0000000000000001 R12: ffff8a1f527e1980
[   88.715415] R13: 0000000000000010 R14: ffff8a1f548f2000 R15: 0000000000000002
[   88.715415] FS:  0000000000000000(0000) GS:ffff8a1f65500000(0000) knlGS:0000000000000000
[   88.715415] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   88.715415] CR2: 00007fffc49c9cd8 CR3: 000000008e00a006 CR4: 00000000003606e0
[   88.715415] Call Trace:
[   88.715415]  <IRQ>
[   88.715415]  tfw_tls_encrypt+0x311/0x6b0 [tempesta_fw]
[   88.715415]  ? kvm_clock_read+0x1a/0x20
[   88.715415]  ? sched_clock+0x5/0x10
[   88.715415]  ? sched_clock_cpu+0x93/0xb0
[   88.715415]  ? tcp_rcv_space_adjust+0x18/0x160
[   88.715415]  ? tcp_cleanup_rbuf+0xd4/0xf0
[   88.715415]  ? kvm_clock_read+0x1a/0x20
[   88.715415]  ? sched_clock+0x5/0x10
[   88.715415]  ? sched_clock_local+0x12/0x80
[   88.715415]  ? sched_clock_cpu+0x93/0xb0
[   88.715415]  ? __skb_flow_dissect+0x659/0x10c0
[   88.715415]  ? sk_reset_timer+0x14/0x30
[   88.715415]  ? tcp_rcv_established+0x2c6/0x570
[   88.715415]  ? tcp_v4_inbound_md5_hash+0x62/0x1b0
[   88.715415]  ? __skb_get_hash+0x8d/0x310
[   88.715415]  ? tcp_v4_rcv+0x969/0xa50
[   88.715415]  ? get_rps_cpu+0x11b/0x300
[   88.715415]  ? kvm_clock_read+0x1a/0x20
[   88.715415]  ? sched_clock_local+0x12/0x80
[   88.715415]  tcp_write_xmit+0x424/0x11c0
[   88.715415]  __tcp_push_pending_frames+0x2d/0xd0
[   88.715415]  ss_do_close+0x253/0x3c0 [tempesta_fw]
[   88.715415]  ss_tx_action+0x43b/0x5a0 [tempesta_fw]
[   88.715415]  ? net_rx_action+0x25d/0x3f0
[   88.715415]  net_tx_action+0x9e/0x1d0
[   88.715415]  __do_softirq+0x10f/0x2a8
[   88.715415]  irq_exit+0xae/0xb0
[   88.715415]  do_IRQ+0x4a/0xd0
[   88.715415]  common_interrupt+0x7d/0x7d
[   88.715415]  </IRQ>
[   88.715415] RIP: 0010:native_safe_halt+0x2/0x10
[   88.715415] RSP: 0018:ffffb5b34068beb8 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff5c
[   88.715415] RAX: ffffffffb0a97e60 RBX: ffff8a1f4fbc1e00 RCX: 0000000000000000
[   88.715415] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[   88.715415] RBP: 0000000000000001 R08: 0000000000000002 R09: 00000000000002d0
[   88.715415] R10: 0000000000000202 R11: 0000000000000000 R12: ffff8a1f4fbc1e00
[   88.715415] R13: ffff8a1f4fbc1e00 R14: 0000000000000000 R15: 0000000000000000
[   88.715415]  ? __sched_text_end+0x3/0x3
[   88.715415]  default_idle+0x1a/0xf0
[   88.715415]  do_idle+0x16e/0x1f0
[   88.715415]  cpu_startup_entry+0x6f/0x80
[   88.715415]  start_secondary+0x1a9/0x200
[   88.715415]  secondary_startup_64+0xa5/0xb0
[   88.715415] Code: 0f 1f 44 00 00 48 8b 06 48 81 c7 58 01 00 00 48 39 f8 74 25 48 83 78 28 00 8b 88 80 00 00 00 74 0c 8b 50 28 01 ca 3b 50 2c 74 02 <0f> 0b 8b 56 2c 89 50 28 01 ca 89 50 2c c3 f3 c3 0f 1f 44 00 00 
[   88.715415] ---[ end trace 36a6caf785f08b49 ]---
[   88.842817] ------------[ cut here ]------------
[   88.844114] WARNING: CPU: 1 PID: 0 at /home/user/qtc/release/tempesta/tempesta_fw/tls.c:275 tfw_tls_encrypt+0x578/0x6b0 [tempesta_fw]
[   88.846750] 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 iTCO_wdt iTCO_vendor_support crc32_pclmul ghash_clmulni_intel snd_hda_codec_generic snd_hda_intel binfmt_misc snd_hda_codec snd_hda_core evdev pcspkr snd_hwdep serio_raw sg snd_pcm virtio_gpu snd_timer snd soundcore virtio_balloon ttm virtio_console drm_kms_helper lpc_ich mfd_core 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 ahci libahci crc32c_intel sym53c8xx scsi_transport_spi libata psmouse i2c_i801 ehci_pci scsi_mod uhci_hcd ehci_hcd virtio_pci virtio_ring virtio usbcore usb_common
[   88.846750] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G        W  O    4.14.0-tempesta-amd64 #1 Debian 4.14.32-tfw7-1
[   88.846750] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS ?-20191013_105130-anatol 04/01/2014
[   88.846750] task: ffff8a1f4fbc1e00 task.stack: ffffb5b340688000
[   88.846750] RIP: 0010:tfw_tls_encrypt+0x578/0x6b0 [tempesta_fw]
[   88.846750] RSP: 0018:ffff8a1f65503ae8 EFLAGS: 00010212
[   88.846750] RAX: 000000002f83cab0 RBX: 00000000000005a8 RCX: 000000002f83caaf
[   88.876100] RDX: 000000002f83caaf RSI: 0000000000000007 RDI: ffff8a1f529d35e0
[   88.876100] RBP: ffff8a1f548f2600 R08: 0000000000040000 R09: 0000000000000001
[   88.876100] R10: 0000000000000001 R11: 000000002f83caaf R12: ffff8a1f527e1980
[   88.876100] R13: 0000000000000586 R14: ffff8a1f548f2600 R15: 0000000000000586
[   88.876100] FS:  0000000000000000(0000) GS:ffff8a1f65500000(0000) knlGS:0000000000000000
[   88.876100] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   88.876100] CR2: 00007fffc49c9cd8 CR3: 000000008e00a006 CR4: 00000000003606e0
[   88.876100] Call Trace:
[   88.876100]  <IRQ>
[   88.876100]  ? virtqueue_add_outbuf+0x27d/0x30a [virtio_ring]
[   88.876100]  ? vp_notify+0x12/0x20 [virtio_pci]
[   88.876100]  ? virtqueue_kick+0x24/0x40 [virtio_ring]
[   88.876100]  ? dev_hard_start_xmit+0xa3/0x1f0
[   88.876100]  ? sch_direct_xmit+0x72/0x1b0
[   88.876100]  ? __dev_queue_xmit+0x2ec/0x7d0
[   88.876100]  ? sk_reset_timer+0x14/0x30
[   88.876100]  ? ip_finish_output2+0x2be/0x3b0
[   88.876100]  ? ip_finish_output2+0x1b3/0x3b0
[   88.876100]  ? ip_output+0x71/0xe0
[   88.876100]  ? ip_output+0x71/0xe0
[   88.876100]  ? ip_queue_xmit+0x5c/0x3b0
[   88.876100]  ? tcp_transmit_skb+0x564/0x9c0
[   88.876100]  tcp_write_xmit+0x424/0x11c0
[   88.876100]  __tcp_push_pending_frames+0x2d/0xd0
[   88.876100]  ss_do_close+0x253/0x3c0 [tempesta_fw]
[   88.876100]  ss_tx_action+0x43b/0x5a0 [tempesta_fw]
[   88.876100]  ? net_rx_action+0x25d/0x3f0
[   88.876100]  net_tx_action+0x9e/0x1d0
[   88.876100]  __do_softirq+0x10f/0x2a8
[   88.876100]  irq_exit+0xae/0xb0
[   88.876100]  do_IRQ+0x4a/0xd0
[   88.876100]  common_interrupt+0x7d/0x7d
[   88.876100]  </IRQ>
[   88.876100] RIP: 0010:native_safe_halt+0x2/0x10
[   88.876100] RSP: 0018:ffffb5b34068beb8 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff5c
[   88.876100] RAX: ffffffffb0a97e60 RBX: ffff8a1f4fbc1e00 RCX: 0000000000000000
[   88.876100] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[   88.876100] RBP: 0000000000000001 R08: 0000000000000002 R09: 00000000000002d0
[   88.876100] R10: 0000000000000202 R11: 0000000000000000 R12: ffff8a1f4fbc1e00
[   88.876100] R13: ffff8a1f4fbc1e00 R14: 0000000000000000 R15: 0000000000000000
[   88.876100]  ? __sched_text_end+0x3/0x3
[   88.876100]  default_idle+0x1a/0xf0
[   88.876100]  do_idle+0x16e/0x1f0
[   88.876100]  cpu_startup_entry+0x6f/0x80
[   88.876100]  start_secondary+0x1a9/0x200
[   88.876100]  secondary_startup_64+0xa5/0xb0
[   88.876100] Code: 8d 50 ff a8 01 48 0f 45 fa f0 ff 4f 1c 75 05 e8 2f 94 e2 ef 49 83 c4 08 4c 39 64 24 48 77 d8 e9 e5 fe ff ff 0f 0b e9 58 fb ff ff <0f> 0b e9 6a fb ff ff 0f 0b 0f 0b 0f 0b e9 76 fd ff ff 48 8b 7c 
[   88.876100] ---[ end trace 36a6caf785f08b4a ]---

Warnings are:

tempesta/tempesta_fw/tls.c

Lines 215 to 216 in 66752e4

WARN_ON_ONCE((tcb_next->seq || tcb_next->end_seq)
&& tcb_next->seq + next->len != tcb_next->end_seq);

https://github.com/tempesta-tech/tempesta/blob/66752e4b84fec84d45ba2085f7bed19118df6224/tempesta_fw/tls.c#L274-275

This happens to me at branch #1374 time to time. Never seen on http/1.1 over TLS. Can't say anything on reproducibility on #1368 branch, I have some issues with that branch.

To reproduce: no special conditions, happens time to time when h2spec is stared against Tempesta. Some tests can trigger the warning, some - always trigger, e.g. generic/3.2/3 always triggers warnings fo me.

Tempesta config:

server 127.0.0.1:8080 conns_n=1;
listen 443 proto=h2;

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

Tempesta is started on VM, h2spec - on host.
@vankoven vankoven added the bug label Dec 29, 2019
@vankoven vankoven self-assigned this Dec 29, 2019
@vankoven vankoven changed the title Multiple Warn_on triggered on h2 (http2 over tls) Multiple TLS Warn_ons are triggered on h2 (http2 over tls) Dec 29, 2019
@vankoven vankoven added this to the 0.7 HTTP/2 milestone Dec 29, 2019
@vankoven vankoven added the h2 label Jan 10, 2020
@krizhanovsky krizhanovsky added the TLS Tempesta TLS module and related issues label Apr 27, 2020
@avbelov23
Copy link
Contributor

Fixed in #1173
Now warning:

WARN_ON_ONCE(tcb->seq + skb->len + !!(tcb->tcp_flags & TCPHDR_FIN) != tcb->end_seq);

@krizhanovsky
Copy link
Contributor

There were also more recent fixes of the place in #1485

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@avbelov23 avbelov23

Labels
bug h2 TLS Tempesta TLS module and related issues
Projects
None yet
Milestone
0.7 - HTTP/2
Development

No branches or pull requests
3 participants
@krizhanovsky @vankoven @avbelov23