Robbie Gemmell created ARTEMIS-2659:
---------------------------------------
Summary: AMQP integration test instabilities, failure to deliver
messages, etc
Key: ARTEMIS-2659
URL: https://issues.apache.org/jira/browse/ARTEMIS-2659
Project: ActiveMQ Artemis
Issue Type: Bug
Components: AMQP
Affects Versions: 2.12.0
Reporter: Robbie Gemmell
Changes in the last few weeks seem to have destablised the AMQP integration
tests on master. I often run these as part of testing out Qpid JMS changes and
releases (by running e.g: mvn clean install -DskipTests && cd
tests/integration-tests/ && mvn -Ptests
-Dtest=org.apache.activemq.artemis.tests.integration.amqp.* test). I ran them
on February 24th without issue while doing the Qpid JMS 0.49.0 release, but now
I see repeated failures in various tests (either with the 0.45.0 client
currently used by artemis, or updated with the 0.49.0 release that worked fine
before, or updated with the 0.50.0 release that tests fine with the Artemis
2.11.0 codebase).
I often see AmqpLargeMessageTest fail. In particular, usually
testSendFixedSizedMessages and/or testSendSmallerMessages. I also see some
unexpected exceptions during test runs. I also noticed an odd behaviour in a
passing test run that may relate to some of the others.
I decided to detail these all here in 1 JIRA as I think they may relate to or
be interactions of more than one change, e.g perhaps these amongst others:
[https://github.com/apache/activemq-artemis/pull/2986]
https://issues.apache.org/jira/browse/ARTEMIS-1975
[https://github.com/apache/activemq-artemis/pull/3012]
https://issues.apache.org/jira/browse/ARTEMIS-2642
[https://github.com/apache/activemq-artemis/pull/3019]
https://issues.apache.org/jira/browse/ARTEMIS-2658
https://issues.apache.org/jira/browse/ARTEMIS-2617
Below is a quick overview of the test failures or issues I see:
=====================
Essentially some of the AmqpLargeMessageTest tests (usually
testSendFixedSizedMessages and/or testSendSmallerMessages) times out with the
client waiting for a message that never arrives.
In this case for AmqpLargeMessageTest # testSendFixedSizedMessages it seems
like it was the second sub-run, "doTestSendLargeMessage(65536 * 2);", which is
I think the first the broker considers 'large'.
Running with protocol trace showed in this case the client sent a message to
the broker, then tried to consume it, abd the client and broker then sit
heartbeating each other with no sign an outgoing Transfer was generated by the
broker. As the test is using a receive-without-timeout call, it sits there
until the test itself times out.
{noformat}
[588596832:1] ->
Attach{name='qpid-jms:sender:ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1:testSendFixedSizedMessages',
handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1',
durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='testSendFixedSizedMessages', 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}
[734665003:1] <-
Attach{name='qpid-jms:sender:ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1:testSendFixedSizedMessages',
handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1',
durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='testSendFixedSizedMessages', 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}
[734665003:1] ->
Attach{name='qpid-jms:sender:ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1:testSendFixedSizedMessages',
handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1',
durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='testSendFixedSizedMessages', durable=NONE,
expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null,
capabilities=[queue]}, unsettled=null, incompleteUnsettled=false,
initialDeliveryCount=null, maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[734665003:1] -> Flow{nextIncomingId=1, incomingWindow=2147483647,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=0,
linkCredit=1000, available=null, drain=false, echo=false, properties=null}
[588596832:1] <-
Attach{name='qpid-jms:sender:ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1:testSendFixedSizedMessages',
handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1',
durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false,
dynamicNodeProperties=null, distributionMode=null, filter=null,
defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list,
amqp:released:list, amqp:modified:list], capabilities=null},
target=Target{address='testSendFixedSizedMessages', durable=NONE,
expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null,
capabilities=[queue]}, unsettled=null, incompleteUnsettled=false,
initialDeliveryCount=null, maxMessageSize=null, offeredCapabilities=null,
desiredCapabilities=null, properties=null}
[588596832:1] <- Flow{nextIncomingId=1, incomingWindow=2147483647,
nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=0,
linkCredit=1000, available=null, drain=false, echo=false, properties=null}
[588596832:1] -> Transfer{handle=0, deliveryId=0, deliveryTag=\x00,
messageFormat=0, settled=false, more=true, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (131050)
"\x00Sr\xc1)\x04\xa3\x0ex-opt-jms-destQ\x00\xa3\x12x-opt-jms-msg-typeQ\x03\x00Ss\xd0\x00\x00\x00z\x00\x00\x00\x0a\xa1/ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1-1@\xa1\x1atestSendFixedSizedMessages@@@\xa3\x18application/octet-stream@@\x83\x00\x00\x01p\xe2\xfez<\x00Su\xb0\x00\x02\x00\x00\xabFe\xdc]\x0d\xb1\xd5\x86\xa2\xd0X8\xbe\x13q\x06}\x9c\x9b\xfc\xb4~&\xb1\xf9\xfc_QM"\x9a\x83\x01^\x0cH\x98\x1dPg8+D\x81V\xcf\xaa{\x8dY\x8f\xea\x01b\x0c\xd5\x9d\xf1A>\xd5\xe2-\xc3\x9c\xf0\xc1\xd2("?\x95\xd3&\xeb\xe7t!c\x16\xea\x1dt\xf9o\xca\x95\xd0-\xb2\xd1\xcd8\xa7\x02\x07\x89\xd0HM\x04\xb3\xa69\xba\x8c\xa5.&_\xc6s\x1a\x16*\x93\x13\xdd\xdb\x91\xd6\xf40\x8e\x18\xf4S\xce\xea\xa7+i\xda\xef\xa1\x9b\x13\x06\xad47\xb1\xe7\xd1\x04\xa6O\xbe=\xaa\xa4\xb9\xc1.S\xc4\xdc\x1a\xd8Vv\xb1T]\xb1*\x0e\x8b_	\xcbD\xf0sc\x89\xa3l\x90\xa2\x1aV\xb5xP\xac\xfb*\x0f\x1d\x97\xfd\xcc\xfb<ul\x0ck\xba\xc9\xbeu\x91\xab\xe3\xb7\xd7T\xfd\xa1\xcf\xfb(_\xf5\xb8\x8b\xf36
\x8aN\xe4\xb0H\xf0%\x80\xcf\x0c\xef\x13s=G\xdd\x9d;\x81\xb1~\xafD\xc2\xe1\xb9Kx$}\x7f"...(truncated)
[588596832:1] -> Transfer{handle=0, deliveryId=0, deliveryTag=\x00,
messageFormat=0, settled=false, more=false, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (206)
"=?\xedxH\xef\xa8\xd1\xcc\xf5\xc3\xa0N\xdc\xab\xbe\xeb\x96\x94\xdcwD\x03R\xd9\xd4\xbd\xcd\xb6\x82\x90\x99/\xc4\x133(\xca-a@\xf9\xbb\xe6\xfeF\xd4\xb9\xcc\xbeG<\x9b\xde\x8ec\xb3\x85q\x1f\xf3rR\xac\xd9\xe9\xf7\x0cxP\xcaY+j\xd9\x02\xd0\x94.\x0b\x8dQ<\x15\x16\x09\x0f>\x94\x13\xb4\x98\xbc$\xf7-\xed\xc5\x98\x1e\xe4\xb46k\x02>Vd\xb7\xe4\x1e\x8bt\xe0K\xffVV\x1bZ(\xf7\xff)\xf1\x0c\xe0Q\x0e
\xcc>\xfb+\xe6|\xfc,?\xb2\xcf\xab\xeb\xf2\xfd\x89\x82\xe3\x997/\x05\xc7H\x17\x175\xe1C\xbcnx\x17\x19\x83W\x1f\xde\x12\xbc\xe7<\xbb\xc8?\xb9\xeb\xa2\x09\x87\x84\xd2\x07\x1b'\x81Sw\xf2:\xaam\xe4jE[\x01\xa4\x19\xae\x11\xdf\xa9\xa3\xe5\xc3"
[588596832:1] ->
Attach{name='qpid-jms:receiver:ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1:testSendFixedSizedMessages',
handle=1, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='testSendFixedSizedMessages', 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}
[734665003:1] <- Transfer{handle=0, deliveryId=0, deliveryTag=\x00,
messageFormat=0, settled=false, more=true, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (131050)
"\x00Sr\xc1)\x04\xa3\x0ex-opt-jms-destQ\x00\xa3\x12x-opt-jms-msg-typeQ\x03\x00Ss\xd0\x00\x00\x00z\x00\x00\x00\x0a\xa1/ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1-1@\xa1\x1atestSendFixedSizedMessages@@@\xa3\x18application/octet-stream@@\x83\x00\x00\x01p\xe2\xfez<\x00Su\xb0\x00\x02\x00\x00\xabFe\xdc]\x0d\xb1\xd5\x86\xa2\xd0X8\xbe\x13q\x06}\x9c\x9b\xfc\xb4~&\xb1\xf9\xfc_QM"\x9a\x83\x01^\x0cH\x98\x1dPg8+D\x81V\xcf\xaa{\x8dY\x8f\xea\x01b\x0c\xd5\x9d\xf1A>\xd5\xe2-\xc3\x9c\xf0\xc1\xd2("?\x95\xd3&\xeb\xe7t!c\x16\xea\x1dt\xf9o\xca\x95\xd0-\xb2\xd1\xcd8\xa7\x02\x07\x89\xd0HM\x04\xb3\xa69\xba\x8c\xa5.&_\xc6s\x1a\x16*\x93\x13\xdd\xdb\x91\xd6\xf40\x8e\x18\xf4S\xce\xea\xa7+i\xda\xef\xa1\x9b\x13\x06\xad47\xb1\xe7\xd1\x04\xa6O\xbe=\xaa\xa4\xb9\xc1.S\xc4\xdc\x1a\xd8Vv\xb1T]\xb1*\x0e\x8b_	\xcbD\xf0sc\x89\xa3l\x90\xa2\x1aV\xb5xP\xac\xfb*\x0f\x1d\x97\xfd\xcc\xfb<ul\x0ck\xba\xc9\xbeu\x91\xab\xe3\xb7\xd7T\xfd\xa1\xcf\xfb(_\xf5\xb8\x8b\xf36
\x8aN\xe4\xb0H\xf0%\x80\xcf\x0c\xef\x13s=G\xdd\x9d;\x81\xb1~\xafD\xc2\xe1\xb9Kx$}\x7f"...(truncated)
[734665003:1] <- Transfer{handle=0, deliveryId=0, deliveryTag=\x00,
messageFormat=0, settled=false, more=false, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (206)
"=?\xedxH\xef\xa8\xd1\xcc\xf5\xc3\xa0N\xdc\xab\xbe\xeb\x96\x94\xdcwD\x03R\xd9\xd4\xbd\xcd\xb6\x82\x90\x99/\xc4\x133(\xca-a@\xf9\xbb\xe6\xfeF\xd4\xb9\xcc\xbeG<\x9b\xde\x8ec\xb3\x85q\x1f\xf3rR\xac\xd9\xe9\xf7\x0cxP\xcaY+j\xd9\x02\xd0\x94.\x0b\x8dQ<\x15\x16\x09\x0f>\x94\x13\xb4\x98\xbc$\xf7-\xed\xc5\x98\x1e\xe4\xb46k\x02>Vd\xb7\xe4\x1e\x8bt\xe0K\xffVV\x1bZ(\xf7\xff)\xf1\x0c\xe0Q\x0e
\xcc>\xfb+\xe6|\xfc,?\xb2\xcf\xab\xeb\xf2\xfd\x89\x82\xe3\x997/\x05\xc7H\x17\x175\xe1C\xbcnx\x17\x19\x83W\x1f\xde\x12\xbc\xe7<\xbb\xc8?\xb9\xeb\xa2\x09\x87\x84\xd2\x07\x1b'\x81Sw\xf2:\xaam\xe4jE[\x01\xa4\x19\xae\x11\xdf\xa9\xa3\xe5\xc3"
[734665003:1] <-
Attach{name='qpid-jms:receiver:ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1:testSendFixedSizedMessages',
handle=1, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='testSendFixedSizedMessages', 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}
[734665003:1] ->
Attach{name='qpid-jms:receiver:ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1:testSendFixedSizedMessages',
handle=1, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='testSendFixedSizedMessages', 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}
[588596832:1] <-
Attach{name='qpid-jms:receiver:ID:f683c24d-7a3c-473a-ae88-d6bef89633ce:1:1:1:testSendFixedSizedMessages',
handle=1, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST,
source=Source{address='testSendFixedSizedMessages', 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}
[588596832:1] -> Flow{nextIncomingId=1, incomingWindow=2047, nextOutgoingId=3,
outgoingWindow=2147483647, handle=1, deliveryCount=0, linkCredit=1000,
available=null, drain=false, echo=false, properties=null}
[734665003:1] <- Flow{nextIncomingId=1, incomingWindow=2047, nextOutgoingId=3,
outgoingWindow=2147483647, handle=1, deliveryCount=0, linkCredit=1000,
available=null, drain=false, echo=false, properties=null}
[734665003:1] -> Disposition{role=RECEIVER, first=0, last=0, settled=true,
state=Accepted{}, batchable=false}
[588596832:1] <- Disposition{role=RECEIVER, first=0, last=0, settled=true,
state=Accepted{}, batchable=false}
[734665003:0] -> Empty Frame
[588596832:0] -> Empty Frame
[588596832:0] <- Empty Frame
[734665003:0] <- Empty Frame
{noformat}
=======================================
I'd also draw attention to AmqpLargeMessageTest # testSend1MBMessage, as I
noticed that although this particular AmqpLargeMessageTest run had actually
passed rather than failing the above tests, the output for 'testSend1MBMessage'
showed the broker doing something unexpected which could perhaps be related to
the above failures.
It sends an empty final Transfer frame for the message it is giving to the
consumer, indicating that there is no more payload, while the previous Transfer
which actually contained the final payload had still indicated more payload was
to come by setting "more=true". It is a legal protocol trace but it should
never really happen in a broker.
It suggests that the delivery send isnt being completed at the point the last
payload has been added, with the transport output then generated, and only
later is the delivery being indicated completed somehow and further transport
output generated that sends the final transfer.
{noformat}
[207826248:1] -> Transfer{handle=1, deliveryId=0, deliveryTag=\x00,
messageFormat=0, settled=false, more=true, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (1024)
"c\xa3\xa13\xf3\xbcH\x10\x7f\x14\xd9\xce+\x17\x1d\x17
\xad,\x89\x94\xbb\xaf\x80\x84\x1dU\xcc\xa9EZ\xff\x80\x8e\x9d\x09&\xc7\xd5\xc5\xb8d-\x0dQ?^\x15\xa7\xd0\x93\x8cP\x93kM\xd6\xb3\xe4_m>\xe3\xd5N\xe1w{\xff>\x93\x96\xad\xdeM\x8d;\xa4\xee\xc3\xd9Z;\x16\xee5wc\xf5\xb7\x90#\xb6j\x16t\xb4\xd1\x97\xe9I\xc5\x89k\xda\x0d~4\xdb,\x86\xa2i\x81f\xf9\xbf\x92\xa7q\xad\x9a\x0aj\x03\x931\xd1\xf1HN\x8e\xce4\xce\xe7\xa1\x0d)\xc6\x14\x15\xf5F>\xd7\xe8\x98&\xb1,|e\x9dh\xc9\xa7Y\xa7V\x10\x18\xfa\x1b`\x9a\xb2@\x08\xd6\xf7\x01p\x9e=]{\x18\x84+|\xfarE\x8b\x8a\x03(s\x02\x8e\xc9\xb7\x0a\xb3D\xc6mv\xd2\xed\x0c\x8eI\xe1\x90h\x1c-\x1e\xfd2*\xf4\xd2\xab\xb671\xa7\xa9W\xf2\xd2\xcaU\xef\xb3\x17t\x1a\xef7\xd1lX\x08\x14\x88~\x0d{v\x91g\xf2\x94\x8f\x06Oi\xc3\xb8\x14\xa5\x9cj\xfb\xb1\xeb\x00\xe5\xb5o~\x1ej\x84\x82em\xe5\xd97\x8a\xd6\x1cF\xc8\xa74\xd8;UDz\xfa\x19\xcc\x89\xaf\x9cj5\xe0w\xaf"X\x0d\xc8\xd4\x84\x9d\xc81\xa56vRa\xe1\xe2\x09\xb4\xd2\xefc\xf1Zk\xba\x04\xdb\x11"\xba\x07#%>\xfd\x0c\x9bv\xb2\x98\xac(\xab\x9f#5\xb5\xa5\xdb\x9dfv}V\x8b\x0f"...(truncated)
[207826248:1] -> Transfer{handle=1, deliveryId=0, deliveryTag=\x00,
messageFormat=0, settled=false, more=true, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (176)
"\xec\x8d\xc3\xdf\xa3\xf6\xfc\x971\xdb9\x8a\xa6!\x15\x06\xbb\xa3\xd9Z\x19\xef\xa6,c\x84h\xa0
\x99|?|u|\xad\x08\x01\xdd\x8ezj
R\xcd0\xdd\xe3L\x9d\xe4\xba\xa2\xdd\x0b\xc0\xea\x9b\xf3\xafp\x03\xa8\x877\xbaZ\xe14{(\xcc\xcd\xb1\x93\xd5\x91\xbbEF\xc8I\xa4\xda\xba\xd2\x05VP\xf1\xa1\xddpi1\xc4#:\x15\xf1\xc0\x85x\xe5\x13\xac\xf7\x15\xafL\x07\x85\x0d\x99\x13G\x0c\xa9\xb6\xdb\xfc\xcen\xb6X0\x11\x09|\xd6!\xe4\xa2\xf7r2?\xd55\x95\xf9c\xf3\x81\x97t\xa2\xabA\x1f\xa5k\xa2\x83,y\xed\x8c\x8c!F;\xf9\x95W\xf6\x0dM+\x13\xf3\x134\xc80I"
...
[207826248:1] -> Transfer{handle=1, deliveryId=0, deliveryTag=\x00,
messageFormat=0, settled=false, more=false, rcvSettleMode=null, state=null,
resume=false, aborted=false, batchable=false} (0) ""
{noformat}
=======================================
I also see TopicDurableTests testSharedNonDurableSubscription fail quite often,
rejecting the link attach with a not-found error indicating an invalid
destination while creating the shared topic consumer. The test runs the squence
10 times in a loop, I havent looked into when it fails, but in this particular
case it seemed to fail on the second loop (i.e iteration 1, 0-based count).
Perhaps a race between tearing down an old shared subscription and a new one
establishing?
{noformat}
Tests run: 2, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 0.378 sec <<<
FAILURE! - in
org.apache.activemq.artemis.tests.integration.amqp.TopicDurableTests
testSharedNonDurableSubscription(org.apache.activemq.artemis.tests.integration.amqp.TopicDurableTests)
Time elapsed: 0.179 sec <<< ERROR!
javax.jms.InvalidDestinationException: AMQ119010: source address does not exist
[condition = amqp:not-found]
at
org.apache.qpid.jms.provider.exceptions.ProviderInvalidDestinationException.toJMSException(ProviderInvalidDestinationException.java:37)
at
org.apache.qpid.jms.provider.exceptions.ProviderInvalidDestinationException.toJMSException(ProviderInvalidDestinationException.java:23)
at
org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:80)
at
org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:112)
at
org.apache.qpid.jms.JmsConnection.createResource(JmsConnection.java:698)
at
org.apache.qpid.jms.JmsMessageConsumer.<init>(JmsMessageConsumer.java:125)
at
org.apache.qpid.jms.JmsSharedMessageConsumer.<init>(JmsSharedMessageConsumer.java:29)
at
org.apache.qpid.jms.JmsSession.createSharedConsumer(JmsSession.java:625)
at
org.apache.qpid.jms.JmsSession.createSharedConsumer(JmsSession.java:613)
at
org.apache.activemq.artemis.tests.integration.amqp.TopicDurableTests.testSharedNonDurableSubscription(TopicDurableTests.java:149)
{noformat}
{noformat}
...
[main] 12:50:51,254 INFO [org.apache.activemq.artemis.core.server] AMQ221001:
Apache ActiveMQ Artemis Message Broker version 2.12.0-SNAPSHOT [localhost,
nodeID=c4269bc3-6784-11ea-bb9b-000c29e9f622]
testSharedNonDurableSubscription; iteration: 0
messages sent
Mesages receivedJmsTextMessage {
org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@4af6da0 }
count: 10
Mesages receivedJmsTextMessage {
org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@1d68c19f }
count: 9
Mesages receivedJmsTextMessage {
org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@13af3c42 }
count: 8
Mesages receivedJmsTextMessage {
org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@a689345 }
count: 7
Mesages receivedJmsTextMessage {
org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@1790aaef }
count: 6
Mesages receivedJmsTextMessage {
org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@e5706d0 }
count: 5
Mesages receivedJmsTextMessage {
org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@52923679 }
count: 5
Mesages receivedJmsTextMessage {
org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@9ad718d }
count: 3
Mesages receivedJmsTextMessage {
org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@4b55997e }
count: 2
Mesages receivedJmsTextMessage {
org.apache.qpid.jms.provider.amqp.message.AmqpJmsTextMessageFacade@630a01d6 }
count: 2
messages received
testSharedNonDurableSubscription; iteration: 1
[main] 12:50:51,416 INFO [org.apache.activemq.artemis.core.server] AMQ221002:
Apache ActiveMQ Artemis Message Broker version 2.12.0-SNAPSHOT
[c4269bc3-6784-11ea-bb9b-000c29e9f622] stopped, uptime 0.174 seconds
...
{noformat}
=======================================
I've also seen several cases of exception like the following during the tests.
This one cane from ab earler run of the testSend1MBMessage test mentioned
earlier:
{noformat}
[main] 14:51:10,416 INFO [org.apache.activemq.artemis.core.server] AMQ221001:
Apache ActiveMQ Artemis Message Broker version 2.12.0-SNAPSHOT [localhost,
nodeID=bf089402-63a7-11ea-875e-000c29e9f622]
[Thread-1 (activemq-netty-threads)] 14:51:10,482 WARN
[org.apache.activemq.artemis.core.server] AMQ222061: Client connection failed,
clearing up resources for session bf0efca4-63a7-11ea-875e-000c29e9f622
[Thread-1 (activemq-netty-threads)] 14:51:10,483 WARN
[org.apache.activemq.artemis.core.server] AMQ222107: Cleared up resources for
session bf0efca4-63a7-11ea-875e-000c29e9f622
[Thread-1
(ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@407cf41)]
14:51:10,602 ERROR [org.apache.activemq.artemis.core.server] AMQ224065: Failed
to remove auto-created queue testSend1MBMessage:
ActiveMQShutdownException[errorType=SHUTDOWN_ERROR message=Journal must be in
state=LOADED, was [STOPPED]]
at
org.apache.activemq.artemis.core.journal.impl.JournalImpl.checkJournalIsLoaded(JournalImpl.java:1086)
[artemis-journal-2.12.0-SNAPSHOT.jar:2.12.0-SNAPSHOT]
at
org.apache.activemq.artemis.core.journal.impl.JournalImpl.appendDeleteRecordTransactional(JournalImpl.java:1159)
[artemis-journal-2.12.0-SNAPSHOT.jar:2.12.0-SNAPSHOT]
at
org.apache.activemq.artemis.core.journal.impl.JournalBase.appendDeleteRecordTransactional(JournalBase.java:98)
[artemis-journal-2.12.0-SNAPSHOT.jar:2.12.0-SNAPSHOT]
at
org.apache.activemq.artemis.core.journal.impl.JournalImpl.appendDeleteRecordTransactional(JournalImpl.java:92)
[artemis-journal-2.12.0-SNAPSHOT.jar:2.12.0-SNAPSHOT]
at
org.apache.activemq.artemis.core.persistence.impl.journal.AbstractJournalStorageManager.deleteQueueBinding(AbstractJournalStorageManager.java:1345)
[artemis-server-2.12.0-SNAPSHOT.jar:2.12.0-SNAPSHOT]
at
org.apache.activemq.artemis.core.server.impl.QueueImpl.deleteQueue(QueueImpl.java:2182)
[artemis-server-2.12.0-SNAPSHOT.jar:2.12.0-SNAPSHOT]
at
org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl.destroyQueue(ActiveMQServerImpl.java:2177)
[artemis-server-2.12.0-SNAPSHOT.jar:2.12.0-SNAPSHOT]
at
org.apache.activemq.artemis.core.server.impl.QueueManagerImpl.performAutoDeleteQueue(QueueManagerImpl.java:72)
[artemis-server-2.12.0-SNAPSHOT.jar:2.12.0-SNAPSHOT]
at
org.apache.activemq.artemis.core.server.impl.QueueManagerImpl.doIt(QueueManagerImpl.java:44)
[artemis-server-2.12.0-SNAPSHOT.jar:2.12.0-SNAPSHOT]
at
org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:42)
[artemis-commons-2.12.0-SNAPSHOT.jar:2.12.0-SNAPSHOT]
at
org.apache.activemq.artemis.utils.actors.OrderedExecutor.doTask(OrderedExecutor.java:31)
[artemis-commons-2.12.0-SNAPSHOT.jar:2.12.0-SNAPSHOT]
at
org.apache.activemq.artemis.utils.actors.ProcessorBase.executePendingTasks(ProcessorBase.java:66)
[artemis-commons-2.12.0-SNAPSHOT.jar:2.12.0-SNAPSHOT]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[rt.jar:1.8.0_181]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[rt.jar:1.8.0_181]
{noformat}
=======================================
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
