Troubleshooting and Debugging WebLogic SAF

In the logs typically we shall find at startup:

<Info> <SAFService> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766521288> <BEA-281003> <SAF Service has been initialized.>

<Info> <SAFService> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766521300> <BEA-281002> <SAF Service has been started.>

<Info> <SAFService> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766522952> <BEA-281007> <SAF Agent "TESTSAFAgent@ms2" has been successfully prepared.>


<Info> <Store> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766522976> <BEA-280008> <Opening the persistent file store "filestore2" for recovery: directory=C:\Oracle2\Middleware\user_projects\domains\osb_domain\servers\ms2\data\store\filestore2 requestedWritePolicy="Direct-Write" fileLockingEnabled=true driver="wlfileio3".>

<Info> <Store> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523128> <BEA-280009> <The persistent file store "filestore2" (6664685f-2e2e-4a64-b87d-c9fc9e485ade) has been opened: blockSize=512 actualWritePolicy="Direct-Write(read-buffered)" explicitIOEnforced=false records=49.>

<Info> <JMS> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523135> <BEA-040321> <JMSServer "TESTSAFAgent@ms2" is resuming.>

<Info> <Messaging> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523212> <BEA-282003> <The messaging kernel TESTSAFAgent@ms2 will use up to 345,986,389 bytes of memory before paging begins>

<Info> <Messaging> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523226> <BEA-282001> <The messaging kernel TESTSAFAgent@ms2 is beginning recovery of its persistent state>

<Info> <Messaging> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523265> <BEA-282002> <The messaging kernel TESTSAFAgent@ms2 has recovered 0 persistent messages>

<Debug> <SAFStore> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523341> <BEA-000000> <*********** ***** <SAFStoreRecord> state= class=weblogic.messaging.saf.internal.SendingAgentImpl code=15 obj=<SendingAgentImpl> : SAFAgentInternalName = TESTSAFAgent@ms2 null>

<Debug> <SAFStore> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523341> <BEA-000000> < == SAFStore Created for Agent TESTSAFAgent@ms2.SA>

<Debug> <SAFSendingAgent> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523343> <BEA-000000> <Sending Agent 'TESTSAFAgent@ms2' has recovered 0 conversation infos>

<Debug> <SAFSendingAgent> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523343> <BEA-000000> <Sending Agent 'TESTSAFAgent@ms2' is starting: found 0 topics>

<Info> <SAFService> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523343> <BEA-281008> <SAF Agent "TESTSAFAgent@ms2" has been successfully activated.>


<Info> <JMS> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766539485> <BEA-040109> <JMSServer "TESTSAFAgent@ms2" is started.>




http://download.oracle.com/docs/cd/E12840_01/wls/docs103/saf_admin/troubleshoot.html




weblogic.diagnostics.debug.DebugLogger.DISABLED
weblogic.management.utils.debug

-Dweblogic.debug.DebugSAFSendingAgent=true
-Dweblogic.log.StdoutSeverity="Debug"



Server debug flags:

in the "default" area:
DebugMessaging
(remember to restart)

in the WebLogic area:
DebugSAFAdmin, DebugSAFLifeCycle, DebugSAFManager, DebugSAFMessagePath, DebugSAFReceivingAgent, DebugSAFSendingAgent, DebugSAFStore
DebugSAFTransport, DebugSAFVerbose, DebugJMSSAF, DebugMessagingKernel


Especially enabling DebugJMSSAF traces this info in the logs:

<Debug> <JMSSAF> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315778607231> <BEA-000000> <Forwarder reconnect(): remoteInitialCtx= null>
<Debug> <JMSSAF> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315778607231> <BEA-000000> <Forwarder connectTarget()>
<Debug> <JMSSAF> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315778607231> <BEA-000000> <Retry for 't3://pierrepc:7011' to 't3://pierrepc:7011'>
<Debug> <JMSSAF> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315778607232> <BEA-000000> <Forwarder::getInitialContext()::Password=XXXX,username=weblogic>


The DebugMessagingKernel produces a lot of info:


<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <weblogic> <> <> <1315779610966> <BEA-000000> <Queue SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2 sending message element: [ sequence=0 queue=1 name=SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2 state=0 deliveryCount=0 ] handle: [ id=3 queueRefCount=1 quotaRefCount=1 persistentRefCount=0 pinCount=1 size=5 persistent=true persistBody=false ]>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <weblogic> <> <> <1315779610967> <BEA-000000> <Added message to the queue list: [ sequence=3 queue=1 name=SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2 state=1 deliveryCount=0 sequence=osb_domain@myCluster@ms2@SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2201109091356440079 number=0 ]>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <weblogic> <> <> <1315779610967> <BEA-000000> <Enlisting message [ sequence=3 queue=1 name=SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2 state=1 deliveryCount=0 sequence=osb_domain@myCluster@ms2@SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2201109091356440079 number=0 ] in transaction weblogic.store.gxa.internal.GXALocalTransactionImpl@80e605>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <weblogic> <> <> <1315779610975> <BEA-000000> <SendOperation prepare called for [ sequence=3 queue=1 name=SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2 state=5 deliveryCount=0 sequence=osb_domain@myCluster@ms2@SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2201109091356440079 number=0 ]>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <weblogic> <> <> <1315779610978> <BEA-000000> <Persisted new value of 0 for sequence [ name=osb_domain@myCluster@ms2@SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2201109091356440079 sequenceMode=ASSIGN destination=weblogic.messaging.kernel.internal.QueueImpl@8845ff03 lastValue=0 lastAssignedValue=9 ]>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <weblogic> <> <> <1315779610983> <BEA-000000> <Persisted message element 3 to queue weblogic.messaging.kernel.internal.QueueImpl@8845ff03>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315779610987> <BEA-000000> <SendOperation commit called. Making message visible [ sequence=3 queue=1 name=SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2 state=261 deliveryCount=0 sequence=osb_domain@myCluster@ms2@SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2201109091356440079 number=10 ]>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315779610994> <BEA-000000> <Resuming send of message [ state = COMMIT handle = [ id=3 queueRefCount=1 quotaRefCount=1 persistentRefCount=1 pinCount=1 size=5 persistent=true persistBody=true ] ]>