Hey Christopher,
thanks a lot for the config snipped.
"Luckily" the issue appeared again, shortly after applied the config.
So here is the output of the ring file:
<0>2023-11-25T14:41:41.050846+00:00 [01|h1|0|mux_h1.c:4377] reporting error to
the app-layer stream : [F,RUN] [MSG_DONE, MSG_DONE] - req=(.fl=0x00001550
.curr_len=0 .body_len=0) res=(.fl=0x00001515 .curr_len=0 .body_len=0) -
h1c=0x7f50672668f0(0x00000200) conn=0x7f5043245e10(0x801c0300)
h1s=0x7f506722a2f0(0x00014010) sd=0x7f50672387e0(0x04014001)
sc=0x7f506722d890(0x00014422)
<0>2023-11-25T14:56:31.907270+00:00 [05|h1|0|mux_h1.c:3129] processing error :
[B,RUN] [MSG_DONE, MSG_RPBEFORE] - req=(.fl=0x00001511 .curr_len=0
.body_len=2352560) res=(.fl=0x00001404 .curr_len=0 .body_len=0) -
h1c=0x7f503b255a70(0x80000000) conn=0x7f5043c78f10(0x00000300)
h1s=0x7f503b252e40(0x00015040) sd=0x7f503b239f90(0x05010001)
sc=0x7f503b233260(0x00000401)
<0>2023-11-25T14:56:32.998177+00:00 [05|h1|0|mux_h1.c:3129] processing error :
[B,RUN] [MSG_DONE, MSG_DONE] - req=(.fl=0x00001511 .curr_len=0
.body_len=2501993) res=(.fl=0x00001535 .curr_len=0 .body_len=0) -
h1c=0x7f503b256620(0x80000100) conn=0x7f506722ed10(0x00040300)
h1s=0x7f503b23afa0(0x00015040) sd=0x7f503b23bf30(0x0101c001)
sc=0x7f503b234240(0x00040003)
<0>2023-11-25T14:56:32.998187+00:00 [05|h1|0|mux_h1.c:3169] txn done but data
waiting to be sent, set error on h1c : [B,RUN] [MSG_DONE, MSG_DONE] -
req=(.fl=0x00001511 .curr_len=0 .body_len=2501993) res=(.fl=0x00001535
.curr_len=0 .body_len=0) - h1c=0x7f503b256620(0x80000100)
conn=0x7f506722ed10(0x00040300) h1s=0x7f503b23afa0(0x00015040)
sd=0x7f503b23bf30(0x0101c001) sc=0x7f503b234240(0x00040003)
<0>2023-11-25T14:56:33.052598+00:00 [05|h1|0|mux_h1.c:3129] processing error :
[B,RUN] [MSG_DONE, MSG_RPBEFORE] - req=(.fl=0x00001511 .curr_len=0
.body_len=2551166) res=(.fl=0x00001404 .curr_len=0 .body_len=0) -
h1c=0x7f503b232eb0(0x80000000) conn=0x7f504723e230(0x00000300)
h1s=0x7f503b23b1b0(0x00015040) sd=0x7f503b22ea00(0x05010001)
sc=0x7f503b2420d0(0x00000401)
<0>2023-11-25T14:56:33.651131+00:00 [05|h1|0|mux_h1.c:3129] processing error :
[B,RUN] [MSG_DONE, MSG_DONE] - req=(.fl=0x00001511 .curr_len=0
.body_len=2618038) res=(.fl=0x00001535 .curr_len=0 .body_len=0) -
h1c=0x7f503b22a6e0(0x80000100) conn=0x7f504b22c3e0(0x00040300)
h1s=0x7f503b252d70(0x00015040) sd=0x7f503b22b5e0(0x0101c001)
sc=0x7f503b229720(0x00040003)
<0>2023-11-25T14:56:33.651139+00:00 [05|h1|0|mux_h1.c:3169] txn done but data
waiting to be sent, set error on h1c : [B,RUN] [MSG_DONE, MSG_DONE] -
req=(.fl=0x00001511 .curr_len=0 .body_len=2618038) res=(.fl=0x00001535
.curr_len=0 .body_len=0) - h1c=0x7f503b22a6e0(0x80000100)
conn=0x7f504b22c3e0(0x00040300) h1s=0x7f503b252d70(0x00015040)
sd=0x7f503b22b5e0(0x0101c001) sc=0x7f503b229720(0x00040003)
<0>2023-11-25T14:56:33.807314+00:00 [05|h1|0|mux_h1.c:3129] processing error :
[B,RUN] [MSG_DONE, MSG_RPBEFORE] - req=(.fl=0x00001511 .curr_len=0
.body_len=2697148) res=(.fl=0x00001404 .curr_len=0 .body_len=0) -
h1c=0x7f503b22cdb0(0x80000000) conn=0x7f5033249120(0x00000300)
h1s=0x7f503b241ae0(0x00015040) sd=0x7f503b238d50(0x05010001)
sc=0x7f503b238a30(0x00000401)
<0>2023-11-25T14:56:34.125475+00:00 [05|h1|0|mux_h1.c:3129] processing error :
[B,RUN] [MSG_DONE, MSG_RPBEFORE] - req=(.fl=0x00001511 .curr_len=0
.body_len=2777462) res=(.fl=0x00001404 .curr_len=0 .body_len=0) -
h1c=0x7f503b22ab00(0x80000000) conn=0x7f506725c350(0x00000300)
h1s=0x7f503b22a090(0x00015040) sd=0x7f503b232800(0x05010001)
sc=0x7f503b229640(0x00000401)
<0>2023-11-25T14:56:59.867896+00:00 [05|h1|0|mux_h1.c:3129] processing error :
[B,RUN] [MSG_DONE, MSG_RPBEFORE] - req=(.fl=0x00001511 .curr_len=0
.body_len=31809438) res=(.fl=0x00001404 .curr_len=0 .body_len=0) -
h1c=0x7f503b240ec0(0x80000000) conn=0x7f5043c78da0(0x00000300)
h1s=0x7f503b2571a0(0x00015040) sd=0x7f503b25c4d0(0x05010001)
sc=0x7f503b25c470(0x00000401)
Does that help you to debug further?
In case you need any additional information, feel free to ping me.
Thanks a lot
Marno
Am Freitag, 24. November 2023 um 22:17:20 MEZ hat Christopher Faulet
<cfau...@haproxy.com> Folgendes geschrieben:
Le 20/11/2023 à 20:23, Marno Krahmer a écrit :
> Hello,
>
> since a while I see connection errors in my HAProxy-Logs, looking like this:
>
> <134>Nov 20 13:19:10 haproxy[8]: <redacted>:60923 [20/Nov/2023:13:18:41.494]
> http~ nextcloud/nextcloud 0/0/18/-1/28956 500 208 - - IH-- 19/19/0/0/0 0/0
> {<redacted>} "PUT
> https://<redacted>/remote.php/dav/uploads/<redacted>/5D56BCEB-AE7E-423A-B424-DCAB3F98C590/3
> HTTP/2.0"
>
> According to the documentation, a termination state of "I" should never
> happen
> and be reported together with logs.
>
> Now my Problem is: I don't have any more logs, besides that one line being
> logged.
> Therefore my question: What can I do to get further information about
> when/why
> this occurs?
Hi,
A 500-Internal-error with "IH--" termination state is not common. AFAIK, It is
an issue when HAProxy tries to format the request before pushing it to the
server, in th H1 multiplexer. It happens ~29s after the beginning of the
request. So it should be an issue with the request payload. It may be because
the payload is larger or smaller than announced. At this stage it is surprising
because it was already accepted on the client side.
You can try to enable the H1 traces at the error level, hoping the error rate
for other reasons is not too high.
You can add this snippet after your global section:
ring buf1
size 104857600 # 10MB
format timed
backing-file /tmp/blah
global
expose-experimental-directives
trace h1 sink buf1
trace h1 level error
trace h1 verbosity complete
trace h1 start now
This will write the H1 error traces in /tmp/blah file. You can show the traces
by running:
strings /tmp/blah | less
If it does not work, you may use haring tool from HAProxy sources. To do so,
you
should compile it (make dev/haring/haring). Then run
./dev/haring/haring -f /tmp/blah | less
--
Christopher Faulet
