Hi all,
the two pytests
modules/http2/test_200_header_invalid.py::TestInvalidHeaders::test_h2_200_17
modules/http2/test_200_header_invalid.py::TestInvalidHeaders::test_h2_200_18
consistently fail for me on current httpd 2.4.x HEAD on Linux, MPM event
and worker.
The failing assert in both tests is the final one for the AH03401 debug
log message in the error log.
I do have the complete error log for the two tests available (not too
big) and indeed the message is not there.
Can anyone reproduce?
@icing: would it help to make the full error_log available to you? For
relevant parts see below, but maybe not nice inline.
I can also add some more debugging lines to the code and
recompile/retest if that helps.
Independent of that: in the same file
modules/http2/test_200_header_invalid.py test 17 seems to be defined
twice. the first definition seems incomplete, the second seems to be the
one that's used. Unless I misunderstood something.
Best regards,
Rainer
Access log for the test 17 is:
{ "request": "GET / HTTP/1.1", "status": 200, "bytes_resp_B": 709,
"bytes_tx_O": 936, "bytes_rx_I": 102, "bytes_rx_tx_S": 1038,
"time_taken": 1886 }
{ "request": "GET / HTTP/1.1", "status": 400, "bytes_resp_B": 278,
"bytes_tx_O": 476, "bytes_rx_I": 87, "bytes_rx_tx_S": 563, "time_taken":
488 }
{ "request": "GET / HTTP/2.0", "status": 431, "bytes_resp_B": 273,
"bytes_tx_O": 381, "bytes_rx_I": 0, "bytes_rx_tx_S": 381, "time_taken":
2066 }
and parts from the error log:
Timestamp always 11:42:28, microseconds see below
347976 [http2:debug] [tid 712] h2_stream.c(609): AH03082:
h2_stream(2309684-0-0,IDLE): created
348110 [http2:debug] [tid 712] h2_session.c(1006): AH03200:
h2_session(2309684-0,INIT,0): created, max_streams=100,
stream_mem=32768, workers_limit=6, workers_max=64,
push_diary(type=1,N=256), max_data_frame_len=0
348145 [http2:debug] [tid 712] h2_session.c(1104): AH03201:
h2_session(2309684-0,INIT,0): start, INITIAL_WINDOW_SIZE=65535,
MAX_CONCURRENT_STREAMS=100
348177 [http2:debug] [tid 712] h2_session.c(1798): AH03079:
h2_session(2309684-0,INIT,0): started on cgi.tests.httpd.apache.org:5001
348191 [http2:debug] [tid 712] h2_session.c(1393): AH03078:
h2_session(2309684-0,INIT,0): transit [INIT] -- init --> [BUSY]
348235 [http2:debug] [tid 712] h2_session.c(610): AH03068:
h2_session(2309684-0,BUSY,0): sent FRAME[SETTINGS[length=6, stream=0]],
frames=0/1 (r/s)
348254 [http2:debug] [tid 712] h2_session.c(610): AH03068:
h2_session(2309684-0,BUSY,0): sent FRAME[WINDOW_UPDATE[stream=0,
incr=2147418112]], frames=0/2 (r/s)
348585 [core:trace6] [tid 712] core_filters.c(828): writev_nonblocking:
50/50
349195 [http2:debug] [tid 712] h2_session.c(364): AH03066:
h2_session(2309684-0,BUSY,0): recv FRAME[SETTINGS[length=18, stream=0]],
frames=0/2 (r/s)
349215 [http2:debug] [tid 712] h2_session.c(364): AH03066:
h2_session(2309684-0,BUSY,0): recv FRAME[WINDOW_UPDATE[stream=0,
incr=1048510465]], frames=1/2 (r/s)
349235 [http2:debug] [tid 712] h2_stream.c(609): AH03082:
h2_stream(2309684-0-1,IDLE): created
349277 [http2:info] [tid 712] AH10180: h2_stream(2309684-0-1,IDLE):
Request header exceeds LimitRequestFieldSize: user-agent
349298 [http2:info] [tid 712] AH10180: h2_stream(2309684-0-1,IDLE):
Request header exceeds LimitRequestFieldSize: ap-test-name
349314 [http2:info] [tid 712] AH10180: h2_stream(2309684-0-1,IDLE):
Request header exceeds LimitRequestFieldSize: x0
349327 [http2:info] [tid 712] AH10180: h2_stream(2309684-0-1,IDLE):
Request header exceeds LimitRequestFieldSize: x1
349340 [http2:info] [tid 712] AH10180: h2_stream(2309684-0-1,IDLE):
Request header exceeds LimitRequestFieldSize: x2
349353 [http2:info] [tid 712] AH10180: h2_stream(2309684-0-1,IDLE):
Request header exceeds LimitRequestFieldSize: x3
349366 [http2:info] [tid 712] AH10180: h2_stream(2309684-0-1,IDLE):
Request header exceeds LimitRequestFieldSize: x4
349379 [http2:info] [tid 712] AH10180: h2_stream(2309684-0-1,IDLE):
Request header exceeds LimitRequestFieldSize: x5
349391 [http2:info] [tid 712] AH10180: h2_stream(2309684-0-1,IDLE):
Request header exceeds LimitRequestFieldSize: x6
349454 [http2:info] [tid 712] AH10180: h2_stream(2309684-0-1,IDLE):
Request header exceeds LimitRequestFieldSize: x7
349483 [http2:info] [tid 712] AH10180: h2_stream(2309684-0-1,IDLE):
Request header exceeds LimitRequestFieldSize: x8
349509 [http2:info] [tid 712] AH10180: h2_stream(2309684-0-1,IDLE):
Request header exceeds LimitRequestFieldSize: x9
349525 [http2:debug] [tid 712] h2_session.c(357): AH10302:
h2_stream(2309684-0-1,IDLE): recv FRAME[HEADERS[length=334, hend=1,
stream=1, eos=1]], frames=2/2 (r/s)
349733 [http2:debug] [tid 712] h2_session.c(364): AH03066:
h2_session(2309684-0,BUSY,0): recv FRAME[SETTINGS[ack=1, stream=0]],
frames=3/2 (r/s)
349756 [http2:debug] [tid 712] h2_session.c(610): AH03068:
h2_session(2309684-0,BUSY,0): sent FRAME[SETTINGS[ack=1, stream=0]],
frames=4/3 (r/s)
350033 [http:trace3] [tid 695] http_filters.c(1141): Response sent with
status 431, headers:
350061 [http:trace5] [tid 695] http_filters.c(1150): Date: Fri, 17 Jan
2025 10:42:28 GMT
350071 [http:trace5] [tid 695] http_filters.c(1153): Server:
Apache/2.4.63-dev (Unix) OpenSSL/3.4.0
350083 [http:trace4] [tid 695] http_filters.c(971): Content-Length: 273
350093 [http:trace4] [tid 695] http_filters.c(971): Connection: close
350103 [http:trace4] [tid 695] http_filters.c(971): Content-Type:
text/html; charset=iso-8859-1
350139 [http2:debug] [tid 695] h2_c2_filter.c(442): h2_c2(2309684-0-1):
read response line: HTTP/1.1 431 Request Header Fields Too Large
350169 [http2:debug] [tid 695] h2_c2_filter.c(442): h2_c2(2309684-0-1):
read response line: Date: Fri, 17 Jan 2025 10:42:28 GMT
350183 [http2:debug] [tid 695] h2_c2_filter.c(442): h2_c2(2309684-0-1):
read response line: Server: Apache/2.4.63-dev (Unix) OpenSSL/3.4.0
350194 [http2:debug] [tid 695] h2_c2_filter.c(442): h2_c2(2309684-0-1):
read response line: Content-Length: 273
350205 [http2:debug] [tid 695] h2_c2_filter.c(442): h2_c2(2309684-0-1):
read response line: Connection: close
350216 [http2:debug] [tid 695] h2_c2_filter.c(442): h2_c2(2309684-0-1):
read response line: Content-Type: text/html; charset=iso-8859-1
350227 [http2:debug] [tid 695] h2_c2_filter.c(442): h2_c2(2309684-0-1):
read response line:
350270 [http2:debug] [tid 695] h2_c2_filter.c(553): AH03197:
h2_c2(2309684-0-1): passed response 431
350573 [core:trace6] [tid 712] core_filters.c(828): writev_nonblocking:
31/31
350617 [http2:debug] [tid 712] h2_stream.c(1652): AH03073:
h2_stream(2309684-0-1,HALF_CLOSED_REMOTE): submit response 431
350735 [http2:debug] [tid 712] h2_session.c(603): AH10303:
h2_stream(2309684-0-1,HALF_CLOSED_REMOTE): sent FRAME[HEADERS[length=90,
hend=1, stream=1, eos=0]], frames=4/4 (r/s)
350763 [http2:debug] [tid 712] h2_session.c(603): AH10303:
h2_stream(2309684-0-1,HALF_CLOSED_REMOTE): sent FRAME[DATA[length=273,
flags=1, stream=1, padlen=0]], frames=4/5 (r/s)
351282 [core:trace6] [tid 712] core_filters.c(828): writev_nonblocking:
403/403
351473 [http2:debug] [tid 712] h2_session.c(1393): AH03078:
h2_session(2309684-0,BUSY,0): transit [BUSY] -- input exhausted, no
streams --> [IDLE]
351516 [http2:debug] [tid 712] h2_session.c(1887): AH10306:
h2_session(2309684-0,IDLE,0): returning to mpm c1 monitoring
351564 [mpm_event:trace7] [tid 742] event.c(1859): (4)Interrupted system
call: polled with num=0 exit=0/0 conns=1 queues_timeout=4999967
timers_timeout=-1737110548351563
351587 [mpm_event:trace7] [tid 742] event.c(1839): polling with
timeout=5000000 queues_timeout=4999944 timers_timeout=-1737110548351586
352320 [mpm_event:trace7] [tid 742] event.c(1859): polled with num=1
exit=0/0 conns=1 queues_timeout=4999212 timers_timeout=-1737110548352318
352385 [mpm_event:trace7] [tid 742] event.c(1839): polling with
timeout=5000000 queues_timeout=4999146 timers_timeout=-1737110548352384
352882 [http2:debug] [tid 714] h2_session.c(364): AH03066:
h2_session(2309684-0,IDLE,0): recv FRAME[GOAWAY[error=0,
reason='shutdown', last_stream=0]], frames=4/5 (r/s)
352902 [http2:debug] [tid 714] h2_session.c(1393): AH03078:
h2_session(2309684-0,IDLE,0): transit [IDLE] -- remote goaway --> [DONE]
352934 [http2:debug] [tid 714] h2_c1.c(134): (70014)End of file found:
AH03045: h2_session(2309684-0,DONE,0): process, closing conn
352965 [mpm_event:trace6] [tid 714] event.c(1543): lingering close from
state 5
352993 [http2:debug] [tid 714] h2_session.c(610): AH03068:
h2_session(2309684-0,DONE,0): sent FRAME[GOAWAY[error=0, reason='',
last_stream=1]], frames=5/6 (r/s)
353233 [core:trace6] [tid 714] core_filters.c(828): writev_nonblocking:
39/39
353258 [http2:debug] [tid 714] h2_session.c(798): AH03069:
h2_session(2309684-0,DONE,0): sent GOAWAY, err=0, msg=
353283 [http2:debug] [tid 714] h2_session.c(1393): AH03078:
h2_session(2309684-0,DONE,0): transit [DONE] -- pre_close --> [CLEANUP]
353544 [core:trace6] [tid 714] core_filters.c(828): (32)Broken pipe:
writev_nonblocking: 0/24
353561 [core:trace1] [tid 714] core_filters.c(537): (32)Broken pipe:
core_output_filter: writing data to the network
353707 [mpm_event:trace6] [tid 714] event.c(883): closing connection
from state 5
353738 [mpm_event:trace8] [tid 714] event.c(552): closing socket
14/7f4ed4000f70 from close_connection:886
353786 [mpm_event:trace8] [tid 714] event.c(800): cleanup connection
from state 5
From here timestamp always 11:42:33
357603 [mpm_event:trace7] [tid 742] event.c(1859): (70007)The timeout
specified has expired: polled with num=0 exit=0/0 conns=0
queues_timeout=-6066 timers_timeout=-1737110553357596
357871 [mpm_event:trace7] [tid 742] event.c(2040): queues maintenance
with timeout=-6340
357893 [mpm_event:trace7] [tid 742] event.c(2073): queues maintained
with timeout=-1
357905 [mpm_event:trace6] [tid 742] event.c(1767): connections: 0
(waitio:0 write-completion:0keep-alive:0 lingering:0 suspended:0
clogged:0), workers: 0/25 shutdown
357916 [mpm_event:trace7] [tid 742] event.c(1839): polling with
timeout=-1 queues_timeout=-1737110553357915 timers_timeout=-1737110553357915
From here timestamp always 11:42:38
630648 [mpm_event:debug] [tid 684] event.c(583): wake up listener
633292 [mpm_event:trace1] [tid 684] event.c(2799): ungraceful
termination received, joining workers
