Andrew, Maybe try setting your prefetch to 1 to see if the rest of the messages expire. Prefetch is basically a batch delivery to the consumer, with 1000 messages being default for queues. If messages are prefetched to the consumer then they cannot be expired (unless should have already been considered expired before dispatching to the consumer). Not sure which is your case. To change the prefetch settings, try using vm://localhost?jms.prefetchPolicy.queuePrefetch=1 in your connection string to the connection factory.
http://activemq.apache.org/what-is-the-prefetch-limit-for.html You could also debug a little further by turning off the camel route, sending messages to the queue, and waiting to see if activemq does expire the messages as you're expecting. Hope that helps... On Tue, May 21, 2013 at 2:56 AM, al94781 <and...@harmel-law.com> wrote: > 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. > -- *Christian Posta* http://www.christianposta.com/blog twitter: @christianposta
