TLDR messages redelivered from artemis broker get into state where qpid jms
client api will not show me the properties or body. trying to determine if
its the broker sending down bad data or if its the client not supporting
some frame structure
I have a message on my broker right now (Artemis 2.6.2) its on a Queue
waiting to be delivered. I am connecting with Qpid Jms Client 0.35.0 and
the client is not revealing to me the properties or payload of the message.
below is my code. its using the simplified api we got in 2.0 (JmsContext)
to create a Consumer and the set a MessageListener. Then i do this on each
javax.jms.Message
for(Object name: Collections.list(message.getPropertyNames())) {
System.out.printf("property name=%s value=%s%n", name,
message.getObjectProperty((String) name));
}
System.out.printf("message payload=%s%n", message.getBody(String.class));
System.out.println("done");
and here are the frames i am seeing due to env variable PN_TRACE_FRM=true
(with some data scrubbed like hostnames)
[199721506:0] -> Open{
containerId='ID:12eea5d0-97f3-47d4-8d5a-e59c37452c10:1', hostname='
stage.myhost.org', maxFrameSize=1048576, channelMax=32767,
idleTimeOut=30000, outgoingLocales=null, incomingLocales=null,
offeredCapabilities=null,
desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS, version=0.35.0,
platform=JVM: 1.8.0_181, 25.181-b13, Oracle Corporation, OS: Mac OS X,
10.13.6, x86_64}}
[199721506:0] <- Open{ containerId='node1', hostname='null',
maxFrameSize=131072, channelMax=65535, idleTimeOut=30000,
outgoingLocales=null, incomingLocales=null,
offeredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
SHARED-SUBS, ANONYMOUS-RELAY], desiredCapabilities=null,
properties={product=apache-activemq-artemis,
failover-server-list=[{hostname=node1, scheme=amqp, port=61616,
network-host=node2}], version=2.6.2}}
[199721506:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[199721506:0] <- Begin{remoteChannel=0, nextOutgoingId=1,
incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[199721506:1] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[199721506:1] <- Begin{remoteChannel=1, nextOutgoingId=1,
incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[199721506:1] ->
Attach{name='qpid-jms:receiver:ID:36414498-1cef-45b7-9829-65adf6b870b4:1:1:1:QUE-134b55356db040f68dd2f51413c1895c',
handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='QUE-134b55356db040f68dd2f51413c1895c', durable=NONE,
expiryPolicy=LINK_DETACH, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null,
messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=[queue]},
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}
[199721506:1] <-
Attach{name='qpid-jms:receiver:ID:36414498-1cef-45b7-9829-65adf6b870b4:1:1:1:QUE-134b55356db040f68dd2f51413c1895c',
handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='QUE-134b55356db040f68dd2f51413c1895c', durable=NONE,
expiryPolicy=LINK_DETACH, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null,
messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=[queue]},
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}
[199721506:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=0,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
[199721506:1] <- Transfer{handle=0, deliveryId=0, deliveryTag=\x00,
messageFormat=0, settled=null, more=false, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (416) "\x00Sp\xc0\x0b\x05A@p
\x00\x00\x03\xe8@R\x01@R
\x01\x00Sr\xc1\xd5\x0c\xa3\x0ex-opt-jms-destQ\x00\xa3\x12x-opt-jms-msg-typeQ\x05\xa3\x0f_AMQ_ORIG_QUEUE\xa1$QUE-85fee1e8cefd47da94da26cac73786f9\xa3\x11_AMQ_ORIG_ADDRESS\xa1$QUE-85fee1e8cefd47da94da26cac73786f9\xa3\x14_AMQ_ORIG_MESSAGE_ID\x81\x00\x00\x00\x02\x80X\x87\x14\xa3\x12_AMQ_ACTUAL_EXPIRY\x81\x00\x00\x01e%\xbf\xd3\x05\x00Ss\xd0\x00\x00\x00k\x00\x00\x00\x0a\xa1/ID:568b4c5e-3ee8-4e81-9c30-e68b0d7c4dc4:1:1:1-1@
\xa1$QUE-85fee1e8cefd47da94da26cac73786f9@@@@@@\x83\x00\x00\x01e%\xbfs\xe1\x00St\xc1)\x02\xa1\x15generatedNotification\xa1\x0fdanny's
machine\x00Sw\xa1\x0dhello, world!"
[199721506:1] -> Flow{nextIncomingId=2, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=1,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
property name=JMSXDeliveryCount value=2
message payload=null
done
those last 3 lines being from my code System.out.print
as you can see in the frames there is a header called
"generatedNotification" and the body says "hello, world!" however i cannot
see them on the header.
HERE is the real kicker. notice the JMSXDeliveryCount is 2. always the
first time or two that a message is delivered i CAN get the data.
so i am trying to compare the frames to see what is different about the 3rd
or 4th time a message is redelivered that causes it to stop showing the
data via the client api. but i am struggling to notice anything. i am
unfamiliar with picking apart these frames. here is another attempt. this
body contains "hello, again". i will intentionally cause a redelivery to
occur
[2004921391:0] -> Open{
containerId='ID:cbcbdd0a-d2a9-4cef-8b5a-6f7818a07d85:1', hostname='
stage.myhost.org', maxFrameSize=1048576, channelMax=32767,
idleTimeOut=30000, outgoingLocales=null, incomingLocales=null,
offeredCapabilities=null,
desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS, version=0.35.0,
platform=JVM: 1.8.0_181, 25.181-b13, Oracle Corporation, OS: Mac OS X,
10.13.6, x86_64}}
[2004921391:0] <- Open{ containerId='node1', hostname='null',
maxFrameSize=131072, channelMax=65535, idleTimeOut=30000,
outgoingLocales=null, incomingLocales=null,
offeredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY,
SHARED-SUBS, ANONYMOUS-RELAY], desiredCapabilities=null,
properties={product=apache-activemq-artemis,
failover-server-list=[{hostname=node2, scheme=amqp, port=61616,
network-host=node2}], version=2.6.2}}
[2004921391:0] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[2004921391:0] <- Begin{remoteChannel=0, nextOutgoingId=1,
incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[2004921391:1] -> Begin{remoteChannel=null, nextOutgoingId=1,
incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[2004921391:1] <- Begin{remoteChannel=1, nextOutgoingId=1,
incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=65535,
offeredCapabilities=null, desiredCapabilities=null, properties=null}
[2004921391:1] ->
Attach{name='qpid-jms:receiver:ID:db01d08f-fd6a-4057-938c-a45b291769c9:1:1:1:QUE-134b55356db040f68dd2f51413c1895c',
handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='QUE-134b55356db040f68dd2f51413c1895c', durable=NONE,
expiryPolicy=LINK_DETACH, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null,
messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=[queue]},
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}
[2004921391:1] <-
Attach{name='qpid-jms:receiver:ID:db01d08f-fd6a-4057-938c-a45b291769c9:1:1:1:QUE-134b55356db040f68dd2f51413c1895c',
handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='QUE-134b55356db040f68dd2f51413c1895c', durable=NONE,
expiryPolicy=LINK_DETACH, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null,
messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=[queue]},
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}
[2004921391:1] -> Flow{nextIncomingId=1, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=0,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
[2004921391:1] <- Transfer{handle=0, deliveryId=0, deliveryTag=\x00,
messageFormat=0, settled=null, more=false, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (412) "\x00Sp\xc0\x0b\x05A@p
\x00\x00\x03\xe8@R
\x01\x00Sr\xc1\xd5\x0c\xa3\x0ex-opt-jms-destQ\x00\xa3\x12x-opt-jms-msg-typeQ\x05\xa3\x0f_AMQ_ORIG_QUEUE\xa1$QUE-85fee1e8cefd47da94da26cac73786f9\xa3\x11_AMQ_ORIG_ADDRESS\xa1$QUE-85fee1e8cefd47da94da26cac73786f9\xa3\x14_AMQ_ORIG_MESSAGE_ID\x81\x00\x00\x00\x02\x80Z`\x80\xa3\x12_AMQ_ACTUAL_EXPIRY\x81\x00\x00\x01e%\xe2\x9dN\x00Ss\xd0\x00\x00\x00k\x00\x00\x00\x0a\xa1/ID:da162463-7d2a-4e84-b4fd-7daebdd72c02:1:1:1-1@
\xa1$QUE-85fee1e8cefd47da94da26cac73786f9@@@@@@\x83\x00\x00\x01e%\xe2}\xe1\x00St\xc1)\x02\xa1\x15generatedNotification\xa1\x0fdanny's
machine\x00Sw\xa1\x0chello, again"
[2004921391:1] -> Flow{nextIncomingId=2, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=1,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
property name=JMSXDeliveryCount value=2
property name=generatedNotification value=danny's machine
message payload=hello, again
done
[2004921391:1] -> Disposition{role=RECEIVER, first=0, last=0, settled=true,
state=Released{}, batchable=false}
[2004921391:1] <- Transfer{handle=0, deliveryId=1, deliveryTag=\x00,
messageFormat=0, settled=null, more=false, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (415) "\x00Sp\xc0\x0b\x05A@p
\x00\x00\x03\xe8@R\x01@R
\x01\x00Sr\xc1\xd5\x0c\xa3\x0ex-opt-jms-destQ\x00\xa3\x12x-opt-jms-msg-typeQ\x05\xa3\x0f_AMQ_ORIG_QUEUE\xa1$QUE-85fee1e8cefd47da94da26cac73786f9\xa3\x11_AMQ_ORIG_ADDRESS\xa1$QUE-85fee1e8cefd47da94da26cac73786f9\xa3\x14_AMQ_ORIG_MESSAGE_ID\x81\x00\x00\x00\x02\x80Z`\x80\xa3\x12_AMQ_ACTUAL_EXPIRY\x81\x00\x00\x01e%\xe2\x9dN\x00Ss\xd0\x00\x00\x00k\x00\x00\x00\x0a\xa1/ID:da162463-7d2a-4e84-b4fd-7daebdd72c02:1:1:1-1@
\xa1$QUE-85fee1e8cefd47da94da26cac73786f9@@@@@@\x83\x00\x00\x01e%\xe2}\xe1\x00St\xc1)\x02\xa1\x15generatedNotification\xa1\x0fdanny's
machine\x00Sw\xa1\x0chello, again"
[2004921391:1] -> Flow{nextIncomingId=3, incomingWindow=2047,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=2,
linkCredit=1, available=null, drain=false, echo=false, properties=null}
property name=JMSXDeliveryCount value=2
message payload=null
done
interestingly enough in this one the JMSXDeliveryCount did not increment.
this was the same message attempting to be redelivered after a failure. the
size(?) increased from 412 to 415. meaning the broker did send down
different data. i am trying to determine if its a problem with what the
broker is sending or a problem with how the client is reading in the
message that would cause it to (after a few redeliveries) cease to permit
me to access the data.
FWIW the way in which we get into this situation is that we have in Artemis
a Last Value Queue. messages expire from that queue into the queue we are
listening to above. if messages have an expiration of a few seconds then
the pattern acts to deduplicate messages. and it has been working great
until we got into a spot where we had to rely a little more on the brokers
ability to redeliver a failed message. thats when we started to notice some
"blank" messages, or messages that appeard blank via the api. the frames
show that the data was sent, i wonder if it was sent in a goofy way that
the client cannot understand and if so if its a problem with the client or
the broker
we do have OTHER situations in which the redelivery from artemis broker is
working great. i plan to work with them on why this certain scenario gets
goofed up. i was wondering if you could notice anything on the FRAMES that
is clearly out of line. and help me rule out a client side problem.
thanks so much for your time and consideration
Danny Langford
