You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by "Alex Rudyy (Jira)" <ji...@apache.org> on 2021/05/17 13:30:00 UTC
[jira] [Commented] (QPID-8526) Connection looping in
NonBlockingConnectionTLSDelegate.doWrite()
[ https://issues.apache.org/jira/browse/QPID-8526?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17346166#comment-17346166 ]
Alex Rudyy commented on QPID-8526:
----------------------------------
Hi [~daniel.kirilyuk],
As per provided WARN logs the {{SSLEngine}} was closed (_status: [ Status = CLOSED...) on invoking {{shutdownFinalWrite}} before closing the connection socket:
{noformat}
_status: [ Status = CLOSED, HandshakeStatus = NOT_HANDSHAKING, bytesConsumed = 0, bytesProduced = 0 ], _sslEngine.isOutboundDone(): true, _sslEngine.isInboundDone(): true, _sslEngine.getPeerHost(): null, _sslEngine.getPeerPort(): -1, buffers.size(): 2, _encryptedOutput.size(): 0, _netOutputBuffer.remaining(): 152185, _sslEngine.getSession().getPacketBufferSize(): 16709, _sslEngine.getSession().getCreationTime(): 1620621054549, _sslEngine.getSession().getLastAccessedTime(): 1620621054549, _sslEngine.getHandshakeSession().isValid(): null handshake session
{noformat}
As result, the connection could not flush final bytes and entered a loop. That indicate about a defect in the connection close functionality. I am not sure how the {{SSLEngine}} got in that state.
I think we need to understand what happened when the following message got logged:
{noformat}
[con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)] : Connection closed with error : amqp:resource-limit-exceeded - local-idle-timeout expired
{noformat}
Could you please expand on how the connection got marked as closed for the above log?
Potentially, the write loop can be broken by adding the following change:
{code}
$ git diff broker-core/src/main/java/org/apache/qpid/server/transport/NonBlockingConnectionTLSDelegate.java
diff --git a/broker-core/src/main/java/org/apache/qpid/server/transport/NonBlockingConnectionTLSDelegate.java b/broker-core/src/main/java/org/apache/qpid/server/transport/NonBlockingConnectionTLSDelegate.java
index f6bdabc071..2d2b800a8a 100644
--- a/broker-core/src/main/java/org/apache/qpid/server/transport/NonBlockingConnectionTLSDelegate.java
+++ b/broker-core/src/main/java/org/apache/qpid/server/transport/NonBlockingConnectionTLSDelegate.java
@@ -253,6 +253,12 @@ public class NonBlockingConnectionTLSDelegate implements NonBlockingConnectionDe
}
_status = QpidByteBuffer.encryptSSL(_sslEngine, buffers, _netOutputBuffer);
+ if (_status.getStatus() == SSLEngineResult.Status.CLOSED)
+ {
+ throw new SSLException(String.format("SSLEngine.wrap operation could not be completed because"
+ + " it was already closed (status %s, handshake status %s)",
+ _status.getStatus(), _status.getHandshakeStatus()));
+ }
// QPID-8489: workaround for JDK 8 bug to avoid tight looping for half closed connections
// Additional info: https://bugs.openjdk.java.net/browse/JDK-8240071,
// http://mail.openjdk.java.net/pipermail/security-dev/2019-January/019142.html
{code}
Though, the above would cause a loss of all buffered data in {{_netOutputBuffer}}. Thus, we need to fix conditions causing a close of SSLEngine output
> Connection looping in NonBlockingConnectionTLSDelegate.doWrite()
> ----------------------------------------------------------------
>
> Key: QPID-8526
> URL: https://issues.apache.org/jira/browse/QPID-8526
> Project: Qpid
> Issue Type: Bug
> Components: Broker-J
> Affects Versions: qpid-java-broker-8.0.4
> Reporter: Daniil Kirilyuk
> Priority: Minor
>
> Issue is similar to QPID-8489: on certain conditions SSL connection thread falls into an infinite loop consuming CPU.
> Stacktrace from the threaddump:
> {noformat}
> "IO-/127.0.0.1:50414" #32 prio=5 os_prio=0 cpu=43504522.88ms elapsed=330519.20s tid=0x00007f47a0375000 nid=0x9089 runnable [0x00007f47956fe000]
> java.lang.Thread.State: RUNNABLE
> at sun.security.ssl.TransportContext.getHandshakeStatus(java.base@11.0.7/TransportContext.java:571)
> at sun.security.ssl.SSLEngineImpl.getHandshakeStatus(java.base@11.0.7/SSLEngineImpl.java:801)
> - locked <0x00007f4b721e7340> (a sun.security.ssl.SSLEngineImpl)
> at org.apache.qpid.server.transport.NonBlockingConnectionTLSDelegate.wrapBufferArray(NonBlockingConnectionTLSDelegate.java:239)
> at org.apache.qpid.server.transport.NonBlockingConnectionTLSDelegate.doWrite(NonBlockingConnectionTLSDelegate.java:164)
> at org.apache.qpid.server.transport.NonBlockingConnection.doWrite(NonBlockingConnection.java:521)
> at org.apache.qpid.server.transport.NonBlockingConnection.shutdownFinalWrite(NonBlockingConnection.java:422)
> at org.apache.qpid.server.transport.NonBlockingConnection.shutdown(NonBlockingConnection.java:384)
> 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:575)
> at org.apache.qpid.server.transport.SelectorThread$SelectionTask.performSelect(SelectorThread.java:366)
> at org.apache.qpid.server.transport.SelectorThread$SelectionTask.run(SelectorThread.java:97)
> at org.apache.qpid.server.transport.SelectorThread.run(SelectorThread.java:533)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.7/ThreadPoolExecutor.java:1128)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.7/ThreadPoolExecutor.java:628)
> at org.apache.qpid.server.bytebuffer.QpidByteBufferFactory.lambda$null$0(QpidByteBufferFactory.java:464)
> at org.apache.qpid.server.bytebuffer.QpidByteBufferFactory$$Lambda$64/0x00007f47d52bcc40.run(Unknown Source)
> at java.lang.Thread.run(java.base@11.0.7/Thread.java:834)
> {noformat}
> Stacktrace 2 from the threaddump:
> {noformat}
> "IO-/127.0.0.1:50414" #32 prio=5 os_prio=0 cpu=43536330.84ms elapsed=330555.26s tid=0x00007f47a0375000 nid=0x9089 runnable [0x00007f47956fe000]
> java.lang.Thread.State: RUNNABLE
> at org.apache.qpid.server.bytebuffer.QpidByteBufferFactory.encryptSSL(QpidByteBufferFactory.java:178)
> at org.apache.qpid.server.bytebuffer.QpidByteBuffer.encryptSSL(QpidByteBuffer.java:62)
> at org.apache.qpid.server.transport.NonBlockingConnectionTLSDelegate.wrapBufferArray(NonBlockingConnectionTLSDelegate.java:255)
> at org.apache.qpid.server.transport.NonBlockingConnectionTLSDelegate.doWrite(NonBlockingConnectionTLSDelegate.java:164)
> at org.apache.qpid.server.transport.NonBlockingConnection.doWrite(NonBlockingConnection.java:521)
> at org.apache.qpid.server.transport.NonBlockingConnection.shutdownFinalWrite(NonBlockingConnection.java:422)
> at org.apache.qpid.server.transport.NonBlockingConnection.shutdown(NonBlockingConnection.java:384)
> 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:575)
> at org.apache.qpid.server.transport.SelectorThread$SelectionTask.performSelect(SelectorThread.java:366)
> at org.apache.qpid.server.transport.SelectorThread$SelectionTask.run(SelectorThread.java:97)
> at org.apache.qpid.server.transport.SelectorThread.run(SelectorThread.java:533)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.7/ThreadPoolExecutor.java:1128)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.7/ThreadPoolExecutor.java:628)
> at org.apache.qpid.server.bytebuffer.QpidByteBufferFactory.lambda$null$0(QpidByteBufferFactory.java:464)
> at org.apache.qpid.server.bytebuffer.QpidByteBufferFactory$$Lambda$64/0x00007f47d52bcc40.run(Unknown Source)
> at java.lang.Thread.run(java.base@11.0.7/Thread.java:834)
> {noformat}
> Stucked connection details (retrieved via broker REST API):
> {noformat}
> {
> "id" : "60b493c2-de91-4690-8e4c-1e3d5d5ea353",
> "name" : "[8332442] 127.0.0.1:64711",
> "type" : "AMQP_1_0",
> "desiredState" : "ACTIVE",
> "state" : "ACTIVE",
> "durable" : false,
> "lifetimePolicy" : "PERMANENT",
> "incoming" : true,
> "incomingIdleTimeout" : 60000,
> "lastOpenedTime" : 1618942801846,
> "maxUncommittedInMemorySize" : 10485760,
> "outgoingIdleTimeout" : 0,
> "port" : "amqps",
> "protocol" : "AMQP_1_0",
> "remoteAddress" : "/127.0.0.1:64711",
> "sendSaslFinalChallengeAsChallenge" : false,
> "sessionCountLimit" : 1,
> "transport" : "SSL",
> "transportInfo" : "TLSv1.2 ; TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256",
> "lastUpdatedTime" : 1618942801846,
> "createdTime" : 1618942801846,
> "statistics" : {
> "bytesIn" : 0,
> "bytesOut" : 0,
> "lastInboundMessageTime" : 1618942801846,
> "lastIoTime" : 1618942801846,
> "lastMessageTime" : 1618942801846,
> "lastOutboundMessageTime" : 1618942801846,
> "localTransactionBegins" : 0,
> "localTransactionOpen" : 0,
> "localTransactionRollbacks" : 0,
> "messagesIn" : 0,
> "messagesOut" : 0,
> "sessionCount" : 0,
> "transactedMessagesIn" : 0,
> "transactedMessagesOut" : 0
> }
> }
> {noformat}
> It seems that broker tries to close SSL connection and loops inside NonBlockingConnection.shutdownFinalWrite() continuously calling NonBlockingConnection.doWrite() -> NonBlockingConnectionTLSDelegate.doWrite() -> NonBlockingConnectionTLSDelegate.wrapBufferArray().
> After adding circuit breaker and explicit logging in methods NonBlockingConnection.doWrite(), NonBlockingConnectionTLSDelegate.doWrite() and NonBlockingConnectionTLSDelegate.wrapBufferArray() following logs were retrieved:
> {noformat}
> 2021-05-10 06:30:54,637 INFO [Broker-Config] (q.m.c.open) - [con:9,435,937(/127.0.0.1:52648)] CON-1001 : Open : Destination : amqps(90.163.253.5:10170) : Protocol Version : 1.0 : SSL
> 2021-05-10 06:30:54,688 INFO [IO-/127.0.0.1:52648] (q.m.c.open) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)] CON-1001 : Open : Destination : amqps(90.163.253.5:10170) : Protocol Version : 1.0 : SSL : Client ID : Exxeta-299e32f1-1d0a-4db6-aeb8-1822411b7fc6 : Client Version : 0.50.0 : Client Product : QpidJMS
> 2021-05-10 06:30:54,689 INFO [IO-/127.0.0.1:52648] (q.m.a.allowed) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)] ACL-1001 : Allowed : Access Virtualhost NAME=default,VIRTUALHOST_NAME=default
> 2021-05-10 06:30:54,709 INFO [IO-/127.0.0.1:52648] (q.m.c.create) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:0] CHN-1001 : Create
> 2021-05-10 06:30:54,739 INFO [IO-/127.0.0.1:52648] (q.m.c.create) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] CHN-1001 : Create
> 2021-05-10 06:30:54,771 INFO [VirtualHostNode-default-Config] (q.m.a.allowed) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] ACL-1001 : Allowed : Consume Queue NAME=broadcast.VTVTV_YYYYXXXXXZZZSSS.TradeConfirmation,DURABLE=true,EXCLUSIVE=false,TEMPORARY=false,AUTO_DELETE=false,VIRTUALHOST_NAME=default,CREATED_BY=admin
> 2021-05-10 06:30:54,771 INFO [VirtualHostNode-default-Config] (q.m.s.create) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] [sub:36,978(vh(/default)/qu(broadcast.VTVTV_YYYYXXXXXZZZSSS.TradeConfirmation)] SUB-1001 : Create
> 2021-05-10 06:30:54,799 INFO [VirtualHostNode-default-Config] (q.m.a.allowed) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] ACL-1001 : Allowed : Consume Queue NAME=broadcast.VTVTV_YYYYXXXXXZZZSSS.Workflow,DURABLE=true,EXCLUSIVE=false,TEMPORARY=false,AUTO_DELETE=false,VIRTUALHOST_NAME=default,CREATED_BY=admin
> 2021-05-10 06:30:54,799 INFO [VirtualHostNode-default-Config] (q.m.s.create) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] [sub:36,979(vh(/default)/qu(broadcast.VTVTV_YYYYXXXXXZZZSSS.Workflow)] SUB-1001 : Create
> 2021-05-10 06:30:54,816 INFO [VirtualHostNode-default-Config] (q.m.a.allowed) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] ACL-1001 : Allowed : Consume Queue NAME=broadcast.VTVTV_YYYYXXXXXZZZSSS.Public,DURABLE=true,EXCLUSIVE=false,TEMPORARY=false,AUTO_DELETE=false,VIRTUALHOST_NAME=default,CREATED_BY=admin
> 2021-05-10 06:30:54,816 INFO [VirtualHostNode-default-Config] (q.m.s.create) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] [sub:36,980(vh(/default)/qu(broadcast.VTVTV_YYYYXXXXXZZZSSS.Public)] SUB-1001 : Create
> 2021-05-10 06:30:54,834 INFO [VirtualHostNode-default-Config] (q.m.a.allowed) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] ACL-1001 : Allowed : Consume Queue NAME=response.VTVTV_YYYYXXXXXZZZSSS,DURABLE=true,EXCLUSIVE=false,TEMPORARY=false,AUTO_DELETE=false,VIRTUALHOST_NAME=default,CREATED_BY=admin
> 2021-05-10 06:30:54,834 INFO [VirtualHostNode-default-Config] (q.m.s.create) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] [sub:36,981(vh(/default)/qu(response.VTVTV_YYYYXXXXXZZZSSS)] SUB-1001 : Create
> 2021-05-10 06:30:54,856 INFO [IO-/127.0.0.1:52648] (q.m.s.create) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] SND-1001 : Create : qpid-jms:sender:ID:e72a83ab-2332-4e64-b891-0bf26cb8f632:1:1:1:request.VTVTV_YYYYXXXXXZZZSSS : request.VTVTV_YYYYXXXXXZZZSSS
> 2021-05-10 10:01:40,576 INFO [IO-/127.0.0.1:52648] (q.m.c.close) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:0] [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:0] CHN-1003 : Close
> 2021-05-10 10:01:40,576 INFO [VirtualHostNode-default-Config] (q.m.s.close) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] [sub:36,978(vh(/default)/qu(broadcast.VTVTV_YYYYXXXXXZZZSSS.TradeConfirmation)] SUB-1002 : Close
> 2021-05-10 10:01:40,576 INFO [IO-/127.0.0.1:52648] (q.m.s.close) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] SND-1002 : Close : qpid-jms:sender:ID:e72a83ab-2332-4e64-b891-0bf26cb8f632:1:1:1:request.VTVTV_YYYYXXXXXZZZSSS : request.VTVTV_YYYYXXXXXZZZSSS
> 2021-05-10 10:01:40,577 INFO [VirtualHostNode-default-Config] (q.m.s.close) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] [sub:36,980(vh(/default)/qu(broadcast.VTVTV_YYYYXXXXXZZZSSS.Public)] SUB-1002 : Close
> 2021-05-10 10:01:40,578 INFO [VirtualHostNode-default-Config] (q.m.s.close) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] [sub:36,981(vh(/default)/qu(response.VTVTV_YYYYXXXXXZZZSSS)] SUB-1002 : Close
> 2021-05-10 10:01:40,578 INFO [VirtualHostNode-default-Config] (q.m.s.close) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] [sub:36,979(vh(/default)/qu(broadcast.VTVTV_YYYYXXXXXZZZSSS.Workflow)] SUB-1002 : Close
> 2021-05-10 10:01:40,579 INFO [IO-/127.0.0.1:52648] (q.m.c.close) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)/ch:1] CHN-1003 : Close
> 2021-05-10 10:01:40,579 INFO [IO-/127.0.0.1:52648] (o.a.q.s.p.v.AMQPConnection_1_0Impl) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@/127.0.0.1:52648/default)] : Connection closed with error : amqp:resource-limit-exceeded - local-idle-timeout expired
> 2021-05-10 10:01:40,644 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - bufCount: 2
> 2021-05-10 10:01:40,644 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - _status: [ Status = CLOSED, HandshakeStatus = NOT_HANDSHAKING, bytesConsumed = 0, bytesProduced = 0 ], _sslEngine.isOutboundDone(): true, _sslEngine.isInboundDone(): true, _sslEngine.getPeerHost(): null, _sslEngine.getPeerPort(): -1, buffers.size(): 2, _encryptedOutput.size(): 0, _netOutputBuffer.remaining(): 152185, _sslEngine.getSession().getPacketBufferSize(): 16709, _sslEngine.getSession().getCreationTime(): 1620621054549, _sslEngine.getSession().getLastAccessedTime(): 1620621054549, _sslEngine.getHandshakeSession().isValid(): null handshake session
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - buffers.size(): 2, bufsSent: false, bytesWritten: -1, _encryptedOutput: 0
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnection) - Looping detected: false, 0, 2
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - bufCount: 2
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - _status: [ Status = CLOSED, HandshakeStatus = NOT_HANDSHAKING, bytesConsumed = 0, bytesProduced = 0 ], _sslEngine.isOutboundDone(): true, _sslEngine.isInboundDone(): true, _sslEngine.getPeerHost(): null, _sslEngine.getPeerPort(): -1, buffers.size(): 2, _encryptedOutput.size(): 0, _netOutputBuffer.remaining(): 152185, _sslEngine.getSession().getPacketBufferSize(): 16709, _sslEngine.getSession().getCreationTime(): 1620621054549, _sslEngine.getSession().getLastAccessedTime(): 1620621054549, _sslEngine.getHandshakeSession().isValid(): null handshake session
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - buffers.size(): 2, bufsSent: false, bytesWritten: -1, _encryptedOutput: 0
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnection) - Looping detected: false, 0, 2
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - bufCount: 2
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - _status: [ Status = CLOSED, HandshakeStatus = NOT_HANDSHAKING, bytesConsumed = 0, bytesProduced = 0 ], _sslEngine.isOutboundDone(): true, _sslEngine.isInboundDone(): true, _sslEngine.getPeerHost(): null, _sslEngine.getPeerPort(): -1, buffers.size(): 2, _encryptedOutput.size(): 0, _netOutputBuffer.remaining(): 152185, _sslEngine.getSession().getPacketBufferSize(): 16709, _sslEngine.getSession().getCreationTime(): 1620621054549, _sslEngine.getSession().getLastAccessedTime(): 1620621054549, _sslEngine.getHandshakeSession().isValid(): null handshake session
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - buffers.size(): 2, bufsSent: false, bytesWritten: -1, _encryptedOutput: 0
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnection) - Looping detected: false, 0, 2
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - bufCount: 2
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - _status: [ Status = CLOSED, HandshakeStatus = NOT_HANDSHAKING, bytesConsumed = 0, bytesProduced = 0 ], _sslEngine.isOutboundDone(): true, _sslEngine.isInboundDone(): true, _sslEngine.getPeerHost(): null, _sslEngine.getPeerPort(): -1, buffers.size(): 2, _encryptedOutput.size(): 0, _netOutputBuffer.remaining(): 152185, _sslEngine.getSession().getPacketBufferSize(): 16709, _sslEngine.getSession().getCreationTime(): 1620621054549, _sslEngine.getSession().getLastAccessedTime(): 1620621054549, _sslEngine.getHandshakeSession().isValid(): null handshake session
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - buffers.size(): 2, bufsSent: false, bytesWritten: -1, _encryptedOutput: 0
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnection) - Looping detected: false, 0, 2
> 2021-05-10 10:01:40,645 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - bufCount: 2
> 2021-05-10 10:01:40,646 WARN [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnectionTLSDelegate) - _status: [ Status = CLOSED, HandshakeStatus = NOT_HANDSHAKING, bytesConsumed = 0, bytesProduced = 0 ], _sslEngine.isOutboundDone(): true, _sslEngine.isInboundDone(): true, _sslEngine.getPeerHost(): null, _sslEngine.getPeerPort(): -1, buffers.size(): 2, _encryptedOutput.size(): 0, _netOutputBuffer.remaining(): 152185, _sslEngine.getSession().getPacketBufferSize(): 16709, _sslEngine.getSession().getCreationTime(): 1620621054549, _sslEngine.getSession().getLastAccessedTime(): 1620621054549, _sslEngine.getHandshakeSession().isValid(): null handshake session
> 2021-05-10 10:01:40,646 INFO [IO-/127.0.0.1:52648] (o.a.q.s.t.NonBlockingConnection) - Exception performing final write/close for '/127.0.0.1:52648': Looping detected, executing circuit breaker
> 2021-05-10 10:01:40,647 INFO [Broker-Config] (q.m.c.close) - [con:9,435,937(VTVTV_YYYYXXXXXZZZSSS@null/default)] CON-1002 : Close
> {noformat}
> Noticeable is SSLEngineResult.Status.CLOSED as well as SSLEngineResult.HandshakeStatus NOT_HANDSHAKING. Combination of those statuses indicates that the last operation closed broker side of the SSLEngine, or the operation could not be completed because it was already closed.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org