mod_h2
mod_h2 copied to clipboard
icing
Server sent events canceled by client block further request when using h2
Hello,
we encountered a problem when working with server sent events and h2. When to many; 16 to be excact, server sent events requests get canceled by the client (indicated by a "canceled" in the "Status" field of the browser trace) in a certain timeframe (simply speaking it depends on the TimeOut setting in Apache) then the following request get stuck in the "Pending" status for as long as the time set by TimeOut. At when the request are beginning to get stuck, we see the following message appears in the error logs
2022-05-12 10:51:06.617048 http2:debug 10.16.12.58:59119 h2_session(1032): delaying request processing. Current limit is 16 and 16 workers are in use.
Right after the requests get stuck, we see some messages looping in the error log:
2022-05-12 10:51:06.617153 http2:trace2 10.16.12.58:59119 h2_mplx(1032): trywait on data for 0.010000 ms)
2022-05-12 10:51:06.617161 http2:trace1 10.16.12.58:59119 AH03078: h2_session(1032,BUSY,1): transit [WAIT] -- wait cycle --> [BUSY]
2022-05-12 10:51:06.617166 http2:trace1 10.16.12.58:59119 h2_session(1032): read, NONBLOCK_READ, mode=0, readbytes=65536
2022-05-12 10:51:06.617173 http2:trace1 10.16.12.58:59119 h2_session(1032): read
2022-05-12 10:51:06.617176 http2:trace2 10.16.12.58:59119 h2_mplx(1032): dispatch events
2022-05-12 10:51:06.617179 http2:trace2 10.16.12.58:59119 h2_session(1032,BUSY,1): NO_IO event, 1 streams open
2022-05-12 10:51:06.617182 http2:trace1 10.16.12.58:59119 AH03078: h2_session(1032,WAIT,1): transit [BUSY] -- no io --> [WAIT]
2022-05-12 10:51:06.617185 http2:trace3 10.16.12.58:59119 h2_session: wait for data, 20 micros
2022-05-12 10:51:06.617389 http2:trace2 10.16.12.58:59119 h2_mplx(1032): trywait on data for 0.020000 ms)
2022-05-12 10:51:06.617397 http2:trace1 10.16.12.58:59119 AH03078: h2_session(1032,BUSY,1): transit [WAIT] -- wait cycle --> [BUSY]
2022-05-12 10:51:06.617402 http2:trace1 10.16.12.58:59119 h2_session(1032): read, NONBLOCK_READ, mode=0, readbytes=65536
2022-05-12 10:51:06.617409 http2:trace1 10.16.12.58:59119 h2_session(1032): read
2022-05-12 10:51:06.617412 http2:trace2 10.16.12.58:59119 h2_mplx(1032): dispatch events
2022-05-12 10:51:06.617415 http2:trace2 10.16.12.58:59119 h2_session(1032,BUSY,1): NO_IO event, 1 streams open
2022-05-12 10:51:06.617418 http2:trace1 10.16.12.58:59119 AH03078: h2_session(1032,WAIT,1): transit [BUSY] -- no io --> [WAIT]
2022-05-12 10:51:06.617421 http2:trace3 10.16.12.58:59119 h2_session: wait for data, 40 micros
2022-05-12 10:51:06.617537 http2:trace2 10.16.12.58:59119 h2_mplx(1032): trywait on data for 0.040000 ms)
2022-05-12 10:51:06.617544 http2:trace1 10.16.12.58:59119 AH03078: h2_session(1032,BUSY,1): transit [WAIT] -- wait cycle --> [BUSY]
2022-05-12 10:51:06.617548 http2:trace1 10.16.12.58:59119 h2_session(1032): read, NONBLOCK_READ, mode=0, readbytes=65536
2022-05-12 10:51:06.617555 http2:trace1 10.16.12.58:59119 h2_session(1032): read
2022-05-12 10:51:06.617558 http2:trace2 10.16.12.58:59119 h2_mplx(1032): dispatch events
2022-05-12 10:51:06.617561 http2:trace2 10.16.12.58:59119 h2_session(1032,BUSY,1): NO_IO event, 1 streams open
…and it starts over again...
We further analyzed the error log while setting the log level to trace4 and this is what we found after running into the blocking issue after 16 requests canceled by client side:
First we found all SSEs in the log (which all got canceled from the client side) via their distinct request line which always looks the same and noted down their h2 session and stream number. What we saw is that each of the streams received an RST frame with error 8 at some point, e.g.:
2022-05-12 10:50:18.143644 http2:debug 10.16.12.58:59119 AH03067: h2_stream(1032-13): RST_STREAM by client, error=8
We found this for every single canceled SSE request, which makes sense since they all got canceled by the client.
So to us it seems that the client sents us the right signal to destroy the stream at some point since it is no longer needed:
"CANCEL (0x8): Used by the endpoint to indicate that the stream is no longer needed."
But it seems that this is not happening correctly and therefore block the available workers. We have yet one other request, which is no SSE request, where we also receive a RST frame with error 8
2022-05-12 10:50:30.181478 http2:debug 10.16.12.58:59119 AH03067: h2_stream(1032-179): RST_STREAM by client, error=8
But something is different with this one: In addition to the RST frame log message there is also another last log message for this stream that indicates that the stream was destroyed:
2022-05-12 10:50:30.363820 http2:trace3 10.16.12.58:59119 h2_stream(1032-179,CLEANUP): destroy
We do not see this kind of log message with ANY of the canceled SSE streams, at least not in the timeframe of observation (The pending problem starts at 10:51:05, the log ends at 10:56:01 and the first SSE request started at 10:50:14 and got canceled a few seconds later. TimeOut is at 320 seconds)
For some, but not all, canceled SSE streams we additionally found a message like this:
2022-05-12 10:50:45.973224 http2:trace2 10.16.12.58:59119 h2_stream(1032-329,CLEANUP): task_done, in hold
What we also found strange is that the problems always occoured after 16 canceled requests/streams which as far as we understand corresponds to 16 workers dealing with those streams. We understand the mood update mechanism and that RST Frames influence the number of available workers but it is interesting that we always ends up with 16 workers, even if we increase the max workers with the respective directive (man, this rhymes). Although we maybe end up with this number because we always to more or less the same during our testing.
It would be great if someone could help us out here.
Thanks in advance
Hello Stefan
thanks for your swift reply!
Yeah, unfortunately it was also us who reported issue #231 ;) daum3ns is a colleague of mine and we worked together on that issue. So the behavior described here also occurs with the fix from #231 (and without it). The logs above where taken with the fix from #231 already installed. Thanks again for your effort with #231, that really helped us a lot!
Let me know if I can do anything else to help
All the best
I almost suspected, but it was worth a try.
Can you give me a at-least trace2 log of such a cancelled stream? Let's say it is 123-83, everything in the log from first to last appearance?
First one correction: When analyzing the logs again I saw that the very first canceled SSE Stream indeed ends with a "destroy"
2022-05-12 10:50:18.143721 http2:trace2 10.16.12.58:59119 h2_stream(1032-13,CLEANUP): cleanup
...
2022-05-12 10:55:19.884356 http2:trace2 10.16.12.58:59119 h2_stream(1032-13,CLEANUP): task_done, in hold
2022-05-12 10:55:19.912406 http2:trace3 10.16.12.58:59119 h2_stream(1032-13,CLEANUP): destroy
The next canceled SSE stream (1032-75) which was created just 5 seconds after the first stream (1032-13) and got canceled by the client 7 seconds after the first one is missing the "destroy" line:
2022-05-12 10:50:25.189209 http2:trace2 10.16.12.58:59119 h2_stream(1032-75,CLEANUP): cleanup
...
2022-05-12 10:55:24.495797 http2:trace2 10.16.12.58:59119 h2_stream(1032-75,CLEANUP): task_done, in hold
I also noticed the long time (seems to be exactly 5 minutes) between cleanup and the next log lines which include "task_done, in hold". Might have something to do with our long "Timeout". We are actually able to set different "Timeouts" for SSEs (= different paths then the other request). The other request/strem (1032-179, see my first post) that is not an SSE and got cancelled by the client did not have such a long waiting time between "cleanup" and "task_done, in hold".
Now finally to the logs for the complete stream that you asked about (LogLevel trace4). I actually want to show you two, the first and the second SSE stream cancelled by the client (1032-13, 1032-75 respectively). I do that because they behave differently and that might be of interest to you.
2022-05-12 10:50:14.531291 http2:debug 10.16.12.58:59119 AH03082: h2_stream(1032-13,IDLE): created
2022-05-12 10:50:14.531296 http2:trace2 10.16.12.58:59119 h2_stream(1032-13,IDLE): entered state
2022-05-12 10:50:14.531321 http2:debug 10.16.12.58:59119 AH03066: h2_session(1032,BUSY,7): recv FRAME[HEADERS[length=129, hend=1, stream=13, eos=1]], frames=9/3 (r/s)
2022-05-12 10:50:14.531326 http2:trace1 10.16.12.58:59119 h2_stream(1032-13,IDLE): transit to [OPEN]
2022-05-12 10:50:14.531329 http2:trace2 10.16.12.58:59119 h2_stream(1032-13,OPEN): entered state
2022-05-12 10:50:14.531332 http2:trace1 10.16.12.58:59119 h2_stream(1032-13,OPEN): transit to [HALF_CLOSED_REMOTE]
2022-05-12 10:50:14.531335 http2:trace1 10.16.12.58:59119 h2_stream(1032-13,HALF_CLOSED_REMOTE): closing input
2022-05-12 10:50:14.531338 http2:trace2 10.16.12.58:59119 h2_stream(1032-13,HALF_CLOSED_REMOTE): entered state
2022-05-12 10:50:14.531341 http2:trace2 10.16.12.58:59119 h2_session(1032,BUSY,7): fed 138 bytes to nghttp2, 138 read
2022-05-12 10:50:14.531344 http2:trace1 10.16.12.58:59119 h2_session(1032): read, NONBLOCK_READ, mode=0, readbytes=196608
2022-05-12 10:50:14.531358 http2:trace1 10.16.12.58:59119 h2_session(1032): read
2022-05-12 10:50:14.531368 http2:trace1 10.16.12.58:59119 h2_stream(1032-13,HALF_CLOSED_REMOTE): schedule GET https://<MYHOST>/sse/v1/kern-aggreg/mandanten/stzh/dossiers/1001001/DOSSIERMENUUPDATEEVENT chunked=0
2022-05-12 10:50:14.531375 http2:trace1 10.16.12.58:59119 h2_stream(1032-13,HALF_CLOSED_REMOTE): process, added to q
...
2022-05-12 10:50:14.802541 http2:trace3 10.16.12.58:59119 h2_stream(1032-13): create secondary
2022-05-12 10:50:14.802556 http2:trace3 10.16.12.58:59119 h2_secondary(1032-13): created
2022-05-12 10:50:14.802566 http2:trace2 10.16.12.58:59119 h2_secondary(1032-13), pre_connection, adding filters
2022-05-12 10:50:14.802579 http2:trace1 10.16.12.58:59119 h2_task(1032-13): serialize request GET /sse/v1/kern-aggreg/mandanten/stzh/dossiers/1001001/DOSSIERMENUUPDATEEVENT
2022-05-12 10:50:14.802591 http2:trace1 10.16.12.58:59119 h2_task(1032-13): process connection
2022-05-12 10:50:14.802595 http2:trace1 10.16.12.58:59119 h2_task(1032-13), serialized handling
2022-05-12 10:50:14.802616 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=3, block=0, readbytes=1
2022-05-12 10:50:14.802620 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[800])
2022-05-12 10:50:14.802623 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 1 data bytes
2022-05-12 10:50:14.802626 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802629 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[1] HEAP[799])
2022-05-12 10:50:14.802637 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: GET /sse/v1/kern-aggreg/mandanten/stzh/dossiers/1001001/DOSSIERMENUUPDATEEVENT HTTP/1.1\r\n
2022-05-12 10:50:14.802640 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 89 data bytes
2022-05-12 10:50:14.802647 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802650 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[711])
2022-05-12 10:50:14.802653 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: Sec-Ch-Ua: " Not A;Brand";v="99", "Chromium";v="100", "Google Chrome";v="100"\r\n
2022-05-12 10:50:14.802656 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 79 data bytes
2022-05-12 10:50:14.802659 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802662 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[632])
2022-05-12 10:50:14.802665 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: Accept: text/event-stream\r\n
2022-05-12 10:50:14.802667 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 27 data bytes
2022-05-12 10:50:14.802670 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802673 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[605])
2022-05-12 10:50:14.802676 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: Cache-Control: no-cache\r\n
2022-05-12 10:50:14.802678 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 25 data bytes
2022-05-12 10:50:14.802681 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802684 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[580])
2022-05-12 10:50:14.802686 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: Sec-Ch-Ua-Mobile: ?0\r\n
2022-05-12 10:50:14.802689 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 22 data bytes
2022-05-12 10:50:14.802692 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802695 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[558])
2022-05-12 10:50:14.802697 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/100.0.4896.127 Safari/537.36\r\n
2022-05-12 10:50:14.802700 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 130 data bytes
2022-05-12 10:50:14.802704 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802706 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[428])
2022-05-12 10:50:14.802709 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: Sec-Ch-Ua-Platform: "Windows"\r\n
2022-05-12 10:50:14.802711 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 31 data bytes
2022-05-12 10:50:14.802714 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802717 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[397])
2022-05-12 10:50:14.802719 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: Sec-Fetch-Site: same-origin\r\n
2022-05-12 10:50:14.802722 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 29 data bytes
2022-05-12 10:50:14.802725 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802728 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[368])
2022-05-12 10:50:14.802730 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: Sec-Fetch-Mode: cors\r\n
2022-05-12 10:50:14.802733 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 22 data bytes
2022-05-12 10:50:14.802736 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802738 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[346])
2022-05-12 10:50:14.802741 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: Sec-Fetch-Dest: empty\r\n
2022-05-12 10:50:14.802743 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 23 data bytes
2022-05-12 10:50:14.802746 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802749 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[323])
2022-05-12 10:50:14.802751 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: Referer: https://<URL>/mandanten/stzh/dossiers/1001001/uebersicht\r\n
2022-05-12 10:50:14.802754 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 81 data bytes
2022-05-12 10:50:14.802757 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802760 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[242])
2022-05-12 10:50:14.802762 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: Accept-Encoding: gzip, deflate, br\r\n
2022-05-12 10:50:14.802765 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 36 data bytes
2022-05-12 10:50:14.802768 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802770 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[206])
2022-05-12 10:50:14.802773 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: Accept-Language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7\r\n
2022-05-12 10:50:14.802775 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 54 data bytes
2022-05-12 10:50:14.802779 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802781 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[152])
2022-05-12 10:50:14.802784 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: Cookie: <Cookies>\r\n
2022-05-12 10:50:14.802786 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 123 data bytes
2022-05-12 10:50:14.802790 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802793 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[29])
2022-05-12 10:50:14.802795 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: Host: <MYHOST>\r\n
2022-05-12 10:50:14.802798 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 27 data bytes
2022-05-12 10:50:14.802801 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:14.802804 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[2])
2022-05-12 10:50:14.802806 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): getline: \r\n
2022-05-12 10:50:14.802809 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-13): 2 data bytes
2022-05-12 10:50:14.802872 http2:trace3 10.16.12.58:59119 <clientid> <reqid> h2_task(1032-13): adding request filters https://<MYHOST>/mandanten/stzh/dossiers/1001001/uebersicht
...
2022-05-12 10:50:18.143644 http2:debug 10.16.12.58:59119 AH03067: h2_stream(1032-13): RST_STREAM by client, error=8
2022-05-12 10:50:18.143648 http2:trace1 10.16.12.58:59119 h2_mplx(1032): mood update, decreasing worker limit to 16
2022-05-12 10:50:18.143651 http2:debug 10.16.12.58:59119 AH03065: h2_stream(1032-13,HALF_CLOSED_REMOTE): closing with err=8 cancel
2022-05-12 10:50:18.143654 http2:trace1 10.16.12.58:59119 h2_stream(1032-13,HALF_CLOSED_REMOTE): reset, error=8
2022-05-12 10:50:18.143657 http2:trace2 10.16.12.58:59119 h2_stream(1032-13,HALF_CLOSED_REMOTE): dispatch event 2
2022-05-12 10:50:18.143661 http2:trace1 10.16.12.58:59119 h2_stream(1032-13,HALF_CLOSED_REMOTE): transit to [CLOSED]
2022-05-12 10:50:18.143663 http2:trace1 10.16.12.58:59119 h2_stream(1032-13,CLOSED): closing input
2022-05-12 10:50:18.143666 http2:trace2 10.16.12.58:59119 h2_stream(1032-13,CLOSED): entered state
2022-05-12 10:50:18.143669 http2:trace2 10.16.12.58:59119 h2_session(1032,BUSY,1): fed 13 bytes to nghttp2, 13 read
2022-05-12 10:50:18.143672 http2:trace1 10.16.12.58:59119 h2_session(1032): read, NONBLOCK_READ, mode=0, readbytes=65536
2022-05-12 10:50:18.143677 http2:trace1 10.16.12.58:59119 h2_session(1032): read
2022-05-12 10:50:18.143681 http2:trace1 10.16.12.58:59119 h2_stream(1032-53,HALF_CLOSED_REMOTE): schedule GET https://<MYHOST>/rs/v1/kern-aggreg/mandanten/stzh/cockpits/benutzer/EINSTIEG_COCKPIT chunked=0
2022-05-12 10:50:18.143693 http2:trace1 10.16.12.58:59119 h2_stream(1032-53,HALF_CLOSED_REMOTE): process, added to q
2022-05-12 10:50:18.143696 http2:trace2 10.16.12.58:59119 h2_mplx(1032): dispatch events
2022-05-12 10:50:18.143702 http2:debug 10.16.12.58:59119 AH03068: h2_session(1032,BUSY,1): sent FRAME[RST_STREAM[length=4, flags=0, stream=13]], frames=36/130 (r/s)
2022-05-12 10:50:18.143708 http2:trace2 10.16.12.58:59119 h2_session(1032)-out: h2eos heap[13] flush
2022-05-12 10:50:18.143712 http2:trace2 10.16.12.58:59119 h2_stream(1032-13,CLOSED): dispatch event 3
2022-05-12 10:50:18.143715 http2:trace1 10.16.12.58:59119 h2_stream(1032-13,CLOSED): transit to [CLEANUP]
2022-05-12 10:50:18.143718 http2:trace2 10.16.12.58:59119 h2_stream(1032-13,CLEANUP): entered state
2022-05-12 10:50:18.143714 http2:trace1 10.16.12.58:59119 h2_task(1032-53): serialize request GET /rs/v1/kern-aggreg/mandanten/stzh/cockpits/benutzer/EINSTIEG_COCKPIT
2022-05-12 10:50:18.143721 http2:trace2 10.16.12.58:59119 h2_stream(1032-13,CLEANUP): cleanup
...
2022-05-12 10:55:19.883299 http2:trace2 10.16.12.58:59119 bb_dump(1032-13): h2_task send_out(FLUSH EOC)
2022-05-12 10:55:19.883306 http2:trace2 10.16.12.58:59119 beam(1032-13,output,closed=0,aborted=0,empty=1,buf=0): send_out(before)
2022-05-12 10:55:19.883313 http2:trace2 10.16.12.58:59119 beam(1032-13,output,closed=0,aborted=0,empty=0,buf=0): send_out(after)
2022-05-12 10:55:19.883316 http2:trace2 10.16.12.58:59119 h2_task(1032-13): send_out done
2022-05-12 10:55:19.883319 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-13): buffered=1
2022-05-12 10:55:19.883321 http2:debug 10.16.12.58:59119 AH03348: h2_task(1032-13): open output to GET <MYHOST> /sse/v1/kern-aggreg/mandanten/stzh/dossiers/1001001/DOSSIERMENUUPDATEEVENT
2022-05-12 10:55:19.883326 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-13): secondary_out leave
2022-05-12 10:55:19.883985 http2:trace1 10.16.12.58:59119 h2_task(1032-13): output_filter called
2022-05-12 10:55:19.883997 http2:trace2 10.16.12.58:59119 bb_dump(1032-13): h2_task send_out(MMAP[2557])
2022-05-12 10:55:19.884000 http2:trace2 10.16.12.58:59119 beam(1032-13,output,closed=0,aborted=1,empty=1,buf=0): send_out(before)
2022-05-12 10:55:19.884004 http2:trace2 10.16.12.58:59119 beam(1032-13,output,closed=0,aborted=1,empty=0,buf=2557): send_out(after)
2022-05-12 10:55:19.884007 http2:debug 10.16.12.58:59119 h2_task(1032-13): send_out (2557 bytes)
2022-05-12 10:55:19.884010 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-13): buffered=1
2022-05-12 10:55:19.884013 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-13): secondary_out leave
2022-05-12 10:55:19.884027 http2:trace2 10.16.12.58:59119 bb_dump(1032-13): h2_task send_out(EOR)
2022-05-12 10:55:19.884032 http2:trace2 10.16.12.58:59119 beam(1032-13,output,closed=0,aborted=1,empty=1,buf=0): send_out(before)
2022-05-12 10:55:19.884035 http2:trace2 10.16.12.58:59119 beam(1032-13,output,closed=0,aborted=1,empty=0,buf=0): send_out(after)
2022-05-12 10:55:19.884037 http2:debug 10.16.12.58:59119 h2_task(1032-13): send_out (0 bytes)
2022-05-12 10:55:19.884040 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-13): buffered=1
2022-05-12 10:55:19.884042 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-13): secondary_out leave
2022-05-12 10:55:19.884322 http2:trace2 10.16.12.58:59119 bb_dump(1032-13): h2_task send_out(FLUSH)
2022-05-12 10:55:19.884329 http2:trace2 10.16.12.58:59119 beam(1032-13,output,closed=0,aborted=1,empty=1,buf=0): send_out(before)
2022-05-12 10:55:19.884332 http2:trace2 10.16.12.58:59119 beam(1032-13,output,closed=0,aborted=1,empty=0,buf=0): send_out(after)
2022-05-12 10:55:19.884335 http2:debug 10.16.12.58:59119 h2_task(1032-13): send_out (0 bytes)
2022-05-12 10:55:19.884338 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-13): buffered=1
2022-05-12 10:55:19.884340 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-13): secondary_out leave
2022-05-12 10:55:19.884344 http2:trace1 10.16.12.58:59119 h2_task(1032-13): processing done
2022-05-12 10:55:19.884347 http2:trace1 10.16.12.58:59119 h2_mplx(1032): task(1032-13) done
2022-05-12 10:55:19.884351 http2:trace2 10.16.12.58:59119 h2_mplx(1032-13): request done, 305081.787000 ms elapsed
2022-05-12 10:55:19.884356 http2:trace2 10.16.12.58:59119 h2_stream(1032-13,CLEANUP): task_done, in hold
...
2022-05-12 10:55:19.912348 http2:trace1 10.16.12.58:59119 beam(1032-13,output,closed=0,aborted=1,empty=1,buf=0): h2_task_destroy, destroy secondary
2022-05-12 10:55:19.912352 http2:trace3 10.16.12.58:59119 h2_secondary(1032-13): destroy
2022-05-12 10:55:19.912406 http2:trace3 10.16.12.58:59119 h2_stream(1032-13,CLEANUP): destroy
... and the other one:
2022-05-12 10:50:19.438052 http2:debug 10.16.12.58:59119 AH03082: h2_stream(1032-75,IDLE): created
2022-05-12 10:50:19.438055 http2:trace2 10.16.12.58:59119 h2_stream(1032-75,IDLE): entered state
2022-05-12 10:50:19.438072 http2:debug 10.16.12.58:59119 AH03066: h2_session(1032,BUSY,7): recv FRAME[HEADERS[length=80, hend=1, stream=75, eos=1]], frames=49/157 (r/s)
2022-05-12 10:50:19.438077 http2:trace1 10.16.12.58:59119 h2_stream(1032-75,IDLE): transit to [OPEN]
2022-05-12 10:50:19.438080 http2:trace2 10.16.12.58:59119 h2_stream(1032-75,OPEN): entered state
2022-05-12 10:50:19.438082 http2:trace1 10.16.12.58:59119 h2_stream(1032-75,OPEN): transit to [HALF_CLOSED_REMOTE]
2022-05-12 10:50:19.438085 http2:trace1 10.16.12.58:59119 h2_stream(1032-75,HALF_CLOSED_REMOTE): closing input
2022-05-12 10:50:19.438087 http2:trace2 10.16.12.58:59119 h2_stream(1032-75,HALF_CLOSED_REMOTE): entered state
2022-05-12 10:50:19.438090 http2:trace2 10.16.12.58:59119 h2_session(1032,BUSY,7): fed 89 bytes to nghttp2, 89 read
2022-05-12 10:50:19.438093 http2:trace1 10.16.12.58:59119 h2_session(1032): read, NONBLOCK_READ, mode=0, readbytes=196608
2022-05-12 10:50:19.438099 http2:trace1 10.16.12.58:59119 h2_session(1032): read
2022-05-12 10:50:19.438101 http2:trace1 10.16.12.58:59119 h2_stream(1032-75,HALF_CLOSED_REMOTE): schedule GET https://<MYHOST>/sse/v1/kern-aggreg/mandanten/stzh/dossiers/1001003/DOSSIERMENUUPDATEEVENT chunked=0
2022-05-12 10:50:19.438113 http2:trace1 10.16.12.58:59119 h2_stream(1032-75,HALF_CLOSED_REMOTE): process, added to q
2022-05-12 10:50:19.438116 http2:trace2 10.16.12.58:59119 h2_mplx(1032): dispatch events
2022-05-12 10:50:19.438119 http2:trace1 10.16.12.58:59119 h2_session(1032): read, NONBLOCK_READ, mode=0, readbytes=229376
2022-05-12 10:50:19.438124 http2:trace1 10.16.12.58:59119 h2_session(1032): read
2022-05-12 10:50:19.438126 http2:trace2 10.16.12.58:59119 h2_mplx(1032): dispatch events
2022-05-12 10:50:19.438129 http2:trace2 10.16.12.58:59119 h2_session(1032,BUSY,7): NO_IO event, 7 streams open
2022-05-12 10:50:19.438128 http2:trace3 10.16.12.58:59119 h2_stream(1032-75): create secondary
2022-05-12 10:50:19.438145 http2:trace3 10.16.12.58:59119 h2_secondary(1032-75): created
2022-05-12 10:50:19.438156 http2:trace2 10.16.12.58:59119 h2_secondary(1032-75), pre_connection, adding filters
2022-05-12 10:50:19.438172 http2:trace1 10.16.12.58:59119 h2_task(1032-75): serialize request GET /sse/v1/kern-aggreg/mandanten/stzh/dossiers/1001003/DOSSIERMENUUPDATEEVENT
2022-05-12 10:50:19.438181 http2:trace1 10.16.12.58:59119 h2_task(1032-75): process connection
2022-05-12 10:50:19.438185 http2:trace1 10.16.12.58:59119 h2_task(1032-75), serialized handling
2022-05-12 10:50:19.438194 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=3, block=0, readbytes=1
2022-05-12 10:50:19.438197 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[800])
2022-05-12 10:50:19.438200 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 1 data bytes
2022-05-12 10:50:19.438204 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438207 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[1] HEAP[799])
2022-05-12 10:50:19.438211 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: GET /sse/v1/kern-aggreg/mandanten/stzh/dossiers/1001003/DOSSIERMENUUPDATEEVENT HTTP/1.1\r\n
2022-05-12 10:50:19.438214 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 89 data bytes
2022-05-12 10:50:19.438220 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438223 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[711])
2022-05-12 10:50:19.438226 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: Sec-Ch-Ua: " Not A;Brand";v="99", "Chromium";v="100", "Google Chrome";v="100"\r\n
2022-05-12 10:50:19.438229 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 79 data bytes
2022-05-12 10:50:19.438232 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438235 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[632])
2022-05-12 10:50:19.438238 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: Accept: text/event-stream\r\n
2022-05-12 10:50:19.438240 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 27 data bytes
2022-05-12 10:50:19.438244 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438246 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[605])
2022-05-12 10:50:19.438249 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: Cache-Control: no-cache\r\n
2022-05-12 10:50:19.438252 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 25 data bytes
2022-05-12 10:50:19.438255 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438258 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[580])
2022-05-12 10:50:19.438260 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: Sec-Ch-Ua-Mobile: ?0\r\n
2022-05-12 10:50:19.438263 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 22 data bytes
2022-05-12 10:50:19.438266 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438269 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[558])
2022-05-12 10:50:19.438271 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/100.0.4896.127 Safari/537.36\r\n
2022-05-12 10:50:19.438274 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 130 data bytes
2022-05-12 10:50:19.438277 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438280 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[428])
2022-05-12 10:50:19.438283 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: Sec-Ch-Ua-Platform: "Windows"\r\n
2022-05-12 10:50:19.438285 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 31 data bytes
2022-05-12 10:50:19.438288 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438291 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[397])
2022-05-12 10:50:19.438294 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: Sec-Fetch-Site: same-origin\r\n
2022-05-12 10:50:19.438296 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 29 data bytes
2022-05-12 10:50:19.438299 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438302 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[368])
2022-05-12 10:50:19.438305 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: Sec-Fetch-Mode: cors\r\n
2022-05-12 10:50:19.438307 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 22 data bytes
2022-05-12 10:50:19.438310 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438313 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[346])
2022-05-12 10:50:19.438316 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: Sec-Fetch-Dest: empty\r\n
2022-05-12 10:50:19.438318 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 23 data bytes
2022-05-12 10:50:19.438322 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438325 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[323])
2022-05-12 10:50:19.438327 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: Referer: https://<MYHOST>/mandanten/stzh/dossiers/1001003/uebersicht\r\n
2022-05-12 10:50:19.438330 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 81 data bytes
2022-05-12 10:50:19.438333 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438336 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[242])
2022-05-12 10:50:19.438338 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: Accept-Encoding: gzip, deflate, br\r\n
2022-05-12 10:50:19.438341 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 36 data bytes
2022-05-12 10:50:19.438344 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438347 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[206])
2022-05-12 10:50:19.438349 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: Accept-Language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7\r\n
2022-05-12 10:50:19.438352 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 54 data bytes
2022-05-12 10:50:19.438355 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438358 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[152])
2022-05-12 10:50:19.438360 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: Cookie: <Cookies>
2022-05-12 10:50:19.438363 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 123 data bytes
2022-05-12 10:50:19.438367 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438369 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[29])
2022-05-12 10:50:19.438372 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: Host: <MYHOST>\r\n
2022-05-12 10:50:19.438374 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 27 data bytes
2022-05-12 10:50:19.438378 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): read, mode=1, block=1, readbytes=8192
2022-05-12 10:50:19.438381 http2:trace2 10.16.12.58:59119 bb_dump(1032): task_input.bb(HEAP[2])
2022-05-12 10:50:19.438383 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): getline: \r\n
2022-05-12 10:50:19.438386 http2:trace1 10.16.12.58:59119 h2_secondary_in(1032-75): 2 data bytes
2022-05-12 10:50:19.438429 http2:trace3 10.16.12.58:59119 <clientid> <requestid> h2_task(1032-75): adding request filters https://<MYHOST>/mandanten/stzh/dossiers/1001003/uebersicht
...
2022-05-12 10:50:25.189128 http2:debug 10.16.12.58:59119 AH03067: h2_stream(1032-75): RST_STREAM by client, error=8
2022-05-12 10:50:25.189133 http2:trace1 10.16.12.58:59119 h2_mplx(1032): mood update, decreasing worker limit to 16
2022-05-12 10:50:25.189136 http2:debug 10.16.12.58:59119 AH03065: h2_stream(1032-75,HALF_CLOSED_REMOTE): closing with err=8 cancel
2022-05-12 10:50:25.189139 http2:trace1 10.16.12.58:59119 h2_stream(1032-75,HALF_CLOSED_REMOTE): reset, error=8
2022-05-12 10:50:25.189142 http2:trace2 10.16.12.58:59119 h2_stream(1032-75,HALF_CLOSED_REMOTE): dispatch event 2
2022-05-12 10:50:25.189145 http2:trace1 10.16.12.58:59119 h2_stream(1032-75,HALF_CLOSED_REMOTE): transit to [CLOSED]
2022-05-12 10:50:25.189148 http2:trace1 10.16.12.58:59119 h2_stream(1032-75,CLOSED): closing input
2022-05-12 10:50:25.189151 http2:trace2 10.16.12.58:59119 h2_stream(1032-75,CLOSED): entered state
2022-05-12 10:50:25.189154 http2:trace2 10.16.12.58:59119 h2_session(1032,BUSY,1): fed 13 bytes to nghttp2, 13 read
2022-05-12 10:50:25.189157 http2:trace1 10.16.12.58:59119 h2_session(1032): read, NONBLOCK_READ, mode=0, readbytes=65536
2022-05-12 10:50:25.189163 http2:trace1 10.16.12.58:59119 h2_session(1032): read
2022-05-12 10:50:25.189167 http2:trace1 10.16.12.58:59119 h2_stream(1032-127,HALF_CLOSED_REMOTE): schedule GET https://<MYHOST>/rs/v1/kern-aggreg/mandanten/stzh/cockpits/benutzer/EINSTIEG_COCKPIT chunked=0
2022-05-12 10:50:25.189180 http2:trace1 10.16.12.58:59119 h2_stream(1032-127,HALF_CLOSED_REMOTE): process, added to q
2022-05-12 10:50:25.189183 http2:trace2 10.16.12.58:59119 h2_mplx(1032): dispatch events
2022-05-12 10:50:25.189188 http2:debug 10.16.12.58:59119 AH03068: h2_session(1032,BUSY,1): sent FRAME[RST_STREAM[length=4, flags=0, stream=75]], frames=83/414 (r/s)
2022-05-12 10:50:25.189196 http2:trace2 10.16.12.58:59119 h2_session(1032)-out: h2eos heap[13] flush
2022-05-12 10:50:25.189201 http2:trace2 10.16.12.58:59119 h2_stream(1032-75,CLOSED): dispatch event 3
2022-05-12 10:50:25.189204 http2:trace1 10.16.12.58:59119 h2_stream(1032-75,CLOSED): transit to [CLEANUP]
2022-05-12 10:50:25.189206 http2:trace2 10.16.12.58:59119 h2_stream(1032-75,CLEANUP): entered state
2022-05-12 10:50:25.189209 http2:trace2 10.16.12.58:59119 h2_stream(1032-75,CLEANUP): cleanup
...
2022-05-12 10:55:24.494939 http2:trace2 10.16.12.58:59119 bb_dump(1032-75): h2_task send_out(FLUSH EOC)
2022-05-12 10:55:24.494943 http2:trace2 10.16.12.58:59119 beam(1032-75,output,closed=0,aborted=0,empty=1,buf=0): send_out(before)
2022-05-12 10:55:24.494948 http2:trace2 10.16.12.58:59119 beam(1032-75,output,closed=0,aborted=0,empty=0,buf=0): send_out(after)
2022-05-12 10:55:24.494951 http2:trace2 10.16.12.58:59119 h2_task(1032-75): send_out done
2022-05-12 10:55:24.494954 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-75): buffered=1
2022-05-12 10:55:24.494957 http2:debug 10.16.12.58:59119 AH03348: h2_task(1032-75): open output to GET <MYHOST> /sse/v1/kern-aggreg/mandanten/stzh/dossiers/1001003/DOSSIERMENUUPDATEEVENT
2022-05-12 10:55:24.494962 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-75): secondary_out leave
2022-05-12 10:55:24.495453 http2:trace1 10.16.12.58:59119 h2_task(1032-75): output_filter called
2022-05-12 10:55:24.495460 http2:trace2 10.16.12.58:59119 bb_dump(1032-75): h2_task send_out(MMAP[2557])
2022-05-12 10:55:24.495463 http2:trace2 10.16.12.58:59119 beam(1032-75,output,closed=0,aborted=1,empty=1,buf=0): send_out(before)
2022-05-12 10:55:24.495467 http2:trace2 10.16.12.58:59119 beam(1032-75,output,closed=0,aborted=1,empty=0,buf=2557): send_out(after)
2022-05-12 10:55:24.495470 http2:debug 10.16.12.58:59119 h2_task(1032-75): send_out (2557 bytes)
2022-05-12 10:55:24.495472 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-75): buffered=1
2022-05-12 10:55:24.495475 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-75): secondary_out leave
2022-05-12 10:55:24.495490 http2:trace2 10.16.12.58:59119 bb_dump(1032-75): h2_task send_out(EOR)
2022-05-12 10:55:24.495494 http2:trace2 10.16.12.58:59119 beam(1032-75,output,closed=0,aborted=1,empty=1,buf=0): send_out(before)
2022-05-12 10:55:24.495497 http2:trace2 10.16.12.58:59119 beam(1032-75,output,closed=0,aborted=1,empty=0,buf=0): send_out(after)
2022-05-12 10:55:24.495499 http2:debug 10.16.12.58:59119 h2_task(1032-75): send_out (0 bytes)
2022-05-12 10:55:24.495502 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-75): buffered=1
2022-05-12 10:55:24.495504 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-75): secondary_out leave
2022-05-12 10:55:24.495766 http2:trace2 10.16.12.58:59119 bb_dump(1032-75): h2_task send_out(FLUSH)
2022-05-12 10:55:24.495769 http2:trace2 10.16.12.58:59119 beam(1032-75,output,closed=0,aborted=1,empty=1,buf=0): send_out(before)
2022-05-12 10:55:24.495774 http2:trace2 10.16.12.58:59119 beam(1032-75,output,closed=0,aborted=1,empty=0,buf=0): send_out(after)
2022-05-12 10:55:24.495777 http2:debug 10.16.12.58:59119 h2_task(1032-75): send_out (0 bytes)
2022-05-12 10:55:24.495779 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-75): buffered=1
2022-05-12 10:55:24.495782 http2:trace2 10.16.12.58:59119 h2_secondary_out(1032-75): secondary_out leave
2022-05-12 10:55:24.495785 http2:trace1 10.16.12.58:59119 h2_task(1032-75): processing done
2022-05-12 10:55:24.495789 http2:trace1 10.16.12.58:59119 h2_mplx(1032): task(1032-75) done
2022-05-12 10:55:24.495793 http2:trace2 10.16.12.58:59119 h2_mplx(1032-75): request done, 305057.643000 ms elapsed
2022-05-12 10:55:24.495797 http2:trace2 10.16.12.58:59119 h2_stream(1032-75,CLEANUP): task_done, in hold
What is really strange is also that for the last part (starting with "bb_dump(session-stream): h2_task send_out(FLUSH EOC)" and ending with "h2_stream(session-stream,CLEANUP): task_done, in hold") stream 75 and stream 13 seem to pass throught exactly the same states but for stream 75 the "destroy" is missing.
Hope that helps. If required, I could also send you the whole log file of the whole test with all canceled streams via email (might contain some sensitive stuff).
Cheers
@vvo459 thanks for the samples. I would prefer to have a look at the complete log. If you could send it to stefan at eissing.org, thanks!
When the h2 connection sees behaviour that it regards as an attempt by the client to hog its resources, it falls back to allowing 16 active requests only. That is why you see the 16. Successful requests raise this always above, up to max h2 workers, but on the first mood downgrade, it goes back to 16.
What you may try in the meantime is to change the misbehaviour detection in reset_is_acceptable(), lines 1040-1060 in h2_mplx.c. Please remove the line:
if (!stream->out_data_frames) return 0; /* no response body data sent yet. bad. */
This should result in client RST of responses as acceptable, where no data has been sent yet. I imagine that happens in your SSE implementation.
I will check the complete log to see if the internal accounting of open/active streams has a bug or if you just run into the limit of 16 and that stalls your app. Should this be the case, I imagine h2 needs to add a directive, so the mood change consequences can be adapted or completely disabled for apps who need that.
"When the h2 connection sees behaviour that it regards as an attempt by the client to hog its resources,.." For example sending an RST frame correct?
"but on the first mood downgrade, it goes back to 16." Does that depend on the number of workers active before the mood downgrade or is it always 16?
"This should result in client RST of responses as acceptable, where no data has been sent yet. I imagine that happens in your SSE implementation." If you mean no response data from the backend then I agree. The backend only pushes data from time to time and in our testing we canceled the connection very quickly (after a few seconds), so I am quite sure the backend did probably not sent anything. Quick explanation: The logs that you see are actually from a reverse proxy, so when I am talking about the backend I talk about the server behind the proxy where the application is running on.
We will try to remove the line and then lets see.
Cheers
"When the h2 connection sees behaviour that it regards as an attempt by the client to hog its resources,.." For example sending an RST frame correct?
Sending RST before a single byte of the response was sent. After that, it's fine. The propose line removal changes that to: RST is fine as long as the client waited for the response status+headers.
"but on the first mood downgrade, it goes back to 16." Does that depend on the number of workers active before the mood downgrade or is it always 16?
It goes to 16 if the limit was higher before. Otherwise it shrinks to 8, then 4, then 2 as minimum.
"This should result in client RST of responses as acceptable, where no data has been sent yet. I imagine that happens in your SSE implementation." If you mean no response data from the backend then I agree. The backend only pushes data from time to time and in our testing we canceled the connection very quickly (after a few seconds), so I am quite sure the backend did probably not sent anything. Quick explanation: The logs that you see are actually from a reverse proxy, so when I am talking about the backend I talk about the server behind the proxy where the application is running on.
We will try to remove the line and then lets see.
Thanks!
"Sending RST before a single byte of the response was sent. After that, it's fine. The propose line removal changes that to: RST is fine as long as the client waited for the response status+headers." Ok makes sense I guess: It like the clients says "hey server lets open a stream" and before anything gets send back "you know what...never mind". If he does that again and again it looks like the client just keeps playing games with the server to keep him busy.
One more question: client waited for the response status + header = http request if fully done from the point of view?
"It goes to 16 if the limit was higher before. Otherwise it shrinks to 8, then 4, then 2 as minimum." Ok good to know. This then also explains why increasing the MaxWorkers did not help that much.
"Thanks!" Thank you :)
Unfortunately, this time the fix did not help. From the clients side the effect was quite the same: 16 canceled requests by the client again lead to a blocking of further requests. This is also again reflected in the error log:
2022-05-20 15:19:48.606991 http2:debug 10.16.12.58:58611 AH03067: h2_stream(522-123): RST_STREAM by client, error=8
2022-05-20 15:19:48.606996 http2:trace1 10.16.12.58:58611 h2_mplx(522): mood update, decreasing worker limit to 16
Take it with a grain of salt, we will check again if we made a mistake on our side in building and distributing the version with your fix.
Again a complete stream of a cancelled SSE request (I will sent you the complete log agein via Email). Note the smaller jump in time, not 5 but 2 minutes, after 2022-05-20 15:19:48.607081 http2:trace2 10.16.12.58:58611 h2_stream(522-123,CLEANUP): cleanup. I reduced our timeout to 120 seconds so we do not have to wait that long until the blockade ends.
2022-05-20 15:19:47.517276 http2:debug 10.16.12.58:58611 AH03082: h2_stream(522-123,IDLE): created
2022-05-20 15:19:47.517279 http2:trace2 10.16.12.58:58611 h2_stream(522-123,IDLE): entered state
2022-05-20 15:19:47.517299 http2:debug 10.16.12.58:58611 AH03066: h2_session(522,BUSY,7): recv FRAME[HEADERS[length=80, hend=1, stream=123, eos=1]], frames=86/271 (r/s)
2022-05-20 15:19:47.517304 http2:trace1 10.16.12.58:58611 h2_stream(522-123,IDLE): transit to [OPEN]
2022-05-20 15:19:47.517307 http2:trace2 10.16.12.58:58611 h2_stream(522-123,OPEN): entered state
2022-05-20 15:19:47.517309 http2:trace1 10.16.12.58:58611 h2_stream(522-123,OPEN): transit to [HALF_CLOSED_REMOTE]
2022-05-20 15:19:47.517312 http2:trace1 10.16.12.58:58611 h2_stream(522-123,HALF_CLOSED_REMOTE): closing input
2022-05-20 15:19:47.517314 http2:trace2 10.16.12.58:58611 h2_stream(522-123,HALF_CLOSED_REMOTE): entered state
2022-05-20 15:19:47.517317 http2:trace2 10.16.12.58:58611 h2_session(522,BUSY,7): fed 89 bytes to nghttp2, 89 read
2022-05-20 15:19:47.517320 http2:trace1 10.16.12.58:58611 h2_session(522): read, NONBLOCK_READ, mode=0, readbytes=196608
2022-05-20 15:19:47.517326 http2:trace1 10.16.12.58:58611 h2_session(522): read
2022-05-20 15:19:47.517329 http2:trace1 10.16.12.58:58611 h2_stream(522-123,HALF_CLOSED_REMOTE): schedule GET https://<MyHost>/sse/v1/kern-aggreg/mandanten/stzh/dossiers/1001001/DOSSIERMENUUPDATEEVENT chunked=0
2022-05-20 15:19:47.517335 http2:trace1 10.16.12.58:58611 h2_stream(522-123,HALF_CLOSED_REMOTE): process, added to q
...
2022-05-20 15:19:47.517514 http2:trace3 10.16.12.58:58611 h2_stream(522-123): create secondary
2022-05-20 15:19:47.517529 http2:trace3 10.16.12.58:58611 h2_secondary(522-123): created
2022-05-20 15:19:47.517535 http2:trace2 10.16.12.58:58611 h2_secondary(522-123), pre_connection, adding filters
2022-05-20 15:19:47.517549 http2:trace1 10.16.12.58:58611 h2_task(522-123): serialize request GET /sse/v1/kern-aggreg/mandanten/stzh/dossiers/1001001/DOSSIERMENUUPDATEEVENT
2022-05-20 15:19:47.517563 http2:trace1 10.16.12.58:58611 h2_task(522-123): process connection
2022-05-20 15:19:47.517566 http2:trace1 10.16.12.58:58611 h2_task(522-123), serialized handling
2022-05-20 15:19:47.517575 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=3, block=0, readbytes=1
2022-05-20 15:19:47.517578 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[800])
2022-05-20 15:19:47.517581 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 1 data bytes
2022-05-20 15:19:47.517584 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517588 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[1] HEAP[799])
2022-05-20 15:19:47.517593 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: GET /sse/v1/kern-aggreg/mandanten/stzh/dossiers/1001001/DOSSIERMENUUPDATEEVENT HTTP/1.1\r\n
2022-05-20 15:19:47.517596 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 89 data bytes
2022-05-20 15:19:47.517604 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517607 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[711])
2022-05-20 15:19:47.517610 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: Sec-Ch-Ua: " Not A;Brand";v="99", "Chromium";v="100", "Google Chrome";v="100"\r\n
2022-05-20 15:19:47.517612 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 79 data bytes
2022-05-20 15:19:47.517616 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517619 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[632])
2022-05-20 15:19:47.517621 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: Accept: text/event-stream\r\n
2022-05-20 15:19:47.517623 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 27 data bytes
2022-05-20 15:19:47.517627 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517630 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[605])
2022-05-20 15:19:47.517632 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: Cache-Control: no-cache\r\n
2022-05-20 15:19:47.517635 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 25 data bytes
2022-05-20 15:19:47.517638 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517641 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[580])
2022-05-20 15:19:47.517643 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: Sec-Ch-Ua-Mobile: ?0\r\n
2022-05-20 15:19:47.517645 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 22 data bytes
2022-05-20 15:19:47.517649 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517651 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[558])
2022-05-20 15:19:47.517654 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/100.0.4896.127 Safari/537.36\r\n
2022-05-20 15:19:47.517656 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 130 data bytes
2022-05-20 15:19:47.517660 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517662 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[428])
2022-05-20 15:19:47.517665 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: Sec-Ch-Ua-Platform: "Windows"\r\n
2022-05-20 15:19:47.517668 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 31 data bytes
2022-05-20 15:19:47.517671 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517674 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[397])
2022-05-20 15:19:47.517676 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: Sec-Fetch-Site: same-origin\r\n
2022-05-20 15:19:47.517678 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 29 data bytes
2022-05-20 15:19:47.517682 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517684 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[368])
2022-05-20 15:19:47.517687 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: Sec-Fetch-Mode: cors\r\n
2022-05-20 15:19:47.517689 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 22 data bytes
2022-05-20 15:19:47.517692 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517695 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[346])
2022-05-20 15:19:47.517697 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: Sec-Fetch-Dest: empty\r\n
2022-05-20 15:19:47.517699 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 23 data bytes
2022-05-20 15:19:47.517703 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517705 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[323])
2022-05-20 15:19:47.517708 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: Referer: https://<MyHost>/mandanten/stzh/dossiers/1001001/uebersicht\r\n
2022-05-20 15:19:47.517710 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 81 data bytes
2022-05-20 15:19:47.517713 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517716 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[242])
2022-05-20 15:19:47.517719 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: Accept-Encoding: gzip, deflate, br\r\n
2022-05-20 15:19:47.517721 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 36 data bytes
2022-05-20 15:19:47.517724 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517727 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[206])
2022-05-20 15:19:47.517729 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: Accept-Language: de-DE,de;q=0.9,en-US;q=0.8,en;q=0.7\r\n
2022-05-20 15:19:47.517732 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 54 data bytes
2022-05-20 15:19:47.517735 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517737 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[152])
2022-05-20 15:19:47.517740 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: Cookie: <Cookies>
2022-05-20 15:19:47.517742 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 123 data bytes
2022-05-20 15:19:47.517746 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517748 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[29])
2022-05-20 15:19:47.517751 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: Host: <MyHost>\r\n
2022-05-20 15:19:47.517753 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 27 data bytes
2022-05-20 15:19:47.517756 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): read, mode=1, block=1, readbytes=8192
2022-05-20 15:19:47.517759 http2:trace2 10.16.12.58:58611 bb_dump(522): task_input.bb(HEAP[2])
2022-05-20 15:19:47.517762 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): getline: \r\n
2022-05-20 15:19:47.517764 http2:trace1 10.16.12.58:58611 h2_secondary_in(522-123): 2 data bytes
2022-05-20 15:19:47.517809 http2:trace3 10.16.12.58:58611 <ClientId> <RequesId> h2_task(522-123): adding request filters https://<MyHost>/mandanten/stzh/dossiers/1001001/uebersicht
...
2022-05-20 15:19:48.606991 http2:debug 10.16.12.58:58611 AH03067: h2_stream(522-123): RST_STREAM by client, error=8
2022-05-20 15:19:48.606996 http2:trace1 10.16.12.58:58611 h2_mplx(522): mood update, decreasing worker limit to 16
2022-05-20 15:19:48.606999 http2:debug 10.16.12.58:58611 AH03065: h2_stream(522-123,HALF_CLOSED_REMOTE): closing with err=8 cancel
2022-05-20 15:19:48.607002 http2:trace1 10.16.12.58:58611 h2_stream(522-123,HALF_CLOSED_REMOTE): reset, error=8
2022-05-20 15:19:48.607004 http2:trace2 10.16.12.58:58611 h2_stream(522-123,HALF_CLOSED_REMOTE): dispatch event 2
2022-05-20 15:19:48.607008 http2:trace1 10.16.12.58:58611 h2_stream(522-123,HALF_CLOSED_REMOTE): transit to [CLOSED]
2022-05-20 15:19:48.607010 http2:trace1 10.16.12.58:58611 h2_stream(522-123,CLOSED): closing input
2022-05-20 15:19:48.607013 http2:trace2 10.16.12.58:58611 h2_stream(522-123,CLOSED): entered state
2022-05-20 15:19:48.607016 http2:trace2 10.16.12.58:58611 h2_session(522,BUSY,1): fed 13 bytes to nghttp2, 13 read
2022-05-20 15:19:48.607019 http2:trace1 10.16.12.58:58611 h2_session(522): read, NONBLOCK_READ, mode=0, readbytes=65536
2022-05-20 15:19:48.607025 http2:trace1 10.16.12.58:58611 h2_session(522): read
2022-05-20 15:19:48.607028 http2:trace1 10.16.12.58:58611 h2_stream(522-137,HALF_CLOSED_REMOTE): schedule GET https://<MyHost>/rs/v1/kern-aggreg/mandanten/stzh/cockpits/benutzer/EINSTIEG_COCKPIT chunked=0
2022-05-20 15:19:48.607038 http2:trace1 10.16.12.58:58611 h2_stream(522-137,HALF_CLOSED_REMOTE): process, added to q
2022-05-20 15:19:48.607040 http2:trace2 10.16.12.58:58611 h2_mplx(522): dispatch events
2022-05-20 15:19:48.607045 http2:debug 10.16.12.58:58611 AH03068: h2_session(522,BUSY,1): sent FRAME[RST_STREAM[length=4, flags=0, stream=123]], frames=98/327 (r/s)
2022-05-20 15:19:48.607068 http2:trace2 10.16.12.58:58611 h2_session(522)-out: h2eos heap[13] flush
2022-05-20 15:19:48.607073 http2:trace2 10.16.12.58:58611 h2_stream(522-123,CLOSED): dispatch event 3
2022-05-20 15:19:48.607076 http2:trace1 10.16.12.58:58611 h2_stream(522-123,CLOSED): transit to [CLEANUP]
2022-05-20 15:19:48.607078 http2:trace2 10.16.12.58:58611 h2_stream(522-123,CLEANUP): entered state
2022-05-20 15:19:48.607081 http2:trace2 10.16.12.58:58611 h2_stream(522-123,CLEANUP): cleanup
...
2022-05-20 15:21:47.620826 http2:trace1 10.16.12.58:58611 h2_task(522-123): output_filter called
2022-05-20 15:21:47.620835 http2:trace2 10.16.12.58:58611 bb_dump(522-123): h2_task send_out(MMAP[2557])
2022-05-20 15:21:47.620840 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=1,buf=0): send_out(before)
2022-05-20 15:21:47.620845 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=2557): send_out(after)
2022-05-20 15:21:47.620848 http2:trace2 10.16.12.58:58611 h2_task(522-123): send_out done
2022-05-20 15:21:47.620851 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): buffered=1
2022-05-20 15:21:47.620854 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): secondary_out leave
2022-05-20 15:21:47.620915 http2:trace1 10.16.12.58:58611 h2_task(522-123): output_filter called
2022-05-20 15:21:47.620919 http2:trace2 10.16.12.58:58611 bb_dump(522-123): h2_task send_out(MMAP[582])
2022-05-20 15:21:47.620922 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=2557): send_out(before)
2022-05-20 15:21:47.620925 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3139): send_out(after)
2022-05-20 15:21:47.620927 http2:trace2 10.16.12.58:58611 h2_task(522-123): send_out done
2022-05-20 15:21:47.620930 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): buffered=1
2022-05-20 15:21:47.620932 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): secondary_out leave
2022-05-20 15:21:47.620939 http2:trace1 10.16.12.58:58611 h2_task(522-123): output_filter called
2022-05-20 15:21:47.620943 http2:trace2 10.16.12.58:58611 bb_dump(522-123): h2_task send_out(POOL[45] MMAP[5])
2022-05-20 15:21:47.620945 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3139): send_out(before)
2022-05-20 15:21:47.620948 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3189): send_out(after)
2022-05-20 15:21:47.620951 http2:trace2 10.16.12.58:58611 h2_task(522-123): send_out done
2022-05-20 15:21:47.620953 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): buffered=1
2022-05-20 15:21:47.620955 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): secondary_out leave
2022-05-20 15:21:47.621068 http2:trace1 10.16.12.58:58611 h2_task(522-123): output_filter called
2022-05-20 15:21:47.621071 http2:trace2 10.16.12.58:58611 bb_dump(522-123): h2_task send_out(POOL[33] MMAP[5])
2022-05-20 15:21:47.621073 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3189): send_out(before)
2022-05-20 15:21:47.621076 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3227): send_out(after)
2022-05-20 15:21:47.621078 http2:trace2 10.16.12.58:58611 h2_task(522-123): send_out done
2022-05-20 15:21:47.621081 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): buffered=1
2022-05-20 15:21:47.621083 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): secondary_out leave
2022-05-20 15:21:47.621088 http2:trace1 10.16.12.58:58611 h2_task(522-123): output_filter called
2022-05-20 15:21:47.621090 http2:trace2 10.16.12.58:58611 bb_dump(522-123): h2_task send_out(POOL[27] MMAP[0])
2022-05-20 15:21:47.621093 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3227): send_out(before)
2022-05-20 15:21:47.621096 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3254): send_out(after)
2022-05-20 15:21:47.621098 http2:trace2 10.16.12.58:58611 h2_task(522-123): send_out done
2022-05-20 15:21:47.621101 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): buffered=1
2022-05-20 15:21:47.621103 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): secondary_out leave
2022-05-20 15:21:47.621109 http2:trace1 10.16.12.58:58611 h2_task(522-123): output_filter called
2022-05-20 15:21:47.621112 http2:trace2 10.16.12.58:58611 bb_dump(522-123): h2_task send_out(POOL[74] MMAP[152])
2022-05-20 15:21:47.621114 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3254): send_out(before)
2022-05-20 15:21:47.621118 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3480): send_out(after)
2022-05-20 15:21:47.621120 http2:trace2 10.16.12.58:58611 h2_task(522-123): send_out done
2022-05-20 15:21:47.621123 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): buffered=1
2022-05-20 15:21:47.621125 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): secondary_out leave
2022-05-20 15:21:47.621140 http2:trace1 10.16.12.58:58611 h2_task(522-123): output_filter called
2022-05-20 15:21:47.621143 http2:trace2 10.16.12.58:58611 bb_dump(522-123): h2_task send_out(POOL[45] MMAP[7])
2022-05-20 15:21:47.621145 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3480): send_out(before)
2022-05-20 15:21:47.621148 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3532): send_out(after)
2022-05-20 15:21:47.621151 http2:trace2 10.16.12.58:58611 h2_task(522-123): send_out done
2022-05-20 15:21:47.621153 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): buffered=1
2022-05-20 15:21:47.621155 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): secondary_out leave
2022-05-20 15:21:47.621160 http2:trace1 10.16.12.58:58611 h2_task(522-123): output_filter called
2022-05-20 15:21:47.621162 http2:trace2 10.16.12.58:58611 bb_dump(522-123): h2_task send_out(POOL[33] MMAP[7])
2022-05-20 15:21:47.621165 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3532): send_out(before)
2022-05-20 15:21:47.621168 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3572): send_out(after)
2022-05-20 15:21:47.621170 http2:trace2 10.16.12.58:58611 h2_task(522-123): send_out done
2022-05-20 15:21:47.621172 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): buffered=1
2022-05-20 15:21:47.621175 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): secondary_out leave
2022-05-20 15:21:47.621179 http2:trace1 10.16.12.58:58611 h2_task(522-123): output_filter called
2022-05-20 15:21:47.621182 http2:trace2 10.16.12.58:58611 bb_dump(522-123): h2_task send_out(POOL[27] MMAP[0])
2022-05-20 15:21:47.621184 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3572): send_out(before)
2022-05-20 15:21:47.621187 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3599): send_out(after)
2022-05-20 15:21:47.621189 http2:trace2 10.16.12.58:58611 h2_task(522-123): send_out done
2022-05-20 15:21:47.621192 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): buffered=1
2022-05-20 15:21:47.621194 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): secondary_out leave
2022-05-20 15:21:47.621199 http2:trace1 10.16.12.58:58611 h2_task(522-123): output_filter called
2022-05-20 15:21:47.621201 http2:trace2 10.16.12.58:58611 bb_dump(522-123): h2_task send_out(POOL[74] MMAP[22])
2022-05-20 15:21:47.621204 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3599): send_out(before)
2022-05-20 15:21:47.621207 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3695): send_out(after)
2022-05-20 15:21:47.621210 http2:trace2 10.16.12.58:58611 h2_task(522-123): send_out done
2022-05-20 15:21:47.621212 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): buffered=1
2022-05-20 15:21:47.621214 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): secondary_out leave
2022-05-20 15:21:47.621218 http2:trace1 10.16.12.58:58611 h2_task(522-123): output_filter called
2022-05-20 15:21:47.621221 http2:trace2 10.16.12.58:58611 bb_dump(522-123): h2_task send_out(MMAP[436] EOS)
2022-05-20 15:21:47.621224 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=0,aborted=0,empty=0,buf=3695): send_out(before)
2022-05-20 15:21:47.621228 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=1,aborted=0,empty=0,buf=4131): send_out(after)
2022-05-20 15:21:47.621230 http2:trace2 10.16.12.58:58611 h2_task(522-123): send_out done
2022-05-20 15:21:47.621233 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): buffered=1
2022-05-20 15:21:47.621235 http2:debug 10.16.12.58:58611 AH03348: h2_task(522-123): open output to GET <MyHost> /sse/v1/kern-aggreg/mandanten/stzh/dossiers/1001001/DOSSIERMENUUPDATEEVENT
2022-05-20 15:21:47.621239 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): secondary_out leave
2022-05-20 15:21:47.621259 http2:trace2 10.16.12.58:58611 bb_dump(522-123): h2_task send_out(EOR)
2022-05-20 15:21:47.621263 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=1,aborted=1,empty=1,buf=0): send_out(before)
2022-05-20 15:21:47.621267 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=1,aborted=1,empty=0,buf=0): send_out(after)
2022-05-20 15:21:47.621270 http2:debug 10.16.12.58:58611 h2_task(522-123): send_out (0 bytes)
2022-05-20 15:21:47.621273 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): buffered=1
2022-05-20 15:21:47.621276 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): secondary_out leave
2022-05-20 15:21:47.621540 http2:trace2 10.16.12.58:58611 bb_dump(522-123): h2_task send_out(FLUSH)
2022-05-20 15:21:47.621543 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=1,aborted=1,empty=1,buf=0): send_out(before)
2022-05-20 15:21:47.621547 http2:trace2 10.16.12.58:58611 beam(522-123,output,closed=1,aborted=1,empty=0,buf=0): send_out(after)
2022-05-20 15:21:47.621549 http2:debug 10.16.12.58:58611 h2_task(522-123): send_out (0 bytes)
2022-05-20 15:21:47.621552 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): buffered=1
2022-05-20 15:21:47.621554 http2:trace2 10.16.12.58:58611 h2_secondary_out(522-123): secondary_out leave
2022-05-20 15:21:47.621558 http2:trace1 10.16.12.58:58611 h2_task(522-123): processing done
2022-05-20 15:21:47.621561 http2:trace1 10.16.12.58:58611 h2_mplx(522): task(522-123) done
2022-05-20 15:21:47.621565 http2:trace2 10.16.12.58:58611 h2_mplx(522-123): request done, 120104.032000 ms elapsed
2022-05-20 15:21:47.621570 http2:trace2 10.16.12.58:58611 h2_stream(522-123,CLEANUP): task_done, in hold
What I still find very odd: Only the first canceled SSE ends up in the state h2_stream(772-13,CLEANUP): destroy and all the other end up in task_done, in hold.
This leeds me to two more questions: Why does a RST by the client not lead to the stream to get destroyed immediately (ending up in h2_stream(SESSION-STREAM,CLEANUP): destroy) and why is there always this gap in time after h2_stream(SESSION-STREAM,CLEANUP): cleanup which can be manipulated by manipulation of the TimeOut? Maybe I have a wrong understanding, but if that behaviour would be changed so that a reset would immediately lead to h2_stream(SESSION-STREAM,CLEANUP): destroy then the worker would be free to work on newly incomming streams and we would not even care about the reduction to 16 workers since all workers would be immediately freed up after receiving the RST. IMHO this would be even better then disabling the mood downgrade. Does that make sense or did I get something completely wrong here?
Thanks again for your help!
I did not receive any logs in my email (spam checked as well), btw.
The problem is that for Apache, an SSE request occupies a worker while running. The SSE does nothing for 2 minutes (as seen in your log) if there are no events. Since worker threads cannot be just "killed", it takes these 2 minutes for the worker to detect that it has been cancelled.
What sort of SSE configuration/implementation do you use? Is the SSE proxied by apache?
Yeah you are absolutely right. I just saw the message did not get sent for some reason ("Delivery expired"), just got the notification in my inbox on saturday. I will try again. Payload is not that big tough, last log file I sent you was bigger.
The problem is that for Apache, an SSE request occupies a worker while running.... Ok, got it. So the only way to go is basically disable the mood downgrade (+ maybe increase the max workers so there are enought workers to handle requests if many workers are blocked by cancelled SSEs + decrease the timeout so blocking is not that long, originally we had a timeout of 5 mins).
what sort of SSE configuration/implementation do you use? you are probably asking about how the application is implementing SSEs? Unfortunately; I am only the proxy guy, not the application person. Which kind of anseres your second question: Yes, the SSE is proxied by apache and we also did some configuration on this Apache to make it work, sort of. From this point on it might get complicated to discribe what we did exactly. If you would not mind I would propose a clarifiying call via Skype etc.
All the best
I hope in the meantime you received our logs, we tried with an other email address from our side.
In the meantime, the application developers changed tha application a bit: Now, the moment you open an SSE, there will be some (meaningless) response from the server immediately. So now, we do not run into the mood downgrade issue just as you predicted, since the RST Frame comes after the response from the server. Now we need to open maxWorkers SSE to get stalled, which in itself would be ok for us. Unfortunately we yet have another problem: As I already mentioned, the SSEs are proxied by Apache. So the communication between the client and Apache is indeed in h2, but then the connection from Apache to the actual application server is in http/1.1. So for each of the SSE requests , there is one open TCP connection from Apache to the application server. This is not feasible for us. You wrote the following:
"The problem is that for Apache, an SSE request occupies a worker while running. The SSE does nothing for 2 minutes (as seen in your log) if there are no events. Since worker threads cannot be just "killed", it takes these 2 minutes for the worker to detect that it has been cancelled."
One more question arises: Did I understand it correctly that if there are events in the SSE sent by the backend, the worker will then detect that it has been canceled? Or will it still remain open for 2 minutes even after receiving an event? Asking because there is a plan to implement an event heartbeat in the application.
I hope in the meantime you received our logs, we tried with an other email address from our side.
I found the access information in my spam folder, but the download gives a 500 page on your server. It seems a bit cursed.
In the meantime, the application developers changed tha application a bit: Now, the moment you open an SSE, there will be some (meaningless) response from the server immediately. So now, we do not run into the mood downgrade issue just as you predicted, since the RST Frame comes after the response from the server. Now we need to open maxWorkers SSE to get stalled, which in itself would be ok for us. Unfortunately we yet have another problem: As I already mentioned, the SSEs are proxied by Apache. So the communication between the client and Apache is indeed in h2, but then the connection from Apache to the actual application server is in http/1.1. So for each of the SSE requests , there is one open TCP connection from Apache to the application server. This is not feasible for us. You wrote the following:
Sending the response headers immediately is definitely a good idea.
"The problem is that for Apache, an SSE request occupies a worker while running. The SSE does nothing for 2 minutes (as seen in your log) if there are no events. Since worker threads cannot be just "killed", it takes these 2 minutes for the worker to detect that it has been cancelled."
One more question arises: Did I understand it correctly that if there are events in the SSE sent by the backend, the worker will then detect that it has been canceled? Or will it still remain open for 2 minutes even after receiving an event? Asking because there is a plan to implement an event heartbeat in the application.
Yes, when an SSE event is being forwarded to the client, the code will detect that the request has been cancelled and tear everything down. Since the http/1.1 backend connection is then in an incomplete response, it will close the connection to the backend.
To trigger this, I would recommend to send a "dummy" event to the client every few seconds.
SSE events on top of http are tricky, as you found out, as http and its implementations are not designed for responses that take "forever". See for example the warning on the Mozilla page. Although it says "unless you use http/2", the h2 on the connection to the browser alone is not sufficient.
Other open source servers seem to run into similar problems, see for example this.
I found the access information in my spam folder, but the download gives a 500 page on your server. It seems a bit cursed.
Probably now the download link expired. I am not a superstitious person but...
To trigger this, I would recommend to send a "dummy" event to the client every few seconds.
We did it and now it works! Thanks a lot for you valuable help!