Hi,
I have found a regression in mod_http2. When the client stops sending
data and closes the connection, mod_http2 doesn't detect that the
client has left and continues to "read" request data (until the
request times out because of the server's TimeOut value).
The bug has been introduced with mod_http2 version 1.5.8 (SVN
1747532). It is also present in the httpd 2.4.21 release candidate.
mod_http2 version 1.5.7 (SVN 1747194) works.
How to reproduce:
curl --http2 -k -v --data-binary @bigfile.dat --limit-rate 1
https://http2-enabled-apache-server/
... then kill the curl process with "kill <pid>"
Log messages:
h2_session.c(1827): h2_session(66): NO_IO event, 1 streams open
h2_session.c(1691): AH03078: h2_session(66): transit [BUSY] -- no io
--> [WAIT]
h2_session.c(2260): h2_session: wait for data, 200000 micros
h2_mplx.c(775): h2_mplx(66): trywait on data for 200.000000 ms)
h2_session.c(1691): AH03078: h2_session(66): transit [WAIT] -- wait
cycle --> [BUSY]
h2_filter.c(113): core_input(66): read, NONBLOCK_READ, mode=0, readbytes=8000
h2_filter.c(164): (104)Connection reset by peer: AH03046: h2_conn_io:
error reading
h2_session.c(1576): (104)Connection reset by peer: h2_session(66): input gone
h2_session.c(1777): h2_session(66): conn error -> shutdown
h2_session.c(789): h2_session(66): malloc(120)
h2_session.c(643): AH03068: h2_session(66): sent FRAME[GOAWAY[error=0,
reason='', last_stream=1]], frames=3/3 (r/s)
h2_session.c(799): h2_session(66): free()
h2_session.c(799): h2_session(66): free()
h2_conn_io.c(289): h2_conn_io: pass_output
h2_conn_io.c(124): bb_dump(66-0)-master conn pass: heap[17] flush
h2_conn_io.c(309): (32)Broken pipe: AH03044: h2_conn_io(66): pass_out
brigade 17 bytes
h2_session.c(740): AH03069: session(66): sent GOAWAY, err=0, msg=
h2_session.c(1691): AH03078: h2_session(66): transit [BUSY] -- local
goaway --> [LSHUTDOWN]
h2_mplx.c(1356): h2_mplx(66): dispatch events
h2_session.c(1827): h2_session(66): NO_IO event, 1 streams open
h2_session.c(1691): AH03078: h2_session(66): transit [LSHUTDOWN] -- no
io --> [WAIT]
h2_session.c(2260): h2_session: wait for data, 200000 micros
h2_mplx.c(775): h2_mplx(66): trywait on data for 200.000000 ms)
h2_session.c(1691): AH03078: h2_session(66): transit [WAIT] -- wait
cycle --> [LSHUTDOWN]
h2_filter.c(113): core_input(66): read, NONBLOCK_READ, mode=0, readbytes=8000
h2_filter.c(164): (103)Software caused connection abort: AH03046:
h2_conn_io: error reading
h2_session.c(1576): (103)Software caused connection abort:
h2_session(66): input gone
h2_session.c(1691): AH03078: h2_session(66): transit [LSHUTDOWN] --
conn error --> [DONE]
h2_mplx.c(1356): h2_mplx(66): dispatch events
h2_session.c(2312): (70014)End of file found: h2_session(66): [DONE]
process returns
h2_conn_io.c(289): h2_conn_io: pass_output
h2_conn_io.c(124): bb_dump(66-0)-master conn pass: h2eoc flush
h2_session.c(963): session(66): cleanup and destroy
h2_mplx.c(539): h2_mplx(66): release_join with 1 streams open, 0
streams resume, 0 streams ready, 1 tasks
h2_mplx.c(518): h2_mplx(66-1): exists, started=1, scheduled=1,
submitted=0, suspended=0
h2_mplx.c(402): h2_stream(66-1): done
h2_mplx.c(567): h2_mplx(66): 2. release_join with 1 streams in hold
AH03198: h2_mplx(66): release, waiting for 5 seconds now for 1
h2_workers to return, have still 1 tasks outstanding
->03198: h2_stream(66-1): POST server /myurl -> ? 0[orph=1/started=1/done=0]
AH03198: h2_mplx(66): release, waiting for 10 seconds now for 1
h2_workers to return, have still 1 tasks outstanding
AH03198: h2_mplx(66): release, waiting for 15 seconds now for 1
h2_workers to return, have still 1 tasks outstanding
AH03198: h2_mplx(66): release, waiting for 20 seconds now for 1
h2_workers to return, have still 1 tasks outstanding
[...]
AH03198: h2_mplx(66): release, waiting for 270 seconds now for 1
h2_workers to return, have still 1 tasks outstanding
AH03198: h2_mplx(66): release, waiting for 275 seconds now for 1
h2_workers to return, have still 1 tasks outstanding
AH03198: h2_mplx(66): release, waiting for 280 seconds now for 1
h2_workers to return, have still 1 tasks outstanding
AH03198: h2_mplx(66): release, waiting for 285 seconds now for 1
h2_workers to return, have still 1 tasks outstanding
h2_task.c(194): (70007)The timeout specified has expired:
h2_task(66-1): read returned
mod_airlock.c(1307): Error reading body data from client (errno = 0)
h2_from_h1.c(488): h2_from_h1(1): output_filter called
h2_from_h1.c(551): h2_from_h1(1): removed header filter, passing brigade len=0
h2_task.c(355): h2_task(66-1): write response body (0 bytes)
h2_task.c(355): h2_task(66-1): write response body (0 bytes)
h2_task.c(355): h2_task(66-1): write response body (0 bytes)
h2_task.c(343): AH03348: h2_task(66-1): open response to POST iaves60
/capi/TestServlet
h2_task.c(753): h2_task(66-1): process_request done
h2_task.c(725): h2_task(66-1): processing done
h2_mplx.c(949): h2_mplx(66): task(66-1) done
h2_mplx.c(995): h2_mplx(66-1): request done, 300007.554000 ms elapsed
h2_mplx.c(1009): h2_mplx(66): increase worker limit to 8
h2_mplx.c(1030): h2_mplx(66-1): task_done, stream in hold
h2_workers.c(119): h2_worker(0): looking for work
h2_workers.c(159): h2_worker(0): waiting signal (eternal),
worker_count=64, idle=64
h2_mplx.c(612): h2_mplx(66): 3. release_join 1 streams to purge
h2_stream.c(234): h2_stream(66-1): destroy
h2_mplx.c(350): h2_task(66-1): destroy
h2_conn.c(316): h2_slave_conn(66): destroy (task=66-1)
h2_mplx.c(223): h2_mplx(66): destroy, tasks=0
h2_session.c(799): h2_session(66): free()
h2_session.c(799): h2_session(66): free()
h2_session.c(799): h2_session(66): free()
[...]
h2_session.c(698): h2_session(66): destroy
h2_conn_io.c(309): (103)Software caused connection abort: AH03044:
h2_conn_io(66): pass_out brigade 0 bytes
h2_conn.c(215): (70014)End of file found: AH03045: h2_session(66):
process, closing conn
Regards,
Michael
