Re: Qpid Proton (Java) - send() method frequently hangs when sending to ActiveMQ queue

Mon, 29 Aug 2016 06:41:03 -0700 

On 28/08/16 19:53, rlemmers wrote:

*jstack didn't help:*
/usr/lib/jvm/java/bin/jstack -J-d64 -m 32444
Attaching to process ID 32444, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 24.91-b01
Exception in thread "main" java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at sun.tools.jstack.JStack.runJStackTool(JStack.java:136)
        at sun.tools.jstack.JStack.main(JStack.java:102)
Caused by: java.lang.RuntimeException: Unable to deduce type of thread from
address 0x00007f6d442bc000 (expected type JavaThread, CompilerThread,
ServiceThread, JvmtiAgentThread, or SurrogateLockerThread)
        at
sun.jvm.hotspot.runtime.Threads.createJavaThreadWrapper(Threads.java:162)
        at sun.jvm.hotspot.runtime.Threads.first(Threads.java:150)
        at sun.jvm.hotspot.tools.PStack.initJFrameCache(PStack.java:205)
        at sun.jvm.hotspot.tools.PStack.run(PStack.java:66)
        at sun.jvm.hotspot.tools.PStack.run(PStack.java:53)
        at sun.jvm.hotspot.tools.PStack.run(PStack.java:48)
        at sun.jvm.hotspot.tools.JStack.run(JStack.java:60)
        at sun.jvm.hotspot.tools.Tool.start(Tool.java:221)
        at sun.jvm.hotspot.tools.JStack.main(JStack.java:86)
        ... 6 more
Caused by: sun.jvm.hotspot.types.WrongTypeException: No suitable match for
type of address 0x00007f6d442bc000


Did you run jstack as the same user as the process you are checking?


The two protocol traces below don't show any looping at that level. The 
one thing that I noticed happens on both the first two traces (the third 
doesn't include any protocol information), namely that the connection is 
closed by the sender before it receives the settlement (i.e. 
acknowledgement) from the broker.



You could try setting the outgoing window to 1 which I *think* would 
cause the send to block until the broker had acknowledged it, at which 
point you could stop the messenger. However I am merely speculating.


Do you have to use the messenger API? Could you use JMS instead?


*Information via "PN_TRACE_FRM=1", example 1 - message processed
successfully:*
18:30:40.384 [Thread-7] INFO  (ResponsesMessageSender.java:32)
p.s.j.m.s.ResponsesMessageSender - Sending ProxyServerResponseMessage with
connectionId: btNTVwiRwIvoxbabekREKBWIBnFGGhyC
18:30:40.392 [Thread-7] INFO  (ResponsesMessageSender.java:40)
p.s.j.m.s.ResponsesMessageSender - Using replyToQueue:
amqp://172.x.y.z:5672/queue://proxy-server-responses
18:30:40.392 [Thread-7] INFO  (ResponsesMessageSender.java:42)
p.s.j.m.s.ResponsesMessageSender - Set body
18:30:40.393 [Thread-7] INFO  (ResponsesMessageSender.java:46)
p.s.j.m.s.ResponsesMessageSender - Create messenger
18:30:40.393 [Thread-7] INFO  (ResponsesMessageSender.java:48)
p.s.j.m.s.ResponsesMessageSender - Start messenger
18:30:40.393 [Thread-7] INFO  (ResponsesMessageSender.java:50)
p.s.j.m.s.ResponsesMessageSender - Put message
18:30:40.396 [Thread-7] INFO  (ResponsesMessageSender.java:52)
p.s.j.m.s.ResponsesMessageSender - Change timeout to 5000 milliseconds
18:30:40.396 [Thread-7] INFO  (ResponsesMessageSender.java:54)
p.s.j.m.s.ResponsesMessageSender - Number of messages to send: 1
18:30:40.396 [Thread-7] INFO  (ResponsesMessageSender.java:55)
p.s.j.m.s.ResponsesMessageSender - send
[365297280:0] -> Open{ containerId='824b0ce1-eb31-4570-9736-43dd13685153',
hostname='172.x.y.z', maxFrameSize=4294967295, channelMax=65535,
idleTimeOut=null, outgoingLocales=null, incomingLocales=null,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[365297280:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[365297280:0] -> Attach{name='queue://proxy-server-responses', handle=0,
role=SENDER, sndSettleMode=MIXED, rcvSettleMode=FIRST,
source=Source{address='queue://proxy-server-responses', durable=NONE,
expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=null, capabilities=null},
target=Target{address='queue://proxy-server-responses', 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}
[365297280:0] <- Open{ containerId='', hostname='', maxFrameSize=4294967295,
channelMax=32767, idleTimeOut=null, outgoingLocales=null,
incomingLocales=null, offeredCapabilities=[ANONYMOUS-RELAY],
desiredCapabilities=null, properties={product=ActiveMQ,
platform=Java/1.7.0_91, topic-prefix=topic://, queue-prefix=queue://,
version=5.12.3}}
[365297280:0] <- Begin{remoteChannel=0, nextOutgoingId=1,
incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[365297280:0] <- Attach{name='queue://proxy-server-responses', handle=0,
role=RECEIVER, sndSettleMode=MIXED, rcvSettleMode=FIRST,
source=Source{address='queue://proxy-server-responses', durable=NONE,
expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=null, capabilities=null},
target=Target{address='queue://proxy-server-responses', 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}
[365297280:0] <- Flow{nextIncomingId=1, incomingWindow=2147483647,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=0,
linkCredit=1000, available=null, drain=false, echo=false, properties=null}
[365297280:0] -> Transfer{handle=0, deliveryId=0, deliveryTag=1,
messageFormat=0, settled=null, more=false, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (31723)
"\x00Ss\xc0G\x03@@\xa1Bamqp://172.x.y.z:5672/queue://proxy-server-responses\x00Sw\xb1\x00\x00{\x97~btNTVwiRwIvoxbabekREKBWIBnFGGhyC~PFNPQVAtRU5WOkVudmVsb3BlIHhtbG5zOlNPQVAtRU5WPSJodHRwOi8vc2NoZW1hcy54bWxzb2FwLm9yZy9zb2FwL2VudmVsb3BlLyI+PFNPQVAtRU5WOkhlYWRlci8+PFNPQVAtRU5WOkJvZHk+PG5zMjpGaW5kTWVzc2FnZUxvZ3NSZXNwb25zZSB4bWxuczpuczI9Imh0dHA6Ly93d3cuYWxsaWFuZGVyLmNvbS9zY2hlbWFzL29zZ3AvYWRtaW4vZGV2aWNlbWFuYWdlbWVudC8yMDE0LzEwIj48bnMyOk1lc3NhZ2VMb2dQYWdlPjxuczI6VG90YWxQYWdlcz4xNjcxPC9uczI6VG90YWxQYWdlcz48bnMyOk1lc3NhZ2VMb2dzPjxuczI6VGltZXN0YW1wPjIwMTYtMDgtMjhUMTE6MDE6MzIuMzIxWjwvbnMyOlRpbWVzdGFtcD48bnMyOk9yZ2FuaXNhdGlvbklkZW50aWZpY2F0aW9uPkxpYW5kZXJOZXRNYW5hZ2VtZW50PC9uczI6T3JnYW5pc2F0aW9uSWRlbnRpZmljYXRpb24+PG5zMjpEZXZpY2VVaWQ+QUFGZGd4VjgxTnN0Y1J3azwvbnMyOkRldmljZVVpZD48bnMyOkRldmljZUlkZW50aWZpY2F0aW9uPlNTTERfMTQtMzUtRUhWLTAwNjwvbnMyOkRldmljZUlkZW50aWZpY2F0aW9uPjxuczI6RGVjb2RlZE1lc3NhZ2U+ZXZlbnROb3RpZmljYXRpb25SZXNwb25zZSB7ICBzdGF0dXM6IE9LfTwvbnMyOkRlY29kZWRNZXNzYWdlPjxuczI6RW5jb2RlZE1lc3NhZ2U+MHg5Miw"...(truncated)
18:30:40.453 [Thread-7] INFO  (ResponsesMessageSender.java:57)
p.s.j.m.s.ResponsesMessageSender - stop
[365297280:0] -> Close{error=null}
[365297280:0] <- Disposition{role=RECEIVER, first=0, last=0, settled=true,
state=Accepted{}, batchable=false}
18:30:40.461 [loggingMessageListenerContainer-3] INFO
(LoggingMessageListener.java:43) l.i.jms.LoggingMessageListener - Received
logging message
[365297280:0] <- Close{error=null}
18:30:40.464 [Thread-7] INFO  (ResponsesMessageSender.java:59)
p.s.j.m.s.ResponsesMessageSender - Messenger stopped
18:30:40.464 [Thread-7] INFO  (PlatformCommunicationService.java:66)
p.s.a.s.PlatformCommunicationService - Successfully sent response message
via AMQP
[1720713056:0] -> Flow{nextIncomingId=10, incomingWindow=2147483647,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=9,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
[1720713056:0] -> Disposition{role=RECEIVER, first=8, last=8, settled=true,
state=Accepted{}, batchable=false}


*Information via "PN_TRACE_FRM=1", example 2 - message processing failure:*
18:32:12.712 [Thread-7] INFO  (ResponsesMessageSender.java:32)
p.s.j.m.s.ResponsesMessageSender - Sending ProxyServerResponseMessage with
connectionId: jTLObRLfNssrTlcfaoLpTjHysyiyTGMc
18:32:12.712 [Thread-7] INFO  (ResponsesMessageSender.java:40)
p.s.j.m.s.ResponsesMessageSender - Using replyToQueue:
amqp://172.x.y.z:5672/queue://proxy-server-responses
18:32:12.712 [Thread-7] INFO  (ResponsesMessageSender.java:42)
p.s.j.m.s.ResponsesMessageSender - Set body
18:32:12.712 [Thread-7] INFO  (ResponsesMessageSender.java:46)
p.s.j.m.s.ResponsesMessageSender - Create messenger
18:32:12.712 [Thread-7] INFO  (ResponsesMessageSender.java:48)
p.s.j.m.s.ResponsesMessageSender - Start messenger
18:32:12.713 [Thread-7] INFO  (ResponsesMessageSender.java:50)
p.s.j.m.s.ResponsesMessageSender - Put message
18:32:12.715 [Thread-7] INFO  (ResponsesMessageSender.java:52)
p.s.j.m.s.ResponsesMessageSender - Change timeout to 5000 milliseconds
18:32:12.715 [Thread-7] INFO  (ResponsesMessageSender.java:54)
p.s.j.m.s.ResponsesMessageSender - Number of messages to send: 1
18:32:12.715 [Thread-7] INFO  (ResponsesMessageSender.java:55)
p.s.j.m.s.ResponsesMessageSender - send
[1653882925:0] -> Open{ containerId='89038e7f-c319-4147-84b3-66fa20a0cfd7',
hostname='172.x.y.z', maxFrameSize=4294967295, channelMax=65535,
idleTimeOut=null, outgoingLocales=null, incomingLocales=null,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[1653882925:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[1653882925:0] -> Attach{name='queue://proxy-server-responses', handle=0,
role=SENDER, sndSettleMode=MIXED, rcvSettleMode=FIRST,
source=Source{address='queue://proxy-server-responses', durable=NONE,
expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=null, capabilities=null},
target=Target{address='queue://proxy-server-responses', 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}
[1653882925:0] <- Open{ containerId='', hostname='',
maxFrameSize=4294967295, channelMax=32767, idleTimeOut=null,
outgoingLocales=null, incomingLocales=null,
offeredCapabilities=[ANONYMOUS-RELAY], desiredCapabilities=null,
properties={product=ActiveMQ, platform=Java/1.7.0_91, topic-prefix=topic://,
queue-prefix=queue://, version=5.12.3}}
18:32:12.732 [loggingMessageListenerContainer-4] INFO
(LoggingMessageListener.java:43) l.i.jms.LoggingMessageListener - Received
logging message
[1653882925:0] <- Begin{remoteChannel=0, nextOutgoingId=1,
incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[1653882925:0] <- Attach{name='queue://proxy-server-responses', handle=0,
role=RECEIVER, sndSettleMode=MIXED, rcvSettleMode=FIRST,
source=Source{address='queue://proxy-server-responses', durable=NONE,
expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=null, capabilities=null},
target=Target{address='queue://proxy-server-responses', 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}
[1653882925:0] <- Flow{nextIncomingId=1, incomingWindow=2147483647,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=0,
linkCredit=1000, available=null, drain=false, echo=false, properties=null}
[1653882925:0] -> Transfer{handle=0, deliveryId=0, deliveryTag=1,
messageFormat=0, settled=null, more=false, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (31723)
"\x00Ss\xc0G\x03@@\xa1Bamqp://172.x.y.z:5672/queue://proxy-server-responses\x00Sw\xb1\x00\x00{\x97~jTLObRLfNssrTlcfaoLpTjHysyiyTGMc~PFNPQVAtRU5WOkVudmVsb3BlIHhtbG5zOlNPQVAtRU5WPSJodHRwOi8vc2NoZW1hcy54bWxzb2FwLm9yZy9zb2FwL2VudmVsb3BlLyI+PFNPQVAtRU5WOkhlYWRlci8+PFNPQVAtRU5WOkJvZHk+PG5zMjpGaW5kTWVzc2FnZUxvZ3NSZXNwb25zZSB4bWxuczpuczI9Imh0dHA6Ly93d3cuYWxsaWFuZGVyLmNvbS9zY2hlbWFzL29zZ3AvYWRtaW4vZGV2aWNlbWFuYWdlbWVudC8yMDE0LzEwIj48bnMyOk1lc3NhZ2VMb2dQYWdlPjxuczI6VG90YWxQYWdlcz4xNjcxPC9uczI6VG90YWxQYWdlcz48bnMyOk1lc3NhZ2VMb2dzPjxuczI6VGltZXN0YW1wPjIwMTYtMDgtMjhUMTE6MDE6MzIuMzIxWjwvbnMyOlRpbWVzdGFtcD48bnMyOk9yZ2FuaXNhdGlvbklkZW50aWZpY2F0aW9uPkxpYW5kZXJOZXRNYW5hZ2VtZW50PC9uczI6T3JnYW5pc2F0aW9uSWRlbnRpZmljYXRpb24+PG5zMjpEZXZpY2VVaWQ+QUFGZGd4VjgxTnN0Y1J3azwvbnMyOkRldmljZVVpZD48bnMyOkRldmljZUlkZW50aWZpY2F0aW9uPlNTTERfMTQtMzUtRUhWLTAwNjwvbnMyOkRldmljZUlkZW50aWZpY2F0aW9uPjxuczI6RGVjb2RlZE1lc3NhZ2U+ZXZlbnROb3RpZmljYXRpb25SZXNwb25zZSB7ICBzdGF0dXM6IE9LfTwvbnMyOkRlY29kZWRNZXNzYWdlPjxuczI6RW5jb2RlZE1lc3NhZ2U+MHg5Miw"...(truncated)
18:32:12.770 [Thread-7] INFO  (ResponsesMessageSender.java:57)
p.s.j.m.s.ResponsesMessageSender - stop
[1653882925:0] -> Close{error=null}
[1653882925:0] <- Disposition{role=RECEIVER, first=0, last=0, settled=true,
state=Accepted{}, batchable=false}
[1653882925:0] <- Close{error=null}
18:32:12.785 [Thread-7] INFO  (ResponsesMessageSender.java:59)
p.s.j.m.s.ResponsesMessageSender - Messenger stopped
18:32:12.786 [Thread-7] INFO  (PlatformCommunicationService.java:66)
p.s.a.s.PlatformCommunicationService - Successfully sent response message
via AMQP
[1720713056:0] -> Flow{nextIncomingId=15, incomingWindow=2147483647,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=14,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
[1720713056:0] -> Disposition{role=RECEIVER, first=13, last=13,
settled=true, state=Accepted{}, batchable=false}

*Information via "PN_TRACE_FRM=1", example 3 - another message processing
failure:*
18:27:33.884 [Thread-7] INFO  (ResponsesMessageSender.java:32)
p.s.j.m.s.ResponsesMessageSender - Sending ProxyServerResponseMessage with
connectionId: NPNQrTAKKqxKSQvMqeNuAnmMubYqspPu
18:27:33.884 [Thread-7] INFO  (ResponsesMessageSender.java:40)
p.s.j.m.s.ResponsesMessageSender - Using replyToQueue:
amqp://172.x.y.z:5672/queue://proxy-server-responses
18:27:33.884 [Thread-7] INFO  (ResponsesMessageSender.java:42)
p.s.j.m.s.ResponsesMessageSender - Set body
18:27:33.884 [Thread-7] INFO  (ResponsesMessageSender.java:46)
p.s.j.m.s.ResponsesMessageSender - Create messenger
18:27:33.885 [Thread-7] INFO  (ResponsesMessageSender.java:48)
p.s.j.m.s.ResponsesMessageSender - Start messenger
18:27:33.885 [Thread-7] INFO  (ResponsesMessageSender.java:50)
p.s.j.m.s.ResponsesMessageSender - Put message
18:27:33.886 [Thread-7] INFO  (ResponsesMessageSender.java:52)
p.s.j.m.s.ResponsesMessageSender - Change timeout to 5000 milliseconds
18:27:33.887 [Thread-7] INFO  (ResponsesMessageSender.java:54)
p.s.j.m.s.ResponsesMessageSender - Number of messages to send: 1
18:27:33.887 [Thread-7] INFO  (ResponsesMessageSender.java:55)
p.s.j.m.s.ResponsesMessageSender - send
18:27:33.930 [loggingMessageListenerContainer-3] INFO
(LoggingMessageListener.java:43) l.i.jms.LoggingMessageListener - Received
logging message
Aug 28, 2016 6:27:38 PM org.apache.qpid.proton.messenger.impl.MessengerImpl
waitUntil
SEVERE: Timeout when waiting for condition
org.apache.qpid.proton.messenger.impl.MessengerImpl$SentSettled@726cd304
after 5000 ms
18:27:38.888 [Thread-7] ERROR (ResponsesMessageSender.java:64)
p.s.j.m.s.ResponsesMessageSender - Some other exception
org.apache.qpid.proton.TimeoutException: null
        at
org.apache.qpid.proton.messenger.impl.MessengerImpl.waitUntil(MessengerImpl.java:849)
~[proton-j-0.13.0.jar:na]
        at
org.apache.qpid.proton.messenger.impl.MessengerImpl.send(MessengerImpl.java:417)
~[proton-j-0.13.0.jar:na]
        at
proxy.server.jms.message.senders.ResponsesMessageSender.send(ResponsesMessageSender.java:56)
~[ResponsesMessageSender.class:na]
        at
proxy.server.soap.clients.SoapClient.sendRequest(SoapClient.java:110)
[SoapClient.class:na]
        at
proxy.server.application.services.PlatformCommunicationService.handleIncomingRequest(PlatformCommunicationService.java:61)
[PlatformCommunicationService.class:na]
        at
proxy.server.jms.message.listeners.RequestsMessageListener.onMessage(RequestsMessageListener.java:79)
[RequestsMessageListener.class:na]
        at
proxy.server.jms.message.listeners.MessageReceiver.receive(MessageReceiver.java:81)
[MessageReceiver.class:na]
        at
proxy.server.jms.message.listeners.MessageReceiver.run(MessageReceiver.java:49)
[MessageReceiver.class:na]
18:27:38.889 [Thread-7] ERROR (PlatformCommunicationService.java:64)
p.s.a.s.PlatformCommunicationService - Unsuccessful at sending request to
platform.
[1720713056:0] -> Flow{nextIncomingId=9, incomingWindow=2147483647,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=8,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
[1720713056:0] -> Disposition{role=RECEIVER, first=7, last=7, settled=true,
state=Accepted{}, batchable=false}
Aug 28, 2016 6:27:40 PM org.apache.qpid.proton.messenger.impl.MessengerImpl
waitUntil
SEVERE: Timeout when waiting for condition
org.apache.qpid.proton.messenger.impl.MessengerImpl$MessageAvailable@559b7470
after 2000 ms
18:27:40.893 [Thread-7] DEBUG (MessageReceiver.java:84)
p.s.j.m.l.MessageReceiver - No message received during the defined timeout
period



--
View this message in context: 
http://qpid.2158936.n2.nabble.com/Qpid-Proton-Java-send-method-frequently-hangs-when-sending-to-ActiveMQ-queue-tp7649640p7649736.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

























					Reply via email to