Runtime logging with Log4j & Spring

I've blogged before about logging but it has been always about programming or AOP. I wanted today to talk a little about a good way to handle logging during runtime. A correct approach to logging during runtime crucial for a couple of reasons, first it's probably the last resort on production servers where debugging (or testing in general) is not possible and second, it greatly affects performance. So the issues to consider are:

• Change logging levels during runtime
• Adding runtime information to log entries
• Visualize remote log files

As of today, no application should be deployed to a production machine before having this topics resolved.

Let's start with our main concern, performance. Any written software today contains several thousand log calls easily. A big chunk of the total code are traces in fact. This means that a poor logging solution (System.out is one) degrades the overall behavior of the application. A good solution is achieved just by understanding when and what to log. Any logging framework (and so does Log4j) includes the ability to bypass log messages based on a configured level. The minimum level in a production machine should be set at least to WARNING. But even if the logging framework is going to skip the message a performance penalty can be hidden during message construction. This is also easily solved testing the need programmatically using the provided isXXXEnabled() methods before any log invocation.

Using those techniques the underlying logging structure will be as fast as it can be but, unfortunately, it won't provide much information when an error occurs. Of course, that has to be managed. The easiest way is to be able to change the configuration online. That, in logging terms, means changing the level of an individual or a group of loggers.

Doing it depends on the actual logging library so I'm posting an example that works with Log4j. The first thing to achieve is access the loggers to be able to modify them. This is not possible out-of-the-box so a workaround is in order. We need access to the log4j.properties file. An important side note is in order here, use just one (common) configuration file independent of the number of (web) applications or other modules deployed (of course, inside an EAR). Otherwise, it can quickly become a nightmare to maintain.

<util:properties id="log4jProperties" location="classpath:log4j.properties"/>

<bean id="logManager" class="es.internna.logging.LogManagerImpl">
   <property name="loggingProperties" ref="log4jProperties" />
</bean>

With it loaded in memory it can be easily modified:

public void changeLoggingLevel(String logger, int level) {
   switch (level) {
      case 1: loggingProperties.setProperty(logger, "INFO"); break;
      case 2: loggingProperties.setProperty(logger, "WARN"); break;
      case 3: loggingProperties.setProperty(logger, "ERROR"); break;
      default: loggingProperties.setProperty(logger, "DEBUG"); break;
   }
}

When all the changes are applied the logging system (not the server!) has to be restarted

public void resetConfiguration() {
   org.apache.log4j.LogManager.resetConfiguration();
   org.apache.log4j.PropertyConfigurator.configure(loggingProperties);
}

Once done, automatically, all the previously removed messages will start to pop in the console and/or log files.

Now that our first tasks is completed we can focus on the others. The next will be adding environment information to the log entries, for example, the current user or the name of the host. A lot of programmers have invented ad hoc solutions to this problem. This is usually incorrect as a standard solution is provided using the Nested Diagnostic Context. It's main function is to distinguish loggings from separate sources. To do it, it basically uses the thread context to store some information that can be later flushed with a log entry using a the %x layout pattern. Since Spring 2.1 a new nested diagnostic context web request interceptor exists making our task even easier.

Finally, just one task stands unresolved. There are serveral tools that provide a graphical user interface to geenrated log files (see Chainsaw for example) but nothing exists (that I know of) for web viewing. After working extensively with Glassfish, one of the things I like more is the log viewer it packs. Directly extracting the code from is very simple (well, it's Opesn Source) but it doesn't suit every project (it uses JSF for example). An even simpler solution is to code a parser and a JSP to show the results (this can be complicated later as much as wanted, for example, I use AJAX to update the page). I will show the core classes:

public class LogEntry {

   SimpleDateFormat formatter = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss,SSS");

   private long index;
   private Date date;
   private String level;
   private String logger;
   private String message;
   ...

   LogEntry (String line, long index) {
      if (line != null) {
         this.index = index;
         StringTokenizer tokenizer = new StringTokenizer(line, "|");
         setDate(tokenizer.nextToken());
         setLevel(tokenizer.nextToken());
         ...
      }
   }
}

public class LogFileParser implements LogParser {

   private String RECORD_BEGIN = "<##";
   private String RECORD_END = "##>";

   LogEntry readRecord(BufferedReader reader, long index) throws IOException {
      String line = null;
      boolean recordFinished = false;
      StringBuilder builder = new StringBuilder();
      do {
         line = reader.readLine();
         if (line != null) {
            if ((builder.length() <= 3) & (!line.startsWith(RECORD_BEGIN)))
               continue;
            if (line.endsWith(RECORD_END)) recordFinished = true;
            builder.append(line.replace(RECORD_BEGIN, "")
               .replace(RECORD_END, ""));
         }
      } while(!recordFinished & (line != null));
      LogEntry entry = null;
      line = builder.toString();
      if (line.length() > 0) entry = new LogEntry(line, index);
      return entry;
   }

   public List getLogEntries(long startingRecord, long maxRecords) {
      long index = 0;
      List results = new ArrayList();
      ...
      for (index = 0; index < startingRecord - 1; index++)
         readRecord(reader, 0);
      while (index < startingRecord + maxRecords - 1) {
         LogEntry entry = readRecord(reader, index);
         if (entry != null) results.add(entry);
         index++;
      }
      return results;
   }
}

I hope the code is clear (unfortunately the IO operations imply a lot of try-catch blocks in the middle) but I'll explain it a little. The LogEntry class just stores the values we want to show. A log entry is bounded by RECORD_BEGIN / RECORD_END tags. Each part of the record entry is separated by a pipe (|) char (by design). The LogParser just reads the file and creates as many LogEntry objects as needed. Of course this needs a specific log file configuration.

log4j.appender.rolling=org.apache.log4j.RollingFileAppender
log4j.appender.rolling.File=/tmp/server.log
log4j.appender.rolling.MaxFileSize=1024KB
log4j.appender.rolling.MaxBackupIndex=10
log4j.appender.rolling.layout=org.apache.log4j.PatternLayout
log4j.appender.rolling.layout.ConversionPattern=<##%d|%p|%x|%c|%m##>%n

Showing everything in a JSP is trivial. I will (again) refer to the Glassfish console to get a visually appealing design for the Log Viewer.

And, that's all. Following those simple steps ensure that a consistent methodology to treat logging during runtime is enforced and the results are obvious: better performance, better information on the context where errors happened, a powerful viewer and the possibility to deploy everything packaged in a separate webapp. And, by the way, it offers a professional touch to the result.

Fullscreen with Firefox

In a public web environment is not advisable to resize the user's current window without permission. Let alone forcing full screen mode. That's probably the reason why Firefox does not allow it at all. Unfortunately that's a handicap when developing for more controlled environments. To solve it Firefox offers a powerful tool in extension development. As you see along the article it's really simple to create a custom extension that, once installed in the client machine, it will change to fullscreen on certain pages.

There are a lot of tutorials along the web that explain step by step how to build an extension. Check here or here, for example. I will focus more on creating a specific fullscreen solution than a custom extension during the article. Please refer to those tutorials if a more detailed view is needed.

As our extension does not have any widgets (visual elements) or texts the gross of the work is skipped. Great! In practice, all we need to do is

• Create an overlay to chrome://browser/content/browser.xul
• Add the javascript event handlers
• Package everything as a XPI file

Once created the folder structure (we just need a project folder and a content subfolder), the first step is to create the overlay. This is done creating two files

//chrome.manifest
content gofs content/
overlay chrome://browser/content/browser.xul chrome://gofs/content/gofs.xul

//content/gofs.xul
<?xml version="1.0"?>
<overlay id="gofs-overlay"
  xmlns="http://www.mozilla.org/keymaster/gatekeeper/there.is.only.xul">
   <script src="gofs.js" />
</overlay>

The code basically does nothing. It just declares an overlay and includes a js file with the meat and potatoes

function gofullscreen(event)
{
   function resizeToFullscreen(event)
   {
      var theDocument = event.originalTarget;
      if (theDocument.body.getAttribute('fullscreen')) BrowserFullScreen();
   }
   window.removeEventListener("load", gofullscreen, false);
   window.document.getElementById("content")
         .addEventListener("DOMContentLoaded", resizeToFullscreen, false);
}
window.addEventListener("load", gofullscreen, false);

The code above is really simple. It just uses a couple of events fired on page load. Then it checks for a fullscreen attribute on the body tag. If it finds it it calls the BrowserFullScreen function (provided by Firefox) to handle change the screen mode. And that's really all, to test it create a simple HTML page like this

<hmtl>
   <body fullscreen="yes">hi!</body>
</html>

For the ones interested I have packaged a working example at Internna's repository.