Line number does not show up using log4j async appender in JBoss EAP

Solution Verified - Updated -

Environment

  • Red Hat JBoss Enterprise Application Platform (EAP) 7.x
  • Red Hat JBoss Enterprise Application Platform (EAP) 6.x

Issue

We are using log4j.xml in our application and using an async appender to capture logging. Appender configuration looks like this with %L to capture the line number in our ConversionPattern:

<appender name="console" class="org.apache.log4j.ConsoleAppender">
    <param name="Target" value="System.out" />
    <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n" />
    </layout>
</appender>
<appender name="async" class="org.apache.log4j.AsyncAppender">
    <param name="BufferSize" value="500"/>
    <appender-ref ref="appender"/>
</appender>

But with async appender we can't see line number of logger class in log file, it only shows number '1' for all log messages, like this:
2017-09-13 11:12:25 WARN WsTest:22 - Test logging

If we remove async it works fine.

Resolution

This is the expected default behavior for Log4j, but it's not very well documented in Log4j 1.2.

This page does document it for Log4j2 though and explain the reasons why it works like this:
https://logging.apache.org/log4j/log4j-2.3/manual/async.html#Location

Location, location, location...
If one of the layouts is configured with a location-related attribute like HTML locationInfo, or one of the patterns %C or $class, %F or %file, %l or %location, %L or %line, %M or %method, Log4j will take a snapshot of the stack, and walk the stack trace to find the location information.

This is an expensive operation: 1.3 - 5 times slower for synchronous loggers. Synchronous loggers wait as long as possible before they take this stack snapshot. If no location is required, the snapshot will never be taken.

However, asynchronous loggers need to make this decision before passing the log message to another thread; the location information will be lost after that point. The performance impact of taking a stack trace snapshot is even higher for asynchronous loggers: logging with location is 4 - 20 times slower than without location. For this reason, asynchronous loggers and asynchronous appenders do not include location information by default.

You can override the default behaviour in your logger or asynchronous appender configuration by specifying includeLocation="true".

Looking at the Log4j 1.2 AsyncAppender page reveals that there is a setLocationInfo() method on the class:
https://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/AsyncAppender.html

If you update the async appender configuration to pass this property with value "true" like this:

<appender name="async" class="org.apache.log4j.AsyncAppender">
    <param name="BufferSize" value="500"/>
    <param name="LocationInfo" value="true"/>
    <appender-ref ref="console" ></appender>
</appender>

After making this change, the line number shows up correctly:
2017-09-13 11:12:25 WARN WsTest:22 - Test logging

If the message ends up getting logged then the overhead doesn't really matter, you were going to have to take a snapshot of the stack anyway. However, if the message is NOT going to get logged (due to being lower priority) then this overhead would be wasted. So, take this into account when deciding whether to use LocationInfo or not.

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.

Comments