Tag Archives: logging support

Javascript remote logging with Log4j & log4js-ext

I released log4js-ext several days ago, and I’m planning to add remote logging support. I would love to consolidate client and server side logging at the server to help me debug complex browser/server app interactions.

The first logging system I would like to support is Log4j, with slf4j a close second.

Log4js-ext remote logger sends information that I will gather in my RemoteLoggingEvent Java class, as follows:

public class RemoteLoggingEvent {
   String level;
   String category;
   String formattedMessage;
   String ndc;
   long   timeMillis;
   boolean hasLoggedObject;
   String formattedLoggedObject;
   String formattedTime;
   // ************************************************************************
   // javascript side information ommitted on purpose because there is not
   // much the server can do with this raw data
   // ************************************************************************
   // Date time;
   // String message;
   // Object[] formatParams;
   // Object loggedObject;
   // int levelLevel;

   // ...

My first thought was to simply redirect the data to a Log4j logger, much like this:

Logger logger = Logger.getLogger(remoteLog.getCategory());
logger.log( getPriority(remoteLog.getLevel()), remoteLog.getMessage() );

This works, but there is a *BIG* but. The logged timestamp will correspond to the moment when we called the log method at the server, not the client side timestamp.

Due to the asynchronous nature of web requests, it might well happen that two logs A and B that were created in that order at the client could be received in the server in B, A order. Then the call to logger.log will generate slightly different timestamps, telling lies about the ordering of client-side actions. Really bad for debugging purposes.

It is important to note that I’m implementing remote logging with an eye to help debug during development. During development we tend to run the client an the remote app in the same computer, and then we have the guarantee that the client and server side timestamps are coherent. In that scenario, using the client generated log timestamps will be a real boon, providing correct sequencing information.

That can be so useful for debugging that I decided to byspass the Log4j loggers and log directly against their appenders, which have a nice doAppend method that receives a LoggingEvent accepting not only messages, but a timestamp, an NDC, etc.

The following code will create a LoggingEvent based on the remote information provided to the server in my own RemoteLoggingEvent object:

private static LoggingEvent adaptLoggingEvent(RemoteLoggingEvent log, 
      Logger logger) 
   long millis = log.getTimeMillis();
   // A configuration setting very useful during development
      millis = (new Date()).getTime();
   String message = getMessage(log);
   ThrowableInformation exceptionInfo = null;
   if( log.getException() != null ) {
      exceptionInfo = new ThrowableInformation(log.getException());
   LoggingEvent le = new LoggingEvent(
         log.getCategory(), logger, millis, getLevel(log.getLevel()),
         message, log.getThreadName(!APPEND_NDC_AT_THREAD_NAME_END), 
         log.getNdc(), null, null );

   return le;

Now, the problem is Log4j loggers do log following certain rules, and calling its appenders doAppend method would bypass them all.

To follow the rules we have to take into account several things:

  • We have to log to appenders *only* when the log level/priority (error, warn, info, etc.) is greater than the logger priority.

  • We need to write to the logger appenders, and then to all parent appenders, and to the parent parent’s appenders, and so on. But *only* if the current logger additivity is set to true, else the only appenders I have to write to are those directly attached to the logger (maybe none).

Here is the code that takes all of this into account:

public void log(RemoteLoggingEvent log) {
   Logger logger = getLocalLogger(log);
   LoggingEvent le = adaptLoggingEvent(log, logger);
   Category cat = logger;
   // Because we are not logging through the Logger interface, we 
   // need to take care of logging only when level is ok
   if( le.getLevel().isGreaterOrEqual(cat.getEffectiveLevel())) {
      // We traverse all appenders upwards -unless additivity is set to false
      // This simulates calling Logger.log, which we don't call because 
      // it would create the wrong timestamp, the wrong 'thread', etc. 😦
      while( cat != null ) {
         @SuppressWarnings({"unchecked" })
         Enumeration<Appender> appenders = cat.getAllAppenders();
         while( appenders.hasMoreElements()) {
            Appender appender = appenders.nextElement();
         if( cat.getAdditivity()) {
            cat = cat.getParent();
          else {
             cat = null;

I wanted to get the same level of support for slf4j, but I just found that there is not an easy way to log timestamps and other additional information. In the end I just wrote the slf4j adapter by calling Logger.info, error, etc., with the corresponding timestamps being server generated.

This will make into log4js-ext in the following weeks, probably using my own DirectJNgine to perform remote communication, so that I can benefit from the built-in support for batching, etc.