TfwStream objects leaks if errors happen on serving h2 clients #1377

vankoven · 2020-01-10T05:45:54Z

Scope

To reproduce force Tempesta to close client connection with error. Or force client to close the connection with Tempesta with e.g. PROTOCOL_ERROR code. If this happens, connection is closed, but TfwStream object is not destroyed.

[tdb] Close table 'client0.tdb'
[tdb] Close table 'sessions0.tdb'
[tdb] Close table 'cache0.tdb'
[tdb] Close table 'filter0.tdb'
[tempesta fw] modules are stopped
[tempesta fw] exiting...
=============================================================================
BUG tfw_stream_cache (Tainted: G    B   W  O   ): Objects remaining in tfw_stream_cache on __kmem_cache_shutdown()
-----------------------------------------------------------------------------

INFO: Slab 0xffffd48381f8a800 objects=23 used=1 fp=0xffffa0a63e2a1340 flags=0xffffc000008100
CPU: 0 PID: 28679 Comm: rmmod Tainted: G    B   W  O    4.14.0-tempesta-amd64 #1 Debian 4.14.32-tfw7-1
Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS ?-20191223_100556-anatol 04/01/2014
Call Trace:
 dump_stack+0x5c/0x85
 slab_err+0xad/0xd0
 ? __kmalloc+0x164/0x1e0
 __kmem_cache_shutdown+0x1c2/0x3a0
 ? wait_for_completion+0x140/0x190
 shutdown_cache+0x1a/0x1b0
 kmem_cache_destroy+0x1e5/0x210
 tfw_tls_exit+0x2e/0x40 [tempesta_fw]
 ? tfw_tls_free_alpn_protos+0x30/0x30 [tempesta_fw]
 tfw_exit+0x3f/0x70 [tempesta_fw]
 SyS_delete_module+0x1b2/0x280
 do_syscall_64+0x8d/0x120
 entry_SYSCALL_64_after_hwframe+0x3d/0xa2
RIP: 0033:0x7f22a23a85e7
RSP: 002b:00007fff4d6d79a8 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
RAX: ffffffffffffffda RBX: 00007fff4d6d79f8 RCX: 00007f22a23a85e7
RDX: 000000000000000a RSI: 0000000000000800 RDI: 000055ece9d31808
RBP: 000055ece9d317a0 R08: 00007fff4d6d6921 R09: 0000000000000000
R10: 00007f22a2418960 R11: 0000000000000206 R12: 00007fff4d6d7bc0
R13: 00007fff4d6d987e R14: 0000000000000000 R15: 000055ece9d317a0
INFO: Object 0xffffa0a63e2a0b00 @offset=2816
kmem_cache_destroy tfw_stream_cache: Slab cache still has objects
CPU: 0 PID: 28679 Comm: rmmod Tainted: G    B   W  O    4.14.0-tempesta-amd64 #1 Debian 4.14.32-tfw7-1
Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS ?-20191223_100556-anatol 04/01/2014
Call Trace:
 dump_stack+0x5c/0x85
 kmem_cache_destroy+0x202/0x210
 tfw_tls_exit+0x2e/0x40 [tempesta_fw]
 ? tfw_tls_free_alpn_protos+0x30/0x30 [tempesta_fw]
 tfw_exit+0x3f/0x70 [tempesta_fw]
 SyS_delete_module+0x1b2/0x280
 do_syscall_64+0x8d/0x120
 entry_SYSCALL_64_after_hwframe+0x3d/0xa2
RIP: 0033:0x7f22a23a85e7
RSP: 002b:00007fff4d6d79a8 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
RAX: ffffffffffffffda RBX: 00007fff4d6d79f8 RCX: 00007f22a23a85e7
RDX: 000000000000000a RSI: 0000000000000800 RDI: 000055ece9d31808
RBP: 000055ece9d317a0 R08: 00007fff4d6d6921 R09: 0000000000000000
R10: 00007f22a2418960 R11: 0000000000000206 R12: 00007fff4d6d7bc0
R13: 00007fff4d6d987e R14: 0000000000000000 R15: 000055ece9d317a0
[tdb] Shutdown Tempesta DB

Testing

No special tests are required for this particular error. Just need to assure that no warnings are triggered during h2 tests. Like we do so for HTTP/1.1 tests.

The text was updated successfully, but these errors were encountered:

krizhanovsky · 2021-03-06T19:39:42Z

I got probably related bug with current Fix #1435 #1485 as of 01b46e9 . Just constantly restart Tempesta FW on a 2 CPU VM with

$ while :; do ./scripts/tempesta.sh --restart; sleep 10; done

under wrk workload running from the host system.

./wrk -d 120 -c 1000 -t 2 -H 'connection: close' https://debian:443/

Tempesta config (the backend server services the tempesta-tech.com site):

listen 192.168.100.4:443 proto=https;
listen 192.168.100.4:80;

srv_group default {
	server 127.0.0.1:8080 conns_n=4;
}

vhost debian {
	tls_certificate /root/tempesta/etc/tfw-root.crt;
	tls_certificate_key /root/tempesta/etc/tfw-root.key;

	#resp_hdr_set Strict-Transport-Security "max-age=31536000; includeSubDomains"

	proxy_pass default;
}

cache 1;
cache_fulfill * *;

block_action attack reply;

http_chain {
	-> debian;
}

Crash

[19169.612563] [tempesta fw] Warning: Close TCP socket w/o sending alert to the peer: 192.168.100.1:443
[19169.754216] [tdb] Close table 'client0.tdb'
[19169.819865] [tdb] Close table 'sessions0.tdb'
[19171.094230] [tdb] Close table 'cache0.tdb'
[19171.200781] [tdb] Close table 'filter0.tdb'
[19176.245326] net_ratelimit: 115 callbacks suppressed
[19176.245328] [tempesta fw] Warning: pending active connections for 5s (connections count 0x4, queues count 0)
[19176.267957] [tempesta fw] Warning:   cpu 0(0), backlog size 0, work queue size 0
[19176.271999] [tempesta fw] Warning:   cpu 1(0), backlog size 0, work queue size 0
[19176.281506] [tempesta fw] Warning: Memory leakage is possible
[19181.374917] [tempesta fw] ERROR: Got stuck in releasing of server group objects! 1 objects was not released.
[19181.421666] [tempesta fw] exiting...
[19181.441121] kmem_cache_destroy tfw_h2_conn_cache: Slab cache still has objects
[19181.445448] CPU: 1 PID: 4864 Comm: rmmod Tainted: G           O    4.14.32-kdump+ #213
[19181.450355] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.13.0-3.fc33 04/01/2014
[19181.455418] Call Trace:
[19181.455418]  dump_stack+0x5f/0x86
[19181.455418]  kmem_cache_destroy+0x1d2/0x230
[19181.465959]  tfw_sock_clnt_exit+0x1c/0x30 [tempesta_fw]
[19181.465959]  ? tfw_sock_clnt_init+0xb0/0xb0 [tempesta_fw]
[19181.474951]  tfw_exit+0x3a/0x70 [tempesta_fw]
[19181.474951]  SyS_delete_module+0x19c/0x250
[19181.474951]  ? trace_hardirqs_off_thunk+0x1a/0x1c
[19181.485013]  do_syscall_64+0x6b/0x170
[19181.485013]  entry_SYSCALL_64_after_hwframe+0x42/0xb7
[19181.494937] RIP: 0033:0x7f800d71edd7
[19181.494937] RSP: 002b:00007ffed5deaad8 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[19181.504952] RAX: ffffffffffffffda RBX: 0000559b9fab37e0 RCX: 00007f800d71edd7
[19181.504952] RDX: 000000000000000a RSI: 0000000000000800 RDI: 0000559b9fab3848
[19181.504952] RBP: 0000000000000000 R08: 00007ffed5de9a51 R09: 0000000000000000
[19181.514924] R10: 00007f800d790ae0 R11: 0000000000000206 R12: 00007ffed5dead00
[19181.514924] R13: 00007ffed5dece12 R14: 0000559b9fab3260 R15: 0000559b9fab37e0
[19181.820522] [tdb] Shutdown Tempesta DB
[19182.045343] BUG: unable to handle kernel paging request at ffffffffc0734150
[19182.051918] IP: 0xffffffffc0734150
[19182.055300] PGD 48612067 P4D 48612067 PUD 48614067 PMD 4e567067 PTE 0
[19182.055300] Oops: 0010 [#1] SMP PTI

Fixed in #1643

Dmitry-Gouriev · 2021-12-27T20:58:14Z

Another incarnation of this bug was catched by a user.
Configuration:

root@debian:~# cat  tempesta/etc/tempesta_fw.conf
listen <ip1>:443 proto=https;
listen <ip1>:80;
srv_group default {
    server <ip2>:80 conns_n=400;
}
vhost wp.772211.xyz {
  sticky {
   cookie name=my_js_cookie enforce max_misses=3 timeout=3;
  }
    tls_certificate /etc/letsencrypt/live/wp.772211.xyz-0001/fullchain.pem;
    tls_certificate_key /etc/letsencrypt/live/wp.772211.xyz-0001/privkey.pem;
    proxy_pass default;
}
cache 1;
cache_fulfill * *;
block_action attack reply;
http_chain {
    -> wp.772211.xyz;
}

netconsole log

[27705.404883] [tdb] Start Tempesta DB
[27705.516844] [tempesta fw] Initializing Tempesta FW kernel module...
[27705.734375] [tempesta fw] Warning: Listening for HTTP/1.1 protocol is compatibility mode and may lack of performance.
[27705.757547] [tempesta fw] Warning: TLS: no global TLS certificates provided. Client TLS connections with unknown server name values or with no server name specified will be dropped.
[27705.759214] [tempesta fw] Configuration processing is completed.
[27705.772799] [tdb] Opened table /opt/tempesta/db/filter0.tdb: size=16777216 rec_size=20 base=0000000029342cff
[27706.002858] [tdb] Opened table /opt/tempesta/db/cache0.tdb: size=268435456 rec_size=0 base=000000001d4ce8ca
[27706.019293] [tdb] Opened table /opt/tempesta/db/sessions0.tdb: size=16777216 rec_size=312 base=000000008b31d141
[27706.036931] [tdb] Opened table /opt/tempesta/db/client0.tdb: size=16777216 rec_size=624 base=000000004b21df5f
[27706.049985] [tempesta fw] Open listen socket on: <ip1>
[27706.051510] [tempesta fw] Open listen socket on: <ip1>:443
[27706.052265] [tempesta fw] Tempesta FW is ready
[27720.249264] [tempesta fw] Warning: frang: new TLS connections rate exceeded for <ip3>: 3 (lim=2)
[27729.121484] [tempesta fw] Warning: frang: new TLS connections rate exceeded for <ip4>: 3 (lim=2)
[27786.933213] [tempesta fw] Warning: Close TCP socket w/o sending alert to the peer: <ipX>:443
[27786.933752] [tempesta fw] Warning: Close TCP socket w/o sending alert to the peer: <ipX>:443
[27786.934158] [tempesta fw] Warning: Close TCP socket w/o sending alert to the peer: <ipX>:443
[27786.934506] [tempesta fw] Warning: Close TCP socket w/o sending alert to the peer: <ipX>:443
[27786.934849] [tempesta fw] Warning: Close TCP socket w/o sending alert to the peer: <ipX>:443
[27786.935203] [tempesta fw] Warning: Close TCP socket w/o sending alert to the peer: <ipX>:443
[27786.935528] [tempesta fw] Warning: Close TCP socket w/o sending alert to the peer: <ipX>:443
[27786.935868] [tempesta fw] Warning: Close TCP socket w/o sending alert to the peer: <ipX>:443
[27786.936195] [tempesta fw] Warning: Close TCP socket w/o sending alert to the peer: <ipX>:443
[27786.936498] [tempesta fw] Warning: Close TCP socket w/o sending alert to the peer: <ipX>:443
[27787.172218] [tdb] Close table 'client0.tdb'
[27787.195224] [tdb] Close table 'sessions0.tdb'
[27787.833529] [tdb] Close table 'cache0.tdb'
[27787.888794] [tdb] Close table 'filter0.tdb'
[27792.889914] net_ratelimit: 20331 callbacks suppressed
[27792.889916] [tempesta fw] Warning: pending active connections for 5s (connections count 0x1, queues count 0)
[27792.890754] [tempesta fw] Warning:   cpu 0(0), backlog size 0, work queue size 0
[27792.891098] [tempesta fw] Warning: Memory leakage is possible
[27797.889949] [tempesta fw] ERROR: Got stuck in releasing of server group objects! 1 objects was not released.
[27797.901635] [tempesta fw] exiting...
[27797.910025] =============================================================================
[27797.910687] BUG tfw_h2_conn_cache (Tainted: G           OE    ): Objects remaining in tfw_h2_conn_cache on __kmem_cache_shutdown()
[27797.911636] -----------------------------------------------------------------------------
[27797.911636] 
[27797.912488] Disabling lock debugging due to kernel taint
[27797.912938] INFO: Slab 0x00000000dd42fefc objects=15 used=1 fp=0x000000001b5c755b flags=0xfffffc0010200
[27797.913339] CPU: 0 PID: 19161 Comm: rmmod Tainted: G    B      OE     5.10.35 #1
[27797.913827] Hardware name: Tencent Cloud CVM, BIOS Bochs 01/01/2011
[27797.913933] Call Trace:
[27797.913933]  dump_stack+0x6b/0x83
[27797.913933]  slab_err+0xb7/0xdc
[27797.913933]  ? on_each_cpu_cond_mask+0x6e/0x80
[27797.913933]  __kmem_cache_shutdown.cold+0x31/0xfe
[27797.913933]  kmem_cache_destroy+0x53/0x110
[27797.913933]  tfw_sock_clnt_exit+0x21/0x40 [tempesta_fw]
[27797.913933]  ? tfw_sock_clnt_init+0xb0/0xb0 [tempesta_fw]
[27797.913933]  ? tfw_exit+0xc2/0xd3 [tempesta_fw]
[27797.913933]  ? __do_sys_delete_module+0x190/0x300
[27797.913933]  ? exit_to_user_mode_prepare+0x32/0x120
[27797.913933]  ? do_syscall_64+0x33/0x80
[27797.913933]  ? entry_SYSCALL_64_after_hwframe+0x44/0xa9
[27797.913933] INFO: Object 0x000000003d17e7f8 @offset=18864
[27797.920450] kmem_cache_destroy tfw_h2_conn_cache: Slab cache still has objects
[27797.920821] CPU: 0 PID: 19161 Comm: rmmod Tainted: G    B      OE     5.10.35 #1
[27797.921189] Hardware name: Tencent Cloud CVM, BIOS Bochs 01/01/2011
[27797.921650] Call Trace:
[27797.922004]  dump_stack+0x6b/0x83
[27797.922437]  kmem_cache_destroy.cold+0x15/0x1a
[27797.922867]  tfw_sock_clnt_exit+0x21/0x40 [tempesta_fw]
[27797.923274]  ? tfw_sock_clnt_init+0xb0/0xb0 [tempesta_fw]
[27797.923792]  ? tfw_exit+0xc2/0xd3 [tempesta_fw]
[27797.924162]  ? __do_sys_delete_module+0x190/0x300
[27797.924431]  ? exit_to_user_mode_prepare+0x32/0x120
[27797.924431]  ? do_syscall_64+0x33/0x80
[27797.924431]  ? entry_SYSCALL_64_after_hwframe+0x44/0xa9
[27797.944885] [tdb] Shutdown Tempesta DB

(this is a digest. Full log attached.)
Definitely this is the same bug.

I'll post additional info here if/when succede to reproduce and analyse the case.
zuer rong log.txt

Dmitry-Gouriev · 2021-12-27T23:20:24Z

Also a case (reproducible)

How to reproduce

Put virginal compiled TFW in /root/tempesta.
Install virginal tempesta-test suite.
Create default test configuration

./run_tests.py -d

Run as root the test

./run_tests.py h2/test_h2_specs.py

Get the netconsole log.
The log is attached.

Events in the trace

All begin when the test h2.test_h2_specs.H2Load.test_h2_specs is started.

1. Firstly we get a warning

[  124.560291] WARNING: CPU: 0 PID: 766 at /home/gouriev/work/tempesta/fw/hpack.c:2401 tfw_hpack_rbtree_find+0xda5/0xe00 [tempesta_fw]

This happend at the line:

			WARN_ON_ONCE(state != HPACK_HDR_VALUE_FOUND);

As a result, the request is dropped.

2. The next warning appears when (probably) processing the next request:

[  171.367937] WARNING: CPU: 2 PID: 763 at /home/gouriev/work/tempesta/fw/ss_skb.c:1636 ss_skb_cut_extra_data+0x1d0/0x200 [tempesta_fw]

This happens at the line

			if (WARN_ON_ONCE(skb_head == skb->next))
				return -EINVAL;

3. Once more warning appears

[  224.555828] WARNING: CPU: 0 PID: 984 at /home/gouriev/work/tempesta/fw/http_frame.c:232 tfw_h2_context_clear+0x1d/0x30 [tempesta_fw]

at the line

void
tfw_h2_context_clear(TfwH2Ctx *ctx)
{
	WARN_ON_ONCE(ctx->streams_num);
	tfw_hpack_clean(&ctx->hpack);
}

4. And finaly we get a message similar to main bug in this issue

[  224.955818] BUG tfw_stream_cache (Tainted: G        W  OE    ): Objects remaining in tfw_stream_cache on __kmem_cache_shutdown()

Several subsequent tests reproduce the same bug.

test_h2_specs remote.log

Dmitry-Gouriev · 2022-01-12T01:20:12Z

Some analytics on the way

http_stream.h:

TfwStream *tfw_h2_add_stream(TfwStreamSched *sched, unsigned int id,
			     unsigned short weight, unsigned int wnd);
void tfw_h2_delete_stream(TfwStream *stream);
...
void tfw_h2_stop_stream(TfwStreamSched *sched, TfwStream *stream);

Where the tfw_h2_add_stream() allocates the stream from the cache and adds it to rb_tree,
whereas the tfw_h2_stop_stream() removes the stream from rb_tree only (also calls fake tfw_h2_remove_stream_dep())
and the tfw_h2_delete_stream() frees the stream in the cache only.

However the only calls of these functions are located in:

static inline void
tfw_h2_stream_clean(TfwH2Ctx *ctx, TfwStream *stream)
{
	tfw_h2_stop_stream(&ctx->sched, stream);
	tfw_h2_delete_stream(stream);
	--ctx->streams_num;
}

(http_frame.c)
and never used separately.

The proposal is to remove the tfw_h2_stop_stream() at all and move all it's semantics into the tfw_h2_delete_stream()
(not highly proiritated).

Dmitry-Gouriev · 2022-01-12T15:21:41Z

Another analytics on the way

void
tfw_h2_conn_streams_cleanup(TfwH2Ctx *ctx)
{

...
	rbtree_postorder_for_each_entry_safe(cur, next, &sched->streams, node) {
		tfw_h2_stream_unlink(ctx, cur);
		tfw_h2_stream_clean(ctx, cur);
	}
}

Here rbtree_postorder_for_each_entry_safe doc states:

Note, however, that it cannot handle other modifications that re-order the

rbtree it is iterating over. This includes calling rb_erase() on pos, as

rb_erase() may rebalance the tree, causing us to miss some nodes.

whereas tfw_h2_stream_clean() calls tfw_h2_stop_stream() which in turn calls rb_erase().

Seems to be a bug, moreover, a critical bug.

This bug is a good candidate for a reason of The Issue,
however, there could be another reason(s).

krizhanovsky · 2022-01-12T17:34:57Z

The proposal is to remove the tfw_h2_stop_stream() at all and move all it's semantics into the tfw_h2_delete_stream() (not highly proiritated).

I'm not sure about the proposal since we have #1472

Please move #1377 (comment) and #1377 (comment) to a new task for https://github.com/tempesta-tech/tempesta/milestone/11 milestone.

The original user report and my scenario did not involve HTTP/2 at all, this is pure HTTP/1 over TLS problem. Please observe #1422 "tfw_cli_cache() allocates HTTP/2 context even for HTTP/1 connections". I reckon the bug is much simpler.

Dmitry-Gouriev · 2022-01-13T01:36:51Z

I have repeated this test #1377 (comment)
but can not reproduce the fault in this way.

Everything works fine.

Dmitry-Gouriev · 2022-01-13T02:23:45Z

Additionaly I have insert the catcher (WARN_ON(1)) into tfw_h2_add_stream() which is the only function which allocates from tfw_stream_cache (the cache in the fault) and have not catch any allocation when working with TLS requests.

Realy tfw_tls_init() creates the tfw_stream_cache but no one allocation from it encountered for now.
Realy tfw_sock_clnt_init (called from tfw_init()) creates two caches tfw_cli_conn_cache and tfw_h2_conn_cache,

Dmitry-Gouriev · 2022-01-13T03:22:23Z

Please observe #1422 "tfw_cli_cache() allocates HTTP/2 context even for HTTP/1 connections".

True, this is called via TFW_CONN_HOOK_CALL

[1402171.957686] WARNING: CPU: 0 PID: 135063 at /home/gouriev/work/my/tem
pesta/fw/http_frame.c:208 tfw_h2_context_init+0x9/0x80 [tempesta_fw]
[1402172.034612]  <IRQ>
[1402172.036095]  ? tfw_tls_conn_init+0x56/0xa0 [tempesta_fw]
[1402172.038267]  ? tfw_sock_clnt_new+0x14f/0x290 [tempesta_fw]
[1402172.040646]  ? tcp_mstamp_refresh+0xe/0x40
[1402172.042620]  ? ss_tcp_state_change+0xd2/0x220 [tempesta_fw]
[1402172.045634]  ? tcp_rcv_state_process+0xb39/0xf30
[1402172.047962]  ? tcp_check_req+0x187/0x550
[1402172.049799]  ? tcp_child_process+0x94/0x180
[1402172.052335]  ? tcp_v4_rcv+0x9b7/0xd80
[1402172.055010]  ? ip_protocol_deliver_rcu+0x2b/0x1b0
[1402172.058182]  ? ip_local_deliver_finish+0x44/0x50
[1402172.061168]  ? __netif_receive_skb_one_core+0x87/0xa0
[1402172.064341]  ? process_backlog+0x96/0x160
[1402172.066352]  ? net_rx_action+0x145/0x3e0
[1402172.068328]  ? __do_softirq+0xcf/0x284
[1402172.070253]  ? asm_call_irq_on_stack+0x12/0x20
[1402172.072298]  </IRQ>

(the response from artificaly inserted WARN_ON(1) catcher).

Dmitry-Gouriev · 2022-01-13T12:20:49Z

Ghkm.. I am confised a little...
The initial report #1377 (comment)
and my case #1377 (comment)
are about the tfw_stream_cache and so are connected with h2 functions
whereas
the Alexander's case #1377 (comment)
and Zuer Rong's case #1377 (comment)
are about the tfw_h2_conn_cache and so are ,ost likely connected with TLS functions only.

It seems there are different bugs.
Now focus on the TLS bug.

krizhanovsky · 2022-04-09T11:31:31Z

WARN_ON_ONCE(state != HPACK_HDR_VALUE_FOUND) in tfw_hpack_node_compare() raises 100% if an upstream Nginx sends a header with an empty value.

Fix minor warning for #1377

krizhanovsky · 2022-07-14T01:01:06Z

Just caught warning on simple while :; do ./scripts/tempesta.sh --restart; sleep 10; done and wrk -d 3600 -c 1000 -t 2 -H 'connection: close' https://ubuntu:443/ and _single_CPU VM (I believe I saw it previously on HTTP/2 vs HTTPS handling #1643 or master branch, but this is the same test case as in HTTP/2 vs HTTPS handling #1643 (comment)):

[ 1147.562181] WARNING: CPU: 0 PID: 10 at /root/tempesta/fw/tls.c:294 tfw_tls_encrypt+0xaab/0xf00 [tempesta_fw]
[ 1147.563310] Modules linked in: tempesta_fw(O) tempesta_db(O) tempesta_tls(O) tempesta_lib(O) intel_rapl_msr ppdev intel_rapl_common rapl sg serio_raw parport_pc parport button loop sch_fq_codel ipmi_devintf ipmi_msghandler msr configfs ip_tables x_tables ext4 crc16 mbcache jbd2 efivars linear md_mod virtio_net net_failover failover virtio_blk sr_mod cdrom ata_generic bochs_drm drm_vram_helper drm_ttm_helper ttm drm_kms_helper ata_piix syscopyarea sysfillrect sysimgblt fb_sys_fops libata drm crct10dif_pclmul psmouse i2c_piix4 virtio_pci virtio_ring virtio scsi_mod
[ 1147.569008] CPU: 0 PID: 10 Comm: ksoftirqd/0 Tainted: G           O      5.10.35-kdump+ #14
[ 1147.569996] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
[ 1147.570959] RIP: 0010:tfw_tls_encrypt+0xaab/0xf00 [tempesta_fw]
[ 1147.571644] Code: c2 48 8b 43 60 48 8d b3 68 01 00 00 48 89 74 24 08 c7 44 24 18 e0 ff ff ff a8 01 0f 85 03 fc ff ff 0f 0b e9 fc fb ff ff 0f 0b <0f> 0b e9 16 f7 ff ff 0f 0b 0f 0b e9 cf f6 ff ff 31 d2 89 c6 48 89
[ 1147.573799] RSP: 0018:ffffc900000d7788 EFLAGS: 00010202
[ 1147.574539] RAX: 0000000000000000 RBX: ffff888111f1d400 RCX: dffffc0000000000
[ 1147.575428] RDX: 0000000000000007 RSI: ffff88800af31000 RDI: ffff88800af3102c
[ 1147.576216] RBP: 0000000000000002 R08: ffffffffc0901301 R09: ffff888111f1d54f
[ 1147.576997] R10: ffffed10223e3aa9 R11: 0000000000000001 R12: 000000008f3a73ad
[ 1147.577865] R13: ffff88800af3102c R14: ffff88800af31000 R15: 000000008f3a73ae
[ 1147.578650] FS:  0000000000000000(0000) GS:ffff888118200000(0000) knlGS:0000000000000000
[ 1147.579537] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1147.580174] CR2: 000055b2cc1fa7d8 CR3: 0000000114b90001 CR4: 0000000000370ef0
[ 1147.581019] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1147.581876] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 1147.583103] Call Trace:
[ 1147.583434]  ? netdev_core_pick_tx+0x110/0x110
[ 1147.583975]  ? tfw_tls_connection_recv+0x600/0x600 [tempesta_fw]
[ 1147.584843]  ? __orc_find+0x63/0xc0
[ 1147.585262]  ? ip_finish_output2+0x331/0x9f0
[ 1147.585806]  ? __ip_flush_pending_frames.constprop.0+0x120/0x120
[ 1147.589039]  ? __ip_finish_output.part.0+0xf5/0x2d0
[ 1147.591909]  ? ip_output+0xfb/0x1b0
[ 1147.594669]  ? ip_mc_output+0x420/0x420
[ 1147.597249]  ? create_prof_cpu_mask+0x20/0x20
[ 1147.600431]  ? ipv4_dst_check+0x60/0x80
[ 1147.603530]  ? _raw_spin_lock_irqsave+0x6b/0xb0
[ 1147.607156]  ? _raw_write_lock_irqsave+0xb0/0xb0
[ 1147.610284]  ? __ip_queue_xmit+0x2fa/0x790
[ 1147.613084]  ? enqueue_timer+0xb5/0x1b0
[ 1147.615821]  ? __mod_timer+0x3ea/0x5f0
[ 1147.618356]  ? trace_event_raw_event_hrtimer_start+0x180/0x180
[ 1147.621054]  ? __tcp_select_window+0x350/0x350
[ 1147.623977]  ? ret_from_fork+0x1f/0x30
[ 1147.626570]  ? sk_reset_timer+0x10/0x70
[ 1147.629089]  ? tfw_tls_connection_recv+0x600/0x600 [tempesta_fw]
[ 1147.631831]  tcp_write_xmit+0x808/0x1220
[ 1147.634297]  ? tcp_mtu_probe+0x9b0/0x9b0
[ 1147.637089]  ? tcp_sync_mss+0x260/0x260
[ 1147.639521]  ? __kasan_slab_free+0x101/0x130
[ 1147.642101]  __tcp_push_pending_frames+0x51/0x140
[ 1147.644633]  ss_do_close+0x71a/0x7b0 [tempesta_fw]
[ 1147.647086]  ? _raw_spin_lock+0x65/0xa0
[ 1147.649332]  ss_tx_action+0x497/0x610 [tempesta_fw]
[ 1147.651783]  ? ss_do_send.constprop.0+0x420/0x420 [tempesta_fw]
[ 1147.654283]  ? net_rx_action+0x2a3/0x300
[ 1147.656410]  ? napi_poll+0x2f0/0x2f0
[ 1147.658472]  net_tx_action+0xcf/0x370
[ 1147.660452]  __do_softirq+0xe9/0x368
[ 1147.662437]  ? kthread_should_stop+0x41/0x50
[ 1147.664432]  ? takeover_tasklets+0x2b0/0x2b0
[ 1147.666609]  run_ksoftirqd+0x15/0x20

which is

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

krizhanovsky · 2022-07-20T15:39:14Z

One more TCP warning plus to the previous one on wrk with keep alive connections wrk -d 3600 -c 1000 -t 2 https://ubuntu:443/ (as previously on my current branch ak-h2-vs-https as of commit d0f5d9b, I didn't test it on master):

[13953.145201] ------------[ cut here ]------------
[13953.147773] WARNING: CPU: 2 PID: 915 at /root/tempesta/fw/tls.c:226 tfw_tls_tcp_propagate_dseq+0x76/0xb0 [tempesta_fw]
[13953.150851] Modules linked in: tempesta_fw(O) tempesta_db(O) tempesta_tls(O) tempesta_lib(O) intel_rapl_msr intel_rapl_common rapl ppdev sg serio_raw parport_pc parport button loop sch_fq_codel ipmi_devintf ipmi_msghandler msr configfs ip_tables x_tables ext4 crc16 mbcache jbd2 efivars linear md_mod virtio_net net_failover virtio_blk failover sr_mod cdrom ata_generic bochs_drm drm_vram_helper drm_ttm_helper ttm ata_piix libata drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops i2c_piix4 drm crct10dif_pclmul virtio_pci virtio_ring psmouse scsi_mod virtio [last unloaded: tempesta_lib]
[13953.166177] CPU: 2 PID: 915 Comm: sshd Tainted: G           O      5.10.35-kdump+ #14
[13953.170240] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
[13953.173415] RIP: 0010:tfw_tls_tcp_propagate_dseq+0x76/0xb0 [tempesta_fw]
[13953.176321] Code: 74 2a 48 8d 7b 34 44 8b 7b 28 e8 a5 cc 21 c2 0f b6 43 34 4c 89 f7 45 01 ef 83 e0 01 41 01 c7 e8 20 ce 21 c2 44 3b 7b 2c 74 02 <0f> 0b 48 8d 7d 2c e8 0f ce 21 c2 8b 6d 2c 4c 89 e7 e8 84 ce 21 c2
[13953.182489] RSP: 0018:ffffc900001c88b8 EFLAGS: 00010202
[13953.185105] RAX: 0000000000000000 RBX: ffff88811a4a1600 RCX: dffffc0000000000
[13953.188070] RDX: 0000000000000007 RSI: ffff888104949600 RDI: ffff88811a4a162c
[13953.190982] RBP: ffff888104949600 R08: ffffffffc0bb59d0 R09: ffffea000436b580
[13953.193813] R10: fffff9400086d6b6 R11: 0000000000000001 R12: ffff88811a4a1628
[13953.196658] R13: 0000000000004927 R14: ffff88811a4a162c R15: 0000000090b1ad75
[13953.199567] FS:  00007f74316a2180(0000) GS:ffff88811b700000(0000) knlGS:0000000000000000
[13953.202710] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[13953.205533] CR2: 000055c995b29b28 CR3: 0000000114b24006 CR4: 0000000000370ee0
[13953.208545] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[13953.211354] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[13953.214246] Call Trace:
[13953.216584]  <IRQ>
[13953.218927]  tfw_tls_encrypt+0x45f/0xf00 [tempesta_fw]
[13953.221522]  ? tfw_tls_connection_recv+0x600/0x600 [tempesta_fw]
[13953.224162]  ? add_interrupt_randomness+0x1a1/0x310
[13953.226748]  ? _raw_read_lock_irq+0x30/0x30
[13953.229560]  ? handle_irq_event+0xf4/0x130
[13953.232150]  ? handle_irq_event_percpu+0xc0/0xc0
[13953.234714]  ? _raw_spin_lock+0x65/0xa0
[13953.237209]  ? _raw_read_lock_irq+0x30/0x30
[13953.239843]  ? handle_edge_irq+0x1d5/0x380
[13953.242664]  ? idle_cpu+0x40/0x80
[13953.245272]  ? irq_exit_rcu+0x35/0x100
[13953.247976]  ? common_interrupt+0x69/0x110
[13953.250581]  ? asm_common_interrupt+0x1e/0x40
[13953.253280]  ? enqueue_timer+0x90/0x1b0
[13953.255841]  ? _raw_spin_unlock_irqrestore+0xd/0x20
[13953.258741]  ? _raw_spin_unlock_irqrestore+0x12/0x20
[13953.261472]  ? pg_skb_alloc+0x5ef/0x690
[13953.264077]  ? skb_zerocopy_clone+0x58/0x270
[13953.266759]  ? skb_split+0x4c3/0x640
[13953.269354]  ? tcp_fragment_tstamp+0x4e/0x120
[13953.271936]  ? tfw_tls_connection_recv+0x600/0x600 [tempesta_fw]
[13953.274661]  tcp_write_xmit+0x808/0x1220
[13953.277185]  ? tcp_mtu_probe+0x9b0/0x9b0
[13953.279804]  ? tcp_sync_mss+0x260/0x260
[13953.282256]  __tcp_push_pending_frames+0x51/0x140
[13953.284804]  ss_do_close+0x71a/0x7b0 [tempesta_fw]
[13953.287159]  ? _raw_spin_lock+0x65/0xa0
[13953.289573]  ss_tx_action+0x497/0x610 [tempesta_fw]
[13953.291872]  ? ss_do_send.constprop.0+0x420/0x420 [tempesta_fw]
[13953.294340]  ? net_rx_action+0x2a3/0x300
[13953.296427]  ? napi_poll+0x2f0/0x2f0
[13953.298866]  net_tx_action+0xcf/0x370
[13953.301002]  __do_softirq+0xe9/0x368
[13953.302919]  asm_call_irq_on_stack+0xf/0x20
[13953.304958]  </IRQ>
[13953.306683]  do_softirq_own_stack+0x32/0x40
[13953.308755]  irq_exit_rcu+0xb3/0x100
[13953.310779]  common_interrupt+0x69/0x110
[13953.312628]  asm_common_interrupt+0x1e/0x40
[13953.314439] RIP: 0010:kmem_cache_free.part.0+0x30/0x80
[13953.316385] Code: f4 55 48 89 fd 53 9c 5b fa 4c 8b 6c 24 20 4c 89 ea e8 b4 1e 00 00 84 c0 75 0e 4c 89 ea 4c 89 e6 48 89 ef e8 02 d3 ff ff 53 9d <48> 8b 74 24 20 0f 1f 44 00 00 5b 5d 41 5c 41 5d c3 65 8b 05 18 9f
[13953.321787] RSP: 0018:ffffc90000e57668 EFLAGS: 00000286
[13953.324001] RAX: 0000000000000001 RBX: 0000000000000286 RCX: 0000000000000800
[13953.326340] RDX: ffff8881114158c0 RSI: ffff8881001d8000 RDI: ffff88800b4d3500
[13953.328938] RBP: ffff8881001d8000 R08: 00000000bf8e3e6d R09: ffffffff84abb463
[13953.331470] R10: fffffbfff095768c R11: 0000000000000001 R12: ffff88800b4d3500
[13953.333783] R13: ffffffff82b3bcfa R14: ffff88800b4d3500 R15: ffff888108708040
[13953.336474]  ? finish_task_switch+0x21a/0x2d0
[13953.338722]  finish_task_switch+0x21a/0x2d0
[13953.340970]  ? __switch_to+0x357/0x6c0
[13953.343185]  __schedule+0x38c/0xaa0
[13953.345245]  ? io_schedule_timeout+0xb0/0xb0
[13953.347331]  ? _raw_spin_unlock_irqrestore+0x20/0x20
[13953.352271]  schedule+0x6a/0x120
[13953.354206]  schedule_hrtimeout_range_clock+0x187/0x190
[13953.356379]  ? hrtimer_nanosleep_restart+0xb0/0xb0
[13953.358698]  ? _raw_spin_lock_irqsave+0x6b/0xb0
[13953.360831]  ? _raw_write_lock_irqsave+0xb0/0xb0
[13953.362990]  ? tcp_stream_memory_free+0x65/0x80
[13953.365268]  ? tty_buffer_space_avail+0x2c/0x40
[13953.367576]  poll_schedule_timeout.constprop.0+0xa7/0x110
[13953.369989]  ? get_order+0x20/0x20
[13953.372037]  ? ldsem_up_read+0xe/0x30
[13953.374043]  do_poll.constprop.0+0x2e5/0x470
[13953.376006]  ? __x32_compat_sys_pselect6_time64+0xc0/0xc0
[13953.378470]  ? check_stack_object+0x1d/0x60
[13953.380657]  do_sys_poll+0x2b4/0x350
[13953.382544]  ? do_poll.constprop.0+0x470/0x470
[13953.384758]  ? tcp_mtu_probe+0x9b0/0x9b0
[13953.386687]  ? tcp_recvmsg+0x10b0/0x10b0
[13953.388847]  ? __tcp_push_pending_frames+0x51/0x140
[13953.391063]  ? tcp_sendmsg_locked+0x477/0x13b0
[13953.393162]  ? poll_schedule_timeout.constprop.0+0x110/0x110
[13953.395682]  ? poll_schedule_timeout.constprop.0+0x110/0x110
[13953.398168]  ? poll_schedule_timeout.constprop.0+0x110/0x110
[13953.400415]  ? poll_schedule_timeout.constprop.0+0x110/0x110
[13953.402472]  ? poll_schedule_timeout.constprop.0+0x110/0x110
[13953.404640]  ? poll_schedule_timeout.constprop.0+0x110/0x110
[13953.406675]  ? new_sync_write+0x30d/0x320
[13953.408777]  ? new_sync_read+0x320/0x320
[13953.410791]  ? fsnotify+0x4c0/0x520
[13953.412682]  ? _raw_spin_lock_irq+0x66/0xa0
[13953.414593]  ? recalc_sigpending_tsk+0x7e/0xb0
[13953.416614]  ? recalc_sigpending+0x55/0x70
[13953.418638]  ? set_user_sigmask+0x119/0x160
[13953.420679]  ? __set_current_blocked+0x80/0x80
[13953.422647]  ? __x64_sys_rt_sigsuspend+0xc0/0xc0
[13953.424604]  __x64_sys_ppoll+0x124/0x1c0
[13953.426299]  ? __ia32_compat_sys_ppoll_time64+0x1b0/0x1b0
[13953.428459]  ? ksys_write+0xf7/0x120
[13953.430287]  ? __ia32_sys_read+0x40/0x40
[13953.431938]  ? fpregs_assert_state_consistent+0x4d/0x60
[13953.433808]  do_syscall_64+0x2d/0x70
[13953.435508]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[13953.437410] RIP: 0033:0x7f7431b8ae1f
[13953.439194] Code: f3 0f 6f 02 4c 8d 6c 24 20 0f 29 44 24 20 64 8b 04 25 18 00 00 00 85 c0 75 39 41 b8 08 00 00 00 4c 89 ea b8 0f 01 00 00 0f 05 <48> 3d 00 f0 ff ff 77 79 48 8b 54 24 38 64 48 2b 14 25 28 00 00 00
[13953.444280] RSP: 002b:00007ffe9e76d630 EFLAGS: 00000246 ORIG_RAX: 000000000000010f
[13953.446534] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f7431b8ae1f
[13953.448983] RDX: 0000000000000000 RSI: 0000000000000004 RDI: 000055fe6ed687c0
[13953.451190] RBP: 0000000000000004 R08: 0000000000000008 R09: 0000000000008000
[13953.453447] R10: 00007ffe9e76d790 R11: 0000000000000246 R12: 0000000000000000
[13953.456251] R13: 0000000000000000 R14: 0000000000000004 R15: 000055fe6ed37af0
[13953.458767] ---[ end trace bf65aedb9ce18084 ]---
[13953.472184] net_ratelimit: 66 callbacks suppressed
[13953.472188] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.472630] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.485687] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.488744] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.490341] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.493854] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.502974] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.503084] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.511025] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.511622] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.815739] [tdb] Close table 'client0.tdb'
[13953.915951] [tdb] Close table 'sessions0.tdb'
[13955.464208] [tdb] Close table 'cache0.tdb'
[13955.679480] [tdb] Close table 'filter0.tdb'

const-t · 2022-08-10T12:37:45Z

Caught warning during sending http2 multiplexed request with six or above streams.

[19097.737101] ------------[ cut here ]------------
[19097.737670] WARNING: CPU: 1 PID: 27635 at /home/constantine/projects/tempesta/fw/http_frame.c:232 tfw_h2_context_clear+0x15/0x20 [tempesta_fw]
[19097.739075] Modules linked in: tempesta_fw(OE) tempesta_db(OE) tempesta_tls(OE) tempesta_lib(OE) sha256_ssse3(E) sha512_ssse3(E) sha512_generic(E) 9p(E) fscache(E) rfkill(E) kvm_amd(E) ccp(E) rng_core(E) kvm(E) irqbypass(E) ghash_clmulni_intel(E) aesni_intel(E) libaes(E) crypto_simd(E) cryptd(E) glue_helper(E) snd_pcm(E) snd_timer(E) snd(E) joydev(E) soundcore(E) 9pnet_virtio(E) serio_raw(E) pcspkr(E) sg(E) 9pnet(E) evdev(E) qemu_fw_cfg(E) msr(E) parport_pc(E) ppdev(E) lp(E) parport(E) fuse(E) configfs(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc32c_generic(E) crc16(E) mbcache(E) jbd2(E) sr_mod(E) cdrom(E) ata_generic(E) virtio_blk(E) bochs_drm(E) drm_vram_helper(E) drm_ttm_helper(E) e1000(E) ttm(E) crct10dif_pclmul(E) virtio_pci(E) crct10dif_common(E) virtio_ring(E) drm_kms_helper(E) cec(E) ata_piix(E) crc32_pclmul(E) drm(E) virtio(E) floppy(E) libata(E) scsi_mod(E) crc32c_intel(E) psmouse(E) i2c_piix4(E) button(E) [last unloaded: tempesta_lib]
[19097.748521] CPU: 1 PID: 27635 Comm: python3 Kdump: loaded Tainted: G    B   W  OE     5.10.35 #2
[19097.749472] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS ArchLinux 1.16.0-1 04/01/2014
[19097.750469] RIP: 0010:tfw_h2_context_clear+0x15/0x20 [tempesta_fw]
[19097.751147] Code: 4b 1c 48 89 53 24 48 89 43 2c 5b e9 d5 0a ff ff 0f 1f 44 00 00 0f 1f 44 00 00 48 83 7f 38 00 75 09 48 83 c7 68 e9 ab 0b ff ff <0f> 0b 48 83 c7 68 e9 a0 0b ff ff 0f 1f 44 00 00 48 83 c4 80 49 89
[19097.753506] RSP: 0018:ffffc900000b8ed0 EFLAGS: 00010202
[19097.754074] RAX: ffffffffa0a0cae0 RBX: ffff888276d2e480 RCX: 0000000080170012
[19097.754848] RDX: 0000000080170013 RSI: ffffffffa09b100a RDI: ffff888276c6fa78
[19097.755638] RBP: ffff888276c6f380 R08: 0000000000000001 R09: 0000000000000000
[19097.756411] R10: 0000000000000001 R11: 0000000000000000 R12: ffff888276c6f6f8
[19097.757182] R13: ffff88815173df00 R14: 0000000000000009 R15: ffff888276d2e500
[19097.757956] FS:  00007fbca0e5d740(0000) GS:ffff888276d00000(0000) knlGS:0000000000000000
[19097.758833] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[19097.759659] CR2: 00007fbc9f3c2e40 CR3: 0000000154a28000 CR4: 0000000000350ee0
[19097.760433] Call Trace:
[19097.760711]  <IRQ>
[19097.760944]  tfw_tls_conn_dtor+0x1e/0x180 [tempesta_fw]
[19097.761520]  ss_tx_action+0x45e/0x660 [tempesta_fw]
[19097.762059]  ? process_backlog+0x129/0x170
[19097.762508]  net_tx_action+0x94/0x240
[19097.762913]  __do_softirq+0xd0/0x284
[19097.763313]  asm_call_irq_on_stack+0x12/0x20
[19097.763790]  </IRQ>
[19097.764028]  do_softirq_own_stack+0x37/0x40
[19097.764491]  do_softirq+0x5e/0x70
[19097.764859]  __local_bh_enable_ip+0x4b/0x50
[19097.765325]  ip_finish_output2+0x1a8/0x580
[19097.765775]  ? __ip_finish_output+0xf2/0x1f0
[19097.766244]  __ip_queue_xmit+0x180/0x410
[19097.766677]  ? __wake_up_common+0x80/0x180
[19097.767137]  __tcp_transmit_skb+0xa02/0xbb0
[19097.767605]  tcp_write_xmit+0x40b/0x1250
[19097.768038]  ? tcp_current_mss+0x5b/0xb0
[19097.768468]  __tcp_push_pending_frames+0x32/0xf0
[19097.768980]  tcp_close+0x2ee/0x470
[19097.769356]  inet_release+0x42/0x80
[19097.769743]  __sock_release+0x3d/0xa0
[19097.770144]  sock_close+0x11/0x20
[19097.770511]  __fput+0x95/0x240
[19097.770848]  task_work_run+0x65/0xa0
[19097.771251]  exit_to_user_mode_prepare+0x109/0x110
[19097.771774]  syscall_exit_to_user_mode+0x28/0x140
[19097.772290]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[19097.772838] RIP: 0033:0x7fbca11d511b
[19097.773228] Code: 0f 05 48 3d 00 f0 ff ff 77 45 c3 0f 1f 40 00 48 83 ec 18 89 7c 24 0c e8 f3 fb ff ff 8b 7c 24 0c 41 89 c0 b8 03 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 35 44 89 c7 89 44 24 0c e8 31 fc ff ff 8b 44
[19097.774999] RSP: 002b:00007ffd35023620 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
[19097.775820] RAX: 0000000000000000 RBX: 00007fbc9d9cce80 RCX: 00007fbca11d511b
[19097.776383] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000005
[19097.776953] RBP: 0000000000000005 R08: 0000000000000000 R09: 0000000000929820
[19097.777523] R10: 0000000000512108 R11: 0000000000000293 R12: 0000000001cd7570
[19097.778089] R13: 0000000001cd5960 R14: 0000000000644d30 R15: 00007fbc9f3c2e08
[19097.778662] ---[ end trace 214d98fa19b2d1c3 ]---
[19098.014447] [tdb] Close table 'client0.tdb'
[19098.018872] [tdb] Close table 'sessions0.tdb'
[19098.081158] [tdb] Close table 'cache0.tdb'
[19098.114831] [tdb] Close table 'filter0.tdb'
[19098.115374] [tempesta fw] modules are stopped
[19098.140567] [tempesta fw] exiting...
[19098.202965] =============================================================================
[19098.203771] BUG tfw_stream_cache (Tainted: G    B   W  OE    ): Objects remaining in tfw_stream_cache on __kmem_cache_shutdown()
[19098.204740] -----------------------------------------------------------------------------
[19098.204740] 
[19098.205556] INFO: Slab 0x0000000079325155 objects=23 used=6 fp=0x00000000690a3e30 flags=0x17ffffc0010200
[19098.206298] CPU: 1 PID: 27767 Comm: rmmod Kdump: loaded Tainted: G    B   W  OE     5.10.35 #2
[19098.206977] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS ArchLinux 1.16.0-1 04/01/2014
[19098.207854] Call Trace:
[19098.208057]  dump_stack+0x6b/0x83
[19098.208325]  slab_err+0xb7/0xdc
[19098.208594]  ? slub_cpu_dead+0xa0/0xa0
[19098.208895]  ? slub_cpu_dead+0xa0/0xa0
[19098.209197]  ? slub_cpu_dead+0xa0/0xa0
[19098.209499]  __kmem_cache_shutdown.cold+0x3d/0x114
[19098.210282]  kmem_cache_destroy+0x53/0x110
[19098.210965]  tfw_tls_exit+0x20/0x30 [tempesta_fw]
[19098.211745]  tfw_exit+0xc1/0xd1 [tempesta_fw]
[19098.212461]  __do_sys_delete_module+0x190/0x300
[19098.213197]  do_syscall_64+0x33/0x80
[19098.213783]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[19098.214596] RIP: 0033:0x7f981a5287d7
[19098.215181] Code: 73 01 c3 48 8b 0d b9 f6 0b 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 b8 b0 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 89 f6 0b 00 f7 d8 64 89 01 48
[19098.218214] RSP: 002b:00007ffe64b01208 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[19098.219450] RAX: ffffffffffffffda RBX: 000055efb777d750 RCX: 00007f981a5287d7
[19098.220610] RDX: 000000000000000a RSI: 0000000000000800 RDI: 000055efb777d7b8
[19098.221772] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[19098.222966] R10: 00007f981a59bac0 R11: 0000000000000206 R12: 00007ffe64b01430
[19098.224287] R13: 00007ffe64b017da R14: 000055efb777d2a0 R15: 000055efb777d750
[19098.225463] INFO: Object 0x00000000d1d24ab1 @offset=3520
[19098.226333] INFO: Object 0x000000005de87673 @offset=4928
[19098.227336] INFO: Object 0x00000000bb6bb513 @offset=7040
[19098.228565] INFO: Object 0x000000008fa58d48 @offset=7744
[19098.229665] INFO: Object 0x000000001b9789d4 @offset=9856
[19098.230780] INFO: Object 0x00000000ee61bc33 @offset=11264
[19098.231987] kmem_cache_destroy tfw_stream_cache: Slab cache still has objects
[19098.233567] CPU: 1 PID: 27767 Comm: rmmod Kdump: loaded Tainted: G    B   W  OE     5.10.35 #2
[19098.235451] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS ArchLinux 1.16.0-1 04/01/2014
[19098.237461] Call Trace:
[19098.238003]  dump_stack+0x6b/0x83
[19098.238750]  kmem_cache_destroy.cold+0x15/0x1a
[19098.240073]  tfw_tls_exit+0x20/0x30 [tempesta_fw]
[19098.241146]  tfw_exit+0xc1/0xd1 [tempesta_fw]
[19098.242138]  __do_sys_delete_module+0x190/0x300
[19098.243160]  do_syscall_64+0x33/0x80
[19098.243950]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[19098.245034] RIP: 0033:0x7f981a5287d7
[19098.245833] Code: 73 01 c3 48 8b 0d b9 f6 0b 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 b8 b0 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 89 f6 0b 00 f7 d8 64 89 01 48
[19098.249960] RSP: 002b:00007ffe64b01208 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[19098.251644] RAX: ffffffffffffffda RBX: 000055efb777d750 RCX: 00007f981a5287d7
[19098.253080] RDX: 000000000000000a RSI: 0000000000000800 RDI: 000055efb777d7b8
[19098.254444] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[19098.256057] R10: 00007f981a59bac0 R11: 0000000000000206 R12: 00007ffe64b01430
[19098.257422] R13: 00007ffe64b017da R14: 000055efb777d2a0 R15: 000055efb777d750
[19098.282443] [tdb] Shutdown Tempesta DB

krizhanovsky · 2022-08-11T21:02:36Z

The Bad TLS alert is a separate issue: I leave a subtask here, but probably we should move it to a new issue. We constantly see the message with legitimate and good clients, which shouldn't send anything bad. Maybe it's a decoding issue linked with other TLS errors mentioned in this issue.

UPD this is just an invalid message printed when a peer closes TLS connection, removed in a2b71ce

RomanBelozerov · 2022-10-05T12:42:19Z

Quote

One more TCP warning plus to the previous one on wrk with keep alive connections wrk -d 3600 -c 1000 -t 2 https://ubuntu:443/ (as previously on my current branch ak-h2-vs-https as of commit d0f5d9b, I didn't test it on master):

[13953.145201] ------------[ cut here ]------------
[13953.147773] WARNING: CPU: 2 PID: 915 at /root/tempesta/fw/tls.c:226 tfw_tls_tcp_propagate_dseq+0x76/0xb0 [tempesta_fw]
[13953.150851] Modules linked in: tempesta_fw(O) tempesta_db(O) tempesta_tls(O) tempesta_lib(O) intel_rapl_msr intel_rapl_common rapl ppdev sg serio_raw parport_pc parport button loop sch_fq_codel ipmi_devintf ipmi_msghandler msr configfs ip_tables x_tables ext4 crc16 mbcache jbd2 efivars linear md_mod virtio_net net_failover virtio_blk failover sr_mod cdrom ata_generic bochs_drm drm_vram_helper drm_ttm_helper ttm ata_piix libata drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops i2c_piix4 drm crct10dif_pclmul virtio_pci virtio_ring psmouse scsi_mod virtio [last unloaded: tempesta_lib]
[13953.166177] CPU: 2 PID: 915 Comm: sshd Tainted: G           O      5.10.35-kdump+ #14
[13953.170240] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
[13953.173415] RIP: 0010:tfw_tls_tcp_propagate_dseq+0x76/0xb0 [tempesta_fw]
[13953.176321] Code: 74 2a 48 8d 7b 34 44 8b 7b 28 e8 a5 cc 21 c2 0f b6 43 34 4c 89 f7 45 01 ef 83 e0 01 41 01 c7 e8 20 ce 21 c2 44 3b 7b 2c 74 02 <0f> 0b 48 8d 7d 2c e8 0f ce 21 c2 8b 6d 2c 4c 89 e7 e8 84 ce 21 c2
[13953.182489] RSP: 0018:ffffc900001c88b8 EFLAGS: 00010202
[13953.185105] RAX: 0000000000000000 RBX: ffff88811a4a1600 RCX: dffffc0000000000
[13953.188070] RDX: 0000000000000007 RSI: ffff888104949600 RDI: ffff88811a4a162c
[13953.190982] RBP: ffff888104949600 R08: ffffffffc0bb59d0 R09: ffffea000436b580
[13953.193813] R10: fffff9400086d6b6 R11: 0000000000000001 R12: ffff88811a4a1628
[13953.196658] R13: 0000000000004927 R14: ffff88811a4a162c R15: 0000000090b1ad75
[13953.199567] FS:  00007f74316a2180(0000) GS:ffff88811b700000(0000) knlGS:0000000000000000
[13953.202710] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[13953.205533] CR2: 000055c995b29b28 CR3: 0000000114b24006 CR4: 0000000000370ee0
[13953.208545] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[13953.211354] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[13953.214246] Call Trace:
[13953.216584]  <IRQ>
[13953.218927]  tfw_tls_encrypt+0x45f/0xf00 [tempesta_fw]
[13953.221522]  ? tfw_tls_connection_recv+0x600/0x600 [tempesta_fw]
[13953.224162]  ? add_interrupt_randomness+0x1a1/0x310
[13953.226748]  ? _raw_read_lock_irq+0x30/0x30
[13953.229560]  ? handle_irq_event+0xf4/0x130
[13953.232150]  ? handle_irq_event_percpu+0xc0/0xc0
[13953.234714]  ? _raw_spin_lock+0x65/0xa0
[13953.237209]  ? _raw_read_lock_irq+0x30/0x30
[13953.239843]  ? handle_edge_irq+0x1d5/0x380
[13953.242664]  ? idle_cpu+0x40/0x80
[13953.245272]  ? irq_exit_rcu+0x35/0x100
[13953.247976]  ? common_interrupt+0x69/0x110
[13953.250581]  ? asm_common_interrupt+0x1e/0x40
[13953.253280]  ? enqueue_timer+0x90/0x1b0
[13953.255841]  ? _raw_spin_unlock_irqrestore+0xd/0x20
[13953.258741]  ? _raw_spin_unlock_irqrestore+0x12/0x20
[13953.261472]  ? pg_skb_alloc+0x5ef/0x690
[13953.264077]  ? skb_zerocopy_clone+0x58/0x270
[13953.266759]  ? skb_split+0x4c3/0x640
[13953.269354]  ? tcp_fragment_tstamp+0x4e/0x120
[13953.271936]  ? tfw_tls_connection_recv+0x600/0x600 [tempesta_fw]
[13953.274661]  tcp_write_xmit+0x808/0x1220
[13953.277185]  ? tcp_mtu_probe+0x9b0/0x9b0
[13953.279804]  ? tcp_sync_mss+0x260/0x260
[13953.282256]  __tcp_push_pending_frames+0x51/0x140
[13953.284804]  ss_do_close+0x71a/0x7b0 [tempesta_fw]
[13953.287159]  ? _raw_spin_lock+0x65/0xa0
[13953.289573]  ss_tx_action+0x497/0x610 [tempesta_fw]
[13953.291872]  ? ss_do_send.constprop.0+0x420/0x420 [tempesta_fw]
[13953.294340]  ? net_rx_action+0x2a3/0x300
[13953.296427]  ? napi_poll+0x2f0/0x2f0
[13953.298866]  net_tx_action+0xcf/0x370
[13953.301002]  __do_softirq+0xe9/0x368
[13953.302919]  asm_call_irq_on_stack+0xf/0x20
[13953.304958]  </IRQ>
[13953.306683]  do_softirq_own_stack+0x32/0x40
[13953.308755]  irq_exit_rcu+0xb3/0x100
[13953.310779]  common_interrupt+0x69/0x110
[13953.312628]  asm_common_interrupt+0x1e/0x40
[13953.314439] RIP: 0010:kmem_cache_free.part.0+0x30/0x80
[13953.316385] Code: f4 55 48 89 fd 53 9c 5b fa 4c 8b 6c 24 20 4c 89 ea e8 b4 1e 00 00 84 c0 75 0e 4c 89 ea 4c 89 e6 48 89 ef e8 02 d3 ff ff 53 9d <48> 8b 74 24 20 0f 1f 44 00 00 5b 5d 41 5c 41 5d c3 65 8b 05 18 9f
[13953.321787] RSP: 0018:ffffc90000e57668 EFLAGS: 00000286
[13953.324001] RAX: 0000000000000001 RBX: 0000000000000286 RCX: 0000000000000800
[13953.326340] RDX: ffff8881114158c0 RSI: ffff8881001d8000 RDI: ffff88800b4d3500
[13953.328938] RBP: ffff8881001d8000 R08: 00000000bf8e3e6d R09: ffffffff84abb463
[13953.331470] R10: fffffbfff095768c R11: 0000000000000001 R12: ffff88800b4d3500
[13953.333783] R13: ffffffff82b3bcfa R14: ffff88800b4d3500 R15: ffff888108708040
[13953.336474]  ? finish_task_switch+0x21a/0x2d0
[13953.338722]  finish_task_switch+0x21a/0x2d0
[13953.340970]  ? __switch_to+0x357/0x6c0
[13953.343185]  __schedule+0x38c/0xaa0
[13953.345245]  ? io_schedule_timeout+0xb0/0xb0
[13953.347331]  ? _raw_spin_unlock_irqrestore+0x20/0x20
[13953.352271]  schedule+0x6a/0x120
[13953.354206]  schedule_hrtimeout_range_clock+0x187/0x190
[13953.356379]  ? hrtimer_nanosleep_restart+0xb0/0xb0
[13953.358698]  ? _raw_spin_lock_irqsave+0x6b/0xb0
[13953.360831]  ? _raw_write_lock_irqsave+0xb0/0xb0
[13953.362990]  ? tcp_stream_memory_free+0x65/0x80
[13953.365268]  ? tty_buffer_space_avail+0x2c/0x40
[13953.367576]  poll_schedule_timeout.constprop.0+0xa7/0x110
[13953.369989]  ? get_order+0x20/0x20
[13953.372037]  ? ldsem_up_read+0xe/0x30
[13953.374043]  do_poll.constprop.0+0x2e5/0x470
[13953.376006]  ? __x32_compat_sys_pselect6_time64+0xc0/0xc0
[13953.378470]  ? check_stack_object+0x1d/0x60
[13953.380657]  do_sys_poll+0x2b4/0x350
[13953.382544]  ? do_poll.constprop.0+0x470/0x470
[13953.384758]  ? tcp_mtu_probe+0x9b0/0x9b0
[13953.386687]  ? tcp_recvmsg+0x10b0/0x10b0
[13953.388847]  ? __tcp_push_pending_frames+0x51/0x140
[13953.391063]  ? tcp_sendmsg_locked+0x477/0x13b0
[13953.393162]  ? poll_schedule_timeout.constprop.0+0x110/0x110
[13953.395682]  ? poll_schedule_timeout.constprop.0+0x110/0x110
[13953.398168]  ? poll_schedule_timeout.constprop.0+0x110/0x110
[13953.400415]  ? poll_schedule_timeout.constprop.0+0x110/0x110
[13953.402472]  ? poll_schedule_timeout.constprop.0+0x110/0x110
[13953.404640]  ? poll_schedule_timeout.constprop.0+0x110/0x110
[13953.406675]  ? new_sync_write+0x30d/0x320
[13953.408777]  ? new_sync_read+0x320/0x320
[13953.410791]  ? fsnotify+0x4c0/0x520
[13953.412682]  ? _raw_spin_lock_irq+0x66/0xa0
[13953.414593]  ? recalc_sigpending_tsk+0x7e/0xb0
[13953.416614]  ? recalc_sigpending+0x55/0x70
[13953.418638]  ? set_user_sigmask+0x119/0x160
[13953.420679]  ? __set_current_blocked+0x80/0x80
[13953.422647]  ? __x64_sys_rt_sigsuspend+0xc0/0xc0
[13953.424604]  __x64_sys_ppoll+0x124/0x1c0
[13953.426299]  ? __ia32_compat_sys_ppoll_time64+0x1b0/0x1b0
[13953.428459]  ? ksys_write+0xf7/0x120
[13953.430287]  ? __ia32_sys_read+0x40/0x40
[13953.431938]  ? fpregs_assert_state_consistent+0x4d/0x60
[13953.433808]  do_syscall_64+0x2d/0x70
[13953.435508]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[13953.437410] RIP: 0033:0x7f7431b8ae1f
[13953.439194] Code: f3 0f 6f 02 4c 8d 6c 24 20 0f 29 44 24 20 64 8b 04 25 18 00 00 00 85 c0 75 39 41 b8 08 00 00 00 4c 89 ea b8 0f 01 00 00 0f 05 <48> 3d 00 f0 ff ff 77 79 48 8b 54 24 38 64 48 2b 14 25 28 00 00 00
[13953.444280] RSP: 002b:00007ffe9e76d630 EFLAGS: 00000246 ORIG_RAX: 000000000000010f
[13953.446534] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f7431b8ae1f
[13953.448983] RDX: 0000000000000000 RSI: 0000000000000004 RDI: 000055fe6ed687c0
[13953.451190] RBP: 0000000000000004 R08: 0000000000000008 R09: 0000000000008000
[13953.453447] R10: 00007ffe9e76d790 R11: 0000000000000246 R12: 0000000000000000
[13953.456251] R13: 0000000000000000 R14: 0000000000000004 R15: 000055fe6ed37af0
[13953.458767] ---[ end trace bf65aedb9ce18084 ]---
[13953.472184] net_ratelimit: 66 callbacks suppressed
[13953.472188] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.472630] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.485687] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.488744] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.490341] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.493854] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.502974] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.503084] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.511025] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.511622] [tempesta tls] Warning: [::ffff:192.168.100.1] Bad TLS alert
[13953.815739] [tdb] Close table 'client0.tdb'
[13953.915951] [tdb] Close table 'sessions0.tdb'
[13955.464208] [tdb] Close table 'cache0.tdb'
[13955.679480] [tdb] Close table 'filter0.tdb'

I get like trace for tests long body and mtu 80 ip link set lo mtu 80. Test to reproduce: long_body.test_long_request.HttpsPostRequestTest1k

DMESG

------------[ cut here ]------------
[  273.302931] WARNING: CPU: 4 PID: 3132 at /root/tempesta/fw/tls.c:226 tfw_tls_tcp_propagate_dseq+0x35/0x50 [tempesta_fw]
[  273.302932] Modules linked in: tempesta_fw(OE) tempesta_db(OE) tempesta_tls(OE) tempesta_lib(OE) sha256_ssse3 sha512_ssse3 rfcomm bnep vsock_loopback vmw_vsock_virtio_transport_common vmw_vsock_vmci_transport vsock nls_iso8859_1 snd_ens1371 snd_ac97_codec intel_rapl_msr gameport intel_rapl_common btusb ac97_bus snd_pcm btrtl crct10dif_pclmul btbcm ghash_clmulni_intel snd_seq_midi btintel aesni_intel bluetooth snd_seq_midi_event crypto_simd cryptd snd_rawmidi glue_helper vmw_balloon snd_seq input_leds joydev ecdh_generic ecc snd_seq_device snd_timer snd serio_raw 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 ramoops pstore_blk efi_pstore pstore_zone reed_solomon ip_tables x_tables autofs4 hid_generic usbhid hid psmouse e1000 crc32_pclmul mptspi i2c_piix4 mptscsih mptbase ahci scsi_transport_spi libahci pata_acpi [last unloaded: tempesta_lib]
[  273.302972] CPU: 4 PID: 3132 Comm: wrk Tainted: G        W  OE     5.10.35+ #1
[  273.302973] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 11/12/2020
[  273.302977] RIP: 0010:tfw_tls_tcp_propagate_dseq+0x35/0x50 [tempesta_fw]
[  273.302978] Code: c7 68 01 00 00 48 89 e5 48 39 f8 74 2a 48 83 78 28 00 8b 48 70 74 15 8b 78 28 0f b6 50 34 01 cf 83 e2 01 01 fa 3b 50 2c 74 02 <0f> 0b 8b 56 2c 89 50 28 01 ca 89 50 2c 5d c3 66 66 2e 0f 1f 84 00
[  273.302979] RSP: 0018:ffffb0ebc057cb28 EFLAGS: 00010202
[  273.302980] RAX: ffff9eddf6385000 RBX: 000000000000001f RCX: 0000000000000018
[  273.302981] RDX: 00000000be1e888d RSI: ffff9eddf683d000 RDI: 00000000be1e888c
[  273.302981] RBP: ffffb0ebc057cb28 R08: 0000000000000000 R09: 00000000000002c0
[  273.302982] R10: 0000000000000001 R11: ffff9eddf683d000 R12: 0000000000000010
[  273.302983] R13: ffff9eddf765b900 R14: 0000000000000002 R15: ffff9eddf683d000
[  273.302984] FS:  0000000000000000(0000) GS:ffff9edeb5f00000(0000) knlGS:0000000000000000
[  273.302984] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  273.302985] CR2: 00007f8581187048 CR3: 0000000211c10005 CR4: 0000000000770ee0
[  273.303013] PKRU: 55555554
[  273.303014] Call Trace:
[  273.303015]  <IRQ>
[  273.303021]  tfw_tls_encrypt+0x2da/0x850 [tempesta_fw]
[  273.303025]  ? ip_fragment.constprop.0+0x48/0x90
[  273.303027]  ? prep_new_page+0xcd/0x120
[  273.303028]  ? get_page_from_freelist+0xed8/0x1100
[  273.303029]  ? ip_local_out+0x3d/0x50
[  273.303030]  ? __alloc_pages_nodemask+0x164/0x300
[  273.303032]  ? pg_skb_alloc+0x43b/0x480
[  273.303034]  ? skb_split+0x62/0x2d0
[  273.303035]  tcp_write_xmit+0x41d/0x1350
[  273.303037]  __tcp_push_pending_frames+0x37/0x100
[  273.303044]  ss_do_close+0x42e/0x5f0 [tempesta_fw]
[  273.303050]  ss_tx_action+0x417/0x5f0 [tempesta_fw]
[  273.303051]  ? process_backlog+0xdb/0x160
[  273.303052]  net_tx_action+0x9c/0x250
[  273.303055]  __do_softirq+0xd9/0x291
[  273.303057]  asm_call_irq_on_stack+0xf/0x20
[  273.303058]  </IRQ>
[  273.303060]  do_softirq_own_stack+0x3d/0x50
[  273.303062]  do_softirq.part.0+0x46/0x50
[  273.303063]  __local_bh_enable_ip+0x50/0x60
[  273.303064]  ip_finish_output2+0x1ab/0x590
[  273.303067]  ? __cgroup_bpf_run_filter_skb+0x3c3/0x3d0
[  273.303068]  __ip_finish_output+0xd8/0x220
[  273.303068]  ip_finish_output+0x2d/0xb0
[  273.303069]  ip_output+0x7a/0x100
[  273.303070]  ? __ip_finish_output+0xd8/0x220
[  273.303071]  ip_local_out+0x3d/0x50
[  273.303072]  __ip_queue_xmit+0x17a/0x470
[  273.303073]  ip_queue_xmit+0x15/0x20
[  273.303074]  __tcp_transmit_skb+0xa94/0xc90
[  273.303075]  tcp_write_xmit+0x453/0x1350
[  273.303076]  __tcp_push_pending_frames+0x37/0x100
[  273.303077]  tcp_send_fin+0x4e/0x190
[  273.303079]  tcp_close+0x33c/0x4e0
[  273.303080]  inet_release+0x4b/0x90
[  273.303082]  __sock_release+0x42/0xb0
[  273.303082]  sock_close+0x15/0x20
[  273.303084]  __fput+0xa9/0x260
[  273.303085]  ____fput+0xe/0x10
[  273.303087]  task_work_run+0x70/0xb0
[  273.303088]  do_exit+0x37b/0xaf0
[  273.303089]  ? vfs_write+0x218/0x280
[  273.303090]  do_group_exit+0x47/0xb0
[  273.303091]  __x64_sys_exit_group+0x18/0x20
[  273.303092]  do_syscall_64+0x38/0x90
[  273.303093]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  273.303094] RIP: 0033:0x7f8581064146
[  273.303095] Code: Unable to access opcode bytes at RIP 0x7f858106411c.
[  273.303095] RSP: 002b:00007ffdd9258a28 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
[  273.303096] RAX: ffffffffffffffda RBX: 00007f85811698a0 RCX: 00007f8581064146
[  273.303097] RDX: 0000000000000000 RSI: 000000000000003c RDI: 0000000000000000
[  273.303097] RBP: 0000000000000000 R08: 00000000000000e7 R09: ffffffffffffff60
[  273.303098] R10: 0000000000000006 R11: 0000000000000246 R12: 00007f85811698a0
[  273.303098] R13: 0000000000000002 R14: 00007f85811722e8 R15: 0000000000000000
[  273.303100] ---[ end trace 7d981f8811b15c4a ]---
[  273.303159] ------------[ cut here ]------------
[  273.303163] WARNING: CPU: 4 PID: 3132 at /root/tempesta/fw/tls.c:296 tfw_tls_encrypt+0x534/0x850 [tempesta_fw]
[  273.303163] Modules linked in: tempesta_fw(OE) tempesta_db(OE) tempesta_tls(OE) tempesta_lib(OE) sha256_ssse3 sha512_ssse3 rfcomm bnep vsock_loopback vmw_vsock_virtio_transport_common vmw_vsock_vmci_transport vsock nls_iso8859_1 snd_ens1371 snd_ac97_codec intel_rapl_msr gameport intel_rapl_common btusb ac97_bus snd_pcm btrtl crct10dif_pclmul btbcm ghash_clmulni_intel snd_seq_midi btintel aesni_intel bluetooth snd_seq_midi_event crypto_simd cryptd snd_rawmidi glue_helper vmw_balloon snd_seq input_leds joydev ecdh_generic ecc snd_seq_device snd_timer snd serio_raw 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 ramoops pstore_blk efi_pstore pstore_zone reed_solomon ip_tables x_tables autofs4 hid_generic usbhid hid psmouse e1000 crc32_pclmul mptspi i2c_piix4 mptscsih mptbase ahci scsi_transport_spi libahci pata_acpi [last unloaded: tempesta_lib]
[  273.303184] CPU: 4 PID: 3132 Comm: wrk Tainted: G        W  OE     5.10.35+ #1
[  273.303185] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 11/12/2020
[  273.303188] RIP: 0010:tfw_tls_encrypt+0x534/0x850 [tempesta_fw]
[  273.303189] Code: 48 8b 47 60 a8 01 0f 84 15 02 00 00 4c 89 ef 41 be e0 ff ff ff e8 7c 77 1a e8 e9 47 ff ff ff 0f 0b 0f 0b 0f 0b e9 b2 fb ff ff <0f> 0b e9 c7 fb ff ff 31 d2 44 89 e6 4c 89 ef e8 18 ec 0d e8 4c 8b
[  273.303190] RSP: 0018:ffffb0ebc057cb38 EFLAGS: 00010202
[  273.303191] RAX: 00000000be1e89e9 RBX: 0000000000000002 RCX: 00000000be1e89e8
[  273.303191] RDX: 00000000be1e89e8 RSI: ffff9eddeaddc000 RDI: ffff9eddf61441e0
[  273.303192] RBP: ffffb0ebc057ce08 R08: 0000000000000000 R09: 00000000be1e89e8
[  273.303192] R10: 00000000000001c0 R11: 0000000000000000 R12: ffff9eddf765b900
[  273.303193] R13: ffff9eddf765b900 R14: 0000000000000002 R15: ffff9eddeaddc000
[  273.303194] FS:  0000000000000000(0000) GS:ffff9edeb5f00000(0000) knlGS:0000000000000000
[  273.303194] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  273.303195] CR2: 00007f8581187048 CR3: 0000000211c10005 CR4: 0000000000770ee0
[  273.303207] PKRU: 55555554
[  273.303207] Call Trace:
[  273.303208]  <IRQ>
[  273.303209]  ? ip_fragment.constprop.0+0x48/0x90
[  273.303210]  ? ip_finish_output+0x2d/0xb0
[  273.303211]  ? ip_output+0x7a/0x100
[  273.303212]  ? ip_local_out+0x3d/0x50
[  273.303213]  ? __ip_queue_xmit+0x182/0x470
[  273.303214]  ? ip_queue_xmit+0x15/0x20
[  273.303215]  ? __tcp_transmit_skb+0x5dc/0xc90
[  273.303216]  tcp_write_xmit+0x41d/0x1350
[  273.303217]  __tcp_push_pending_frames+0x37/0x100
[  273.303223]  ss_do_close+0x42e/0x5f0 [tempesta_fw]
[  273.303229]  ss_tx_action+0x417/0x5f0 [tempesta_fw]
[  273.303230]  ? process_backlog+0xdb/0x160
[  273.303231]  net_tx_action+0x9c/0x250
[  273.303232]  __do_softirq+0xd9/0x291
[  273.303233]  asm_call_irq_on_stack+0xf/0x20
[  273.303233]  </IRQ>
[  273.303234]  do_softirq_own_stack+0x3d/0x50
[  273.303235]  do_softirq.part.0+0x46/0x50
[  273.303236]  __local_bh_enable_ip+0x50/0x60
[  273.303237]  ip_finish_output2+0x1ab/0x590
[  273.303238]  ? __cgroup_bpf_run_filter_skb+0x3c3/0x3d0
[  273.303239]  __ip_finish_output+0xd8/0x220
[  273.303240]  ip_finish_output+0x2d/0xb0
[  273.303241]  ip_output+0x7a/0x100
[  273.303242]  ? __ip_finish_output+0xd8/0x220
[  273.303243]  ip_local_out+0x3d/0x50
[  273.303244]  __ip_queue_xmit+0x17a/0x470
[  273.303244]  ip_queue_xmit+0x15/0x20
[  273.303245]  __tcp_transmit_skb+0xa94/0xc90
[  273.303247]  tcp_write_xmit+0x453/0x1350
[  273.303248]  __tcp_push_pending_frames+0x37/0x100
[  273.303249]  tcp_send_fin+0x4e/0x190
[  273.303250]  tcp_close+0x33c/0x4e0
[  273.303250]  inet_release+0x4b/0x90
[  273.303251]  __sock_release+0x42/0xb0
[  273.303252]  sock_close+0x15/0x20
[  273.303253]  __fput+0xa9/0x260
[  273.303254]  ____fput+0xe/0x10
[  273.303255]  task_work_run+0x70/0xb0
[  273.303256]  do_exit+0x37b/0xaf0
[  273.303256]  ? vfs_write+0x218/0x280
[  273.303257]  do_group_exit+0x47/0xb0
[  273.303258]  __x64_sys_exit_group+0x18/0x20
[  273.303259]  do_syscall_64+0x38/0x90
[  273.303260]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  273.303261] RIP: 0033:0x7f8581064146
[  273.303261] Code: Unable to access opcode bytes at RIP 0x7f858106411c.
[  273.303262] RSP: 002b:00007ffdd9258a28 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
[  273.303262] RAX: ffffffffffffffda RBX: 00007f85811698a0 RCX: 00007f8581064146
[  273.303263] RDX: 0000000000000000 RSI: 000000000000003c RDI: 0000000000000000
[  273.303263] RBP: 0000000000000000 R08: 00000000000000e7 R09: ffffffffffffff60
[  273.303264] R10: 0000000000000006 R11: 0000000000000246 R12: 00007f85811698a0
[  273.303264] R13: 0000000000000002 R14: 00007f85811722e8 R15: 0000000000000000
[  273.303265] ---[ end trace 7d981f8811b15c4b ]---

s0nx · 2022-11-04T19:47:09Z

#1744

s0nx · 2022-12-21T17:37:03Z

I believe the initial problem, which was:
BUG tfw_stream_cache (Tainted: G B W O ): Objects remaining in tfw_stream_cache on __kmem_cache_shutdown()
has already been fixed by 7a00fdf05b3ae65ed5861ce46c44f2f1e300deb3.

Since we don't delete stream from sched->streams rbtree even when moving it to ctx->closed_streams list, and the fact that we don't call rb_erase() while traversing rbtree nodes anymore, there shouldn't be any leaked stream objects while dropping client connection.

s0nx · 2023-01-13T14:19:22Z

I've rechecked all the warnings on TFW master branch from 12 Jan 2021 using tempesta-test de0cbb8 and then ran the same tests on #1777.
I don't see any warnings/crashes mentioned in this issue.
I can't reproduce this one as well.

krizhanovsky · 2023-01-13T14:27:44Z

I can't reproduce this one as well.

Yeah, I believe this one was fixed in 71ebe12

vankoven added bug h2 labels Jan 10, 2020

vankoven added this to the 0.7 HTTP/2 milestone Jan 10, 2020

vankoven self-assigned this Jan 10, 2020

krizhanovsky assigned avbelov23 and unassigned vankoven Sep 14, 2020

krizhanovsky assigned i-rinat and unassigned avbelov23 Nov 18, 2020

krizhanovsky unassigned i-rinat Feb 19, 2021

krizhanovsky assigned avbelov23 Mar 5, 2021

krizhanovsky assigned i-rinat Jun 25, 2021

krizhanovsky unassigned i-rinat and avbelov23 Dec 11, 2021

krizhanovsky assigned Dmitry-Gouriev Dec 27, 2021

krizhanovsky added the crucial label Jan 12, 2022

krizhanovsky assigned byko3y Jan 13, 2022

krizhanovsky unassigned Dmitry-Gouriev Jan 13, 2022

krizhanovsky unassigned byko3y Jan 25, 2022

krizhanovsky assigned dmpetroff and unassigned dmpetroff Mar 3, 2022

krizhanovsky self-assigned this Mar 28, 2022

krizhanovsky added a commit that referenced this issue Jun 2, 2022

Merge pull request #1632 from tempesta-tech/ak-1377-empy-hdr-warn

38cfaf2

Fix minor warning for #1377

This was referenced Aug 16, 2022

test ALPN protocol priority order tempesta-tech/tempesta-test#283

Merged

HTTP/2 vs HTTPS handling #1643

Merged

krizhanovsky assigned s0nx and unassigned krizhanovsky Sep 16, 2022

b3b mentioned this issue Oct 4, 2022

Kernel crashes under concurrent connections tests #1703

Closed

s0nx linked a pull request Jan 9, 2023 that will close this issue

Fix various warnings reported in #1377 #1777

Merged

s0nx closed this as completed in #1777 Jan 13, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

TfwStream objects leaks if errors happen on serving h2 clients #1377

TfwStream objects leaks if errors happen on serving h2 clients #1377

vankoven commented Jan 10, 2020 •

edited by s0nx

Loading

krizhanovsky commented Mar 6, 2021 •

edited

Loading

Dmitry-Gouriev commented Dec 27, 2021 •

edited by krizhanovsky

Loading

Dmitry-Gouriev commented Dec 27, 2021 •

edited by s0nx

Loading

Dmitry-Gouriev commented Jan 12, 2022 •

edited

Loading

Dmitry-Gouriev commented Jan 12, 2022 •

edited by krizhanovsky

Loading

krizhanovsky commented Jan 12, 2022

Dmitry-Gouriev commented Jan 13, 2022 •

edited

Loading

Dmitry-Gouriev commented Jan 13, 2022 •

edited

Loading

Dmitry-Gouriev commented Jan 13, 2022 •

edited by krizhanovsky

Loading

Dmitry-Gouriev commented Jan 13, 2022

krizhanovsky commented Apr 9, 2022 •

edited

Loading

krizhanovsky commented Jul 14, 2022 •

edited by s0nx

Loading

krizhanovsky commented Jul 20, 2022 •

edited by s0nx

Loading

const-t commented Aug 10, 2022 •

edited by s0nx

Loading

krizhanovsky commented Aug 11, 2022 •

edited

Loading

RomanBelozerov commented Oct 5, 2022 •

edited

Loading

s0nx commented Nov 4, 2022

s0nx commented Dec 21, 2022

s0nx commented Jan 13, 2023

krizhanovsky commented Jan 13, 2023

TfwStream objects leaks if errors happen on serving h2 clients #1377

TfwStream objects leaks if errors happen on serving h2 clients #1377

Comments

vankoven commented Jan 10, 2020 • edited by s0nx Loading

Scope

Testing

krizhanovsky commented Mar 6, 2021 • edited Loading

Dmitry-Gouriev commented Dec 27, 2021 • edited by krizhanovsky Loading

Dmitry-Gouriev commented Dec 27, 2021 • edited by s0nx Loading

Also a case (reproducible)

How to reproduce

Events in the trace

Dmitry-Gouriev commented Jan 12, 2022 • edited Loading

Some analytics on the way

Dmitry-Gouriev commented Jan 12, 2022 • edited by krizhanovsky Loading

Another analytics on the way

krizhanovsky commented Jan 12, 2022

Dmitry-Gouriev commented Jan 13, 2022 • edited Loading

Dmitry-Gouriev commented Jan 13, 2022 • edited Loading

Dmitry-Gouriev commented Jan 13, 2022 • edited by krizhanovsky Loading

Dmitry-Gouriev commented Jan 13, 2022

krizhanovsky commented Apr 9, 2022 • edited Loading

krizhanovsky commented Jul 14, 2022 • edited by s0nx Loading

krizhanovsky commented Jul 20, 2022 • edited by s0nx Loading

const-t commented Aug 10, 2022 • edited by s0nx Loading

krizhanovsky commented Aug 11, 2022 • edited Loading

RomanBelozerov commented Oct 5, 2022 • edited Loading

s0nx commented Nov 4, 2022

s0nx commented Dec 21, 2022

s0nx commented Jan 13, 2023

krizhanovsky commented Jan 13, 2023

vankoven commented Jan 10, 2020 •

edited by s0nx

Loading

krizhanovsky commented Mar 6, 2021 •

edited

Loading

Dmitry-Gouriev commented Dec 27, 2021 •

edited by krizhanovsky

Loading

Dmitry-Gouriev commented Dec 27, 2021 •

edited by s0nx

Loading

Dmitry-Gouriev commented Jan 12, 2022 •

edited

Loading

Dmitry-Gouriev commented Jan 12, 2022 •

edited by krizhanovsky

Loading

Dmitry-Gouriev commented Jan 13, 2022 •

edited

Loading

Dmitry-Gouriev commented Jan 13, 2022 •

edited

Loading

Dmitry-Gouriev commented Jan 13, 2022 •

edited by krizhanovsky

Loading

krizhanovsky commented Apr 9, 2022 •

edited

Loading

krizhanovsky commented Jul 14, 2022 •

edited by s0nx

Loading

krizhanovsky commented Jul 20, 2022 •

edited by s0nx

Loading

const-t commented Aug 10, 2022 •

edited by s0nx

Loading

krizhanovsky commented Aug 11, 2022 •

edited

Loading

RomanBelozerov commented Oct 5, 2022 •

edited

Loading