Warning during transform HTTP/1.1 response into HTTP/2

[const-t]

Scope

There is warning on executing http2_general.test_h2_headers test suite, it appears not on every run.
[ 6195.924928] [tempesta fw] Warning: Unable to transform HTTP/1.1 data into HTTP/2 format: free space exhausted (accumulated length: 136

Testing

Just run http2_general.test_h2_headers test suite many times.

[krizhanovsky]

Related issue for testing tempesta-tech/tempesta-test#261

[const-t]

Tempesta prints [tempesta fw] Warning: Unable to transform HTTP/1.1 data into HTTP/2 format: free space exhausted (accumulated length: 99 when receive certain response from server and forwards it to http2 client. Example of such responses:

'HTTP/1.1 200 OK\r\n'
'Content-Length: 1\r\n\r\n'
'1'

'HTTP/1.1 200 OK\r\n'
'Server: qwertyuiop-qwertyuiop-qwertyuiop\r\n'
'Content-Length: 1\r\n\r\n'
'1'

However, this response will be processed correctly:

'HTTP/1.1 200 OK\r\n'
'Server: test\r\n'
'Date: test\r\n'
'Content-Length: 1\r\n\r\n'
'1'

Testing

Need to develop functional test which will contain responses from current issue.

[RomanBelozerov]

I receive 500 (expected 200) response and dmesg warning for for h2 request with 100 DATA frames and HTTP/1.1 200 OK\r\nContent-Length: 0\r\n\r\n backend response.

Test to reproduce.

DMESG

[ 3825.247602] [tempesta fw] Warning: Unable to transform HTTP/1.1 data into HTTP/2 format: free space exhausted (accumulated length: 78
[ 3825.250485] ------------[ cut here ]------------
[ 3825.251252] WARNING: CPU: 0 PID: 44171 at /root/tempesta/fw/ss_skb.c:1738 ss_skb_cut_extra_data+0x1b3/0x220 [tempesta_fw]
[ 3825.253477] Modules linked in: tempesta_fw(OE) tempesta_db(OE) tempesta_tls(OE) tempesta_lib(OE) sha256_ssse3(E) sha512_ssse3(E) sha512_generic(E) uinput(E) xt_conntrack(E) nft_chain_nat(E) xt_MASQUERADE(E) nf_nat(E) nf_conntrack_netlink(E) nf_conntrack(E) nf_defrag_ipv6(E) nf_defrag_ipv4(E) xfrm_user(E) xfrm_algo(E) nft_counter(E) xt_addrtype(E) nft_compat(E) nf_tables(E) libcrc32c(E) nfnetlink(E) br_netfilter(E) bridge(E) stp(E) llc(E) rfcomm(E) bnep(E) btusb(E) btrtl(E) btbcm(E) btintel(E) overlay(E) bluetooth(E) jitterentropy_rng(E) intel_rapl_msr(E) drbg(E) intel_rapl_common(E) intel_pmc_core(E) ghash_clmulni_intel(E) aes_generic(E) aesni_intel(E) crypto_simd(E) cryptd(E) glue_helper(E) snd_ens1371(E) ansi_cprng(E) snd_ac97_codec(E) ac97_bus(E) gameport(E) snd_rawmidi(E) ecdh_generic(E) snd_seq_device(E) vmw_balloon(E) rfkill(E) snd_pcm(E) ecc(E) joydev(E) libaes(E) snd_timer(E) snd(E) serio_raw(E) pcspkr(E) soundcore(E) sg(E) vsock_loopback(E) vmw_vsock_virtio_transport_common(E)
[ 3825.253519]  evdev(E) ac(E) vmw_vsock_vmci_transport(E) vsock(E) vmw_vmci(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) sd_mod(E) t10_pi(E) crc_t10dif(E) crct10dif_generic(E) hid_generic(E) usbhid(E) hid(E) sr_mod(E) cdrom(E) ata_generic(E) crct10dif_pclmul(E) crct10dif_common(E) ata_piix(E) vmwgfx(E) uhci_hcd(E) ttm(E) ehci_pci(E) crc32_pclmul(E) ehci_hcd(E) drm_kms_helper(E) mptspi(E) cec(E) crc32c_intel(E) psmouse(E) mptscsih(E) mptbase(E) scsi_transport_spi(E) libata(E) usbcore(E) e1000(E) drm(E) scsi_mod(E) i2c_piix4(E) button(E) [last unloaded: tempesta_lib]
[ 3825.277745] CPU: 0 PID: 44171 Comm: python3 Tainted: G           OE     5.10.35+ #1
[ 3825.278995] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 11/12/2020
[ 3825.280771] RIP: 0010:ss_skb_cut_extra_data+0x1b3/0x220 [tempesta_fw]
[ 3825.281962] Code: 31 e4 45 85 d2 0f 89 3d ff ff ff 44 89 c1 4c 8d 4c 24 04 4c 8d 44 24 08 48 89 ee f7 d9 4c 89 ef e8 c2 da ff ff e9 3b ff ff ff <0f> 0b b8 ea ff ff ff 48 8b 5c 24 28 65 48 2b 1c 25 28 00 00 00 75
[ 3825.285022] RSP: 0018:ffffa50100003a48 EFLAGS: 00010293
[ 3825.285963] RAX: 0000000000000013 RBX: ffff9562f0cf8fdd RCX: 0000000032340fcd
[ 3825.287222] RDX: ffff9562f0cf8fcd RSI: ffff9562be9b8000 RDI: 0000000000000013
[ 3825.288378] RBP: ffff95620ecc0a00 R08: ffff9562f0cf8fdd R09: 0000000000000001
[ 3825.289555] R10: 0000000000000001 R11: dead0000000000ff R12: 0000000000000000
[ 3825.290779] R13: ffff95620ecc0a00 R14: 0000000000000063 R15: ffff9562be9b7020
[ 3825.291978] FS:  00007fbc06956700(0000) GS:ffff9562f5e00000(0000) knlGS:0000000000000000
[ 3825.293379] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 3825.294418] CR2: 00007fbc0a99db30 CR3: 0000000230e0c002 CR4: 0000000000370ef0
[ 3825.295575] Call Trace:
[ 3825.296019]  
[ 3825.296407]  tfw_h2_make_frames+0x20f/0x4d0 [tempesta_fw]
[ 3825.297442]  ? tfw_h2_msg_hdr_add+0x97/0xc0 [tempesta_fw]
[ 3825.298485]  tfw_h2_resp_adjust_fwd+0x407/0x500 [tempesta_fw]
[ 3825.299560]  ? tfw_h2_resp_adjust_fwd+0x500/0x500 [tempesta_fw]
[ 3825.300609]  ? tfw_h2_resp_adjust_fwd+0x500/0x500 [tempesta_fw]
[ 3825.301796]  tfw_cache_process+0x146/0x290 [tempesta_fw]
[ 3825.302838]  ? tfw_gfsm_move+0x1a5/0x210 [tempesta_fw]
[ 3825.303860]  tfw_http_resp_cache+0xfb/0x1b0 [tempesta_fw]
[ 3825.305149]  tfw_http_msg_process_generic+0x4cb/0x5f0 [tempesta_fw]
[ 3825.306630]  ? __coalesce_frag+0x99/0x150 [tempesta_fw]
[ 3825.307762]  ? ss_skb_queue_coalesce_tail+0xf5/0x130 [tempesta_fw]
[ 3825.309076]  tfw_connection_recv+0x53/0x90 [tempesta_fw]
[ 3825.310342]  ss_tcp_process_data+0x1f1/0x400 [tempesta_fw]
[ 3825.311449]  ss_tcp_data_ready+0x3f/0xa0 [tempesta_fw]
[ 3825.312491]  tcp_rcv_established+0x5d8/0x680
[ 3825.313533]  tcp_v4_do_rcv+0x131/0x1f0
[ 3825.314399]  tcp_v4_rcv+0xc2f/0xd80
[ 3825.315021]  ip_protocol_deliver_rcu+0x2b/0x1b0
[ 3825.315932]  ip_local_deliver_finish+0x44/0x50
[ 3825.316966]  __netif_receive_skb_one_core+0x87/0xa0
[ 3825.318058]  process_backlog+0x96/0x160
[ 3825.318760]  net_rx_action+0x145/0x3e0
[ 3825.319592]  __do_softirq+0xcf/0x284
[ 3825.320285]  asm_call_irq_on_stack+0x12/0x20
[ 3825.322040]  
[ 3825.322528]  do_softirq_own_stack+0x37/0x40
[ 3825.323334]  do_softirq+0x5e/0x70
[ 3825.324171]  __local_bh_enable_ip+0x4b/0x50
[ 3825.325042]  ip_finish_output2+0x1ab/0x590
[ 3825.326114]  __ip_queue_xmit+0x180/0x410
[ 3825.326960]  __tcp_transmit_skb+0xa0e/0xbc0
[ 3825.327706]  tcp_write_xmit+0x41b/0x1240
[ 3825.328566]  __tcp_push_pending_frames+0x32/0xf0
[ 3825.329548]  tcp_sendmsg_locked+0xa32/0xb50
[ 3825.330369]  tcp_sendmsg+0x28/0x40
[ 3825.331033]  sock_sendmsg+0x57/0x60
[ 3825.331793]  __sys_sendto+0xee/0x150
[ 3825.332403]  ? do_user_addr_fault+0x1cf/0x3f0
[ 3825.333320]  ? switch_fpu_return+0x40/0xb0
[ 3825.334320]  __x64_sys_sendto+0x25/0x30
[ 3825.335004]  do_syscall_64+0x33/0x80
[ 3825.335781]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 3825.336870] RIP: 0033:0x7fbc0b381494
[ 3825.337602] Code: 89 4c 24 1c e8 8d f8 ff ff 44 8b 54 24 1c 8b 3c 24 45 31 c9 89 c5 48 8b 54 24 10 48 8b 74 24 08 45 31 c0 b8 2c 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 34 89 ef 48 89 04 24 e8 b9 f8 ff ff 48 8b 04
[ 3825.341382] RSP: 002b:00007fbc06954e30 EFLAGS: 00000246 ORIG_RAX: 000000000000002c
[ 3825.342898] RAX: ffffffffffffffda RBX: 00007fbc06954f10 RCX: 00007fbc0b381494
[ 3825.344224] RDX: 0000000000000026 RSI: 00007fbc06973fa0 RDI: 0000000000000024
[ 3825.345575] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[ 3825.347092] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
[ 3825.348423] R13: 0000000000000000 R14: 00007fbc06954f10 R15: 0000000000000001
[ 3825.349997] ---[ end trace d8bd37bcf00ffcbb ]---
[ 3825.350983] [tempesta fw] Warning: response dropped: processing error, status 500: 127.0.0.1