`WARNING` in `/root/tempesta/fw/tls.c:460`

[RomanBelozerov]

Scope

Tempesta - f5929f91b1fc8373d30d2f47678b1767d3e04ef0

------------[ cut here ]------------
WARNING: CPU: 0 PID: 12 at /root/tempesta/fw/tls.c:460 tfw_tls_encrypt+0x873/0x8a0 [tempesta_fw]
Modules linked in: tempesta_fw(OE) tempesta_db(OE) tempesta_tls(OE) tempesta_lib(OE) iptable_mangle xt_mark tcp_diag inet_diag xt_nat xt_tcpudp veth sha256_ssse3 sha512_ssse3 xt_conntrack xt_MASQUERADE nf_conntrack_netlink xfrm_user xfrm_algo xt_addrtype iptable_filter iptable_nat bpfilter br_netfilter bridge stp llc md4 cmac nls_utf8 cifs libarc4 fscache libdes overlay nfnetlink_cttimeout nfnetlink openvswitch nsh nf_conncount nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 dm_multipath scsi_dh_rdac scsi_dh_emc scsi_dh_alua kvm_amd ccp kvm binfmt_misc sch_fq_codel input_leds serio_raw joydev qemu_fw_cfg mac_hid ramoops reed_solomon msr 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 ghash_clmulni_intel bochs_drm drm_vram_helper drm_ttm_helper ttm drm_kms_helper aesni_intel
 syscopyarea sysfillrect crypto_simd cryptd glue_helper sysimgblt psmouse fb_sys_fops cec virtio_scsi drm pata_acpi e1000 i2c_piix4 floppy [last unloaded: tempesta_lib]
CPU: 0 PID: 12 Comm: ksoftirqd/0 Tainted: G           OE     5.10.35.tfw-4c9ba16 #1
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
RIP: 0010:tfw_tls_encrypt+0x873/0x8a0 [tempesta_fw]
Code: 38 fd ff ff 8b 9d 60 fd ff ff 4d 89 f2 4c 8b a5 30 fd ff ff e9 13 fd ff ff 49 8b 44 24 28 e9 3f fa ff ff 0f 0b e9 0b fd ff ff <0f> 0b e9 73 fe ff ff 0f 0b e9 02 ff ff ff 0f 0b e9 ef fe ff ff e8
RSP: 0018:ffffa8fe8006b9d0 EFLAGS: 00010216
RAX: ffff8bcaea2069e8 RBX: ffff8bcbd48f2300 RCX: 0000000000000004
RDX: 0000000000000008 RSI: ffff8bcbd48f2533 RDI: ffff8bcb0c290c58
RBP: ffffa8fe8006bca0 R08: ffff8bcb0c290c58 R09: 0000000000000010
R10: ffff8bcbd48f2300 R11: 0000000000000010 R12: ffff8bcaea206880
R13: ffffa8fe8006ba30 R14: 0000000000000000 R15: ffff8bcb0c2908a0
FS:  0000000000000000(0000) GS:ffff8bcbf7c00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fa9ebb2eeb0 CR3: 000000012acb0004 CR4: 0000000000770ef0
PKRU: 55555554
Call Trace:
 ? __cgroup_bpf_run_filter_skb+0x3c3/0x3d0
 ? __ip_finish_output+0xd8/0x220
 ? ip_finish_output+0x2d/0xb0
 ? ip_output+0x7a/0x100
 ? __ip_finish_output+0x220/0x220
 ? ip_local_out+0x3d/0x50
 ? lock_timer_base+0x72/0xa0
 ? mod_timer+0x1aa/0x300
 tfw_sk_write_xmit+0x6a/0xc0 [tempesta_fw]
 tcp_tfw_sk_write_xmit+0x36/0x80
 tcp_write_xmit+0x2a9/0x11b0
 __tcp_push_pending_frames+0x37/0x100
 tcp_push+0xfc/0x100
 ss_tx_action+0x30f/0x5a0 [tempesta_fw]
 net_tx_action+0x9c/0x250
 __do_softirq+0xd9/0x291
 run_ksoftirqd+0x2b/0x40
 smpboot_thread_fn+0xd0/0x170
 kthread+0x114/0x150
 ? sort_range+0x30/0x30
 ? kthread_park+0x90/0x90
 ret_from_fork+0x22/0x30
---[ end trace ecd9551dfd6dfd7e ]---

Testing

t_leaks.test_leak.LeakTestH2.test_slab_memory with remote setup on CI.

[voodam]

I found that problem occurs when Tempesta stops: tfw_sock_clnt_stop called, then __cli_conn_close_cb, and inhere ttls_close_notify is called, but after that tfw_h2_resp_fwd continue to be called. We discussed with the team how to fix it, but it seems that that issue should be hold for now:

• 1196 introduces h2 stream queues, so this issue should be refixed after merging 1196.
• It's not obvious how NULL pointer dereference can occur, it wasn't reproduced in my test runs.
• It's very rare case when we shutdown Tempesta under heavy load, or to be more precise, under heavy printk usage with disabled dmesg ratelimited (hundreds of thousands of messages).