Alex Rudyy created QPID-8069:
--------------------------------
Summary: [Qpid JMS AMQP 0-x] An establishment of connection blocks
for 30 seconds when 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 4000ms 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 4000 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: [email protected]
For additional commands, e-mail: [email protected]
