Re: mpm event assertion failures

[Stefan Eissing]

> Am 07.02.2022 um 17:13 schrieb Yann Ylavic :
> 
> On Mon, Feb 7, 2022 at 3:41 PM Stefan Eissing  wrote:
>> 
>> 
>> 
>>> Am 07.02.2022 um 14:44 schrieb Stefan Eissing :
>>> 
>>> 
>>> 
 Am 07.02.2022 um 13:47 schrieb Yann Ylavic :
 
 On Mon, Feb 7, 2022 at 1:29 PM Yann Ylavic  wrote:
> 
> On Mon, Feb 7, 2022 at 1:01 PM Stefan Eissing  wrote:
>> 
 []
> 
> there are still failures for
> mod_md still I haven't looked at (I think I don't have all the mod_md
> dependencies to test on my machine)..
 
 Namely this failure:
 https://app.travis-ci.com/github/apache/httpd/jobs/558512606#L2522
 Does it ring a bell for you?
>>> 
>>> Hmm, no, but I can have a look. There might be some timing involved...
>> 
>> Should be fixed in r1897819.
> 
> All green: https://app.travis-ci.com/github/apache/httpd/builds/246021482  \o/

👍🏻

Re: mpm event assertion failures

[Yann Ylavic]

On Mon, Feb 7, 2022 at 3:41 PM Stefan Eissing  wrote:
>
>
>
> > Am 07.02.2022 um 14:44 schrieb Stefan Eissing :
> >
> >
> >
> >> Am 07.02.2022 um 13:47 schrieb Yann Ylavic :
> >>
> >> On Mon, Feb 7, 2022 at 1:29 PM Yann Ylavic  wrote:
> >>>
> >>> On Mon, Feb 7, 2022 at 1:01 PM Stefan Eissing  wrote:
> 
> >> []
> >>>
> >>> there are still failures for
> >>> mod_md still I haven't looked at (I think I don't have all the mod_md
> >>> dependencies to test on my machine)..
> >>
> >> Namely this failure:
> >> https://app.travis-ci.com/github/apache/httpd/jobs/558512606#L2522
> >> Does it ring a bell for you?
> >
> > Hmm, no, but I can have a look. There might be some timing involved...
>
> Should be fixed in r1897819.

All green: https://app.travis-ci.com/github/apache/httpd/builds/246021482  \o/

Thanks!

Re: mpm event assertion failures

[Stefan Eissing]

> Am 07.02.2022 um 14:44 schrieb Stefan Eissing :
> 
> 
> 
>> Am 07.02.2022 um 13:47 schrieb Yann Ylavic :
>> 
>> On Mon, Feb 7, 2022 at 1:29 PM Yann Ylavic  wrote:
>>> 
>>> On Mon, Feb 7, 2022 at 1:01 PM Stefan Eissing  wrote:
 
>> []
>>> 
>>> there are still failures for
>>> mod_md still I haven't looked at (I think I don't have all the mod_md
>>> dependencies to test on my machine)..
>> 
>> Namely this failure:
>> https://app.travis-ci.com/github/apache/httpd/jobs/558512606#L2522
>> Does it ring a bell for you?
> 
> Hmm, no, but I can have a look. There might be some timing involved...

Should be fixed in r1897819.

> 
>> 
>>> 
>>> Cheers;
>>> Yann.

Re: mpm event assertion failures

[Stefan Eissing]

> Am 07.02.2022 um 13:47 schrieb Yann Ylavic :
> 
> On Mon, Feb 7, 2022 at 1:29 PM Yann Ylavic  wrote:
>> 
>> On Mon, Feb 7, 2022 at 1:01 PM Stefan Eissing  wrote:
>>> 
> []
>> 
>> there are still failures for
>> mod_md still I haven't looked at (I think I don't have all the mod_md
>> dependencies to test on my machine)..
> 
> Namely this failure:
> https://app.travis-ci.com/github/apache/httpd/jobs/558512606#L2522
> Does it ring a bell for you?

Hmm, no, but I can have a look. There might be some timing involved...

> 
>> 
>> Cheers;
>> Yann.

Re: mpm event assertion failures

[Yann Ylavic]

On Mon, Feb 7, 2022 at 1:29 PM Yann Ylavic  wrote:
>
> On Mon, Feb 7, 2022 at 1:01 PM Stefan Eissing  wrote:
> >
[]
>
> there are still failures for
> mod_md still I haven't looked at (I think I don't have all the mod_md
> dependencies to test on my machine)..

Namely this failure:
https://app.travis-ci.com/github/apache/httpd/jobs/558512606#L2522
Does it ring a bell for you?

>
> Cheers;
> Yann.

Re: mpm event assertion failures

[Yann Ylavic]

On Mon, Feb 7, 2022 at 1:01 PM Stefan Eissing  wrote:
>
> > Am 07.02.2022 um 12:46 schrieb Yann Ylavic :
> >>
> >> The assertion failure is due to mpm_event closing all the workers'
> >> sockets forcibly [1] on ungraceful shutdown/restart, while the socket
> >> is still handled by h2, thus when h2 gives the connection back to the
> >> mpm fr lingering close it fails.
>
> Wow, you have been busy! Can I apply the PR diff to trunk for a test drive on 
> my machine?

Yes, the PR is based off trunk.

I've just added a fix for beam cleanups because test_h2_500_20 was
failing sporadically on travis, and there are still failures for
mod_md still I haven't looked at (I think I don't have all the mod_md
dependencies to test on my machine)..

Cheers;
Yann.

Re: mpm event assertion failures

[Stefan Eissing]

> Am 07.02.2022 um 12:46 schrieb Yann Ylavic :
> 
> On Mon, Feb 7, 2022 at 12:41 PM Yann Ylavic  wrote:
>> 
>> On Tue, Jan 25, 2022 at 1:12 PM Stefan Eissing  wrote:
>>> 
>>> Also, while running the http2 test suite, I get repeated assert failures in 
>>> event.c:1230
>>> 
>>> if (rv != APR_SUCCESS && !APR_STATUS_IS_EEXIST(rv)) {
>>> ->  AP_DEBUG_ASSERT(0);
>>>TO_QUEUE_REMOVE(cs->sc->wc_q, cs);
>>>apr_thread_mutex_unlock(timeout_mutex);
>>>ap_log_error(APLOG_MARK, APLOG_ERR, rv, ap_server_conf, APLOGNO(03465)
>>> "process_socket: apr_pollset_add failure for "
>>> "write completion");
>>>close_connection(cs);
>>>signal_threads(ST_GRACEFUL);
>>> }
>>> 
>>> Seems something is fishy with the recent changes.
>> 
>> 
>> The assertion failure is due to mpm_event closing all the workers'
>> sockets forcibly [1] on ungraceful shutdown/restart, while the socket
>> is still handled by h2, thus when h2 gives the connection back to the
>> mpm fr lingering close it fails.

Wow, you have been busy! Can I apply the PR diff to trunk for a test drive on 
my machine?

>> 
>> This is fixed in PR #294 by [2].
>> 
>> [1] 
>> https://github.com/apache/httpd/pull/294/files#diff-0f7c762a65575c89143d8ab894ec9d79e6f2f26aca2c4e4c102e129043683310L594
>> [2] 
>> https://github.com/apache/httpd/pull/294/files#diff-0f7c762a65575c89143d8ab894ec9d79e6f2f26aca2c4e4c102e129043683310R1143
> 
> With the right links..
> 
> [1] 
> https://github.com/apache/httpd/pull/294/commits/9996178dfdb01d41ae26a196109241e16cc041a6#diff-0f7c762a65575c89143d8ab894ec9d79e6f2f26aca2c4e4c102e129043683310L597
> [2] 
> https://github.com/apache/httpd/pull/294/commits/9996178dfdb01d41ae26a196109241e16cc041a6#diff-0f7c762a65575c89143d8ab894ec9d79e6f2f26aca2c4e4c102e129043683310R1070
> 
>> 
>> Regards;
>> Yann.

Re: mpm event assertion failures

[Yann Ylavic]

On Mon, Feb 7, 2022 at 12:41 PM Yann Ylavic  wrote:
>
> On Tue, Jan 25, 2022 at 1:12 PM Stefan Eissing  wrote:
> >
> > Also, while running the http2 test suite, I get repeated assert failures in 
> > event.c:1230
> >
> > if (rv != APR_SUCCESS && !APR_STATUS_IS_EEXIST(rv)) {
> > ->  AP_DEBUG_ASSERT(0);
> > TO_QUEUE_REMOVE(cs->sc->wc_q, cs);
> > apr_thread_mutex_unlock(timeout_mutex);
> > ap_log_error(APLOG_MARK, APLOG_ERR, rv, ap_server_conf, APLOGNO(03465)
> >  "process_socket: apr_pollset_add failure for "
> >  "write completion");
> > close_connection(cs);
> > signal_threads(ST_GRACEFUL);
> > }
> >
> > Seems something is fishy with the recent changes.
>
>
> The assertion failure is due to mpm_event closing all the workers'
> sockets forcibly [1] on ungraceful shutdown/restart, while the socket
> is still handled by h2, thus when h2 gives the connection back to the
> mpm fr lingering close it fails.
>
> This is fixed in PR #294 by [2].
>
> [1] 
> https://github.com/apache/httpd/pull/294/files#diff-0f7c762a65575c89143d8ab894ec9d79e6f2f26aca2c4e4c102e129043683310L594
> [2] 
> https://github.com/apache/httpd/pull/294/files#diff-0f7c762a65575c89143d8ab894ec9d79e6f2f26aca2c4e4c102e129043683310R1143

With the right links..

[1] 
https://github.com/apache/httpd/pull/294/commits/9996178dfdb01d41ae26a196109241e16cc041a6#diff-0f7c762a65575c89143d8ab894ec9d79e6f2f26aca2c4e4c102e129043683310L597
[2] 
https://github.com/apache/httpd/pull/294/commits/9996178dfdb01d41ae26a196109241e16cc041a6#diff-0f7c762a65575c89143d8ab894ec9d79e6f2f26aca2c4e4c102e129043683310R1070

>
> Regards;
> Yann.

Re: mpm event assertion failures

[Yann Ylavic]

On Tue, Jan 25, 2022 at 1:12 PM Stefan Eissing  wrote:
>
> Also, while running the http2 test suite, I get repeated assert failures in 
> event.c:1230
>
> if (rv != APR_SUCCESS && !APR_STATUS_IS_EEXIST(rv)) {
> ->  AP_DEBUG_ASSERT(0);
> TO_QUEUE_REMOVE(cs->sc->wc_q, cs);
> apr_thread_mutex_unlock(timeout_mutex);
> ap_log_error(APLOG_MARK, APLOG_ERR, rv, ap_server_conf, APLOGNO(03465)
>  "process_socket: apr_pollset_add failure for "
>  "write completion");
> close_connection(cs);
> signal_threads(ST_GRACEFUL);
> }
>
> Seems something is fishy with the recent changes.


The assertion failure is due to mpm_event closing all the workers'
sockets forcibly [1] on ungraceful shutdown/restart, while the socket
is still handled by h2, thus when h2 gives the connection back to the
mpm fr lingering close it fails.

This is fixed in PR #294 by [2].

[1] 
https://github.com/apache/httpd/pull/294/files#diff-0f7c762a65575c89143d8ab894ec9d79e6f2f26aca2c4e4c102e129043683310L594
[2] 
https://github.com/apache/httpd/pull/294/files#diff-0f7c762a65575c89143d8ab894ec9d79e6f2f26aca2c4e4c102e129043683310R1143


Regards;
Yann.

Re: Python test suite - failures on Fedora Rawhide / MacOS

[Stefan Eissing]

> Am 07.02.2022 um 12:21 schrieb Graham Leggett :
> 
> On 07 Feb 2022, at 12:42, Stefan Eissing  wrote:
> 
>>> curl -V
>> curl 7.77.0 (x86_64-apple-darwin21.0) libcurl/7.77.0 (SecureTransport) 
>> LibreSSL/2.8.3 zlib/1.2.11 nghttp2/1.42.0
>> Release-Date: 2021-05-26
>> Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap 
>> ldaps mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
>> Features: alt-svc AsynchDNS GSS-API HSTS HTTP2 HTTPS-proxy IPv6 Kerberos 
>> Largefile libz MultiSSL NTLM NTLM_WB SPNEGO SSL UnixSockets
>> 
>> It should list "HTTP2" in the Features line.
> 
> I don’t have HTTP2:
> 
> Little-Net:httpd-trunk6 minfrin$ which curl
> /opt/local/bin/curl
> Little-Net:httpd-trunk6 minfrin$ curl -V
> curl 7.80.0 (x86_64-apple-darwin20.6.0) libcurl/7.80.0 OpenSSL/3.0.1 
> zlib/1.2.11 zstd/1.5.2 libidn2/2.3.2 libpsl/0.21.1 (+libidn2/2.3.2)
> Release-Date: 2021-11-10
> Protocols: dict file ftp ftps gopher gophers http https imap imaps mqtt pop3 
> pop3s rtsp smb smbs smtp smtps telnet tftp 
> Features: alt-svc AsynchDNS HSTS HTTPS-proxy IDN IPv6 Largefile libz NTLM 
> NTLM_WB PSL SSL TLS-SRP UnixSockets zstd
> 
> Looks like you need to explicitly request it:
> 
> Little-Net:httpd-trunk6 minfrin$ sudo port install curl +http2
> Password:
> Warning: The macOS 11 SDK does not appear to be installed. Ports may not 
> build correctly.
> Warning: You can install it as part of the Xcode Command Line Tools package 
> by running `xcode-select --install'.
> --->  Computing dependencies for curl
> --->  Fetching archive for curl
> --->  Attempting to fetch curl-7.80.0_0+http2+ssl.darwin_20.x86_64.tbz2 from 
> https://mse.uk.packages.macports.org/curl
> --->  Attempting to fetch curl-7.80.0_0+http2+ssl.darwin_20.x86_64.tbz2 from 
> https://packages.macports.org/curl
> --->  Attempting to fetch curl-7.80.0_0+http2+ssl.darwin_20.x86_64.tbz2 from 
> https://ema.uk.packages.macports.org/curl
> --->  Fetching distfiles for curl
> --->  Attempting to fetch curl-7.80.0.tar.xz from 
> https://distfiles.macports.org/curl
> --->  Verifying checksums for curl
>
> --->  Extracting curl
> --->  Applying patches to curl
> --->  Configuring curl
> Warning: Configuration logfiles contain indications of 
> -Wimplicit-function-declaration; check that features were not accidentally 
> disabled:
>   getpass_r: found in curl-7.80.0/config.log
>   malloc: found in curl-7.80.0/config.log
>   strchr: found in curl-7.80.0/config.log
>   memrchr: found in curl-7.80.0/config.log
>   free: found in curl-7.80.0/config.log
>   calloc: found in curl-7.80.0/config.log
>   CloseSocket: found in curl-7.80.0/config.log
>   closesocket: found in curl-7.80.0/config.log
> --->  Building curl
> --->  Staging curl into destroot 
> --->  Installing curl @7.80.0_0+http2+ssl
> --->  Deactivating curl @7.80.0_0+ssl
> --->  Cleaning curl
> --->  Activating curl @7.80.0_0+http2+ssl
> --->  Cleaning curl
> --->  Scanning binaries for linking errors
> --->  No broken files found. 
> --->  No broken ports found.
> 
> I suspect we need tests at the very beginning of the test suite to fail if 
> the required tools are missing / incomplete.

I can add a check to the pytest suite that verifies curl and outputs a proper 
error message if HTTP2 is not in curl's features.

> 
> Regards,
> Graham
> —
> 

Re: mpm event assertion failures

[Stefan Eissing]

> Am 07.02.2022 um 12:19 schrieb Graham Leggett :
> 
> On 07 Feb 2022, at 12:35, Stefan Eissing  wrote:
> 
>>> There are two parts that hook into the process_connection hook, the code 
>>> you’ve cited above, and this code:
>>> 
>>> void h2_c2_register_hooks(void)
>>> {
>>>/* When the connection processing actually starts, we might
>>> * take over, if the connection is for a h2 stream.
>>> */
>>>ap_hook_process_connection(h2_c2_hook_process,
>>>   NULL, NULL, APR_HOOK_FIRST);
>>> 
>>> Looks like this code is running before mod_ssl somehow.
>>> 
>>> Is there a way to run the httpd under test in either lldb or gdb?
>> 
>> The names "h2_c1..." and "h2_c2..." indicate, that the former operates on 
>> "primary" connections, e.g. the ones from a client where SSL is applied, and 
>> "secondary" connections (c->master != NULL), e.g. where h2 requests are 
>> processed and SSL is not involved.
> 
> In theory it’s all the same hook though, so even though h2_c2_hook_process() 
> is standing out of the way of anything not a secondary connection, it’s still 
> running before mod_ssl, and it still throws away the AGAIN, leaving mod_ssl 
> in an undefined state.

I do not understand. h2_c2_process returns DECLINED on a c1 connection 
(!c->master). How does that mess with any return code a subsequent hook returns?
> 
> I’m assuming h2_c2_hook_process just wants to run before 
> h2_c1_hook_process_connection?

No, it definitely wants to prevent any other process hook from running *if and 
only if* it processes the connection itself. It does not want any SSL module to 
insert its filters, specifically.

> 
> I just tried this patch on rawhide (where I’m getting success with the http2 
> tests) and we still work:
> 
> Index: modules/http2/h2_c1.c
> ===
> --- modules/http2/h2_c1.c (revision 1897807)
> +++ modules/http2/h2_c1.c (working copy)
> @@ -312,6 +312,7 @@
>  
>  static const char* const mod_ssl[]= { "mod_ssl.c", NULL};
>  static const char* const mod_reqtimeout[] = { "mod_ssl.c", 
> "mod_reqtimeout.c", NULL};
> +static const char* const mod_h2_c2[]  = { "mod_ssl.c", 
> "mod_reqtimeout.c", "h2_c2.c", NULL};
>  
>  void h2_c1_register_hooks(void)
>  {
> @@ -322,7 +323,7 @@
>   * a chance to take over before it.
>   */
>  ap_hook_process_connection(h2_c1_hook_process_connection,
> -   mod_reqtimeout, NULL, APR_HOOK_LAST);
> +   mod_h2_c2, NULL, APR_HOOK_LAST);
>  
>  /* One last chance to properly say goodbye if we have not done so
>   * already. */
> Index: modules/http2/h2_c2.c
> ===
> --- modules/http2/h2_c2.c (revision 1897807)
> +++ modules/http2/h2_c2.c (working copy)
> @@ -707,7 +707,7 @@
>   * take over, if the connection is for a h2 stream.
>   */
>  ap_hook_process_connection(h2_c2_hook_process,
> -   NULL, NULL, APR_HOOK_FIRST);
> +   NULL, NULL, APR_HOOK_LAST);
>  /* We need to manipulate the standard HTTP/1.1 protocol filters and
>   * install our own. This needs to be done very early. */
>  ap_hook_post_read_request(h2_c2_hook_post_read_request, NULL, NULL, 
> APR_HOOK_REALLY_FIRST);
> 
> Regards,
> Graham
> —

Re: Python test suite - failures on Fedora Rawhide / MacOS

[Graham Leggett]

On 07 Feb 2022, at 12:42, Stefan Eissing  wrote:

>> curl -V
> curl 7.77.0 (x86_64-apple-darwin21.0) libcurl/7.77.0 (SecureTransport) 
> LibreSSL/2.8.3 zlib/1.2.11 nghttp2/1.42.0
> Release-Date: 2021-05-26
> Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps 
> mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
> Features: alt-svc AsynchDNS GSS-API HSTS HTTP2 HTTPS-proxy IPv6 Kerberos 
> Largefile libz MultiSSL NTLM NTLM_WB SPNEGO SSL UnixSockets
> 
> It should list "HTTP2" in the Features line.

I don’t have HTTP2:

Little-Net:httpd-trunk6 minfrin$ which curl
/opt/local/bin/curl
Little-Net:httpd-trunk6 minfrin$ curl -V
curl 7.80.0 (x86_64-apple-darwin20.6.0) libcurl/7.80.0 OpenSSL/3.0.1 
zlib/1.2.11 zstd/1.5.2 libidn2/2.3.2 libpsl/0.21.1 (+libidn2/2.3.2)
Release-Date: 2021-11-10
Protocols: dict file ftp ftps gopher gophers http https imap imaps mqtt pop3 
pop3s rtsp smb smbs smtp smtps telnet tftp 
Features: alt-svc AsynchDNS HSTS HTTPS-proxy IDN IPv6 Largefile libz NTLM 
NTLM_WB PSL SSL TLS-SRP UnixSockets zstd

Looks like you need to explicitly request it:

Little-Net:httpd-trunk6 minfrin$ sudo port install curl +http2
Password:
Warning: The macOS 11 SDK does not appear to be installed. Ports may not build 
correctly.
Warning: You can install it as part of the Xcode Command Line Tools package by 
running `xcode-select --install'.
--->  Computing dependencies for curl
--->  Fetching archive for curl
--->  Attempting to fetch curl-7.80.0_0+http2+ssl.darwin_20.x86_64.tbz2 from 
https://mse.uk.packages.macports.org/curl
--->  Attempting to fetch curl-7.80.0_0+http2+ssl.darwin_20.x86_64.tbz2 from 
https://packages.macports.org/curl
--->  Attempting to fetch curl-7.80.0_0+http2+ssl.darwin_20.x86_64.tbz2 from 
https://ema.uk.packages.macports.org/curl
--->  Fetching distfiles for curl
--->  Attempting to fetch curl-7.80.0.tar.xz from 
https://distfiles.macports.org/curl
--->  Verifying checksums for curl  
 
--->  Extracting curl
--->  Applying patches to curl
--->  Configuring curl
Warning: Configuration logfiles contain indications of 
-Wimplicit-function-declaration; check that features were not accidentally 
disabled:
  getpass_r: found in curl-7.80.0/config.log
  malloc: found in curl-7.80.0/config.log
  strchr: found in curl-7.80.0/config.log
  memrchr: found in curl-7.80.0/config.log
  free: found in curl-7.80.0/config.log
  calloc: found in curl-7.80.0/config.log
  CloseSocket: found in curl-7.80.0/config.log
  closesocket: found in curl-7.80.0/config.log
--->  Building curl
--->  Staging curl into destroot 
--->  Installing curl @7.80.0_0+http2+ssl
--->  Deactivating curl @7.80.0_0+ssl
--->  Cleaning curl
--->  Activating curl @7.80.0_0+http2+ssl
--->  Cleaning curl
--->  Scanning binaries for linking errors
--->  No broken files found. 
--->  No broken ports found.

I suspect we need tests at the very beginning of the test suite to fail if the 
required tools are missing / incomplete.

Regards,
Graham
—

Re: mpm event assertion failures

[Graham Leggett]

On 07 Feb 2022, at 12:35, Stefan Eissing  wrote:

>> There are two parts that hook into the process_connection hook, the code 
>> you’ve cited above, and this code:
>> 
>> void h2_c2_register_hooks(void)
>> {
>>/* When the connection processing actually starts, we might
>> * take over, if the connection is for a h2 stream.
>> */
>>ap_hook_process_connection(h2_c2_hook_process,
>>   NULL, NULL, APR_HOOK_FIRST);
>> 
>> Looks like this code is running before mod_ssl somehow.
>> 
>> Is there a way to run the httpd under test in either lldb or gdb?
> 
> The names "h2_c1..." and "h2_c2..." indicate, that the former operates on 
> "primary" connections, e.g. the ones from a client where SSL is applied, and 
> "secondary" connections (c->master != NULL), e.g. where h2 requests are 
> processed and SSL is not involved.

In theory it’s all the same hook though, so even though h2_c2_hook_process() is 
standing out of the way of anything not a secondary connection, it’s still 
running before mod_ssl, and it still throws away the AGAIN, leaving mod_ssl in 
an undefined state.

I’m assuming h2_c2_hook_process just wants to run before 
h2_c1_hook_process_connection?

I just tried this patch on rawhide (where I’m getting success with the http2 
tests) and we still work:

Index: modules/http2/h2_c1.c
===
--- modules/http2/h2_c1.c   (revision 1897807)
+++ modules/http2/h2_c1.c   (working copy)
@@ -312,6 +312,7 @@
 
 static const char* const mod_ssl[]= { "mod_ssl.c", NULL};
 static const char* const mod_reqtimeout[] = { "mod_ssl.c", "mod_reqtimeout.c", 
NULL};
+static const char* const mod_h2_c2[]  = { "mod_ssl.c", "mod_reqtimeout.c", 
"h2_c2.c", NULL};
 
 void h2_c1_register_hooks(void)
 {
@@ -322,7 +323,7 @@
  * a chance to take over before it.
  */
 ap_hook_process_connection(h2_c1_hook_process_connection,
-   mod_reqtimeout, NULL, APR_HOOK_LAST);
+   mod_h2_c2, NULL, APR_HOOK_LAST);
 
 /* One last chance to properly say goodbye if we have not done so
  * already. */
Index: modules/http2/h2_c2.c
===
--- modules/http2/h2_c2.c   (revision 1897807)
+++ modules/http2/h2_c2.c   (working copy)
@@ -707,7 +707,7 @@
  * take over, if the connection is for a h2 stream.
  */
 ap_hook_process_connection(h2_c2_hook_process,
-   NULL, NULL, APR_HOOK_FIRST);
+   NULL, NULL, APR_HOOK_LAST);
 /* We need to manipulate the standard HTTP/1.1 protocol filters and
  * install our own. This needs to be done very early. */
 ap_hook_post_read_request(h2_c2_hook_post_read_request, NULL, NULL, 
APR_HOOK_REALLY_FIRST);

Regards,
Graham
—

Re: Python test suite - failures on Fedora Rawhide / MacOS

[Stefan Eissing]

> Am 07.02.2022 um 11:42 schrieb Stefan Eissing :
> 
> 
> 
>> Am 07.02.2022 um 11:26 schrieb Graham Leggett :
>> 
>> On 07 Feb 2022, at 12:23, Stefan Eissing  wrote:
>> 
>>> could you attach a complete failed output of your pytest run? I use it on 
>>> MacOS all the time and
>>> it seems most likely that some prerequisites have not been documented well 
>>> enough or checks must
>>> add more information in output.
>> 
>> I reduced the tests to http2 only:
>> 
>> pytest test/modules/http2
> 
> Do you have a locally built curl that has no HTTP2 support? To check run
> 
>> curl -V
> curl 7.77.0 (x86_64-apple-darwin21.0) libcurl/7.77.0 (SecureTransport) 
> LibreSSL/2.8.3 zlib/1.2.11 nghttp2/1.42.0
> Release-Date: 2021-05-26
> Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps 
> mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
> Features: alt-svc AsynchDNS GSS-API HSTS HTTP2 HTTPS-proxy IPv6 Kerberos 
> Largefile libz MultiSSL NTLM NTLM_WB SPNEGO SSL UnixSockets
> 
> It should list "HTTP2" in the Features line.

If you do, please run the first failing test with

> pytest -vvv -k test_h2_002_04

and then there is a log with TRACE2 in test/gen/apache/error_log that should 
tell us why HTTP/2 as not negotiated.

> 
>> 
>> and got this as a short summary:
>> 
>>  short test summary 
>> info =
>> FAILED 
>> test/modules/http2/test_002_curl_basics.py::TestCurlBasics::test_h2_002_04 - 
>> AssertionError: assert 'HTTP/1.1' == 'HTTP/2'
>> FAILED 
>> test/modules/http2/test_002_curl_basics.py::TestCurlBasics::test_h2_002_04b 
>> - AssertionError: assert 'HTTP/1.1' == 'HTTP/2'
>> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_01 - 
>> AssertionError: assert 'HTTP/1.1' == 'HTTP/2.0'
>> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_02 - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_21 - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED 
>> test/modules/http2/test_003_get.py::TestGet::test_h2_003_30[/004.html] - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED 
>> test/modules/http2/test_003_get.py::TestGet::test_h2_003_30[/proxy/004.html] 
>> - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED 
>> test/modules/http2/test_003_get.py::TestGet::test_h2_003_30[/h2proxy/004.html]
>>  - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED 
>> test/modules/http2/test_003_get.py::TestGet::test_h2_003_31[/004.html] - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED 
>> test/modules/http2/test_003_get.py::TestGet::test_h2_003_31[/proxy/004.html] 
>> - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED 
>> test/modules/http2/test_003_get.py::TestGet::test_h2_003_31[/h2proxy/004.html]
>>  - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_40 - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[0] - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[1] - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[1291] - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[1292] - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[8] - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[80123] - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[81087] - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[98452] - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED 
>> test/modules/http2/test_003_get.py::TestGet::test_h2_003_50[/004.html] - 
>> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED 
>> test/modules/http2/test_003_get.py::TestGet::test_h2_003_50[/proxy/004.html] 
>> - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED 
>> test/modules/http2/test_003_get.py::TestGet::test_h2_003_50[/h2proxy/004.html]
>>  - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
>> FAILED 
>> test/modules/http2/test_004_post.py::TestPost::test_h2_004_07[HTTP2-on] - 
>> AssertionError: assert None
>> FAILED 
>> test/modules/http2/test_004_post.py::TestPost::test_h2_004_07[H2PUSH-off] - 
>> AssertionError: assert None
>> FAILED 
>> test/modules/http2/test_004_post.py::TestPost::test_h2_004_07[H2_STREAM_ID-1]
>>  - AssertionError: assert None
>> FAILED 
>> test/modules/http2/test_004_post.py::TestPost::test_h2_004_07[H2_STREAM_TAG-\\d+-1]
>>  - Asser

Re: Python test suite - failures on Fedora Rawhide / MacOS

[Stefan Eissing]

> Am 07.02.2022 um 11:26 schrieb Graham Leggett :
> 
> On 07 Feb 2022, at 12:23, Stefan Eissing  wrote:
> 
>> could you attach a complete failed output of your pytest run? I use it on 
>> MacOS all the time and
>> it seems most likely that some prerequisites have not been documented well 
>> enough or checks must
>> add more information in output.
> 
> I reduced the tests to http2 only:
> 
> pytest test/modules/http2

Do you have a locally built curl that has no HTTP2 support? To check run

> curl -V
curl 7.77.0 (x86_64-apple-darwin21.0) libcurl/7.77.0 (SecureTransport) 
LibreSSL/2.8.3 zlib/1.2.11 nghttp2/1.42.0
Release-Date: 2021-05-26
Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps 
mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS GSS-API HSTS HTTP2 HTTPS-proxy IPv6 Kerberos 
Largefile libz MultiSSL NTLM NTLM_WB SPNEGO SSL UnixSockets

It should list "HTTP2" in the Features line.

> 
> and got this as a short summary:
> 
>  short test summary 
> info =
> FAILED 
> test/modules/http2/test_002_curl_basics.py::TestCurlBasics::test_h2_002_04 - 
> AssertionError: assert 'HTTP/1.1' == 'HTTP/2'
> FAILED 
> test/modules/http2/test_002_curl_basics.py::TestCurlBasics::test_h2_002_04b - 
> AssertionError: assert 'HTTP/1.1' == 'HTTP/2'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_01 - 
> AssertionError: assert 'HTTP/1.1' == 'HTTP/2.0'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_02 - 
> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_21 - 
> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_30[/004.html] 
> - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED 
> test/modules/http2/test_003_get.py::TestGet::test_h2_003_30[/proxy/004.html] 
> - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED 
> test/modules/http2/test_003_get.py::TestGet::test_h2_003_30[/h2proxy/004.html]
>  - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_31[/004.html] 
> - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED 
> test/modules/http2/test_003_get.py::TestGet::test_h2_003_31[/proxy/004.html] 
> - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED 
> test/modules/http2/test_003_get.py::TestGet::test_h2_003_31[/h2proxy/004.html]
>  - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_40 - 
> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[0] - 
> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[1] - 
> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[1291] - 
> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[1292] - 
> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[8] - 
> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[80123] - 
> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[81087] - 
> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[98452] - 
> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_50[/004.html] 
> - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED 
> test/modules/http2/test_003_get.py::TestGet::test_h2_003_50[/proxy/004.html] 
> - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED 
> test/modules/http2/test_003_get.py::TestGet::test_h2_003_50[/h2proxy/004.html]
>  - AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED 
> test/modules/http2/test_004_post.py::TestPost::test_h2_004_07[HTTP2-on] - 
> AssertionError: assert None
> FAILED 
> test/modules/http2/test_004_post.py::TestPost::test_h2_004_07[H2PUSH-off] - 
> AssertionError: assert None
> FAILED 
> test/modules/http2/test_004_post.py::TestPost::test_h2_004_07[H2_STREAM_ID-1] 
> - AssertionError: assert None
> FAILED 
> test/modules/http2/test_004_post.py::TestPost::test_h2_004_07[H2_STREAM_TAG-\\d+-1]
>  - AssertionError: assert None
> FAILED 
> test/modules/http2/test_100_conn_reuse.py::TestConnReuse::test_h2_100_01 - 
> AssertionError: assert '2' == '1.1'
> FAILED 
> test/modules/http2/test_100_conn_reuse.py::TestConnReuse::test_h2_100_02 - 
> AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> FAILED 
> test/modules/http2/test_100_conn_reuse.py::TestConnReuse::test_h2_100_03 - 
> Assertion

Re: mpm event assertion failures

[Stefan Eissing]

> Am 07.02.2022 um 11:31 schrieb Graham Leggett :
> 
> On 07 Feb 2022, at 12:18, Stefan Eissing  wrote:
> 
 Is the http2 code doing anything to work around mod_ssl trying to read, 
 failing, throwing away the error, and then pretending nothing happened?
>>> 
>>> The http2 code doesn't try to work around mod_ssl, instead it does the same 
>>> as mod_ssl, which is that it performs an operation but throws away the 
>>> error:
>>> 
>>> https://github.com/apache/httpd/blob/1598f7aebd59acc7494389a3903a33c5e38a5460/modules/http2/h2_c2.c#L632
>>> 
>>> This hook is sorted APR_HOOK_FIRST, which means h2_c2_hook_process() runs 
>>> first, then passes the connection to mod_ssl, which then returns AGAIN, but 
>>> AGAIN is now thrown away inside h2_c2_hook_process(), and now we’re off the 
>>> rails from this point on and we can expect our socket to be stuck in a 
>>> weird state.
>>> 
>>> The http1 code has the same problem, but runs APR_HOOK_LAST, which means 
>>> mod_ssl’s handshake is completely done before http1 touches the connection.
>>> 
>>> I think to fix this test, we need to make sure http2 runs after mod_ssl.
>> 
>> It does.
>> 
>> h2_c1.c:
>> 
>> static const char* const mod_reqtimeout[] = { "mod_ssl.c", 
>> "mod_reqtimeout.c", NULL};
>> 
>> void h2_c1_register_hooks(void)
>> {
>>/* Our main processing needs to run quite late. Definitely after mod_ssl,
>> * as we need its connection filters, but also before reqtimeout as its
>> * method of timeouts is specific to HTTP/1.1 (as of now).
>> * The core HTTP/1 processing run as REALLY_LAST, so we will have
>> * a chance to take over before it.
>> */
>>ap_hook_process_connection(h2_c1_hook_process_connection,
>>   mod_reqtimeout, NULL, APR_HOOK_LAST);
>>...
>> 
>> 
>> In my understanding this is how it should work. When mod_ssl's 
>> process_connection fails, it should return OK to prevent further hooks to 
>> run.
>> 
>> AP_IMPLEMENT_HOOK_RUN_FIRST(int,process_connection,(conn_rec 
>> *c),(c),DECLINED)
>> 
>> process_connection is a RUN_FIRST. So the first hook that returns OK, 
>> terminates it.
>> 
>> If mod_ssl returns OK in case of handshake errors, the connection is done. 
>> That is my read of it.
> 
> There are two parts that hook into the process_connection hook, the code 
> you’ve cited above, and this code:
> 
> void h2_c2_register_hooks(void)
> {
> /* When the connection processing actually starts, we might
>  * take over, if the connection is for a h2 stream.
>  */
> ap_hook_process_connection(h2_c2_hook_process,
>NULL, NULL, APR_HOOK_FIRST);
> 
> Looks like this code is running before mod_ssl somehow.
> 
> Is there a way to run the httpd under test in either lldb or gdb?

The names "h2_c1..." and "h2_c2..." indicate, that the former operates on 
"primary" connections, e.g. the ones from a client where SSL is applied, and 
"secondary" connections (c->master != NULL), e.g. where h2 requests are 
processed and SSL is not involved.

> 
> Regards,
> Graham
> —
> 

Re: SSL handshake nonblocking as PR

[Stefan Eissing]

> Am 06.02.2022 um 21:20 schrieb Graham Leggett :
> 
> On 04 Feb 2022, at 14:49, Stefan Eissing  wrote:
> 
>> https://github.com/apache/httpd/pull/293
>> 
>> is the PR that contains the changes I just reverted 
>> in trunk regarding the non-blocking SSL handshake.
>> 
>> I did not like to revert a set of changes by anyone
>> here. But our trunk CI is failing for some time now
>> and I felt this needs to be analyzed without interfering
>> with other ongoing work.
> 
> Unfortunately this doesn't appear to be a clean revert, as a whole lot of 
> unrelated commits seem to have got caught up in things.

Sorry about that.

> All the bugfixes made to ab for example are now gone:

Not gone. There are in the subversion branch and the history and one should be 
able to remerge them.

> 
> Little-Net:httpd-trunk6 minfrin$ svn log support/ab.c
> r1897760 | icing | 2022-02-04 14:22:26 +0200 (Fri, 04 Feb 2022) | 6 lines
> 
>   *) core/mod_ssl/mpm_event: reverting changes to nonblocing SSL handshakes
>  to stabilize CI tests again. Previous revision of trunk has been copied
>  to branches/trunk-ssl-handshake-unblocking to make those into a PR where
>  changes can be discussed and tested separately.
> 
> You’ve also reported conflicts while reverting, I’m assuming they weren't 
> easily explained like log tags and mmn bumps?

I had one conflict with Yann adding some thread_local stuff into a change you 
had made, so that did not revert cleanly.
And breakage is always around our APLOGNO, since people tend to add the tagged 
code and updated docs/log-message-tags/next-number in the same revision.

> 
> I’m stuck at this point, what do I do to move forward?

1. It was all done in subversion. The git PR is just their UI view.
2. Reapply all safe changes that I was not sure about. It should be possible to 
merge the original revision again.
3. Then the PR should show only the changes that we need to find a solution
   for.

That's how I would do it.

Kind Regards,
Stefan

> 
> Regards,
> Graham
> —
> 

Re: mpm event assertion failures

[Graham Leggett]

On 07 Feb 2022, at 12:18, Stefan Eissing  wrote:

>>> Is the http2 code doing anything to work around mod_ssl trying to read, 
>>> failing, throwing away the error, and then pretending nothing happened?
>> 
>> The http2 code doesn't try to work around mod_ssl, instead it does the same 
>> as mod_ssl, which is that it performs an operation but throws away the error:
>> 
>> https://github.com/apache/httpd/blob/1598f7aebd59acc7494389a3903a33c5e38a5460/modules/http2/h2_c2.c#L632
>> 
>> This hook is sorted APR_HOOK_FIRST, which means h2_c2_hook_process() runs 
>> first, then passes the connection to mod_ssl, which then returns AGAIN, but 
>> AGAIN is now thrown away inside h2_c2_hook_process(), and now we’re off the 
>> rails from this point on and we can expect our socket to be stuck in a weird 
>> state.
>> 
>> The http1 code has the same problem, but runs APR_HOOK_LAST, which means 
>> mod_ssl’s handshake is completely done before http1 touches the connection.
>> 
>> I think to fix this test, we need to make sure http2 runs after mod_ssl.
> 
> It does.
> 
> h2_c1.c:
> 
> static const char* const mod_reqtimeout[] = { "mod_ssl.c", 
> "mod_reqtimeout.c", NULL};
> 
> void h2_c1_register_hooks(void)
> {
>/* Our main processing needs to run quite late. Definitely after mod_ssl,
> * as we need its connection filters, but also before reqtimeout as its
> * method of timeouts is specific to HTTP/1.1 (as of now).
> * The core HTTP/1 processing run as REALLY_LAST, so we will have
> * a chance to take over before it.
> */
>ap_hook_process_connection(h2_c1_hook_process_connection,
>   mod_reqtimeout, NULL, APR_HOOK_LAST);
>...
> 
> 
> In my understanding this is how it should work. When mod_ssl's 
> process_connection fails, it should return OK to prevent further hooks to run.
> 
> AP_IMPLEMENT_HOOK_RUN_FIRST(int,process_connection,(conn_rec *c),(c),DECLINED)
> 
> process_connection is a RUN_FIRST. So the first hook that returns OK, 
> terminates it.
> 
> If mod_ssl returns OK in case of handshake errors, the connection is done. 
> That is my read of it.

There are two parts that hook into the process_connection hook, the code you’ve 
cited above, and this code:

void h2_c2_register_hooks(void)
{
/* When the connection processing actually starts, we might
 * take over, if the connection is for a h2 stream.
 */
ap_hook_process_connection(h2_c2_hook_process,
   NULL, NULL, APR_HOOK_FIRST);

Looks like this code is running before mod_ssl somehow.

Is there a way to run the httpd under test in either lldb or gdb?

Regards,
Graham
—

Re: Python test suite - failures on Fedora Rawhide / MacOS

[Graham Leggett]

On 07 Feb 2022, at 12:23, Stefan Eissing  wrote:

> could you attach a complete failed output of your pytest run? I use it on 
> MacOS all the time and
> it seems most likely that some prerequisites have not been documented well 
> enough or checks must
> add more information in output.

I reduced the tests to http2 only:

pytest test/modules/http2

and got this as a short summary:

 short test summary 
info =
FAILED 
test/modules/http2/test_002_curl_basics.py::TestCurlBasics::test_h2_002_04 - 
AssertionError: assert 'HTTP/1.1' == 'HTTP/2'
FAILED 
test/modules/http2/test_002_curl_basics.py::TestCurlBasics::test_h2_002_04b - 
AssertionError: assert 'HTTP/1.1' == 'HTTP/2'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_01 - 
AssertionError: assert 'HTTP/1.1' == 'HTTP/2.0'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_02 - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_21 - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_30[/004.html] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED 
test/modules/http2/test_003_get.py::TestGet::test_h2_003_30[/proxy/004.html] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED 
test/modules/http2/test_003_get.py::TestGet::test_h2_003_30[/h2proxy/004.html] 
- AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_31[/004.html] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED 
test/modules/http2/test_003_get.py::TestGet::test_h2_003_31[/proxy/004.html] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED 
test/modules/http2/test_003_get.py::TestGet::test_h2_003_31[/h2proxy/004.html] 
- AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_40 - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[0] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[1] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[1291] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[1292] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[8] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[80123] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[81087] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_41[98452] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_003_get.py::TestGet::test_h2_003_50[/004.html] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED 
test/modules/http2/test_003_get.py::TestGet::test_h2_003_50[/proxy/004.html] - 
AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED 
test/modules/http2/test_003_get.py::TestGet::test_h2_003_50[/h2proxy/004.html] 
- AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_004_post.py::TestPost::test_h2_004_07[HTTP2-on] 
- AssertionError: assert None
FAILED 
test/modules/http2/test_004_post.py::TestPost::test_h2_004_07[H2PUSH-off] - 
AssertionError: assert None
FAILED 
test/modules/http2/test_004_post.py::TestPost::test_h2_004_07[H2_STREAM_ID-1] - 
AssertionError: assert None
FAILED 
test/modules/http2/test_004_post.py::TestPost::test_h2_004_07[H2_STREAM_TAG-\\d+-1]
 - AssertionError: assert None
FAILED test/modules/http2/test_100_conn_reuse.py::TestConnReuse::test_h2_100_01 
- AssertionError: assert '2' == '1.1'
FAILED test/modules/http2/test_100_conn_reuse.py::TestConnReuse::test_h2_100_02 
- AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED test/modules/http2/test_100_conn_reuse.py::TestConnReuse::test_h2_100_03 
- AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
FAILED 
test/modules/http2/test_101_ssl_reneg.py::TestSslRenegotiation::test_h2_101_02 
- AssertionError: assert None
FAILED 
test/modules/http2/test_101_ssl_reneg.py::TestSslRenegotiation::test_h2_101_03 
- AssertionError: assert None
FAILED 
test/modules/http2/test_101_ssl_reneg.py::TestSslRenegotiation::test_h2_101_04 
- AssertionError: assert None
FAILED 
test/modules/http2/test_101_ssl_reneg.py::TestSslRenegotiation::test_h2_101_11 
- AssertionError: assert None
FAILED test/modules/http2/test_102_require.py::TestRequire::test_h2_102_01 - 
assert 404 == 403
FAILED test/modules/http2/test_102_require.py::TestRequire::test_h2_102_02 - 
assert 403 == 404
FAILED test/modules/http2/test_105_timeout.py::TestTimeout::test_h2_105_1

Re: Python test suite - failures on Fedora Rawhide / MacOS

[Stefan Eissing]

Graham,

could you attach a complete failed output of your pytest run? I use it on MacOS 
all the time and
it seems most likely that some prerequisites have not been documented well 
enough or checks must
add more information in output.

Kind Regards,
Stefan


> Am 07.02.2022 um 11:14 schrieb Graham Leggett :
> 
> Hi all,
> 
> I am not having any luck getting the python test suite to run on either MacOS 
> or Rawhide.
> 
> In the case of MacOS I see this:
> 
> == 50 failed, 214 passed, 239 skipped, 195 
> errors in 282.97s (0:04:42) ===
> 
> A selection of errors:
> 
> E   AssertionError: received response not in 3 chunks, but 4
> 
> E   AssertionError: assert 'keep-alive' not in {'accept-ranges': 'bytes', 
> 'connection': 'Upgrade, Keep-Alive', 'content-length': '543', 'content-type': 
> 'text/html', …}
> 
> E   assert 431 == 400
> 
> E   AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
> E - HTTP/1.1
> E + HTTP/2
> 
> E   AssertionError: assert None
> E+  where None = ('HTTP_1_1_REQUIRED 
> \\(err 13\\)', '* Added ssl.tests.httpd.apache.org:5001:127.0.0.1 to DNS 
> cache\n* Hostname ssl.tests.httpd.apache.org was found in DN...ta]\n* OpenSSL 
> SSL_read: error:0A000410:SSL routines::sslv3 alert handshake failure, errno 
> 0\n* Closing connection 0\n')
> E+where  = re.search
> E+and   '* Added ssl.tests.httpd.apache.org:5001:127.0.0.1 to DNS 
> cache\n* Hostname ssl.tests.httpd.apache.org was found in DN...ta]\n* OpenSSL 
> SSL_read: error:0A000410:SSL routines::sslv3 alert handshake failure, errno 
> 0\n* Closing connection 0\n' = ExecResult[code=56, args=['curl', '-s', 
> '--path-as-is', '-D', 
> '/Users/minfrin/src/apache/sandbox/httpd/httpd-trunk6/te... data]\n* OpenSSL 
> SSL_read: error:0A000410:SSL routines::sslv3 alert handshake failure, errno 
> 0\n* Closing connection 0\n].stderr
> 
> In the case of Rawhide we have this:
> 
> = 3 failed, 262 passed, 238 
> skipped, 195 errors in 539.82s (0:08:59) 
> ==
> 
> E   FileNotFoundError: [Errno 2] No such file or directory: 
> ‘openssl'
> 
> E   FileNotFoundError: [Errno 2] No such file or directory: 
> ‘pebble'
> 
> Has anyone else had any luck?
> 
> Regards,
> Graham
> —
> 

Re: mpm event assertion failures

[Stefan Eissing]

> Am 06.02.2022 um 23:00 schrieb Graham Leggett :
> 
> On 25 Jan 2022, at 23:25, Graham Leggett  wrote:
> 
>> Is the http2 code doing anything to work around mod_ssl trying to read, 
>> failing, throwing away the error, and then pretending nothing happened?
> 
> The http2 code doesn't try to work around mod_ssl, instead it does the same 
> as mod_ssl, which is that it performs an operation but throws away the error:
> 
> https://github.com/apache/httpd/blob/1598f7aebd59acc7494389a3903a33c5e38a5460/modules/http2/h2_c2.c#L632
> 
> This hook is sorted APR_HOOK_FIRST, which means h2_c2_hook_process() runs 
> first, then passes the connection to mod_ssl, which then returns AGAIN, but 
> AGAIN is now thrown away inside h2_c2_hook_process(), and now we’re off the 
> rails from this point on and we can expect our socket to be stuck in a weird 
> state.
> 
> The http1 code has the same problem, but runs APR_HOOK_LAST, which means 
> mod_ssl’s handshake is completely done before http1 touches the connection.
> 
> I think to fix this test, we need to make sure http2 runs after mod_ssl.

It does.

h2_c1.c:

static const char* const mod_reqtimeout[] = { "mod_ssl.c", "mod_reqtimeout.c", 
NULL};

void h2_c1_register_hooks(void)
{
/* Our main processing needs to run quite late. Definitely after mod_ssl,
 * as we need its connection filters, but also before reqtimeout as its
 * method of timeouts is specific to HTTP/1.1 (as of now).
 * The core HTTP/1 processing run as REALLY_LAST, so we will have
 * a chance to take over before it.
 */
ap_hook_process_connection(h2_c1_hook_process_connection,
   mod_reqtimeout, NULL, APR_HOOK_LAST);
...


In my understanding this is how it should work. When mod_ssl's 
process_connection fails, it should return OK to prevent further hooks to run.

AP_IMPLEMENT_HOOK_RUN_FIRST(int,process_connection,(conn_rec *c),(c),DECLINED)

process_connection is a RUN_FIRST. So the first hook that returns OK, 
terminates it.

If mod_ssl returns OK in case of handshake errors, the connection is done. That 
is my read of it.

Kind Regards,
Stefan

> Regards,
> Graham
> —
> 

Python test suite - failures on Fedora Rawhide / MacOS

[Graham Leggett]

Hi all,

I am not having any luck getting the python test suite to run on either MacOS 
or Rawhide.

In the case of MacOS I see this:

== 50 failed, 214 passed, 239 skipped, 195 
errors in 282.97s (0:04:42) ===

A selection of errors:

E   AssertionError: received response not in 3 chunks, but 4

E   AssertionError: assert 'keep-alive' not in {'accept-ranges': 'bytes', 
'connection': 'Upgrade, Keep-Alive', 'content-length': '543', 'content-type': 
'text/html', …}

E   assert 431 == 400

E   AssertionError: assert 'HTTP/2' == 'HTTP/1.1'
E - HTTP/1.1
E + HTTP/2

E   AssertionError: assert None
E+  where None = ('HTTP_1_1_REQUIRED 
\\(err 13\\)', '* Added ssl.tests.httpd.apache.org:5001:127.0.0.1 to DNS 
cache\n* Hostname ssl.tests.httpd.apache.org was found in DN...ta]\n* OpenSSL 
SSL_read: error:0A000410:SSL routines::sslv3 alert handshake failure, errno 
0\n* Closing connection 0\n')
E+where  = re.search
E+and   '* Added ssl.tests.httpd.apache.org:5001:127.0.0.1 to DNS 
cache\n* Hostname ssl.tests.httpd.apache.org was found in DN...ta]\n* OpenSSL 
SSL_read: error:0A000410:SSL routines::sslv3 alert handshake failure, errno 
0\n* Closing connection 0\n' = ExecResult[code=56, args=['curl', '-s', 
'--path-as-is', '-D', 
'/Users/minfrin/src/apache/sandbox/httpd/httpd-trunk6/te... data]\n* OpenSSL 
SSL_read: error:0A000410:SSL routines::sslv3 alert handshake failure, errno 
0\n* Closing connection 0\n].stderr

In the case of Rawhide we have this:

= 3 failed, 262 passed, 238 
skipped, 195 errors in 539.82s (0:08:59) 
==

E   FileNotFoundError: [Errno 2] No such file or directory: 
‘openssl'

E   FileNotFoundError: [Errno 2] No such file or directory: ‘pebble'

Has anyone else had any luck?

Regards,
Graham
—

Re: svn commit: r1897458 - in /httpd/httpd/trunk: changes-entries/ab-ssl-sense-fix.txt support/ab.c

[Graham Leggett]

On 27 Jan 2022, at 09:53, Ruediger Pluem  wrote:

>> Modified: httpd/httpd/trunk/support/ab.c
>> URL: 
>> http://svn.apache.org/viewvc/httpd/httpd/trunk/support/ab.c?rev=1897458&r1=1897457&r2=1897458&view=diff
>>  
>> 
>> ==
>> --- httpd/httpd/trunk/support/ab.c (original)
>> +++ httpd/httpd/trunk/support/ab.c Tue Jan 25 15:54:22 2022
> 
>> @@ -810,9 +811,6 @@ static void ssl_proceed_handshake(struct
>> 
>> static void write_request(struct connection * c)
>> {
>> -if (started >= requests) {
>> -return;
>> -}
> 
> Why is this no longer needed?

It’s in the wrong place, this has been moved one level up. 

>> do {
>> apr_time_t tnow;
> 
>> @@ -1461,7 +1465,6 @@ static void start_connect(struct connect
>> }
>> 
>> /* connected first time */
>> -set_conn_state(c, STATE_CONNECTED);
> 
> Why don't we set the state to connected any longer?
> 
>> #ifdef USE_SSL
>> if (c->ssl) {
>> ssl_proceed_handshake(c);

…because directly after being set, ssl_proceed_handshake() or read_connection() 
sets the state to something else.

Part of the confusion is that these states represent how the code needs to 
react after the poll. It seems in a number of places they were being set 
arbitrarily where it didn’t make sense.

>> @@ -1786,7 +1799,7 @@ read_more:
>> c->read = c->bread = 0;
>> /* zero connect time with keep-alive */
>> c->start = c->connect = lasttime = apr_time_now();
>> -set_conn_state(c, STATE_CONNECTED);
> 
> Why don't we set the state to connected any longer?
> 
>> +
>> write_request(c);

Again, directly after being set, write_request() sets it to something else.

>> }
>> }
> 
>> @@ -2048,7 +2077,7 @@ static void test(void)
>> continue;
>> }
>> else {
>> -set_conn_state(c, STATE_CONNECTED);
> 
> Why don't we set the state to connected any longer?
> 
>> +
>> #ifdef USE_SSL
>> if (c->ssl)
>> ssl_proceed_handshake(c);

Same reason as above.

Regards,
Graham
—