You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by "Keith Wall (JIRA)" <ji...@apache.org> on 2015/08/26 11:59:45 UTC
[jira] [Updated] (QPID-6711) [0-8..0-9-1] Client may send a
ChannelOpen before connection establishment is complete
[ https://issues.apache.org/jira/browse/QPID-6711?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Keith Wall updated QPID-6711:
-----------------------------
Description:
I am seeing a sporadic issue on the legacy Qpid Client when using the 0-8..0-91 protocol with SSL. Occasionally, the client is seen to emit a ChannelOpen before the ConnectionOpenOk has been received. The Java Broker detects that illegal state and closes the connection.
I have not checked if this is a regression. I am reproducing this issue running the Perftest profile VaryingNumberOfParticipantsSSL.js using a Java Broker configured with SSL using the canned test certs.
After augmenting the Broker to log a stack trace AMQPConnection_0_8#assertState)
{noformat}
2015-08-26 09:26:47,977 ERROR [IO-/127.0.0.1:51674] (o.a.q.s.p.v.AMQPConnection_0_8) - Connection is in the wrong state AWAIT_START_OK , expecting OPEN
java.lang.Exception: null
at org.apache.qpid.server.protocol.v0_8.AMQPConnection_0_8.assertState(AMQPConnection_0_8.java:1061) [classes/:na]
at org.apache.qpid.server.protocol.v0_8.AMQPConnection_0_8.receiveChannelOpen(AMQPConnection_0_8.java:1020) [classes/:na]
at org.apache.qpid.framing.ChannelOpenBody.process(ChannelOpenBody.java:92) [classes/:na]
at org.apache.qpid.codec.ServerDecoder.processMethod(ServerDecoder.java:122) [classes/:na]
{noformat}
And augmenting the Qpid Client to that IoSender and IoReceiver include the socket's localport:
{noformat}
2015-08-26 09:26:47,972 DEBUG [Dispatcher-2-Conn-34] o.a.q.c.AMQProtocolHandler SEND: AMQP1109
2015-08-26 09:26:47,972 INFO [Dispatcher-2-Conn-34] o.a.q.c.AMQConnection Connection 82 now connected from /127.0.0.1:51674 to localhost/127.0.0.1:5671
2015-08-26 09:26:47,973 DEBUG [Dispatcher-2-Conn-34] o.a.q.c.AMQConnection Are we connected:true
2015-08-26 09:26:47,973 DEBUG [Dispatcher-2-Conn-34] o.a.q.c.AMQConnection Connected with ProtocolHandler Version:0-9
2015-08-26 09:26:47,974 DEBUG [Dispatcher-2-Conn-1] o.a.q.c.AMQProtocolHandler SEND: Frame channelId: 2, bodyFrame: [BasicAckBodyImpl: deliveryTag=81, multiple=false]
2015-08-26 09:26:47,974 DEBUG [Dispatcher-2-Conn-34] o.a.q.c.AMQProtocolHandler SEND: org.apache.qpid.framing.CompositeAMQDataBlock{ 0=[Frame channelId: 3, bodyFrame: [BasicPublishBodyImpl: ticket=0, exchange=amq.direct, routingKey=controllerqueue, mandatory=true, immediate=false]] 1=[Frame channelId: 3, bodyFrame: ContentHeaderBody{classId=60, weight=0, bodySize=0, properties=reply-to = null,propertyFlags = 47312,ApplicationID = null,ClusterID = null,UserId = guest,JMSMessageID = ID:448e77ea-0fde-3dd8-9133-1654cdb15fad,JMSCorrelationID = null,JMSDeliveryMode = 2,JMSExpiration = 0,JMSPriority = 4,JMSTimestamp = 1440577607974,JMSType = null}]}
2015-08-26 09:26:47,974 DEBUG [Dispatcher-2-Conn-34] o.a.q.c.AMQProtocolHandler SEND: Frame channelId: 2, bodyFrame: [BasicAckBodyImpl: deliveryTag=1, multiple=false]
2015-08-26 09:26:47,975 DEBUG [Dispatcher-2-Conn-34] o.a.q.c.AMQProtocolHandler SEND: Frame channelId: 1, bodyFrame: [ChannelOpenBody]
2015-08-26 09:26:47,976 DEBUG [IoRcvr-localhost/127.0.0.1:5671-51674] o.a.q.c.AMQProtocolHandler RECV: Frame channelId: 0, bodyFrame: [ConnectionStartBodyImpl: versionMajor=0, versionMinor=9, serverProperties={product=[LONG_STRING: qpid], version=[LONG_STRING: 6.0.0-SNAPSHOT], qpid.build=[LONG_STRING: Unversioned directory], qpid.instance_name=[LONG_STRING: Broker], qpid.close_when_no_route=[LONG_STRING: true], qpid.message_compression_supported=[LONG_STRING: true], qpid.confirmed_publish_supported=[LONG_STRING: true], qpid.virtualhost_properties_supported=[LONG_STRING: true]}, mechanisms=[80, 76, 65, 73, 78, 32, 67, 82, 65, 77, 45, 77, 68, 53], locales=[101, 110, 95, 85, 83]]
2015-08-26 09:26:47,977 DEBUG [IoRcvr-localhost/127.0.0.1:5671-51674] o.a.q.c.AMQProtocolHandler SEND: Frame channelId: 0, bodyFrame: [ConnectionStartOkBodyImpl: clientProperties={instance=[LONG_STRING: clientid], product=[LONG_STRING: qpid], version=[LONG_STRING: 6.0.0-SNAPSHOT], platform=[LONG_STRING: Java(TM) SE Runtime Environment, 1.7.0_79-b15, Oracle Corporation, x86_64, Mac OS X, 10.10.4, unknown], qpid.client_process=[LONG_STRING: Qpid Java Client], qpid.client_pid=[INT: 1142], qpid.message_compression_supported=[LONG_STRING: false]}, mechanism=CRAM-MD5, response=null, locale=en_US]
2015-08-26 09:26:47,978 DEBUG [IoRcvr-localhost/127.0.0.1:5672-51588] o.a.q.c.AMQProtocolHandler RECV: Frame channelId: 2, bodyFrame: [BasicDeliverBodyImpl: consumerTag=1, deliveryTag=82, redelivered=false, exchange=amq.direct, routingKey=controllerqueue]
2015-08-26 09:26:47,978 DEBUG [IoRcvr-localhost/127.0.0.1:5672-51588] o.a.q.c.AMQProtocolHandler RECV: Frame channelId: 2, bodyFrame: ContentHeaderBody{classId=60, weight=0, bodySize=0, properties=reply-to = null,propertyFlags = 47312,ApplicationID = null,ClusterID = null,UserId = guest,JMSMessageID = ID:448e77ea-0fde-3dd8-9133-1654cdb15fad,JMSCorrelationID = null,JMSDeliveryMode = 2,JMSExpiration = 0,JMSPriority = 4,JMSTimestamp = 1440577607974,JMSType = null}
2015-08-26 09:26:47,980 DEBUG [Dispatcher-2-Conn-1] o.a.q.c.AMQProtocolHandler SEND: Frame channelId: 2, bodyFrame: [BasicAckBodyImpl: deliveryTag=82, multiple=false]
2015-08-26 09:26:47,981 DEBUG [IoRcvr-localhost/127.0.0.1:5671-51673] o.a.q.c.AMQProtocolHandler RECV: Frame channelId: 0, bodyFrame: [ConnectionCloseBodyImpl: replyCode=503, replyText=Command Invalid - not in required state OPEN current state AWAIT_START_OK, classId=20, methodId=10]
2015-08-26 09:26:47,981 DEBUG [IoRcvr-localhost/127.0.0.1:5671-51674] o.a.q.c.AMQProtocolHandler RECV: Frame channelId: 0, bodyFrame: [ConnectionCloseBodyImpl: replyCode=503, replyText=Command Invalid - not in required state OPEN current state AWAIT_START_OK, classId=20, methodId=10]
{noformat}
Notice that 51674 is reporting "Connection 82 now connected" before ConnectionOpenOk has been received. It suggests to me a defect in the StateWaiter mechanics.
was:
I am seeing a sporadic issue on the legacy Qpid Client when using the 0-8..0-91 protocol with SSL. Occasionally, the client is seen to emit a ChannelOpen before the ConnectionOpenOk has been received. The Java Broker detects that illegal state and closes the connection.
I have not checked if this is a regression. I am reproducing this issue running the Perftest profile VaryingNumberOfParticipantsSSL.js using a Java Broker configured with SSL using the canned test certs.
> [0-8..0-9-1] Client may send a ChannelOpen before connection establishment is complete
> ---------------------------------------------------------------------------------------
>
> Key: QPID-6711
> URL: https://issues.apache.org/jira/browse/QPID-6711
> Project: Qpid
> Issue Type: Bug
> Components: Java Client
> Affects Versions: qpid-java-6.0
> Environment: MacBookAir 1.7 GHz Intel Core i7
> Maximum Memory : 1,908,932,608 bytes
> Platform : JVM : Oracle Corporation version: 1.7.0_45-b18 OS : Mac OS X version: 10.10.4 arch: x86_64 cores: 4
> Reporter: Keith Wall
>
> I am seeing a sporadic issue on the legacy Qpid Client when using the 0-8..0-91 protocol with SSL. Occasionally, the client is seen to emit a ChannelOpen before the ConnectionOpenOk has been received. The Java Broker detects that illegal state and closes the connection.
> I have not checked if this is a regression. I am reproducing this issue running the Perftest profile VaryingNumberOfParticipantsSSL.js using a Java Broker configured with SSL using the canned test certs.
> After augmenting the Broker to log a stack trace AMQPConnection_0_8#assertState)
> {noformat}
> 2015-08-26 09:26:47,977 ERROR [IO-/127.0.0.1:51674] (o.a.q.s.p.v.AMQPConnection_0_8) - Connection is in the wrong state AWAIT_START_OK , expecting OPEN
> java.lang.Exception: null
> at org.apache.qpid.server.protocol.v0_8.AMQPConnection_0_8.assertState(AMQPConnection_0_8.java:1061) [classes/:na]
> at org.apache.qpid.server.protocol.v0_8.AMQPConnection_0_8.receiveChannelOpen(AMQPConnection_0_8.java:1020) [classes/:na]
> at org.apache.qpid.framing.ChannelOpenBody.process(ChannelOpenBody.java:92) [classes/:na]
> at org.apache.qpid.codec.ServerDecoder.processMethod(ServerDecoder.java:122) [classes/:na]
> {noformat}
> And augmenting the Qpid Client to that IoSender and IoReceiver include the socket's localport:
> {noformat}
> 2015-08-26 09:26:47,972 DEBUG [Dispatcher-2-Conn-34] o.a.q.c.AMQProtocolHandler SEND: AMQP1109
> 2015-08-26 09:26:47,972 INFO [Dispatcher-2-Conn-34] o.a.q.c.AMQConnection Connection 82 now connected from /127.0.0.1:51674 to localhost/127.0.0.1:5671
> 2015-08-26 09:26:47,973 DEBUG [Dispatcher-2-Conn-34] o.a.q.c.AMQConnection Are we connected:true
> 2015-08-26 09:26:47,973 DEBUG [Dispatcher-2-Conn-34] o.a.q.c.AMQConnection Connected with ProtocolHandler Version:0-9
> 2015-08-26 09:26:47,974 DEBUG [Dispatcher-2-Conn-1] o.a.q.c.AMQProtocolHandler SEND: Frame channelId: 2, bodyFrame: [BasicAckBodyImpl: deliveryTag=81, multiple=false]
> 2015-08-26 09:26:47,974 DEBUG [Dispatcher-2-Conn-34] o.a.q.c.AMQProtocolHandler SEND: org.apache.qpid.framing.CompositeAMQDataBlock{ 0=[Frame channelId: 3, bodyFrame: [BasicPublishBodyImpl: ticket=0, exchange=amq.direct, routingKey=controllerqueue, mandatory=true, immediate=false]] 1=[Frame channelId: 3, bodyFrame: ContentHeaderBody{classId=60, weight=0, bodySize=0, properties=reply-to = null,propertyFlags = 47312,ApplicationID = null,ClusterID = null,UserId = guest,JMSMessageID = ID:448e77ea-0fde-3dd8-9133-1654cdb15fad,JMSCorrelationID = null,JMSDeliveryMode = 2,JMSExpiration = 0,JMSPriority = 4,JMSTimestamp = 1440577607974,JMSType = null}]}
> 2015-08-26 09:26:47,974 DEBUG [Dispatcher-2-Conn-34] o.a.q.c.AMQProtocolHandler SEND: Frame channelId: 2, bodyFrame: [BasicAckBodyImpl: deliveryTag=1, multiple=false]
> 2015-08-26 09:26:47,975 DEBUG [Dispatcher-2-Conn-34] o.a.q.c.AMQProtocolHandler SEND: Frame channelId: 1, bodyFrame: [ChannelOpenBody]
> 2015-08-26 09:26:47,976 DEBUG [IoRcvr-localhost/127.0.0.1:5671-51674] o.a.q.c.AMQProtocolHandler RECV: Frame channelId: 0, bodyFrame: [ConnectionStartBodyImpl: versionMajor=0, versionMinor=9, serverProperties={product=[LONG_STRING: qpid], version=[LONG_STRING: 6.0.0-SNAPSHOT], qpid.build=[LONG_STRING: Unversioned directory], qpid.instance_name=[LONG_STRING: Broker], qpid.close_when_no_route=[LONG_STRING: true], qpid.message_compression_supported=[LONG_STRING: true], qpid.confirmed_publish_supported=[LONG_STRING: true], qpid.virtualhost_properties_supported=[LONG_STRING: true]}, mechanisms=[80, 76, 65, 73, 78, 32, 67, 82, 65, 77, 45, 77, 68, 53], locales=[101, 110, 95, 85, 83]]
> 2015-08-26 09:26:47,977 DEBUG [IoRcvr-localhost/127.0.0.1:5671-51674] o.a.q.c.AMQProtocolHandler SEND: Frame channelId: 0, bodyFrame: [ConnectionStartOkBodyImpl: clientProperties={instance=[LONG_STRING: clientid], product=[LONG_STRING: qpid], version=[LONG_STRING: 6.0.0-SNAPSHOT], platform=[LONG_STRING: Java(TM) SE Runtime Environment, 1.7.0_79-b15, Oracle Corporation, x86_64, Mac OS X, 10.10.4, unknown], qpid.client_process=[LONG_STRING: Qpid Java Client], qpid.client_pid=[INT: 1142], qpid.message_compression_supported=[LONG_STRING: false]}, mechanism=CRAM-MD5, response=null, locale=en_US]
> 2015-08-26 09:26:47,978 DEBUG [IoRcvr-localhost/127.0.0.1:5672-51588] o.a.q.c.AMQProtocolHandler RECV: Frame channelId: 2, bodyFrame: [BasicDeliverBodyImpl: consumerTag=1, deliveryTag=82, redelivered=false, exchange=amq.direct, routingKey=controllerqueue]
> 2015-08-26 09:26:47,978 DEBUG [IoRcvr-localhost/127.0.0.1:5672-51588] o.a.q.c.AMQProtocolHandler RECV: Frame channelId: 2, bodyFrame: ContentHeaderBody{classId=60, weight=0, bodySize=0, properties=reply-to = null,propertyFlags = 47312,ApplicationID = null,ClusterID = null,UserId = guest,JMSMessageID = ID:448e77ea-0fde-3dd8-9133-1654cdb15fad,JMSCorrelationID = null,JMSDeliveryMode = 2,JMSExpiration = 0,JMSPriority = 4,JMSTimestamp = 1440577607974,JMSType = null}
> 2015-08-26 09:26:47,980 DEBUG [Dispatcher-2-Conn-1] o.a.q.c.AMQProtocolHandler SEND: Frame channelId: 2, bodyFrame: [BasicAckBodyImpl: deliveryTag=82, multiple=false]
> 2015-08-26 09:26:47,981 DEBUG [IoRcvr-localhost/127.0.0.1:5671-51673] o.a.q.c.AMQProtocolHandler RECV: Frame channelId: 0, bodyFrame: [ConnectionCloseBodyImpl: replyCode=503, replyText=Command Invalid - not in required state OPEN current state AWAIT_START_OK, classId=20, methodId=10]
> 2015-08-26 09:26:47,981 DEBUG [IoRcvr-localhost/127.0.0.1:5671-51674] o.a.q.c.AMQProtocolHandler RECV: Frame channelId: 0, bodyFrame: [ConnectionCloseBodyImpl: replyCode=503, replyText=Command Invalid - not in required state OPEN current state AWAIT_START_OK, classId=20, methodId=10]
> {noformat}
> Notice that 51674 is reporting "Connection 82 now connected" before ConnectionOpenOk has been received. It suggests to me a defect in the StateWaiter mechanics.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org