Re: pytest for 2.4.x HEAD: Log check for AH03401 fails
> Am 17.01.2025 um 17:00 schrieb Rainer Jung : > > Cool!! Ironischerweise eine Verbesserung, die ich selbst in curl eingebaut hatte... -.- Schönes Wochenende, Stefan > > Am 17.01.25 um 16:50 schrieb Stefan Eissing via dev: >> Hi Rainer, >> fix is in https://github.com/icing/mod_h2/pull/292. Will apply this to >> apache svn soonish. >> Cheers, >> Stefan >>> Am 17.01.2025 um 16:44 schrieb Rainer Jung : >>> >>> I should also add, that the working curl 8.7.1 and 8.8.0 have been build >>> using nghttp2 1.60.1 resp. 1.62.0, the failing curl 8.9.0 and beyond have >>> been build using nghttp2 1.62.1, 1.63.0 and 1.64.0. >>> >>> Am 17.01.25 um 16:30 schrieb Stefan Eissing via dev: > Am 17.01.2025 um 16:16 schrieb Rainer Jung : > > 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=467 timers_timeout=-1737110548351563 > [Fri Jan 17 11:42:28.351587 2025] [mpm_event:trace7] [pid 2309684:tid > 2309742] event.c(1839): polling with timeout=500 > queues_timeout=444 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=500 > 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? Oh, thanks for the analysis. I'll have to test with a recent curl then to see who is wrong here. - Stefan > Thanks and best regards, > > Rainer > >>> Am 17.01.2025 um 15:00 schrieb Rainer Jung : >>> >>> 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
Re: pytest for 2.4.x HEAD: Log check for AH03401 fails
Cool!! Am 17.01.25 um 16:50 schrieb Stefan Eissing via dev: Hi Rainer, fix is in https://github.com/icing/mod_h2/pull/292. Will apply this to apache svn soonish. Cheers, Stefan Am 17.01.2025 um 16:44 schrieb Rainer Jung : I should also add, that the working curl 8.7.1 and 8.8.0 have been build using nghttp2 1.60.1 resp. 1.62.0, the failing curl 8.9.0 and beyond have been build using nghttp2 1.62.1, 1.63.0 and 1.64.0. Am 17.01.25 um 16:30 schrieb Stefan Eissing via dev: Am 17.01.2025 um 16:16 schrieb Rainer Jung : 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=467 timers_timeout=-1737110548351563 [Fri Jan 17 11:42:28.351587 2025] [mpm_event:trace7] [pid 2309684:tid 2309742] event.c(1839): polling with timeout=500 queues_timeout=444 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=500 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? Oh, thanks for the analysis. I'll have to test with a recent curl then to see who is wrong here. - Stefan Thanks and best regards, Rainer Am 17.01.2025 um 15:00 schrieb Rainer Jung : 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
Re: pytest for 2.4.x HEAD: Log check for AH03401 fails
Hi Rainer, fix is in https://github.com/icing/mod_h2/pull/292. Will apply this to apache svn soonish. Cheers, Stefan > Am 17.01.2025 um 16:44 schrieb Rainer Jung : > > I should also add, that the working curl 8.7.1 and 8.8.0 have been build > using nghttp2 1.60.1 resp. 1.62.0, the failing curl 8.9.0 and beyond have > been build using nghttp2 1.62.1, 1.63.0 and 1.64.0. > > Am 17.01.25 um 16:30 schrieb Stefan Eissing via dev: >>> Am 17.01.2025 um 16:16 schrieb Rainer Jung : >>> >>> 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=467 timers_timeout=-1737110548351563 >>> [Fri Jan 17 11:42:28.351587 2025] [mpm_event:trace7] [pid 2309684:tid >>> 2309742] event.c(1839): polling with timeout=500 queues_timeout=444 >>> 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=500 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? >> Oh, thanks for the analysis. I'll have to test with a recent curl then to >> see who is wrong here. >> - Stefan >>> Thanks and best regards, >>> >>> Rainer >>> > Am 17.01.2025 um 15:00 schrieb Rainer Jung : > > 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
Re: pytest for 2.4.x HEAD: Log check for AH03401 fails
I should also add, that the working curl 8.7.1 and 8.8.0 have been build using nghttp2 1.60.1 resp. 1.62.0, the failing curl 8.9.0 and beyond have been build using nghttp2 1.62.1, 1.63.0 and 1.64.0. Am 17.01.25 um 16:30 schrieb Stefan Eissing via dev: Am 17.01.2025 um 16:16 schrieb Rainer Jung : 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=467 timers_timeout=-1737110548351563 [Fri Jan 17 11:42:28.351587 2025] [mpm_event:trace7] [pid 2309684:tid 2309742] event.c(1839): polling with timeout=500 queues_timeout=444 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=500 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? Oh, thanks for the analysis. I'll have to test with a recent curl then to see who is wrong here. - Stefan Thanks and best regards, Rainer Am 17.01.2025 um 15:00 schrieb Rainer Jung : 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
Re: pytest for 2.4.x HEAD: Log check for AH03401 fails
> Am 17.01.2025 um 16:16 schrieb Rainer Jung : > > 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=467 timers_timeout=-1737110548351563 > [Fri Jan 17 11:42:28.351587 2025] [mpm_event:trace7] [pid 2309684:tid > 2309742] event.c(1839): polling with timeout=500 queues_timeout=444 > 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=500 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? Oh, thanks for the analysis. I'll have to test with a recent curl then to see who is wrong here. - Stefan > Thanks and best regards, > > Rainer > >>> Am 17.01.2025 um 15:00 schrieb Rainer Jung : >>> >>> 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
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=467 timers_timeout=-1737110548351563 [Fri Jan 17 11:42:28.351587 2025] [mpm_event:trace7] [pid 2309684:tid 2309742] event.c(1839): polling with timeout=500 queues_timeout=444 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=500 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 : 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
Re: pytest for 2.4.x HEAD: Log check for AH03401 fails
Hallo Rainer, hier mein error log when ich, erfolgreich: httpd/2.4.x> pytest -v -k test_h2_200_17 laufen lasse. error_log.gz Description: GNU Zip compressed data > Am 17.01.2025 um 15:00 schrieb Rainer Jung : > > 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 > >
Re: pytest for 2.4.x HEAD: Log check for AH03401 fails
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
Re: pytest for 2.4.x HEAD: Log check for AH03401 fails
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 :
>
> Hi Stefan,
>
> the pytest error is (example for 17):
>
> __ TestInvalidHeaders.test_h2_200_17
> ___
>
> self = 0x7f932c3e59f0>
> env =
>
>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.dylib0x10a9ae174 err_string_data_cmp + 4
>> 1 libcrypto.3.dylib0x10a9fb911 OPENSSL_LH_retrieve +
>> 225
>> 2 libcrypto.3.dylib0x10a9ad95d 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.dylib0x10aa15be9 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 httpd0x109dfce71 ap_run_post_config + 81
>> 17 httpd0x109e05928 main + 2648
>> 18 dyld 0x7ff80fb5c2cd start + 1805
>>>
Re: pytest for 2.4.x HEAD: Log check for AH03401 fails
Hi Stefan,
the pytest error is (example for 17):
__ TestInvalidHeaders.test_h2_200_17
___
self = 0x7f932c3e59f0>
env =
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.dylib0x7ff80ff1ca65 _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 dyld0x7ff80fb5c2cd start + 1805
Am 17.01.2025 um 12:08 schrieb Rainer Jung :
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
Re: pytest for 2.4.x HEAD: Log check for AH03401 fails
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.dylib0x7ff80ff1ca65 _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 dyld0x7ff80fb5c2cd start + 1805
> Am 17.01.2025 um 12:08 schrieb Rainer Jung :
>
> 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
