Uploaded image for project: 'Qpid'
  1. Qpid
  2. QPID-8069

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

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Won't Fix
    • Affects Version/s: qpid-java-client-0-x-6.3.0
    • Fix Version/s: None
    • Component/s: JMS AMQP 0-x
    • Labels:
      None

      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

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              orudyy Alex Rudyy
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: