in WildFly and JBoss EAP Loggers are used to log messages by defining a category generally consisting of a package name or a class name. In short, they can let you customize the logging events for a package or Class name. We will see 5 Loggers which I’ve found pretty useful in my work.
org.jboss.remoting.remote
<logger category="org.jboss.remoting.remote">
<level name="TRACE"/>
</logger>
Cannot say how helpful is this logger! Handling remote EJB connections is not a walk in the park to be honest and the Exception “No EJB receiver available for handling” opens to different scenarios. By including this logger you can solve at least two common problems:
1) Probe that the application server received the incoming connection (Yes tcpdump is the best, but you have to be root in order to use it!)
Here is a sample log from a successful handled connection:
2016-04-15 22:47:38,710 TRACE [org.jboss.remoting.remote] (default I/O-5) Accepted connection from /127.0.0.1:36556 to localhost.localdomain/127.0.0.1:8080 2016-04-15 22:47:38,710 TRACE [org.jboss.remoting.remote] (default I/O-5) Setting read listener to org.jboss.remoting3.remote.ServerConnectionOpenListener$Initial@23d6ef6a 2016-04-15 22:47:38,710 TRACE [org.jboss.remoting.remote.connection] (default I/O-5) Can't directly send message java.nio.DirectByteBuffer[pos=0 lim=24 cap=8192], enqueued 2016-04-15 22:47:38,710 TRACE [org.jboss.remoting.remote.connection] (default I/O-5) Sent message java.nio.DirectByteBuffer[pos=24 lim=24 cap=8192] (via queue) 2016-04-15 22:47:38,710 TRACE [org.jboss.remoting.remote.connection] (default I/O-5) Flushed channel 2016-04-15 22:47:38,807 TRACE [org.jboss.remoting.remote.server] (default I/O-5) Server received capabilities request 2016-04-15 22:47:38,808 TRACE [org.jboss.remoting.remote.server] (default I/O-5) Server received capability: version 1 2016-04-15 22:47:38,808 TRACE [org.jboss.remoting.remote.server] (default I/O-5) Server received capability: remote endpoint name "config-based-ejb-client-endpoint" 2016-04-15 22:47:38,808 TRACE [org.jboss.remoting.remote.server] (default I/O-5) Server received capability: message close protocol supported 2016-04-15 22:47:38,808 TRACE [org.jboss.remoting.remote.server] (default I/O-5) Server received capability: remote version is "4.0.18.Final" 2016-04-15 22:47:38,808 TRACE [org.jboss.remoting.remote.server] (default I/O-5) Server received capability: remote channels in is "40" 2016-04-15 22:47:38,808 TRACE [org.jboss.remoting.remote.server] (default I/O-5) Server received capability: remote channels out is "40" com.sun.security.sasl.ServerFactoryImpl@442be6bc 2016-04-15 22:47:38,809 TRACE [org.jboss.remoting.remote.server] (default I/O-5) Excluding mechanism CRAM-MD5 because it is not in the allowed list 2016-04-15 22:47:38,809 TRACE [org.jboss.remoting.remote.server] (default I/O-5) Trying SASL server factory com.sun.security.sasl.gsskerb.FactoryImpl@3ccb19f1 2016-04-15 22:47:38,809 TRACE [org.jboss.remoting.remote.server] (default I/O-5) Excluding mechanism GSSAPI because it is not in the allowed list 2016-04-15 22:47:38,809 TRACE [org.jboss.remoting.remote.connection] (default I/O-5) Can't directly send message java.nio.DirectByteBuffer[pos=0 lim=73 cap=8192], enqueued 2016-04-15 22:47:38,809 TRACE [org.jboss.remoting.remote.connection] (default I/O-5) Sent message java.nio.DirectByteBuffer[pos=73 lim=73 cap=8192] (via queue) 2016-04-15 22:47:38,809 TRACE [org.jboss.remoting.remote.connection] (default I/O-5) Flushed channel
This logger is especially useful for remoting ejb connections, as it can show connection heartbeats.
2) More details on possible failures in communication:
Here is a sample log from a failed authentication due to a mistyped user in the jboss-ejb-client.properties:
2016-04-16 17:55:54,121 TRACE [org.jboss.remoting.remote.server] (default I/O-1) Received java.nio.DirectByteBuffer[pos=280 lim=8192 cap=8192]
2016-04-16 17:55:54,121 TRACE [org.jboss.remoting.remote.server] (default I/O-1) Server received authentication response
2016-04-16 17:55:54,124 TRACE [org.jboss.remoting.remote.server] (default task-33) Server sending authentication rejected: javax.security.sasl.SaslException: DIGEST-MD5: IO error acquiring password [Caused by org.jboss.as.domain.management.security.UserNotFoundException: WFLYDM0019: User 'ejbuserX' not found.]
at org.jboss.sasl.digest.DigestMD5Server.validateClientResponse(DigestMD5Server.java:629)
at org.jboss.sasl.digest.DigestMD5Server.evaluateResponse(DigestMD5Server.java:270)
at org.xnio.sasl.SaslUtils.evaluateResponse(SaslUtils.java:245)
at org.xnio.sasl.SaslUtils.evaluateResponse(SaslUtils.java:217)
at org.jboss.remoting3.remote.ServerConnectionOpenListener$AuthStepRunnable.run(ServerConnectionOpenListener.java:490)
at org.jboss.remoting3.EndpointImpl$TrackingExecutor$1.run(EndpointImpl.java:717)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: org.jboss.as.domain.management.security.UserNotFoundException: WFLYDM0019: User 'ejbuser222' not found.
org.apache.activemq
<logger category="org.apache.activemq">
<level name="TRACE"/>
</logger>
As you can imagine, by tracing the Messaging broker core package you will have useful insights on what’s going in and which messages are consumed. Watch out! the package name has changed so update your configurations if you have used the former org.hornetq Logger.
Here is for example the org.apache.activemq in action when receiving a message:
016-04-16 09:10:32,741 TRACE [org.apache.activemq.artemis.core.server] (Thread-16 (ActiveMQ-remoting-threads-ActiveMQServerImpl::serverUUID=e809b634-03a0-11e6-b719-e1aab88f48c3-1827981914-366741840)) ServerSessionPacketHandler::handlePacket,PACKET(SessionBindingQueryMessage)[type=49, channelID=11, packetObject=SessionBindingQueryMessage] 2016-04-16 09:10:32,741 TRACE [org.apache.activemq.artemis.core.server] (Thread-16 (ActiveMQ-remoting-threads-ActiveMQServerImpl::serverUUID=e809b634-03a0-11e6-b719-e1aab88f48c3-1827981914-366741840)) ServerSessionPacketHandler::scheduling response::PACKET(SessionBindingQueryResponseMessage_V2)[type=-8, channelID=0, packetObject=SessionBindingQueryResponseMessage_V2] 2016-04-16 09:10:32,743 INFO [stdout] (default task-50) Producer ActiveMQMessageProducer->org.apache.activemq.artemis.core.client.impl.ClientProducerImpl@710bcf75 2016-04-16 09:10:32,744 INFO [stdout] (default task-50) Message blank msg 2016-04-16 09:10:32,744 TRACE [org.apache.activemq.artemis.core.server] (Thread-16 (ActiveMQ-remoting-threads-ActiveMQServerImpl::serverUUID=e809b634-03a0-11e6-b719-e1aab88f48c3-1827981914-366741840)) ServerSessionPacketHandler::handlePacket,PACKET(SessionRequestProducerCreditsMessage)[type=79, channelID=11, packetObject=SessionRequestProducerCreditsMessage] 2016-04-16 09:10:32,744 TRACE [org.apache.activemq.artemis.core.server] (Thread-16 (ActiveMQ-remoting-threads-ActiveMQServerImpl::serverUUID=e809b634-03a0-11e6-b719-e1aab88f48c3-1827981914-366741840)) ServerSessionPacketHandler::scheduling response::null 2016-04-16 09:10:32,744 TRACE [org.apache.activemq.artemis.core.server] (Thread-16 (ActiveMQ-remoting-threads-ActiveMQServerImpl::serverUUID=e809b634-03a0-11e6-b719-e1aab88f48c3-1827981914-366741840)) ServerSessionPacketHandler::handlePacket,PACKET(SessionSendMessage)[type=71, channelID=11, packetObject=SessionSendMessage,message=ServerMessage[messageID=0,durable=true,userID=4f106b49-03a2-11e6-b719-e1aab88f48c3,priority=4, bodySize=194, timestamp=Sat Apr 16 09:10:32 CEST 2016,expiration=0, durable=true, address=null,properties=TypedProperties[__AMQ_CID=fb3a5265-03a1-11e6-b719-e1aab88f48c3]]@1076914897] 2016-04-16 09:10:32,745 TRACE [org.apache.activemq.artemis.core.server] (Thread-16 (ActiveMQ-remoting-threads-ActiveMQServerImpl::serverUUID=e809b634-03a0-11e6-b719-e1aab88f48c3-1827981914-366741840)) Message after routed=ServerMessage[messageID=79,durable=true,userID=4f106b49-03a2-11e6-b719-e1aab88f48c3,priority=4, bodySize=194, timestamp=Sat Apr 16 09:10:32 CEST 2016,expiration=0, durable=true, address=jms.queue.exampleQueue,properties=TypedProperties[__AMQ_CID=fb3a5265-03a1-11e6-b719-e1aab88f48c3]]@1076914897 2016-04-16 09:10:32,745 TRACE [org.apache.activemq.artemis.core.server] (Thread-16 (ActiveMQ-remoting-threads-ActiveMQServerImpl::serverUUID=e809b634-03a0-11e6-b719-e1aab88f48c3-1827981914-366741840)) ServerSessionPacketHandler::scheduling response::PACKET(NullResponseMessage)[type=21, channelID=0, packetObject=NullResponseMessage]
And here is an MDB, consuming the above message:
2016-04-16 09:10:32,749 TRACE [org.apache.activemq.artemis.core.server] (Thread-23 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$2@7a10996c-1751602232)) ServerConsumerImpl::ServerConsumerImpl [id=0, filter=null, binding=LocalQueueBinding [address=jms.queue.exampleQueue, queue=QueueImpl[name=jms.queue.exampleQueue, postOffice=PostOfficeImpl [server=ActiveMQServerImpl::serverUUID=e809b634-03a0-11e6-b719-e1aab88f48c3]]@200ce714, filter=null, name=jms.queue.exampleQueue, clusterName=jms.queue.exampleQueuee809b634-03a0-11e6-b719-e1aab88f48c3]] Handling reference Reference[79]:RELIABLE:ServerMessage[messageID=79,durable=true,userID=4f106b49-03a2-11e6-b719-e1aab88f48c3,priority=4, bodySize=256, timestamp=Sat Apr 16 09:10:32 CEST 2016,expiration=0, durable=true, address=jms.queue.exampleQueue,properties=TypedProperties[__AMQ_CID=fb3a5265-03a1-11e6-b719-e1aab88f48c3]]@1076914897 2016-04-16 09:10:32,750 TRACE [org.apache.activemq.artemis.core.server] (Thread-23 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$2@7a10996c-1751602232)) ServerConsumerImpl [id=0, filter=null, binding=LocalQueueBinding [address=jms.queue.exampleQueue, queue=QueueImpl[name=jms.queue.exampleQueue, postOffice=PostOfficeImpl [server=ActiveMQServerImpl::serverUUID=e809b634-03a0-11e6-b719-e1aab88f48c3]]@200ce714, filter=null, name=jms.queue.exampleQueue, clusterName=jms.queue.exampleQueuee809b634-03a0-11e6-b719-e1aab88f48c3]]::FlowControl::delivery standard taking 253 from credits, available now is 1048323 2016-04-16 09:10:32,750 TRACE [org.apache.activemq.artemis.core.client] (Thread-259 (ActiveMQ-client-global-threads-582264346)) Adding Runner on Executor for delivery 2016-04-16 09:10:32,750 TRACE [org.apache.activemq.artemis.core.client] (Thread-260 (ActiveMQ-client-global-threads-582264346)) Calling handler.onMessage 2016-04-16 09:10:32,751 TRACE [org.apache.activemq.artemis.ra] (Thread-260 (ActiveMQ-client-global-threads-582264346)) onMessage(ClientMessage[messageID=79, durable=true, address=jms.queue.exampleQueue,userID=4f106b49-03a2-11e6-b719-e1aab88f48c3,properties=TypedProperties[__AMQ_CID=fb3a5265-03a1-11e6-b719-e1aab88f48c3]])
The Log information produced at TRACE level by org.apache.activemq is quite verbose. Consider using a more specific namespace for your needs. For example, if you want more details about the journaling, use rather the org.apache.activemq.artemis.journal.
com.arjuna
<logger category="com.arjuna">
<level name="TRACE"/>
</logger>
This logger is already defined in your configuration out of the box, however it is set to a WARN level. You can consider increasing the severity of this logger if you want low level details about the transaction begin/commit/rollback. Here is a sample output of a successful transaction:
2016-04-16 09:12:11,426 TRACE [com.arjuna.ats.jta] (Thread-268 (ActiveMQ-client-global-threads-582264346)) TransactionImpleManager.suspend 2016-04-16 09:12:11,427 TRACE [com.arjuna.ats.jta] (Thread-268 (ActiveMQ-client-global-threads-582264346)) BaseTransaction.begin 2016-04-16 09:12:11,427 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) StateManager::StateManager( 2, 0 ) 2016-04-16 09:12:11,427 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) BasicAction::BasicAction() 2016-04-16 09:12:11,427 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) BasicAction::Begin() for action-id 0:ffff7f000001:12011438:5711e30d:3e 2016-04-16 09:12:11,427 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) BasicAction::actionInitialise() for action-id 0:ffff7f000001:12011438:5711e30d:3e 2016-04-16 09:12:11,427 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) ActionHierarchy::ActionHierarchy(1) 2016-04-16 09:12:11,427 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) ActionHierarchy::add(0:ffff7f000001:12011438:5711e30d:3e, 1) 2016-04-16 09:12:11,427 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) BasicAction::addChildThread () action 0:ffff7f000001:12011438:5711e30d:3e adding Thread[Thread-268 (ActiveMQ-client-global-threads-582264346),5,ActiveMQ-client-global-threads-582264346] 2016-04-16 09:12:11,427 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) BasicAction::addChildThread () action 0:ffff7f000001:12011438:5711e30d:3e adding Thread[Thread-268 (ActiveMQ-client-global-threads-582264346),5,ActiveMQ-client-global-threads-582264346] result = true 2016-04-16 09:12:11,427 INFO [stdout] (default task-40) Sent ActiveMQMessage[ID:89e17caa-03a2-11e6-b719-e1aab88f48c3]:PERSISTENT/ClientMessage[messageID=0, durable=true, address=null,userID=89e17caa-03a2-11e6-b719-e1aab88f48c3,properties=TypedProperties[__AMQ_CID=fb3a5265-03a1-11e6-b719-e1aab88f48c3]] 2016-04-16 09:12:11,428 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) TransactionReaper::insert ( BasicAction: 0:ffff7f000001:12011438:5711e30d:3e status: ActionStatus.RUNNING, 300 ) 2016-04-16 09:12:11,428 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) ReaperElement::ReaperElement ( BasicAction: 0:ffff7f000001:12011438:5711e30d:3e status: ActionStatus.RUNNING, 300 ) 2016-04-16 09:12:11,428 TRACE [com.arjuna.ats.jta] (Thread-268 (ActiveMQ-client-global-threads-582264346)) TransactionImple.enlistResource ( org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper@35c12a45 ) 2016-04-16 09:12:11,428 TRACE [com.arjuna.ats.jta] (Thread-268 (ActiveMQ-client-global-threads-582264346)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE 2016-04-16 09:12:11,429 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) StateManager::StateManager( 1, 0 ) 2016-04-16 09:12:11,429 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) AbstractRecord::AbstractRecord (0:ffff7f000001:12011438:5711e30d:40, 1) 2016-04-16 09:12:11,429 TRACE [com.arjuna.ats.jta] (Thread-268 (ActiveMQ-client-global-threads-582264346)) XAResourceRecord.XAResourceRecord ( < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:12011438:5711e30d:3e, node_name=1, branch_uid=0:ffff7f000001:12011438:5711e30d:3f, subordinatenodename=null, eis_name=java:/JmsXA NodeId:e809b634-03a0-11e6-b719-e1aab88f48c3 >, org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper@35c12a45 ), record id=0:ffff7f000001:12011438:5711e30d:40 2016-04-16 09:12:11,430 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffff7f000001:12011438:5711e30d:40 2016-04-16 09:12:11,430 INFO [stdout] (Thread-268 (ActiveMQ-client-global-threads-582264346)) Received message blank msg 2016-04-16 09:12:11,431 TRACE [com.arjuna.ats.jta] (Thread-268 (ActiveMQ-client-global-threads-582264346)) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE 2016-04-16 09:12:11,431 TRACE [com.arjuna.ats.jta] (Thread-268 (ActiveMQ-client-global-threads-582264346)) BaseTransaction.commit 2016-04-16 09:12:11,431 TRACE [com.arjuna.ats.jta] (Thread-268 (ActiveMQ-client-global-threads-582264346)) TransactionImple.commitAndDisassociate 2016-04-16 09:12:11,431 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) BasicAction::End() for action-id 0:ffff7f000001:12011438:5711e30d:3e 2016-04-16 09:12:11,431 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) BasicAction::onePhaseCommit() for action-id 0:ffff7f000001:12011438:5711e30d:3e 2016-04-16 09:12:11,431 TRACE [com.arjuna.ats.jta] (Thread-268 (ActiveMQ-client-global-threads-582264346)) XAResourceRecord.topLevelOnePhaseCommit for XAResourceRecord < resource:org.jboss.activemq.artemis.wildfly.integration.WildFlyActiveMQXAResourceWrapper@35c12a45, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff7f000001:12011438:5711e30d:3e, node_name=1, branch_uid=0:ffff7f000001:12011438:5711e30d:3f, subordinatenodename=null, eis_name=java:/JmsXA NodeId:e809b634-03a0-11e6-b719-e1aab88f48c3 >, heuristic: TwoPhaseOutcome.FINISH_OK, product: ActiveMQ Artemis/1.1.0.wildfly-011, jndiName: java:/JmsXA NodeId:e809b634-03a0-11e6-b719-e1aab88f48c3 com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@28b66a6c >, record id=0:ffff7f000001:12011438:5711e30d:40 2016-04-16 09:12:11,443 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) BasicAction::End() result for action-id (0:ffff7f000001:12011438:5711e30d:3e) is (TwoPhaseOutcome.PREPARE_OK) node id: (1) 2016-04-16 09:12:11,443 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) BasicAction::removeChildThread () action 0:ffff7f000001:12011438:5711e30d:3e removing TSThread:3 2016-04-16 09:12:11,443 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) BasicAction::removeChildThread () action 0:ffff7f000001:12011438:5711e30d:3e removing TSThread:3 result = true 2016-04-16 09:12:11,443 TRACE [com.arjuna.ats.arjuna] (Thread-268 (ActiveMQ-client-global-threads-582264346)) TransactionReaper::remove ( BasicAction: 0:ffff7f000001:12011438:5711e30d:3e status: ActionStatus.COMMITTED )
org.jgroups
<logger category="org.jgroups">
<level name="TRACE"/>
</logger>
JGroups is a key subsystem of the application server and the messaging layer of the cluster. When you are preparing to battle with cluster issues, tracing this subsystem can be vital to solve recover information about Failure detection (FD_SOCK) , UNICAST3 (For point-to-point communication), NAKACK2 (For multicast communication). Here is a sample dump from a org.jgroups trace output:
2016-04-16 09:24:32,109 TRACE [org.jgroups.protocols.UNICAST3] (OOB-18,ee,nodeA) nodeA <-- DATA(nodeB: #32, conn_id=0) 2016-04-16 09:24:32,109 TRACE [org.jgroups.protocols.UNICAST3] (OOB-18,ee,nodeA) nodeA: delivering nodeB#32 2016-04-16 09:24:32,109 TRACE [org.jgroups.protocols.UFC] (OOB-18,ee,nodeA) nodeB used 69 credits, 1996055 remaining 2016-04-16 09:24:32,109 TRACE [org.jgroups.blocks.RequestCorrelator] (OOB-18,ee,nodeA) calling (org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher) with request 25 2016-04-16 09:24:32,110 TRACE [org.jgroups.blocks.Request] (remote-thread--p5-t3) sending request (id=43) 2016-04-16 09:24:32,110 TRACE [org.jgroups.protocols.UNICAST3] (remote-thread--p5-t3) nodeA --> DATA(nodeB: #37, conn_id=2) 2016-04-16 09:24:32,110 TRACE [org.jgroups.protocols.UDP] (remote-thread--p5-t3) nodeA: sending msg to nodeB, src=nodeA, headers are RequestCorrelator: id=200, type=REQ, id=43, rsp_expected=false, FORK: ee:ejb, UNICAST3: DATA, seqno=37, conn_id=2, UDP: [cluster_name=ee] 2016-04-16 09:24:32,110 TRACE [org.jgroups.protocols.UFC] (remote-thread--p5-t3) nodeA used 939 credits, 1981588 remaining 2016-04-16 09:24:32,110 TRACE [org.jgroups.protocols.UDP] (TransferQueueBundler,ee,nodeA) nodeA: sending 1 msgs (1025 bytes (1.60% of max_bundle_size) to 1 dests(s): [ee:nodeB] 2016-04-16 09:24:32,111 TRACE [org.jgroups.blocks.RequestCorrelator] (remote-thread--p5-t3) sending rsp for 25 to nodeB 2016-04-16 09:24:32,111 TRACE [org.jgroups.protocols.UNICAST3] (remote-thread--p5-t3) nodeA --> DATA(nodeB: #38, conn_id=2) 2016-04-16 09:24:32,111 TRACE [org.jgroups.protocols.UDP] (remote-thread--p5-t3) nodeA: sending msg to nodeB, src=nodeA, headers are RequestCorrelator: id=200, type=RSP, id=25, rsp_expected=false, FORK: ee:ejb, UNICAST3: DATA, seqno=38, conn_id=2, UDP: [cluster_name=ee] 2016-04-16 09:24:32,111 TRACE [org.jgroups.protocols.UDP] (TransferQueueBundler,ee,nodeA) nodeA: sending 1 msgs (92 bytes (0.14% of max_bundle_size) to 1 dests(s): [ee:nodeB] 2016-04-16 09:24:32,141 TRACE [org.jgroups.protocols.UNICAST3] (Timer-3,ee,nodeA) nodeA --> ACK(nodeB: #32) 2016-04-16 09:24:32,142 TRACE [org.jgroups.protocols.UDP] (Timer-3,ee,nodeA) nodeA: sending msg to nodeB, src=nodeA, headers are UNICAST3: ACK, seqno=32, ts=9, UDP: [cluster_name=ee] 2016-04-16 09:24:32,142 TRACE [org.jgroups.protocols.UDP] (TransferQueueBundler,ee,nodeA) nodeA: sending 1 msgs (58 bytes (0.09% of max_bundle_size) to 1 dests(s): [ee:nodeB] 2016-04-16 09:24:32,178 TRACE [org.jgroups.protocols.UDP] (OOB-18,ee,nodeA) nodeA: received [dst: <null>, src: nodeB (4 headers), size=171 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: id=200, type=REQ, id=26, rsp_expected=true, FORK: ee:ejb, NAKACK2: [MSG, seqno=2], UDP: [cluster_name=ee] 2016-04-16 09:24:32,179 TRACE [org.jgroups.protocols.pbcast.NAKACK2] (OOB-18,ee,nodeA) nodeA: received nodeB#2 2016-04-16 09:24:32,180 TRACE [org.jgroups.protocols.pbcast.NAKACK2] (OOB-18,ee,nodeA) nodeA: delivering nodeB#2 2016-04-16 09:24:32,181 TRACE [org.jgroups.protocols.MFC] (OOB-18,ee,nodeA) nodeB used 171 credits, 1999585 remaining 2016-04-16 09:24:32,181 TRACE [org.jgroups.blocks.RequestCorrelator] (OOB-18,ee,nodeA) calling (org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher) with request 26 2016-04-16 09:24:32,182 TRACE [org.jgroups.blocks.RequestCorrelator] (remote-thread--p5-t3) sending rsp for 26 to nodeB 2016-04-16 09:24:32,183 TRACE [org.jgroups.protocols.UNICAST3] (remote-thread--p5-t3) nodeA --> DATA(nodeB: #39, conn_id=2) 2016-04-16 09:24:32,183 TRACE [org.jgroups.protocols.UDP] (remote-thread--p5-t3) nodeA: sending msg to nodeB, src=nodeA, headers are RequestCorrelator: id=200, type=RSP, id=26, rsp_expected=false, FORK: ee:ejb, UNICAST3: DATA, seqno=39, conn_id=2, UDP: [cluster_name=ee] 2016-04-16 09:24:32,183 TRACE [org.jgroups.protocols.UDP] (TransferQueueBundler,ee,nodeA) nodeA: sending 1 msgs (90 bytes (0.14% of max_bundle_size) to 1 dests(s): [ee:nodeB] 2016-04-16 09:24:32,206 TRACE [org.jgroups.protocols.UDP] (OOB-18,ee,nodeA) nodeA: received [dst: nodeA, src: nodeB (4 headers), size=79 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: id=200, type=REQ, id=27, rsp_expected=false, FORK: ee:ejb, UNICAST3: DATA, seqno=33, UDP: [cluster_name=ee] 2016-04-16 09:24:32,207 TRACE [org.jgroups.protocols.UNICAST3] (OOB-18,ee,nodeA) nodeA <-- DATA(nodeB: #33, conn_id=0) 2016-04-16 09:24:32,207 TRACE [org.jgroups.protocols.UNICAST3] (OOB-18,ee,nodeA) nodeA: delivering nodeB#33 2016-04-16 09:24:32,207 TRACE [org.jgroups.protocols.UFC] (OOB-18,ee,nodeA) nodeB used 79 credits, 1995976 remaining 2016-04-16 09:24:32,207 TRACE [org.jgroups.blocks.RequestCorrelator] (OOB-18,ee,nodeA) calling (org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher) with request 27
org.infinispan
<logger category="org.infinispan">
<level name="TRACE"/>
</logger>
The Infinispan subsystem exposes a wealth of information about the clustering topology and the Data Grid Container. Hence we suggest you choosing a more specific namespace such as:
- org.infinispan.remoting.transport.jgroups: This package traces information about the Infinispan-JGroups communication
- org.infinispan.topology: This package traces information about changes in the Cluster topology
- org.infinispan.container: This package exposes information about entries creation, update, removal
Here is a transcript from a Session item stored in the Cache:
2016-04-16 09:42:44,605 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-3) Creating new entry for key UnknownSessionID [5465576970707067575552505248555566665248686865705255665754546649]
2016-04-16 09:42:44,605 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-3) Wrap UnknownSessionID [5465576970707067575552505248555566665248686865705255665754546649] for read. Entry=RepeatableReadEntry(4d1bb5fb){key=UnknownSessionID [5465576970707067575552505248555566665248686865705255665754546649], value=org.wildfly.clustering.ejb.infinispan.bean.InfinispanBeanEntry@55ca0188, oldValue=null, isCreated=false, isChanged=false, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}}
2016-04-16 09:42:44,605 TRACE [org.infinispan.interceptors.CacheLoaderInterceptor] (default task-3) Skip load for command GetKeyValueCommand {key=UnknownSessionID [5465576970707067575552505248555566665248686865705255665754546649], flags=null}. Entry already exists in context.
2016-04-16 09:42:44,605 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-3) Executing command: GetKeyValueCommand {key=UnknownSessionID [5465576970707067575552505248555566665248686865705255665754546649], flags=null}.
2016-04-16 09:42:44,605 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-3) Invoked with command GetKeyValueCommand {key=f8009a1b-ab2a-470d-9734-d9c88d969c9a, flags=null} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@d84aa3f]
2016-04-16 09:42:44,605 TRACE [org.infinispan.statetransfer.StateTransferInterceptor] (default task-3) handleTopologyAffectedCommand for command GetKeyValueCommand {key=f8009a1b-ab2a-470d-9734-d9c88d969c9a, flags=null}, origin null
2016-04-16 09:42:44,605 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-3) Exists in context? null
2016-04-16 09:42:44,605 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-3) Retrieved from container ImmortalCacheEntry{key=f8009a1b-ab2a-470d-9734-d9c88d969c9a, value=org.wildfly.clustering.ejb.infinispan.group.InfinispanBeanGroupEntry@5baab53f} (ignoreOwnership=false, isLocal=true)
2016-04-16 09:42:44,605 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-3) Creating new entry for key f8009a1b-ab2a-470d-9734-d9c88d969c9a
2016-04-16 09:42:44,606 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-3) Wrap f8009a1b-ab2a-470d-9734-d9c88d969c9a for read. Entry=RepeatableReadEntry(12ba8a52){key=f8009a1b-ab2a-470d-9734-d9c88d969c9a, value=org.wildfly.clustering.ejb.infinispan.group.InfinispanBeanGroupEntry@5baab53f, oldValue=null, isCreated=false, isChanged=false, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}}
2016-04-16 09:42:44,606 TRACE [org.infinispan.interceptors.CacheLoaderInterceptor] (default task-3) Skip load for command GetKeyValueCommand {key=f8009a1b-ab2a-470d-9734-d9c88d969c9a, flags=null}. Entry already exists in context.
2016-04-16 09:42:44,606 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-3) Executing command: GetKeyValueCommand {key=f8009a1b-ab2a-470d-9734-d9c88d969c9a, flags=null}.
And here is a dump of a change in the Cluster Topology:
2016-04-16 09:30:00,319 DEBUG [org.infinispan.topology.LocalTopologyManagerImpl] (transport-thread--p15-t9) Updating local topology for cache client-mappings: CacheTopology{id=10, rebalanceId=3, currentCH=DefaultConsistentHash{ns=80, owners = (1)[nodeA: 80+0]}, pendingCH=null, unionCH=null, actualMembers=[nodeA]}
2016-04-16 09:30:00,319 DEBUG [org.infinispan.statetransfer.StateConsumerImpl] (transport-thread--p15-t9) Removing no longer owned entries for cache client-mappings
2016-04-16 09:30:00,320 DEBUG [org.infinispan.transaction.impl.TransactionTable] (transport-thread--p15-t9) Topology changed, recalculating minTopologyId
2016-04-16 09:30:00,321 DEBUG [org.infinispan.topology.ClusterCacheStatus] (remote-thread--p5-t4) Queueing rebalance for cache client-mappings with members [nodeA]
2016-04-16 09:30:00,322 TRACE [org.infinispan.topology.ClusterCacheStatus] (remote-thread--p5-t4) Rebalancing consistent hash for cache client-mappings, members are [nodeA]
2016-04-16 09:30:00,322 TRACE [org.infinispan.topology.ClusterCacheStatus] (remote-thread--p5-t4) The balanced CH is the same as the current CH, not rebalancing
2016-04-16 09:30:00,324 TRACE [org.infinispan.transaction.impl.AbstractEnlistmentAdapter] (notification-thread--p2-t1) Committed in onePhase? true isOptimistic? false
2016-04-16 09:30:00,324 TRACE [org.infinispan.transaction.impl.AbstractEnlistmentAdapter] (notification-thread--p2-t1) About to invoke tx completion notification on commitNodes: null
2016-04-16 09:30:00,395 DEBUG [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-15,ee,nodeA) New view accepted: [nodeA|6] (1) [nodeA]
2016-04-16 09:30:00,396 DEBUG [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-15,ee,nodeA) Joined: [], Left: [nodeB]
2016-04-16 09:30:00,396 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-15,ee,nodeA) ISPN000094: Received new cluster view for channel server: [nodeA|6] (1) [nodeA]
2016-04-16 09:30:00,397 DEBUG [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-15,ee,nodeA) New view accepted: [nodeA|6] (1) [nodeA]
2016-04-16 09:30:00,397 TRACE [org.infinispan.topology.ClusterTopologyManagerImpl] (transport-thread--p16-t6) Updating cluster members for all the caches. New list is [nodeA]
2016-04-16 09:30:00,397 DEBUG [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-15,ee,nodeA) Joined: [], Left: [nodeB]
2016-04-16 09:30:00,397 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-15,ee,nodeA) ISPN000094: Received new cluster view for channel web: [nodeA|6] (1) [nodeA]
2016-04-16 09:30:00,398 DEBUG [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-15,ee,nodeA) New view accepted: [nodeA|6] (1) [nodeA]
2016-04-16 09:30:00,399 DEBUG [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-15,ee,nodeA) Joined: [], Left: [nodeB]
2016-04-16 09:30:00,399 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-15,ee,nodeA) ISPN000094: Received new cluster view for channel hibernate: [nodeA|6] (1) [nodeA]
2016-04-16 09:30:00,400 DEBUG [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-15,ee,nodeA) New view accepted: [nodeA|6] (1) [nodeA]
2016-04-16 09:30:00,400 DEBUG [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-15,ee,nodeA) Joined: [], Left: [nodeB]
2016-04-16 09:30:00,400 INFO [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (Incoming-15,ee,nodeA) ISPN000094: Received new cluster view for channel ejb: [nodeA|6] (1) [nodeA]
In the following tutorial we will cover how to debug WildFly Security Issues by enabling loggers:
How to debug WildFly security issues?
Found the article helpful? if so please follow us on Socials
