[jetty-users] Jetty 9.3 negotiating to HTTP/1.1 instead of HTTP/2.0

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
[jetty-users] Jetty 9.3 negotiating to HTTP/1.1 instead of HTTP/2.0
From: bengreenberg <ben@xxxxxxxxxxxxxxxx>
Date: Tue, 24 Mar 2015 08:12:39 -0700 (PDT)
Delivered-to: jetty-users@xxxxxxxxxxx
List-archive: <https://dev.eclipse.org/mailman/private/jetty-users>
List-help: <mailto:jetty-users-request@eclipse.org?subject=help>
List-subscribe: <https://dev.eclipse.org/mailman/listinfo/jetty-users>, <mailto:jetty-users-request@eclipse.org?subject=subscribe>
List-unsubscribe: <https://dev.eclipse.org/mailman/options/jetty-users>, <mailto:jetty-users-request@eclipse.org?subject=unsubscribe>
Hi all,

I'm experimenting with the HTTP/2.0 features of Jetty 9.3 and running into
an issue I don't understand. I have a server running with the http2 module.
When I hit it using nghttp, I get a 2.0 connection. However, when I access
it using Chrome or curl, it is a 1.1 connection. I know curl works for
HTTP/2.0 because I can see it working when I hit webtide.com.

Curl -v output looks like this:

* Connected to localhost (127.0.0.1) port 8181 (#0)
* ALPN, offering h2-14, http/1.1
* TLSv1.2, TLS Unknown, Unknown (22):
* TLSv1.2, TLS handshake, Client hello (1):
* SSLv2, Unknown (22):
* TLSv1.2, TLS handshake, Server hello (2):
* TLSv1.2, TLS handshake, CERT (11):
* TLSv1.2, TLS handshake, Server key exchange (12):
* TLSv1.2, TLS handshake, Server finished (14):
* SSLv2, Unknown (22):
* TLSv1.2, TLS handshake, Client key exchange (16):
* SSLv2, Unknown (20):
* TLSv1.2, TLS change cipher, Client hello (1):
* SSLv2, Unknown (22):
* TLSv1.2, TLS handshake, Finished (20):
* SSLv2, Unknown (20):
* TLSv1.2, TLS change cipher, Client hello (1):
* SSLv2, Unknown (22):
* TLSv1.2, TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use http/1.1


The Jetty debug output is similar:

2015-03-24 11:08:53.372:DBUG:oejs.session:Scheduler-410424423: Scavenging
sessions at 1427209733372
2015-03-24
11:08:54.042:DBUG:oeji.ManagedSelector:qtp1401420256-21-acceptor-0@19c65cdc-ServerConnector@3c5a99da{SSL,[ssl,
alpn, http/1.1, h2-17, h2-16, h2-15, h2-14, h2]}{0.0.0.0:8181}: Queued
change org.eclipse.jetty.io.ManagedSelector$Accept@6abc8c85 on
org.eclipse.jetty.io.ManagedSelector@7ac296f6 id=3 keys=0 selected=0
2015-03-24 11:08:54.042:DBUG:oeji.ManagedSelector:qtp1401420256-22: Selector
loop woken up from select, 0/0 selected
2015-03-24 11:08:54.042:DBUG:oeji.ManagedSelector:qtp1401420256-22: Running
change org.eclipse.jetty.io.ManagedSelector$Accept@6abc8c85
2015-03-24 11:08:54.043:DBUG:oeji.ManagedSelector:qtp1401420256-22: Queued
change org.eclipse.jetty.io.ManagedSelector$CreateEndPoint@5816945d on
org.eclipse.jetty.io.ManagedSelector@7ac296f6 id=3 keys=1 selected=0
2015-03-24 11:08:54.043:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-22: EPR
Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945 produced
org.eclipse.jetty.io.ManagedSelector$CreateEndPoint@5816945d
2015-03-24 11:08:54.043:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-22: EPR
Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945 dispatch
2015-03-24 11:08:54.043:DBUG:oejut.QueuedThreadPool:qtp1401420256-22: queue
EPR Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945
2015-03-24 11:08:54.043:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-22: EPR
Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945 run
org.eclipse.jetty.io.ManagedSelector$CreateEndPoint@5816945d
2015-03-24 11:08:54.043:DBUG:oejut.QueuedThreadPool:qtp1401420256-95: run
EPR Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945
2015-03-24 11:08:54.043:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-95: EPR
Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945 run
2015-03-24 11:08:54.043:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-95: EPR
Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945 produce
enter
2015-03-24 11:08:54.043:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-95: EPR
Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945
producing
2015-03-24 11:08:54.043:DBUG:oeji.ManagedSelector:qtp1401420256-95: Selector
loop waiting on select
2015-03-24 11:08:54.043:DBUG:oeji.AbstractEndPoint:qtp1401420256-22: onOpen
SelectChannelEndPoint@498f2782{/127.0.0.1:55035<->8181,Open,in,out,-,-,0/30000,null}{io=0,kio=0,kro=0}
2015-03-24 11:08:54.043:DBUG:oeji.IdleTimeout:qtp1401420256-22:
SelectChannelEndPoint@498f2782{/127.0.0.1:55035<->8181,Open,in,out,-,-,0/30000,null}{io=0,kio=0,kro=0}
idle timeout check, elapsed: 0 ms, remaining: 30000 ms
2015-03-24 11:08:54.046:DBUG:oeji.IdleTimeout:qtp1401420256-22:
DecryptedEndPoint@1d16968b{/127.0.0.1:55035<->8181,Open,in,out,-,-,0/30000,null}->SelectChannelEndPoint@498f2782{/127.0.0.1:55035<->8181,Open,in,out,-,-,3/30000,null}{io=0,kio=0,kro=0}
idle timeout check, elapsed: 0 ms, remaining: 30000 ms
2015-03-24 11:08:54.046:DBUG:oeji.AbstractConnection:qtp1401420256-22:
onOpen SslConnection@5ba6f860{NEED_UNWRAP,eio=-1/-1,di=-1} ->
ALPNServerConnection@58ef714f
2015-03-24 11:08:54.046:DBUG:oeji.AbstractConnection:qtp1401420256-22:
onOpen ALPNServerConnection@58ef714f
2015-03-24 11:08:54.047:DBUG:oeji.AbstractConnection:qtp1401420256-22:
fillInterested ALPNServerConnection@58ef714f
2015-03-24 11:08:54.047:DBUG:oeji.FillInterest:qtp1401420256-22:
FillInterest@71e41617{true,AC.ReadCB@58ef714f{ALPNServerConnection@58ef714f}}
register AC.ReadCB@58ef714f{ALPNServerConnection@58ef714f}
2015-03-24 11:08:54.047:DBUG:oeji.FillInterest:qtp1401420256-22:
FillInterest@71e41617{true,AC.ReadCB@58ef714f{ALPNServerConnection@58ef714f}}
register AC.ReadCB@58ef714f{ALPNServerConnection@58ef714f}
2015-03-24 11:08:54.047:DBUG:oeji.AbstractConnection:qtp1401420256-22:
fillInterested SslConnection@5ba6f860{NEED_UNWRAP,eio=-1/-1,di=-1} ->
ALPNServerConnection@58ef714f
2015-03-24 11:08:54.047:DBUG:oeji.FillInterest:qtp1401420256-22:
FillInterest@74786046{true,AC.ReadCB@5ba6f860{SslConnection@5ba6f860{NEED_UNWRAP,eio=-1/-1,di=-1}
-> ALPNServerConnection@58ef714f}} register
AC.ReadCB@5ba6f860{SslConnection@5ba6f860{NEED_UNWRAP,eio=-1/-1,di=-1} ->
ALPNServerConnection@58ef714f}
2015-03-24 11:08:54.047:DBUG:oeji.FillInterest:qtp1401420256-22:
FillInterest@74786046{true,AC.ReadCB@5ba6f860{SslConnection@5ba6f860{NEED_UNWRAP,eio=-1/-1,di=-1}
-> ALPNServerConnection@58ef714f}} register
AC.ReadCB@5ba6f860{SslConnection@5ba6f860{NEED_UNWRAP,eio=-1/-1,di=-1} ->
ALPNServerConnection@58ef714f}
2015-03-24 11:08:54.047:DBUG:oeji.SelectChannelEndPoint:qtp1401420256-22:
changeInterests p=false 0->1 for
SelectChannelEndPoint@498f2782{/127.0.0.1:55035<->8181,Open,in,out,R,-,0/30000,SslConnection}{io=1,kio=0,kro=0}
2015-03-24 11:08:54.047:DBUG:oeji.ManagedSelector:qtp1401420256-22: Queued
change org.eclipse.jetty.io.SelectChannelEndPoint$1@1871e351 on
org.eclipse.jetty.io.ManagedSelector@7ac296f6 id=3 keys=1 selected=0
2015-03-24 11:08:54.047:DBUG:oeji.ManagedSelector:qtp1401420256-95: Selector
loop woken up from select, 0/1 selected
2015-03-24 11:08:54.047:DBUG:oeji.ManagedSelector:qtp1401420256-22: Created
SelectChannelEndPoint@498f2782{/127.0.0.1:55035<->8181,Open,in,out,R,-,0/30000,SslConnection}{io=1,kio=0,kro=0}
2015-03-24 11:08:54.047:DBUG:oeji.ManagedSelector:qtp1401420256-95: Running
change org.eclipse.jetty.io.SelectChannelEndPoint$1@1871e351
2015-03-24 11:08:54.047:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-22: EPR
Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945 ran
org.eclipse.jetty.io.ManagedSelector$CreateEndPoint@5816945d
2015-03-24 11:08:54.047:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-22: EPR
Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945 produce
exit
2015-03-24 11:08:54.047:DBUG:oejut.QueuedThreadPool:qtp1401420256-22: ran
org.eclipse.jetty.io.ManagedSelector@7ac296f6 id=3 keys=1 selected=0
2015-03-24 11:08:54.047:DBUG:oeji.SelectChannelEndPoint:qtp1401420256-95:
Key interests updated 0 -> 1 on
SelectChannelEndPoint@498f2782{/127.0.0.1:55035<->8181,Open,in,out,R,-,0/30000,SslConnection}{io=1,kio=1,kro=0}
2015-03-24 11:08:54.047:DBUG:oeji.ManagedSelector:qtp1401420256-95: Selector
loop waiting on select
2015-03-24 11:08:54.047:DBUG:oeji.ManagedSelector:qtp1401420256-95: Selector
loop woken up from select, 1/1 selected
2015-03-24 11:08:54.047:DBUG:oeji.SelectChannelEndPoint:qtp1401420256-95:
onSelected 1->0 for
SelectChannelEndPoint@498f2782{/127.0.0.1:55035<->8181,Open,in,out,R,-,0/30000,SslConnection}{io=0,kio=1,kro=1}
2015-03-24 11:08:54.047:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-95: EPR
Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945 produced
org.eclipse.jetty.io.SelectChannelEndPoint$2@27c822e5
2015-03-24 11:08:54.047:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-95: EPR
Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945 dispatch
2015-03-24 11:08:54.047:DBUG:oejut.QueuedThreadPool:qtp1401420256-95: queue
EPR Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945
2015-03-24 11:08:54.047:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-95: EPR
Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945 run
org.eclipse.jetty.io.SelectChannelEndPoint$2@27c822e5
2015-03-24 11:08:54.047:DBUG:oejut.QueuedThreadPool:qtp1401420256-93: run
EPR Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945
2015-03-24 11:08:54.047:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-93: EPR
Pend/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945 run
2015-03-24 11:08:54.047:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-93: EPR
Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945 produce
enter
2015-03-24 11:08:54.047:DBUG:oejuts.ExecuteProduceRun:qtp1401420256-93: EPR
Prod/org.eclipse.jetty.io.ManagedSelector$SelectorProducer@4a643945
producing
2015-03-24 11:08:54.047:DBUG:oeji.SelectChannelEndPoint:qtp1401420256-93:
Key interests updated 1 -> 0 on
SelectChannelEndPoint@498f2782{/127.0.0.1:55035<->8181,Open,in,out,R,-,1/30000,SslConnection}{io=0,kio=0,kro=1}
2015-03-24 11:08:54.048:DBUG:oeji.ManagedSelector:qtp1401420256-93: Selector
loop waiting on select
2015-03-24 11:08:54.047:DBUG:oeji.FillInterest:qtp1401420256-95:
FillInterest@74786046{true,AC.ReadCB@5ba6f860{SslConnection@5ba6f860{NEED_UNWRAP,eio=-1/-1,di=-1}
-> ALPNServerConnection@58ef714f}} fillable
AC.ReadCB@5ba6f860{SslConnection@5ba6f860{NEED_UNWRAP,eio=-1/-1,di=-1} ->
ALPNServerConnection@58ef714f}
2015-03-24 11:08:54.048:DBUG:oejis.SslConnection:qtp1401420256-95:
onFillable enter
DecryptedEndPoint@1d16968b{/127.0.0.1:55035<->8181,Open,in,out,R,-,1/30000,ALPNServerConnection}->SelectChannelEndPoint@498f2782{/127.0.0.1:55035<->8181,Open,in,out,-,-,1/30000,SslConnection}{io=0,kio=0,kro=1}
2015-03-24 11:08:54.048:DBUG:oeji.FillInterest:qtp1401420256-95:
FillInterest@71e41617{true,AC.ReadCB@58ef714f{ALPNServerConnection@58ef714f}}
fillable AC.ReadCB@58ef714f{ALPNServerConnection@58ef714f}
2015-03-24 11:08:54.048:DBUG:oeji.ChannelEndPoint:qtp1401420256-95: filled
517
SelectChannelEndPoint@498f2782{/127.0.0.1:55035<->8181,Open,in,out,-,-,1/30000,SslConnection}{io=0,kio=0,kro=1}
2015-03-24 11:08:54.048:DBUG:oejis.SslConnection:qtp1401420256-95:
SslConnection@5ba6f860{NEED_TASK,eio=0/-1,di=0} ->
ALPNServerConnection@58ef714f net=517 unwrap Status = OK HandshakeStatus =
NEED_TASK bytesConsumed = 517 bytesProduced = 0
2015-03-24 11:08:54.048:DBUG:oejis.SslConnection:qtp1401420256-95:
SslConnection@5ba6f860{NEED_TASK,eio=0/-1,di=0} ->
ALPNServerConnection@58ef714f filled b[0]=
2015-03-24 11:08:54.060:DBUG:oejas.ALPNServerConnection:qtp1401420256-95:
ALPNServerConnection@58ef714f protocol selected http/1.1


Why is the server selecting 1.1 over 2.0?

Thanks,
Ben



--
View this message in context: http://jetty.4.x6.nabble.com/Jetty-9-3-negotiating-to-HTTP-1-1-instead-of-HTTP-2-0-tp4963797.html
Sent from the Jetty User mailing list archive at Nabble.com.
Follow-Ups:
- Re: [jetty-users] Jetty 9.3 negotiating to HTTP/1.1 instead of HTTP/2.0
  - From: Simone Bordet
Prev by Date: Re: [jetty-users] Choose Certificate dialog
Next by Date: [jetty-users] Idle timeout causes spurious HTTP parse errors?
Previous by thread: [jetty-users] Choose Certificate dialog
Next by thread: Re: [jetty-users] Jetty 9.3 negotiating to HTTP/1.1 instead of HTTP/2.0
Index(es):
- Date
- Thread
Breadcrumbs
