WildFly HornetQ-Based Messaging Subsystem Troubleshooting

Internal

• WildFly HornetQ-Based Messaging Subsystem

Relevance

• EAP 6.4.15

Common Causes of Troubles

• BLOCK policy. The queues seize up.
• Always keep an eye on memory - automate gc log processing and failure detection.

Tracing Connection Creation

• Set "org.hornetq.core.server" to TRACE.
• Look for:

15:26:20,189 TRACE [org.hornetq.core.server] (Old I/O server worker (parentId: 1444597516, [id: 0x561acf0c, /127.0.0.1:5445]), runningThread=Thread-1 (HornetQ-remoting-threads-HornetQServerImpl::serverUUID=1dce22c5-4700-11e7-88d5-53aa0b02fcd0-1887100554-1781384206)) Connection created org.hornetq.core.remoting.impl.netty.NettyConnection@14335f60[local= /127.0.0.1:5445, remote=/127.0.0.1:49365]

Tracing Session Creation

• Set "org.hornetq.core.client" to TRACE.
• Look for:

15:26:50,240 TRACE [org.hornetq.core.client] (Old I/O server worker (parentId: 1444597516, [id: 0x561acf0c, /127.0.0.1:5445]), runningThread=Thread-2 (HornetQ-remoting-threads-HornetQServerImpl::serverUUID=1dce22c5-4700-11e7-88d5-53aa0b02fcd0-1887100554-1781384206)) handling packet PACKET(CreateSessionMessage)[type=30, channelID=1, packetObject=CreateSessionMessage]
...
15:26:50,245 TRACE [org.hornetq.core.client] (Old I/O server worker (parentId: 1444597516, [id: 0x561acf0c, /127.0.0.1:5445]), runningThread=Thread-2 (HornetQ-remoting-threads-HornetQServerImpl::serverUUID=1dce22c5-4700-11e7-88d5-53aa0b02fcd0-1887100554-1781384206)) Sending packet nonblocking PACKET(CreateSessionResponseMessage)[type=31, channelID=1, packetObject=CreateSessionResponseMessage] on channeID=1

Tracing a Message Send on the Server

• Set "org.hornetq.core.client" to TRACE.
• Look for:

15:51:00,366 TRACE [org.hornetq.core.client] (Old I/O server worker (parentId: -269084569, [id: 0xeff61867, /127.0.0.1:5445]), runningThread=Thread-1 (HornetQ-remoting-threads-HornetQServerImpl::serverUUID=8448b231-4703-11e7-93ff-f1aa4df06f3c-1443861124-597302249)) handling packet PACKET(SessionSendMessage)[type=71, channelID=12, packetObject=SessionSendMessage,message=ServerMessage[messageID=0,userID=a3061c1b-4703-11e7-9549-33f7fa104ebd,priority=4, bodySize=314,expiration=0, durable=true, address=jms.queue.remote-playground,properties=TypedProperties[__HQ_CID=a3011303-4703-11e7-9549-33f7fa104ebd]]@1086285711]
15:51:00,366 TRACE [org.hornetq.core.server] (Old I/O server worker (parentId: -269084569, [id: 0xeff61867, /127.0.0.1:5445]), runningThread=Thread-1 (HornetQ-remoting-threads-HornetQServerImpl::serverUUID=8448b231-4703-11e7-93ff-f1aa4df06f3c-1443861124-597302249)) ServerSessionPacketHandler::handlePacket,PACKET(SessionSendMessage)[type=71, channelID=12, packetObject=SessionSendMessage,message=ServerMessage[messageID=0,userID=a3061c1b-4703-11e7-9549-33f7fa104ebd,priority=4, bodySize=314,expiration=0, durable=true, address=jms.queue.remote-playground,properties=TypedProperties[__HQ_CID=a3011303-4703-11e7-9549-33f7fa104ebd]]@1086285711]
15:51:00,367 TRACE [org.hornetq.core.server] (Old I/O server worker (parentId: -269084569, [id: 0xeff61867, /127.0.0.1:5445]), runningThread=Thread-1 (HornetQ-remoting-threads-HornetQServerImpl::serverUUID=8448b231-4703-11e7-93ff-f1aa4df06f3c-1443861124-597302249)) send(message=ServerMessage[messageID=16,userID=a3061c1b-4703-11e7-9549-33f7fa104ebd,priority=4, bodySize=314,expiration=0, durable=true, address=jms.queue.remote-playground,properties=TypedProperties[__HQ_CID=a3011303-4703-11e7-9549-33f7fa104ebd]]@1086285711, direct=true) being called
15:51:00,367 TRACE [org.hornetq.core.server] (Old I/O server worker (parentId: -269084569, [id: 0xeff61867, /127.0.0.1:5445]), runningThread=Thread-1 (HornetQ-remoting-threads-HornetQServerImpl::serverUUID=8448b231-4703-11e7-93ff-f1aa4df06f3c-1443861124-597302249)) Routing message ServerMessage[messageID=16,userID=a3061c1b-4703-11e7-9549-33f7fa104ebd,priority=4, bodySize=314,expiration=0, durable=true, address=jms.queue.remote-playground,properties=TypedProperties[__HQ_CID=a3011303-4703-11e7-9549-33f7fa104ebd]]@1086285711 on binding=BindingsImpl [name=jms.queue.remote-playground]
15:51:00,368 TRACE [org.hornetq.core.server] (Old I/O server worker (parentId: -269084569, [id: 0xeff61867, /127.0.0.1:5445]), runningThread=Thread-1 (HornetQ-remoting-threads-HornetQServerImpl::serverUUID=8448b231-4703-11e7-93ff-f1aa4df06f3c-1443861124-597302249)) Message after routed=ServerMessage[messageID=16,userID=a3061c1b-4703-11e7-9549-33f7fa104ebd,priority=4, bodySize=314,expiration=0, durable=true, address=jms.queue.remote-playground,properties=TypedProperties[__HQ_CID=a3011303-4703-11e7-9549-33f7fa104ebd]]@1086285711
15:51:00,368 TRACE [org.hornetq.journal] (Old I/O server worker (parentId: -269084569, [id: 0xeff61867, /127.0.0.1:5445]), runningThread=Thread-1 (HornetQ-remoting-threads-HornetQServerImpl::serverUUID=8448b231-4703-11e7-93ff-f1aa4df06f3c-1443861124-597302249)) appendAddRecord::id=16, userRecordType=31, usedFile = JournalFileImpl: (hornetq-data-1.hq id = 1, recordID = 1)
15:51:00,369 TRACE [org.hornetq.journal] (Old I/O server worker (parentId: -269084569, [id: 0xeff61867, /127.0.0.1:5445]), runningThread=Thread-1 (HornetQ-remoting-threads-HornetQServerImpl::serverUUID=8448b231-4703-11e7-93ff-f1aa4df06f3c-1443861124-597302249)) appendUpdateRecord::id=16, userRecordType=32, usedFile = JournalFileImpl: (hornetq-data-1.hq id = 1, recordID = 1)

...

15:51:00,371 DEBUG [org.hornetq.core.server] (Thread-4 (HornetQ-server-HornetQServerImpl::serverUUID=8448b231-4703-11e7-93ff-f1aa4df06f3c-88477240)) QueueImpl[name=jms.queue.remote-playground, postOffice=PostOfficeImpl [server=HornetQServerImpl::serverUUID=8448b231-4703-11e7-93ff-f1aa4df06f3c]]@6794cf5f doing deliver. messageReferences=0

The log entry regular expressions most reliably associated with handling a messages locally on the node is

grep "send(message=ServerMessage" | grep -v "address=jms\.queue\.hornetq\.management" | grep -v "_HQ_ROUTE_TO"

_HQ_ROUTE_TO is contained by messages being routed over bridges.

Another possibility is (to be further explored):

Routing message ServerMessage.*<queue-name>

printData

The data related to message, bindings and transaction records can be extracted using printData tool. Instructions how to run the tool can be find here:

https://access.redhat.com/solutions/516643