First figure out if your problem is that the messages are not getting into
the CommandQueue or if it's that they're not getting from there to the
consumer. To do that, attach a JMX viewer such as JConsole to the broker
process, and then in the MBeans tab navigate down to the MBean for the
queue and click on it. You'll see a bunch of stats, including EnqueueCount
(the total number of messages sent to the queue; if this is 0, your problem
is the publisher and you should step through it with a debugger),
InFlightCount (the number of messages that have been dispatched to the
consumer but not yet acknowledged; if this is non-zero, you need to figure
out what the consumer is doing and why it's not acking the messages),
and DequeueCount
(if it matches the EnqueueCount, then all messages have been consumed, and
you need to figure out why you're not seeing your log line).
Then expand the queue's MBean in the tree and expand the Consumers node and
see if you have zero, one, or more connected consumers, and if they appear
to be the right ones (IP/port matches the connection from your app server).
Tim
On Oct 20, 2017 6:44 AM, "Frans Henskens" <fhensk...@yahoo.com.invalid>
wrote:
> Hi all,
> Apologies. I was posting directly in the nabble forum area, which is
> probably on a lot of spam folders.
> I've configured a couple of topics and a queue. The topics work fine, but
> I'm having some trouble activating the queue.
>
> If anyone can spot what I've done wrong, it would be greatly appreciated!
> Producer (identical to topic producers, bar using queue):
> public synchronized void queue( final InitialContext context, final
> boolean postpone ) throws JMSException,
>
> NamingException
> {
> final ConnectionFactory connectionFactory =
> (ConnectionFactory)Application.getInitialContext().lookup(
> "openejb:Resource/JmsConnectionFactory" );
> final Connection connection = connectionFactory.
> createConnection();
> connection.start();
> final Session session =
> connection.createSession(false, Session.AUTO_ACKNOWLEDGE);
> final Queue commandQueue =
> (Queue)Application.getInitialContext().lookup(
> "openejb:Resource/CommandQueue" );
> final MessageProducer producer = session.createProducer(
> commandQueue );
> final ObjectMessage message = session.createObjectMessage( this );
> if ( postpone )
> {
> message.setLongProperty(
> ScheduledMessage.AMQ_SCHEDULED_DELAY,
> getRetryIntervalMinutes() * 60000 );
> }
> producer.send( message );
> try { producer.close(); } catch ( final Exception e ) {}
> try { session.close(); } catch ( final Exception e ) {}
> try { connection.close(); } catch ( final Exception e ) {}
> }
>
> Consumer (also largely the same to topic consumers):
> @MessageDriven(name = "CommandExecutorMDB", activationConfig = {
> @ActivationConfigProperty(propertyName = "destinationType",
> propertyValue = "javax.jms.Queue"),
> @ActivationConfigProperty(propertyName = "destination",
> propertyValue = "CommandQueue"),
> @ActivationConfigProperty(propertyName = "acknowledgeMode",
> propertyValue = "Auto-acknowledge") })
> @LocalClient
> public class CommandExecutorMDB implements MessageListener
> {
> @Resource
> private ConnectionFactory myConnectionFactory;
>
> @Resource( name="CommandQueue" )
> private Queue myCommandQueue;
>
> /* (non-Javadoc)
> * @see javax.jms.MessageListener#onMessage(javax.jms.Message)
> */
> @Override
> public void onMessage( final Message msg )
> {
> DefaultLog.getDefaultLog().logInfo( "CommandQueue received
> message" ); // Never reached, sadly
> try
> {
> Command command = null;
>
> // We got a message, try to read it
> try
> {
> command = Command.read( msg );
> if ( command == null )
> {
> throw new Exception(
> "Null message received on command queue" );
> }
> }
> catch ( final Exception e )
> {
> DefaultLog.getDefaultLog().logError( "Error reading
> message from JMS queue. Committing the transaction and trying again.", e );
> }
>
> // attempt the command.
> command.attempt( Application.getInitialContext() );
> }
> catch ( final Exception e )
> {
> DefaultLog.getDefaultLog().logError( "Internal error while
> attempting Command. ", e );
> }
> }}
> Here's log entries showing ActiveMQ activating the MDBs20-Oct-2017
> 16:14:15.173 INFO [localhost-startStop-1]
> org.apache.openejb.assembler.classic.Assembler.startEjbs
> Started Ejb(deployment-id=XMLEventRedirectorMDB,
> ejb-name=XMLEventRedirectorMDB,
> container=MessageDrivenContainer)
> 20-Oct-2017 16:14:15.173 INFO [localhost-startStop-1]
> org.apache.openejb.assembler.classic.Assembler.startEjbs Started
> Ejb(deployment-id=CommandExecutorMDB, ejb-name=CommandExecutorMDB,
> container=MessageDrivenContainer)
>
> Here's VMTransport adding connections to the consumers (CommandExecutorMDB
> doesn't seem to show up here explicitly. Perhaps I did something wrong
> there? henskens-50366-1508476452803-8:1 only shows up once here in the
> logs)
> 20-Oct-2017 16:14:17.340 FINE [ActiveMQ VMTransport: vm://broker#1-1]
> org.apache.activemq.broker.TransportConnection.processAddConnection
> Setting up new connection id: ID:henskens-50366-1508476452803-7:1,
> address: vm://broker#0, info: ConnectionInfo {commandId = 1,
> responseRequired = true, connectionId = ID:henskens-50366-1508476452803-7:1,
> clientId = XMLEventRedirectorMDB, clientIp = null, userName = null,
> password = *****, brokerPath = null, brokerMasterConnector = false,
> manageable = true, clientMaster = true, faultTolerant = false,
> failoverReconnect = false}
> 20-Oct-2017 16:14:17.340 FINE [ActiveMQ VMTransport: vm://broker#5-1]
> org.apache.activemq.broker.TransportConnection.processAddConnection
> Setting up new connection id: ID:henskens-50366-1508476452803-9:1,
> address: vm://broker#4, info: ConnectionInfo {commandId = 1,
> responseRequired = true, connectionId = ID:henskens-50366-1508476452803-9:1,
> clientId = ID:henskens-50366-1508476452803-8:1, clientIp = null, userName
> = null, password = *****, brokerPath = null, brokerMasterConnector = false,
> manageable = true, clientMaster = true, faultTolerant = false,
> failoverReconnect = false}
>
> hen the topic is fired, there are initial calls about setting up a
> transaction and registering with the consumer before marshalling the
> object:20-Oct-2017 16:41:53.266 FINE [JmsResourceAdapter-worker- - 6]
> org.apache.activemq.TransactionContext.start Start: [Xid:globalId=
> ffffffb7ffffffee4c385f10047544d49440000000000000000000000000
> 00000000000000000000000000,length=64,branchId=
> 1000ffffff9affffffee4c385f1004400000000000000000000000000000
> 0000000000000000000000,length=64], flags: TMNOFLAGS
> 20-Oct-2017 16:41:53.266 FINE [JmsResourceAdapter-worker- - 6]
> org.apache.activemq.TransactionContext.setXid TransactionContext{
> transactionId=XID:[1197822575,globalId=ffffffb7ffffffee4c385f10047544
> d4944000000000000000000000000000000000000000000000000000,branchId=
> 1000ffffff9affffffee4c385f1004400000000000000000000000000000
> 0000000000000000000000],connection=ActiveMQConnection
> {id=ID:henskens-51054-1508478087236-9:1,clientId=
> XMLEventRedirectorMDB,started=true}} started XA transaction
> XID:[1197822575,globalId=ffffffb7ffffffee4c385f10047544
> d4944000000000000000000000000000000000000000000000000000,branchId=
> 1000ffffff9affffffee4c385f1004400000000000000000000000000000
> 0000000000000000000000]
> 20-Oct-2017 16:41:53.267 FINEST [JmsResourceAdapter-worker- - 6]
> org.apache.activemq.ActiveMQSession.run ActiveMQSession
> {id=ID:henskens-51054-1508478087236-9:1:1,started=true}
> java.lang.Object@a79c9a2 onMessage(ID:henskens-51054-
> 1508478087236-13:1:3:1:1)
> 20-Oct-2017 16:41:53.267 FINEST [JmsResourceAdapter-worker- - 6]
> org.apache.activemq.ra.MessageEndpointProxy.onMessage Invoking
> MessageEndpoint.onMethod()
> 20-Oct-2017 16:41:53.267 FINEST [Thread-31] org.apache.activemq.
> ActiveMQMessageConsumer.dequeue ID:henskens-51054-1508478087236-11:1:1:1
> received message: MessageDispatch {commandId = 8, responseRequired = false,
> consumerId = ID:henskens-51054-1508478087236-11:1:1:1, destination =
> topic://EventTopic, message = ActiveMQObjectMessage {commandId = 31,
> responseRequired = false, messageId =
> ID:henskens-51054-1508478087236-13:1:3:1:1,
> originalDestination = null, originalTransactionId = null, producerId =
> ID:henskens-51054-1508478087236-13:1:3:1, destination =
> topic://EventTopic, transactionId = XID:[1197822575,globalId=
> ffffffb6ffffffee4c385f10047544d49440000000000000000000000000
> 00000000000000000000000000,branchId=1000ffffff9affffffee4c385f1004
> 4000000000000000000000000000000000000000000000000000], expiration = 0,
> timestamp = 1508478113231, arrival = 0, brokerInTime = 1508478113233,
> brokerOutTime = 1508478113263, correlationId = null, replyTo = null,
> persistent = true, type = 9, priority = 4, groupID = null, groupSequence =
> 0, targetConsumerId = null, compressed = false, userID = null, content =
> org.apache.activemq.util.ByteSequence@3dd234c3, marshalledProperties =
> null, dataStructure = null, redeliveryCounter = 0, size = 1495, properties
> = null, readOnlyProperties = true, readOnlyBody = true, droppable = false,
> jmsXGroupFirstForConsumer = false}, redeliveryCounter = 0}
> 20-Oct-2017 16:41:53.267 FINEST [ActiveMQ VMTransport: vm://broker#3-1]
> org.apache.activemq.thread.PooledTaskRunner.runTask Running task
> iteration 0 - vm://broker#3
> 20-Oct-2017 16:41:53.269 FINE [ActiveMQ VMTransport: vm://broker#3-1]
> org.apache.activemq.transaction.XATransaction.<init> XA Transaction
> new/begin : XID:[1197822575,globalId=ffffffb7ffffffee4c385f10047544
> d4944000000000000000000000000000000000000000000000000000,branchId=
> 1000ffffff9affffffee4c385f1004400000000000000000000000000000
> 0000000000000000000000]
> 20-Oct-2017 16:41:53.271 FINEST [ActiveMQ VMTransport: vm://broker#3-1]
> org.apache.activemq.thread.PooledTaskRunner$1.run Run task done:
> vm://broker#3
>
>
> The event triggers a message, sending it to CommandQueue... not much
> happens:20-Oct-2017 16:41:53.276 FINEST [ActiveMQ VMTransport:
> vm://broker#7-1] org.apache.activemq.thread.PooledTaskRunner.runTask
> Running task iteration 0 - vm://broker#7
> 20-Oct-2017 16:41:53.277 FINEST [ActiveMQ VMTransport: vm://broker#7-1]
> org.apache.activemq.thread.PooledTaskRunner.runTask Running task
> iteration 1 - vm://broker#7
> 20-Oct-2017 16:41:53.278 FINE [ActiveMQ VMTransport: vm://broker#7-1]
> org.apache.activemq.broker.TransportConnector.getPublishableConnectString
> Publishing: vm://broker for broker transport URI: vm://broker
> 20-Oct-2017 16:41:53.278 FINE [ActiveMQ VMTransport: vm://broker#7-1]
> org.apache.activemq.broker.TransportConnector.getPublishableConnectString
> Publishing: vm://broker for broker transport URI: vm://broker
> 20-Oct-2017 16:41:53.278 FINEST [ActiveMQ VMTransport: vm://broker#7-1]
> org.apache.activemq.thread.PooledTaskRunner$1.run Run task done:
> vm://broker#7
> 20-Oct-2017 16:41:53.278 FINEST [ActiveMQ VMTransport: vm://broker#6-1]
> org.apache.activemq.thread.PooledTaskRunner.runTask Running task
> iteration 0 - vm://broker#6
> Lines about marshalling the message, then:
> 20-Oct-2017 17:08:38.227 FINEST [Thread-31]
> org.apache.activemq.ActiveMQSession.send
> ID:qv-henskens-51583-1508478425436-11:1:10 sending message:
> ActiveMQObjectMessage {commandId = 0, responseRequired = false, messageId =
> ID:qv-henskens-51583-1508478425436-11:1:10:1:1, originalDestination =
> null, originalTransactionId = null, producerId =
> ID:qv-henskens-51583-1508478425436-11:1:10:1,
> destination = queue://CommandQueue, transactionId =
> XID:[1197822575,globalId=ffffffb31752385f10047544d49440
> 00000000000000000000000000000000000000000000000000,branchId=
> 1000ffffffb31752385f10044000000000000000000000000000000000000000000000000000],
> expiration = 0, timestamp = 1508479718227, arrival = 0, brokerInTime = 0,
> brokerOutTime = 0, 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@1cc17480, marshalledProperties =
> null, dataStructure = null, redeliveryCounter = 0, size = 0, properties =
> null, readOnlyProperties = true, readOnlyBody = true, droppable = false,
> jmsXGroupFirstForConsumer = false}
> 20-Oct-2017 17:08:38.237 FINEST [ActiveMQ VMTransport: vm://broker#7-7]
> org.apache.activemq.thread.PooledTaskRunner.runTask Running task
> iteration 0 - vm://broker#7
> 20-Oct-2017 17:08:38.257 FINEST [ActiveMQ VMTransport: vm://broker#7-7]
> org.apache.activemq.thread.PooledTaskRunner.runTask Running task
> iteration 1 - vm://broker#7
> 20-Oct-2017 17:08:38.257 FINEST [ActiveMQ VMTransport: vm://broker#9-8]
> org.apache.activemq.thread.PooledTaskRunner.runTask Running task
> iteration 0 - vm://broker#9
> 20-Oct-2017 17:08:38.257 FINE [ActiveMQ VMTransport: vm://broker#7-7]
> org.apache.activemq.broker.jmx.ManagementContext.unregisterMBean
> Unregistering MBean org.apache.activemq:type=Broker,brokerName=broker,
> destinationType=Queue,destinationName=CommandQueue,
> endpoint=Producer,clientId=ID_qv-henskens-51583-
> 1508478425436-10_1,producerId=ID_qv-henskens-51583-1508478425436-11_1_10_1
> 20-Oct-2017 17:08:38.257 FINE [ActiveMQ VMTransport: vm://broker#9-8]
> org.apache.activemq.broker.TransportConnection.processAddConnection
> Setting up new connection id: ID:qv-henskens-51583-1508478425436-13:1,
> address: vm://broker#8, info: ConnectionInfo {commandId = 76,
> responseRequired = true, connectionId =
> ID:qv-henskens-51583-1508478425436-13:1,
> clientId = ID:qv-henskens-51583-1508478425436-12:1, clientIp = null,
> userName = null, password = *****, brokerPath = null, brokerMasterConnector
> = false, manageable = true, clientMaster = true, faultTolerant = false,
> failoverReconnect = false}
> 20-Oct-2017 17:08:38.257 FINE [ActiveMQ VMTransport: vm://broker#9-8]
> org.apache.activemq.broker.TransportConnector.getPublishableConnectString
> Publishing: vm://broker for broker transport URI: vm://broker
> 20-Oct-2017 17:08:38.257 FINE [ActiveMQ VMTransport: vm://broker#7-7]
> org.apache.activemq.broker.TransportConnector.getPublishableConnectString
> Publishing: vm://broker for broker transport URI: vm://broker
> 20-Oct-2017 17:08:38.257 FINE [ActiveMQ VMTransport: vm://broker#9-8]
> org.apache.activemq.broker.TransportConnector.getPublishableConnectString
> Publishing: vm://broker for broker transport URI: vm://broker
> 20-Oct-2017 17:08:38.257 FINE [ActiveMQ VMTransport: vm://broker#7-7]
> org.apache.activemq.broker.TransportConnector.getPublishableConnectString
> Publishing: vm://broker for broker transport URI: vm://broker
> 20-Oct-2017 17:08:38.257 FINEST [ActiveMQ VMTransport: vm://broker#7-7]
> org.apache.activemq.thread.PooledTaskRunner$1.run Run task done:
> vm://broker#7
> 20-Oct-2017 17:08:38.257 FINEST [ActiveMQ VMTransport: vm://broker#9-8]
> org.apache.activemq.thread.TaskRunnerFactory$1.newThread Created
> thread[ActiveMQ VMTransport: vm://broker#8-7]: Thread[ActiveMQ VMTransport:
> vm://broker#8-7,5,main]
> 20-Oct-2017 17:08:38.257 FINEST [ActiveMQ VMTransport: vm://broker#9-8]
> org.apache.activemq.thread.PooledTaskRunner$1.run Run task done:
> vm://broker#9
> 20-Oct-2017 17:08:38.267 FINEST [ActiveMQ BrokerService[broker] Task-15]
> org.apache.activemq.thread.PooledTaskRunner.runTask Running task
> iteration 0 - Transport Connection to: vm://broker#8
> 20-Oct-2017 17:08:38.267 FINEST [ActiveMQ VMTransport: vm://broker#7-8]
> org.apache.activemq.thread.PooledTaskRunner.runTask Running task
> iteration 0 - vm://broker#7
> 20-Oct-2017 17:08:38.267 FINEST [ActiveMQ VMTransport: vm://broker#7-8]
> org.apache.activemq.thread.PooledTaskRunner$1.run Run task done:
> vm://broker#7
> 20-Oct-2017 17:08:38.277 FINEST [ActiveMQ BrokerService[broker] Task-15]
> org.apache.activemq.thread.PooledTaskRunner.runTask Running task
> iteration 1 - Transport Connection to: vm://broker#8
> 20-Oct-2017 17:08:38.277 FINEST [ActiveMQ BrokerService[broker] Task-15]
> org.apache.activemq.thread.PooledTaskRunner$1.run Run task done:
> Transport Connection to: vm://broker#8
> 20-Oct-2017 17:08:38.317 FINE [ActiveMQ Broker[broker] Scheduler]
> org.apache.activemq.broker.region.Queue.expireMessages
> queue://CommandQueue expiring messages ..
> 20-Oct-2017 17:08:38.317 FINEST [ActiveMQ Broker[broker] Scheduler]
> org.apache.activemq.broker.region.Queue.shouldPageInMoreForBrowse max
> 400, alreadyPagedIn 0, messagesCount 0, memoryUsage 0%
>
> Any ideas how I might have stuffed this up? It would be much appreciated!
> Cheers,Frans
>
