search

icing / mod_h2

HTTP/2 module for Apache httpd
https://icing.github.io/mod_h2/
Apache License 2.0
256 stars 41 forks source link

Busy H2 Session causes infinite loop #208

Closed wif70068 closed 3 years ago

wif70068 commented 3 years ago

Hi, I hope you can help me. For a few months now I get requests which keep being open without an answer for multiple minutes - longer than any timeout in Apache or the nginx load balancer. My version of Apache is 2.4.46, my version of mod_httpd2 is 1.15.9 (I downgraded from 1.15.16 in trying fixing this issue - subjectively there are fewer instances now where the infinite loop occurs).

I use Centos 7 and OpenSSL 1.0.2k-fips

The infinite loop looks like this:

[Sun Jan 31 11:46:46.496406 2021] [http2:trace3] [pid 3506:tid 140223283418880] h2_session.c(2320): [client [ip]:57166] h2_session: wait for data, 200000 micros [Sun Jan 31 11:46:46.636045 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(612): [client [ip]:58246] h2_mplx(74): trywait on data for 200.000000 ms) [Sun Jan 31 11:46:46.636077 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,BUSY,4): transit [WAIT] -- wait cycle --> [BUSY] [Sun Jan 31 11:46:46.636085 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=131072 [Sun Jan 31 11:46:46.636109 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read [Sun Jan 31 11:46:46.636119 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events [Sun Jan 31 11:46:46.636125 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1824): [client [ip]:58246] h2_session(74,BUSY,4): NO_IO event, 4 streams open [Sun Jan 31 11:46:46.636130 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,WAIT,4): transit [BUSY] -- no io --> [WAIT] [Sun Jan 31 11:46:46.636133 2021] [http2:trace3] [pid 3506:tid 140223291811584] h2_session.c(2320): [client [ip]:58246] h2_session: wait for data, 200000 micros [Sun Jan 31 11:46:46.696542 2021] [http2:trace2] [pid 3506:tid 140223283418880] h2_mplx.c(612): [client [ip]:57166] h2_mplx(75): trywait on data for 200.000000 ms) [Sun Jan 31 11:46:46.696581 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_session.c(1698): [client [ip]:57166] AH03078: h2_session(75,BUSY,1): transit [WAIT] -- wait cycle --> [BUSY] [Sun Jan 31 11:46:46.696591 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_filter.c(146): [client [ip]:57166] h2_session(75): read, NONBLOCK_READ, mode=0, readbytes=65536 [Sun Jan 31 11:46:46.696626 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:57166] h2_session(75): read [Sun Jan 31 11:46:46.696637 2021] [http2:trace2] [pid 3506:tid 140223283418880] h2_mplx.c(1103): [client [ip]:57166] h2_mplx(75): dispatch events [Sun Jan 31 11:46:46.696643 2021] [http2:trace2] [pid 3506:tid 140223283418880] h2_session.c(1824): [client [ip]:57166] h2_session(75,BUSY,1): NO_IO event, 1 streams open [Sun Jan 31 11:46:46.696648 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_session.c(1698): [client [ip]:57166] AH03078: h2_session(75,WAIT,1): transit [BUSY] -- no io --> [WAIT] [Sun Jan 31 11:46:46.696652 2021] [http2:trace3] [pid 3506:tid 140223283418880] h2_session.c(2320): [client [ip]:57166] h2_session: wait for data, 200000 micros [Sun Jan 31 11:46:46.836200 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(612): [client [ip]:58246] h2_mplx(74): trywait on data for 200.000000 ms) [Sun Jan 31 11:46:46.836227 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,BUSY,4): transit [WAIT] -- wait cycle --> [BUSY] [Sun Jan 31 11:46:46.836235 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=131072 [Sun Jan 31 11:46:46.836258 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read [Sun Jan 31 11:46:46.836267 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events [Sun Jan 31 11:46:46.836274 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1824): [client [ip]:58246] h2_session(74,BUSY,4): NO_IO event, 4 streams open [Sun Jan 31 11:46:46.836279 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,WAIT,4): transit [BUSY] -- no io --> [WAIT]

Eventually the connection is closed:

[Sun Jan 31 11:46:47.096947 2021] [ssl:info] [pid 3506:tid 140223283418880] (70014)End of file found: [client [ip]:57166] AH01991: SSL input filter read failed. [Sun Jan 31 11:46:47.096953 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_filter.c(191): (70014)End of file found: [client [ip]:57166] h2_session(75): read [Sun Jan 31 11:46:47.096956 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_session.c(1611): (70014)End of file found: [client [ip]:57166] h2_session(75,BUSY,1): input gone [Sun Jan 31 11:46:47.096960 2021] [http2:debug] [pid 3506:tid 140223283418880] h2_session.c(1788): [client [ip]:57166] AH03401: h2_session(75,BUSY,1): conn error -> shutdown [Sun Jan 31 11:46:47.096968 2021] [http2:debug] [pid 3506:tid 140223283418880] h2_session.c(593): [client [ip]:57166] AH03068: h2_session(75,BUSY,1): sent FRAME[GOAWAY[error=0, reason='', last_stream=3]], frames=5/6 (r/s) [Sun Jan 31 11:46:47.096978 2021] [http2:trace2] [pid 3506:tid 140223283418880] h2_conn_io.c(128): [client [ip]:57166] h2_session(75)-out: heap[17] flush [Sun Jan 31 11:46:47.097027 2021] [http2:debug] [pid 3506:tid 140223283418880] h2_session.c(753): [client [ip]:57166] AH03069: h2_session(75,BUSY,1): sent GOAWAY, err=0, msg= [Sun Jan 31 11:46:47.097035 2021] [http2:debug] [pid 3506:tid 140223283418880] h2_session.c(1698): [client [ip]:57166] AH03078: h2_session(75,DONE,1): transit [BUSY] -- local goaway --> [DONE] [Sun Jan 31 11:46:47.097039 2021] [http2:trace2] [pid 3506:tid 140223283418880] h2_mplx.c(1103): [client [ip]:57166] h2_mplx(75): dispatch events [Sun Jan 31 11:46:47.097044 2021] [http2:trace3] [pid 3506:tid 140223283418880] h2_session.c(2367): [client [ip]:57166] h2_session(75,DONE,1): process returns [Sun Jan 31 11:46:47.097047 2021] [http2:debug] [pid 3506:tid 140223283418880] h2_conn.c(219): (70014)End of file found: [client [ip]:57166] AH03045: h2_session(75,DONE,1): process, closing conn [Sun Jan 31 11:46:47.097052 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_session.c(2385): [client [ip]:57166] h2_session(75,DONE,1): pre_close [Sun Jan 31 11:46:47.097055 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_session.c(763): [client [ip]:57166] h2_session(75,DONE,1): pool_cleanup [Sun Jan 31 11:46:47.097058 2021] [http2:debug] [pid 3506:tid 140223283418880] h2_session.c(1698): [client [ip]:57166] AH03078: h2_session(75,CLEANUP,1): transit [DONE] -- pre_close --> [CLEANUP] [Sun Jan 31 11:46:47.097062 2021] [http2:trace2] [pid 3506:tid 140223283418880] h2_mplx.c(423): [client [ip]:57166] h2_mplx(75): start release [Sun Jan 31 11:46:47.097065 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_mplx.c(442): [client [ip]:57166] h2_mplx(75): release, 1/0/0 streams (total/hold/purge), 1 active tasks [Sun Jan 31 11:46:47.097069 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_stream.c(603): [client [ip]:57166] h2_stream(75-1,HALF_CLOSED_REMOTE): reset, error=0 [Sun Jan 31 11:46:47.097072 2021] [http2:trace2] [pid 3506:tid 140223283418880] h2_stream.c(344): [client [ip]:57166] h2_stream(75-1,HALF_CLOSED_REMOTE): dispatch event 2 [Sun Jan 31 11:46:47.097082 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_stream.c(302): [client [ip]:57166] h2_stream(75-1,HALF_CLOSED_REMOTE): transit to [CLOSED] [Sun Jan 31 11:46:47.097085 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_stream.c(211): [client [ip]:57166] h2_stream(75-1,CLOSED): closing input [Sun Jan 31 11:46:47.097088 2021] [http2:trace2] [pid 3506:tid 140223283418880] h2_stream.c(344): [client [ip]:57166] h2_stream(75-1,CLOSED): dispatch event 3 [Sun Jan 31 11:46:47.097091 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_stream.c(302): [client [ip]:57166] h2_stream(75-1,CLOSED): transit to [CLEANUP] [Sun Jan 31 11:46:47.236561 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(612): [client [ip]:58246] h2_mplx(74): trywait on data for 200.000000 ms) [Sun Jan 31 11:46:47.236587 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,BUSY,4): transit [WAIT] -- wait cycle --> [BUSY] [Sun Jan 31 11:46:47.236595 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=131072 [Sun Jan 31 11:46:47.236636 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_filter.c(94): [client [ip]:58246] bb_dump(74): RAW_in(TRANSIENT[13]) [Sun Jan 31 11:46:47.236645 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(341): [client [ip]:58246] AH03066: h2_session(74,BUSY,4): recv FRAME[RST_STREAM[length=4, flags=0, stream=7]], frames=9/5 (r/s) [Sun Jan 31 11:46:47.236649 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(390): [client [ip]:58246] AH03067: h2_stream(74-7): RST_STREAM by client, error=8 [Sun Jan 31 11:46:47.236654 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_mplx.c(1012): [client [ip]:58246] h2_mplx(74): mood update, decreasing worker limit to 4 [Sun Jan 31 11:46:47.236659 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(267): [client [ip]:58246] AH03065: h2_stream(74-7,HALF_CLOSED_REMOTE): closing with err=8 cancel [Sun Jan 31 11:46:47.236663 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(603): [client [ip]:58246] h2_stream(74-7,HALF_CLOSED_REMOTE): reset, error=8 [Sun Jan 31 11:46:47.236666 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_stream.c(344): [client [ip]:58246] h2_stream(74-7,HALF_CLOSED_REMOTE): dispatch event 2 [Sun Jan 31 11:46:47.236671 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(302): [client [ip]:58246] h2_stream(74-7,HALF_CLOSED_REMOTE): transit to [CLOSED] [Sun Jan 31 11:46:47.236675 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(211): [client [ip]:58246] h2_stream(74-7,CLOSED): closing input [Sun Jan 31 11:46:47.236678 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1954): [client [ip]:58246] h2_stream(74-7,CLOSED): entered state [Sun Jan 31 11:46:47.236684 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_filter.c(65): [client [ip]:58246] h2_session(74,BUSY,3): fed 13 bytes to nghttp2, 13 read [Sun Jan 31 11:46:47.236688 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=131072 [Sun Jan 31 11:46:47.236694 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_filter.c(94): [client [ip]:58246] bb_dump(74): RAW_in(TRANSIENT[13]) [Sun Jan 31 11:46:47.236698 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(341): [client [ip]:58246] AH03066: h2_session(74,BUSY,3): recv FRAME[RST_STREAM[length=4, flags=0, stream=5]], frames=10/5 (r/s) [Sun Jan 31 11:46:47.236701 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(390): [client [ip]:58246] AH03067: h2_stream(74-5): RST_STREAM by client, error=8 [Sun Jan 31 11:46:47.236711 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(267): [client [ip]:58246] AH03065: h2_stream(74-5,HALF_CLOSED_REMOTE): closing with err=8 cancel [Sun Jan 31 11:46:47.236720 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(603): [client [ip]:58246] h2_stream(74-5,HALF_CLOSED_REMOTE): reset, error=8 [Sun Jan 31 11:46:47.236724 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_stream.c(344): [client [ip]:58246] h2_stream(74-5,HALF_CLOSED_REMOTE): dispatch event 2 [Sun Jan 31 11:46:47.236727 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(302): [client [ip]:58246] h2_stream(74-5,HALF_CLOSED_REMOTE): transit to [CLOSED] [Sun Jan 31 11:46:47.236731 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(211): [client [ip]:58246] h2_stream(74-5,CLOSED): closing input [Sun Jan 31 11:46:47.236734 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1954): [client [ip]:58246] h2_stream(74-5,CLOSED): entered state [Sun Jan 31 11:46:47.236738 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_filter.c(65): [client [ip]:58246] h2_session(74,BUSY,2): fed 13 bytes to nghttp2, 13 read [Sun Jan 31 11:46:47.236741 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=131072 [Sun Jan 31 11:46:47.236747 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_filter.c(94): [client [ip]:58246] bb_dump(74): RAW_in(TRANSIENT[13]) [Sun Jan 31 11:46:47.236752 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(341): [client [ip]:58246] AH03066: h2_session(74,BUSY,2): recv FRAME[RST_STREAM[length=4, flags=0, stream=1]], frames=11/5 (r/s) [Sun Jan 31 11:46:47.236755 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(390): [client [ip]:58246] AH03067: h2_stream(74-1): RST_STREAM by client, error=8 [Sun Jan 31 11:46:47.236759 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(267): [client [ip]:58246] AH03065: h2_stream(74-1,HALF_CLOSED_REMOTE): closing with err=8 cancel [Sun Jan 31 11:46:47.236762 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(603): [client [ip]:58246] h2_stream(74-1,HALF_CLOSED_REMOTE): reset, error=8 [Sun Jan 31 11:46:47.236765 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_stream.c(344): [client [ip]:58246] h2_stream(74-1,HALF_CLOSED_REMOTE): dispatch event 2 [Sun Jan 31 11:46:47.236768 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(302): [client [ip]:58246] h2_stream(74-1,HALF_CLOSED_REMOTE): transit to [CLOSED] [Sun Jan 31 11:46:47.236772 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(211): [client [ip]:58246] h2_stream(74-1,CLOSED): closing input [Sun Jan 31 11:46:47.236775 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1954): [client [ip]:58246] h2_stream(74-1,CLOSED): entered state [Sun Jan 31 11:46:47.236780 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_filter.c(65): [client [ip]:58246] h2_session(74,BUSY,1): fed 13 bytes to nghttp2, 13 read [Sun Jan 31 11:46:47.236784 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=131072 [Sun Jan 31 11:46:47.236789 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_filter.c(94): [client [ip]:58246] bb_dump(74): RAW_in(TRANSIENT[13]) [Sun Jan 31 11:46:47.236793 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(341): [client [ip]:58246] AH03066: h2_session(74,BUSY,1): recv FRAME[RST_STREAM[length=4, flags=0, stream=3]], frames=12/5 (r/s) [Sun Jan 31 11:46:47.236796 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(390): [client [ip]:58246] AH03067: h2_stream(74-3): RST_STREAM by client, error=8 [Sun Jan 31 11:46:47.236801 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(267): [client [ip]:58246] AH03065: h2_stream(74-3,HALF_CLOSED_REMOTE): closing with err=8 cancel [Sun Jan 31 11:46:47.236805 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(603): [client [ip]:58246] h2_stream(74-3,HALF_CLOSED_REMOTE): reset, error=8 [Sun Jan 31 11:46:47.236808 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_stream.c(344): [client [ip]:58246] h2_stream(74-3,HALF_CLOSED_REMOTE): dispatch event 2 [Sun Jan 31 11:46:47.236811 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(302): [client [ip]:58246] h2_stream(74-3,HALF_CLOSED_REMOTE): transit to [CLOSED] [Sun Jan 31 11:46:47.236814 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(211): [client [ip]:58246] h2_stream(74-3,CLOSED): closing input [Sun Jan 31 11:46:47.236817 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1954): [client [ip]:58246] h2_stream(74-3,CLOSED): entered state [Sun Jan 31 11:46:47.236821 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_filter.c(65): [client [ip]:58246] h2_session(74,BUSY,0): fed 13 bytes to nghttp2, 13 read [Sun Jan 31 11:46:47.236824 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=131072 [Sun Jan 31 11:46:47.236832 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read [Sun Jan 31 11:46:47.236841 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events [Sun Jan 31 11:46:47.236849 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(593): [client [ip]:58246] AH03068: h2_session(74,BUSY,0): sent FRAME[RST_STREAM[length=4, flags=0, stream=7]], frames=13/6 (r/s) [Sun Jan 31 11:46:47.236853 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(593): [client [ip]:58246] AH03068: h2_session(74,BUSY,0): sent FRAME[RST_STREAM[length=4, flags=0, stream=5]], frames=13/7 (r/s) [Sun Jan 31 11:46:47.236857 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(593): [client [ip]:58246] AH03068: h2_session(74,BUSY,0): sent FRAME[RST_STREAM[length=4, flags=0, stream=1]], frames=13/8 (r/s) [Sun Jan 31 11:46:47.236861 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(593): [client [ip]:58246] AH03068: h2_session(74,BUSY,0): sent FRAME[RST_STREAM[length=4, flags=0, stream=3]], frames=13/9 (r/s) [Sun Jan 31 11:46:47.236867 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_conn_io.c(128): [client [ip]:58246] h2_session(74)-out: h2eos h2eos h2eos h2eos heap[52] flush [Sun Jan 31 11:46:47.236873 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_stream.c(344): [client [ip]:58246] h2_stream(74-7,CLOSED): dispatch event 3 [Sun Jan 31 11:46:47.236877 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(302): [client [ip]:58246] h2_stream(74-7,CLOSED): transit to [CLEANUP] [Sun Jan 31 11:46:47.236880 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1954): [client [ip]:58246] h2_stream(74-7,CLEANUP): entered state [Sun Jan 31 11:46:47.236883 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(490): [client [ip]:58246] h2_stream(74-7,CLEANUP): cleanup [Sun Jan 31 11:46:47.236889 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_stream.c(344): [client [ip]:58246] h2_stream(74-5,CLOSED): dispatch event 3 [Sun Jan 31 11:46:47.236892 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(302): [client [ip]:58246] h2_stream(74-5,CLOSED): transit to [CLEANUP] [Sun Jan 31 11:46:47.236895 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1954): [client [ip]:58246] h2_stream(74-5,CLEANUP): entered state [Sun Jan 31 11:46:47.236900 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(490): [client [ip]:58246] h2_stream(74-5,CLEANUP): cleanup [Sun Jan 31 11:46:47.236905 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_stream.c(344): [client [ip]:58246] h2_stream(74-1,CLOSED): dispatch event 3 [Sun Jan 31 11:46:47.236908 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(302): [client [ip]:58246] h2_stream(74-1,CLOSED): transit to [CLEANUP] [Sun Jan 31 11:46:47.236911 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1954): [client [ip]:58246] h2_stream(74-1,CLEANUP): entered state [Sun Jan 31 11:46:47.236914 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(490): [client [ip]:58246] h2_stream(74-1,CLEANUP): cleanup [Sun Jan 31 11:46:47.236918 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_stream.c(344): [client [ip]:58246] h2_stream(74-3,CLOSED): dispatch event 3 [Sun Jan 31 11:46:47.236921 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(302): [client [ip]:58246] h2_stream(74-3,CLOSED): transit to [CLEANUP] [Sun Jan 31 11:46:47.236924 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1954): [client [ip]:58246] h2_stream(74-3,CLEANUP): entered state [Sun Jan 31 11:46:47.236927 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(490): [client [ip]:58246] h2_stream(74-3,CLEANUP): cleanup [Sun Jan 31 11:46:47.236964 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=65536 [Sun Jan 31 11:46:47.236973 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read [Sun Jan 31 11:46:47.236978 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events [Sun Jan 31 11:46:47.236984 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1824): [client [ip]:58246] h2_session(74,BUSY,0): NO_IO event, 0 streams open [Sun Jan 31 11:46:47.236988 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,IDLE,0): transit [BUSY] -- no io (keepalive) --> [IDLE] [Sun Jan 31 11:46:47.236993 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1731): [client [ip]:58246] h2_session(74,IDLE,0): enter idle, keepalive = 5 sec [Sun Jan 31 11:46:47.236996 2021] [http2:trace3] [pid 3506:tid 140223291811584] h2_session.c(2170): [client [ip]:58246] h2_session(74,IDLE,0): nonblock read, 0 streams open [Sun Jan 31 11:46:47.237000 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=65536 [Sun Jan 31 11:46:47.237013 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read [Sun Jan 31 11:46:47.237018 2021] [http2:trace3] [pid 3506:tid 140223291811584] h2_session.c(2367): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74,IDLE,0): process returns [Sun Jan 31 11:46:52.239394 2021] [http2:trace1] [pid 3506:tid 140223275026176] h2_session.c(2385): [client [ip]:58246] h2_session(74,IDLE,0): pre_close [Sun Jan 31 11:46:52.239436 2021] [http2:debug] [pid 3506:tid 140223275026176] h2_session.c(593): [client [ip]:58246] AH03068: h2_session(74,IDLE,0): sent FRAME[GOAWAY[error=0, reason='timeout', last_stream=7]], frames=13/10 (r/s) [Sun Jan 31 11:46:52.239448 2021] [http2:trace2] [pid 3506:tid 140223275026176] h2_conn_io.c(128): [client [ip]:58246] h2_session(76)-out: heap[24] flush [Sun Jan 31 11:46:52.239507 2021] [http2:debug] [pid 3506:tid 140223275026176] h2_session.c(753): [client [ip]:58246] AH03069: h2_session(74,IDLE,0): sent GOAWAY, err=0, msg=timeout [Sun Jan 31 11:46:52.239522 2021] [http2:debug] [pid 3506:tid 140223275026176] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,DONE,0): transit [IDLE] -- local goaway --> [DONE] [Sun Jan 31 11:46:52.239527 2021] [http2:trace1] [pid 3506:tid 140223275026176] h2_session.c(763): [client [ip]:58246] h2_session(74,DONE,0): pool_cleanup [Sun Jan 31 11:46:52.239530 2021] [http2:debug] [pid 3506:tid 140223275026176] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,CLEANUP,0): transit [DONE] -- pre_close --> [CLEANUP] [Sun Jan 31 11:46:52.239533 2021] [http2:trace2] [pid 3506:tid 140223275026176] h2_mplx.c(423): [client [ip]:58246] h2_mplx(74): start release [Sun Jan 31 11:46:52.239538 2021] [http2:trace1] [pid 3506:tid 140223275026176] h2_mplx.c(442): [client [ip]:58246] h2_mplx(74): release, 0/4/0 streams (total/hold/purge), 4 active tasks

Any help would be appreciated!

icing commented 3 years ago

This looks as if the h2 connection handler waits on response information from the thread handling a http request. Do you have mod_reqtimeout configured in your server? With what values?

wif70068 commented 3 years ago

In debugging this problem I added this line RequestReadTimeout handshake=5 header=10 body=30 some days ago within the relevant VirtualHost Config. Before that there was no explicit Directive present. It seemingly made no difference. Is that the right place to put it?

icing commented 3 years ago

It should be, yes. When mod_reqtimeout does not trigger, it means that the request was not submitted to a worker but is hanging on some other limbo state. hmm.

wif70068 commented 3 years ago

Maybe it helps if I tell you what I also already tried without success:

From a client perspective it looks like this: When this problem kicks in, all subsequent requests in all tabs are stalled. Only in private mode is the website still accessible. Presumably because there are no cookies present.

A gdb backtrace looks like this, when the problem is happening:

#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007ff955891218 in apr_thread_cond_timedwait () from /lib64/libapr-1.so.0
#2  0x00007ff94a028109 in h2_mplx_m_out_trywait () from /etc/httpd/modules/mod_http2.so
#3  0x00007ff94a03c8e6 in h2_session_process () from /etc/httpd/modules/mod_http2.so
#4  0x00007ff94a0180c8 in h2_conn_run () from /etc/httpd/modules/mod_http2.so
#5  0x00007ff94a023e85 in h2_h2_process_conn () from /etc/httpd/modules/mod_http2.so
#6  0x000055b9f1dfe730 in ap_run_process_connection ()
#7  0x00007ff94bc5d57a in process_socket () from /etc/httpd/modules/mod_mpm_event.so
#8  0x00007ff94bc5ea24 in worker_thread () from /etc/httpd/modules/mod_mpm_event.so
#9  0x00007ff95565bea5 in start_thread (arg=0x7ff91f7fe700) at pthread_create.c:307
#10 0x00007ff95518096d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
icing commented 3 years ago

Looking at your logs, I see:

[Sun Jan 31 11:46:47.096956 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_session.c(1611): (70014)End of file found: [client [ip]:57166] h2_session(75,BUSY,1): input gone
[Sun Jan 31 11:46:47.096960 2021] [http2:debug] [pid 3506:tid 140223283418880] h2_session.c(1788): [client [ip]:57166] AH03401: h2_session(75,BUSY,1): conn error -> shutdown
[Sun Jan 31 11:46:47.096968 2021] [http2:debug] [pid 3506:tid 140223283418880] h2_session.c(593): [client [ip]:57166] AH03068: h2_session(75,BUSY,1): sent FRAME[GOAWAY[error=0, reason='', last_stream=3]], frames=5/6 (r/s)

Which says the following:

Since you are able to get detailed traces, I would look if there was a stream 5 and what resource it requested. That seems to be the one that is causing the hang.

Also in another part of the log:

[Sun Jan 31 11:46:52.239538 2021] [http2:trace1] [pid 3506:tid 140223275026176] h2_mplx.c(442): [client [ip]:58246] h2_mplx(74): release, 0/4/0 streams (total/hold/purge), 4 active tasks

This is where the connection timed out on the server side (Timeout value) and on shutting down the connection it logged that 4 tasks (aka requests) where active. This would indicate very long running requests in your server that do not deliver a response.

As for the stalling: apache has a max number of requests that are 'active' (being worked on) per connection. It will take in more requests from the client, but it will not start processing them until the running ones are done.

This limit gets raised when requests are processed in a timely manner. This is a DoS protection against clients spamming the server with requests, but never or only slowly reading the responses.

When you open a browser tab in private mode, the browser opens a new connection to the server and not try to send more requests on the same, stalled connection.

Hope this helps.

wif70068 commented 3 years ago

I'm not exactly sure what you want me to do, but I got the last request made before the infinite loop, and it was made to my matomo VirtualHost. It looks like a 10 minute timeout. What is interesting right now, I set SSLSessionCache from shmcb:/run/httpd/sslcache(512000) to none around the time I wrote this ticket. Since then there were zero instances of this infinite loop occuring. This may be a fluke because I had that happen before that it was stable for one or two days before the problem resurfaced, but it's still interesting. Could it be permissions/selinux issues with that sslcache-file? Because I never saw it appearing.

Regarding the log data: Do you think it is worth turning off the matomo VirtualHost or am I interpreting the data wrong?

[Sun Jan 31 11:36:46.787136 2021] [http2:trace3] [pid 3506:tid 140223283418880] h2_session.c(2320): [client [ip]:57166] h2_session: wait for data, 10240 micros
[Sun Jan 31 11:36:46.787138 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1954): [client [ip]:58246] h2_stream(74-5,OPEN): entered state
[Sun Jan 31 11:36:46.787150 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(302): [client [ip]:58246] h2_stream(74-5,OPEN): transit to [HALF_CLOSED_REMOTE]
[Sun Jan 31 11:36:46.787153 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(211): [client [ip]:58246] h2_stream(74-5,HALF_CLOSED_REMOTE): closing input
[Sun Jan 31 11:36:46.787156 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1954): [client [ip]:58246] h2_stream(74-5,HALF_CLOSED_REMOTE): entered state
[Sun Jan 31 11:36:46.787159 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_filter.c(65): [client [ip]:58246] h2_session(74,BUSY,3): fed 263 bytes to nghttp2, 263 read
[Sun Jan 31 11:36:46.787163 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=65536
[Sun Jan 31 11:36:46.787170 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_filter.c(94): [client [ip]:58246] bb_dump(74): RAW_in(TRANSIENT[17])
[Sun Jan 31 11:36:46.787176 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(341): [client [ip]:58246] AH03066: h2_session(74,BUSY,3): recv FRAME[PING[length=8, ack=0, stream=0]], frames=6/3 (r/s)
[Sun Jan 31 11:36:46.787179 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(429): [client [ip]:58246] h2_session(74,BUSY,3): on_frame_rcv PING[length=8, ack=0, stream=0]
[Sun Jan 31 11:36:46.787182 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_filter.c(65): [client [ip]:58246] h2_session(74,BUSY,3): fed 17 bytes to nghttp2, 17 read
[Sun Jan 31 11:36:46.787185 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=65536
[Sun Jan 31 11:36:46.787192 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read
[Sun Jan 31 11:36:46.787197 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_stream.c(585): [client [ip]:58246] h2_stream(74-5,HALF_CLOSED_REMOTE): schedule GET https://[matomo-url] chunked=0
[Sun Jan 31 11:36:46.787207 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_mplx.c(698): [client [ip]:58246] h2_stream(74-5,HALF_CLOSED_REMOTE): process, added to q
[Sun Jan 31 11:36:46.787210 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events
[Sun Jan 31 11:36:46.787216 2021] [http2:debug] [pid 3506:tid 140223291811584] h2_session.c(593): [client [ip]:58246] AH03068: h2_session(74,BUSY,3): sent FRAME[PING[length=8, ack=1, stream=0]], frames=7/4 (r/s)
[Sun Jan 31 11:36:46.787222 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_conn_io.c(128): [client [ip]:58246] h2_session(74)-out: heap[17] flush
[Sun Jan 31 11:36:46.787223 2021] [http2:trace3] [pid 3506:tid 140223592126208] h2_conn.c(289): [client [ip]:58246] h2_stream(74-5): create slave
[Sun Jan 31 11:36:46.787251 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=98304
[Sun Jan 31 11:36:46.787259 2021] [http2:trace3] [pid 3506:tid 140223592126208] h2_conn.c(361): [client [ip]:58246] h2_slave(74-5): created
[Sun Jan 31 11:36:46.787259 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read
[Sun Jan 31 11:36:46.787267 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events
[Sun Jan 31 11:36:46.787267 2021] [http2:trace2] [pid 3506:tid 140223592126208] h2_task.c(495): [client [ip]:58246] h2_slave(74-5), pre_connection, adding filters
[Sun Jan 31 11:36:46.787271 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1824): [client [ip]:58246] h2_session(74,BUSY,3): NO_IO event, 3 streams open
[Sun Jan 31 11:36:46.787275 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,WAIT,3): transit [BUSY] -- no io --> [WAIT]
[Sun Jan 31 11:36:46.787278 2021] [http2:trace1] [pid 3506:tid 140223592126208] h2_task.c(620): [client [ip]:58246] h2_task(74-5): process connection
[Sun Jan 31 11:36:46.787278 2021] [http2:trace3] [pid 3506:tid 140223291811584] h2_session.c(2320): [client [ip]:58246] h2_session: wait for data, 10 micros
[Sun Jan 31 11:36:46.787284 2021] [http2:trace1] [pid 3506:tid 140223592126208] h2_task.c(704): [client [ip]:58246] h2_h2, processing request directly
[Sun Jan 31 11:36:46.787287 2021] [http2:trace1] [pid 3506:tid 140223592126208] h2_task.c(637): [client [ip]:58246] h2_task(74-5): create request_rec
[Sun Jan 31 11:36:46.787301 2021] [http2:trace3] [pid 3506:tid 140223592126208] h2_h2.c(721): [client [ip]:58246] h2_task(74-5): adding request filters, referer: [dev-server]
[Sun Jan 31 11:36:46.787348 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(612): [client [ip]:58246] h2_mplx(74): trywait on data for 0.010000 ms)
[Sun Jan 31 11:36:46.787354 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,BUSY,3): transit [WAIT] -- wait cycle --> [BUSY]
[Sun Jan 31 11:36:46.787357 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=98304
[Sun Jan 31 11:36:46.787364 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read
[Sun Jan 31 11:36:46.787378 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events
[Sun Jan 31 11:36:46.787381 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1824): [client [ip]:58246] h2_session(74,BUSY,3): NO_IO event, 3 streams open
[Sun Jan 31 11:36:46.787384 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,WAIT,3): transit [BUSY] -- no io --> [WAIT]
[Sun Jan 31 11:36:46.787387 2021] [http2:trace3] [pid 3506:tid 140223291811584] h2_session.c(2320): [client [ip]:58246] h2_session: wait for data, 20 micros
[Sun Jan 31 11:36:46.787463 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(612): [client [ip]:58246] h2_mplx(74): trywait on data for 0.020000 ms)
[Sun Jan 31 11:36:46.787467 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,BUSY,3): transit [WAIT] -- wait cycle --> [BUSY]
[Sun Jan 31 11:36:46.787470 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=98304
[Sun Jan 31 11:36:46.787475 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read
[Sun Jan 31 11:36:46.787479 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events
[Sun Jan 31 11:36:46.787482 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1824): [client [ip]:58246] h2_session(74,BUSY,3): NO_IO event, 3 streams open
[Sun Jan 31 11:36:46.787487 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,WAIT,3): transit [BUSY] -- no io --> [WAIT]
[Sun Jan 31 11:36:46.787490 2021] [http2:trace3] [pid 3506:tid 140223291811584] h2_session.c(2320): [client [ip]:58246] h2_session: wait for data, 40 micros
[Sun Jan 31 11:36:46.787614 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(612): [client [ip]:58246] h2_mplx(74): trywait on data for 0.040000 ms)
[Sun Jan 31 11:36:46.787623 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,BUSY,3): transit [WAIT] -- wait cycle --> [BUSY]
[Sun Jan 31 11:36:46.787636 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=98304
[Sun Jan 31 11:36:46.787644 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read
[Sun Jan 31 11:36:46.787649 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events
[Sun Jan 31 11:36:46.787653 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1824): [client [ip]:58246] h2_session(74,BUSY,3): NO_IO event, 3 streams open
[Sun Jan 31 11:36:46.787656 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,WAIT,3): transit [BUSY] -- no io --> [WAIT]
[Sun Jan 31 11:36:46.787659 2021] [http2:trace3] [pid 3506:tid 140223291811584] h2_session.c(2320): [client [ip]:58246] h2_session: wait for data, 80 micros
[Sun Jan 31 11:36:46.787714 2021] [:error] [pid 3506:tid 140223592126208] [client [ip]:58246] [client [ip]] ModSecurity: collection_retrieve_ex: Unable to retrieve collection (name "global", key "global"). Use SecDataDir to define data directory first. [hostname "[matomo-server]"] [uri "/js/"] [unique_id "YBaIPuXSDQYjMl3tkmvgDAAASg8"], referer: [dev-server]
[Sun Jan 31 11:36:46.787778 2021] [:error] [pid 3506:tid 140223592126208] [client [ip]:58246] [client [ip]] ModSecurity: collection_retrieve_ex: Unable to retrieve collection (name "ip", key "[ip]_c8e47cf0bcd013fd8f5053542218d94b79831745"). Use SecDataDir to define data directory first. [hostname "[matomo-server]"] [uri "/js/"] [unique_id "YBaIPuXSDQYjMl3tkmvgDAAASg8"], referer: [dev-server]
[Sun Jan 31 11:36:46.787797 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(612): [client [ip]:58246] h2_mplx(74): trywait on data for 0.080000 ms)
[Sun Jan 31 11:36:46.787806 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,BUSY,3): transit [WAIT] -- wait cycle --> [BUSY]
[Sun Jan 31 11:36:46.787819 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=98304
[Sun Jan 31 11:36:46.787827 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read
[Sun Jan 31 11:36:46.787832 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events
[Sun Jan 31 11:36:46.787836 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1824): [client [ip]:58246] h2_session(74,BUSY,3): NO_IO event, 3 streams open
[Sun Jan 31 11:36:46.787839 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,WAIT,3): transit [BUSY] -- no io --> [WAIT]
[Sun Jan 31 11:36:46.787842 2021] [http2:trace3] [pid 3506:tid 140223291811584] h2_session.c(2320): [client [ip]:58246] h2_session: wait for data, 160 micros
[Sun Jan 31 11:36:46.787894 2021] [ssl:debug] [pid 3506:tid 140223592126208] ssl_engine_kernel.c(422): [client [ip]:58246] AH02034: Subsequent (No.2) HTTPS request received for child 18959 (server [matomo-server]:443), referer: [dev-server]
[Sun Jan 31 11:36:46.787903 2021] [http2:trace1] [pid 3506:tid 140223592126208] h2_task.c(655): [client [ip]:58246] h2_task(74-5): start process_request
[Sun Jan 31 11:36:46.787959 2021] [authz_core:debug] [pid 3506:tid 140223592126208] mod_authz_core.c(818): [client [ip]:58246] AH01626: authorization result of Require all granted: granted, referer: [dev-server]
[Sun Jan 31 11:36:46.787965 2021] [authz_core:debug] [pid 3506:tid 140223592126208] mod_authz_core.c(818): [client [ip]:58246] AH01626: authorization result of <RequireAny>: granted, referer: [dev-server]
[Sun Jan 31 11:36:46.787968 2021] [core:trace3] [pid 3506:tid 140223592126208] request.c(312): [client [ip]:58246] request authorized without authentication by access_checker_ex hook: /js/, referer: [dev-server]
[Sun Jan 31 11:36:46.788064 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(612): [client [ip]:58246] h2_mplx(74): trywait on data for 0.160000 ms)
[Sun Jan 31 11:36:46.788075 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,BUSY,3): transit [WAIT] -- wait cycle --> [BUSY]
[Sun Jan 31 11:36:46.788080 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=98304
[Sun Jan 31 11:36:46.788090 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read
[Sun Jan 31 11:36:46.788095 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events
[Sun Jan 31 11:36:46.788099 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1824): [client [ip]:58246] h2_session(74,BUSY,3): NO_IO event, 3 streams open
[Sun Jan 31 11:36:46.788102 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,WAIT,3): transit [BUSY] -- no io --> [WAIT]
[Sun Jan 31 11:36:46.788105 2021] [http2:trace3] [pid 3506:tid 140223291811584] h2_session.c(2320): [client [ip]:58246] h2_session: wait for data, 320 micros
[Sun Jan 31 11:36:46.788484 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(612): [client [ip]:58246] h2_mplx(74): trywait on data for 0.320000 ms)
[Sun Jan 31 11:36:46.788494 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,BUSY,3): transit [WAIT] -- wait cycle --> [BUSY]
[Sun Jan 31 11:36:46.788498 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=98304
[Sun Jan 31 11:36:46.788506 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read
[Sun Jan 31 11:36:46.788511 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events
[Sun Jan 31 11:36:46.788515 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1824): [client [ip]:58246] h2_session(74,BUSY,3): NO_IO event, 3 streams open
[Sun Jan 31 11:36:46.788518 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,WAIT,3): transit [BUSY] -- no io --> [WAIT]
[Sun Jan 31 11:36:46.788521 2021] [http2:trace3] [pid 3506:tid 140223291811584] h2_session.c(2320): [client [ip]:58246] h2_session: wait for data, 640 micros
[Sun Jan 31 11:36:46.789234 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(612): [client [ip]:58246] h2_mplx(74): trywait on data for 0.640000 ms)
[Sun Jan 31 11:36:46.789244 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,BUSY,3): transit [WAIT] -- wait cycle --> [BUSY]
[Sun Jan 31 11:36:46.789248 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=98304
[Sun Jan 31 11:36:46.789255 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read
[Sun Jan 31 11:36:46.789259 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events
[Sun Jan 31 11:36:46.789262 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1824): [client [ip]:58246] h2_session(74,BUSY,3): NO_IO event, 3 streams open
[Sun Jan 31 11:36:46.789265 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,WAIT,3): transit [BUSY] -- no io --> [WAIT]
[Sun Jan 31 11:36:46.789268 2021] [http2:trace3] [pid 3506:tid 140223291811584] h2_session.c(2320): [client [ip]:58246] h2_session: wait for data, 1280 micros
[Sun Jan 31 11:36:46.790611 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(612): [client [ip]:58246] h2_mplx(74): trywait on data for 1.280000 ms)
[Sun Jan 31 11:36:46.790621 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,BUSY,3): transit [WAIT] -- wait cycle --> [BUSY]
[Sun Jan 31 11:36:46.790625 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=98304
[Sun Jan 31 11:36:46.790633 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read
[Sun Jan 31 11:36:46.790638 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events
[Sun Jan 31 11:36:46.790641 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1824): [client [ip]:58246] h2_session(74,BUSY,3): NO_IO event, 3 streams open
[Sun Jan 31 11:36:46.790644 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,WAIT,3): transit [BUSY] -- no io --> [WAIT]
[Sun Jan 31 11:36:46.790647 2021] [http2:trace3] [pid 3506:tid 140223291811584] h2_session.c(2320): [client [ip]:58246] h2_session: wait for data, 2560 micros
[Sun Jan 31 11:36:46.791609 2021] [rewrite:trace3] [pid 3506:tid 140223592126208] mod_rewrite.c(483): [client [ip]:58246] [ip] - - [[matomo-server]/sid#55c61dfac168][rid#7f87c40b3f80/initial] [perdir /var/www/html/matomo/] strip per-dir prefix: /var/www/html/matomo/js/ -> js/, referer: [dev-server]
[Sun Jan 31 11:36:46.791622 2021] [rewrite:trace3] [pid 3506:tid 140223592126208] mod_rewrite.c(483): [client [ip]:58246] [ip] - - [[matomo-server]/sid#55c61dfac168][rid#7f87c40b3f80/initial] [perdir /var/www/html/matomo/] applying pattern '^.*$' to uri 'js/', referer: [dev-server]
[Sun Jan 31 11:36:46.791638 2021] [rewrite:trace1] [pid 3506:tid 140223592126208] mod_rewrite.c(483): [client [ip]:58246] [ip] - - [[matomo-server]/sid#55c61dfac168][rid#7f87c40b3f80/initial] [perdir /var/www/html/matomo/] pass through /var/www/html/matomo/js/, referer: [dev-server]
[Sun Jan 31 11:36:46.791685 2021] [authz_core:debug] [pid 3506:tid 140223592126208] mod_authz_core.c(818): [client [ip]:58246] AH01626: authorization result of Require all granted: granted, referer: [dev-server]
[Sun Jan 31 11:36:46.791690 2021] [authz_core:debug] [pid 3506:tid 140223592126208] mod_authz_core.c(818): [client [ip]:58246] AH01626: authorization result of <RequireAny>: granted, referer: [dev-server]
[Sun Jan 31 11:36:46.791697 2021] [core:trace3] [pid 3506:tid 140223592126208] request.c(312): [client [ip]:58246] request authorized without authentication by access_checker_ex hook: /js/index.php, referer: [dev-server]
[Sun Jan 31 11:36:46.791706 2021] [rewrite:trace3] [pid 3506:tid 140223592126208] mod_rewrite.c(483): [client [ip]:58246] [ip] - - [[matomo-server]/sid#55c61dfac168][rid#7f87c40b9430/subreq] [perdir /var/www/html/matomo/] strip per-dir prefix: /var/www/html/matomo/js/index.php -> js/index.php, referer: [dev-server]
[Sun Jan 31 11:36:46.791711 2021] [rewrite:trace3] [pid 3506:tid 140223592126208] mod_rewrite.c(483): [client [ip]:58246] [ip] - - [[matomo-server]/sid#55c61dfac168][rid#7f87c40b9430/subreq] [perdir /var/www/html/matomo/] applying pattern '^.*$' to uri 'js/index.php', referer: [dev-server]
[Sun Jan 31 11:36:46.791722 2021] [rewrite:trace1] [pid 3506:tid 140223592126208] mod_rewrite.c(483): [client [ip]:58246] [ip] - - [[matomo-server]/sid#55c61dfac168][rid#7f87c40b9430/subreq] [perdir /var/www/html/matomo/] pass through /var/www/html/matomo/js/index.php, referer: [dev-server]
[Sun Jan 31 11:36:46.793281 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(612): [client [ip]:58246] h2_mplx(74): trywait on data for 2.560000 ms)
[Sun Jan 31 11:36:46.793305 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,BUSY,3): transit [WAIT] -- wait cycle --> [BUSY]
[Sun Jan 31 11:36:46.793312 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=98304
[Sun Jan 31 11:36:46.793328 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:58246] h2_session(74): read
[Sun Jan 31 11:36:46.793335 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(1103): [client [ip]:58246] h2_mplx(74): dispatch events
[Sun Jan 31 11:36:46.793339 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_session.c(1824): [client [ip]:58246] h2_session(74,BUSY,3): NO_IO event, 3 streams open
[Sun Jan 31 11:36:46.793343 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,WAIT,3): transit [BUSY] -- no io --> [WAIT]
[Sun Jan 31 11:36:46.793346 2021] [http2:trace3] [pid 3506:tid 140223291811584] h2_session.c(2320): [client [ip]:58246] h2_session: wait for data, 5120 micros
[Sun Jan 31 11:36:46.797452 2021] [http2:trace2] [pid 3506:tid 140223283418880] h2_mplx.c(612): [client [ip]:57166] h2_mplx(75): trywait on data for 10.240000 ms)
[Sun Jan 31 11:36:46.797469 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_session.c(1698): [client [ip]:57166] AH03078: h2_session(75,BUSY,1): transit [WAIT] -- wait cycle --> [BUSY]
[Sun Jan 31 11:36:46.797475 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_filter.c(146): [client [ip]:57166] h2_session(75): read, NONBLOCK_READ, mode=0, readbytes=65536
[Sun Jan 31 11:36:46.797489 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_filter.c(191): (11)Resource temporarily unavailable: [client [ip]:57166] h2_session(75): read
[Sun Jan 31 11:36:46.797496 2021] [http2:trace2] [pid 3506:tid 140223283418880] h2_mplx.c(1103): [client [ip]:57166] h2_mplx(75): dispatch events
[Sun Jan 31 11:36:46.797500 2021] [http2:trace2] [pid 3506:tid 140223283418880] h2_session.c(1824): [client [ip]:57166] h2_session(75,BUSY,1): NO_IO event, 1 streams open
[Sun Jan 31 11:36:46.797503 2021] [http2:trace1] [pid 3506:tid 140223283418880] h2_session.c(1698): [client [ip]:57166] AH03078: h2_session(75,WAIT,1): transit [BUSY] -- no io --> [WAIT]
[Sun Jan 31 11:36:46.797512 2021] [http2:trace3] [pid 3506:tid 140223283418880] h2_session.c(2320): [client [ip]:57166] h2_session: wait for data, 20480 micros
[Sun Jan 31 11:36:46.798541 2021] [http2:trace2] [pid 3506:tid 140223291811584] h2_mplx.c(612): [client [ip]:58246] h2_mplx(74): trywait on data for 5.120000 ms)
[Sun Jan 31 11:36:46.798553 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_session.c(1698): [client [ip]:58246] AH03078: h2_session(74,BUSY,3): transit [WAIT] -- wait cycle --> [BUSY]
[Sun Jan 31 11:36:46.798558 2021] [http2:trace1] [pid 3506:tid 140223291811584] h2_filter.c(146): [client [ip]:58246] h2_session(74): read, NONBLOCK_READ, mode=0, readbytes=98304
icing commented 3 years ago

Sorry, I cannot really debug your distributed server from here. I can only give you hints where you might want to look.

So far, it sounds that you have a setup where the first n requests are very long running and block the execution of new arriving requests as apache has a limit per connection on how many shall be active at a time. I think these very long running requests is what you should look into. They are not healthy.

wif70068 commented 3 years ago

So, I put the Matomo VirtualHost back to http1.1 and since then the problem disappeared. So it's either SSLSessionCache, Matomo (which has random stuck requests which only are killed after the 10 min timeout - I need to look into that) or both. I think this ticket can be closed. Thanks for your help, you put me in the right direction!

icing commented 3 years ago

you're welcome.