Hi Alex, As mentioned previously off-list, the detach(closed=false) support in proton was largely tacked on after the fact so there may still be some issues there, but the only one I knew of that would play into what you saw was that not free'ing a link object might lead to the situation.
I took yet another look and didn't spot anything else except https://issues.apache.org/jira/browse/PROTON-965. I don't think that would contribute here other than in a unintended helpful fashion, but given I don't know what the issue you are hitting is it might still be worth you checking if it makes any difference. I prodded the nightly snapshot job to build early if you want to give it a shot without building locally. Robbie On 23 July 2015 at 18:00, Kritikos, Alex <[email protected]> wrote: > 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 >
