Ongoing queue troubles

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
8 messages Options
Reply | Threaded
Open this post in threaded view
|

Ongoing queue troubles

Frans Henskens
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=ffffffb7ffffffee4c385f10047544d4944000000000000000000000000000000000000000000000000000,length=64,branchId=1000ffffff9affffffee4c385f10044000000000000000000000000000000000000000000000000000,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=ffffffb7ffffffee4c385f10047544d4944000000000000000000000000000000000000000000000000000,branchId=1000ffffff9affffffee4c385f10044000000000000000000000000000000000000000000000000000],connection=ActiveMQConnection {id=ID:henskens-51054-1508478087236-9:1,clientId=XMLEventRedirectorMDB,started=true}} started XA transaction XID:[1197822575,globalId=ffffffb7ffffffee4c385f10047544d4944000000000000000000000000000000000000000000000000000,branchId=1000ffffff9affffffee4c385f10044000000000000000000000000000000000000000000000000000]
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=ffffffb6ffffffee4c385f10047544d4944000000000000000000000000000000000000000000000000000,branchId=1000ffffff9affffffee4c385f10044000000000000000000000000000000000000000000000000000], 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=ffffffb7ffffffee4c385f10047544d4944000000000000000000000000000000000000000000000000000,branchId=1000ffffff9affffffee4c385f10044000000000000000000000000000000000000000000000000000]
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=ffffffb31752385f10047544d4944000000000000000000000000000000000000000000000000000,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
Reply | Threaded
Open this post in threaded view
|

Re: Ongoing queue troubles

Tim Bain
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" <[hidden email]>
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
>
Reply | Threaded
Open this post in threaded view
|

Re: Ongoing queue troubles

Frans Henskens
 
I see the messages enqueueing. I can see a consumer attached to the command queue. Dispatch count and dequeued count stay at 0.
Does that sound right?
Thanks,Frans    On Saturday, 21 October 2017, 12:13:24 am AEDT, Tim Bain <[hidden email]> wrote:  
 
 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" <[hidden email]> 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= ffffffb7ffffffee4c385f10047544 d49440000000000000000000000000 00000000000000000000000000, length=64,branchId= 1000ffffff9affffffee4c385f1004 400000000000000000000000000000 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 d49440000000000000000000000000 00000000000000000000000000, branchId= 1000ffffff9affffffee4c385f1004 400000000000000000000000000000 0000000000000000000000], connection=ActiveMQConnection {id=ID:henskens-51054- 1508478087236-9:1,clientId= XMLEventRedirectorMDB,started= true}} started XA transaction XID:[1197822575,globalId= ffffffb7ffffffee4c385f10047544 d49440000000000000000000000000 00000000000000000000000000, branchId= 1000ffffff9affffffee4c385f1004 400000000000000000000000000000 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= ffffffb6ffffffee4c385f10047544 d49440000000000000000000000000 00000000000000000000000000, branchId= 1000ffffff9affffffee4c385f1004 400000000000000000000000000000 0000000000000000000000], 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 d49440000000000000000000000000 00000000000000000000000000, branchId= 1000ffffff9affffffee4c385f1004 400000000000000000000000000000 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 000000000000000000000000000000 00000000000000000000,branchId= 1000ffffffb31752385f1004400000 000000000000000000000000000000 0000000000000000], 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

Reply | Threaded
Open this post in threaded view
|

Re: Ongoing queue troubles

Tim Bain
Hmm, that's odd. If you click on the queue in JConsole, it should have an
attribute named Selector; is that non-wildcard/non-empty? The part of your
config that you posted doesn't look like one is in use, but let's be sure.

Is there any chance your messages are expiring before they can be consumed,
either because your producer has configured too small of a time to live or
because there is clock drift between the hostwls where your producer,
broker, and consumer are running? If this was happening, you'd either see
ExpiredCount on the queue or DispatchedCount on the consumer increasing,
and you'd see increasing counts in the corresponding expited-message
advisory topic (look either via the MBeans in JConsole or via the topics
page on the web console).

Speak of the web console, what stats does it show in its row on the queues
page of the web console? Does it agree with the info you're getting via JMX
in JConsole? And can you browse the messages via the web console?

I assume that if there were any errors in the logs of any of the three
processes (producer, broker, consumer) you'd have said so by now.

Since we're not sure where the problem lies, I recommend you try using your
producer with a different consumer (not a MDB) and (separately) using your
MDB consumer with a different producer (the web console is the easiest way
to do this).

If all else fails, you may have to grab the ActiveMQ source code and attach
a debugger to step through the code, but hopefully we can avoid that, or at
least narrow down what code you need to step through.

Tim

On Oct 21, 2017 3:41 AM, "Frans Henskens" <[hidden email]>
wrote:

>
> I see the messages enqueueing. I can see a consumer attached to the
> command queue. Dispatch count and dequeued count stay at 0.
> Does that sound right?
> Thanks,Frans    On Saturday, 21 October 2017, 12:13:24 am AEDT, Tim Bain <
> [hidden email]> wrote:
>
>  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" <[hidden email]>
> 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=
> ffffffb7ffffffee4c385f10047544 d49440000000000000000000000000
> 00000000000000000000000000, length=64,branchId=
> 1000ffffff9affffffee4c385f1004 400000000000000000000000000000
> 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
> d49440000000000000000000000000 00000000000000000000000000, branchId=
> 1000ffffff9affffffee4c385f1004 400000000000000000000000000000
> 0000000000000000000000], connection=ActiveMQConnection
> {id=ID:henskens-51054- 1508478087236-9:1,clientId=
> XMLEventRedirectorMDB,started= true}} started XA transaction
> XID:[1197822575,globalId= ffffffb7ffffffee4c385f10047544
> d49440000000000000000000000000 00000000000000000000000000, branchId=
> 1000ffffff9affffffee4c385f1004 400000000000000000000000000000
> 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=
> ffffffb6ffffffee4c385f10047544 d49440000000000000000000000000
> 00000000000000000000000000, branchId= 1000ffffff9affffffee4c385f1004
> 400000000000000000000000000000 0000000000000000000000], 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
> d49440000000000000000000000000 00000000000000000000000000, branchId=
> 1000ffffff9affffffee4c385f1004 400000000000000000000000000000
> 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 000000000000000000000000000000
> 00000000000000000000,branchId= 1000ffffffb31752385f1004400000
> 000000000000000000000000000000 0000000000000000], 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
>
>
Reply | Threaded
Open this post in threaded view
|

Re: Ongoing queue troubles

Frans Henskens
The queue in jconsole's selector is empty (it's a mdb with no selector).
The queue is in-vm, just for this app. Presumably there's no clock drift possible between the machine and itself? The attempts to send the message most often happen directly after restarting the app.

I reset the stats and sent 1 message.On ActiveMQ.Advisory.Producer.Queue. CommandQueue: - EnqueueCount is 2 - ExpiredCount is 0 - DispatchCount is 0 - DequeueCount is 0 - InFlightCount is 0

On ActiveMQ.advisory.Consumer.Queue.CommandQueue: - EnqueueCount is 0 - ExpiredCount is 0
 - DispatchQueue is 0 - DequeueCount is 0 - InFlightCount is 0
On Queue/CommandQueue/Consumer/henskens-#id - All counts are 0 - DestinationName is CommandQueue
I'm using the ActiveMQ bundled with TomEE 7.0.4, and haven't managed to get the web console up and running yet. Might have a bit more of a crack at that today, if it's valuable.
I previously had the consumer set up as a thread which would receive with a timeout. The resultant message was always null. I switched over to using an MDB in the hopes that I was missing something to do with session setup that was killing it.
I have a decompiler installed in my IDE, and stepped through the code on production to the point that it handed off to PooledTaskRunner (I think?), after which ActiveMQ fired up a new thread and the debugger couldn't follow.
Leaving the app running over the weekend it did receive two Commands on the queue from a background thread that runs expiring old items. It uses the same mechanism as the producer I'm testing to generate messages. Guess the producer is OK? Perhaps there's a transaction being started somewhere which isn't being committed or rolled back.
ISSSUE LOCATED:
I hadn't associated a transaction with the thread which was producing messages for the queue. Now I'll go through all my worker threads and add try/catch transactions around them.
Thank you very much for all your help, Tim. It's very much appreciated!

Cheers,Frans

    On Sunday, 22 October 2017, 12:17:17 am AEDT, Tim Bain <[hidden email]> wrote:  
 
 Hmm, that's odd. If you click on the queue in JConsole, it should have an attribute named Selector; is that non-wildcard/non-empty? The part of your config that you posted doesn't look like one is in use, but let's be sure.
Is there any chance your messages are expiring before they can be consumed, either because your producer has configured too small of a time to live or because there is clock drift between the hostwls where your producer, broker, and consumer are running? If this was happening, you'd either see ExpiredCount on the queue or DispatchedCount on the consumer increasing, and you'd see increasing counts in the corresponding expited-message advisory topic (look either via the MBeans in JConsole or via the topics page on the web console). 
Speak of the web console, what stats does it show in its row on the queues page of the web console? Does it agree with the info you're getting via JMX in JConsole? And can you browse the messages via the web console? 
I assume that if there were any errors in the logs of any of the three processes (producer, broker, consumer) you'd have said so by now. 
Since we're not sure where the problem lies, I recommend you try using your producer with a different consumer (not a MDB) and (separately) using your MDB consumer with a different producer (the web console is the easiest way to do this).
If all else fails, you may have to grab the ActiveMQ source code and attach a debugger to step through the code, but hopefully we can avoid that, or at least narrow down what code you need to step through. 
Tim 
On Oct 21, 2017 3:41 AM, "Frans Henskens" <[hidden email]> wrote:


I see the messages enqueueing. I can see a consumer attached to the command queue. Dispatch count and dequeued count stay at 0.
Does that sound right?
Thanks,Frans    On Saturday, 21 October 2017, 12:13:24 am AEDT, Tim Bain <[hidden email]> wrote:

 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" <[hidden email]> 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= ffffffb7ffffffee4c385f10047544 d49440000000000000000000000000 00000000000000000000000000, length=64,branchId= 1000ffffff9affffffee4c385f1004 400000000000000000000000000000 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 d49440000000000000000000000000 00000000000000000000000000, branchId= 1000ffffff9affffffee4c385f1004 400000000000000000000000000000 0000000000000000000000], connection=ActiveMQConnection {id=ID:henskens-51054- 1508478087236-9:1,clientId= XMLEventRedirectorMDB,started= true}} started XA transaction XID:[1197822575,globalId= ffffffb7ffffffee4c385f10047544 d49440000000000000000000000000 00000000000000000000000000, branchId= 1000ffffff9affffffee4c385f1004 400000000000000000000000000000 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= ffffffb6ffffffee4c385f10047544 d49440000000000000000000000000 00000000000000000000000000, branchId= 1000ffffff9affffffee4c385f1004 400000000000000000000000000000 0000000000000000000000], 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 d49440000000000000000000000000 00000000000000000000000000, branchId= 1000ffffff9affffffee4c385f1004 400000000000000000000000000000 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 000000000000000000000000000000 00000000000000000000,branchId= 1000ffffffb31752385f1004400000 000000000000000000000000000000 0000000000000000], 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


 
Reply | Threaded
Open this post in threaded view
|

Re: Ongoing queue troubles

Tim Bain
Frans,

You provided stats for the ActiveMQ.Advisory.Producer and
ActiveMQ.Advisory.Consumer advisory topics, but the stats we'd really have
liked to see were the ones for the queue itself. For future
troubleshooting, I recommend you look at the stats on the actual queue (or
topic), since they give you more info than you can get solely from the
advisory messages.

But since you located the underlying problem, all of that is moot till the
next time you need to look into something.

Tim

On Sun, Oct 22, 2017 at 6:48 PM, Frans Henskens <[hidden email]
> wrote:

> The queue in jconsole's selector is empty (it's a mdb with no selector).
> The queue is in-vm, just for this app. Presumably there's no clock drift
> possible between the machine and itself? The attempts to send the message
> most often happen directly after restarting the app.
>
> I reset the stats and sent 1 message.On ActiveMQ.Advisory.Producer.Queue.
> CommandQueue: - EnqueueCount is 2 - ExpiredCount is 0 - DispatchCount is
> 0 - DequeueCount is 0 - InFlightCount is 0
>
> On ActiveMQ.advisory.Consumer.Queue.CommandQueue: - EnqueueCount is 0 -
> ExpiredCount is 0
>  - DispatchQueue is 0 - DequeueCount is 0 - InFlightCount is 0
> On Queue/CommandQueue/Consumer/henskens-#id - All counts are 0 -
> DestinationName is CommandQueue
> I'm using the ActiveMQ bundled with TomEE 7.0.4, and haven't managed to
> get the web console up and running yet. Might have a bit more of a crack at
> that today, if it's valuable.
> I previously had the consumer set up as a thread which would receive with
> a timeout. The resultant message was always null. I switched over to using
> an MDB in the hopes that I was missing something to do with session setup
> that was killing it.
> I have a decompiler installed in my IDE, and stepped through the code on
> production to the point that it handed off to PooledTaskRunner (I think?),
> after which ActiveMQ fired up a new thread and the debugger couldn't follow.
> Leaving the app running over the weekend it did receive two Commands on
> the queue from a background thread that runs expiring old items. It uses
> the same mechanism as the producer I'm testing to generate messages. Guess
> the producer is OK? Perhaps there's a transaction being started somewhere
> which isn't being committed or rolled back.
> ISSSUE LOCATED:
> I hadn't associated a transaction with the thread which was producing
> messages for the queue. Now I'll go through all my worker threads and add
> try/catch transactions around them.
> Thank you very much for all your help, Tim. It's very much appreciated!
>
> Cheers,Frans
>
>     On Sunday, 22 October 2017, 12:17:17 am AEDT, Tim Bain <
> [hidden email]> wrote:
>
>  Hmm, that's odd. If you click on the queue in JConsole, it should have an
> attribute named Selector; is that non-wildcard/non-empty? The part of your
> config that you posted doesn't look like one is in use, but let's be sure.
> Is there any chance your messages are expiring before they can be
> consumed, either because your producer has configured too small of a time
> to live or because there is clock drift between the hostwls where your
> producer, broker, and consumer are running? If this was happening, you'd
> either see ExpiredCount on the queue or DispatchedCount on the consumer
> increasing, and you'd see increasing counts in the corresponding
> expited-message advisory topic (look either via the MBeans in JConsole or
> via the topics page on the web console).
> Speak of the web console, what stats does it show in its row on the queues
> page of the web console? Does it agree with the info you're getting via JMX
> in JConsole? And can you browse the messages via the web console?
> I assume that if there were any errors in the logs of any of the three
> processes (producer, broker, consumer) you'd have said so by now.
> Since we're not sure where the problem lies, I recommend you try using
> your producer with a different consumer (not a MDB) and (separately) using
> your MDB consumer with a different producer (the web console is the easiest
> way to do this).
> If all else fails, you may have to grab the ActiveMQ source code and
> attach a debugger to step through the code, but hopefully we can avoid
> that, or at least narrow down what code you need to step through.
> Tim
> On Oct 21, 2017 3:41 AM, "Frans Henskens" <[hidden email]>
> wrote:
>
>
> I see the messages enqueueing. I can see a consumer attached to the
> command queue. Dispatch count and dequeued count stay at 0.
> Does that sound right?
> Thanks,Frans    On Saturday, 21 October 2017, 12:13:24 am AEDT, Tim Bain <
> [hidden email]> wrote:
>
>  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" <[hidden email]>
> 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=
> ffffffb7ffffffee4c385f10047544 d49440000000000000000000000000
> 00000000000000000000000000, length=64,branchId=
> 1000ffffff9affffffee4c385f1004 400000000000000000000000000000
> 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
> d49440000000000000000000000000 00000000000000000000000000, branchId=
> 1000ffffff9affffffee4c385f1004 400000000000000000000000000000
> 0000000000000000000000], connection=ActiveMQConnection
> {id=ID:henskens-51054- 1508478087236-9:1,clientId=
> XMLEventRedirectorMDB,started= true}} started XA transaction
> XID:[1197822575,globalId= ffffffb7ffffffee4c385f10047544
> d49440000000000000000000000000 00000000000000000000000000, branchId=
> 1000ffffff9affffffee4c385f1004 400000000000000000000000000000
> 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=
> ffffffb6ffffffee4c385f10047544 d49440000000000000000000000000
> 00000000000000000000000000, branchId= 1000ffffff9affffffee4c385f1004
> 400000000000000000000000000000 0000000000000000000000], 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
> d49440000000000000000000000000 00000000000000000000000000, branchId=
> 1000ffffff9affffffee4c385f1004 400000000000000000000000000000
> 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 000000000000000000000000000000
> 00000000000000000000,branchId= 1000ffffffb31752385f1004400000
> 000000000000000000000000000000 0000000000000000], 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
>
>
>
>
Reply | Threaded
Open this post in threaded view
|

Re: Ongoing queue troubles

Frans Henskens
 
Hi Tim,
I did write about the advisories. Using JConsole, I could see the advisory topics for the queues/topics, and folders for the queues/topics that I could drill down into to get to the consumers attached to each, e.g. Queue/CommandQueue/Consumer/henskens-#id

I could also see the producers if I created a debug point in the code after they were created and before they were finalised and closed. I couldn't find any beans pertaining to the queue other than those. I'll have a further look tomorrow!
Thank you very much for your help!
Cheers,Frans  
Reply | Threaded
Open this post in threaded view
|

Re: Ongoing queue troubles

Tim Bain
Those "folders" are actually full MBeans, and if you click on them, you'll
see the panel on the right display a bunch of attributes about them.

I think JConsole's choice of iconography in this instance is a confusing
one.

Tim

On Oct 26, 2017 1:09 AM, "Frans Henskens" <[hidden email]>
wrote:

>
> Hi Tim,
> I did write about the advisories. Using JConsole, I could see the advisory
> topics for the queues/topics, and folders for the queues/topics that I
> could drill down into to get to the consumers attached to each,
> e.g. Queue/CommandQueue/Consumer/henskens-#id
>
> I could also see the producers if I created a debug point in the code
> after they were created and before they were finalised and closed. I
> couldn't find any beans pertaining to the queue other than those. I'll have
> a further look tomorrow!
> Thank you very much for your help!
> Cheers,Frans