A Log4J format example

Log4J formatting FAQ: Can you share a Log4J output/logging format example?

Sure. I'll share a Java Log4J format example that I'm pretty happy with.

I've used the following Log4J logging format quite a bit lately, as I've been working on a headless Java app that can be deployed on thousands of computers, and I was looking for a good Log4J format that was easily readable by humans, and also easy to parse by computers. Here's what my Log4J output format look like these days:

DEBUG | 2008-09-06 10:51:44,817 | DefaultBeanDefinitionDocumentReader.java | 86 | Loading bean definitions
DEBUG | 2008-09-06 10:51:44,848 | AbstractBeanDefinitionReader.java | 185 | Loaded 5 bean definitions from location pattern [samContext.xml]
INFO | 2008-09-06 10:51:44,848 | XmlBeanDefinitionReader.java | 323 | Loading XML bean definitions from class path resource [tmfContext.xml]
DEBUG | 2008-09-06 10:51:44,848 | DefaultDocumentLoader.java | 72 | Using JAXP provider [com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl]
DEBUG | 2008-09-06 10:51:44,848 | BeansDtdResolver.java | 72 | Found beans DTD [http://www.springframework.org/dtd/spring-beans.dtd] in classpath: spring-beans.dtd
DEBUG | 2008-09-06 10:51:44,864 | DefaultBeanDefinitionDocumentReader.java | 86 | Loading bean definitions
DEBUG | 2008-09-06 10:51:45,458 | AbstractAutowireCapableBeanFactory.java | 411 | Finished creating instance of bean 'MS-SQL'
DEBUG | 2008-09-06 10:51:45,458 | DefaultSingletonBeanRegistry.java | 213 | Creating shared instance of singleton bean 'MySQL'
DEBUG | 2008-09-06 10:51:45,458 | AbstractAutowireCapableBeanFactory.java | 383 | Creating instance of bean 'MySQL'
DEBUG | 2008-09-06 10:51:45,458 | AbstractAutowireCapableBeanFactory.java | 459 | Eagerly caching bean 'MySQL' to allow for resolving potential circular references
DEBUG | 2008-09-06 10:51:45,458 | AbstractAutowireCapableBeanFactory.java | 411 | Finished creating instance of bean 'MySQL'
DEBUG | 2008-09-06 10:51:45,458 | DefaultSingletonBeanRegistry.java | 213 | Creating shared instance of singleton bean 'Oracle'
DEBUG | 2008-09-06 10:51:45,458 | AbstractAutowireCapableBeanFactory.java | 383 | Creating instance of bean 'Oracle'
DEBUG | 2008-09-06 10:51:45,458 | AbstractAutowireCapableBeanFactory.java | 459 | Eagerly caching bean 'Oracle' to allow for resolving potential circular references
DEBUG | 2008-09-06 10:51:45,473 | AbstractAutowireCapableBeanFactory.java | 411 | Finished creating instance of bean 'Oracle'
DEBUG | 2008-09-06 10:51:45,473 | DefaultSingletonBeanRegistry.java | 213 | Creating shared instance of singleton bean 'PostgreSQL'
DEBUG | 2008-09-06 10:51:45,473 | AbstractAutowireCapableBeanFactory.java | 383 | Creating instance of bean 'PostgreSQL'
DEBUG | 2008-09-06 10:51:45,473 | AbstractAutowireCapableBeanFactory.java | 459 | Eagerly caching bean 'PostgreSQL' to allow for resolving potential circular references
DEBUG | 2008-09-06 10:51:45,473 | AbstractAutowireCapableBeanFactory.java | 411 | Finished creating instance of bean 'PostgreSQL'
INFO | 2008-09-06 10:51:45,473 | SQLErrorCodesFactory.java | 128 | SQLErrorCodes loaded: [DB2, Derby, H2, HSQL, Informix, MS-SQL, MySQL, Oracle, PostgreSQL, Sybase]

To be clear, these are some example Log4J output records which were generated when my program was running.

As you can see, I like to split the columns of Log4J formatted output data using the "|" character, which you're not too likely to find in program output. This Log4J format makes it easier to parse my Log4J output files with a Perl or Ruby script when I need to do something like that, and I think it makes the files a little easier on the human eye as well.

Note that I'd really like to include the Java method name in this output, but the Log4J documentation says this can be a pretty expensive computational task, and you're better off not doing it. The source code line number in the fourth column gives you the exact line number in your Java class where this line of output was printed from anyway, so it's not a great loss.

Log4J format - My Log4J log4j.properties file

Now that you've seen my Log4J formatted logging output, here's the log4j.properties file that was used to create that output format:

log4j.rootLogger=INFO, stdout

log4j.appender.stdout=org.apache.log4j.ConsoleAppender

# here's where I specify the layout and the pattern
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%5p | %d | %F | %L | %m%n

log4j.logger.com.devdaily.myapp=DEBUG
log4j.logger.org.springframework=DEBUG

As you can see, my Log4J properties file is very small. If you want to use this format in your Log4J output all you really need to do is copy and paste these two lines of code into your log4j.properties file:

log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%5p | %d | %F | %L | %m%n

Finally, note that the name stdout needs to match the name of your appender in your Log4J properties file.

Log4J format - What's related

As I wrap up my current collection of Log4J examples, here's a link to my other Log4J tutorials:

Comments

Permalink

Liked the pipes! Be aware though that %F and %L also are slow to compute. Also if you're in a J2EE app-container, shared by many like-minded apps with similar filenames, it could be useful to see the category name(%c) instead of the filename (%F). The thread could also be useful if you'd like to isolate. Tried your pipeversion and I kind of like this ConversionPattern:

%5p | %d{dd-MM-yyyy HH:mm:ss,SSS} | %t | %c | %m%n

(Telling how to parse the date is also faster than just %d)