TNT4J – Track and Tracing API for Java

TNT4J is about tracking and tracing applications, activities, transactions, behavior and performance via an easy to use API that behaves much like a logging framework.

Why track and trace your applications?

Several key features make TNT4J a prime choice for your java application:

Quick Examples

Here is a simple example of using TNT4J:

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

Below is an example of using correlator and a relative class marker to locate caller’s method call on the stack – $my.package.myclass:0. This marker will resolve to the caller’s method name above all the calls that start with $my.package.myclass.

TrackingLogger logger = TrackingLogger.getInstance(this.getClass());
try {
   ...
} catch (Exception e) {
   logger.tnt(OpLevel.ERROR, "$my.package.myclass:0", myCorrelator, 
   	"Failed to process request={0}", request_id, ex);
}

Consolidate all conditional logging checks into a single listener. Why call isDebugEnabled() before each log entry?

TrackingLogger logger = TrackingLogger.getInstance(this.getClass());
logger.addSinkEventFilter(new MyEventFilter(logger));
try {
   logger.debug("My debug message {0}, {1}", arg0, arg1); // no need to gate this call
   ...
} catch (Exception e) {
   logger.error("Failed to process request={0}", request_id, ex);
}

class MyEventFilter implements SinkEventFilter {
	TaskLogger logger;

	MyEventFilter(TaskLogger lg) {
		logger = lg;
	}

	@Override
	public boolean filter(EventSink sink, TrackingEvent event) {
		return logger.isSet(event.getSeverity(), "myappl.token");
	}

	@Override
	public boolean filter(EventSink sink, TrackingActivity activity) {
		return logger.isSet(activity.getSeverity(), "myappl.token");
	}

	@Override
	public boolean filter(EventSink sink, Snapshot snapshot) {
		return logger.isSet(snapshot.getSeverity(), "myappl.token");
	}
	
	@Override
	public boolean filter(EventSink sink, long ttl, Source src, OpLevel level, String msg, Object... args) {
		return logger.isSet(level, "myappl.token");
	}
}

Embed TNT4J into your application and realize the benefits in a matter if minutes. TNT4J can take advantage of other lower level logging frameworks such as slf4j, log4j. Default TNT4J binding is based on slf4j.

Stream over MQTT

Stream your events over MQTT using com.jkoolcloud.tnt4j.logger.mqtt.MqttEventSinkFactory event sink factory. Configure event sink in tnt4j.properties as follows:

...
event.sink.factory: com.jkoolcloud.tnt4j.logger.mqtt.MqttEventSinkFactory
event.sink.factory.mqtt-server-url: tcp://localhost:1883
event.sink.factory.mqtt-topic: tnt4jStream
event.sink.factory.mqtt-user: mqtt-user
event.sink.factory.mqtt-pwd: mqtt-pwd
...

SLF4J Event Sink Integration

TNT4J provides SLF4J event sink implementation via com.jkoolcloud.tnt4j.logger.slf4j.SLF4JEventSinkFactory event sink factory. Other logging frameworks can be supported by implementing EventSinkFactory & EventSink interfaces. TNT4J default integration is with SLF4J/SimpleLogger.

All TNT4J messages can be routed via a SLF4J event sink and therefore can take advantage of the underlying logging frameworks supported by SLF4J.

Developers may also enrich event messages and pass context to TNT4J using hash tag enrichment scheme. Hash tags are used to decorate event messages with important meta data about each log message. This meta data is used to generate TNT4J tracking events:

logger.info("Starting a tnt4j activity #beg=Test, #app=" + Log4JTest.class.getName());
logger.warn("First log message #app=" + Log4JTest.class.getName() + ", #msg='1 Test warning message'");
logger.error("Second log message #app=" + Log4JTest.class.getName() + ", #msg='2 Test error message'", new Exception("test exception"));
logger.info("Ending a tnt4j activity #end=Test, #app=" + Log4JTest.class.getName() + " #%i/order-no=" + orderNo  + " #%d:currency/amount=" + amount);

Above example groups messages between first and last into a related logical collection called Activity. Activity is a collection of logically related events/messages. Hash tags #beg, #end are used to demarcate activity boundaries. This method also supports nested activities.

User defined fields can be reported using #[data-type][:value-type]/your-metric-name=your-value convention (e.g. #%i/order-no=62627 or #%d:currency/amount=50.45). TNT4JAppender supports the following optional data-type qualifiers:

	%i/ -- integer
	%l/ -- long
	%d/ -- double
	%f/ -- float
	%b/ -- boolean
	%n/ -- number
	%s/ -- string

All value-type qualifiers are defined in com.jkoolcloud.tnt4j.core.ValueTypes. Examples:

	currency 	-- generic currency
	flag 		-- boolean flag
	age 		-- age in time units
	guid 		-- globally unique identifier
	guage		-- numeric gauge
	counter		-- numeric counter
	percent		-- percent
	timestamp	-- timestamp
	addr 		-- generic address

Not specifying a qualifier defaults to auto detection of type by TNT4JAppender. First number qualifier is tested and defaults to string if the test fails (e.g. #order-no=62627).

Performance

No need to concatenate messages before logging. String concatenation is expensive especially in loops. Simply log using message patterns as follows and TNT4J will resolve the message only if it actually gets logged:

logger.debug("My message {0}, {1}, {2}", arg0, arg1, arg3);

TNT4J enhances logging performance by supporting asynchronous pooled logging, which delegates logging to a dedicated thread pool. Use BufferedEventSinkFactory in your tnt4.properties configuration to enable this feature. See example below:

...
event.sink.factory: com.jkoolcloud.tnt4j.sink.BufferedEventSinkFactory
event.sink.factory.PooledLoggerFactory: com.jkoolcloud.tnt4j.sink.PooledLoggerFactoryImpl
event.sink.factory.EventSinkFactory: com.jkoolcloud.tnt4j.logger.slf4j.SLF4JEventSinkFactory
...

Simplicity & Clean Code

No need to check for isDebugEnabled() before logging messages. Just register your own SinkEventFilter and consolidate all checking into a single listener.

logger.addSinkEventFilter(new MyLogFilter()); 
...
logger.debug("My message {0}, {1}, {2}", arg0, arg1, arg2);

All conditional logging can be consolidated into a single listener object.

Flexible Filtering

Filter out not only based on category/severity (as slf4j), but also based on performance objectives. Example: log events only if their elapsed time or wait times are greater than a ceratin value. TNT4J allows users to register filters within tnt4j.properties without changing application code. Create your own filters which would allow you to filter events out based on user defined criteria and inject filters using tnt4j.properties. See tnt4j.properties and com.jkoolcloud.tnt4j.filters.EventLevelTimeFilter for details. Register filters via declarations in tnt4j.properties or in your application by creating your own event filter.

logger.addSinkEventFilter(new ThresholdEventFilter(OpLevel.WARNING));

Below is an example of an event sink filter ThresholdEventFilter which must implement SinkEventFilter interface.

public class ThresholdEventFilter implements SinkEventFilter {
	OpLevel threshold = OpLevel.INFO;

	public ThresholdEventFilter() {
	}

	public ThresholdEventFilter(OpLevel level) {
		this.threshold = level;
	}

	@Override
	public boolean filter(EventSink sink, TrackingEvent event) {
		return (event.getSeverity().ordinal() >= threshold.ordinal()) && sink.isSet(event.getSeverity());
	}

	@Override
	public boolean filter(EventSink sink, TrackingActivity activity) {
		return (activity.getSeverity().ordinal() >= threshold.ordinal()) && sink.isSet(activity.getSeverity());
	}

	@Override
	public boolean filter(EventSink sink, Snapshot snapshot) {
		return (snapshot.getSeverity().ordinal() >= threshold.ordinal()) && sink.isSet(snapshot.getSeverity());
	}

	@Override
	public boolean filter(EventSink sink, long ttl, Source source, OpLevel level, String msg, Object... args) {
		return (level.ordinal() >= threshold.ordinal()) && sink.isSet(level);
	}
}

Granular conditional logging

Log only what matters. Increase performance of your applications by decreasing the amount of logging your application produces while increasing the relevance and quality of the output.

if (logger.isSet(OpLevel.DEBUG)) {
	logger.debug("My message {0}, {1}, {2}", arg0, arg1, arg2);
}
if (logger.isSet(OpLevel.DEBUG, "myapp.mykey", myvalue)) {
	logger.debug("My message {0}, {1}, my.value={2}", arg0, arg1, myvalue);
}

Checking a global debug flag is not granular enough for most applications. Many java apps require granular tracking to log only what matters based on specific context. Consolidate conditional checks (logger.isSet()) into SinkEventFilter implementation and register with the tracker instance.

logger.addSinkEventFilter(new MyLogFilter());

Share logging context across apps

Pass logging context across threads or applications.

logger.set(OpLevel.DEBUG, "myapp.mykey", myvalue);

Imagine writing an application that has to pass tracking context/flag to applications downstream, how would you do that? TNT4J lets you set and get conditional variables within and across application boundaries.

Set and check tracking context as follows (track all requests matching a specific zip code only):

// set level, key & value pair
logger.set(OpLevel.DEBUG, "zip-code", trackZipCode);
..
..
// check for sev, key & value pair match
String zipCode = request.getZipCode();  // example request containing a zip code
if (logger.isSet(OpLevel.DEBUG, "zip-code", zipCode)) {
	// your conditional logic here
}

State logging

Log application state to improve diagnostics of performance, resource utilization and other tough problems which are difficult to trace using standard event logging techniques. Simply register your state dump provider (see DumpProvider interface) and export state variables specific to you application. Dump providers can be called on VM shutdown or on demand.

Generate application dump on demand.

// register your dump provider
TrackingLogger.addDumpProvider(new MyDumpProvider());
...
TrackingLogger.dumpState();

Measurements & Metrics

TNT4J is not just about logging messages, it is also about measurements and metrics such as response time, CPU, memory, block/wait times as well as user defined metrics. TNT4J lets you report metrics at the time of the logged event. Below is an example of creating a snapshot (collection of metrics) and attaching it to an activity:

// post processing of activity: enrich activity with application metrics
TrackingLogger logger = TrackingLogger.getInstance(this.getClass());
TrackingActivity activity = logger.newActivity(OpLevel.INFO, "Order");
...
PropertySnapshot snapshot = logger.newSnapshot("Order", "Payment");
snapshot.add("order-no", orderNo, ValueTypes.VALUE_TYPE_ID);
snapshot.add("order-amount", orderAmount, ValueTypes.VALUE_TYPE_CURRENCY);
activity.add(snapshot); // add property snapshot associated with this activity
...
logger.tnt(activity); // report activity and associated snapshots as a single entity

A Snapshot is a collection of name, value pairs called Property. Each Property can be further qualified with a value type defined in ValueTypes class.

Below is an example of reporting a snapshot:

// post processing of activity: enrich activity with application metrics
TrackingLogger logger = TrackingLogger.getInstance(this.getClass());
TrackingActivity activity = logger.newActivity(OpLevel.INFO, "Order");
...
PropertySnapshot snapshot = logger.newSnapshot("Order", "Payment");
snapshot.add("order-no", orderNo, ValueTypes.VALUE_TYPE_ID);
snapshot.add("order-amount", orderAmount, ValueTypes.VALUE_TYPE_CURRENCY);
activity.tnt(snapshot); // add and report property snapshot associated with this activity

Below is an example of reporting standalone snapshot:

// post processing of activity: enrich activity with application metrics
TrackingLogger logger = TrackingLogger.getInstance(this.getClass());
...
PropertySnapshot snapshot = logger.newSnapshot("Order", "Payment");
snapshot.add("order-no", orderNo, ValueTypes.VALUE_TYPE_ID);
snapshot.add("order-amount", orderAmount, ValueTypes.VALUE_TYPE_CURRENCY);
logger.tnt(snapshot); // report a property snapshot

Correlation, Topology, Time Synchronization

Developers can relate events by grouping them into activities (activity is a collection of related events and sub-activities) or passing context – correlator(s). Activity grouping and correlators create connectivity between events across thread, applications, server, runtime, location boundaries. TNT4J allows attachment of correlators when reporting tracking events: see TrackingLogger.tnt(..) calls for details. The API also allows relating tracking events across application and runtime boundaries using the same mechanism.

TrackingLogger.tnt(..) also allows developers to specify the flow of messages using OpType.SEND and OpType.RECEIVE modifiers. These modifiers let developers specify message flow & direction. This is especially useful for applications that pass information via network, middleware, messaging or any other communication mechanism. Tracking events with such modifiers specify graph/topology information required for root cause analysis as well as visualization of message flow.

Below is an example of a sender application:

// post processing of activity: enrich activity with application metrics
TrackingLogger logger = TrackingLogger.getInstance(this.getClass());

// report sending an order with a specific correlator (order_id)
logger.tnt(OpLevel.INFO, OpType.SEND, "SendOrder", order_id, 
	elasped_time, "Sending order to={0}", destination);
// sending logic
....
....

Here is an example of a receiver application:

// post processing of activity: enrich activity with application metrics
TrackingLogger logger = TrackingLogger.getInstance(this.getClass());
...
// report received an order with a specific correlator (order_id)
logger.tnt(OpLevel.INFO, OpType.RECEIVE, "ReceiveOrder", order_id,
	elasped_time, "Received order from={0}", source);

NOTE: TNT4J uses NTP natively to synchronize times across servers to enable cross server event correlation in time. To enable NTP time synchronization define java property -Dtnt4j.time.server=ntp-server:123.

TIP: Developers should use TimeServer.currentTimeMillis() instead of System.currentTimeMillis() to obtain time adjusted to NTP time. TNT4J also maintains a microsecond resolution clock using Useconds.CURRENT.get() which returns the number of microseconds between the current time and midnight, January 1, 1970 UTC (NTP adjusted). TNT4J automatically measures and adjusts clock drift between NTP, System.currentTimeMillis() and System.nanoTime() clocks to ensure accurate microsecond precision/accuracy timing spanning VMs, devices, servers, geo locations.

Tracking Associations

TNT4J allows developers to track associations between sources. Source is a logical definition of an entity such as application, server, network, geo location. Here is an example of a source: APP=WebAppl#SERVER=MYSERVER#DATACENTER=DC1#GEOADDR=New York, which means application WebAppl deployed on server MYSERVER, located on datacenter DC1, located in New York. Say you want track an association between 2 applications that exchange data, where one application sends data to another:

// post processing of activity: enrich activity with application metrics
TrackingLogger logger = TrackingLogger.getInstance(this.getClass());
...
TrackingEvent event = logger.newEvent(...);
// create an association between 2 applications
event.relate2(DefaultSourceFactory.getInstance().newFromFQN("APP=Orders#SERVER=HOST1#DATACENTER=DC1#GEOADDR=New York, NY"),
	DefaultSourceFactory.getInstance().newFromFQN("APP=Billing#SERVER=HOST2#DATACENTER=DC1#GEOADDR=London, UK",
	OpType.SEND);
logger.tnt(event);

The snippet above creates the following asssociation: Orders->SEND->Billing, which expresses flow between Orders and Billing applications, where Orders and Billing are nodes and SEND is an edge.

Logging Statistics

TNT4J keeps detailed statistics about logging activities. Each logger instance maintains counts of logged events, messages, errors, overhead in usec and more. Do you know the overhead of your logging framework on your application?

Obtain a map of all available key/value pairs:

Map<String, Long> stats = logger.getStats();
System.out.println("Logger stats: " + stats);
...
System.out.println("Resetting logger stats");
logger.resetStats();

Obtain metrics for all available trackers:

List<TrackingLogger> loggers = TrackingLogger.getAllTrackers();
for (TrackingLogger lg: loggers) {
	Map<String, Long> stats = lg.getStats();
	printStats(stats); // your call to print out tracker statistics
	...
}

TNT4J keeps track of stack traces for all TrackingLogger allocations. Below is an example of how to get stack frames for a set of TrackingLogger instances:

// obtain all available tracker instances
List<TrackingLogger> loggers = TrackingLogger.getAllTrackers();
for (TrackingLogger lg: loggers) {
	StackTraceElement[] stack = TrackingLogger.getTrackerStackTrace(lg);
	Utils.printStackTrace("Tracker stack trace", stack, System.out);
	...
}

About TNT4J

Track and Trace 4 Java API, Application logging framework for correlation, diagnostics and tracking of application activities within and across multiple applications, runtime, servers, geo locations. This API is specifically designed to troubleshoot distributed, concurrent, multi-threaded, composite applications and includes activity correlation, application state dumps, performance and user defined metrics.

Here is short list of TNT4J features:

See TNT4J tutorial (http://www.slideshare.net/AlbertMavashev/open-source-application-behavior-tnt4j-tutorial) See Getting Started (https://github.com/Nastel/TNT4J/wiki/Getting-Started) for quick reference on TNT4J. Wiki is available at https://github.com/Nastel/TNT4J/wiki

TNT4J Mission

TNT4J Concepts

TNT4J is fully plug-in and play tracking, tracing and logging framework that consists of the following basic constructs:

How to Build TNT4J

Requirements

TNT4J depends on the following external packages:

To build TNT4J:

Known Projects Using TNT4J