Jump to: navigation, search

Difference between revisions of "Paho/Log and Debug in the Java client"

 
(Capturing log and trace using the default logger)
Line 26: Line 26:
 
java -Djava.util.logging.config.file=C:\Users\locke\workspace\djl.utils\src\jsr47min.properties
 
java -Djava.util.logging.config.file=C:\Users\locke\workspace\djl.utils\src\jsr47min.properties
  
<pre/>
+
</pre>
 
A working property file  jsr47min.properties is provided in package org.eclipse.paho.client.mqttv3.logging.   
 
A working property file  jsr47min.properties is provided in package org.eclipse.paho.client.mqttv3.logging.   
  
Line 83: Line 83:
 
# Style of output (Simple or XML):
 
# Style of output (Simple or XML):
 
java.util.logging.FileHandler.formatter=org.eclipse.paho.client.mqttv3.logging.SimpleLogFormatter
 
java.util.logging.FileHandler.formatter=org.eclipse.paho.client.mqttv3.logging.SimpleLogFormatter
<pre/>
+
</pre>
  
 
The format that messages are written out can be controlled by configuring a FileHandler. A custom file handler is provided with Paho that writes out more than the SimpleHandler and less than XMLHandler provided with the Java runtime.  
 
The format that messages are written out can be controlled by configuring a FileHandler. A custom file handler is provided with Paho that writes out more than the SimpleHandler and less than XMLHandler provided with the Java runtime.  
Line 90: Line 90:
 
<pre>
 
<pre>
 
Level  Data & Time  Class  Method  Thread  clientID  Message
 
Level  Data & Time  Class  Method  Thread  clientID  Message
<pre/>
+
</pre>
  
 
Pasted below is some example trace output from a connect call using the MqttAsyncClient:
 
Pasted below is some example trace output from a connect call using the MqttAsyncClient:
Line 140: Line 140:
 
FINE    13-05-30  22:26:57.0652        ttv3.internal.Token      notifyComplete                3      samplePub1: >key=Con response=org.eclipse.paho.client.mqttv3.internal.wire.MqttConnack@170d170d excep=null
 
FINE    13-05-30  22:26:57.0652        ttv3.internal.Token      notifyComplete                3      samplePub1: >key=Con response=org.eclipse.paho.client.mqttv3.internal.wire.MqttConnack@170d170d excep=null
 
FINE    13-05-30  22:26:57.0653        ernal.CommsCallback      fireActionEvent                3      samplePub1: call onSuccess key=Con
 
FINE    13-05-30  22:26:57.0653        ernal.CommsCallback      fireActionEvent                3      samplePub1: call onSuccess key=Con
<pre/>
+
</pre>
  
 
==== How to collect debug information ====
 
==== How to collect debug information ====
Line 150: Line 150:
 
     public class Debug
 
     public class Debug
 
     package org.eclipse.paho.client.mqttv3.util
 
     package org.eclipse.paho.client.mqttv3.util
<pre/>
+
</pre>
  
 
An instance of Debug can be obtained using the method getDebug() on both the asynchronous and synchronous MQTT client objects.
 
An instance of Debug can be obtained using the method getDebug() on both the asynchronous and synchronous MQTT client objects.
Line 285: Line 285:
 
java.specification.version  :  1.6
 
java.specification.version  :  1.6
 
==========================================
 
==========================================
How Logging and Trace is Implemented  
+
</pre>
Logging and Trace Interface
+
 
 +
=== How Logging and Trace is Implemented ===
 +
 
 +
==== Logging and Trace Interface =====
 +
 
 
The Java Client is instrumented to write log and trace records at pertinent points. The log and trace records are written to a “pluggable” log interface.   
 
The Java Client is instrumented to write log and trace records at pertinent points. The log and trace records are written to a “pluggable” log interface.   
  
Line 293: Line 297:
  
 
It enables log messages to be at different levels depending on the severity of the event:-
 
It enables log messages to be at different levels depending on the severity of the event:-
 +
<pre>
 
public static final int SEVERE = 1;
 
public static final int SEVERE = 1;
 
public static final int WARNING = 2;
 
public static final int WARNING = 2;
Line 300: Line 305:
 
public static final int FINER = 6;
 
public static final int FINER = 6;
 
public static final int FINEST = 7;
 
public static final int FINEST = 7;
 +
</pre>
  
 
There are a set of corresponding methods that enable an application to write log records at each level.  For instance the methods to write severe records are:
 
There are a set of corresponding methods that enable an application to write log records at each level.  For instance the methods to write severe records are:
 +
 +
<pre>
 
/**
 
/**
 
* Log a message, specifying source class and method,  
 
* Log a message, specifying source class and method,  
Line 327: Line 335:
 
public void severe(String sourceClass, String sourceMethod,
 
public void severe(String sourceClass, String sourceMethod,
 
     String msg, Object[] inserts, Throwable thrown);
 
     String msg, Object[] inserts, Throwable thrown);
 +
</pre>
  
  
 +
==== Logging and Trace Default Implementation ====
  
Logging and Trace Default Implementation
 
 
A default implementation of the logger interface is provided that uses the standard Java logging interface (JSR47) – java.util.logging. The implementation is provided by:
 
A default implementation of the logger interface is provided that uses the standard Java logging interface (JSR47) – java.util.logging. The implementation is provided by:
 +
<pre>
 
package org.eclipse.paho.client.mqttv3.logging;
 
package org.eclipse.paho.client.mqttv3.logging;
 
public class JSR47Logger implements Logger
 
public class JSR47Logger implements Logger
 +
</pre>
  
 
The JSR47 logging facility is very flexible in how and what it captures. See the How to use log and trace facility for more details.  
 
The JSR47 logging facility is very flexible in how and what it captures. See the How to use log and trace facility for more details.  
 +
 
How the Logger is loaded
 
How the Logger is loaded
 
A factory is used to load a logger at runtime:  
 
A factory is used to load a logger at runtime:  
Line 345: Line 357:
 
private static String overrideloggerClassName
 
private static String overrideloggerClassName
 
in LoggerFactory must be set to the fully qualified class name of the Logger implementation that is to be used. This must be set before the MQTT client is instantiated.  
 
in LoggerFactory must be set to the fully qualified class name of the Logger implementation that is to be used. This must be set before the MQTT client is instantiated.  
Adding new trace and log events
+
 
 +
==== Adding new trace and log events ====
 +
 
 
Each Log and trace message:
 
Each Log and trace message:
Has an identifier that is unique across the Paho client.  If the message is removed the message identifier should not be reused.  
+
* Has an identifier that is unique across the Paho client.  If the message is removed the message identifier should not be reused.  
Can be translated to other languages
+
* Can be translated to other languages
Can contain inserts
+
* Can contain inserts
  
 
In order to make the code readable and to make maintenance of messages simpler,  English log messages are embedded in the source code before the statement that writes the log record.  Below is an example from the disconnect method in MqttAsyncClient.  
 
In order to make the code readable and to make maintenance of messages simpler,  English log messages are embedded in the source code before the statement that writes the log record.  Below is an example from the disconnect method in MqttAsyncClient.  
  
 +
<pre>
 
// @TRACE 104=> quiesceTimeout={0} userContext={1} callback={2}
 
// @TRACE 104=> quiesceTimeout={0} userContext={1} callback={2}
 
log.fine(className,methodName, "104",
 
log.fine(className,methodName, "104",
Line 359: Line 374:
 
   callback
 
   callback
 
});
 
});
 
+
</pre>
  
 
The comment contains:  
 
The comment contains:  
A unique identifier of “104”  (The identifier must be unique across the Paho client )
+
* A unique identifier of “104”  (The identifier must be unique across the Paho client )
The English message that will be output e.g “quiesceTimeout=”…   
+
* The English message that will be output e.g “quiesceTimeout=”…   
Inserts that will be replaced dynamically at runtime:  {0} will be replaced by the quiesceTimeout value
+
* Inserts that will be replaced dynamically at runtime:  {0} will be replaced by the quiesceTimeout value
 +
 
 
The corresponding log statement must contain:
 
The corresponding log statement must contain:
A log method that is defined in the Logger Interface in the example fine.  
+
* A log method that is defined in the Logger Interface in the example fine.  
 
The class name and method name of the method the log entry is in.
 
The class name and method name of the method the log entry is in.
A unique identifier that must match the identifier in the comment
+
* A unique identifier that must match the identifier in the comment
A set of inserts that match the substitution parameters in the comment. The inserts must be in the same sequence as in the comment.
+
* A set of inserts that match the substitution parameters in the comment. The inserts must be in the same sequence as in the comment.
Building the log message files
+
 
 +
==== Building the log message files ====
 
The log messages that are embedded in the source must be extracted into a resource file that is then used at runtime.  Use  
 
The log messages that are embedded in the source must be extracted into a resource file that is then used at runtime.  Use  
 +
<pre>
 
class LogMessageExtractor
 
class LogMessageExtractor
 +
</pre>
 
in package org.eclipse.paho.client.mqttv3.internal.traceformat to achieve this.  
 
in package org.eclipse.paho.client.mqttv3.internal.traceformat to achieve this.  
  
 
The class can be run directly from inside of Eclipse and will create / replace file  
 
The class can be run directly from inside of Eclipse and will create / replace file  
  
 +
<pre>
 
logcat.properties in package org.eclipse.paho.client.mqttv3.internal.nls
 
logcat.properties in package org.eclipse.paho.client.mqttv3.internal.nls
 +
</pre>
  
 
The utility to extract messages is run whenever a change to log or trace is made. The resulting logcat properties file must then be checked into the library system.
 
The utility to extract messages is run whenever a change to log or trace is made. The resulting logcat properties file must then be checked into the library system.

Revision as of 05:04, 5 August 2013

A Guild to Log and Debug in the Paho Java Client

The Paho Java client has a number of features that can be used to help solve problems both in the MQTT client library and to a lesser degree with the application using the client library. This document describes these features and how to use them.

The document does not go into detail on each class and method but provides an overview showing how the log and trace facilities are implemented and used. The JavaDoc should be used along this side to obtain detailed information.

How to use the log and trace facility

Capturing log and trace using the default logger

The logging implementation in Paho is pluggable but comes with a default logger that uses the standard Java logging facility known as JSR47 or java.util.logging.

The JSR47 logging facility is very flexible and can be used in a number of ways including:

  • Collect messages from a selected set of packages
  • Collect messages from at and below a log level
  • Choose multiple destinations for the log messages
  • A built in logger that will write to a file and control the size and number of files used.
  • A built in logger that will write to memory and enable the in memory messages to be written out based on a trigger
  • If the application using the MQTT client library is also instrumented using JSR47 then messages from the application and client library will be intermingled.

Full details on JSR47 can be found in the JavaDoc for package java.util.logging [1].

JSR47 can be configured either via the use of a configuration / properties file or programmatically. The simplest method to tell the Java runtime about the configuration file is to pass in the property java.util.logging.config.file. For instance:

 

java -Djava.util.logging.config.file=C:\Users\locke\workspace\djl.utils\src\jsr47min.properties

A working property file jsr47min.properties is provided in package org.eclipse.paho.client.mqttv3.logging.

The configuration in this file is a suggested configuration for collecting trace that will help solve problems related to the Paho MQTT client. It configures trace to be continuously collected in memory with minimal impact on performance.

When the push trigger (by default a Severe level message) or a specific request is made to "push", the in memory trace is "pushed" to the configured target handler. By default this is the standard java.util.logging.FileHandler. The Paho Debug class can be used to push the memory trace to its target.

A good approach to debug is: Start trace when the Java runtime is started (via logging.config.file property) When an exception occurs or the problem has occurred use the Paho Debug class to cause the in memory trace to be written to the configured file target.

For reference the bulk of jsr47min.properties is pasted below:

# Loggers
# ------------------------------------------
# A memory handler is attached to the Paho packages
# and the level specified to collect all trace related
# to Paho packages.  This will override any root/global
# level handlers if set.  
org.eclipse.paho.client.mqttv3.handlers=java.util.logging.MemoryHandler
org.eclipse.paho.client.mqttv3.level=ALL
# It is possible to set more granular trace on a per class basis e.g.
#org.eclipse.paho.client.mqttv3.internal.ClientComms.level=ALL

# Handlers
# -----------------------------------------
# Note: the target handler that is associated with the Memory Handler is not a root handler 
# and hence not returned when getting the handlers from root. It appears accessing 
# target handler programmatically is not possible as target is a private variable in 
# class MemoryHandler
java.util.logging.MemoryHandler.level=FINEST
java.util.logging.MemoryHandler.size=10000
java.util.logging.MemoryHandler.push=SEVERE
java.util.logging.MemoryHandler.target=java.util.logging.FileHandler
#java.util.logging.MemoryHandler.target=java.util.logging.ConsoleHandler


# --- FileHandler ---
# Override of global logging level
java.util.logging.FileHandler.level=ALL

# Naming style for the output file:
# (The output file is placed in the directory
# defined by the "user.home" System property.)
# See java.util.logging for more options 
java.util.logging.FileHandler.pattern=%h/paho%u.log

# Limiting size of output file in bytes:
java.util.logging.FileHandler.limit=200000

# Number of output files to cycle through, by appending an
# integer to the base file name:
java.util.logging.FileHandler.count=3

# Style of output (Simple or XML):
java.util.logging.FileHandler.formatter=org.eclipse.paho.client.mqttv3.logging.SimpleLogFormatter

The format that messages are written out can be controlled by configuring a FileHandler. A custom file handler is provided with Paho that writes out more than the SimpleHandler and less than XMLHandler provided with the Java runtime.

Trace records using the Paho log formatter are of the form:

Level   Data & Time   Class   Method   Thread   clientID   Message

Pasted below is some example trace output from a connect call using the MqttAsyncClient:

FINE     13-05-30  22:26:56.0936        tv3.MqttAsyncClient      
connect   0      samplePub1: 
cleanSession=true connectionTimeout=30 TimekeepAlive=60 userName=null password=[null] will=[null] userContext=null callback=null

FINE     13-05-30  22:26:56.0936        tv3.MqttAsyncClient      createNetworkModules           0       samplePub1: URI=tcp://m2m.eclipse.org:1883
FINE     13-05-30  22:26:56.0937        tv3.MqttAsyncClient      createNetworkModule            0       samplePub1: URI=tcp://m2m.eclipse.org:1883
FINE     13-05-30  22:26:56.0939        tv3.MqttAsyncClient      createNetworkModules           0       samplePub1: <
FINE     13-05-30  22:26:56.0981        nternal.ClientComms      connect                        0       samplePub1: state=CONNECTING
FINE     13-05-30  22:26:56.0985        nal.CommsTokenStore      open                           0       samplePub1: >
FINE     13-05-30  22:26:57.0026        nternal.ClientComms      connectBG:run                  1       samplePub1: >
FINE     13-05-30  22:26:57.0026        ttv3.internal.Token      waitForCompletion              0       samplePub1: key=null wait max=-1 token=key=null ,topics= ,usercontext=org.eclipse.paho.client.mqttv3.MqttAsyncClient@63576357 ,isComplete=false ,isNotified=false ,exception=null ,actioncallback=org.eclipse.paho.client.mqttv3.internal.ConnectActionListener@69e769e7
FINE     13-05-30  22:26:57.0026        nal.CommsTokenStore      getOutstandingDelTokens        1       samplePub1: >
FINE     13-05-30  22:26:57.0027        ttv3.internal.Token      waitForResponse                0       samplePub1: >key=null timeout=-1 sent=false completed=false hasException=false response=null token=key=null ,topics= ,usercontext=org.eclipse.paho.client.mqttv3.MqttAsyncClient@63576357 ,isComplete=false ,isNotified=false ,exception=null ,actioncallback=org.eclipse.paho.client.mqttv3.internal.ConnectActionListener@69e769e7
FINE     13-05-30  22:26:57.0027        nal.CommsTokenStore      saveToken                      1       samplePub1: key=Con message=org.eclipse.paho.client.mqttv3.internal.wire.MqttConnect@74cf74cf
FINE     13-05-30  22:26:57.0028        ttv3.internal.Token      waitForResponse                0       samplePub1: key=null wait max=-1
FINE     13-05-30  22:26:57.0028        nal.CommsTokenStore      saveToken                      1       samplePub1: key=Con token=org.eclipse.paho.client.mqttv3.MqttToken@69ec69ec
FINE     13-05-30  22:26:57.0029        al.TCPNetworkModule      start                          1       samplePub1: connect to host m2m.eclipse.org port 1,883 timeout 30,000
FINE     13-05-30  22:26:57.0455        ernal.CommsReceiver      start                          1       samplePub1: starting
FINE     13-05-30  22:26:57.0456        ernal.CommsReceiver      run                            2       samplePub1: network read message
FINE     13-05-30  22:26:57.0472        ernal.CommsCallback      run                            3       samplePub1: wait for workAvailable
FINE     13-05-30  22:26:57.0472        nternal.ClientState      get                            4       samplePub1: wait for 60,000 ms for new work or for space in the inflight window
FINE     13-05-30  22:26:57.0472        nternal.ClientComms      internalSend                   1       samplePub1: internalSend key=Con message=org.eclipse.paho.client.mqttv3.internal.wire.MqttConnect@74cf74cf token=org.eclipse.paho.client.mqttv3.MqttToken@69ec69ec
FINE     13-05-30  22:26:57.0473        nternal.ClientState      send                           1       samplePub1: pending send key=0 message org.eclipse.paho.client.mqttv3.internal.wire.MqttConnect@74cf74cf
FINE     13-05-30  22:26:57.0474        nal.CommsTokenStore      saveToken                      1       samplePub1: key=Con message=org.eclipse.paho.client.mqttv3.internal.wire.MqttConnect@74cf74cf
FINE     13-05-30  22:26:57.0474        nal.CommsTokenStore      saveToken                      1       samplePub1: key=Con token=org.eclipse.paho.client.mqttv3.MqttToken@69ec69ec
FINE     13-05-30  22:26:57.0475        nternal.CommsSender      run                            4       samplePub1: network send key=Con msg=org.eclipse.paho.client.mqttv3.internal.wire.MqttConnect@74cf74cf
FINE     13-05-30  22:26:57.0476        nternal.ClientState      notifySent                     4       samplePub1: key=Con
FINE     13-05-30  22:26:57.0476        ttv3.internal.Token      notifySent                     4       samplePub1: > key=Con
FINE     13-05-30  22:26:57.0476        nternal.ClientState      get                            4       samplePub1: wait for 60,000 ms for new work or for space in the inflight window
FINE     13-05-30  22:26:57.0647        nternal.ClientState      notifyReceivedAck              2       samplePub1: received key=0 message=org.eclipse.paho.client.mqttv3.internal.wire.MqttConnack@170d170d
FINE     13-05-30  22:26:57.0647        nternal.ClientState      clearState                     2       samplePub1: >
FINE     13-05-30  22:26:57.0648        nal.CommsTokenStore      clear                          2       samplePub1: > 1 tokens
FINE     13-05-30  22:26:57.0648        nal.CommsTokenStore      saveToken                      2       samplePub1: key=Con message=org.eclipse.paho.client.mqttv3.internal.wire.MqttConnack@170d170d
FINE     13-05-30  22:26:57.0648        nal.CommsTokenStore      saveToken                      2       samplePub1: key=Con token=org.eclipse.paho.client.mqttv3.MqttToken@69ec69ec
FINE     13-05-30  22:26:57.0649        nternal.ClientState      connected                      2       samplePub1: connected
FINE     13-05-30  22:26:57.0649        nternal.ClientComms      connectComplete                2       samplePub1: state=CONNECTED
FINE     13-05-30  22:26:57.0650        ttv3.internal.Token      markComplete                   2       samplePub1: >key=Con response=org.eclipse.paho.client.mqttv3.internal.wire.MqttConnack@170d170d excep=null
FINE     13-05-30  22:26:57.0650        nternal.ClientState      notifyResult                   2       samplePub1: keyCon, msg=org.eclipse.paho.client.mqttv3.internal.wire.MqttConnack@170d170d, excep=null
FINE     13-05-30  22:26:57.0651        ernal.CommsCallback      asyncOperationComplete         2       samplePub1: new workAvailable. key=Con
FINE     13-05-30  22:26:57.0651        nal.CommsTokenStore      removeToken                    2       samplePub1: key=Con
FINE     13-05-30  22:26:57.0651        ernal.CommsReceiver      run                            2       samplePub1: network read message
FINE     13-05-30  22:26:57.0651        ernal.CommsCallback      handleActionComplete           3       samplePub1: callback and notify for key=Con
FINE     13-05-30  22:26:57.0652        nternal.ClientState      get                            4       samplePub1: wait for 59,824 ms for new work or for space in the inflight window
FINE     13-05-30  22:26:57.0652        ttv3.internal.Token      notifyComplete                 3       samplePub1: >key=Con response=org.eclipse.paho.client.mqttv3.internal.wire.MqttConnack@170d170d excep=null
FINE     13-05-30  22:26:57.0653        ernal.CommsCallback      fireActionEvent                3       samplePub1: call onSuccess key=Con

How to collect debug information

A utility class is provided to help collect debug info which includes the log and trace messages from memory described above but in addition can collect additional info like Java system properties and the value of variables from inside the Paho client.

The debug facility is provided in class

    public class Debug
    package org.eclipse.paho.client.mqttv3.util

An instance of Debug can be obtained using the method getDebug() on both the asynchronous and synchronous MQTT client objects.

Method dumpClientDebug() will dump the maximum amount of debug information. This is written to the log facility hence it is important that the log facility is enabled to capture the full debug info.

A good time to call one of the dump* methods is when the problem is known to have occurred, for instance after a particular exception has occurred.

Below is an example that was written to the log facility when dumpClientDebug() was called.

======== samplePub1 : ClientComms ========

stoppingComms  : false serverURI  : tcp://m2m.eclipse.org:1883 conState  : 3 callback  : org.eclipse.paho.client.mqttv3.internal.CommsCallback@78737873

==============================

FINE 13-05-30 22:51:23.0074 nternal.ClientComms dumpConOptions 0 samplePub1:

======== samplePub1 : Connect Options ========

CleanSession  : true SocketFactory  : null KeepAliveInterval  : 60 ConTimeout  : 30 UserName  : null SSLProperties  : null WillDestination  : null

==============================

FINE 13-05-30 22:51:23.0074 nternal.ClientComms dumpClientState 0 samplePub1:

======== samplePub1 : ClientState ========

quiescing  : false In use msgids  : {} lastInboundActivity  : 1369950683042 inFlightPubRels  : 0 pendingFlows  : [] outboundQoS2  : {} outboundQoS1  : {} pingoutstanding  : false lastOutboundActivity  : 1369950683042 nextMsgID  : 1 maxInflight  : 10 pendingMessages  : [] inboundQoS2  : {} tokens  : actualInFlight  : 0

==============================

FINE 13-05-30 22:51:23.0074 nternal.ClientComms dumpVersion 0 samplePub1:

======== Version Info ========

Version  : @@VERSION@@ Build Level  : @@BUILDLEVEL@@

==============================

FINE 13-05-30 22:51:23.0074 nternal.ClientComms dumpSystemProperties 0 samplePub1:

======== SystemProperties ========

java.vendor  : IBM Corporation sun.java.launcher  : SUN_STANDARD os.name  : Windows 7 sun.boot.class.path  : C:\Prods\Java16IBMSDK\jre\lib\vm.jar;C:\Prods\Java16IBMSDK\jre\lib\annotation.jar;C:\Prods\Java16IBMSDK\jre\lib\beans.jar;C:\Prods\Java16IBMSDK\jre\lib\java.util.jar;C:\Prods\Java16IBMSDK\jre\lib\jndi.jar;C:\Prods\Java16IBMSDK\jre\lib\logging.jar;C:\Prods\Java16IBMSDK\jre\lib\security.jar;C:\Prods\Java16IBMSDK\jre\lib\sql.jar;C:\Prods\Java16IBMSDK\jre\lib\ibmorb.jar;C:\Prods\Java16IBMSDK\jre\lib\ibmorbapi.jar;C:\Prods\Java16IBMSDK\jre\lib\ibmcfw.jar;C:\Prods\Java16IBMSDK\jre\lib\rt.jar;C:\Prods\Java16IBMSDK\jre\lib\charsets.jar;C:\Prods\Java16IBMSDK\jre\lib\resources.jar;C:\Prods\Java16IBMSDK\jre\lib\ibmpkcs.jar;C:\Prods\Java16IBMSDK\jre\lib\ibmcertpathfw.jar;C:\Prods\Java16IBMSDK\jre\lib\ibmjgssfw.jar;C:\Prods\Java16IBMSDK\jre\lib\ibmjssefw.jar;C:\Prods\Java16IBMSDK\jre\lib\ibmsaslfw.jar;C:\Prods\Java16IBMSDK\jre\lib\ibmjcefw.jar;C:\Prods\Java16IBMSDK\jre\lib\ibmjgssprovider.jar;C:\Prods\Java16IBMSDK\jre\lib\ibmjsseprovider2.jar;C:\Prods\Java16IBMSDK\jre\lib\ibmcertpathprovider.jar;C:\Prods\Java16IBMSDK\jre\lib\management-agent.jar;C:\Prods\Java16IBMSDK\jre\lib\xml.jar;C:\Prods\Java16IBMSDK\jre\lib\jlm.jar;C:\Prods\Java16IBMSDK\jre\lib\javascript.jar java.util.logging.config.file: C:\Users\locke\workspace\djl.utils\src\jsr47tofile.properties sun.java2d.fontpath  : java.vm.specification.vendor: Sun Microsystems Inc. java.runtime.version  : pwi3260sr11-20120806_01 (SR11) user.name  : locke java.compiler  : j9jit24 os.encoding  : UTF8 com.ibm.util.extralibs.properties: com.ibm.jcl.checkClassPath  : user.language  : en com.ibm.oti.vm.bootstrap.library.path: C:\Prods\Java16IBMSDK\jre\bin sun.boot.library.path  : C:\Prods\Java16IBMSDK\jre\bin java.version  : 1.6.0 user.timezone  : Europe/London sun.arch.data.model  : 32 com.ibm.zero.version  : 1 java.endorsed.dirs  : C:\Prods\Java16IBMSDK\jre\lib\endorsed com.ibm.oti.vm.library.version: 24 sun.jnu.encoding  : Cp1252 jxe.current.romimage.version: 15 file.separator  : \ java.specification.name  : Java Platform API Specification java.class.version  : 50.0 user.country  : GB java.home  : C:\Prods\Java16IBMSDK\jre java.vm.info  : JRE 1.6.0 IBM J9 2.4 Windows 7 x86-32 jvmwi3260sr11-20120801_118201 (JIT enabled, AOT enabled) J9VM - 20120801_118201 JIT - r9_20120608_24176ifx1 GC - 20120516_AA os.version  : 6.1 build 7601 Service Pack 1 java.awt.fonts  : path.separator  :  ; java.vm.version  : 2.4 java.util.prefs.PreferencesFactory: java.util.prefs.WindowsPreferencesFactory user.variant  : java.awt.printerjob  : sun.awt.windows.WPrinterJob sun.io.unicode.encoding  : UnicodeLittle awt.toolkit  : sun.awt.windows.WToolkit ibm.signalhandling.sigint  : true java.assistive  : ON user.home  : C:\Users\locke com.ibm.cpu.endian  : little java.specification.vendor  : Sun Microsystems Inc. ibm.signalhandling.sigchain : true java.library.path  : C:\Prods\Java16IBMSDK\jre\bin;C:\Windows\SysWOW64;C:\Windows;C:\Program Files (x86)\IBM\WebSphere MQ_p000\java\lib;C:\Program Files (x86)\IBM\WebSphere MQ_p000\java\lib64;C:\Python27\;C:\Python27\Scripts;C:\PROGRAM FILES\COMMON FILES\MICROSOFT SHARED\WINDOWS LIVE;C:\PROGRAM FILES\IBM\INFOPRINT SELECT;C:\PROGRAM FILES (X86)\COMMON FILES\MICROSOFT SHARED\WINDOWS LIVE;C:\Windows\SYSTEM32;C:\Windows;C:\Windows\SYSTEM32\WBEM;C:\PROGRAM FILES (X86)\COMMON FILES\LENOVO;C:\PROGRAM FILES (X86)\COMMON FILES\ULEAD SYSTEMS\MPEG;C:\PROGRAM FILES (X86)\WINDOWS LIVE\SHARED;C:\SWTOOLS\READYAPPS;C:\PROGRAM FILES (X86)\INTEL\SERVICES\IPT\;C:\PROGRAM FILES (X86)\IBM\PERSONAL COMMUNICATIONS\;C:\PROGRAM FILES (X86)\IBM\TRACE FACILITY\;C:\PRODS\CMVCCMDLINE\BIN\;C:\PROGRAM FILES\THINKPAD\BLUETOOTH SOFTWARE\;C:\PROGRAM FILES\THINKPAD\BLUETOOTH SOFTWARE\SYSWOW64;C:\Program Files (x86)\IBM\WebSphere MQ_p000\bin64;C:\Program Files (x86)\IBM\WebSphere MQ_p000\bin;C:\Program Files (x86)\IBM\WebSphere MQ_p000\tools\c\samples\bin;C:\Program Files (x86)\IBM\Mobility Client\;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files\Intel\WiFi\bin\;C:\Program Files\Common Files\Intel\WirelessCommon\;C:\Program Files (x86)\Git\cmd;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\QuickTime\QTSystem\;C:\Users\locke\AppData\Roaming\Python\Scripts;C:\Program Files (x86)\SlickEditV15.0.1\win\;c:\tools\apache-ant\bin;. java.vendor.url  : http://www.ibm.com/ java.vm.vendor  : IBM Corporation java.fullversion  : JRE 1.6.0 IBM J9 2.4 Windows 7 x86-32 jvmwi3260sr11-20120801_118201 (JIT enabled, AOT enabled) J9VM - 20120801_118201 JIT - r9_20120608_24176ifx1 GC - 20120516_AA java.runtime.name  : Java(TM) SE Runtime Environment sun.java.command  : org.eclipse.paho.sample.mqttv3app.Sample -i samplePub1 java.class.path  : C:\Users\locke\workspace\org.eclipse.paho.sample.mqttv3app\bin;C:\Users\locke\workspace\org.eclipse.paho.client.mqttv3\bin java.vm.specification.name  : Java Virtual Machine Specification java.vm.specification.version: 1.0 sun.cpu.endian  : little java.io.tmpdir  : C:\Users\locke\AppData\Local\Temp\ java.jcl.version  : 20120713_01 ibm.system.encoding  : Cp1252 os.arch  : x86 java.awt.graphicsenv  : sun.awt.Win32GraphicsEnvironment ibm.signalhandling.rs  : false java.ext.dirs  : C:\Prods\Java16IBMSDK\jre\lib\ext user.dir  : C:\Users\locke\workspace\org.eclipse.paho.sample.mqttv3app line.separator  :

java.vm.name  : IBM J9 VM com.ibm.oti.shared.enabled  : false com.ibm.vm.bitmode  : 32 jxe.lowest.romimage.version : 15 file.encoding  : Cp1252 com.ibm.oti.configuration  : scar com.ibm.oti.jcl.build  : 20120801_2119 java.specification.version  : 1.6

==============================

</pre>

How Logging and Trace is Implemented

Logging and Trace Interface =

The Java Client is instrumented to write log and trace records at pertinent points. The log and trace records are written to a “pluggable” log interface.

package org.eclipse.paho.client.mqttv3.logging; public interface Logger

It enables log messages to be at different levels depending on the severity of the event:-

public static final int	SEVERE	= 1;
	public static final int	WARNING	= 2;
	public static final int	INFO		= 3;
	public static final int	CONFIG	= 4;
	public static final int	FINE		= 5;
	public static final int	FINER		= 6;
	public static final int	FINEST	= 7;

There are a set of corresponding methods that enable an application to write log records at each level. For instance the methods to write severe records are:

/**
	 * Log a message, specifying source class and method, 
 * with if the logger is enabled for the given 
 * message level.
	 */
public void severe(String sourceClass, String sourceMethod,
 String msg);

/**
	 * Log a message, specifying source class and method, 
 * with an array of object arguments 
 * if the logger is enabled for the given 
 * message level.
	 */
public void severe(String sourceClass, String sourceMethod,
 			String msg, Object[] inserts);

	/**
	 * Log a message, specifying source class and method, 
 * with an array of object arguments and a throwable, 
 * if the logger is enabled for the given 
 * message level.
	 */
public void severe(String sourceClass, String sourceMethod,
    String msg, Object[] inserts, Throwable thrown);


Logging and Trace Default Implementation

A default implementation of the logger interface is provided that uses the standard Java logging interface (JSR47) – java.util.logging. The implementation is provided by:

package org.eclipse.paho.client.mqttv3.logging;
public class JSR47Logger implements Logger

The JSR47 logging facility is very flexible in how and what it captures. See the How to use log and trace facility for more details.

How the Logger is loaded A factory is used to load a logger at runtime: package org.eclipse.paho.client.mqttv3.logging; public class LoggerFactory By default it will load the default logger – JSR47Logger.

In order to load a different logger the static variable: private static String overrideloggerClassName in LoggerFactory must be set to the fully qualified class name of the Logger implementation that is to be used. This must be set before the MQTT client is instantiated.

Adding new trace and log events

Each Log and trace message:

  • Has an identifier that is unique across the Paho client. If the message is removed the message identifier should not be reused.
  • Can be translated to other languages
  • Can contain inserts

In order to make the code readable and to make maintenance of messages simpler, English log messages are embedded in the source code before the statement that writes the log record. Below is an example from the disconnect method in MqttAsyncClient.

	// @TRACE 104=> quiesceTimeout={0} userContext={1} callback={2}
	log.fine(className,methodName, "104",
new Object[]{ new Long(quiesceTimeout), 
  userContext, 
  callback
});

The comment contains:

  • A unique identifier of “104” (The identifier must be unique across the Paho client )
  • The English message that will be output e.g “quiesceTimeout=”…
  • Inserts that will be replaced dynamically at runtime: {0} will be replaced by the quiesceTimeout value

The corresponding log statement must contain:

  • A log method that is defined in the Logger Interface in the example fine.

The class name and method name of the method the log entry is in.

  • A unique identifier that must match the identifier in the comment
  • A set of inserts that match the substitution parameters in the comment. The inserts must be in the same sequence as in the comment.

Building the log message files

The log messages that are embedded in the source must be extracted into a resource file that is then used at runtime. Use

class LogMessageExtractor

in package org.eclipse.paho.client.mqttv3.internal.traceformat to achieve this.

The class can be run directly from inside of Eclipse and will create / replace file

logcat.properties in package org.eclipse.paho.client.mqttv3.internal.nls

The utility to extract messages is run whenever a change to log or trace is made. The resulting logcat properties file must then be checked into the library system.