Re: Qpid Jms Client 0.35.0 problem reading message after some message redeliveries

[Timothy Bish <ta...@gmail.com>]

This has been identified as an issue in the Artemis broker's AMQP 
implementation and fixed for the next release:
https://issues.apache.org/jira/browse/ARTEMIS-2082


On 08/10/2018 06:53 PM, Dan Langford wrote:
> 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
>

-- 
Tim Bish
twitter: @tabish121
blog: http://timbish.blogspot.com/


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@qpid.apache.org
For additional commands, e-mail: users-help@qpid.apache.org