"Server closed connection.." error may be due to HTTP/2 parser problem

[ant5]

I have quite many "Server closed connection.." errors in logs and one of them I pinned and explored.
Entry in log:

Server closed connection while reading response header. (origin deepwiki.com/squid-cache/squid)

Corresponding diagnostics:

[Jun 25 19:03:15.153] [TS_MAIN] NOTE: <traffic_server.cc:2439 (main)> traffic server running
[Jun 25 19:03:15.185] [ET_NET 3] NOTE: <StripeSM.cc:558 (handle_recover_from_data)> recovery clearing offsets of Stripe /usr/local/var/trafficserver/cache.db 16384:32766 : [249151488, 257540096] sync_serial 2977 next 2978
[Jun 25 19:03:15.189] [ET_NET 2] NOTE: <CacheHosting.cc:250 (BuildTableFromString)> hosting.config loading ...
[Jun 25 19:03:15.189] [ET_NET 2] NOTE: <CacheHosting.cc:331 (BuildTableFromString)> hosting.config finished loading
[Jun 25 19:03:15.190] [ET_NET 2] NOTE: <CacheProcessor.cc:1617 (cacheInitialized)> cache enabled
[Jun 25 19:03:15.190] [ET_NET 2] NOTE: <traffic_server.cc:570 (emit_fully_initialized_message)> Traffic Server is fully initialized.
[Jun 25 19:03:19.459] [ET_NET 2] ERROR: <Http2ConnectionState.cc:1498 (rcv_frame)> HTTP/2 stream error code=0x01 client_ip=76.76.21.21 session_id=195931873744250880 stream_id=3 recv headers malformed request
[Jun 25 19:03:19.525] [ET_NET 2] ERROR: <Http2ConnectionState.cc:1498 (rcv_frame)> HTTP/2 stream error code=0x01 client_ip=76.76.21.21 session_id=195931873744250880 stream_id=5 recv headers malformed request
[Jun 25 19:03:19.584] [ET_NET 2] ERROR: <Http2ConnectionState.cc:1498 (rcv_frame)> HTTP/2 stream error code=0x01 client_ip=76.76.21.21 session_id=195931873744250880 stream_id=7 recv headers malformed request
[Jun 25 19:03:19.674] [ET_NET 2] ERROR: <Http2ConnectionState.cc:1498 (rcv_frame)> HTTP/2 stream error code=0x01 client_ip=76.76.21.21 session_id=195931873744250880 stream_id=9 recv headers malformed request

Packet dumps:

No.	Time	Source	Destination	Protocol	Length	Info
1	0.000000	89.125.138.120	76.76.21.21	TCP	74	41008 → 443 [SYN] Seq=0 Win=65535 Len=0 MSS=1460 WS=64 SACK_PERM TSval=205403789 TSecr=0
2	0.001531	76.76.21.21	89.125.138.120	TCP	66	443 → 41008 [SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=1460 WS=128 SACK_PERM
3	0.001562	89.125.138.120	76.76.21.21	TCP	54	41008 → 443 [ACK] Seq=1 Ack=1 Win=65728 Len=0
4	0.001923	89.125.138.120	76.76.21.21	TLSv1.3	583	Client Hello (SNI=deepwiki.com)
5	0.003226	76.76.21.21	89.125.138.120	TCP	54	443 → 41008 [ACK] Seq=1 Ack=530 Win=66688 Len=0
6	0.008569	76.76.21.21	89.125.138.120	TLSv1.3	432	Server Hello, Change Cipher Spec, Application Data, Application Data, Application Data
7	0.009014	89.125.138.120	76.76.21.21	TLSv1.3	118	Change Cipher Spec, Application Data
8	0.010189	89.125.138.120	76.76.21.21	TLSv1.3	440	Application Data
9	0.011497	76.76.21.21	89.125.138.120	TCP	54	443 → 41008 [ACK] Seq=379 Ack=980 Win=67712 Len=0
10	0.012561	76.76.21.21	89.125.138.120	TLSv1.3	115	Application Data
...
No.	Time	Source	Destination	Protocol	Length	Info
353	0.261363	76.76.21.21	89.125.138.120	TCP	1514	443 → 41008 [ACK] Seq=259014 Ack=1707 Win=67712 Len=1460 [TCP PDU reassembled in 357]
354	0.261450	76.76.21.21	89.125.138.120	TCP	1514	443 → 41008 [ACK] Seq=260474 Ack=1707 Win=67712 Len=1460 [TCP PDU reassembled in 357]
355	0.261461	89.125.138.120	76.76.21.21	TCP	54	41008 → 443 [ACK] Seq=1847 Ack=261934 Win=220288 Len=0
356	0.261466	76.76.21.21	89.125.138.120	TCP	1514	443 → 41008 [ACK] Seq=261934 Ack=1707 Win=67712 Len=1460 [TCP PDU reassembled in 357]
357	0.261469	76.76.21.21	89.125.138.120	TLSv1.3	1001	Application Data, Application Data
358	0.261480	89.125.138.120	76.76.21.21	TCP	54	41008 → 443 [ACK] Seq=1847 Ack=264341 Win=217920 Len=0
359	0.261570	89.125.138.120	76.76.21.21	TLSv1.3	89	Application Data
360	0.262203	76.76.21.21	89.125.138.120	TCP	54	443 → 41008 [ACK] Seq=264341 Ack=1742 Win=67712 Len=0
361	0.262553	76.76.21.21	89.125.138.120	TCP	54	443 → 41008 [ACK] Seq=264341 Ack=1777 Win=67712 Len=0
362	0.262710	76.76.21.21	89.125.138.120	TCP	54	443 → 41008 [ACK] Seq=264341 Ack=1812 Win=67712 Len=0
363	0.262863	76.76.21.21	89.125.138.120	TCP	54	443 → 41008 [ACK] Seq=264341 Ack=1847 Win=67712 Len=0
364	0.263265	76.76.21.21	89.125.138.120	TCP	54	443 → 41008 [ACK] Seq=264341 Ack=1882 Win=67712 Len=0

Note that TCP session ended nothing. No FIN, RST etc.

I understand that the most interesting thing is the data itself but I don't now how to extract it from TLS stream.
deepwiki.com site seems to be stable producer of this error via ATS interaction. Meanwhile it opened well in a browsers but does browser use HTTP/2 or HTTP/1.1 I can't figure out.

P.S. ATS 10.2.x, FreeBSD 14-STABLE

[bryancall]

Thanks, the detailed capture made this reproducible. I tracked it down: the origin (deepwiki, on Vercel) is sending a 103 Early Hints interim response before the final 200 on the HTTP/2 connection from ATS to the origin. Apache Traffic Server's origin-side HTTP/2 code currently does not handle 1xx interim responses correctly. It merges the interim headers and the final response headers together, which produces a duplicate :status pseudo-header and trips the HTTP/2 header validation. ATS then resets the stream and reports it as "Server closed connection while reading response header," even though the origin never closed the connection (your packet capture confirms that, no FIN or RST).

One detail worth noting: the 103 Early Hints only appears when the request carries the usual browser navigation headers (the sec-fetch-* set, accept-encoding including zstd, and so on). A plain request does not trigger it, which is why it shows up from a real browser through the proxy but not from simple command-line tools.

Workaround until this is fixed: remove h2 from proxy.config.ssl.client.alpn_protocols (leaving http/1.1). ATS will then speak HTTP/1.1 to the origin, where this does not occur. I confirmed that makes the same request succeed.

I have a fix for the HTTP/2 origin path and I am preparing a pull request with a test. I will link it here.