OK, as I posted earlier, I can see the broker trying to expire messages, but
nothing seems to expire. Is it because things as listed as "inflight"? (See
below) I'm aware that my unit test harness might not be entirely realistic.
Can anyone point out anything dumb I'm doing?
The inbound message has "expiration = 2" and "persistent = true". I notice
however that expiration has become "JMSExpiration=0" further on in
processing which might be problematic. (I have "preserveMessageQos=true" set
on the JMS uri:
jms://queue:fulfillmentRequest?explicitQosEnabled=true&preserveMessageQos=true&timeToLive=1000&transacted=true)
The following is the detail from my logs:
2013-05-21 09:44:07,289 [main ] DEBUG ProducerCache
- >>>> Endpoint[jms://queue:fulfillmentRequest] Exchange[Message: <?xml
version="1.0"?><body>!!!!!TIMED OUT AGAIN!!!!!</body>]
2013-05-21 09:44:07,290 [main ] DEBUG
Configuration$CamelJmsTemplate - Executing callback on JMS Session:
PooledSession { ActiveMQSession
{id=ID:LTPW764AHARMEL-65261-1369125844695-9:1:1,started=false} }
2013-05-21 09:44:07,290 [main ] DEBUG JmsConfiguration
- Sending JMS message to: queue://fulfillmentRequest with message:
ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId =
null, originalDestination = null, originalTransactionId = null, producerId =
null, destination = null, transactionId = null, expiration = 2, timestamp =
0, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = null,
replyTo = null, persistent = true, type = null, priority = 0, groupID =
null, groupSequence = 0, targetConsumerId = null, compressed = false, userID
= null, content = null, marshalledProperties = null, dataStructure = null,
redeliveryCounter = 0, size = 0, properties =
{breadcrumbId=ID-LTPW764AHARMEL-65263-1369125845761-0-5}, readOnlyProperties
= false, readOnlyBody = false, droppable = false, text = <?xml
version="1.0"?><body>!!!!!TIMED OUT AGAIN!!!!!</body>}
2013-05-21 09:44:07,290 [main ] DEBUG TransactionContext
- Begin:TX:ID:LTPW764AHARMEL-65261-1369125844695-9:1:3
2013-05-21 09:44:07,290 [main ] DEBUG ActiveMQSession
- ID:LTPW764AHARMEL-65261-1369125844695-9:1:1 Transaction Commit
:TX:ID:LTPW764AHARMEL-65261-1369125844695-9:1:3
2013-05-21 09:44:07,291 [main ] DEBUG TransactionContext
- Commit: TX:ID:LTPW764AHARMEL-65261-1369125844695-9:1:3 syncCount: 0
2013-05-21 09:44:07,291 [://myBroker#9-2] DEBUG LocalTransaction
- commit: TX:ID:LTPW764AHARMEL-65261-1369125844695-9:1:3 syncCount: 2
2013-05-21 09:44:07,292 [://myBroker#9-2] DEBUG Queue
- myBroker Message ID:LTPW764AHARMEL-65261-1369125844695-9:1:1:1:3 sent to
queue://fulfillmentRequest
2013-05-21 09:44:07,292 [yBroker] Task-2] DEBUG Queue
- fulfillmentRequest toPageIn: 1, Inflight: 2, pagedInMessages.size 2,
enqueueCount: 3, dequeueCount: 0
2013-05-21 09:44:07,292 [main ] DEBUG ActiveMQSession
- ID:LTPW764AHARMEL-65261-1369125844695-9:1:1 Transaction Rollback,
txid:null
2013-05-21 09:44:07,292 [main ] INFO MockEndpoint
- Asserting: Endpoint[mock://initialProcessor] is satisfied
2013-05-21 09:44:07,292 [main ] DEBUG MockEndpoint
- Waiting on the latch for: 0 millis
2013-05-21 09:44:07,316 [oker] Scheduler] DEBUG Queue
- queue://fulfillmentRequest expiring messages ..
2013-05-21 09:44:07,316 [oker] Scheduler] DEBUG Queue
- fulfillmentRequest toPageIn: 0, Inflight: 3, pagedInMessages.size 3,
enqueueCount: 3, dequeueCount: 0
2013-05-21 09:44:07,316 [oker] Scheduler] DEBUG Queue
- queue://fulfillmentRequest expiring messages done.
2013-05-21 09:44:07,317 [oker] Scheduler] DEBUG Queue
- queue://fulfillmentRequest expiring messages ..
2013-05-21 09:44:07,317 [oker] Scheduler] DEBUG Queue
- fulfillmentRequest toPageIn: 0, Inflight: 3, pagedInMessages.size 3,
enqueueCount: 3, dequeueCount: 0
2013-05-21 09:44:07,317 [oker] Scheduler] DEBUG Queue
- queue://fulfillmentRequest expiring messages done.
... <snip>
2013-05-21 09:44:07,693 [illmentRequest]] DEBUG EndpointMessageListener
-
Endpoint[jms://queue:fulfillmentRequest?explicitQosEnabled=true&preserveMessageQos=true&timeToLive=1000&transacted=true]
consumer received JMS message: ActiveMQTextMessage {commandId = 12,
responseRequired = false, messageId =
ID:LTPW764AHARMEL-65261-1369125844695-9:1:1:1:3, originalDestination = null,
originalTransactionId = null, producerId =
ID:LTPW764AHARMEL-65261-1369125844695-9:1:1:1, destination =
queue://fulfillmentRequest, transactionId =
TX:ID:LTPW764AHARMEL-65261-1369125844695-9:1:3, expiration = 0, timestamp =
1369125847290, arrival = 0, brokerInTime = 1369125847291, brokerOutTime =
1369125847693, correlationId = null, replyTo = null, persistent = true, type
= null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId =
null, compressed = false, userID = null, content =
org.apache.activemq.util.ByteSequence@4f2a858f, marshalledProperties =
org.apache.activemq.util.ByteSequence@70a697e3, dataStructure = null,
redeliveryCounter = 0, size = 1149, properties =
{breadcrumbId=ID-LTPW764AHARMEL-65263-1369125845761-0-5}, readOnlyProperties
= true, readOnlyBody = true, droppable = false, text = <?xml
version="1.0"?><body>!!!!!TIMED OUT AGAIN!!!!!</body>}
... <snip>
13-05-21 09:44:07,692 [://myBroker#7-2] DEBUG Queue
- queue://fulfillmentRequest add sub: QueueSubscription:
consumer=ID:LTPW764AHARMEL-65261-1369125844695-7:1:1:3, destinations=0,
dispatched=0, delivered=0, pending=0, dequeues: 2, dispatched: 2, inflight:
0
2013-05-21 09:44:07,692 [yBroker] Task-1] DEBUG Queue
- fulfillmentRequest toPageIn: 0, Inflight: 0, pagedInMessages.size 1,
enqueueCount: 3, dequeueCount: 2
2013-05-21 09:44:07,693 [illmentRequest]] DEBUG TransactionContext
- Begin:TX:ID:LTPW764AHARMEL-65261-1369125844695-7:1:3
2013-05-21 09:44:07,693 [illmentRequest]] DEBUG
ultJmsMessageListenerContainer - Received message of type [class
org.apache.activemq.command.ActiveMQTextMessage] from consumer
[PooledMessageConsumer { ActiveMQMessageConsumer {
value=ID:LTPW764AHARMEL-65261-1369125844695-7:1:1:3, started=true } }] of
session [PooledSession { ActiveMQSession
{id=ID:LTPW764AHARMEL-65261-1369125844695-7:1:1,started=true} }]
2013-05-21 09:44:07,693 [illmentRequest]] DEBUG EndpointMessageListener
-
Endpoint[jms://queue:fulfillmentRequest?explicitQosEnabled=true&preserveMessageQos=true&timeToLive=1000&transacted=true]
consumer received JMS message: ActiveMQTextMessage {commandId = 12,
responseRequired = false, messageId =
ID:LTPW764AHARMEL-65261-1369125844695-9:1:1:1:3, originalDestination = null,
originalTransactionId = null, producerId =
ID:LTPW764AHARMEL-65261-1369125844695-9:1:1:1, destination =
queue://fulfillmentRequest, transactionId =
TX:ID:LTPW764AHARMEL-65261-1369125844695-9:1:3, expiration = 0, timestamp =
1369125847290, arrival = 0, brokerInTime = 1369125847291, brokerOutTime =
1369125847693, correlationId = null, replyTo = null, persistent = true, type
= null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId =
null, compressed = false, userID = null, content =
org.apache.activemq.util.ByteSequence@4f2a858f, marshalledProperties =
org.apache.activemq.util.ByteSequence@70a697e3, dataStructure = null,
redeliveryCounter = 0, size = 1149, properties =
{breadcrumbId=ID-LTPW764AHARMEL-65263-1369125845761-0-5}, readOnlyProperties
= true, readOnlyBody = true, droppable = false, text = <?xml
version="1.0"?><body>!!!!!TIMED OUT AGAIN!!!!!</body>}
2013-05-21 09:44:07,694 [illmentRequest]] DEBUG TransactionErrorHandler
- Transaction begin (0x3ab8dd3f) redelivered(false) for (MessageId:
ID:LTPW764AHARMEL-65261-1369125844695-9:1:1:1:3 on ExchangeId:
ID-LTPW764AHARMEL-65263-1369125845761-0-9))
2013-05-21 09:44:07,694 [illmentRequest]] DEBUG SendProcessor
- >>>> Endpoint[mock://initialProcessor] Exchange[JmsMessage[JmsMessageID:
ID:LTPW764AHARMEL-65261-1369125844695-9:1:1:1:3]]
2013-05-21 09:44:07,694 [illmentRequest]] DEBUG MockEndpoint
- mock://initialProcessor >>>> 2 : Exchange[JmsMessage[JmsMessageID:
ID:LTPW764AHARMEL-65261-1369125844695-9:1:1:1:3]] with body: <?xml
version="1.0"?><body>!!!!!TIMED OUT AGAIN!!!!!</body> and
headers:{JMSDestination=queue://fulfillmentRequest, JMSXGroupID=null,
JMSPriority=4, JMSMessageID=ID:LTPW764AHARMEL-65261-1369125844695-9:1:1:1:3,
JMSExpiration=0, JMSReplyTo=null,
breadcrumbId=ID-LTPW764AHARMEL-65263-1369125845761-0-5,
JMSRedelivered=false, JMSDeliveryMode=2, JMSCorrelationID=null,
JMSType=null, JMSTimestamp=1369125847290}
2013-05-21 09:44:07,694 [illmentRequest]] DEBUG TransactionErrorHandler
- Transaction commit (0x3ab8dd3f) redelivered(false) for (MessageId:
ID:LTPW764AHARMEL-65261-1369125844695-9:1:1:1:3 on ExchangeId:
ID-LTPW764AHARMEL-65263-1369125845761-0-9))
2013-05-21 09:44:07,694 [main ] DEBUG MockEndpoint
- Took 402 millis to complete latch
2013-05-21 09:44:07,694 [illmentRequest]] DEBUG ActiveMQSession
- ID:LTPW764AHARMEL-65261-1369125844695-7:1:1 Transaction Commit
:TX:ID:LTPW764AHARMEL-65261-1369125844695-7:1:3
2013-05-21 09:44:07,694 [illmentRequest]] DEBUG TransactionContext
- Commit: TX:ID:LTPW764AHARMEL-65261-1369125844695-7:1:3 syncCount: 1
2013-05-21 09:44:07,695 [://myBroker#7-2] DEBUG LocalTransaction
- commit: TX:ID:LTPW764AHARMEL-65261-1369125844695-7:1:3 syncCount: 2
2013-05-21 09:44:07,695 [illmentRequest]] DEBUG ActiveMQMessageConsumer
- remove: ID:LTPW764AHARMEL-65261-1369125844695-7:1:1:3,
lastDeliveredSequenceId:11
2013-05-21 09:44:07,695 [illmentRequest]] DEBUG ActiveMQSession
- ID:LTPW764AHARMEL-65261-1369125844695-7:1:1 Transaction Rollback,
txid:null
2013-05-21 09:44:07,695 [illmentRequest]] DEBUG ActiveMQSession
- ID:LTPW764AHARMEL-65261-1369125844695-3:4:1 Transaction Commit :null
I hope this makes sense and that someone can help.
TIA
Cheers, Andrew
--
View this message in context:
http://camel.465427.n5.nabble.com/Not-Expiring-JMS-Messages-with-ActiveMQ-Camel-tp5732841p5732881.html
Sent from the Camel - Users mailing list archive at Nabble.com.
