Hi Rainer,
these tests work for me in trunk and 2.4.x. Also github CI seems to run them,
see https://github.com/apache/httpd/actions/runs/12653902522/job/35260461610
On what pytest line do the tests fail for you?
The tests were added 2024-11-07 in trunk:
mod_http2, fix keepalive timeout on reset requests Count failed requests
that are RST'ed, so that the connection enters keepalive timeout instead of the
regular timeout if the first request fails. Add tests to verify.
Cheers,
Stefan
PS. The github CI shows a segmentation fault in 106_02 shutdown, something I
can also see locally and the stack trace usually looks like this:
Thread 0 Crashed:: Dispatch queue: com.apple.main-thread
0 libcrypto.3.dylib 0x10a9ae174 err_string_data_cmp
+ 4
1 libcrypto.3.dylib 0x10a9fb911 OPENSSL_LH_retrieve
+ 225
2 libcrypto.3.dylib 0x10a9ad95d
ERR_reason_error_string + 109
3 libssl.3.dylib 0x10a41027e
ossl_err_load_SSL_strings + 14
4 libssl.3.dylib 0x10a410399
ossl_init_load_ssl_strings_ossl_ + 9
5 libsystem_pthread.dylib 0x7ff80fee696f
__pthread_once_handler + 65
6 libsystem_platform.dylib 0x7ff80ff1ca65 _os_once_callout + 17
7 libsystem_pthread.dylib 0x7ff80fee691d pthread_once + 74
8 libcrypto.3.dylib 0x10aa15be9
CRYPTO_THREAD_run_once + 9
9 libssl.3.dylib 0x10a41033e OPENSSL_init_ssl +
142
10 libssl.3.dylib 0x10a417631 SSL_CTX_new_ex + 49
11 mod_ssl.so 0x10a1fe505
ssl_init_ctx_protocol + 313 (ssl_engine_init.c:694) [inlined]
12 mod_ssl.so 0x10a1fe505 ssl_init_ctx + 341
(ssl_engine_init.c:1264)
13 mod_ssl.so 0x10a1fcbca ssl_init_server_ctx
+ 533 (ssl_engine_init.c:2023) [inlined]
14 mod_ssl.so 0x10a1fcbca
ssl_init_ConfigureServer + 682 (ssl_engine_init.c:2124)
15 mod_ssl.so 0x10a1fc35f ssl_init_Module +
1071 (ssl_engine_init.c:405)
16 httpd 0x109dfce71 ap_run_post_config +
81
17 httpd 0x109e05928 main + 2648
18 dyld 0x7ff80fb5c2cd start + 1805
> Am 17.01.2025 um 12:08 schrieb Rainer Jung <rainer.j...@kippdata.de>:
>
> 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
>
