Apache 2.4.25 mod_http2 NGHTTP2 1.17.0 Bug?

Started by nono303, December 20, 2016, 05:17:08 PM

Previous topic - Next topic

nono303

Hi,

I've just upgraded my version of apache from 2.4.23 to 2.4.25 (vc14 x64) and I've noticed a bug? relating to mod_http2.
According to changelog https://www.apachehaus.com/forum/index.php?topic=1396.msg3626#msg3626 nghttp2 had been upgraded to 1.17.0 from 1.12.0
=> [http2:info] AH03090: mod_http2 (v1.8.3, feats=, nghttp2 1.17.0), initializing...

In my case, I've multiple ssl vhost with 'H2Direct on' & 'Protocols h2 http/1.1' directives (all working fine with 2.4.23) but since upgrade, all (but only) location with 'Options +Indexes' directive fail to work (unable to connect from browser)
Downgrading only mod_http2.so with the 2.4.23 one (on a 2.4.25 httpd binary) solve the issue.


  • WORKING : mod_http2.so (nghttp2 1.12.0 from 2.4.23 vc14 x64 distrib) SHA-1: 296f024c98e95ca3e72d0108ff39e75edf7640fd
  • FAILING : mod_http2.so (nghttp2 1.17.0 from 2.4.25 vc14 x64 distrib) SHA-1: b48733e6efa8431fab4026370329491607949cce
Please find debug log (curl client and Apache2.4.25 http2:debug) below

Can you reproduce this on your side? Have you any idea of any configuration mistake?

Don't hesitate to ask for more details or tests and thanks in advance for your feedback on this issue.

Regards,

Arnaud
-------
WORKING
curl client verbose trace

* STATE: INIT => CONNECT handle 0x80068520; line 1407 (connection #-5000)
* Added connection 0. The cache now contains 1 members
*   Trying 192.168.30.18...
* TCP_NODELAY set
* STATE: CONNECT => WAITCONNECT handle 0x80068520; line 1460 (connection #0)
* Connected to mydomain.com (192.168.30.18) port 443 (#0)
* STATE: WAITCONNECT => SENDPROTOCONNECT handle 0x80068520; line 1567 (connection #0)
* Marked for [keep alive]: HTTP default
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
*   CAfile: /etc/pki/tls/certs/ca-bundle.crt
  CApath: none
* TLSv1.2 (OUT), TLS header, Certificate Status (22):
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* STATE: SENDPROTOCONNECT => PROTOCONNECT handle 0x80068520; line 1581 (connection #0)
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=FR; CN=mydomain.com
*  start date: Jun 14 08:50:22 2016 GMT
*  expire date: Jun 14 08:50:22 2017 GMT
*  subjectAltName: host "mydomain.com" matched cert's "mydomain.com"
*  issuer: C=IL; O=StartCom Ltd.; OU=StartCom Certification Authority; CN=StartCom Class 1 DV Server CA
*  SSL certificate verify ok.
* STATE: PROTOCONNECT => DO handle 0x80068520; line 1602 (connection #0)
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* nghttp2_session_mem_recv() returns 0
* http2_send len=79
* h2 header: :method:GET
* h2 header: :path:/
* h2 header: :scheme:https
* h2 header: :authority:mydomain.com
* h2 header: User-Agent:curl/7.51.0
* h2 header: Accept:*/*
* Using Stream ID: 1 (easy handle 0x80068520)
* before_frame_send() was called
* on_frame_send() was called, length = 31
> GET / HTTP/1.1
> Host: mydomain.com
> User-Agent: curl/7.51.0
> Accept: */*
>
* STATE: DO => DO_DONE handle 0x80068520; line 1664 (connection #0)
* multi changed, check CONNECT_PEND queue!
* STATE: DO_DONE => WAITPERFORM handle 0x80068520; line 1791 (connection #0)
* STATE: WAITPERFORM => PERFORM handle 0x80068520; line 1801 (connection #0)
* http2_recv: easy 0x80068520 (stream 1)
* nread=37
* Got SETTINGS
* MAX_CONCURRENT_STREAMS == 100
* ENABLE_PUSH == TRUE
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
* Got SETTINGS
* MAX_CONCURRENT_STREAMS == 100
* ENABLE_PUSH == TRUE
* nghttp2_session_mem_recv() returns 37
* All data in connection buffer processed
* http2_recv returns AGAIN for stream 1
* multi changed, check CONNECT_PEND queue!
* http2_recv: easy 0x80068520 (stream 1)
* nread=1300
* on_begin_headers() was called
* h2 status: HTTP/2 200 (easy 0x80068520)
* h2 header: date: Tue, 20 Dec 2016 15:03:18 GMT
* h2 header: server: Apache
* h2 header: strict-transport-security: max-age=15768000; includeSubDomains
* h2 header: last-modified: Tue, 20 Dec 2016 13:59:34 GMT
* h2 header: vary: Accept-Encoding,User-Agent
* h2 header: content-type: text/html;charset=UTF-8
* on_frame_recv() header 1 stream 1
* Store 251 bytes headers from stream 1 at 0x80068b04
* 1158 data received for stream 1 (14975 left in buffer 0x80068b04, total 1409)
* nghttp2_session_mem_recv() returns 1300
* All data in connection buffer processed
* http2_recv: returns 1409 for stream 1
* HTTP/2 found, allow multiplexing
< HTTP/2 200

Apache2.4.25 with mod_http2 nghttp2 1.12.0 verbose trace

h2_session: AH03200: h2_session: created, max_streams=100, stream_mem=65536, workers_limit=4, workers_max=100, push_diary(type=0,N=256)
h2_session: AH03201: h2_session: start, INITIAL_WINDOW_SIZE=65535, MAX_CONCURRENT_STREAMS=100
h2_session: AH03079: h2_session: started on mydomain.com:443
h2_session: AH03078: h2_session: transit [INIT] -- init --> [BUSY]
h2_session: AH03068: h2_session: sent FRAME[SETTINGS[length=6, stream=0]], frames=0/0 (r/s)
h2_session: AH03068: h2_session: sent FRAME[WINDOW_UPDATE[stream=0, incr=2147418112]], frames=0/1 (r/s)
h2_session: AH03078: h2_session: transit [BUSY] -- no io (keepalive) --> [IDLE]
h2_session: AH03066: h2_session: recv FRAME[SETTINGS[length=0, stream=0]], frames=0/2 (r/s)
h2_session: AH03078: h2_session: transit [IDLE] -- data read --> [BUSY]
h2_session: AH03068: h2_session: sent FRAME[SETTINGS[ack=1, stream=0]], frames=1/2 (r/s)
h2_session: AH03078: h2_session: transit [BUSY] -- no io (keepalive) --> [IDLE]
h2_stream: AH03082: h2_stream: opened
h2_session: AH03066: h2_session: recv FRAME[HEADERS[length=31, hend=1, stream=1, eos=1]], frames=1/3 (r/s)
h2_session: AH03078: h2_session: transit [IDLE] -- data read --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03066: h2_session: recv FRAME[SETTINGS[ack=1, stream=0]], frames=2/3 (r/s)
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_session: AH03078: h2_session: transit [WAIT] -- wait cycle --> [BUSY]
h2_session: AH03078: h2_session: transit [BUSY] -- no io --> [WAIT]
h2_task: AH03348: h2_task: open response to GET mydomain.com /
h2_session: AH03078: h2_session: transit [WAIT] -- data read --> [BUSY]
h2_session: AH03073: h2_stream: submit response 200, REMOTE_WINDOW_SIZE=65535
h2_session: AH03068: h2_session: sent FRAME[HEADERS[length=124, hend=1, stream=1, eos=0]], frames=3/3 (r/s)
h2_session: AH03068: h2_session: sent FRAME[DATA[length=2909, flags=1, stream=1, padlen=0]], frames=3/4 (r/s)
h2_session: AH03078: h2_session: transit [BUSY] -- no io (flow wait) --> [IDLE]
h2_session: AH03401: h2_session: conn error -> shutdown
h2_session: AH03068: h2_session: sent FRAME[GOAWAY[error=0, reason='error', last_stream=1]], frames=3/5 (r/s)
h2_session: AH03069: session: sent GOAWAY, err=0, msg=error
h2_session: AH03078: h2_session: transit [IDLE] -- local goaway --> [DONE]
h2_conn: (70014)End of file found: AH03045: h2_session: process, closing conn


FAILING
curl client verbose trace

* STATE: INIT => CONNECT handle 0x80068520; line 1407 (connection #-5000)
* Added connection 0. The cache now contains 1 members
*   Trying 192.168.30.18...
* TCP_NODELAY set
* STATE: CONNECT => WAITCONNECT handle 0x80068520; line 1460 (connection #0)
* Connected to mydomain.com (192.168.30.18) port 443 (#0)
* STATE: WAITCONNECT => SENDPROTOCONNECT handle 0x80068520; line 1567 (connection #0)
* Marked for [keep alive]: HTTP default
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
*   CAfile: /etc/pki/tls/certs/ca-bundle.crt
  CApath: none
* TLSv1.2 (OUT), TLS header, Certificate Status (22):
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* STATE: SENDPROTOCONNECT => PROTOCONNECT handle 0x80068520; line 1581 (connection #0)
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=FR; CN=mydomain.com
*  start date: Jun 14 08:50:22 2016 GMT
*  expire date: Jun 14 08:50:22 2017 GMT
*  subjectAltName: host "mydomain.com" matched cert's "mydomain.com"
*  issuer: C=IL; O=StartCom Ltd.; OU=StartCom Certification Authority; CN=StartCom Class 1 DV Server CA
*  SSL certificate verify ok.
* STATE: PROTOCONNECT => DO handle 0x80068520; line 1602 (connection #0)
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* nghttp2_session_mem_recv() returns 0
* http2_send len=79
* h2 header: :method:GET
* h2 header: :path:/
* h2 header: :scheme:https
* h2 header: :authority:mydomain.com
* h2 header: User-Agent:curl/7.51.0
* h2 header: Accept:*/*
* Using Stream ID: 1 (easy handle 0x80068520)
* before_frame_send() was called
* on_frame_send() was called, length = 31
> GET / HTTP/1.1
> Host: mydomain.com
> User-Agent: curl/7.51.0
> Accept: */*
>
* STATE: DO => DO_DONE handle 0x80068520; line 1664 (connection #0)
* multi changed, check CONNECT_PEND queue!
* STATE: DO_DONE => WAITPERFORM handle 0x80068520; line 1791 (connection #0)
* STATE: WAITPERFORM => PERFORM handle 0x80068520; line 1801 (connection #0)
* http2_recv: easy 0x80068520 (stream 1)
* nread=37
* Got SETTINGS
* MAX_CONCURRENT_STREAMS == 100
* ENABLE_PUSH == TRUE
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
* Got SETTINGS
* MAX_CONCURRENT_STREAMS == 100
* ENABLE_PUSH == TRUE
* nghttp2_session_mem_recv() returns 37
* All data in connection buffer processed
* http2_recv returns AGAIN for stream 1
* multi changed, check CONNECT_PEND queue!
* http2_recv: easy 0x80068520 (stream 1)
* nread=13
* on_frame_recv() header 3 stream 1
* Got frame type 3 for stream 1!
* on_stream_close(), PROTOCOL_ERROR (err 1), stream 1
* Removed stream 1 hash!
* nghttp2_session_mem_recv() returns 13
* All data in connection buffer processed
* h2_process_pending_input: All data in connection buffer processed
* HTTP/2 stream 1 was not closed cleanly: PROTOCOL_ERROR (err 1)
* multi_done
* Curl_http_done: called premature == 1
* free header_recvbuf!!
* HTTP/2 DISCONNECT starts now
* HTTP/2 DISCONNECT done
* Closing connection 0
* The cache now contains 0 members
* TLSv1.2 (OUT), TLS alert, Client hello (1):
* Expire cleared
curl: (92) HTTP/2 stream 1 was not closed cleanly: PROTOCOL_ERROR (err 1)

Apache2.4.25 with mod_http2 nghttp2 1.17.0 verbose trace

h2_session: AH03200: h2_session: created, max_streams=100, stream_mem=65536, workers_limit=6, workers_max=100, push_diary(type=0,N=256)
h2_session: AH03201: h2_session: start, INITIAL_WINDOW_SIZE=65535, MAX_CONCURRENT_STREAMS=100
h2_session: AH03079: h2_session: started on mydomain.com:443
h2_session: AH03078: h2_session: transit [INIT] -- init --> [BUSY]
h2_session: AH03068: h2_session: sent FRAME[SETTINGS[length=6, stream=0]], frames=0/0 (r/s)
h2_session: AH03068: h2_session: sent FRAME[WINDOW_UPDATE[stream=0, incr=2147418112]], frames=0/1 (r/s)
h2_session: AH03078: h2_session: transit [BUSY] -- no io (keepalive) --> [IDLE]
h2_session: AH03066: h2_session: recv FRAME[SETTINGS[length=0, stream=0]], frames=0/2 (r/s)
h2_session: AH03078: h2_session: transit [IDLE] -- data read --> [BUSY]
h2_session: AH03068: h2_session: sent FRAME[SETTINGS[ack=1, stream=0]], frames=1/2 (r/s)
h2_session: AH03078: h2_session: transit [BUSY] -- no io (keepalive) --> [IDLE]
h2_stream: AH03082: h2_stream: opened
h2_session: AH03066: h2_session: recv FRAME[HEADERS[length=31, hend=1, stream=1, eos=1]], frames=1/3 (r/s)
h2_session: AH03078: h2_session: transit [IDLE] -- data read --> [BUSY]
h2_session: AH03066: h2_session: recv FRAME[SETTINGS[ack=1, stream=0]], frames=2/3 (r/s)
h2_task: AH03348: h2_task: open output to GET mydomain.com /
h2_session: AH03466: h2_stream: no response, RST_STREAM, err=1
h2_session: AH03068: h2_session: sent FRAME[RST_STREAM[length=4, flags=0, stream=1]], frames=3/3 (r/s)
h2_session: AH03065: h2_stream: closing with err=1 protocol error
h2_mplx: AH03385: h2_task: destroy output beam empty=1, holds proxies=0
h2_session: AH03078: h2_session: transit [BUSY] -- no io (keepalive) --> [IDLE]
h2_session: AH03401: h2_session: conn error -> shutdown
h2_session: AH03068: h2_session: sent FRAME[GOAWAY[error=0, reason='', last_stream=1]], frames=3/4 (r/s)
h2_session: AH03069: session: sent GOAWAY, err=0, msg=
h2_session: AH03078: h2_session: transit [IDLE] -- local goaway --> [DONE]
h2_conn: (70014)End of file found: AH03045: h2_session: process, closing conn

Gregg

I see you have posted this on the board at Apache Lounge and the module author is involved.
https://www.apachelounge.com/viewtopic.php?p=34692#34692


nono303


Davidshaky

Hello

Have you tried with a simple tcp bolean check on port 90 for example?

Regards
Ivo

.

nono303