August 24, 2009

Configure Log4J DailyRollingFileAppender with custom PatternLayout

For some time I haven been planning to learn the mystic configuration of the org.apache.log4j.PatternLayout for Log4j and finally I have taken the time to do so.
  • c - The calling class name, if giving without precision is the fully qualified name returned.
  • C - The fully qualified class name.
  • d - The date of the logging request, can be formatted with java.text.SimpleDateFormat, i.e. %d{yyyy-MM-dd}
  • F - The name of the calling File.
  • l - The location information, same as %C%M(%F:%L). This can be slow.
  • L - The calling class line number
  • m - The logging message.
  • M - The calling class method.
  • n - The platform dependent line separator.
  • p - The logging Level.
  • r - The relative date in millisecond since application start.
  • t - The invoking thread.
  • [x|X] - the Message Diagnostic (MDC) information.

Now for some example. To be compliant with large open-source project such as Hibernate Annotation we use SLF4J as Logger interface. To use SLF4J, simply add the following to your Maven pom.xml
<dependency>

<groupId>org.slf4j</groupId>

<artifactId>slf4j-log4j12</artifactId>

<version>1.4.2</version>

</dependency>

And if we run 'mvn dependency:tree', we see that the artifact also contains the log4j.jar implementation.
[INFO] Scanning for projects...

[INFO] Searching repository for plugin with prefix: 'dependency'.

[INFO] ------------------------------------------------------------------------

[INFO] Building Log4J Test

[INFO]    task-segment: [dependency:tree]

[INFO] ------------------------------------------------------------------------

[INFO] [dependency:tree]

[INFO] se.msc.development:log4j-test:jar:1.0-SNAPSHOT

[INFO] +- org.slf4j:slf4j-log4j12:jar:1.4.2:compile

[INFO] |  +- org.slf4j:slf4j-api:jar:1.4.2:compile

[INFO] |  \- log4j:log4j:jar:1.2.13:compile

[INFO] +- javax.mail:mail:jar:1.4.1:compile

[INFO] |  \- javax.activation:activation:jar:1.1.1:compile

[INFO] \- junit:junit:jar:4.5:test

[INFO] ------------------------------------------------------------------------

[INFO] BUILD SUCCESSFUL

[INFO] ------------------------------------------------------------------------

[INFO] Total time: 4 seconds

[INFO] Finished at: Mon Aug 24 03:05:27 CEST 2009

[INFO] Final Memory: 12M/144M

[INFO] ------------------------------------------------------------------------

And here follows an example of how to use SLF4J in your code.
package se.msc.log4j;

import org.junit.Test;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Log4JTest {
//import org.slf4j.Logger;
//import org.slf4j.LoggerFactory;
private static final Logger log = LoggerFactory.getLogger(Log4JTest.class);

//import org.apache.log4j.Logger;
//private static final Logger log = Logger.getLogger(Log4JTest.class);

@Test
public void testFoo() throws Exception {
log.info("Info log message.");
log.error("Fatal log message.", new NullPointerException("Null pointer exceptopn."));
}

}

An the log4j configuration file log4j.properties
# configure the root logger
log4j.rootLogger=INFO, STDOUT, DAILY

# configure the console appender
log4j.appender.STDOUT=org.apache.log4j.ConsoleAppender
log4j.appender.STDOUT.Target=System.out
log4j.appender.STDOUT.layout=org.apache.log4j.PatternLayout
log4j.appender.STDOUT.layout.conversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%p] %c:%L - %m%n

# configure the daily rolling file appender
log4j.appender.DAILY=org.apache.log4j.DailyRollingFileAppender
log4j.appender.DAILY.File=/tmp/log4j/log4jtest.log
log4j.appender.DAILY.DatePattern='.'yyyy-MM-dd
log4j.appender.DAILY.layout=org.apache.log4j.PatternLayout
log4j.appender.DAILY.layout.conversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%p] %c:%L - %m%n

and when running the JUnit test:
2009-08-24 03:00:47.775 [INFO] se.msc.log4j.Log4JTest:18 - Info log message.
2009-08-24 03:00:47.783 [ERROR] se.msc.log4j.Log4JTest:19 - Fatal log message.
java.lang.NullPointerException: Null pointer exceptopn.
at se.msc.log4j.Log4JTest.testFoo(Log4JTest.java:19)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:73)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:46)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:180)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:41)
at org.junit.runners.ParentRunner$1.evaluate(ParentRunner.java:173)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
at org.junit.runners.ParentRunner.run(ParentRunner.java:220)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:45)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)

And now I final word about the DatePattern for the org.apache.log4j.DailyRollingFileAppender:
log4j.appender.DAILY.DatePattern='.'yyyy-MM-dd-a

Rolls over at midnight each day, as is the expected behaviour of a rolling log.

1 comment:

Drew Noakes said...

According to the documentation on the class, the date pattern "'.'yyyy-MM-dd-a" rolls over at midday, not midnight. Drop the trailing "-a" for midnight rollovers.