JAMonAppender for Log4j

Some Problems with Log Files

Logs although useful, can be difficult to gather information from because:

The Log4j JAMonAppender solves these problems and more as it allows you to view a "summarized" version of your log, as well as the details of your most recent log messags, all via the sortable/searchable JAMon web application.

How does JAMon enhance Log4j?

Wouldn't it be nice to be able to do the following with your Log4j log files?

JAMon 2.6 introduces the Log4J JAMonAppender which allows you to do all of the above and more.

JAMon can also track realtime performance stats for SQL statements, and web pages (See http://www.jamonapi.com for more info). Because JAMon is an API it can easily be used in any application to monitor anything you desire via 3 basic methods: start/stop/add. In fact the JAMonAppender capabilities only took a couple days to implement by calling the JAMon 'MonitorFactory.add(...)' method. The rest of this document will further explain how Log4j users can benefit by using JAMon.

Here are some simple ways to understand how the JAMonAppender is both similar and different to logging to a file.

Background on Log4j Appenders

Log4j allows logging requests to be sent to multiple destinations including a console, file, database, or even a Socket Server. Log4j uses its Appender interface to accomplish this. Log4j allows developers to attach multiple Appenders to each Logger via a property file, XML configuration file or programmatically via the Log4J API.

Loggers call their attached Appenders every time the Loggers trace/debug/warn/info/error/fatal methods are called. The Appenders "append(LoggingEvent event)" method is called. An instance of the Log4j LoggingEvent object is passed to the Appender. The LoggingEvent has context information about the message being logged such as the "LoggerName", "Level", "ThreadName", "Message", "Date", and the "Exception Stacktrace" (In the case of "Exception" if the overloaded methods such as "logger.error(message, exception)" were called).

A Very Brief JAMon Primer

JAMon is based on a very simple concept of passing a key and a numeric value to an add method (MonitorFactory.add(key, numericValue)) and every time JAMon gets passed the same key it adds this value to the aggregated stats (hits/avg/min/max/total/...) already associated with this key. The key can represent anything (a SQL statement, a web page, in the case of Log4j a log message or anything else you can think of). The key should be 'relatively' distinct as every unique key will reside in memory (i.e. don't put a sequential counter or timestamp in your key). Below are some examples:

JAMon has a concept similar to Log4j's Appenders. They are called JAMonListeners. Everytime "MonitorFactory.add(...)" is called any registered JAMonListeners are notified and given the numeric value the method was passed as well as any contextual information. JAMon comes with some very useful JAMonListeners. One of them is the Log4jBufferListener which keeps the most recent N (configurable by Log4j or the JAMon web app) messages written to the monitor associated with the key.

See the following links for more info on JAMon and JAMonListeners.

Setting up the JAMonAppender - Default Behaviour

Setting up the JAMonAppender should only take a few minutes. The steps follow:

  1. Download JAMon and extract the following from the zip file.
  2. Put JAMon's jar file in your classpath (jamon-2.6.jar or higher for future releases)
  3. Install JAMon.war in your application, so you can view your Log4J statistics and log records.
  4. Configure Log4j to use JAMon's Appender. Example: log4j.rootLogger=DEBUG, jamonAppender
  5. The JAMon web application has a log4j.jsp which will run the JAMonAppender. You must have both JAMon and Log4j in your classpath for the page to work. You can access this page with the following link: http://yourhost:port/jamon/log4j.jsp

Note the JAMonAppender has useful default behaviour and need not have any properties set. By default JAMon keeps summary stats of how many times each of the different logging methods associated with the various methods are called (trace/debug/warn/info/error/fatal). Each of these correspond to a label in the JAMon report of the format 'com.jamonapi.log4j.JAMonAppender.LEVEL' where LEVEL is replaced by one of the Levels such as DEBUG. The report indicates that log methods associated with each of the different levels were called 15,000 times. The "LastAccess" column indicates when the method associated with the JAMon label was last called. Most of the other columns have no real meaning to Log4j, as we are only counting method calls and so fields like 'Max' have no meaning in this context. Notice there is also a JAMon row with the label "com.jamonapi.log4j.JAMonAppender.TOTAL" and that it had 75,000 hits (15,000 for each of the 5 Levels). This monitor is incremented whenever any of the loggers log methods are executed regardless of Level (i.e. it represents all log methods that were called).

jamonadmin.jsp from JAMon.war

This behaviour is by default enabled, but if you wish to turn it off you can set the following JAMonAppender property: log4j.appender.jamonAppender.EnableLevelMonitoring=false

Note many of the JAMon web pages can be 'queried' via the FormattedDataSet APIs ArraySQL class which allows you to query JAMon's internal data structures with a SQL like syntax. Don't be confused by this JAMon data is not kept in a database but are stored in memory. The screen snapshot shows how only 'log4j' JAMon rows are displayed by putting 'log4j' in the filter text box. For more info on querying data see the pages help section as well as and the FormattedDataSet.

The default behaviour is already useful for answering such questions as "When did an error last occur?", or "How many errors have occurred in my application?". Finding this out is much easier via the jamonadmin.jsp page than it would be by grepping or tailing a log file.

Using the JAMonAppender to mimic 'tail'

By adding the 'EnableListeners' property you will be able to use JAMon to view the most recent messages in a buffer for that is kept for each of the Log4j Levels (trace/debug/warn/info/error/fatal/total). Sample JAMonAppender XML configuration values that enable BASIC listeners follows: 

       <appender name="JAMONAPPENDER" class="com.jamonapi.log4j.JAMonAppender">
          <param name="EnableListeners" value="BASIC"/>
       </appender>

       <root>
          <appender-ref ref="CONSOLE"/>
          <appender-ref ref="FILE"/>
          <appender-ref ref="JAMONAPPENDER"/>
       </root>

BASIC means to track the most recent N log messages at the error/fatal/total levels. This means that we will have 3 buffers each of 100 rows (this is configurable via a JAMonAppender or at runtime via the JAMon war. The default is 100 rows) that will contain Log4J data including the LoggerName, Level, ThreadName, FormattedMessage, Date, and Exception Stack trace (if there is one). See the sample screen that follows. Note the screen is sortable, queryable, and realtime. Valid values for the EnableListeners property: DEBUG/WARN/INFO/ERROR/FATAL/TOTAL/ALL/BASIC. ALL enables individual buffers for each of the Levels as well as for TOTAL. Note these are additive in the XML file and so you can enable any combination of the values by using an approach like the one below: 

      <appender name="jamonAppender" class="com.jamonapi.log4j.JAMonAppender">
         <param name="EnableListeners" value="ERROR"/>
         <param name="EnableListeners" value="FATAL"/>
         <param name="EnableListeners" value="WARN"/>
      </appender>

To view the Log4jBufferListener click on the blue square labeled "Modify" on the jamonadmin.jsp page (see image above). From the "Modify" from the "Current" JAMonListeners list box select to display "Log4jBufferListener" and you will get a screen similar to the following (if you select TOTAL from jamonadmin.jsp). Note the different Level values in the Levels column due to the fact that we selected 'TOTAL'. If you select a buffer for one Level (say ERROR) it would only have the most recent N messages of that Level in the buffer. Also note the Exception stack trace. And finally the message sent to the 'log' methods is contained in the "FormattedMessage" column.

mondetail.jsp from JAMon.war

Using the JAMonAppender to aggregate and 'tail' individual messages - Generalizing

JAMon can also keep aggregate stats, and the N most recent detailed messages based on content within the logged message itself. Be careful when using the following capabilities as if the String isn't 'relatively unique' then JAMon's memory can grow unbounded (each row in JAMon is a HashMap entry).

The following example will allow us to take specific Strings that are passed to a Log4j logging method (debug/warn/error etc.) and 'generalize' them so they can also be placed into JAMon. A couple example s will make this concept more clear and show the benefit:

The JAMonAppender implements the following simple rules in generalizing these Strings.

To perform generalization the JAMonAppender uses "com.jamonapi.utils.DefaultGeneralizer" which implements the "com.jamonapi.utils.Generalizer interface". However, as this is a simple interface with one method (String generalize(String input)) you can implement it and easily replace the default behaviour. Later I will show how you can override the default class via Log4j configuration.

Take care to surround portions of Strings that aren't very unique with quotes, so they are replaced with '?' (examples would be names that occur in a message such as 'smith', 'jones', 'souza', 'jagger'). If the string is already relatively unique then you need not surround its contents with quotes.

The JAMonAppender property 'generalize' specifies that the JAMonAppender should take the log message generalize it with the DefaultGeneralizer and pass the results through JAMon. The following example would take a String a log message of the format:

    ERROR.com.mypackage - Invalid password provided by user 'aeinstein'

and convert it to

    ERROR.com.mypackage - Invalid password provided by user ?

And create a JAMon entry with the new String and put the original detailed String in a buffer for this monitor label (if enabled). The following information shows the xml configuration file used to do this. 

     <appender name="jamonAppender" class="com.jamonapi.log4j.JAMonAppender">
        <param name="EnableListeners" value="BASIC"/>
        <param name="generalize" value="true"/>
        <layout class="org.apache.log4j.PatternLayout">
           <param name="ConversionPattern" value="%p.%c-%m"/>
        </layout>
     </appender>

The following screen snapsot from jamonadmin.jsp shows that the generalized form of the log message was called 20,000 times.


Assuming we have enabled a JAMon "Log4jBufferListener" for the generalized monitor we can view the N most recent details written to the buffer via mondetail.jsp. Note the nongeneralized form is put in the buffer (In this case that can be identified by 'aeinstein'. Unfortunately at this time the only way to enable buffer listeners for log message monitors is via the JAMon web app or programmatically (i.e. it can't be done via Log4j configuration files)


Note if the log message is already generalized (say a layout of %c is used) then you can disable using the DefaultGeneralizer and pass the raw message through to JAMon. This isn't required however it will save a few cycles. Be careful when doing this or JAMon memory consumption can grow unbounded (every unique string consumes memory in JAMon). The following xml file will do this. An example of the JAMon label is 'ERROR.com.mypackage': 

<appender name="jamonAppender" class="com.jamonapi.log4j.JAMonAppender">
  <param name="EnableListeners" value="BASIC"/>
  <param name="generalize" value="true"/>
  <param name="enableDefaultGeneralizer" value="false"/>
  <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%p.%c"/>
  </layout>
</appender>
Finally if you want to provide your own Generalizer simply provide a default noarg constructor and pass the class name into the JAMonAppender via the Log4j configuration file. 
<appender name="jamonAppender" class="com.jamonapi.log4j.JAMonAppender">
    <param name="generalize" value="true"/>
    <param name="GeneralizerDynamic" value="com.mypackage.MyGeneralizer"/>
    <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%p.%c-%m"/>
    </layout>
</appender>

SourceForge.net Logo