Log4J - Extending the Appender classes to wrap messages

Here's the problem: I want my Log4J output (hell, any logging output, Log4J or otherwise)to be easy to look at. I don't want the format to be "busy". I want things to line up so that the information I'm looking for is easily spotted. I don't think I'm alone in this idea and to drive this point home, it's partially the reason why Log Factor 5 and Chainsaw exists, in my opinion.

To illustrate, this is what I'm talking about as motivation to get order into log files.


I don't know about you, but looking at that is not my idea of a good time, especially if it happens to be 4:00AM. All I'm asking for is a little order in my chaos.

Formatting the message body
I'm not going to go into the detail surrounding Log4J message formatting. You can get that information from here.
What I am referring to is how to use the formatting instructions presented at the above link to help accomplish a more formatted message body.

*NOTE*
The example log-files presented below will not be properly formatted if you are using Internet Explorer. However, when using Firefox the formatting is presented properly. (You're missing out if you're using I.E.)

Limiting the message body to a certain length so as to maintain a degree of uniformity serves to help the ol' Mark-IV eyeball make sense out of the log entries. To illustrate, shown below is the log-file layout that tries to maintain a certain place for each logging element and where the message body is limited to say- - - 80-bytes.

                             .... ....1.... ....2.... ....3.... ....4.... ....5.... ....6.... ....7.... ....8
2007-08-24 13:39:06 [DEBUG]  Implementation title   : log4j                                                    at line [    62] of class [Log4JTest.run()]  [Logger:log4j.test.Log4JTest] 
2007-08-24 13:39:06 [DEBUG]  Implementation vendor  : "Apache Software Foundation"                             at line [    63] of class [Log4JTest.run()]  [Logger:log4j.test.Log4JTest] 
2007-08-24 13:39:06 [DEBUG]  Implementation version : 1.2.14                                                   at line [    64] of class [Log4JTest.run()]  [Logger:log4j.test.Log4JTest] 

But what about when the message body is more than 80-bytes? That would hork-up the "pretty factor", huh? Now it was apparent that when a message body is more than 80 bytes, it should be wrapped to the next line, BUT, maintain the same information about where the logging event (line number, mainly) took place AND the developer should not have to deal with that issue. All the developer should do is what they were used to doing in the first place... mainly this:

  log.info(theReallyLongMessage); 

The whole solution

Extend the ConsoleAppender class in log4j. The idea being pursued here is to intercept the message, testing the message body length and if greater than 80-bytes, breaking up the message body into 80-byte segments and reconstituting the message segment into a new LoggingEvent object. Simple, really.

/* 
 * History of modification 
 * 
 * History of modification 
 * 
 * Date     Project           By                    Description 
 * -------- -----------        ----------- ----------------------------------------------- 
 * 
 * 
 */ 
package com.log4j.extensions; 

/** 
 *  This class provides the means for wrapping an arbitrary logging event-line, so 
 *  that the body of the message - this is, "%m" - is wrapped to the next line(s). 
 *   
 *  Keep in mind we aren't interested in formatting or altering the pattern layout 
 *  as the logging event has already been formatted.  The only aspect this class 
 *  deals with is the actual length of the message; if it's greater than 80 bytes, 
 *  the message will be broken up into 80-byte segments and sent to the ConsoleAppender. 
 *   
 *   
 *   
 */ 


import java.util.ArrayList; 

import org.apache.log4j.ConsoleAppender; 
import org.apache.log4j.Layout; 
import org.apache.log4j.Level; 
import org.apache.log4j.Logger; 
import org.apache.log4j.spi.LoggingEvent; 

public class FoldingConsoleAppender extends ConsoleAppender { 

        private final static int LINE_LIMIT = 80; 
        private final static String HEADER = "THE FOLLOWING LINES WERE SPLIT INTO " + 
                                                                LINE_LIMIT + " BYTE SEGMENTS TO FIT INTO THIS SPACE."; 
        private final static String FOOTER = "FOLDING COMPLETED"; 
        private final static String NULL_MESSAGE = "The initial message value of null has been replaced with this message."; 

        /** 
         * 
         * Overrides the parent class method 'subAppend()' so that the Logging event can 
         * be intercepted to inspect the lenght of the message (%m). 
         * 
         */ 
        protected void subAppend(LoggingEvent event) { 
                
                //Take the logging event and inspect the message.  If greater than 80-bytes 
                //create a CustomLoggingEvent with the 80-byte portion and send to the 
                //parent class subAppend() method.  Repeat for the succeeding lines required 
                //to complete the process. 
                
                if ((String)event.getMessage() == null) { 
                        String catClass = event.fqnOfCategoryClass; 
                        Logger logger = Logger.getLogger(event.getLoggerName()); 
                        long ts = event.timeStamp; 
                        Level level = event.getLevel(); 
                        Object message = NULL_MESSAGE; 
                        LoggingEvent cle = new LoggingEvent(catClass, logger, ts, level, message, null); 
                        super.subAppend(cle); 
                        return; 
                } 
                
                if (((String)event.getMessage()).length() > LINE_LIMIT) { 
                        Object m = event.getMessage(); 
                        
                        String line = (String) event.getMessage(); 
                        
                        if (line.length() > LINE_LIMIT) { 
                                //Call foldLine to break up the message into 80-byte segments which 
                                //have been placed into the array list. 
                                ArrayList al = this.foldLine(line, LINE_LIMIT); 
                                
                                //For every 80-byte segment in the ArrayList, create a CustomLoggingEvent 
                                //object using information from the original LoggingEvent but put the 
                                //80-byte line into the new CustomLoggingEvent 
                                for (int i = 0; i < al.size(); i++) { 
                                        Object o = al.get(i); 
                                        String catClass = event.fqnOfCategoryClass; 
                                        Logger logger = Logger.getLogger(event.getLoggerName()); 
                                        long ts = event.timeStamp; 
                                        Level level = event.getLevel(); 
                                        Object message = al.get(i); 
                                        LoggingEvent cle = new LoggingEvent(catClass, logger, ts, level, message, null); 
                                        super.subAppend(cle); 
                                } 

                        } 
                        
                } else { 
                        //Prints any log entry <= LINE_LIMIT bytes in length 
                        super.subAppend(event); 
                } 

        } 
        
        /** 
         * 
         * Take the message body (%m) and divide it into 80-byte line-segments placing 
         * each segment (with preseding and ending note) into an ArrayList to be returned. 
         * 
         * @param line 
         * @param maxLen 
         * @return 
         */ 
        public ArrayList foldLine(String line, int maxLen) { 

                String foldedLine = null; 
                StringBuffer sb = new StringBuffer(); 
                ArrayList al = new ArrayList(); 

                int index = 0; 
                int lineLength = line.length(); 
                int endIndex = index + maxLen; 
                al.add(HEADER); 
                while (index < lineLength) { 
                        al.add(line.substring(index, endIndex)); 
                        index = index + maxLen; 
                        endIndex = index + maxLen; 
                        if (endIndex > lineLength) { 
                                endIndex = lineLength; 
                        } 
                } 
                al.add(FOOTER); 

                foldedLine = sb.toString(); 
                return al; 
        } 
        
} 

Now that the class is created, place it into any package of your project. Next, modify your log4j.xml segment that describes the use of the ConsoleAppender as shown below.


Now, whenever the developer logs a message longer than 80-bytes:

//This demonstrates the idea of "folding" a line to ensure it fits inside the 
//message space defined in the layout ( %-80m ) of the appender 
String line = ".... ....1.... ....2.... ....3.... ....4.... ....5.... ....6.... ....7.... ....8.... ....9.... ....0"; 
log.info(line); 

Instead of this message formatting .... (some messages appear before and after)

2007-08-24 10:26:19 [ERROR]  3. ERROR error message                                                            at line [    39] of class [ArbitraryAppenderReference.log()]  [Logger:Example_Logger] 
2007-08-24 10:26:19 [FATAL]  4. FATAL error message                                                            at line [    40] of class [ArbitraryAppenderReference.log()]  [Logger:Example_Logger] 
2007-08-24 10:26:19 [INFO ]  .... ....1.... ....2.... ....3.... ....4.... ....5.... ....6.... ....7.... ....8.... ....9.... ....0  at line [    43] of class [ArbitraryAppenderReference.log()]  [Logger:Example_Logger] 
2007-08-24 10:28:56 [INFO ]  This logging entry is attached to appender 'Example_Logger'.                      at line [    21] of class [ArbitraryAppenderReference.log()]  [Logger:Example_Logger] 
2007-08-24 10:28:56 [INFO ]  and originated from class ArbitraryAppenderReference                              at line [    22] of class [ArbitraryAppenderReference.log()]  [Logger:Example_Logger] 

... the message is formatted like this.

2007-08-24 10:26:19 [ERROR]  3. ERROR error message                                                            at line [    39] of class [ArbitraryAppenderReference.log()]  [Logger:Example_Logger] 
2007-08-24 10:26:19 [FATAL]  4. FATAL error message                                                            at line [    40] of class [ArbitraryAppenderReference.log()]  [Logger:Example_Logger] 
2007-08-24 13:39:06 [INFO ]  THE FOLLOWING LINES WERE SPLIT INTO 80 BYTE SEGMENTS TO FIT INTO THIS SPACE.      at line [    33] of class [Log4JTest.run()]  [Logger:log4j.test.Log4JTest] 
2007-08-24 13:39:06 [INFO ]  .... ....1.... ....2.... ....3.... ....4.... ....5.... ....6.... ....7.... ....8  at line [    33] of class [Log4JTest.run()]  [Logger:log4j.test.Log4JTest] 
2007-08-24 13:39:06 [INFO ]  .... ....9.... ....0                                                              at line [    33] of class [Log4JTest.run()]  [Logger:log4j.test.Log4JTest] 
2007-08-24 13:39:06 [INFO ]  FOLDING COMPLETED                                                                 at line [    33] of class [Log4JTest.run()]  [Logger:log4j.test.Log4JTest] 
2007-08-24 10:28:56 [INFO ]  This logging entry is attached to appender 'Example_Logger'.                      at line [    21] of class [ArbitraryAppenderReference.log()]  [Logger:Example_Logger] 
2007-08-24 10:28:56 [INFO ]  and originated from class ArbitraryAppenderReference                              at line [    22] of class [ArbitraryAppenderReference.log()]  [Logger:Example_Logger] 
    

You can take the same FoldingConsoleAppender class above and use it as the basis to extend Log4J's FileAppender and DailyRollingFileAppender.

Thanks to Log4J's open source position !

Log4J all over again

I've not had to do Log4J configuration since before the time of the introduction of log4j.xml. Before that I used the simple log4j.properties variation.

But now, since I've run across an application using lo4j.xml I've had to learn how to configure Log4J using it. Initially, I thought "Argh" but as it turns out, it's not as bad as I had feared.

Having searched high and low on the internet, I found a lot of sites on the subject on log4j configuration. Some sites were good and other sites were not so good. All of them were broad; explained everything and then some. None offered real clarity. This was probably due to my impatience from just wanting a 1, 2, 3... list.

The log4j.xml file

Briefly, there's a layout to log4j.xml, shown below.


1. The class file
This is where the sequence of events begin. Somewhere, usually at the class level or perhaps in the constructor, you're going to have an entry such as this:

  Logger log = Logger.getLogger(name);

The name may appear to be arbitrary, but its actual value is important. This is because it is linked to a named logger defined in log4j.xml. Many examples show the getLogger() method like this:

  Logger log = Logger.getLogger(this.getClass().getName() );

Documentation such as this is a dis-service to both you and Log4j. The fact is that when getting a logger using the above approach returns the named logger only if one has been defined! If a logger having this name is not defined in log4j.xml a new logger instance will be created. Consequently, log entries will be sent to ALL log-files in your application. If you only have one then the problem is masked. Needless to say this approach should be avoided. Stick with names that are associated with named loggers you have defined in log4j.xml and your logging output to the correct log files will be much more predictable. Under this approach, you should expect to see something like this throughout your application:

  Logger log =  Logger.getLogger("Example_Logger");  

Using named loggers you can create a separate set of log-files designed to contain entries for a given process.

2. Log4J looks-up the Logger Definition
Using the name ("Example_Logger") Log4J looks up logger information that were described using Logger Definitions.

From this lookup, Log4J obtains the name of the Appender.

3. Appender Definitions
Logger Definitions "point-to" Appenders which are described using Appender Definitions. Among other things, Appender Definitions define the log-file (and the filtering logging level) used to receive entries.


4. The Root Definition
The Root definition is used to define which logger is to descend from Log4J's root logger.