I had a look at this on master and though I did see a missing guard
(diff below) on the connection close that could be related, I haven't
reproduced what you are seeing even without that. It may still be
worth you giving it a try out.
Your logging snippets only include protons protocol trace, it might
also help to turn on some of the other client logging.
I also think I see an issue with the closeTimeout handling in that in
one place it seems likely to be using the requestTimeout value
instead. Need to investigate that further.
I'm heading on vacation so itll be late next week before I get back to
having a further look.
+++ b/qpid-jms-client/src/main/java/org/apache/qpid/jms/JmsConnection.java
@@ -185,6 +185,7 @@ public class JmsConnection implements
AutoCloseable, Connection, TopicConnection
if (isConnected() && !failed.get()) {
ProviderFuture request = new ProviderFuture();
try {
+ requests.put(request, request);
provider.destroy(connectionInfo, request);
try {
@@ -200,6 +201,8 @@ public class JmsConnection implements
AutoCloseable, Connection, TopicConnection
}
} catch(ProviderClosedException pce) {
LOG.debug("Ignoring provider closed exception
during connection close");
+ } finally {
+ requests.remove(request);
}
}
On 24 November 2016 at 17:08, DraCzech <dracz...@gmail.com> wrote:
> So I tried to turn on logging on qpid and this is what I found so far.
>
> In case I shut down the messaging bundle, it sends *Close*, receives
> *Close*, everything goes fine.
>
> But In case the device loses network connection it sends *Close* and waits
> for response which never comes.
>
> I'm using factory.setCloseTimeout(8000) and amqp.idleTimeout=120000 on my
> URL. I'd expect one of these parameters to fire some exception after
> respective period of time. But every time I lose network the cleaning thread
> hangs and I have to kill it manually (currently timeout is 25s).
>
> *Network lost:*
> 2016-11-24 16:41:38.315759 [19105288:4] ->
> Attach{name='qpid-jms:sender:ID:7fa560e5-9f45-43ab-9215-2b6021fec6d0:3:-1:15:/devices/7C9763001961/messages/events',
> handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
> source=Source{address='ID:7fa560e5-9f45-43ab-9215-2b6021fec6d0:3:-1:15',
> durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
> dynamicNodeProperties=null, distributionMode=null, filter=null,
> defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list],
> capabilities=null},
> target=Target{address='/devices/7C9763001961/messages/events', durable=NONE,
> expiryPolicy=SESSION_END, timeout=0, dynamic=false,
> dynamicNodeProperties=null, capabilities=[queue]}, unsettled=null,
> incompleteUnsettled=false, initialDeliveryCount=0, maxMessageSize=null,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> 2016-11-24 16:41:38.991236 [19105288:4] <-
> Attach{name='qpid-jms:sender:ID:7fa560e5-9f45-43ab-9215-2b6021fec6d0:3:-1:15:/devices/7C9763001961/messages/events',
> handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
> source=Source{address='ID:7fa560e5-9f45-43ab-9215-2b6021fec6d0:3:-1:15',
> durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
> dynamicNodeProperties=null, distributionMode=null, filter=null,
> defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list],
> capabilities=null},
> target=Target{address='/devices/7C9763001961/messages/events', durable=NONE,
> expiryPolicy=SESSION_END, timeout=0, dynamic=false,
> dynamicNodeProperties=null, capabilities=[queue]}, unsettled=null,
> incompleteUnsettled=false, initialDeliveryCount=null,
> maxMessageSize=1048576, offeredCapabilities=null, desiredCapabilities=null,
> properties=null}
> 2016-11-24 16:41:39.150984 [19105288:4] <- Flow{nextIncomingId=16,
> incomingWindow=5000, nextOutgoingId=1, outgoingWindow=2047, handle=0,
> deliveryCount=0, linkCredit=1000, available=0, drain=false, echo=false,
> properties=null}
> 2016-11-24 16:41:39.182738 [19105288:4] -> Transfer{handle=0,
> deliveryId=15, deliveryTag=0, messageFormat=0, settled=null, more=false,
> rcvSettleMode=null, state=null, resume=false, aborted=false,
> batchable=false} (10823)
> "\x00Sp\xc0\x02\x01A\x00Sr\xc1)\x04\xa3\x12x-opt-jms-msg-typeQ\x03\xa3\x0ex-opt-jms-destQ\x00\x00Ss\xc0\x83\x0a\xa10ID:ec766fb9-8779-4bbd-afe2-604752e8b480:1:6:1-16@\xa1%/devices/7C9763001961/messages/events@@@\xa3\x18application/octet-stream@@\x83\x00\x00\x01X\x976\xc2\xe6\x00St\xc1\xac\x10\xa1\x05boxId\xa1\x0c7C9763001961\xa1\x06scopes\xa1\x06SERVER\xa1\x08priority\xa1\x012\xa1\x04name\xa13com.openmatics.system.fw.config.localchange.request\xa1\x0bcomponentId\xa1\x02-1\xa1\x0atimeToLive\xa1\x02-1\xa1\x07version\xa1\x051.0.0\xa1\x06appKey\xa1\x03-14\x00Su\xb0\x00\x00(\xd1\x0b\x01\x1b\x01\x02com.openmatics.system.fw.config.localchange.reques\xf4\x0c\x03\x00$\x04\x01\x0e\x05\x04\x06\x02\x071.0.\xb0&\x01\x03\x03\x02LOCAL_VARIANT_TIMESTAM\xd0\x09\xe4\x8a\xb6\xf3\x92V\x03\x03LOCAL_VARIANT_ID\xd3&\x04\x01\x03\x05/sbx/config/lcr.xm\xec\x03\x067C9763001961_0148000569814\xb1\x03\x07BOX_CONFIGURATIO\xce\x01\x00\xc3\x01com.openmatics.shared.messaging.box.configuration.BoxConfiguration\x08\x00$\x09\x01\x01\x01com.openmat"...(truncated)
> 2016-11-24 16:41:39.745306 [19105288:4] <- Disposition{role=RECEIVER,
> first=15, last=null, settled=true, state=Accepted{}, batchable=false}
> 2016-11-24 16:41:39.747107 [19105288:4] -> Detach{handle=0, closed=true,
> error=null}
> 2016-11-24 16:41:39.919648 [19105288:4] <- Detach{handle=0, closed=true,
> error=null}
> 2016-11-24 16:41:45.202589 [19105288:0] -> Close{error=null}
>
> *Normal bundle shutdown:*
> 2016-11-24 16:51:11.517312 [18734493:6] ->
> Attach{name='qpid-jms:sender:ID:4c47ee6a-8f04-46bd-9a81-ac1be65b2b5e:15:-1:9:/devices/7C9763001961/messages/events',
> handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
> source=Source{address='ID:4c47ee6a-8f04-46bd-9a81-ac1be65b2b5e:15:-1:9',
> durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
> dynamicNodeProperties=null, distributionMode=null, filter=null,
> defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list],
> capabilities=null},
> target=Target{address='/devices/7C9763001961/messages/events', durable=NONE,
> expiryPolicy=SESSION_END, timeout=0, dynamic=false,
> dynamicNodeProperties=null, capabilities=[queue]}, unsettled=null,
> incompleteUnsettled=false, initialDeliveryCount=0, maxMessageSize=null,
> offeredCapabilities=null, desiredCapabilities=null, properties=null}
> 2016-11-24 16:51:11.690158 [18734493:6] <-
> Attach{name='qpid-jms:sender:ID:4c47ee6a-8f04-46bd-9a81-ac1be65b2b5e:15:-1:9:/devices/7C9763001961/messages/events',
> handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
> source=Source{address='ID:4c47ee6a-8f04-46bd-9a81-ac1be65b2b5e:15:-1:9',
> durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
> dynamicNodeProperties=null, distributionMode=null, filter=null,
> defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list],
> capabilities=null},
> target=Target{address='/devices/7C9763001961/messages/events', durable=NONE,
> expiryPolicy=SESSION_END, timeout=0, dynamic=false,
> dynamicNodeProperties=null, capabilities=[queue]}, unsettled=null,
> incompleteUnsettled=false, initialDeliveryCount=null,
> maxMessageSize=1048576, offeredCapabilities=null, desiredCapabilities=null,
> properties=null}
> 2016-11-24 16:51:11.842212 [18734493:6] <- Flow{nextIncomingId=10,
> incomingWindow=5000, nextOutgoingId=1, outgoingWindow=2047, handle=0,
> deliveryCount=0, linkCredit=1000, available=0, drain=false, echo=false,
> properties=null}
> 2016-11-24 16:51:11.861722 [18734493:6] -> Transfer{handle=0, deliveryId=9,
> deliveryTag=0, messageFormat=0, settled=null, more=false,
> rcvSettleMode=null, state=null, resume=false, aborted=false,
> batchable=false} (443)
> "\x00Sp\xc0\x02\x01A\x00Sr\xc1)\x04\xa3\x12x-opt-jms-msg-typeQ\x03\xa3\x0ex-opt-jms-destQ\x00\x00Ss\xc0\x83\x0a\xa10ID:15ec0e45-968b-4028-a0ac-80cf3e7a62fc:1:8:1-10@\xa1%/devices/7C9763001961/messages/events@@@\xa3\x18application/octet-stream@@\x83\x00\x00\x01X\x97?\x82\x0b\x00St\xc1\x93\x10\xa1\x05boxId\xa1\x0c7C9763001961\xa1\x06scopes\xa1\x06SERVER\xa1\x08priority\xa1\x014\xa1\x04name\xa1\x1bcom.openmatics.system.alive\xa1\x0bcomponentId\xa1\x02-1\xa1\x0atimeToLive\xa1\x02-1\xa1\x07version\xa1\x051.0.0\xa1\x06appKey\xa1\x02-3\x00Su\xa0a\x0b\x01\x05\x01\x02com.openmatics.system.aliv\xe5\x0c\x03\x00$\x04\x01\x0e\x05\x04\x06\x04\x071.0.\xb0&\x01\x03\x03\x02lo\xee\x1a\x03@*\xbc\x82C\x80w#\x03\x04Aliv\xe5\x1c\x05\xb4\xf7\xfb\xf3\x92V\x03\x06la\xf4\x1a\x07@H\xdfd\xf6\xb3\xbf\xcf"
> 2016-11-24 16:51:12.075635 [18734493:6] <- Disposition{role=RECEIVER,
> first=9, last=null, settled=true, state=Accepted{}, batchable=false}
> 2016-11-24 16:51:12.085039 [18734493:6] -> Detach{handle=0, closed=true,
> error=null}
> 2016-11-24 16:51:12.254863 [18734493:6] <- Detach{handle=0, closed=true,
> error=null}
> 2016-11-24 16:51:31.027968 [18734493:0] -> Close{error=null}
> 2016-11-24 16:51:31.977722 [18734493:0] <- Close{error=null}
>
>
>
> --
> View this message in context:
> http://qpid.2158936.n2.nabble.com/Qpid-JMS-client-JmsConnection-close-hangs-tp7654565p7654821.html
> Sent from the Apache Qpid users mailing list archive at Nabble.com.
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscr...@qpid.apache.org
> For additional commands, e-mail: users-h...@qpid.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@qpid.apache.org
For additional commands, e-mail: users-h...@qpid.apache.org
