Notice: This Wiki is now read only and edits are no longer possible. Please see: https://gitlab.eclipse.org/eclipsefdn/helpdesk/-/wikis/Wiki-shutdown-plan for the plan.
Paho/Log and Debug in the Java client
Contents
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. 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 ==========================================
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.