Hi Andreas,
On Mon, Nov 11, 2024 at 08:49:16AM +0000, Andreas Bergander wrote:
> After enabling h2 between haproxy and our backend servers we sometimes notice
> that haproxy sends an RST_STREAM immediately after the HEADERS packet with
> the GET request. I've logged the packages and in this case less than 3 ms
> after haproxy sends GET, haproxy then sends an RST_STREAM.
>
> Time (seconds) source destination Protocol Packet
> 69.632322 haproxy -> backend HTTP2 HEADERS[25]: GET /image.svg
> 69.635099 haproxy -> backend HTTP2 RST_STREAM[25]
>
> What could be the cause of that? The stream gets closed before the backend
> can write the response. First I suspected this was due to e.g. end user
> closing their browser or similar. But it occurs a bit too often for that and
> we have also got reports of missing images from end users. We are using
> haproxy 3.0.5. Any ideas what I can look into or is this normal?
That's interesting. We're currently chasing an issue that a few users
observe, by which some H1 requests on the backend are sometimes immediately
aborted with a FIN and for now we don't know what causes this (and we've
searched a lot). What you're observing here could very likely be the H2
variant of the same issue.
> I can also see a bunch of WINDOW_UPDATE packages sent very frequently by
> haproxy, maybe that is expected and unrelated?
>
> 8.915556 haproxy -> backend HTTP2 WINDOW_UPDATE[127], WINDOW_UPDATE[0]
> 8.915594 haproxy -> backend HTTP2 WINDOW_UPDATE[127], WINDOW_UPDATE[0]
> 8.916445 haproxy -> backend HTTP2 WINDOW_UPDATE[127], WINDOW_UPDATE[0]
> 8.916487 haproxy -> backend HTTP2 WINDOW_UPDATE[127], WINDOW_UPDATE[0]
> 8.917168 haproxy -> backend HTTP2 WINDOW_UPDATE[127], WINDOW_UPDATE[0]
> 8.917220 haproxy -> backend HTTP2 WINDOW_UPDATE[127], WINDOW_UPDATE[0]
> 8.918075 haproxy -> backend HTTP2 WINDOW_UPDATE[127], WINDOW_UPDATE[0]
These ones can be perfectly normal and are quite common on the backend
side. WINDOW_UPDATE frames allow to refill the sender's budget to send
more DATA frames. So as data get delivered to haproxy, it had to send
the equivalent amount of refill. HAProxy keeps count of the received
data per frame and connection to send a single aggregate WINDOW_UPDATE
frame for each of them, once per processed buffer (a buffer is 16kB by
default). If the sender is sending large amounts of data in 16kB frames,
in the worst case you could see two WU frames per DATA frame (one for the
connection and one for the stream). But these frames are very small (13
bytes) so that's not a problem.
> This is the config we use for the backend:
>
> backend bk_appsrv
> mode http
> balance roundrobin
> option httpchk
> http-check connect proto h2
> http-check send meth GET uri /status ver HTTP/2
> http-check expect rstatus 200
> cookie shtick insert indirect nocache secure
> server server1 server1:80 cookie appbfy1 check maxconn 512 proto h2
> server server2 server2:80 cookie appbfy2 check maxconn 512 proto h2
Thanks for sharing this. Do you have anything specific in the frontend,
such as maybe "option abortonclose", or such stuff ? And what are your
timeouts ? We're still trying to figure what conditoins could provoke
this, and were going towards socket errors for H1 but your report could
change a part of the analysis.
If you don't have too much traffic, it could be useful to enable H2 traces
to a ring buffer, combined with network captures so that the comparison
between what the H2 mux sees and what the network sees helps eliminate
some possibilities.
Traces can be enabled in the config by adding first a "ring" section
and second another "global" section with traces in it. Note that "trace"
is marked experimental in 3.0 since it's ugly to declare it in the global
section, and was simplified in 3.1 with a new dedicated "traces" section.
global
...
ring buf1
size 1073741824 # 1 GB
format timed
backing-file /tmp/h2-trace.bin
global
expose-experimental-directives
trace h2 sink buf1
trace h2 level developer
trace h2 verbosity complete
trace h2 start now
Note that each request will produce around 1kB of traces on average, so
the volume can be high. The file is a circular ring buffer which
automatically loops back and keeps 1GB of contiguous traces. You can
increase the size if needed. Also please be aware that each reload of
haproxy will rotate the trace, replacing the file with the same name
suffixed by ".bak". This way once you capture the problem on the network
you can simply reload, and the old trace (.bak) will contain the event
and can safely be moved somewhere else (a second reload will destroy it).
You can use dev/haring/haring on the file to read its contents. It will
emit them in text format, in chronological order. This allows to spot
the relevant request based on timing and URL. We can help you with this,
but keep in mind that some decoded requests will appear and may disclose
some private information (IPs are not present though, unless they appear
in x-forwarded-for for example).
Regards,
Willy
