Hi Rüdiger,
this *may* happen if you have a httpd process still lingering around on the
test port somewhere?
- Stefan
> Am 17.01.2025 um 14:01 schrieb Rainer Jung <rainer.j...@kippdata.de>:
>
> Hi Stefan,
>
> the pytest error is (example for 17):
>
> ______________________ TestInvalidHeaders.test_h2_200_17
> _______________________
>
> self = <http2.test_200_header_invalid.TestInvalidHeaders object at
> 0x7f932c3e59f0>
> env = <http2.env.H2TestEnv object at 0x7f932c4e67d0>
>
> def test_h2_200_17(self, env):
> conf = H2Conf(env)
> conf.add("""
> LimitRequestFieldSize 20
> LogLevel http2:debug
> """)
> conf.add_vhost_cgi()
> conf.install()
> assert env.apache_restart() == 0
> re_emitted = re.compile(r'.* AH03401: .* shutdown, remote.emitted=1')
> url = env.mkurl("https", "cgi", "/")
> opt = []
> for i in range(10):
> opt += ["-H", f"x{i}: 012345678901234567890123456789"]
> r = env.curl_get(url, options=opt)
> assert r.response
> assert r.response["status"] == 431
> > assert env.httpd_error_log.scan_recent(re_emitted)
>
> modules/http2/test_200_header_invalid.py:254:
> _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
> _
>
> self =
> HttpdErrorLog[/tmp/esupport-testdir/pytest-event-340/gen/apache/logs/error_log,
> errors: , warnings: ]
> pattern = re.compile('.* AH03401: .* shutdown, remote.emitted=1'), timeout =
> 10
>
> def scan_recent(self, pattern: re.Pattern, timeout=10):
> if not os.path.isfile(self.path):
> return False
> with open(self.path) as fd:
> end = datetime.now() + timedelta(seconds=timeout)
> while True:
> fd.seek(self._recent_pos, os.SEEK_SET)
> for line in fd:
> if pattern.match(line):
> return True
> if datetime.now() > end:
> > raise TimeoutError(f"pattern not found in error log after
> > {timeout} seconds")
> E TimeoutError: pattern not found in error log after 10
> seconds
>
> pyhttpd/log.py:150: TimeoutError
>
> Thanks!
>
> BTW (and not the reason for the failure): Should I remove the first -
> probably incomplete definition of test 17:
>
> # test few failed headers, should
> def test_h2_200_17(self, env):
> url = env.mkurl("https", "cgi", "/")
>
> # test few failed headers, should give response
> def test_h2_200_17(self, env):
> conf = H2Conf(env)
> ...
>
> Rainer
>
> Am 17.01.25 um 12:54 schrieb Stefan Eissing via dev:
>> 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
