Hi all,
We have a broker that uses proton-j 0.9.1 and we execute a test that does a
NULL lookup caused by the JMSSession.unsubscribe(name) call. The test passes
when using the QPID Proton JMS 0.3.0 but fails when run used the QPID legacy
JMS 0.32 with the following error:
javax.jms.JMSException: Timeout waiting for attach
at
org.apache.qpid.amqp_1_0.jms.impl.SessionImpl.unsubscribe(SessionImpl.java:663)
The test essentially does the following:
1. Create a durable subscriber
2. Close it (causes detach but no close)
3. Call JMSSession.unsubscribe(name) to delete the durable subscriber state)
What appears to be happening is that when the attach frame of step 3 is sent,
we call the link.open() method causing a LINK_LOCAL_OPEN proton event, however
proton does not send an attach response. This is only when using the legacy JMS
client and it looks like there are some differences in the frame traffic
(attached below)
Could this be a Proton bug?
Any help will be greatly appreciated.
Regards,
Alex Kritikos
Software AG
Proton client
——————-
Thu Jul 23 17:49:06 EEST 2015 ReadPool:2
AMQP>Trace:EventImpl{type=CONNECTION_INIT,
context=org.apache.qpid.proton.engine.impl.ConnectionImpl@3fa05c3d}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:1 AMQP>RECV: {Open{
containerId='testTopicDeleteDurableSubscriberState', hostname='localhost',
maxFrameSize=1048576, channelMax=32767, idleTimeOut=30000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=[sole-connection-for-container], properties=null}}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:1
AMQP>Trace:EventImpl{type=CONNECTION_REMOTE_OPEN,
context=org.apache.qpid.proton.engine.impl.ConnectionImpl@3fa05c3d}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:1
AMQP>Trace:EventImpl{type=CONNECTION_LOCAL_OPEN,
context=org.apache.qpid.proton.engine.impl.ConnectionImpl@3fa05c3d}
Thu Jul 23 17:49:06 EEST 2015 WritePool:4 AMQP>SENT: {Open{ containerId='',
hostname='', maxFrameSize=4294967295, channelMax=65535, idleTimeOut=30000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:3 AMQP>RECV: {Begin{remoteChannel=null,
nextOutgoingId=1, incomingWindow=0, outgoingWindow=0, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:3 AMQP>RECV: {Flow{nextIncomingId=null,
incomingWindow=2047, nextOutgoingId=1, outgoingWindow=0, handle=null,
deliveryCount=null, linkCredit=null, available=null, drain=false, echo=false,
properties=null}}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:3
AMQP>Trace:EventImpl{type=SESSION_INIT,
context=org.apache.qpid.proton.engine.impl.SessionImpl@3e755d27}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:3
AMQP>Trace:EventImpl{type=SESSION_REMOTE_OPEN,
context=org.apache.qpid.proton.engine.impl.SessionImpl@3e755d27}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:3
AMQP>Trace:EventImpl{type=SESSION_LOCAL_OPEN,
context=org.apache.qpid.proton.engine.impl.SessionImpl@3e755d27}
Thu Jul 23 17:49:06 EEST 2015 WritePool:1 AMQP>SENT: {Begin{remoteChannel=0,
nextOutgoingId=1, incomingWindow=0, outgoingWindow=0, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}}
Thu Jul 23 17:49:06 EEST 2015 WritePool:1 AMQP>SENT: {Flow{nextIncomingId=1,
incomingWindow=2147483647, nextOutgoingId=1, outgoingWindow=0, handle=null,
deliveryCount=null, linkCredit=null, available=null, drain=false, echo=false,
properties=null}}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:0 AMQP>RECV: {Begin{remoteChannel=null,
nextOutgoingId=1, incomingWindow=0, outgoingWindow=0, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:0 AMQP>RECV: {Flow{nextIncomingId=null,
incomingWindow=2047, nextOutgoingId=1, outgoingWindow=0, handle=null,
deliveryCount=null, linkCredit=null, available=null, drain=false, echo=false,
properties=null}}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:0
AMQP>Trace:EventImpl{type=SESSION_INIT,
context=org.apache.qpid.proton.engine.impl.SessionImpl@b36cb7a}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:0
AMQP>Trace:EventImpl{type=SESSION_REMOTE_OPEN,
context=org.apache.qpid.proton.engine.impl.SessionImpl@b36cb7a}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:0
AMQP>Trace:EventImpl{type=SESSION_LOCAL_OPEN,
context=org.apache.qpid.proton.engine.impl.SessionImpl@b36cb7a}
Thu Jul 23 17:49:06 EEST 2015 WritePool:2 AMQP>SENT: {Begin{remoteChannel=1,
nextOutgoingId=1, incomingWindow=0, outgoingWindow=0, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}}
Thu Jul 23 17:49:06 EEST 2015 WritePool:2 AMQP>SENT: {Flow{nextIncomingId=1,
incomingWindow=2147483647, nextOutgoingId=1, outgoingWindow=0, handle=null,
deliveryCount=null, linkCredit=null, available=null, drain=false, echo=false,
properties=null}}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:4 AMQP>RECV:
{Attach{name='testTopicDeleteDurableSubscriberState', handle=0, role=RECEIVER,
sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='testTopic', durable=UNSETTLED_STATE, expiryPolicy=NEVER,
timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=copy,
filter=null, defaultOutcome=Modified{deliveryFailed=true,
undeliverableHere=false, messageAnnotations=null},
outcomes=[amqp:accepted:list, amqp:rejected:list, amqp:released:list,
amqp:modified:list], capabilities=[topic]}, target=Target{address='null',
durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, capabilities=null}, unsettled=null,
incompleteUnsettled=false, initialDeliveryCount=null, maxMessageSize=null,
offeredCapabilities=null, desiredCapabilities=null, properties=null}}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:4 AMQP>Trace:EventImpl{type=LINK_INIT,
context=org.apache.qpid.proton.engine.impl.SenderImpl@3a68bc56}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:4
AMQP>Trace:EventImpl{type=LINK_REMOTE_OPEN,
context=org.apache.qpid.proton.engine.impl.SenderImpl@3a68bc56}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:4
AMQP>Trace:EventImpl{type=LINK_LOCAL_OPEN,
context=org.apache.qpid.proton.engine.impl.SenderImpl@3a68bc56}
Thu Jul 23 17:49:06 EEST 2015 WritePool:6 AMQP>SENT:
{Attach{name='testTopicDeleteDurableSubscriberState', handle=0, role=SENDER,
sndSettleMode=MIXED, rcvSettleMode=FIRST, source=Source{address='testTopic',
durable=UNSETTLED_STATE, expiryPolicy=NEVER, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=copy, filter=null,
defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=false,
messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=[topic]},
target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=null,
properties=null}}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:2 AMQP>RECV: {Flow{nextIncomingId=1,
incomingWindow=2047, nextOutgoingId=1, outgoingWindow=0, handle=0,
deliveryCount=0, linkCredit=1000, available=null, drain=false, echo=false,
properties=null}}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:2 AMQP>Trace:EventImpl{type=LINK_FLOW,
context=org.apache.qpid.proton.engine.impl.SenderImpl@3a68bc56}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:2 AMQP>RECV: {Detach{handle=0,
closed=false, error=null}}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:2
AMQP>Trace:EventImpl{type=LINK_REMOTE_DETACH,
context=org.apache.qpid.proton.engine.impl.SenderImpl@3a68bc56}
Thu Jul 23 17:49:06 EEST 2015 ReadPool:2
AMQP>Trace:EventImpl{type=LINK_LOCAL_DETACH,
context=org.apache.qpid.proton.engine.impl.SenderImpl@3a68bc56}
Thu Jul 23 17:49:06 EEST 2015 WritePool:1 AMQP>SENT: {Detach{handle=0,
closed=false, error=null}}
(this is when the unsubscribe(string) call occurs)
Thu Jul 23 17:49:50 EEST 2015 ReadPool:5 AMQP>RECV:
{Attach{name='testTopicDeleteDurableSubscriberState', handle=0, role=RECEIVER,
sndSettleMode=UNSETTLED, rcvSettleMode=FIRST, source=null,
target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=null,
maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=null,
properties=null}}
Thu Jul 23 17:49:50 EEST 2015 ReadPool:5 AMQP>Link init
Thu Jul 23 17:49:50 EEST 2015 ReadPool:5 AMQP>Trace:EventImpl{type=LINK_INIT,
context=org.apache.qpid.proton.engine.impl.SenderImpl@8a41535}
Thu Jul 23 17:49:50 EEST 2015 ReadPool:5
AMQP>Trace:EventImpl{type=LINK_REMOTE_OPEN,
context=org.apache.qpid.proton.engine.impl.SenderImpl@8a41535}
Thu Jul 23 17:49:50 EEST 2015 ReadPool:5
AMQP>Trace:EventImpl{type=LINK_LOCAL_OPEN,
context=org.apache.qpid.proton.engine.impl.SenderImpl@8a41535}
Thu Jul 23 17:49:50 EEST 2015 WritePool:5 AMQP>SENT:
{Attach{name='testTopicDeleteDurableSubscriberState', handle=0, role=SENDER,
sndSettleMode=MIXED, rcvSettleMode=FIRST, source=Source{address='testTopic',
durable=UNSETTLED_STATE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=null, capabilities=null},
target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END,
timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null},
unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0,
maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=null,
properties=null}}
Thu Jul 23 17:49:50 EEST 2015 ReadPool:1 AMQP>RECV: {Detach{handle=0,
closed=true, error=null}}
Thu Jul 23 17:49:50 EEST 2015 WritePool:2 AMQP>SENT: {Detach{handle=0,
closed=true, error=null}}
Thu Jul 23 17:49:50 EEST 2015 ReadPool:1
AMQP>Trace:EventImpl{type=LINK_REMOTE_CLOSE,
context=org.apache.qpid.proton.engine.impl.SenderImpl@8a41535}
Thu Jul 23 17:49:50 EEST 2015 ReadPool:1
AMQP>Trace:EventImpl{type=LINK_LOCAL_CLOSE,
context=org.apache.qpid.proton.engine.impl.SenderImpl@8a41535}
Thu Jul 23 17:49:50 EEST 2015 ReadPool:1 AMQP>Trace:EventImpl{type=LINK_FINAL,
context=org.apache.qpid.proton.engine.impl.SenderImpl@8a41535}
Legacy client
——————-
Thu Jul 23 17:36:59 EEST 2015 ReadPool:1
AMQP>Trace:EventImpl{type=CONNECTION_INIT,
context=org.apache.qpid.proton.engine.impl.ConnectionImpl@55602519}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:3 AMQP>RECV: {Open{
containerId='testTopicDeleteDurableSubscriberState', hostname='null',
maxFrameSize=65536, channelMax=255, idleTimeOut=null, outgoingLocales=null,
incomingLocales=null, offeredCapabilities=null, desiredCapabilities=null,
properties=null}}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:3
AMQP>Trace:EventImpl{type=CONNECTION_REMOTE_OPEN,
context=org.apache.qpid.proton.engine.impl.ConnectionImpl@55602519}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:3
AMQP>Trace:EventImpl{type=CONNECTION_LOCAL_OPEN,
context=org.apache.qpid.proton.engine.impl.ConnectionImpl@55602519}
Thu Jul 23 17:36:59 EEST 2015 WritePool:1 AMQP>SENT: {Open{ containerId='',
hostname='', maxFrameSize=4294967295, channelMax=65535, idleTimeOut=30000,
outgoingLocales=null, incomingLocales=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:5 AMQP>RECV: {Begin{remoteChannel=null,
nextOutgoingId=0, incomingWindow=2048, outgoingWindow=2048,
handleMax=4294967295, offeredCapabilities=null, desiredCapabilities=null,
properties=null}}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:5
AMQP>Trace:EventImpl{type=SESSION_INIT,
context=org.apache.qpid.proton.engine.impl.SessionImpl@6100bf59}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:5
AMQP>Trace:EventImpl{type=SESSION_REMOTE_OPEN,
context=org.apache.qpid.proton.engine.impl.SessionImpl@6100bf59}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:5
AMQP>Trace:EventImpl{type=SESSION_LOCAL_OPEN,
context=org.apache.qpid.proton.engine.impl.SessionImpl@6100bf59}
Thu Jul 23 17:36:59 EEST 2015 WritePool:4 AMQP>SENT: {Begin{remoteChannel=0,
nextOutgoingId=1, incomingWindow=0, outgoingWindow=0, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}}
Thu Jul 23 17:36:59 EEST 2015 WritePool:4 AMQP>SENT: {Flow{nextIncomingId=0,
incomingWindow=2147483647, nextOutgoingId=1, outgoingWindow=0, handle=null,
deliveryCount=null, linkCredit=null, available=null, drain=false, echo=false,
properties=null}}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:4 AMQP>RECV:
{Attach{name='testTopicDeleteDurableSubscriberState', handle=0, role=RECEIVER,
sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='topic://testTopic', durable=UNSETTLED_STATE,
expiryPolicy=NEVER, timeout=0, dynamic=false, dynamicNodeProperties=null,
distributionMode=copy, filter=null, defaultOutcome=null, outcomes=null,
capabilities=null},
target=Target{address='8e653a67-7b12-4fcc-a7e0-7f836c103928', durable=NONE,
expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null,
capabilities=null}, unsettled=null, incompleteUnsettled=false,
initialDeliveryCount=null, maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:4 AMQP>Link init
Thu Jul 23 17:36:59 EEST 2015 ReadPool:4 AMQP>Trace:EventImpl{type=LINK_INIT,
context=org.apache.qpid.proton.engine.impl.SenderImpl@78129dcf}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:4
AMQP>Trace:EventImpl{type=LINK_REMOTE_OPEN,
context=org.apache.qpid.proton.engine.impl.SenderImpl@78129dcf}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:4
AMQP>Trace:EventImpl{type=LINK_LOCAL_OPEN,
context=org.apache.qpid.proton.engine.impl.SenderImpl@78129dcf}
Thu Jul 23 17:36:59 EEST 2015 WritePool:2 AMQP>SENT:
{Attach{name='testTopicDeleteDurableSubscriberState', handle=0, role=SENDER,
sndSettleMode=MIXED, rcvSettleMode=FIRST,
source=Source{address='topic://testTopic', durable=UNSETTLED_STATE,
expiryPolicy=NEVER, timeout=0, dynamic=false, dynamicNodeProperties=null,
distributionMode=copy, filter=null, defaultOutcome=null, outcomes=null,
capabilities=null},
target=Target{address='8e653a67-7b12-4fcc-a7e0-7f836c103928', durable=NONE,
expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null,
capabilities=null}, unsettled=null, incompleteUnsettled=false,
initialDeliveryCount=0, maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:4 AMQP>RECV: {Detach{handle=0,
closed=false, error=null}}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:4
AMQP>Trace:EventImpl{type=LINK_REMOTE_DETACH,
context=org.apache.qpid.proton.engine.impl.SenderImpl@78129dcf}
Thu Jul 23 17:36:59 EEST 2015 ReadPool:4
AMQP>Trace:EventImpl{type=LINK_LOCAL_DETACH,
context=org.apache.qpid.proton.engine.impl.SenderImpl@78129dcf}
Thu Jul 23 17:36:59 EEST 2015 WritePool:1 AMQP>SENT: {Detach{handle=0,
closed=false, error=null}}
(this is when the unsubscribe(string) call occurs)
Thu Jul 23 17:37:21 EEST 2015 ReadPool:2 AMQP>RECV:
{Attach{name='testTopicDeleteDurableSubscriberState', handle=0, role=RECEIVER,
sndSettleMode=UNSETTLED, rcvSettleMode=FIRST, source=null,
target=Target{address='fe08f28a-f8ad-4031-8e63-a5759176f8da', durable=NONE,
expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null,
capabilities=null}, unsettled=null, incompleteUnsettled=false,
initialDeliveryCount=null, maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}}
Thu Jul 23 17:37:21 EEST 2015 ReadPool:2
AMQP>Trace:EventImpl{type=LINK_REMOTE_OPEN,
context=org.apache.qpid.proton.engine.impl.SenderImpl@78129dcf}
Thu Jul 23 17:37:21 EEST 2015 ReadPool:2
AMQP>Trace:EventImpl{type=LINK_LOCAL_OPEN,
context=org.apache.qpid.proton.engine.impl.SenderImpl@78129dcf}
This communication contains information which is confidential and may also be
privileged. It is for the exclusive use of the intended recipient(s). If you
are not the intended recipient(s), please note that any distribution, copying,
or use of this communication or the information in it, is strictly prohibited.
If you have received this communication in error please notify us by e-mail and
then delete the e-mail and any copies of it.
Software AG (UK) Limited Registered in England & Wales 1310740 -
http://www.softwareag.com/uk
