log4j Notes

Table of Contents

Using log4j
External modification of log4j behavior (properties)
A more basic variation
Other behavior variations
Properties: logging level
More on properties: set logging level
Performance
Web applications
log4j from Eclipse
Where to put log4j.properties?
log4j.properties with support for JSF and Spring
Java service wrapper
Changing level at runtime
Some links...
A great example of a production properties file
Errors encountered and solved
Locking when logging—performance considerations
Configuring log4j starting in v2
Log4j2

Using log4j

log4j logging is pretty easy. Here's a good tutorial: http://www.developer.com/open/article.php/10930_3097221_1, but you'll find better illustration on this page once you've spent the time on the concepts there. The bonafide Apache tutorial (log4j is an Apache thing) is at: http://logging.apache.org/log4j/1.2/manual.html and it's a good resource once you've read the first one and mine here unless you prefer more formal language.

Source code sample

Here is the sample code for the output we'll be studying. What's in italics and bold will vary for our examples.

package com.etretatlogiciels.samples.log4j;

import org.apache.log4j.Logger;

public class Log4J
{
	  private static Logger   logger = Logger.getLogger( Log4J.class.getName() );
	  private SimpleLayout    myLayout;
	  private Appender        myAppender;

  public Log4J()
  {
	    logger.setLevel( Level.INFO );
	    myLayout   = new SimpleLayout();
	    myAppender = new ConsoleAppender( myLayout );
	    logger.addAppender( myAppender );
  }

  public static void do_something( int a, float b )
  {
	    double   X = b - a - 3.1415;

	    logger.info ( "Parameters passed to method do_something are: " + a + ", " + b );
	    logger.debug( "Operation performed successfully" );
	    logger.error( "Value of X is " + X );
  }

  public static void main( String[] args )
  {
	    PropertyConfigurator.configure( "src/resources/log4j.properties" );
	    do_something( 99, 542 );
  }
}

External modification of log4j behaviors (properties)

Given the above code, here is an option properties file that can tailor, without need to rebuild the code, the behavior of the logging. In particular, note SimpleLayout below. Despite coding to use SimpleLayout above, we can vary the behavior widely as shown here.

log4j.properties

Note the call to PropertyConfigurator.configure() in main() above; the properties file is placed on the path <project-name>/src/resources/log4j.properties. Its text consists of:

log4j.rootLogger=debug, myAppender
log4j.appender.myAppender=org.apache.log4j.ConsoleAppender
log4j.appender.myAppender.layout=org.apache.log4j.SimpleLayout

Note: the placement of the properties file and the argument passed to the PropertyConfigurator.configure() method is annoyingly difficult when using Eclipse. Please see a better working example below.

myAppender in this properties file is, of course, the very variable in the code. It must be identical. Some examples of console output while varying SimpleLayout in the properties file are:

SimpleLayout

Yeah, this is a sort of default. Here's what comes out in the Eclipse Console tab when you run the code:

INFO - Parameters passed to method do_something are: 99, 542.0
DEBUG - Operation performed successfully
ERROR - Value of X is 439.8585

PatternLayout

With this scheme, you lose the labels for whatever reason there is behind that.

Parameters passed to method do_something are: 99, 542.0
Operation performed successfully
Value of X is 439.8585

HTMLLayout

This gives you HTML output that can be nicely browsed:

Log session start time Tue Oct 14 16:27:31 MDT 2008

Time Thread Level Category Message
0 main INFO com.etretatlogiciels.samples.logging.Log4J Parameters passed to method do_something are: 99, 542.0
2 main DEBUG com.etretatlogiciels.samples.logging.Log4J Operation performed successfully
2 main ERROR com.etretatlogiciels.samples.logging.Log4J Value of X is 439.8585

DateLayout

Deprecated? I don't know why this isn't working in my set up, except that I looked at the class documentation and much of it was deprecated. I'll be figuring this out because most logging is done using a timestamp for obvious reasons.

java.lang.ClassNotFoundException:org.apache.log4j.DateLayout

XMLLayout

Didn't work. The doc doesn't say it's deprecated (unlike DateLayout) and it's also not full, legal XML, but only XML that you can tuck inside the surrounding tag of a full, legal file.

java.lang.ClassNotFoundException:org.apache.log4j.XMLLayout

A more basic variation

A more basic behavior can be had by simplifying the code above. You don't need a log4j.properties file.

package com.etretatlogiciels.samples.log4j;

import org.apache.log4j.Logger;
import org.apache.log4j.BasicConfigurator;

public class Log4J
{
	  private static Logger   logger = Logger.getLogger( Log4J.class.getName() );
	  private SimpleLayout    myLayout;
	  private Appender        myAppender;

  public Log4J()
  {
	    logger.setLevel( Level.INFO );
	    myLayout   = new SimpleLayout();
	    myAppender = new ConsoleAppender( myLayout );
	    logger.addAppender( myAppender );
  }

  public static void do_something( int a, float b )
  {
	    double   X = b - a - 3.1415;

	    logger.info ( "Parameters passed to method do_something are: " + a + ", " + b );
	    logger.debug( "Operation performed successfully" );
	    logger.error( "Value of X is " + X );
  }

  public static void main( String[] args )
  {
	    BasicConfigurator.configure();
	    do_something( 99, 542 );
  }
}

Other behavior variations

If you change the properties file above to use info in place of debug:

log4j.rootLogger=info, appender
log4j.appender.appender=org.apache.log4j.ConsoleAppender
log4j.appender.appender.layout=org.apache.log4j.DateLayout

...you get (in simple-layout mode):

INFO - Parameters passed to method do_something are: 99, 542.0
ERROR - Value of X is 439.8585

...and you're now missing the DEBUG log line because DEBUG is left off and ERROR is higher in value. (The appender puts out the level set to, plus all higher-valued levels). The levels in ascending order are:

  1. DEBUG
  2. INFO
  3. WARN
  4. ERROR
  5. FATAL

To console, to file, to ?

We don't vary ConsoleAppender to FileAppender, JDBCAppender, SocketAppender, etc. in this sample because we want the output to go othe console for our demonstration. However, these are possibilities. What additional information must be supplied we don't yet know.


Logging level

To change the "global" (whole application) logging level (from INFO to DEBUG, etc.), edit log4j.properties:

log4j.rootLogger=DEBUG, ...

It's important to understand levels and their effect on what's to be logged. If the event level is greater or equal to the logger's level, then that even is printed out (wherever and however its appender is supposed to put it out). Crudely put, if the even level is set to TRACE, then everything gets printed. Here's a table:

FATAL ERROR WARN INFO DEBUG TRACE ALL
OFF
FATAL x
ERROR x x
WARN x x x
INFO x x x x
DEBUG x x x x x
TRACE x x x x x x
ALL x x x x x x x

For example, if the event level is set to INFO, whose cell colors in the table above are highlighted green, the following logging statements would reach the log file:

...but, not DEBUG or TRACE.

In logback.xml or whatever configuration file you're using, INFO is set thus:

<logger name="com.etretatlogiciels" level="INFO" additivity="false">
  <appender-ref ref="CONSOLE"/>
</logger>

More on properties: set logging level

The properties file (or the .xml variant) can be used to set the logging level for classes individually.

log4j.logger.com.acme=DEBUG
log4j.logger.org.springframework=DEBUG
log4j.logger.javax.faces=TRACE
log4j.logger.org.apache.myfaces=TRACE
log4j.logger.com.sun.faces=INFO

Performance

There are performance issues with log4j. If it's configured not to log, then it adds only the overhead of a function call and an integer compare. However, if the parameters to logger are complex conversions, they will be performed (needlessly) anyway. A good way around this is:

if( log.isDebugEnabled() )
    log.debug( "Entry number: " + i + " is " + String.valueOf( entry[ i ] ) );

PatternLayout

This class supports all sorts of interesting equivalent features to the C preprocessor like __FILENAME__ and __LINE__. However, these are implemented at runtime by log4j, require performing a stack crawl, and are generally too poor in performance to warrant using.

An alternative to scrapping the idea entirely is to lock out their use via a check for circumstances, assuming these can be detected, as noted earlier in this section.

The doc for this feature is found at: http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PatternLayout.html


Web applications

log4j is particularly useful in web and distributed applications where using a debugger like the one in Eclipse is difficult or impossible. For Tomcat use, place log4j.properties where it will be copied down under the WEB-INF/classes subdirectory, for example, project-name/src.


log4j from Eclipse

Set up an Eclipse project and do some logging in it, for example.

package com.mycompany.pkg;

import org.apache.log4j.Logger;

public class MyClass
{
   private static final Logger log = Logger.getLogger( MyClass.class );
   .
   .
   .
   public void someMethod()
   {
      log.debug( "This is a message at DEBUG level in the log file" );
      .
      .
      .
}

Put log4j.properties directly into the src folder/directory of the project because to subsume it under src/properties or some other handy path requires more work.

Where to put log4j.properties?

In theory, this should be adjustable by the addition of

	import org.apache.log4j.PropertyConfigurator;
	.
	.
	.
	PropertyConfigurator.configure( "properties/log4j.properties" );
		

...but this does not seem to work unless you a) create a new folder at the same hierarchical level as src (let's call it properties for our example), then make it a "source" folder by right-clicking on it, choosing Build Path -> Use as Source Folder.

Put log4j.properties down under this new properties folder. Use refactoring (move) if you created it somewhere else first and want to relocate it. Inspect this picture of what I was doing one day along these lines. The logger went to the console and shows up as ERROR messages.

If log4j cannot find the properties file, a nasty gram will issue such as:


log4j:WARN No appenders could be found for logger (com.mycompany.pkg.MyClass).
log4j:WARN Please initialize the log4j system properly.

...and the logged message will (probably) come out anyway in the Eclipse console view, but you should set this up to work correctly (the point of this blurb).

Despite our message, we'll send this to the Eclipse console during our run. In consequence, set up log4j.properties thus. This is a good place to get started.

# The root logger is assigned priority level DEBUG and an appender named
# myAppender.
log4j.rootLogger=DEBUG,myAppender

# The appender's type specified as ConsoleAppender, i.e. log output to
# the Eclipse console. (Could have been FileAppender.)
log4j.appender.myAppender=org.apache.log4j.ConsoleAppender

# The appender is assigned a layout SimpleLayout. SimpleLayout will
# include only priority level of the log statement and the log statement
# itself in the log output.
log4j.appender.myAppender.layout=org.apache.log4j.SimpleLayout

log4j.properties with support for JSF and Spring

I shamelessly ripped this off from the web for future use.

log4j.rootLogger=DEBUG,myAppender

log4j.appender.myAppender=org.apache.log4j.RollingFileAppender
log4j.appender.myAppender.file=/var/log/myapp.log
log4j.appender.myAppender.maxFileSize=10MB
log4j.appender.myAppender.maxBackupIndex=10
log4j.appender.myAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.myAppender.layout.ConversionPattern=%5p | %d | %F:%L | %m%n

log4j.logger.com.acme=DEBUG
log4j.logger.org.springframework=DEBUG
log4j.logger.javax.faces=DEBUG
log4j.logger.org.apache.myfaces=DEBUG
log4j.logger.com.sun.faces=DEBUG

Java service wrapper

A service wrapper wraps around another program to allow it to live in a more useful context. For example, the Java service wrapper from Tanuki Software manages, among an array of useful solutions to problems, the logging of an application written in Java.

The Java service wrapper places an initial log line prefix prior to anything formally logged to log4j as specified in wrapper.conf. This can be confusing when attempting, without success, to tailor the lines logged to your log file. You quickly realize that there is a leftmost "column" over whose format you seemingly have no power. This is because it's defined in a different configuration file than log4j.properties, usually wrapper.conf.

See, primarily, http://wrapper.tanukisoftware.org/doc/english/introduction.html

wrapper.logfile.format

For example,

wrapper.logfile.format=LPTM

...yields

INFO | wrapper  | 2012/03/23 13:45:33.560 | INFO my message stuff...

You can turn lines logged into blank lines using

wrapper.logfile.format=

...or constrain the logfile to just that content you are trying to log via the usual log4j mechanisms:

wrapper.logfile.format=M

Changing level at runtime

It's possible, and simple, to change the logging level at runtime:

import org.apache.log4j.Level;
import org.apache.log4j.Logger;
...

{
    ...
    Logger root = Logger.getRootLogger();
    Level  level = Level.toLevel( "DEBUG" );

    root.setLevel( level );
    ...
}

Some links...

...on some topics.


A great example of a production properties file...

Please see important note on using ${catalina.home} here.

# This controls /var/log/tomcat6/catalina.out on our servers such that this file doesn't
# grow beyond 550Mb, rolls each day and only 5 days back are kept.
log4j.rootLogger=TRACE,console,tomcat,splunkable

# Rolling-file appender for Tomcat, goes to catalina.out. ----------------------------
log4j.appender.tomcat.Threshold=INFO
log4j.appender.tomcat=org.apache.log4j.DailyRollingFileAppender
log4j.appender.tomcat.DatePattern='.'yyy-MM-dd
log4j.appender.tomcat.File=${catalina.base}/logs/catalina.out
log4j.appender.tomcat.file.MaxFileSize=500Mb
log4j.appender.tomcat.file.MaxBackupIndex=5
log4j.appender.tomcat.layout=org.apache.log4j.PatternLayout
log4j.appender.tomcat.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

# Splunkable log ---------------------------------------------------------------------
log4j.appender.splunkable.Threshold=TRACE
log4j.appender.splunkable=org.apache.log4j.RollingFileAppender
log4j.appender.splunkable.File=${catalina.base}/logs/accountmgr.log
log4j.appender.splunkable.MaxFileSize=1Gb
log4j.appender.splunkable.MaxBackupIndex=7
log4j.appender.splunkable.layout=org.apache.log4j.PatternLayout
log4j.appender.splunkable.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}: %m%n

log4j.category.com.acme.web.uas.logging=TRACE,splunkable
log4j.additivity.com.acme.web.uas.logging=false

# This logs output to the Eclipse console when running in that mode. -----------------
log4j.appender.console.Threshold=TRACE
log4j.appender.console=org.apache.log4j.ConsoleAppender
log4j.appender.console.layout=org.apache.log4j.SimpleLayout
log4j.appender.console.Target=System.out
log4j.appender.console.layout=org.apache.log4j.PatternLayout
log4j.appender.console.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

## Legend ----------------------------------------------------------------------------
# Conversion-    What's printed?
#    specifier
# %d{ABSOLUTE}   hh:mm:ss,mmm
# %5p            one of { INFO, DEBUG, TRACE, WARN, ERROR }
# %c{1}          (simple) class name
# %L             line number in Java file
# -              a hyphen
# %m             caller-supplied message
# %n             platform-specific line separation character (\n)
#
# E.g.: 17:12:40,013 DEBUG MongoDB:145 - Initializing Morphia for use on accountdb

Errors encountered and solved

I went over a complex logging scheme, such as the one illustrated above, and afterward noticed that all my JUnit tests were prefixed with the following.


log4j:ERROR setFile(null,true) call failed.
java.io.FileNotFoundException: /logs/catalina.out (No such file or directory)
	at java.io.FileOutputStream.open(Native Method)
	at java.io.FileOutputStream.(FileOutputStream.java:212)
	at java.io.FileOutputStream.(FileOutputStream.java:136)
	at org.apache.log4j.FileAppender.setFile(FileAppender.java:294)
	at org.apache.log4j.FileAppender.activateOptions(FileAppender.java:165)
	at org.apache.log4j.DailyRollingFileAppender.activateOptions(DailyRollingFileAppender.java:223)
.
.
.

This turned out to be quite simple. When I was running my JUnit tests, the very explicit treatment of Tomcat and other logging I put into log4j.properties was asking Log4j to open files that didn't exist in the environment.

The solution was simply to put a separate copy of log4j.properties under the test subdirectory of my project (parallel to the origin one under the src subdirectory). The final result was something like:

log4j.rootLogger=TRACE,console
log4j.appender.console.Threshold=TRACE
log4j.appender.console=org.apache.log4j.ConsoleAppender
log4j.appender.console.layout=org.apache.log4j.SimpleLayout
log4j.appender.console.Target=System.out
log4j.appender.console.layout=org.apache.log4j.PatternLayout
log4j.appender.console.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

Locking when logging—performance considerations

See article, here.


Configuring log4j starting in v2

This is different from how it was done in previous versions.

import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.config.Configuration;
import org.apache.logging.log4j.core.config.LoggerConfig;
.
.
.
    if( LOGGING )
    {
      // turn on logging to INFO level...
      LoggerContext ctx = ( LoggerContext ) LogManager.getContext( false );
      Configuration config = ctx.getConfiguration();
      LoggerConfig loggerConfig = config.getLoggerConfig( LogManager.ROOT_LOGGER_NAME );
      loggerConfig.setLevel( Level.INFO );
      ctx.updateLoggers();
   }
.
.
.

Log4j2

...doesn't recognize log4j.properties but XML, JSON and other formats. And the name is by default, log4j2. Here's a working sample:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration xmlns="http://logging.apache.org/log4j/2.0/config">
  <Properties>
    <Property name="LEVEL">trace</Property> <!-- Change to info in production -->
    <Property name="log-path">/var/log/search/</Property>
    <Property name="logfile-size">1 GB</Property>
    <Property name="cda-feeder">cda-feeder</Property>

    <!-- The console pattern gives calling method name and line numbers (%L). E.g.:
    TRACE | 2015-09-17 10:15:02 | [main] logging.Log4j2Example (Log4j2Example.java:38) - This will be printed on trace
      -->
    <Property name="console-pattern">%d{ABSOLUTE} %5p %c{1}:%L - %m%n</Property>

    <!-- The file pattern is shorter and more static; other differences are due simply to RollingFileAppender. E.g.:
    10:15:02,987 TRACE Log4j2Example: This will be printed on trace
      -->
    <Property name="file-pattern">   %d{ABSOLUTE} %5p %c{1}: %m%n    </Property>
  </Properties>

  <Appenders>
    <Console name="console" target="SYSTEM_OUT">
      <PatternLayout pattern="%-5p | %d{yyyy-MM-dd HH:mm:ss} | [%t] %C{2} (%F:%L) - %m%n" />
    </Console>

    <RollingFile name="rollingfile"
                 fileName="${log-path}/${cda-feeder}.log"
                 filePattern="${log-path}/${cda-feeder}-%d{yyyy-MM-dd}-%i.log"
                 append="true">
      <PatternLayout pattern="${file-pattern}" />
      <Policies>
        <SizeBasedTriggeringPolicy size="${logfile-size}" />
      </Policies>
      <DefaultRolloverStrategy max="4" />
    </RollingFile>
  </Appenders>

  <Loggers>
    <Logger name="root" level="${LEVEL}" additivity="false">
      <appender-ref ref="rollingfile" level="${LEVEL}" />
    </Logger>

    <Root level="${LEVEL}" additivity="false">
      <AppenderRef ref="console" />
      <AppenderRef ref="rollingfile" />
    </Root>
  </Loggers>

</Configuration>

Logging sins...

A list of don'ts...

  1. Don't log sensitive information.
  2. Don't log too much (exhausting disk space).
  3. Don't log cryptic messages (like, "Operation failed.").
  4. Don't use a single log file.
  5. Don't choose incorrect log levels.
  6. FATAL for errors that cause the application to crash or fail to start.
    ERROR for technical issues that need to be resolved for proper functioning of the system.
    WARN for temporary problems or unexpected behavior that does not significantly hamper the functioning of the application.
    INFO for messages that describe what is happening in the application.
    DEBUG for messages that could be useful in debugging an issue.
    TRACE, like DEBUG, but for more detailed events.
  7. Don't crush performance with logging. Don't log during
    loops
    file I/O operations
  8. Don't log to the console (except episodically, like early on, during test runs, etc.).