Jump to: navigation, search

Paho/Log and Debug in the Java client

A Guide 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.  
# It is possible to set more granular trace on a per class basis e.g.

# 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

# --- FileHandler ---
# Override of global logging level

# 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 

# Limiting size of output file in bytes:

# Number of output files to cycle through, by appending an
# integer to the base file name:

# Style of output (Simple or XML):

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.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

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), 

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.