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

Hi Stefan,

Am 17.01.25 um 15:22 schrieb Stefan Eissing via dev:
> Hallo Rainer,
> 
> hier mein error log when ich, erfolgreich:
> 
> httpd/2.4.x> pytest -v -k test_h2_200_17
> 
> laufen lasse.

Interesting. In your log, directly before the wanted line AH03401 there 
is a thread switch:

[Fri Jan 17 15:20:38.596914 2025] [http2:debug] [pid 34167:tid 
123145428578304] h2_session.c(1887): [client 127.0.0.1:55956] AH10306: 
h2_session(34167-0,IDLE,0): returning to mpm c1 monitoring

[Fri Jan 17 15:20:38.597152 2025] [http2:debug] [pid 34167:tid 
123145429114880] h2_session.c(1503): [client 127.0.0.1:55956] AH03401: 
h2_session(34167-0,IDLE,0): conn error -> shutdown, remote.emitted=1

In my output, everything is the same until

[Fri Jan 17 11:42:28.351516 2025] [http2:debug] [pid 2309684:tid 
2309712] h2_session.c(1887): [client 127.0.0.1:47394] AH10306: 
h2_session(2309684-0,IDLE,0): returning to mpm c1 monitoring

But then instead of the AH03401 I see:

- trace messages which might be there for you as well but are logged in 
my setup due to higher log level:

[Fri Jan 17 11:42:28.351564 2025] [mpm_event:trace7] [pid 2309684:tid 
2309742] event.c(1859): (4)Interrupted system call: polled with num=0 
exit=0/0 conns=1 queues_timeout=4999967 timers_timeout=-1737110548351563
[Fri Jan 17 11:42:28.351587 2025] [mpm_event:trace7] [pid 2309684:tid 
2309742] event.c(1839): polling with timeout=5000000 
queues_timeout=4999944 timers_timeout=-1737110548351586
[Fri Jan 17 11:42:28.352320 2025] [mpm_event:trace7] [pid 2309684:tid 
2309742] event.c(1859): polled with num=1 exit=0/0 conns=1 
queues_timeout=4999212 timers_timeout=-1737110548352318
[Fri Jan 17 11:42:28.352385 2025] [mpm_event:trace7] [pid 2309684:tid 
2309742] event.c(1839): polling with timeout=5000000 
queues_timeout=4999146 timers_timeout=-1737110548352384

and then

[Fri Jan 17 11:42:28.352882 2025] [http2:debug] [pid 2309684:tid 
2309714] h2_session.c(364): [client 127.0.0.1:47394] AH03066: 
h2_session(2309684-0,IDLE,0): recv FRAME[GOAWAY[error=0, 
reason='shutdown', last_stream=0]], frames=4/5 (r/s)
[Fri Jan 17 11:42:28.352902 2025] [http2:debug] [pid 2309684:tid 
2309714] h2_session.c(1393): [client 127.0.0.1:47394] AH03078: 
h2_session(2309684-0,IDLE,0): transit [IDLE] -- remote goaway --> [DONE]
[Fri Jan 17 11:42:28.352934 2025] [http2:debug] [pid 2309684:tid 
2309714] h2_c1.c(134): (70014)End of file found: [client 
127.0.0.1:47394] AH03045: h2_session(2309684-0,DONE,0): process, closing 
conn

So I think httpd receives the clients GOAWAY before it comes to the 
AH03401 point.

In your setup the GOAWAY comes from the server, in my setup from the 
client. So either the test is timing sensitive, or our clients (curl) 
behave differently.

And indeed when running the test using curl 8.7.1 or 8.8.0 it succeeds, 
with 8.9.0 , 8.9.1, 8.10.1 and 8.11.1 it fails.

So how should we handle that? Making it dependent on the curl version? 
Or is there another way to defer the client GOAWAY?

Thanks and best regards,

Rainer

>> Am 17.01.2025 um 15:00 schrieb Rainer Jung <[email protected]>:
>>
>> Hi Stefan,
>>
>> (Rainer not Rüdiger)
>>
>> Am 17.01.25 um 14:22 schrieb Stefan Eissing via dev:
>>> this*may* happen if you have a httpd process still lingering around on the test port somewhere?
>>
>> Unfortunately this is not the reason here.
>>
>> I am using OpenSSL 3.4.0 (in the server) and client side curl 8.11.1 and nghttp2 1.64.0 (with multiple OpenSSL versions in the clients, all failing the same way).
>>
>> I might try a manual reproduction scenario for the test
>>
>> - LimitRequestFieldSize 20
>> - LogLevel http2:debug
>> - curl with a couple of long request headers
>>
>> Maybe you could provide example pytest output for 17, how it should look like?
>>
>> Thanks,
>>
>> Rainer