Re: pytest for 2.4.x HEAD: Log check for AH03401 fails

[Rainer Jung]

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