Getting Started with TNT4J: Advanced Java Diagnostics and Monitoring

TNT4J is an easy-to-use Java diagnostics library, designed to help developers deliver better-quality code, especially applications that are multi-threaded, concurrent and use external services. Logging simple messages is no longer sufficient to understand application behavior (or misbehavior).

TrackingConfig config = DefaultConfigFactory.getInstance().getConfig("com.myco.appl.Receiver").build();
TrackingLogger tracker = TrackingLogger.getInstance(config); // register and obtain Tracker logger instance

Developers may also obtain tracker instances using an object class.

TrackingLogger tracker = TrackingLogger.getInstance(this.getClass()); // register and obtain Tracker logger instance

DefaultConfigFactory.getInstance().getConfig("com.myco.appl.Receiver").build() triggers tnt4j configuration loaded from tnt4j.properties file for the specified source (com.myco.appl.Receiver).

Below is a simple try/catch block that reports an error on exception.

TrackingLogger tracker = TrackingLogger.getInstance(this.getClass());
try {
   ...
} catch (Exception e) {
   tracker.error("Failed to process request={0}", request_id, ex);
}

Below is a simple try/catch block that reports a correlated error on exception. A correlated log message is a message related to something else such as a given correlator (request_id in this example). Correlated log messages are basically log messages decorated with a correlator. Multi-threaded applications can benefit from correlated log messages by simplifying relationships between application activities and the messages written to the underlying event sink (such as a log file).

TrackingLogger tracker = TrackingLogger.getInstance(this.getClass());
try {
   ...
} catch (Exception e) {
   tracker.tnt(OpLevel.ERROR, "ProcessRequest", correlator, "Failed to process request={0}", request_id, ex);
}

TrackingLogger.tnt(OpLevel.ERROR, "ProcessRequest", correlator, "Failed to process request", ex); has several key elements required for diagnostics and correlation especially across thread and application boundaries:

• Correlator - user-defined token that allows correlation of entries across thread, application boundaries. This token can be an order-id, trade-id, account-no or anything else that is relevant for application correlation.
• ProcessRequest - operation name which is a logical name assigned by the application to the activity that is being performed.

Activities are timed and correlated sets of events and sub-activities. Below is a simple example of how to create, start, stop activities.

TrackingConfig config = DefaultConfigFactory.getInstance().getConfig("com.myco.appl.name").build();
TrackingLogger tracker = TrackingLogger.getInstance(config); // register and obtain Tracker logger instance
TrackingActivity activity = tracker.newActivity(); // create a new application activity

// start activity
activity.start();

// create a tracking event
TrackingEvent event = tracker.newEvent(OpLevel.SUCCESS, "SQL-SELECT", corrid, "SQL customer lookup"); `
event.start(); // start timing a tracking event

try {
  ...
  ...
  event.stop(); // stop timing tracking event
} catch (SQLException e) {
  event.stop(e); // stop timing tracking event and associate an exception
  ...
} finally {
  activity.stop(); // stop application activity timing
  // track and trace tracking event, associate tracking event with the given activity
  activity.tnt(event); 
  tracker.tnt(activity); // track and trace application activity
}

TNT4J allows nesting of timed activities within a thread context. This means that TNT4J maintains a stack of nested activities per thread. An activity gets on the stack when it is started and comes off the when it is stopped. See the example below of two nested tracking activities:

TrackingConfig config = DefaultConfigFactory.getInstance().getConfig("com.myco.appl.name").build();
TrackingLogger tracker = TrackingLogger.getInstance(config); // register and obtain Tracker logger instance
TrackingActivity activity = tracker.newActivity(OpLevel.INFO, "OrderProcess"); // create a new application activity

// start activity
activity.start(); // start topmost activity
TrackingActivity subActivity = tracker.newActivity(OpLevel.INFO, "CreditCheck");
subActivity.start(); // this automatically relates activity and subActivity as parent and child
...
logger.getCurrentActivity(); // return topmost activity on the stack (sub-activity in this case)
...
subActivity.stop();
activity.stop(); // stopping the topmost activity before sub-activity will result in an exception
tracker.tnt(subActivity);
tracker.tnt(activity);

Developers may obtain the most current activity (topmost on the activity stack) using logger.getCurrentActivity() call -- which returns `subActivity' in the example above.

TrackingLogger allows developers to obtain activity stack trace. See example below:

...
TrackingActivity subActivity = tracker.newActivity(OpLevel.INFO, "CreditCheck");
StackTraceElement[] stackTrace = logger.getStackTrace(); 
Exception ex = new Exception("Activity trace");
ex.setStackTrace(stackTrace);
ex.printStackTrace(); // print out activity stack trace

The output may look something like this:

java.lang.Exception: Activity trace
        at com.nastel.TestApp.OrderProcess(6bab8ea2-a119-4265-8f84-a5313c632dec:74475e32-d7bb-4fdd-826d-b852db387bc1:15)
        at com.nastel.TestApp.CreditCheck(74475e32-d7bb-4fdd-826d-b852db387bc1:null:1)

The output consists of: source name (com.nastel.TestApp), activity name (OrderProcess) followed by (tracking-id:parent-id:child-count), where child-count shows how many id/correlators have been added to the activity.

Conditional tracking and tracing allows developers to log only events which are relevant based on application business logic. Instead of testing for isDebugEnabled(), TNT4J allows testing of user-defined tokens and using key/value patterns (regexp) matching to determine if in fact message needs to be logged. Here is a quick example that only logs a message when zipCode is enabled for DEBUG tracing. This approach can eliminate unwanted messages and allow message logging only for those that match the specified criteria.

Conditional logging can be done by wrapping logging calls with an isSet() if statement or by implementing and registering SinkEventFilter and consolidating all conditional checks such as isSet() into a single listener and therefore eliminate the need to gate each logging call.

TrackingLogger tracker = TrackingLogger.getInstance(this.getClass());
if (tracker.isSet(OpLevel.DEBUG, "myappl.location", zipCode)) {
    tracker.tnt(OpLevel.DEBUG, "locationRequest", zipCode, "Processing location request={0}", request_id);
}

Conditional tracking and tracing is especially useful when logging must be coordinated across multiple apps, run-times, devices, locations. Consider the case of two applications exchanging requests and you would like to log only specific requests across these two apps. TNT4J allows applications to check for such logging across apps and decide what is relevant and what is not. See example below:

// sender application sending a message to a receiver
Request request = new Request(request_id);
Sender.send(request); // example code showing sending of the request
if (tracker.isSet(OpeLevel.DEBUG, "myappl.request.id", request.getRequestId())) {
    tracker.tnt(OpLevel.DEBUG, "sendRequest", request.getRequestId(), "Processing location request={0}", request_id);
}

Below is a receiver/handler of the request:

// receiver application handling a request
Request request = Receiver.get();
if (tracker.isSet(OpLevel.DEBUG, "myappl.request.id", request.getRequestId())) {
    tracker.tnt(OpLevel.DEBUG, "getRequest", request.getRequestId(), "Processing location request={0}",  request.getRequestId());
}

Consider the fact that there may be thousands of requests being processed by multiple threads and such ability of TNT4J to track only what is needed becomes very valuable for the developer. TNT4J also allows setting trace levels and key/value pairs at run-time. Consider the following example where the sender decides to trace a specific request and pass this along to the receiver:

// sender application sending a message to a receiver
Request request = new Request(request_id);
tracker.set(OpeLevel.DEBUG, "myappl.request." + request.getRequestId()); // enable debug on a dynamic key for a specific request 
Sender.send(request); // example code showing sending of the request
if (tracker.isSet(OpLevel.DEBUG, "myappl.request." + request.getRequestId())) {
    tracker.tnt(OpLevel.DEBUG, "sendRequest", request.getRequestId(), "Processing location request={0}", request.getRequestId());
}

Below is an example of the receiver:

// receiver application handling a request
Request request = Receiver.get();
if (tracker.isSet(OpLevel.DEBUG, "myappl.request." + request.getRequestId())) {
    tracker.tnt(OpLevel.DEBUG, "getRequest", request.getRequestId(), "Processing location request={0}", request.getRequestId());
}

Application state, variables, and collection sizes are often needed to identify and diagnose application misbehavior. TNT4J allows applications to register and trigger application state dumps at run time. These dumps can be recorded into an underlying DumpSink (such as a file) on demand, trigger, or VM shutdown. Much like JVM dumps, application state dumps offer a view of the application's internal data structures, variables. Below is an example of using TNT4J state dump framework.

TrackingLogger.addDumpProvider(new MyDumpProvider("ApplDump", "ApplRuntime"));
TrackingLogger.addDumpProvider(new ObjectDumpProvider("ObjectDump", this));

class MyDumpProvider extends DefaultDumpProvider {
	
	private long startTime = 0;

	public MyDumpProvider(String name, String cat) {
	    super(name, cat);`
	    startTime = System.currentTimeMillis();
        }

	@Override
	public DumpCollection getDump() {
		Dump dump = new Dump("runtimeMetrics", this);
		dump.add("appl.start.time", new Date(startTime));
		dump.add("appl.elapsed.ms", (System.currentTimeMillis() - startTime));
		dump.add("appl.activity.count", TNT4JTest.activityCount);
		dump.add("appl.event.count", TNT4JTest.eventCount);
		return dump;
	}
}

Developers create classes that extend DefaultDumpProvider class and implement getDump() method that returns all key/value pairs for each variable to be dumped into a DumpSink. TNT4J offers a default object dump implementation ObjectDumpProvider which dumps out all internal object variables, collection sizes, memory (shallow and deep sizes). To enable variable memory calculations (shallow and deep) users must add -javaagent:tnt4j-api.jar command line option to the JVM arguments.

User-defined DumpProvider will get triggered when TrackingLogger.dumpState() method is called. Dumps can be generated automatically on VM shutdown when java property tnt4j.dump.provider.default=true is defined.

Applications calling TrackingLogger.getInstance() are configured via a default TNT4J configuration file (tnt4j.properties) where each source is defined. The location of the file can be defined by using tnt4j.config java property (e.g. -Dtnt4j.config=/opt/tnt4j/config/tnt4j.properties).

TrackingConfig config = DefaultConfigFactory.getInstance().getConfig(source).build();

TNT4J loads appropriate stanza that matches a given source name. The configuration contains all factories, formatters, selectors required to handle reported events, activities and dumps. Developers can provide their own implementation classes that override the behavior of default implementations. For example, Developers can create their own EventSinkFactory implementation and override using event.sink.factory property. Default EventSinkFactory is based on LOG4J (Log4JEventSinkFactory).

See default configuration below:

;Default tracking configuration for all sources (source: *),
;used only if no other stanza matches.`
{
 source: *
 tracker.factory: com.nastel.jkool.tnt4j.tracker.DefaultTrackerFactory
 dump.sink.factory: com.nastel.jkool.tnt4j.dump.DefaultDumpSinkFactory
 event.sink.factory: com.nastel.jkool.tnt4j.logger.Log4JEventSinkFactory
 event.formatter: com.nastel.jkool.tnt4j.format.JSONFormatter
 tracking.selector: com.nastel.jkool.tnt4j.selector.DefaultTrackingSelector
 tracking.selector.Repository: com.nastel.jkool.tnt4j.repository.FileTokenRepository
}

TNT4J conditional logging is based on severity/key/value combination instead of simplistic isDebugEnabled() test. Often, multi-threaded, concurrent applications require fine control over what is being logged. TNT4J conditional logging provides such facility. All tokens are defined in tnt4j-tokens.properties file. The location of the file can be specified using tnt4j-token.repository java property (e.g. -Dtnt4j-token.repository=/opt/tnt4j/tnt4j-tokens.properties).

See code example below:

if (tracker.isSet(OpeLevel.DEBUG, "myappl.location", zipCode)) {
    tracker.tnt(OpLevel.DEBUG, "locationRequest", zipCode, "Processing location request={0}", zipCode);
}

tracker.isSet(OpeLevel.DEBUG, "myappl.location", zipCode) test is verified against tnt4j-properties file which is loaded in memory and automatically synchronized with file contents. The file has the following general format:

key=severity[:value|regexp_value_pattern]

Below is an example file:

myappl.location=debug:11.*
myappl.correlator=warning:7637
myappl.order.id=error

Selector repository which defines the underlying storage for all sev/key/value tokens, file-based by default. Developers may create memory/cache-based token repositories by overriding TokenRepository implementation and supplying user-defined repository in the TNT4J configuration file using tracking.selector.Repository property.