search

jetty / jetty.project

Eclipse Jetty® - Web Container & Clients - supports HTTP/2, HTTP/1.1, HTTP/1.0, websocket, servlets, and more
https://eclipse.dev/jetty
Other
3.82k stars 1.91k forks source link

ALPN tests failing #753

Closed gregw closed 8 years ago

gregw commented 8 years ago

Using java 1.8.0_77-b03 :

gregw@Tile440: ~/src/jetty-9.3.x/jetty-http2/http2-alpn-tests (jetty-9.3.x)
[2105] mvn
[INFO] Scanning for projects...
[INFO]                                                                         
[INFO] ------------------------------------------------------------------------
[INFO] Building Jetty :: HTTP2 :: ALPN Tests 9.3.11-SNAPSHOT
[INFO] ------------------------------------------------------------------------
[INFO] 
[INFO] --- build-helper-maven-plugin:1.5:parse-version (set-osgi-version) @ http2-alpn-tests ---
[INFO] 
[INFO] --- maven-enforcer-plugin:1.1:enforce (enforce-java) @ http2-alpn-tests ---
[INFO] 
[INFO] --- maven-enforcer-plugin:1.1:enforce (ban-junit-dep.jar) @ http2-alpn-tests ---
[INFO] 
[INFO] --- maven-remote-resources-plugin:1.2:process (default) @ http2-alpn-tests ---
[INFO] Setting property: classpath.resource.loader.class => 'org.codehaus.plexus.velocity.ContextClassLoaderResourceLoader'.
[INFO] Setting property: velocimacro.messages.on => 'false'.
[INFO] Setting property: resource.loader => 'classpath'.
[INFO] Setting property: resource.manager.logwhenfound => 'false'.
[INFO] 
[INFO] --- maven-dependency-plugin:2.2:copy (copy) @ http2-alpn-tests ---
[INFO] Configured Artifact: org.mortbay.jetty.alpn:alpn-boot:8.1.7.v20160121:jar
[INFO] org.mortbay.jetty.alpn:alpn-boot:8.1.7.v20160121:jar already exists in /home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/target/alpn
[INFO] 
[INFO] --- maven-resources-plugin:2.5:resources (default-resources) @ http2-alpn-tests ---
[debug] execute contextualize
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/main/resources
[INFO] Copying 1 resource
[INFO] 
[INFO] --- jetty-version-maven-plugin:2.1:attach-version-text (attach-version) @ http2-alpn-tests ---
[INFO] 
[INFO] --- maven-compiler-plugin:3.3:compile (default-compile) @ http2-alpn-tests ---
[INFO] No sources to compile
[INFO] 
[INFO] >>> maven-pmd-plugin:3.4:check (named-logging-enforcement) > :pmd @ http2-alpn-tests >>>
[INFO] 
[INFO] --- maven-pmd-plugin:3.4:pmd (pmd) @ http2-alpn-tests ---
[INFO] 
[INFO] <<< maven-pmd-plugin:3.4:check (named-logging-enforcement) < :pmd @ http2-alpn-tests <<<
[INFO] 
[INFO] --- maven-pmd-plugin:3.4:check (named-logging-enforcement) @ http2-alpn-tests ---
[INFO] 
[INFO] 
[INFO] >>> maven-source-plugin:2.1.2:jar (attach-sources) > generate-sources @ http2-alpn-tests >>>
[INFO] 
[INFO] --- build-helper-maven-plugin:1.5:parse-version (set-osgi-version) @ http2-alpn-tests ---
[INFO] 
[INFO] --- maven-enforcer-plugin:1.1:enforce (enforce-java) @ http2-alpn-tests ---
[INFO] 
[INFO] --- maven-enforcer-plugin:1.1:enforce (ban-junit-dep.jar) @ http2-alpn-tests ---
[INFO] 
[INFO] <<< maven-source-plugin:2.1.2:jar (attach-sources) < generate-sources @ http2-alpn-tests <<<
[INFO] 
[INFO] --- maven-source-plugin:2.1.2:jar (attach-sources) @ http2-alpn-tests ---
[INFO] about.html already added, skipping
[INFO] Building jar: /home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/target/http2-alpn-tests-9.3.11-SNAPSHOT-sources.jar
[INFO] about.html already added, skipping
[INFO] 
[INFO] >>> maven-bundle-plugin:2.5.4:manifest (default) > process-classes @ http2-alpn-tests >>>
[INFO] 
[INFO] --- build-helper-maven-plugin:1.5:parse-version (set-osgi-version) @ http2-alpn-tests ---
[INFO] 
[INFO] --- maven-enforcer-plugin:1.1:enforce (enforce-java) @ http2-alpn-tests ---
[INFO] 
[INFO] --- maven-enforcer-plugin:1.1:enforce (ban-junit-dep.jar) @ http2-alpn-tests ---
[INFO] 
[INFO] --- maven-remote-resources-plugin:1.2:process (default) @ http2-alpn-tests ---
[INFO] 
[INFO] --- maven-dependency-plugin:2.2:copy (copy) @ http2-alpn-tests ---
[INFO] Configured Artifact: org.mortbay.jetty.alpn:alpn-boot:8.1.7.v20160121:jar
[INFO] org.mortbay.jetty.alpn:alpn-boot:8.1.7.v20160121:jar already exists in /home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/target/alpn
[INFO] 
[INFO] --- maven-resources-plugin:2.5:resources (default-resources) @ http2-alpn-tests ---
[debug] execute contextualize
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/main/resources
[INFO] Copying 1 resource
[INFO] Copying 1 resource
[INFO] 
[INFO] --- jetty-version-maven-plugin:2.1:attach-version-text (attach-version) @ http2-alpn-tests ---
[INFO] 
[INFO] --- maven-compiler-plugin:3.3:compile (default-compile) @ http2-alpn-tests ---
[INFO] No sources to compile
[INFO] 
[INFO] >>> maven-pmd-plugin:3.4:check (named-logging-enforcement) > :pmd @ http2-alpn-tests >>>
[INFO] 
[INFO] --- maven-pmd-plugin:3.4:pmd (pmd) @ http2-alpn-tests ---
[INFO] 
[INFO] <<< maven-pmd-plugin:3.4:check (named-logging-enforcement) < :pmd @ http2-alpn-tests <<<
[INFO] 
[INFO] --- maven-pmd-plugin:3.4:check (named-logging-enforcement) @ http2-alpn-tests ---
[INFO] 
[INFO] 
[INFO] >>> maven-source-plugin:2.1.2:jar (attach-sources) > generate-sources @ http2-alpn-tests >>>
[INFO] 
[INFO] --- build-helper-maven-plugin:1.5:parse-version (set-osgi-version) @ http2-alpn-tests ---
[INFO] 
[INFO] --- maven-enforcer-plugin:1.1:enforce (enforce-java) @ http2-alpn-tests ---
[INFO] 
[INFO] --- maven-enforcer-plugin:1.1:enforce (ban-junit-dep.jar) @ http2-alpn-tests ---
[INFO] 
[INFO] <<< maven-source-plugin:2.1.2:jar (attach-sources) < generate-sources @ http2-alpn-tests <<<
[INFO] 
[INFO] --- maven-source-plugin:2.1.2:jar (attach-sources) @ http2-alpn-tests ---
[INFO] about.html already added, skipping
[INFO] about.html already added, skipping
[INFO] about.html already added, skipping
[INFO] 
[INFO] <<< maven-bundle-plugin:2.5.4:manifest (default) < process-classes @ http2-alpn-tests <<<
[INFO] 
[INFO] --- maven-bundle-plugin:2.5.4:manifest (default) @ http2-alpn-tests ---
[WARNING] Manifest org.eclipse.jetty.http2:http2-alpn-tests:jar:9.3.11-SNAPSHOT : Unused Export-Package instructions: [org.eclipse.jetty.http2.alpn.tests.*] 
[WARNING] Manifest org.eclipse.jetty.http2:http2-alpn-tests:jar:9.3.11-SNAPSHOT : Unused Import-Package instructions: [javax.servlet*, javax.transaction*, org.eclipse.jetty*] 
[INFO] 
[INFO] --- maven-resources-plugin:2.5:testResources (default-testResources) @ http2-alpn-tests ---
[debug] execute contextualize
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 3 resources
[INFO] Copying 1 resource
[INFO] 
[INFO] --- maven-compiler-plugin:3.3:testCompile (default-testCompile) @ http2-alpn-tests ---
[INFO] Nothing to compile - all classes are up to date
[INFO] 
[INFO] --- maven-surefire-plugin:2.18.1:test (default-test) @ http2-alpn-tests ---
[INFO] Surefire report directory: /home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/target/surefire-reports

-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running org.eclipse.jetty.http2.alpn.tests.ALPNNegotiationTest
Running org.eclipse.jetty.http2.alpn.tests.ALPNNegotiationTest.testAbruptCloseDuringHandshake()
2016-07-21 11:19:37.422:INFO::main: Logging initialized @449ms
2016-07-21 11:19:37.594:INFO:oejs.Server:main: jetty-9.3.11-SNAPSHOT
2016-07-21 11:19:37.695:INFO:oejus.SslContextFactory:main: x509=X509@5c7fa833(mykey,h=[],w=[]) for SslContextFactory@39aeed2f(file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/keystore.jks,file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/truststore.jks)
2016-07-21 11:19:37.963:INFO:oejs.AbstractConnector:main: Started ServerConnector@76aa9eb3{SSL,[ssl, alpn, http/1.1, h2, h2-17, h2-16, h2-15, h2-14]}{0.0.0.0:37029}
2016-07-21 11:19:37.963:INFO:oejs.Server:main: Started @991ms
2016-07-21 11:19:37.966:INFO:oejus.SslContextFactory:main: x509=X509@140e5a13(mykey,h=[],w=[]) for SslContextFactory@3439f68d(file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/keystore.jks,file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/truststore.jks)
[C] ALPN protocols [h2] for dbd940d[SSLEngine[hostname=127.0.0.1 port=37029] SSL_NULL_WITH_NULL_NULL]
[S] ALPN protocols [h2] received from client for 1afb5592[SSLEngine[hostname=127.0.0.1 port=50384] SSL_NULL_WITH_NULL_NULL]
2016-07-21 11:19:38.114:DBUG:oejhs.HTTP2ServerConnectionFactory:qtp110456297-10: proto=h2 tls=TLSv1.2 cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 9.2.2-acceptable=true
2016-07-21 11:19:38.115:DBUG:oejas.ALPNServerConnection:qtp110456297-10: ALPNServerConnection@60cf6f6f[DecryptedEndPoint@3019d377{/127.0.0.1:50384<->37029,Open,in,out,-,-,53/30000,ALPNServerConnection@60cf6f6f}->SelectChannelEndPoint@510b1d64{/127.0.0.1:50384<->37029,Open,in,out,-,-,54/30000,SslConnection@7951466b}{io=0/0,kio=0,kro=1}] protocol selected h2
[S] ALPN protocol 'h2' selected for 1afb5592[SSLEngine[hostname=127.0.0.1 port=50384] SSL_NULL_WITH_NULL_NULL]
2016-07-21 11:19:38.195:INFO:oejs.AbstractConnector:main: Stopped ServerConnector@76aa9eb3{SSL,[ssl, alpn, http/1.1, h2, h2-17, h2-16, h2-15, h2-14]}{0.0.0.0:0}
Running org.eclipse.jetty.http2.alpn.tests.ALPNNegotiationTest.testClientAdvertisingMultipleProtocolsServerSpeaksHTTPWhenNegotiated()
2016-07-21 11:19:38.202:INFO:oejs.Server:main: jetty-9.3.11-SNAPSHOT
2016-07-21 11:19:38.207:INFO:oejus.SslContextFactory:main: x509=X509@517cd4b(mykey,h=[],w=[]) for SslContextFactory@6cc7b4de(file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/keystore.jks,file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/truststore.jks)
2016-07-21 11:19:38.234:INFO:oejs.AbstractConnector:main: Started ServerConnector@6356e82c{SSL,[ssl, alpn, http/1.1, h2, h2-17, h2-16, h2-15, h2-14]}{0.0.0.0:45724}
2016-07-21 11:19:38.235:INFO:oejs.Server:main: Started @1263ms
2016-07-21 11:19:38.237:INFO:oejus.SslContextFactory:main: x509=X509@679b62af(mykey,h=[],w=[]) for SslContextFactory@5cdd8682(file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/keystore.jks,file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/truststore.jks)
[C] ALPN protocols [unknown/1.0, http/1.1] for 49c43f4e[SSL_NULL_WITH_NULL_NULL: Socket[addr=localhost/127.0.0.1,port=45724,localport=52888]]
[S] ALPN protocols [unknown/1.0, http/1.1] received from client for 6f2d3408[SSLEngine[hostname=127.0.0.1 port=52888] SSL_NULL_WITH_NULL_NULL]
2016-07-21 11:19:38.263:DBUG:oejas.ALPNServerConnection:qtp270397815-21: ALPNServerConnection@6d3d6aef[DecryptedEndPoint@63fa8938{/127.0.0.1:52888<->45724,Open,in,out,-,-,8/30000,ALPNServerConnection@6d3d6aef}->SelectChannelEndPoint@2a2fbf29{/127.0.0.1:52888<->45724,Open,in,out,-,-,4/30000,SslConnection@67c5019f}{io=0/0,kio=0,kro=1}] could not negotiate protocol: C[unknown/1.0, http/1.1] | S[HTTP/1.1, h2, h2, h2, h2, h2]
2016-07-21 11:19:38.265:WARN:oejut.QueuedThreadPool:qtp270397815-21: 
java.lang.RuntimeException: Delegated task threw Exception/Error
    at sun.security.ssl.Handshaker.checkThrown(Handshaker.java:1429)
    at sun.security.ssl.SSLEngineImpl.checkTaskThrown(SSLEngineImpl.java:535)
    at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:813)
    at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
    at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
    at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:525)
    at org.eclipse.jetty.server.NegotiatingServerConnection.fill(NegotiatingServerConnection.java:153)
    at org.eclipse.jetty.server.NegotiatingServerConnection.onFillable(NegotiatingServerConnection.java:98)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
    at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:202)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
    at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$1.run(QueuedThreadPool.java:589)
    at java.lang.Thread.run(Thread.java:745)
Caused by: 
java.lang.IllegalStateException
    at org.eclipse.jetty.alpn.server.ALPNServerConnection.select(ALPNServerConnection.java:87)
    at sun.security.ssl.ServerHandshaker.clientHello(ServerHandshaker.java:805)
    at sun.security.ssl.ServerHandshaker.processMessage(ServerHandshaker.java:225)
    at sun.security.ssl.Handshaker.processLoop(Handshaker.java:979)
    at sun.security.ssl.Handshaker$1.run(Handshaker.java:919)
    at sun.security.ssl.Handshaker$1.run(Handshaker.java:916)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.security.ssl.Handshaker$DelegatedTask.run(Handshaker.java:1369)
    at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:630)
    at org.eclipse.jetty.server.NegotiatingServerConnection.fill(NegotiatingServerConnection.java:153)
    at org.eclipse.jetty.server.NegotiatingServerConnection.onFillable(NegotiatingServerConnection.java:98)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
    at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:202)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
    at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$1.run(QueuedThreadPool.java:589)
    at java.lang.Thread.run(Thread.java:745)
2016-07-21 11:19:38.279:WARN:oejut.QueuedThreadPool:qtp270397815-21: Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$1@22c78303 in qtp270397815{STARTED,8<=8<=200,i=4,q=0}
2016-07-21 11:19:38.286:INFO:oejs.AbstractConnector:main: Stopped ServerConnector@6356e82c{SSL,[ssl, alpn, http/1.1, h2, h2-17, h2-16, h2-15, h2-14]}{0.0.0.0:0}
Running org.eclipse.jetty.http2.alpn.tests.ALPNNegotiationTest.testClientNotSupportingALPNServerSpeaksDefaultProtocol()
2016-07-21 11:19:38.299:INFO:oejs.Server:main: jetty-9.3.11-SNAPSHOT
2016-07-21 11:19:38.301:INFO:oejus.SslContextFactory:main: x509=X509@120d6fe6(mykey,h=[],w=[]) for SslContextFactory@4ba2ca36(file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/keystore.jks,file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/truststore.jks)
2016-07-21 11:19:38.322:INFO:oejs.AbstractConnector:main: Started ServerConnector@13f7169d{SSL,[ssl, alpn, http/1.1, h2, h2-17, h2-16, h2-15, h2-14]}{0.0.0.0:39648}
2016-07-21 11:19:38.323:INFO:oejs.Server:main: Started @1351ms
2016-07-21 11:19:38.325:INFO:oejus.SslContextFactory:main: x509=X509@3444d69d(mykey,h=[],w=[]) for SslContextFactory@1372ed45(file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/keystore.jks,file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/truststore.jks)
[C] ALPN not supported, no protocols for 6a79c292[SSL_NULL_WITH_NULL_NULL: Socket[addr=localhost/127.0.0.1,port=39648,localport=37688]]
[S] ALPN not received for 5f165bf4[SSLEngine[hostname=127.0.0.1 port=37688] SSL_NULL_WITH_NULL_NULL]
2016-07-21 11:19:38.416:DBUG:oejas.ALPNServerConnection:qtp673186785-33: ALPNServerConnection@3c7fc2f[DecryptedEndPoint@d001227{/127.0.0.1:37688<->39648,Open,in,out,-,-,72/30000,ALPNServerConnection@3c7fc2f}->SelectChannelEndPoint@1a14c6d2{/127.0.0.1:37688<->39648,Open,in,out,-,-,7/30000,SslConnection@93f975f}{io=0/0,kio=0,kro=1}] protocol selected HTTP/1.1
[C] ALPN not supported by server for 6a79c292[SSL_NULL_WITH_NULL_NULL: Socket[addr=localhost/127.0.0.1,port=39648,localport=37688]]
2016-07-21 11:19:38.507:INFO:oejs.AbstractConnector:main: Stopped ServerConnector@13f7169d{SSL,[ssl, alpn, http/1.1, h2, h2-17, h2-16, h2-15, h2-14]}{0.0.0.0:0}
Running org.eclipse.jetty.http2.alpn.tests.ALPNNegotiationTest.testClientAdvertisingHTTPServerSpeaksHTTP()
2016-07-21 11:19:38.510:INFO:oejs.Server:main: jetty-9.3.11-SNAPSHOT
2016-07-21 11:19:38.511:INFO:oejus.SslContextFactory:main: x509=X509@28c4711c(mykey,h=[],w=[]) for SslContextFactory@59717824(file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/keystore.jks,file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/truststore.jks)
2016-07-21 11:19:38.515:INFO:oejs.AbstractConnector:main: Started ServerConnector@146044d7{SSL,[ssl, alpn, http/1.1, h2, h2-17, h2-16, h2-15, h2-14]}{0.0.0.0:36045}
2016-07-21 11:19:38.516:INFO:oejs.Server:main: Started @1544ms
2016-07-21 11:19:38.518:INFO:oejus.SslContextFactory:main: x509=X509@473b46c3(mykey,h=[],w=[]) for SslContextFactory@516be40f(file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/keystore.jks,file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/truststore.jks)
[C] ALPN protocols [http/1.1] for 3c0a50da[SSL_NULL_WITH_NULL_NULL: Socket[addr=localhost/127.0.0.1,port=36045,localport=44894]]
[S] ALPN protocols [http/1.1] received from client for 1a05821b[SSLEngine[hostname=127.0.0.1 port=44894] SSL_NULL_WITH_NULL_NULL]
2016-07-21 11:19:38.526:DBUG:oejas.ALPNServerConnection:qtp1161667116-43: ALPNServerConnection@65163335[DecryptedEndPoint@6bd1c1e7{/127.0.0.1:44894<->36045,Open,in,out,-,-,2/30000,ALPNServerConnection@65163335}->SelectChannelEndPoint@5f07179f{/127.0.0.1:44894<->36045,Open,in,out,-,-,2/30000,SslConnection@6fee5845}{io=1/0,kio=1,kro=1}] could not negotiate protocol: C[http/1.1] | S[HTTP/1.1, h2, h2, h2, h2, h2]
2016-07-21 11:19:38.527:WARN:oejut.QueuedThreadPool:qtp1161667116-43: 
java.lang.RuntimeException: Delegated task threw Exception/Error
    at sun.security.ssl.Handshaker.checkThrown(Handshaker.java:1429)
    at sun.security.ssl.SSLEngineImpl.checkTaskThrown(SSLEngineImpl.java:535)
    at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:813)
    at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
    at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
    at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:525)
    at org.eclipse.jetty.server.NegotiatingServerConnection.fill(NegotiatingServerConnection.java:153)
    at org.eclipse.jetty.server.NegotiatingServerConnection.onFillable(NegotiatingServerConnection.java:98)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
    at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:202)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
    at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$1.run(QueuedThreadPool.java:589)
    at java.lang.Thread.run(Thread.java:745)
Caused by: 
java.lang.IllegalStateException
    at org.eclipse.jetty.alpn.server.ALPNServerConnection.select(ALPNServerConnection.java:87)
    at sun.security.ssl.ServerHandshaker.clientHello(ServerHandshaker.java:805)
    at sun.security.ssl.ServerHandshaker.processMessage(ServerHandshaker.java:225)
    at sun.security.ssl.Handshaker.processLoop(Handshaker.java:979)
    at sun.security.ssl.Handshaker$1.run(Handshaker.java:919)
    at sun.security.ssl.Handshaker$1.run(Handshaker.java:916)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.security.ssl.Handshaker$DelegatedTask.run(Handshaker.java:1369)
    at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:630)
    at org.eclipse.jetty.server.NegotiatingServerConnection.fill(NegotiatingServerConnection.java:153)
    at org.eclipse.jetty.server.NegotiatingServerConnection.onFillable(NegotiatingServerConnection.java:98)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
    at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:202)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:273)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
    at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$1.run(QueuedThreadPool.java:589)
    at java.lang.Thread.run(Thread.java:745)
2016-07-21 11:19:38.528:WARN:oejut.QueuedThreadPool:qtp1161667116-43: Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$1@2aeccbdc in qtp1161667116{STARTED,8<=8<=200,i=4,q=0}
2016-07-21 11:19:38.532:INFO:oejs.AbstractConnector:main: Stopped ServerConnector@146044d7{SSL,[ssl, alpn, http/1.1, h2, h2-17, h2-16, h2-15, h2-14]}{0.0.0.0:0}
Running org.eclipse.jetty.http2.alpn.tests.ALPNNegotiationTest.testGentleCloseDuringHandshake()
2016-07-21 11:19:38.540:INFO:oejs.Server:main: jetty-9.3.11-SNAPSHOT
2016-07-21 11:19:38.542:INFO:oejus.SslContextFactory:main: x509=X509@7364985f(mykey,h=[],w=[]) for SslContextFactory@5d20e46(file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/keystore.jks,file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/truststore.jks)
2016-07-21 11:19:38.547:INFO:oejs.AbstractConnector:main: Started ServerConnector@5e05f7f4{SSL,[ssl, alpn, http/1.1, h2, h2-17, h2-16, h2-15, h2-14]}{0.0.0.0:38555}
2016-07-21 11:19:38.547:INFO:oejs.Server:main: Started @1575ms
2016-07-21 11:19:38.549:INFO:oejus.SslContextFactory:main: x509=X509@709ba3fb(mykey,h=[],w=[]) for SslContextFactory@3d36e4cd(file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/keystore.jks,file:///home/gregw/src/jetty-9.3.x/jetty-http2/http2-alpn-tests/src/test/resources/truststore.jks)
[C] ALPN protocols [h2] for 6a472554[SSLEngine[hostname=127.0.0.1 port=38555] SSL_NULL_WITH_NULL_NULL]
[S] ALPN protocols [h2] received from client for 4813f5c4[SSLEngine[hostname=127.0.0.1 port=41490] SSL_NULL_WITH_NULL_NULL]
2016-07-21 11:19:38.570:DBUG:oejhs.HTTP2ServerConnectionFactory:qtp1684792003-54: proto=h2 tls=TLSv1.2 cipher=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 9.2.2-acceptable=true
2016-07-21 11:19:38.571:DBUG:oejas.ALPNServerConnection:qtp1684792003-54: ALPNServerConnection@7f7e8817[DecryptedEndPoint@71b96988{/127.0.0.1:41490<->38555,Open,in,out,-,-,7/30000,ALPNServerConnection@7f7e8817}->SelectChannelEndPoint@d116a02{/127.0.0.1:41490<->38555,Open,in,out,-,-,7/30000,SslConnection@7586e367}{io=0/0,kio=0,kro=1}] protocol selected h2
[S] ALPN protocol 'h2' selected for 4813f5c4[SSLEngine[hostname=127.0.0.1 port=41490] SSL_NULL_WITH_NULL_NULL]
2016-07-21 11:19:38.583:INFO:oejs.AbstractConnector:main: Stopped ServerConnector@5e05f7f4{SSL,[ssl, alpn, http/1.1, h2, h2-17, h2-16, h2-15, h2-14]}{0.0.0.0:0}
Tests run: 5, Failures: 0, Errors: 2, Skipped: 0, Time elapsed: 1.187 sec <<< FAILURE! - in org.eclipse.jetty.http2.alpn.tests.ALPNNegotiationTest
testClientAdvertisingMultipleProtocolsServerSpeaksHTTPWhenNegotiated(org.eclipse.jetty.http2.alpn.tests.ALPNNegotiationTest)  Time elapsed: 0.094 sec  <<< ERROR!
javax.net.ssl.SSLHandshakeException: Received fatal alert: no_application_protocol
    at sun.security.ssl.Alerts.getSSLException(Alerts.java:203)
    at sun.security.ssl.Alerts.getSSLException(Alerts.java:162)
    at sun.security.ssl.SSLSocketImpl.recvAlert(SSLSocketImpl.java:2023)
    at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1125)
    at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1375)
    at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1403)
    at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1387)
    at org.eclipse.jetty.http2.alpn.tests.ALPNNegotiationTest.testClientAdvertisingMultipleProtocolsServerSpeaksHTTPWhenNegotiated(ALPNNegotiationTest.java:245)

testClientAdvertisingHTTPServerSpeaksHTTP(org.eclipse.jetty.http2.alpn.tests.ALPNNegotiationTest)  Time elapsed: 0.026 sec  <<< ERROR!
javax.net.ssl.SSLHandshakeException: Received fatal alert: no_application_protocol
    at sun.security.ssl.Alerts.getSSLException(Alerts.java:203)
    at sun.security.ssl.Alerts.getSSLException(Alerts.java:162)
    at sun.security.ssl.SSLSocketImpl.recvAlert(SSLSocketImpl.java:2023)
    at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1125)
    at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1375)
    at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1403)
    at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1387)
    at org.eclipse.jetty.http2.alpn.tests.ALPNNegotiationTest.testClientAdvertisingHTTPServerSpeaksHTTP(ALPNNegotiationTest.java:193)

Results :

Tests in error: 
  ALPNNegotiationTest.testClientAdvertisingHTTPServerSpeaksHTTP:193 » SSLHandshake
  ALPNNegotiationTest.testClientAdvertisingMultipleProtocolsServerSpeaksHTTPWhenNegotiated:245 » SSLHandshake

Tests run: 5, Failures: 0, Errors: 2, Skipped: 0
gregw commented 8 years ago

Ooops was e82ed5afb960b03b0347094f137fc6b93890213c investigating

gregw commented 8 years ago

Fixed by 5718726 for #671