You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Petr Sumbera <pe...@oracle.com> on 2016/04/18 11:40:57 UTC
mod_http2 - h2_session(): conn error -> shutdown
Hi,
I'm playing with mod_http2 on Solaris (now with version 2.4.20). And I'm
getting following error (and I believe it worked for me with 2.4.17).
Any idea?
Thanks,
Petr
[Mon Apr 18 09:27:20.217807 2016] [ssl:info] [pid 1834:tid 51] [client
10.163.21.188:54836] AH01964: Connection to child 151 established
(server 127.0.0.1:443)
[Mon Apr 18 09:27:20.219607 2016] [ssl:debug] [pid 1834:tid 51]
ssl_engine_kernel.c(2105): [client 10.163.21.188:54836] AH02044: No
matching SSL virtual host for servername virtuals63.cz.oracle.com found
(using default/first virtual host)
[Mon Apr 18 09:27:20.219695 2016] [core:debug] [pid 1834:tid 51]
protocol.c(1890): [client 10.163.21.188:54836] AH03155: select protocol
from h2,h2c,http/1.1, choices=h2-16,h2-15,h2-14,h2,spdy/3.1,http/1.1 for
server 127.0.0.1
[Mon Apr 18 09:27:20.219872 2016] [core:debug] [pid 1834:tid 51]
protocol.c(1934): [client 10.163.21.188:54836] AH03156: select protocol,
proposals=h2,http/1.1 preferences=h2,h2c,http/1.1 configured=h2,h2c,http/1.1
[Mon Apr 18 09:27:20.219937 2016] [core:debug] [pid 1834:tid 51]
protocol.c(1954): [client 10.163.21.188:54836] AH03157: selected protocol=h2
[Mon Apr 18 09:27:20.220048 2016] [ssl:debug] [pid 1834:tid 51]
ssl_engine_kernel.c(2105): [client 10.163.21.188:54836] AH02044: No
matching SSL virtual host for servername virtuals63.cz.oracle.com found
(using default/first virtual host)
[Mon Apr 18 09:27:20.232028 2016] [ssl:debug] [pid 1834:tid 51]
ssl_engine_kernel.c(2023): [client 10.163.21.188:54836] AH02041:
Protocol: TLSv1.2, Cipher: AES128-SHA (128/128 bits)
[Mon Apr 18 09:27:20.232468 2016] [http2:debug] [pid 1834:tid 51]
h2_session.c(955): [client 10.163.21.188:54836] AH03200: h2_session(151)
created, max_streams=100, stream_mem=65536, workers_limit=4,
workers_max=25, push_diary(type=1,N=256)
[Mon Apr 18 09:27:20.232630 2016] [http2:debug] [pid 1834:tid 51]
h2_session.c(1063): [client 10.163.21.188:54836] AH03201:
h2_session(151): start, INITIAL_WINDOW_SIZE=65535,
MAX_CONCURRENT_STREAMS=100
[Mon Apr 18 09:27:20.232724 2016] [http2:debug] [pid 1834:tid 51]
h2_session.c(2093): [client 10.163.21.188:54836] AH03079:
h2_session(151): started on 127.0.0.1:443
[Mon Apr 18 09:27:20.232783 2016] [http2:debug] [pid 1834:tid 51]
h2_session.c(1762): [client 10.163.21.188:54836] AH03078:
h2_session(151): transit [INIT] -- init --> [BUSY]
[Mon Apr 18 09:27:20.232969 2016] [http2:debug] [pid 1834:tid 51]
h2_session.c(647): [client 10.163.21.188:54836] AH03068:
h2_session(151): sent FRAME[SETTINGS[length=6, stream=0]], frames=0/0 (r/s)
[Mon Apr 18 09:27:20.233034 2016] [http2:debug] [pid 1834:tid 51]
h2_session.c(647): [client 10.163.21.188:54836] AH03068:
h2_session(151): sent FRAME[WINDOW_UPDATE[stream=0, incr=2147418112]],
frames=0/1 (r/s)
[Mon Apr 18 09:27:20.233203 2016] [http2:debug] [pid 1834:tid 51]
h2_session.c(1762): [client 10.163.21.188:54836] AH03078:
h2_session(151): transit [BUSY] -- no io --> [IDLE]
[Mon Apr 18 09:27:20.255871 2016] [http2:debug] [pid 1834:tid 51]
h2_session.c(1830): [client 10.163.21.188:54836] h2_session(151): conn
error -> shutdown
[Mon Apr 18 09:27:20.255956 2016] [http2:debug] [pid 1834:tid 51]
h2_session.c(647): [client 10.163.21.188:54836] AH03068:
h2_session(151): sent FRAME[GOAWAY[error=0, reason='error',
last_stream=0]], frames=0/2 (r/s)
[Mon Apr 18 09:27:20.256161 2016] [http2:debug] [pid 1834:tid 51]
h2_session.c(758): [client 10.163.21.188:54836] AH03069: session(151):
sent GOAWAY, err=0, msg=error
[Mon Apr 18 09:27:20.256223 2016] [http2:debug] [pid 1834:tid 51]
h2_session.c(1762): [client 10.163.21.188:54836] AH03078:
h2_session(151): transit [IDLE] -- local goaway --> [DONE]
[Mon Apr 18 09:27:20.256312 2016] [http2:debug] [pid 1834:tid 51]
h2_mplx.c(439): [client 10.163.21.188:54836] AH03056: h2_mplx(151):
release_join -> destroy
[Mon Apr 18 09:27:20.256437 2016] [http2:debug] [pid 1834:tid 51]
h2_conn.c(213): (70014)End of file found: [client 10.163.21.188:54836]
AH03045: h2_session(151): process, closing conn
[Mon Apr 18 09:27:20.256591 2016] [ssl:debug] [pid 1834:tid 51]
ssl_engine_io.c(1029): [client 10.163.21.188:54836] AH02001: Connection
closed to child 151 with standard shutdown (server 127.0.0.1:443)
Re: mod_http2 - h2_session(): conn error -> shutdown
Posted by Stefan Eissing <st...@greenbytes.de>.
At this location:
> [Mon Apr 18 09:27:20.255871 2016] [http2:debug] [pid 1834:tid 51] h2_session.c(1830): [client 10.163.21.188:54836] h2_session(151): conn error -> shutdown
mod_http2 has tried a read with a 1 second timeout on the connection and got a return code that it does not recognize. It conservatively interprets that as connection error and shuts it down.
I can make a patch that logs the return code more verbose so we could see what gets returned. Interested?
Thanks,
Stefan
> Am 18.04.2016 um 11:40 schrieb Petr Sumbera <pe...@oracle.com>:
>
> Hi,
>
> I'm playing with mod_http2 on Solaris (now with version 2.4.20). And I'm getting following error (and I believe it worked for me with 2.4.17). Any idea?
>
> Thanks,
>
> Petr
>
> [Mon Apr 18 09:27:20.217807 2016] [ssl:info] [pid 1834:tid 51] [client 10.163.21.188:54836] AH01964: Connection to child 151 established (server 127.0.0.1:443)
> [Mon Apr 18 09:27:20.219607 2016] [ssl:debug] [pid 1834:tid 51] ssl_engine_kernel.c(2105): [client 10.163.21.188:54836] AH02044: No matching SSL virtual host for servername virtuals63.cz.oracle.com found (using default/first virtual host)
> [Mon Apr 18 09:27:20.219695 2016] [core:debug] [pid 1834:tid 51] protocol.c(1890): [client 10.163.21.188:54836] AH03155: select protocol from h2,h2c,http/1.1, choices=h2-16,h2-15,h2-14,h2,spdy/3.1,http/1.1 for server 127.0.0.1
> [Mon Apr 18 09:27:20.219872 2016] [core:debug] [pid 1834:tid 51] protocol.c(1934): [client 10.163.21.188:54836] AH03156: select protocol, proposals=h2,http/1.1 preferences=h2,h2c,http/1.1 configured=h2,h2c,http/1.1
> [Mon Apr 18 09:27:20.219937 2016] [core:debug] [pid 1834:tid 51] protocol.c(1954): [client 10.163.21.188:54836] AH03157: selected protocol=h2
> [Mon Apr 18 09:27:20.220048 2016] [ssl:debug] [pid 1834:tid 51] ssl_engine_kernel.c(2105): [client 10.163.21.188:54836] AH02044: No matching SSL virtual host for servername virtuals63.cz.oracle.com found (using default/first virtual host)
> [Mon Apr 18 09:27:20.232028 2016] [ssl:debug] [pid 1834:tid 51] ssl_engine_kernel.c(2023): [client 10.163.21.188:54836] AH02041: Protocol: TLSv1.2, Cipher: AES128-SHA (128/128 bits)
> [Mon Apr 18 09:27:20.232468 2016] [http2:debug] [pid 1834:tid 51] h2_session.c(955): [client 10.163.21.188:54836] AH03200: h2_session(151) created, max_streams=100, stream_mem=65536, workers_limit=4, workers_max=25, push_diary(type=1,N=256)
> [Mon Apr 18 09:27:20.232630 2016] [http2:debug] [pid 1834:tid 51] h2_session.c(1063): [client 10.163.21.188:54836] AH03201: h2_session(151): start, INITIAL_WINDOW_SIZE=65535, MAX_CONCURRENT_STREAMS=100
> [Mon Apr 18 09:27:20.232724 2016] [http2:debug] [pid 1834:tid 51] h2_session.c(2093): [client 10.163.21.188:54836] AH03079: h2_session(151): started on 127.0.0.1:443
> [Mon Apr 18 09:27:20.232783 2016] [http2:debug] [pid 1834:tid 51] h2_session.c(1762): [client 10.163.21.188:54836] AH03078: h2_session(151): transit [INIT] -- init --> [BUSY]
> [Mon Apr 18 09:27:20.232969 2016] [http2:debug] [pid 1834:tid 51] h2_session.c(647): [client 10.163.21.188:54836] AH03068: h2_session(151): sent FRAME[SETTINGS[length=6, stream=0]], frames=0/0 (r/s)
> [Mon Apr 18 09:27:20.233034 2016] [http2:debug] [pid 1834:tid 51] h2_session.c(647): [client 10.163.21.188:54836] AH03068: h2_session(151): sent FRAME[WINDOW_UPDATE[stream=0, incr=2147418112]], frames=0/1 (r/s)
> [Mon Apr 18 09:27:20.233203 2016] [http2:debug] [pid 1834:tid 51] h2_session.c(1762): [client 10.163.21.188:54836] AH03078: h2_session(151): transit [BUSY] -- no io --> [IDLE]
> [Mon Apr 18 09:27:20.255871 2016] [http2:debug] [pid 1834:tid 51] h2_session.c(1830): [client 10.163.21.188:54836] h2_session(151): conn error -> shutdown
> [Mon Apr 18 09:27:20.255956 2016] [http2:debug] [pid 1834:tid 51] h2_session.c(647): [client 10.163.21.188:54836] AH03068: h2_session(151): sent FRAME[GOAWAY[error=0, reason='error', last_stream=0]], frames=0/2 (r/s)
> [Mon Apr 18 09:27:20.256161 2016] [http2:debug] [pid 1834:tid 51] h2_session.c(758): [client 10.163.21.188:54836] AH03069: session(151): sent GOAWAY, err=0, msg=error
> [Mon Apr 18 09:27:20.256223 2016] [http2:debug] [pid 1834:tid 51] h2_session.c(1762): [client 10.163.21.188:54836] AH03078: h2_session(151): transit [IDLE] -- local goaway --> [DONE]
> [Mon Apr 18 09:27:20.256312 2016] [http2:debug] [pid 1834:tid 51] h2_mplx.c(439): [client 10.163.21.188:54836] AH03056: h2_mplx(151): release_join -> destroy
> [Mon Apr 18 09:27:20.256437 2016] [http2:debug] [pid 1834:tid 51] h2_conn.c(213): (70014)End of file found: [client 10.163.21.188:54836] AH03045: h2_session(151): process, closing conn
> [Mon Apr 18 09:27:20.256591 2016] [ssl:debug] [pid 1834:tid 51] ssl_engine_io.c(1029): [client 10.163.21.188:54836] AH02001: Connection closed to child 151 with standard shutdown (server 127.0.0.1:443)