[QPID-8069] [Qpid JMS AMQP 0-x] An establishment of connection blocks for 30 seconds on TLS handshake failure

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Won't Fix
• Affects Version/s: qpid-java-client-0-x-6.3.0
• Component/s: JMS AMQP 0-x
• Assignee: Unassigned
• Reporter: Alex Rudyy
• Created: 04/Jan/18 22:17
• Updated: 09/Jan/18 15:51
• Resolved: 09/Jan/18 15:51

Description

AMQTimeoutException is reported after waiting for "maximum state wait time", when TLS hand shake fails.

The stack traces like below are reported

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

The delay can be mitigated by overriding JVM system property amqj.MaximumStateWait.
Only TLS connections with handshake failures are affected by the issue