Applications of Log4J with Use Cases

In this section, I’ll present a handful of Use Cases that I hope you’ll find useful. Each Use Case will present a problem, followed by the solution to that problem. Some of these you will have already seen in the Short Cut, but I wanted to consolidate the usage patterns I’ve found to be helpful here in one place.

Decouple an Object from its Logged Form

Problem

Every now and then, you may find that you want to just log an object, and let log4j figure out how to transform the object into something useful.

Solution

Log4j has an interface called an ObjectRenderer, which is at the center of log4j’s Object Rendering mechanism. Object Rendering is what log4j uses for every object that it is asked to log—if that object doesn’t get dropped, that is—and is log4j’s formal way to control the String representation of an object and allows for its configuration external to your application. Let’s take a closer look.

There are basically three paths log4j’s infrastructure takes when formatting a message to be logged:

  1. Object to be logged is already a String. Nothing further needs to be done.

  2. Object to be logged has no ObjectRenderer associated with it. Call toString() on the object.

  3. Object to be logged has an ObjectRenderer associated with it. Call doRender() on the object.

Most of the time, you will be passing objects of type java.lang.String to the various log4j API methods. But in those cases where you want to simply “throw” an object at the log4j API, Object Rendering can be very useful. The use cases abound for when you might want to take advantage of this powerful feature, but here are a few:

  • The code doing the logging wants to log an opaque object (such as an Exception)

  • You want to “override” the String representation of an object whose toString() method you don’t want to (or can’t) change

  • You want to delay the cost of String construction, since the ObjectRenderer will only be invoked if the message is going to be logged

Two examples of how to write an ObjectRenderer are provided with the Example application, one of which we have already seen several times in this Short Cut. We have also seen how to configure an Object Renderer in the section Configuring and Using Log4j using properties-style and XML configuration. The example we’ve seen already is for the Queue class, where it uses an inner class QueueRenderer to do its rendering.

The WorkUnit class also has an ObjectRenderer written for it called WorkUnitRenderer, which looks like:

package com.makotogroup.log4j;
import org.apache.log4j.or.ObjectRenderer;
public class WorkUnitRenderer implements ObjectRenderer {
    @Override
    public String doRender(Object o) {
        if (o instanceof WorkUnit) {
            WorkUnit workUnit = (WorkUnit)o;
            return "WORKUNIT: Last prime# -> " +
              workUnit.getLastPrimeNumberCalculated();
        }
        return o.toString();
    }
}

This renderer is very simple but illustrates a usage pattern I have found very helpful. If the WorkUnitRenderer is accidentally configured for the wrong class, the instanceof check will keep bad things from happening (like a ClassCastException). To configure the WorkUnitRenderer to render WorkUnit:

Example 11. Configuring WorkUnitRenderer

log4j.rootLogger=WARN, Console
log4j.appender.Console=org.apache.log4j.ConsoleAppender
log4j.appender.Console.layout=org.apache.log4j.SimpleLayout
log4j.logger.com.makotogroup.log4j.WorkUnit=DEBUG
log4j.renderer.com.makotogroup.log4j.WorkUnit=
  com.makotogroup.log4j.WorkUnitRenderer

And in XML:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j='http://jakarta.apache.org/log4j/'
  debug="true">
  <renderer renderedClass="com.makotogroup.log4j.WorkUnit"
         renderingClass="com.makotogroup.log4j.WorkUnitRenderer"/>
  <appender name="Console" class="org.apache.log4j.ConsoleAppender">
    <layout class="org.apache.log4j.SimpleLayout"/>
  </appender>
  <logger name="com.makotogroup.log4j.WorkUnit">
    <level value="DEBUG"/>
  </logger>
  <root>
    <level value="WARN"/>
    <appender-ref ref="Console"/>
  </root>
  </log4j:configuration>

Sending Log Messages to the Outside World

Problem

System critical information is not always conveyed appropriately. The system log cannot be watched twenty four hours a day.

Solution

Send messages of critical importance via email. Use the SMTPAppender.

SMTPAppender

This appender is used to append log messages to a single email and send that email message to one or more recipients each time a triggering event is received. A triggering event is a log event that is determined (by a TriggeringEventEvaluator) to trigger the appender to send an email. By default the triggering event is a log event of level ERROR or higher. The SMTPAppender keeps a circular buffer of the newest N messages (where N is configurable), so that as the N+1th message is stored in the buffer, the oldest message is discarded. This appender will send an email each time it receives a triggering event.

The following parameters are configurable:

BufferSize

The number of events that will be sent when a triggering event is received; as new messages come in, they are stored in the circular buffer so that only the newest BufferSize messages are kept. By default BufferSize is set to 512. SMTPAppender’s default threshold is null, so that all messages passed to it are kept.

EvaluatorClass

The fully qualified name of a class that implements the TriggeringEventEvaluator interface, so you can override the default behavior, which is to send an email every time an event of ERROR or higher comes in.

From

This parameter is required, and is the email address in the “from” part of the SMTP header.

LocationInfo

Set the value of this parameter to true (it is false by default) if you want the source file and line number of the logger call as part of the message.

SMTPUsername

If your SMTP server requires authentication, use this parameter to supply the username.

SMTPPassword

If your SMTP server requires authentication, use this parameter to supply the password.

SMTPHost

This parameter is required and is the name of the SMTP host that will be used to send the message

To

This parameter is required and is the email address (e.g., ) where the email message will be sent.

Note

The SMTPAppender uses the JavaMail API. If you are using JDK 5 or lower, you will also need the JavaBeans Activation Framework. All of the required JARs are included in the Example Application for compatibility. To get this example to run, you will need to supply values for the required parameters in the example_1-12.properties (or example1-12.xml) configuration file.

Example 12 shows how we might configure the SMTPAppender.

Example 12. Example configuration of the SMTPAppender

log4j.rootLogger=WARN, Console, Email
log4j.debug
log4j.appender.Console=org.apache.log4j.ConsoleAppender
log4j.appender.Console.layout=org.apache.log4j.PatternLayout
log4j.appender.Console.layout.ConversionPattern=%c {%l}:%n    [%t] %-5p - %m%n
log4j.appender.Email=org.apache.log4j.net.SMTPAppender
log4j.appender.Email.SMTPHost=${smtp.host}
log4j.appender.Email.SMTPUsername=${smtp.username}
log4j.appender.Email.SMTPPassword=${smtp.password}
log4j.appender.Email.To=${smtp.to}
log4j.appender.Email.From=${smtp.from}
log4j.appender.Email.layout=org.apache.log4j.HTMLLayout
log4j.logger.com.makotogroup.log4j.Controller=DEBUG

Both appenders are attached to the root logger so that all loggers in the application have potential access to them.

We’re also doing something here we haven’t looked at before: notice the ${smtp.host} value of the SMTPHost parameter. Log4j can substitute system variables into the configuration file. In this case, the values of the SMTPHost, SMTPUsername, and so forth, will be substituted from system variables. As you perused the source for the Example Application you may have noticed a file called setvars.bat (Windows) and setvars.sh (Linux). These files contain the actual values for these parameters, and you will need to place valid values in these files in order for this example to work. When testing these examples, I used my ISPs SMTP server and my login information, but obviously I couldn’t supply these values in example code for this Short Cut.

Remember that the default triggering event for the SMTPAppender to send an email is a log event of ERROR or higher. In a well behaved application this is a (hopefully) rare event. So to cause an ERROR message to be generated, I put a method logError() on each of the classes so that I could trigger an email. Start the application and point your browser to http://localhost:8090 (if this port is not free, change Controller.java to point to a free point and re-run the application). When the JMX management view comes up, click on the Controller MBean (see Figure 2) and you will see a screen like the following:

Managing the Controller MBean: causing an Error message to be generated

Figure 8. Managing the Controller MBean: causing an Error message to be generated

Next to the logError() method is a text field where we can type in the text of an error message that will be generated. This will cause the default TriggeringEventEvaluator to send an email. Type in the message you want and click the logError button to log the message. If you have configured the SMTPAppender correctly, you will receive an email shortly. The message will be in HTML format (you can change this by modifying the layout used in Example 12) and will contain messages, oldest first. The text you typed will appear at the bottom of the email as an ERROR event.

In the email you will see lots of output. Notice from Example 12 that the Controller logger level is set to DEBUG. By default, the last 512 messages above the appender’s threshold level will be kept. The idea is that you may want some context in order to make sense of the error message. But how much context is too much? It’s up to you, but you have several options for reducing or increasing the number of messages that will be sent with the email. Let’s look at two of them.

One option is to set the Threshold value of the appender. Notice in Example 12 no Threshold value was specified, so all messages bound for the SMTPAppender were accepted. To reduce the number of messages that are included, add this line to the configuration:

log4j.appender.Email.Threshold=INFO

And all messages below the INFO level will be dropped by the appender.

The other option is to change the BufferSize parameter. To reduce the number of messages, add this line to the configuration:

log4j.appender.Email.BufferSize=1

In this case, only the ERROR message that triggered the default TriggeringEventEvaluator will be included. To increase the number of messages, add this line:

log4j.appender.Email.BufferSize=2048

And the SMTPAppender will keep the newest 2048 messages (subject to the value of its Threshold parameter you set, of course)

These options may be combined, so that you can custom tailor them to suit your needs. I encourage you to play around with Example 12 to get a feel for how to use the SMTPAppender.

Logging to Multiple Destinations

Problem

Output needs to be written to multiple destinations.

Solution

Use multiple appenders.

This is something we’ve already seen, but we will look closely at using multiple appenders since how you do this can have a significant impact on your production environment. In this section we will look at how to configure the Example application to use three appenders:

  • ConsoleAppender - messages of INFO and higher

  • FileAppender - all messages

  • SMTPAppender - ERROR and higher messages

The simplest approach to take is to attach all appenders to the root logger, so that all loggers in the application have potential access to them. This is shown in Example 13 below.

Example 13. Attach appenders to the root logger

log4j.rootLogger=WARN, Console, Email, File
log4j.debug
log4j.appender.Console=org.apache.log4j.ConsoleAppender
log4j.appender.Console.Threadhole=INFO
log4j.appender.Console.layout=org.apache.log4j.PatternLayout
log4j.appender.Console.layout.ConversionPattern=
%c {%l}:%n    [%t] %-5p - %m%n
log4j.appender.Email=org.apache.log4j.net.SMTPAppender
log4j.appender.Email.Threshold=ERROR
log4j.appender.Email.SMTPHost=${smtp.host}
log4j.appender.Email.SMTPUsername=${smtp.username}
log4j.appender.Email.SMTPPassword=${smtp.password}
log4j.appender.Email.To=${smtp.to}
log4j.appender.Email.From=${smtp.from}
log4j.appender.Email.layout=org.apache.log4j.HTMLLayout
log4j.appender.File=org.apache.log4j.RollingFileAppender
log4j.appender.File.File=output.log
log4j.appender.File.layout=org.apache.log4j.SimpleLayout
log4j.logger.com.makotogroup.log4j.Controller=DEBUG

All three appenders are attached to the root logger. In this example, DEBUG logging for all loggers in the com.makotogroup hierarchy has been enabled to provide lots of messages.

It might be helpful (for debugging, maybe) to use different appenders to handle messages of different Levels. For example, messages of WARN and higher may go to one file, INFO and higher to another file, and DEBUG and higher to a third file. That configuration would look something like Example 14 below.

Example 14. Example 1-14

log4j.rootLogger=WARN, WarnFile, InfoFile, DebugFile
log4j.debug
log4j.appender.WarnFile=org.apache.log4j.RollingFileAppender
log4j.appender.WarnFile.File=WARN.log
log4j.appender.WarnFile.Threshold=WARN
log4j.appender.WarnFile.layout=org.apache.log4j.PatternLayout
log4j.appender.WarnFile.layout.ConversionPattern=
%c {%l}--> [%t] %-5p - %m%n
log4j.appender.InfoFile=org.apache.log4j.RollingFileAppender
log4j.appender.InfoFile.File=INFO.log
log4j.appender.InfoFile.Threshold=INFO
log4j.appender.InfoFile.layout=org.apache.log4j.PatternLayout
log4j.appender.InfoFile.layout.ConversionPattern=
%c {%l}--> [%t] %-5p - %m%n
log4j.appender.DebugFile=org.apache.log4j.RollingFileAppender
log4j.appender.DebugFile.File=DEBUG.log
log4j.appender.DebugFile.Threshold=DEBUG
log4j.appender.DebugFile.layout=org.apache.log4j.PatternLayout
log4j.appender.DebugFile.layout.ConversionPattern=
%c {%l}--> [%t] %-5p - %m%n
log4j.logger.com.makotogroup=DEBUG

Threshold matching drops messages below a particular threshold but allows any at the specified threshold and higher to be logged. What if we want to configure an appender that logs only messages of a particular level and only that level? For that we will need a Filter—which requires us to use XML configuration—in particular a log4j class called LevelMatchFilter. Example 15 shows how to configure a LevelMatchFilter to accept only log events of TRACE.

Example 15. Configuring a LevelMatchFilter to accept only log events of TRACE

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j='http://jakarta.apache.org/log4j/'
debug="true">
  <appender name="Console" class="org.apache.log4j.ConsoleAppender">
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%c {%l}--> [%t] %-5p - %m%n"/>
    </layout>
  </appender>
  <appender name="TraceFile"
            class="org.apache.log4j.RollingFileAppender">
    <param name="File" value="TRACE.html"/>
    <param name="Append" value="false"/>
    <layout class="org.apache.log4j.HTMLLayout"/>
    <filter class="org.apache.log4j.varia.LevelMatchFilter">
      <param name="LevelToMatch" value="trace"/>
    </filter>
    <filter class="org.apache.log4j.varia.DenyAllFilter"/>
  </appender>
  <logger name="com.makotogroup">
    <level value="ALL"/>
  </logger>
  <root>
    <level value="WARN"/>
    <appender-ref ref="Console"/>
    <appender-ref ref="TraceFile"/>
  </root>
</log4j:configuration>

Note

Filter chains work by executing each filter in the chain, beginning with the first one defined in the configuration, until the end of the chain is reached or one of the filters in the chain returns DENY or ACCEPT. When a filter is consulted, if that filter returns DENY the event is dropped. If ACCEPT is returned, the event is logged. If NEUTRAL is returned the next filter in the chain is consulted. If the end of the filter chain is reached without DENY or ACCEPT being returned, log4j behaves—for that log event—normally (as if the filter chain was never there).

When you run this example, you will notice that only messages of TRACE are in the TRACE.log file, even though there are lots of DEBUG messages being output, too, because of the way the com.makotogroup logger is configured. This is because LevelMatchFilter returns ACCEPT only for those events whose level matches the one specified. You may be wondering about the DenyAllFilter. The TraceFile appender has no threshold set, which is what we want because if we set it above TRACE, then none of the TRACE messages will ever make it to TRACE.log, no matter how interesting our filter setup is. But this also has a consequence: all messages of TRACE and higher are accepted. So, to ensure that TRACE.log contains ONLY TRACE messages, we include a filter (LevelMatchFilter) to accept TRACE messages and another (DenyAllFilter) to deny everything else. Each instance of the LevelMatchFilter is neutral towards any events that do not match its LevelToMatch property.

If we want to, say, accept only TRACE and WARN messages, we could do that too with the following:

<appender name="TraceAndWarnFile"
          class="org.apache.log4j.RollingFileAppender">
  <param name="File" value="TRACE_and_WARN.html"/>
  <param name="Append" value="false"/>
  <layout class="org.apache.log4j.HTMLLayout"/>
  <filter class="org.apache.log4j.varia.LevelMatchFilter">
    <param name="LevelToMatch" value="warn"/>
  </filter>
  <filter class="org.apache.log4j.varia.LevelMatchFilter">
    <param name="LevelToMatch" value="trace"/>
  </filter>
  <filter class="org.apache.log4j.varia.DenyAllFilter"/>
</appender>

Since LevelMatchFilter requires an exact match on Level, only WARN and TRACE messages are accepted, and all others are dropped (i.e., denied) by this appender.

Content-Based Logging

Problem

Log messages need to be correlated in a meaningful way from a business standpoint. This is based on information in the message itself.

Solution

Use Mapped Diagnostic Contexts (MDC).

In real-world, multi-user applications it is rare that a unit of work will follow a single, straight-line path through the application. The path a unit of work takes will twist and turn and change depending on many factors. Plus, the application—if it scales—is more than likely servicing more than one user at a time. As a unit of work traverses its way through your application, its log output leaves a trail behind it, but if you need to research a problem by looking in the log files it may be challenging at best and impossible at worst to correlate messages from different parts of your application for a single unit of work.

That is where log4j’s Diagnostic Context comes in handy, in particular the Mapped Diagnostic Context (MDC). An MDC is a key/value entity maintained by log4j on thread local storage (TLS) that can be used to make information available to different parts of the application, allowing all loggers to emit consistent log messages. As a result, a log message can be correlated to others by the content of the messages.

The Example Application attempts to simulate this by associating a “user” from a pool of users for each WorkUnit that is processed. Log messages can be correlated by looking at the UserId and UserName properties of the WorkUnit that is being processed, and you can actually follow a unit of work from the time it is processed by the Supplier until it is completed by the Consumer. This requires very little code to accomplish.

Each WorkUnit simulates a request (the unit of work in this case) on behalf of a user, with which the WorkUnit is associated. When the WorkUnit is created it sets the UserId and UserName of the associated user in the MDC:

public class WorkUnit {
. . .
    public WorkUnit() {
        requestingUser = User.getRandomUser();
    }
. . .
    public void activate() {
        MDC.put(RequestRenderer.USER_ID, getRequestingUser().getUserId());
        MDC.put(RequestRenderer.USER_NAME, getRequestingUser().getUserName());
        requestStartTime = System.currentTimeMillis();
    }
. . .
    public void deactivate() {
        MDC.remove(RequestRenderer.USER_ID);
        MDC.remove(RequestRenderer.USER_NAME);
    }
}

The static method User.getRandomUser() simulates associating the WorkUnit with a “user” as if the work that is done is on behalf of that user. Each component that deals with a unit of work calls activate() on that unit of work (setting the MDC appropriately) and when finished calls deactivate() (removing the information from the MDC). For example, when the Supplier creates the WorkUnit:

public class Supplier extends Worker {
. . .
  public void run() {
    getlogger().trace("Entering method run()...");
    while (!isStopCalled()) {
      while (isSuspended()) {
        if (nap()) {
          getlogger().warn("Got interrupted!");
        }
      }
      nap();
      WorkUnit unitOfWork = new WorkUnit();
      unitOfWork.activate();
      unitOfWork.log();// Object, log thyself!
. . .
  }
. . .
}

When Consumer deals with the WorkUnit:

public class Consumer extends Worker {
. . .
  public void run() {
    getlogger().trace("Entering method run()...");
    while (!isStopCalled()) {
      while (isSuspended()) {
        try {
          Thread.sleep(1000);
        } catch (InterruptedException e) {
        }
      }
      WorkUnit unitOfWork = null;
      while (unitOfWork == null) {
        unitOfWork = getQueue().take();
        unitOfWork.activate();
      }
      incrementTotalProcessingTime(doWork(unitOfWork));
      incrementNumberOfUnitsProcessed(1);
      unitOfWork.log();// Object, log thyself!
      unitOfWork.deactivate();
      }
      getlogger().trace("Exiting method run()");
    }
  }
}

Notice that when Consumer gets the unit of work from the Queue it calls activate() to set the context information in the MDC. When it is finished, it calls deactivate(). In a single threaded application, one call to activate() would be sufficient, but since MDC is stored as TLS, each component must be coded to participate in this pattern so that a unit of work can be traced through its path, even in a multi-threaded application like the Example application.

Finally, you will need to configure the PatternLayout to output the appropriate mapped context:

Example 16. Example 1-16

log4j.rootLogger=WARN, Console
log4j.debug
log4j.appender.Console=org.apache.log4j.ConsoleAppender
log4j.appender.Console.layout=org.apache.log4j.PatternLayout
log4j.appender.Console.layout.ConversionPattern=
%c [%t] %-5p |RQID=%X{request.id} USERID=%X{user.id} 
USERNAME=%X{user.name}| => %m%n
log4j.logger.com.makotogroup=ALL
log4j.renderer.com.makotogroup.log4j.WorkUnit=com.makotogroup.log4j.WorkUnit$Reques
tRenderer

For each WorkUnit that comes through the application, the MDC will contain its requestId, userId, and userName properties, and those are output using the special %X{property_name} notation.

Note

This is all done by contract and convention. This is not automatic, so you will have to write some code and make sure that all parts of the application follow this convention. That is, context properties have to be named consistently, and their values have to have consistent meaning. This is potentially more of a problem where applications are maintained by multiple developers. However, as you can see, it’s very simple code to write.

Now, if you run Example 16, you will see a dizzying array of output on the console. However, the output from each unit of work has diagnostic context associated with it—in this case userId and userName—so that it is possible to correlate a single unit of work as it traverses through the application. With a slight modification we can direct the output to a log file, and on Linux at least (or on Windows if you run Cygwin) we can grep for a single unit of work from, say, Billy:

~/workspace/log4j-example$ grep 'USERNAME=Billy' output.log

And the result will be only those lines that contain the String “USERNAME=Billy”. Is there a way to get log4j to do this? After all, not everyone has an awesome set of command line power tools available to them (like we Linux users do). Fortunately there is a way, and it involves the use of a Filter, specifically a StringMatchFilter subclass. StringMatchFilter looks at the rendered message itself, which means it has been processed by the layout and any ObjectRenderer defined for the message class. But this isn’t quite good enough for that we need. We need a StringMatchFilter that also can look at the MDC for a specific property value. However, log4j does not provide such a Filter, so I wrote one. Check out Example 17.

Example 17. StringMatchFilter

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration
   xmlns:log4j='http://jakarta.apache.org/log4j/' debug="true">
  <renderer renderedClass="com.makotogroup.log4j.WorkUnit"
    renderingClass="com.makotogroup.log4j.WorkUnit$RequestRenderer"/>
  <appender name="Console" class="org.apache.log4j.ConsoleAppender">
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern"
             value="%c [%t] %-5p |%X{request.id} %X{user.id} 
%X{user.name}| => %m%n"/>
    </layout>
  </appender>
  <appender name="File" class="org.apache.log4j.FileAppender">
    <param name="File" value="output.log"/>
    <param name="Append" value="false"/> <!-- Recreate file between runs -->
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern"
             value="%c [%t] %-5p |%X{request.id} %X{user.id} 
%X{user.name}| => %m%n"/>
    </layout>
    <filter
      class="com.makotogroup.log4j.WithContextStringMatchFilter">
      <param name="ContextPropertyToMatch" value="user.name"/>
      <param name="ContextPropertyValueToMatch" value="Billy"/>
    </filter>
    <filter class="org.apache.log4j.varia.DenyAllFilter"/>
  </appender>
  <logger name="com.makotogroup">
    <level value="ALL"/>
  </logger>
  <root>
    <level value="WARN"/>
    <appender-ref ref="Console"/>
    <appender-ref ref="File"/>
  </root>
</log4j:configuration>

If you run Example 17 and look in output.log, you will see all messages where Billy is the userName in the MDC. The StringMatchFilter that comes packaged with log4j only checks the rendered message for the string to match. Because non-matches are considered neutral, once again the DenyAllFilter is in use here.

Logging Messages to a Database

Problem

Messages on the console or in a log file are fine, but can be a bit cumbersome to work with.

Solution

Persist certain messages so they may be correlated based on their properties.

SQL is a great language for joining sets of data together, so it seems logical that for certain types of messages we would want to store them to a relational database in order to correlate messages based on one or more properties of the messages themselves. For that we need an adapter that can save the messages to the database. Log4j comes packaged with an appender called JDBCAppender. I prefer not to use JDBC directly from my Java code because I like dealing with objects, so I use Hibernate. Because of that, I wrote an adapter—HibernateAdapter—for this Short Cut. Example 18 shows how to configure it.

Example 18. Configuring HibernateAdapter

log4j.rootLogger=WARN, Console
log4j.debug
log4j.appender.Console=org.apache.log4j.ConsoleAppender
log4j.appender.Console.layout=org.apache.log4j.PatternLayout
log4j.appender.Console.layout.ConversionPattern=
%c [%t] %-5p |RQID=%X{request.id} USERID=%X{user.id} 
USERNAME=%X{user.name}| => %m%n
log4j.appender.Hibernate=com.makotogroup.log4j.db.HibernateAppender
log4j.logger.com.makotogroup=DEBUG,Hibernate
log4j.renderer.com.makotogroup.log4j.WorkUnit=com.makotogroup.log4j.WorkUnit$Reques
tRenderer

Note

Example 18 expects there to be a MySQL database installed on the machine on which you’re running it. The Example application comes with a script to create the necessary tables to make this work. Instructions for setting up the database are located in the Example application code distribution.

HibernateAdapter needs no layout and has no properties to set. In Example 18 it is associated with the com.makotogroup logger only, and if you run this example you will see messages show up in the database. Depending on the speed of your machine, it may also run slowly. HibernateAdapter uses Hibernate’s default SessionFactory, and if you look at hibernate.cfg.xml you’ll notice there is not much in the way of optimizations. That I leave to you.

Now consider Example 17. While using a StringMatchFilter to pull Billy’s messages out into their own log file, we can use HibernateAdapter to save ALL of the messages to the DB and use SQL to pull them:

Figure 1-9.

Figure 9. Figure 1-9.

It (hopefully) goes without saying that you probably NEVER want to persist DEBUG or TRACE level messages into a database for performance reasons if for no other. However, using a technique like this can be very handy in cases where you need to correlate messages across various thread, VM, or physical machine boundaries based on contextual information.

Segregating Output

Problem

When output from multiple loggers gets interleaved it can be difficult to make sense out of it.

Solution

Use a separate appender for the verbose part(s) of the application, and turn off appender additivity for the appropriate logger(s).

We saw in section titled Appender inheritance that through the use of configuration and turning off appender additivity we can segregate log output. I do this all the time with Hibernate, which I use as my O/R mapping library as I mentioned in the previous section. Every now and then I want to see what Hibernate is doing under the hood (when I can’t get a mapping to work correctly, for example), and so I want to see Hibernate DEBUG output. But I want to see my application’s output too, and when it gets interleaved with the output from Hibernate, well, I just can’t read it. All that great DEBUG output from Hibernate doesn’t really help me all that much because there’s just too much other information getting in the way.

Consider Example 19 below, where we turn off appender additivity, and segregate different parts of the application using different appenders:

Example 19. Segregating different parts of the application using different appenders

log4j.rootLogger=WARN, Console
log4j.appender.Console=org.apache.log4j.ConsoleAppender
log4j.appender.Console.layout=org.apache.log4j.SimpleLayout
log4j.appender.HibernateAppender=org.apache.log4j.FileAppender
log4j.appender.HibernateAppender.File=hibernate.log
log4j.appender.HibernateAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.HibernateAppender.layout.ConversionPattern=
 %c {%l}:%n    [%t] %-5p - %m%n
log4j.additivity.org.hibernate=false
log4j.logger.org.hibernate=DEBUG,HibernateAppender

In this example the output from all of the loggers in the org.hibernate hierarchy goes to the file hibernate.log, and - because we turned off appender additivity for the org.hibernate logger—nowhere else!

The neat thing about segregating appender output is that it works for any logger. The combinations are endless!

Special Messages

Problem

Some messages are more important from an operational standpoint than the Level they are assigned would suggest.

Solution

Use the SMTPAppender, along with a filter chain and a custom TriggeringEventEvaluator to capture these important messages.

When the Example application is about to complete its startup sequence it attempts to log a message that begins with the string “APPLICATION STARTING AT ==> …” and whose Level is INFO. In a real-world application, such a message, while informational in nature, could have serious operational meaning. For example, if your job is to ensure the application is always up and running, such a message at, say, 1:30pm would make you wonder, “Why did the application just start up at 1:30 in the afternoon?” But if you aren’t looking at the log file when this message appears, you probably won’t know the application just restarted (and thus won’t investigate why this seemingly strange thing has happened).

In Example 12 we looked at how to use the SMTPAppender, which by default uses a TriggeringEventEvaluator that sends an email whenever an event of Level ERROR or higher is received. However, in the scenario above we would not see the message since it is at level INFO and would not trigger the default TriggeringEventEvaluator. What we want is to set up an appender that has a null Threshold, a filter chain that only allows events whose message contains certain key String fragments, and a TriggeringEventEvaluator that accepts all events.

First, we create a custom TriggeringEventEvaluator that tells the caller that any event triggers:

package com.makotogroup.log4j;

import org.apache.log4j.spi.LoggingEvent;
import org.apache.log4j.spi.TriggeringEventEvaluator;

public class AcceptAllTriggeringEventEvaluator
 implements TriggeringEventEvaluator {

  @Override
  public boolean isTriggeringEvent(LoggingEvent event) {
    // This TEV accepts all events
    return true;
  }
}

Next, we configure the filter chain, as shown below in Example 20.

Example 20. Configuring the filter chain

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j='http://jakarta.apache.org/log4j/'
debug="true">
  <appender name="Console" class="org.apache.log4j.ConsoleAppender">
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern"
             value="%c [%t] %-5p |%X{request.id} %X{user.id}
%X{user.name}| => %m%n"/>
    </layout>
  </appender>

  <appender name="ImportantEventSmtpAppender"
            class="org.apache.log4j.net.SMTPAppender">
    <param name="EvaluatorClass"
value="com.makotogroup.log4j.AcceptAllTriggeringEventEvaluator"/>
      <param name="SMTPHost" value="${smtp.host}"/>
      <param name="SMTPUsername" value="${smtp.username}"/>
      <param name="SMTPPassword" value="${smtp.password}"/>
      <param name="To" value="${smtp.to}"/>
      <param name="From" value="${smtp.from}"/>
      <layout class="org.apache.log4j.HTMLLayout"/>
      <filter class="org.apache.log4j.varia.StringMatchFilter">
        <param name="StringToMatch" value="APPLICATION STARTING AT"/>
      </filter>
      <filter class="org.apache.log4j.varia.DenyAllFilter"/>
  </appender>

  <logger name="com.makotogroup">
    <level value="ALL"/>
    <appender-ref ref="ImportantEventSmtpAppender"/>
  </logger>
  <root>
    <level value="WARN"/>
    <appender-ref ref="Console"/>
  </root>
</log4j:configuration>

If you run Example 20 (don’t forget to correctly configure your SMTP settings) you should receive an email when the application has finished its startup sequence. The filter chain for the ImportantEventSmtpAppender is configured with a null threshold (by omitting the Threshold parameter) so that all events are passed through to the filter chain which denies all events except those that contain the string “APPLICATION STARTING AT” upon acceptance of which the AcceptAllTriggeringEventEvaluator triggers and an email is sent.

..................Content has been hidden....................

You can't read the all page of ebook, please click here login for view all page.
Reset
13.59.209.131