Bug in response cache processing in specific case

[ttaym]

Scope

Bug reproducible from at least abc9c219ea9409ac75e6ec4a7246240a7f7eb07a (old enough master).

Kernel log:

Mar 24 16:33:02 172.16.0.2 [ 5337.594338] ------------[ cut here ]------------ Mar 24 16:33:02 172.16.0.2 [ 5337.595120] WARNING: CPU: 3 PID: 18825 at /root/tempesta/fw/http.c:3950 tfw_http_hdr_split+0x1be/0x1f0 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.595895] Modules linked in: tempesta_fw(OE) tempesta_db(OE) tempesta_tls(OE) tempesta_lib(OE) sha256_ssse3(E) sha512_ssse3(E) sha512_generic(E) overlay(E) intel_rapl_msr(E) intel _rapl_common(E) nfit(E) libnvdimm(E) ghash_clmulni_intel(E) aesni_intel(E) libaes(E) crypto_simd(E) cryptd(E) glue_helper(E) rapl(E) snd_pcm(E) snd_timer(E) serio_raw(E) sg(E) hv_utils(E) hyperv_keyboard(E) ptp( E) snd(E) hyperv_fb(E) pps_core(E) hv_balloon(E) soundcore(E) evdev(E) pcspkr(E) button(E) joydev(E) netconsole(E) fuse(E) drm(E) configfs(E) ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc32c_generic(E) crc16(E ) mbcache(E) jbd2(E) ata_generic(E) sd_mod(E) hid_generic(E) t10_pi(E) crc_t10dif(E) crct10dif_generic(E) hid_hyperv(E) hv_storvsc(E) hv_netvsc(E) hid(E) scsi_transport_fc(E) crct10dif_pclmul(E) crct10dif_common (E) ata_piix(E) crc32_pclmul(E) crc32c_intel(E) libata(E) psmouse(E) floppy(E) i2c_piix4(E) scsi_mod(E) hv_vmbus(E) [last unloaded: tempesta_lib] Mar 24 16:33:02 172.16.0.2 [ 5337.603437] CPU: 3 PID: 18825 Comm: websocat Tainted: G W OE 5.10.35+ #1 Mar 24 16:33:02 172.16.0.2 [ 5337.604423] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS 090006 04/28/2016 Mar 24 16:33:02 172.16.0.2 [ 5337.605583] RIP: 0010:tfw_http_hdr_split+0x1be/0x1f0 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.606608] Code: 29 c0 48 89 42 10 48 8b 47 10 4c 29 c0 49 89 c0 4c 89 c0 c3 0f 0b 45 89 da 48 83 f8 01 0f 84 e7 fe ff ff 0f 0b e9 e0 fe ff ff <0f> 0b e9 74 ff ff ff 48 03 6f 10 44 89 d3 e9 cd fe ff ff 0f 0b 0f Mar 24 16:33:02 172.16.0.2 [ 5337.608914] RSP: 0018:ffffa8c1c0308ad0 EFLAGS: 00010246 Mar 24 16:33:02 172.16.0.2 [ 5337.609920] RAX: 0000000000000000 RBX: ffff90229f330020 RCX: 0000000000000001 Mar 24 16:33:02 172.16.0.2 [ 5337.611136] RDX: ffffa8c1c0308b50 RSI: ffffa8c1c0308b30 RDI: ffff90229f3303d0 Mar 24 16:33:02 172.16.0.2 [ 5337.612215] RBP: ffffa8c1c0308ba0 R08: 0000000000000000 R09: 0000000000000001 Mar 24 16:33:02 172.16.0.2 [ 5337.613218] R10: 0000000000000001 R11: 0000000000000001 R12: dc75a478ee087c60 Mar 24 16:33:02 172.16.0.2 [ 5337.614185] R13: ffffa8c1c0308b30 R14: ffff90229f3303d0 R15: 0000000000000015 Mar 24 16:33:02 172.16.0.2 [ 5337.615367] FS: 00007f04c31b42d0(0000) GS:ffff9022feec0000(0000) knlGS:0000000000000000 Mar 24 16:33:02 172.16.0.2 [ 5337.616381] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Mar 24 16:33:02 172.16.0.2 [ 5337.617378] CR2: 00007f04c3320ee4 CR3: 000000015f9da003 CR4: 00000000003706e0 Mar 24 16:33:02 172.16.0.2 [ 5337.619647] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Mar 24 16:33:02 172.16.0.2 [ 5337.620625] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 Mar 24 16:33:02 172.16.0.2 [ 5337.622388] Call Trace: Mar 24 16:33:02 172.16.0.2 [ 5337.623421] <IRQ> Mar 24 16:33:02 172.16.0.2 [ 5337.624383] ? __cache_entry_size+0x279/0x530 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.625337] ? loopback_xmit+0x98/0xe0 Mar 24 16:33:02 172.16.0.2 [ 5337.626743] __cache_add_node+0x3b/0xf0 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.627709] tfw_cache_do_action+0x4f1/0x1040 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.628864] ? __new_pgfrag+0x1ee/0x3c0 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.630272] ? tfw_h2_resp_add_loc_hdrs+0x90/0x90 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.631250] ? __str_grow_tree+0x75/0x140 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.632235] ? tfw_hash_str_len+0xb9/0x170 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.633170] tfw_cache_process+0xb7/0x290 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.634099] ? tfw_cache_process+0xb7/0x290 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.635050] ? tfw_gfsm_move+0x137/0x180 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.636043] ? tfw_http_resp_cache+0xf1/0x1a0 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.636985] ? tfw_http_conn_drop+0xda/0x2c0 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.637826] ? tfw_connection_drop+0x25/0x40 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.638746] ? tfw_sock_srv_connect_drop+0x11e/0x170 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.639660] ? ss_tx_action+0x454/0x650 [tempesta_fw] Mar 24 16:33:02 172.16.0.2 [ 5337.640643] ? process_backlog+0x126/0x160 Mar 24 16:33:02 172.16.0.2 [ 5337.641495] ? net_tx_action+0x94/0x240 Mar 24 16:33:02 172.16.0.2 [ 5337.642333] ? __do_softirq+0xcf/0x284 Mar 24 16:33:02 172.16.0.2 [ 5337.643228] ? asm_call_irq_on_stack+0xf/0x20 Mar 24 16:33:02 172.16.0.2 [ 5337.644076] </IRQ> Mar 24 16:33:02 172.16.0.2 [ 5337.644885] ? do_softirq_own_stack+0x37/0x40 Mar 24 16:33:02 172.16.0.2 [ 5337.645637] ? do_softirq+0x5e/0x70 Mar 24 16:33:02 172.16.0.2 [ 5337.646471] ? __local_bh_enable_ip+0x4b/0x50 Mar 24 16:33:02 172.16.0.2 [ 5337.647217] ? ip_finish_output2+0x1ab/0x590 Mar 24 16:33:02 172.16.0.2 [ 5337.648005] ? __ip_queue_xmit+0x180/0x410 Mar 24 16:33:02 172.16.0.2 [ 5337.648673] ? __tcp_transmit_skb+0xa0e/0xbc0 Mar 24 16:33:02 172.16.0.2 [ 5337.650559] ? __tcp_push_pending_frames+0x32/0xf0 Mar 24 16:33:02 172.16.0.2 [ 5337.651299] ? tcp_close+0x320/0x4a0 Mar 24 16:33:02 172.16.0.2 [ 5337.651995] ? inet_release+0x42/0x80 Mar 24 16:33:02 172.16.0.2 [ 5337.652569] ? __sock_release+0x3d/0xa0 Mar 24 16:33:02 172.16.0.2 [ 5337.653160] ? sock_close+0x11/0x20 Mar 24 16:33:02 172.16.0.2 [ 5337.653734] ? __fput+0x95/0x240 Mar 24 16:33:02 172.16.0.2 [ 5337.654282] ? task_work_run+0x65/0xa0 Mar 24 16:33:02 172.16.0.2 [ 5337.654789] ? exit_to_user_mode_prepare+0x111/0x120 Mar 24 16:33:02 172.16.0.2 [ 5337.655344] ? syscall_exit_to_user_mode+0x28/0x140 Mar 24 16:33:02 172.16.0.2 [ 5337.655895] ? entry_SYSCALL_64_after_hwframe+0x44/0xa9 Mar 24 16:33:02 172.16.0.2 [ 5337.656409] ---[ end trace 2f37d075c8341f4c ]---

Tempesta config:

listen 443 proto=https;
listen 45.151.145.147:80;

srv_group default {
    server 127.0.0.1:8000 conns_n=1;
}

vhost debian {
    proxy_pass default;
    tls_certificate     /root/cert.pem;
    tls_certificate_key /root/privkey.pem;
}

cache 1;
cache_fulfill * *;

block_action attack reply;

http_chain {
    -> debian;
}

Request made:

curl -vk -X GET -H "Upgrade: websocket" -H "Connection: upgrade" -H --resolve 45.151.145.147:80:debian http://debian
* Connected to ru.ayum.ru (45.151.145.147) port 80 (#0)
> GET / HTTP/1.1
> Host: debian
> User-Agent: curl/7.74.0
> Accept: */*
> Upgrade: websocket
> Connection: upgrade
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 404 Not Found
< Content-Type: text/plain
< Connection: close
< Transfer-Encoding: chunked
< via: 1.1 tempesta_fw (Tempesta FW pre-0.7.0)
< date: Thu, 24 Mar 2022 13:33:02 GMT
< Server: Tempesta FW/pre-0.7.0
< 

On backend:

websocat -s 127.0.0.1:8000

Backend replies with 404 on the request and Tempesta FW immediately fails with log above.

[s0nx]

Reproduced with websocat 1.10.0 (708b8d57761d48c50a0a1072aea53257ff405c1d).

Tempesta config is the same as described. On backend:

1. Create dummy index.html anywhere.
2. ./websocat -s 127.0.0.1:8000 -v -F /index.html:text/html:index.html

Client: curl -vk -H "Connection: upgrade" -H "Upgrade: websocket" -H "Sec-WebSocket-Version: 11" -H "Sec-WebSocket-Key: LtPu+6OnJjgLCkfEDPvXwA==" http://<hostname>