[
https://issues.apache.org/jira/browse/QPID-8069?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Keith Wall closed QPID-8069.
----------------------------
Resolution: Won't Fix
> [Qpid JMS AMQP 0-x] An establishment of connection blocks for 30 seconds on
> TLS handshake failure
> -------------------------------------------------------------------------------------------------
>
> Key: QPID-8069
> URL: https://issues.apache.org/jira/browse/QPID-8069
> Project: Qpid
> Issue Type: Bug
> Components: JMS AMQP 0-x
> Affects Versions: qpid-java-client-0-x-6.3.0
> Reporter: Alex Rudyy
>
> AMQTimeoutException is reported after waiting for "maximum state wait time",
> when TLS hand shake fails.
> The stack traces like below are reported
> {noformat}
> 2018-01-04 21:59:33,960 DEBUG [main] o.a.q.c.AMQConnection
> Connection(27):amqp://guest:********@clientid/?brokerlist='tcp://localhost:46879?trust_store='/tmp/test-profiles/test_resources/ssl/java_client_truststore.jks'&trust_store_password='********'&ssl='true''
> 2018-01-04 21:59:33,960 DEBUG [main] o.a.q.c.AMQConnection AMQP version 0-9-1
> 2018-01-04 21:59:33,960 DEBUG [main] o.a.q.c.p.AMQProtocolSession Using
> ProtocolVersion for Session:0-91
> 2018-01-04 21:59:33,960 DEBUG [main] o.a.q.c.h.ClientMethodDispatcherImpl New
> Method Dispatcher:AMQProtocolSession[null]
> 2018-01-04 21:59:33,960 DEBUG [main] o.a.q.c.AMQConnection Connecting with
> ProtocolHandler Version:0-91
> 2018-01-04 21:59:33,960 DEBUG [main] o.a.q.c.AMQConnectionDelegate_8_0
> Connecting to
> broker:tcp://localhost:46879?trust_store='/tmp/test-profiles/test_resources/ssl/java_client_truststore.jks'&trust_store_password='********'&ssl='true'
> 2018-01-04 21:59:33,961 DEBUG [main] o.a.q.t.n.i.IoNetworkTransport Socket
> options SO_RCVBUF : 65535, SO_SNDBUF : 65535, TCP_NODELAY : true
> 2018-01-04 21:59:33,961 DEBUG [main] o.a.q.t.n.i.IoNetworkTransport Socket
> connection from /127.0.0.1:48680 to localhost/127.0.0.1:46879 established
> 2018-01-04 21:59:33,961 DEBUG
> [IO-pool-Port-testClientCertificateMissingWhilstNeedingTlsPort-5]
> o.a.q.s.t.NonBlockingConnection Identified transport encryption as TLS
> 2018-01-04 21:59:33,962 DEBUG [main] o.a.q.c.s.StateWaiter New StateWaiter
> :CONNECTION_NOT_STARTED:[CONNECTION_OPEN, CONNECTION_CLOSED]
> 2018-01-04 21:59:33,964 DEBUG [IO-/127.0.0.1:48680]
> o.a.q.s.t.NonBlockingConnection Read 172 byte(s)
> 2018-01-04 21:59:33,973 DEBUG [IO-/127.0.0.1:48680]
> o.a.q.s.t.NonBlockingConnection Written 1825 bytes
> 2018-01-04 21:59:33,974 DEBUG [IO-/127.0.0.1:48680]
> o.a.q.s.t.NonBlockingConnection Read 0 byte(s)
> 2018-01-04 21:59:33,982 DEBUG [IO-/127.0.0.1:48680]
> o.a.q.s.t.NonBlockingConnection Read 173 byte(s)
> 2018-01-04 21:59:33,984 DEBUG [IO-/127.0.0.1:48680]
> o.a.q.s.t.NonBlockingConnection Exception performing I/O for connection
> '/127.0.0.1:48680'
> javax.net.ssl.SSLHandshakeException: null cert chain
> at sun.security.ssl.Handshaker.checkThrown(Handshaker.java:1478)
> 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.apache.qpid.server.bytebuffer.QpidByteBufferFactory.decryptSSL(QpidByteBufferFactory.java:197)
> at
> org.apache.qpid.server.bytebuffer.QpidByteBuffer.decryptSSL(QpidByteBuffer.java:68)
> at
> org.apache.qpid.server.transport.NonBlockingConnectionTLSDelegate.processData(NonBlockingConnectionTLSDelegate.java:125)
> at
> org.apache.qpid.server.transport.NonBlockingConnection.doRead(NonBlockingConnection.java:496)
> at
> org.apache.qpid.server.transport.NonBlockingConnection.doWork(NonBlockingConnection.java:270)
> at
> org.apache.qpid.server.transport.NetworkConnectionScheduler.processConnection(NetworkConnectionScheduler.java:134)
> at
> org.apache.qpid.server.transport.SelectorThread$ConnectionProcessor.processConnection(SelectorThread.java:580)
> at
> org.apache.qpid.server.transport.SelectorThread$SelectionTask.performSelect(SelectorThread.java:371)
> at
> org.apache.qpid.server.transport.SelectorThread$SelectionTask.run(SelectorThread.java:97)
> at
> org.apache.qpid.server.transport.SelectorThread.run(SelectorThread.java:538)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at
> org.apache.qpid.server.bytebuffer.QpidByteBufferFactory.lambda$null$0(QpidByteBufferFactory.java:464)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: javax.net.ssl.SSLHandshakeException: null cert chain
> at sun.security.ssl.Alerts.getSSLException(Alerts.java:192)
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1666)
> at sun.security.ssl.Handshaker.fatalSE(Handshaker.java:304)
> at sun.security.ssl.Handshaker.fatalSE(Handshaker.java:292)
> at
> sun.security.ssl.ServerHandshaker.clientCertificate(ServerHandshaker.java:1862)
> at
> sun.security.ssl.ServerHandshaker.processMessage(ServerHandshaker.java:233)
> at sun.security.ssl.Handshaker.processLoop(Handshaker.java:1026)
> at sun.security.ssl.Handshaker$1.run(Handshaker.java:966)
> at sun.security.ssl.Handshaker$1.run(Handshaker.java:963)
> at java.security.AccessController.doPrivileged(Native Method)
> at sun.security.ssl.Handshaker$DelegatedTask.run(Handshaker.java:1416)
> at
> org.apache.qpid.server.transport.NonBlockingConnectionTLSDelegate.runSSLEngineTasks(NonBlockingConnectionTLSDelegate.java:295)
> at
> org.apache.qpid.server.transport.NonBlockingConnectionTLSDelegate.processData(NonBlockingConnectionTLSDelegate.java:134)
> ... 11 common frames omitted
> 2018-01-04 21:59:33,984 DEBUG [IO-/127.0.0.1:48680]
> o.a.q.s.t.NonBlockingConnection Written 7 bytes
> 2018-01-04 21:59:33,984 DEBUG [IO-/127.0.0.1:48680]
> o.a.q.s.t.MultiVersionProtocolEngine Closed
> 2018-01-04 21:59:33,984 DEBUG [IO-/127.0.0.1:48680]
> o.a.q.s.t.MultiVersionProtocolEngine Connection from /127.0.0.1:48680 was
> closed before any protocol version was established.
> 2018-01-04 21:59:33,984 DEBUG [IO-/127.0.0.1:48680]
> o.a.q.s.t.NonBlockingConnection Closing /127.0.0.1:48680
> 2018-01-04 21:59:33,984 DEBUG
> [IoRcvr-/127.0.0.1:48680-localhost/127.0.0.1:46879] o.a.q.t.n.s.s.SSLReceiver
> Error caught in SSLReceiver
> javax.net.ssl.SSLException: Received fatal alert: bad_certificate
> at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1666)
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1634)
> at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1800)
> at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1083)
> at
> sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:907)
> at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
> at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
> at
> org.apache.qpid.transport.network.security.ssl.SSLReceiver.received(SSLReceiver.java:105)
> at
> org.apache.qpid.client.AMQConnectionDelegate_8_0$ReceiverClosedWaiter.received(AMQConnectionDelegate_8_0.java:549)
> at
> org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:164)
> at java.lang.Thread.run(Thread.java:745)
> 2018-01-04 21:59:33,984 DEBUG [IO-/127.0.0.1:48680]
> o.a.q.s.t.NonBlockingConnectionTLSDelegate Exception when closing SSLEngine
> javax.net.ssl.SSLException: Inbound closed before receiving peer's
> close_notify: possible truncation attack?
> at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1666)
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1634)
> at
> sun.security.ssl.SSLEngineImpl.closeInbound(SSLEngineImpl.java:1561)
> at
> org.apache.qpid.server.transport.NonBlockingConnectionTLSDelegate.shutdownOutput(NonBlockingConnectionTLSDelegate.java:406)
> at
> org.apache.qpid.server.transport.NonBlockingConnection.shutdownOutput(NonBlockingConnection.java:449)
> at
> org.apache.qpid.server.transport.NonBlockingConnection.shutdown(NonBlockingConnection.java:386)
> at
> org.apache.qpid.server.transport.NonBlockingConnection.doWork(NonBlockingConnection.java:313)
> at
> org.apache.qpid.server.transport.NetworkConnectionScheduler.processConnection(NetworkConnectionScheduler.java:134)
> at
> org.apache.qpid.server.transport.SelectorThread$ConnectionProcessor.processConnection(SelectorThread.java:580)
> at
> org.apache.qpid.server.transport.SelectorThread$SelectionTask.performSelect(SelectorThread.java:371)
> at
> org.apache.qpid.server.transport.SelectorThread$SelectionTask.run(SelectorThread.java:97)
> at
> org.apache.qpid.server.transport.SelectorThread.run(SelectorThread.java:538)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at
> org.apache.qpid.server.bytebuffer.QpidByteBufferFactory.lambda$null$0(QpidByteBufferFactory.java:464)
> at java.lang.Thread.run(Thread.java:745)
> 2018-01-04 21:59:33,985 DEBUG [main] o.a.q.c.AMQProtocolHandler SEND: AMQP0091
> 2018-01-04 21:59:33,985 DEBUG [main] o.a.q.c.AMQProtocolHandler Sent 1
> protocol messages
> 2018-01-04 21:59:33,985 INFO
> [IoRcvr-/127.0.0.1:48680-localhost/127.0.0.1:46879]
> o.a.q.c.AMQProtocolHandler Connection exception caught therefore going to
> attempt failover: org.apache.qpid.transport.TransportException: Error in
> SSLReceiver: Received fatal alert: bad_certificate
> org.apache.qpid.transport.TransportException: Error in SSLReceiver: Received
> fatal alert: bad_certificate
> at
> org.apache.qpid.transport.network.security.ssl.SSLReceiver.received(SSLReceiver.java:201)
> at
> org.apache.qpid.client.AMQConnectionDelegate_8_0$ReceiverClosedWaiter.received(AMQConnectionDelegate_8_0.java:549)
> at
> org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:164)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: javax.net.ssl.SSLException: Received fatal alert: bad_certificate
> at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1666)
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1634)
> at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1800)
> at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1083)
> at
> sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:907)
> at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
> at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
> at
> org.apache.qpid.transport.network.security.ssl.SSLReceiver.received(SSLReceiver.java:105)
> ... 3 common frames omitted
> 2018-01-04 21:59:33,985 DEBUG
> [IoRcvr-/127.0.0.1:48680-localhost/127.0.0.1:46879]
> o.a.q.c.AMQProtocolHandler Session closed called with failover state
> FailoverState: NOT STARTED
> 2018-01-04 21:59:33,985 DEBUG
> [IoRcvr-/127.0.0.1:48680-localhost/127.0.0.1:46879] o.a.q.t.n.s.s.SSLSender
> Closing SSL connection
> 2018-01-04 21:59:33,985 DEBUG
> [IoRcvr-/127.0.0.1:48680-localhost/127.0.0.1:46879]
> o.a.q.c.AMQProtocolHandler We are in process of establishing the initial
> connection
> 2018-01-04 21:59:33,985 DEBUG
> [IoRcvr-/127.0.0.1:48680-localhost/127.0.0.1:46879] o.a.q.c.AMQConnection
> exceptionReceived done by:IoRcvr-/127.0.0.1:48680-localhost/127.0.0.1:46879
> org.apache.qpid.QpidException: Connection could not be established: Error in
> SSLReceiver: Received fatal alert: bad_certificate
> at
> org.apache.qpid.client.AMQProtocolHandler.closed(AMQProtocolHandler.java:245)
> at
> org.apache.qpid.transport.network.security.ssl.SSLReceiver.closed(SSLReceiver.java:69)
> at
> org.apache.qpid.client.AMQConnectionDelegate_8_0$ReceiverClosedWaiter.closed(AMQConnectionDelegate_8_0.java:563)
> at
> org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:225)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: org.apache.qpid.transport.TransportException: Error in
> SSLReceiver: Received fatal alert: bad_certificate
> at
> org.apache.qpid.transport.network.security.ssl.SSLReceiver.received(SSLReceiver.java:201)
> at
> org.apache.qpid.client.AMQConnectionDelegate_8_0$ReceiverClosedWaiter.received(AMQConnectionDelegate_8_0.java:549)
> at
> org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:164)
> ... 1 common frames omitted
> Caused by: javax.net.ssl.SSLException: Received fatal alert: bad_certificate
> at sun.security.ssl.Alerts.getSSLException(Alerts.java:208)
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1666)
> at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1634)
> at sun.security.ssl.SSLEngineImpl.recvAlert(SSLEngineImpl.java:1800)
> at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:1083)
> at
> sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:907)
> at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
> at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
> at
> org.apache.qpid.transport.network.security.ssl.SSLReceiver.received(SSLReceiver.java:105)
> ... 3 common frames omitted
> 2018-01-04 21:59:33,985 ERROR
> [IoRcvr-/127.0.0.1:48680-localhost/127.0.0.1:46879] o.a.q.c.AMQConnection
> Throwable Received but no listener set: org.apache.qpid.QpidException:
> Connection could not be established: Error in SSLReceiver: Received fatal
> alert: bad_certificate
> 2018-01-04 21:59:33,985 DEBUG
> [IoRcvr-/127.0.0.1:48680-localhost/127.0.0.1:46879]
> o.a.q.c.AMQProtocolHandler Protocol Session
> [org.apache.qpid.client.AMQProtocolHandler@69becd8e] closed
> 2018-01-04 21:59:37,985 DEBUG [main] o.a.q.c.AMQConnectionDelegate_8_0
> Waiting 60000ms for receiver to be closed
> 2018-01-04 21:59:37,985 INFO [main] o.a.q.c.AMQConnection Unable to connect
> to broker at
> tcp://localhost:46879?trust_store='/tmp/test-profiles/test_resources/ssl/java_client_truststore.jks'&trust_store_password='********'&ssl='true'
> org.apache.qpid.AMQTimeoutException: Waiting for 30000ms to attain one of the
> states [CONNECTION_OPEN, CONNECTION_CLOSED]; current state is
> CONNECTION_NOT_STARTED
> at
> org.apache.qpid.client.state.StateWaiter.await(StateWaiter.java:119)
> at org.apache.qpid.client.state.StateWaiter.await(StateWaiter.java:92)
> at
> org.apache.qpid.client.AMQConnectionDelegate_8_0.makeBrokerConnection(AMQConnectionDelegate_8_0.java:161)
> at
> org.apache.qpid.client.AMQConnection.makeBrokerConnection(AMQConnection.java:816)
> at
> org.apache.qpid.client.AMQConnection.makeConnection(AMQConnection.java:583)
> at org.apache.qpid.client.AMQConnection.<init>(AMQConnection.java:522)
> at
> org.apache.qpid.client.AMQConnectionFactory.createConnection(AMQConnectionFactory.java:164)
> at
> org.apache.qpid.client.AMQConnectionFactory.createConnection(AMQConnectionFactory.java:143)
> at
> org.apache.qpid.client.AMQConnectionFactory.createConnection(AMQConnectionFactory.java:57)
> at
> org.apache.qpid.systests.QpidJmsClient0xConnectionBuilder.build(QpidJmsClient0xConnectionBuilder.java:235)
> at
> org.apache.qpid.systests.jms_1_1.extensions.tls.TlsTest.testClientCertificateMissingWhilstNeeding(TlsTest.java:382)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
> at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
> at
> org.apache.qpid.tests.utils.QpidTestRunner.runChild(QpidTestRunner.java:69)
> at
> org.apache.qpid.tests.utils.QpidTestRunner.runChild(QpidTestRunner.java:28)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> at
> org.apache.qpid.tests.utils.QpidTestRunner.run(QpidTestRunner.java:55)
> at org.junit.runner.JUnitCore.run(JUnitCore.java:160)
> at
> com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
> at
> com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47)
> Caused by: org.apache.qpid.AMQTimeoutException: The server's response was not
> received within the time-out period of 30000 ms. Possible reasons include:
> the server may be too busy, the network may be overloaded, or this JVM itself
> may be too busy to process the response.
> at
> org.apache.qpid.client.util.BlockingWaiter.block(BlockingWaiter.java:175)
> at
> org.apache.qpid.client.state.StateWaiter.await(StateWaiter.java:115)
> ... 38 common frames omitted
> 2018-01-04 21:59:37,985 DEBUG [main] o.a.q.j.FailoverPolicy All failover
> methods exhausted
> {noformat}
> The delay can be mitigated by overriding JVM system property
> {{amqj.MaximumStateWait}}.
> Only TLS connections with handshake failures are affected by the issue
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@qpid.apache.org
For additional commands, e-mail: dev-h...@qpid.apache.org
