Why log4j 2 does not log method name for app and unit tests

Question

My Log4j2 config file looks like:

<Appenders>
  <RollingRandomAccessFile name="APP_LOG_APPENDER" fileName="${sys:baseLogPath}/${appLogFileName}.log"
            filePattern="${sys:baseLogPath}/backups/$${date:yyyy-MM}/${appLogFileName}-%d{yyyy-MM-dd}-%i.log.gz" immediateFlush="false">
    <PatternLayout>
      <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [Thread: %t] %level [%c][%M] - %msg%n</Pattern>
    </PatternLayout>
    <Policies>
      <TimeBasedTriggeringPolicy />
      <SizeBasedTriggeringPolicy size="50 MB" />
    </Policies>
    <DefaultRolloverStrategy max="20"/>
  </RollingRandomAccessFile>
</Appenders>
<Loggers>
  <Root level="debug" additivity="false">
    <AppenderRef ref="APP_LOG_APPENDER" />
  </Root>
</Loggers>

Logger statements in class MyClass

public class MyClass {
  private final static org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger(MyClass.class);
  public void someMethod() {
    logger.debug("Some sample string at DEBUG level....");
    logger.info("Some sample string at INFO level....");
    logger.warn("Some sample string at WARN level....");
    logger.error("Some sample string at ERROR level....");
  }
}

The log messages are coming out as:

2016-04-11 12:32:31.245 [Thread: main] DEBUG [com.demo.MyClass][] - Some sample string at DEBUG level....
2016-04-11 12:32:31.245 [Thread: main] INFO [com.demo.MyClass][] - Some sample string at INFO level....
2016-04-11 12:32:31.245 [Thread: main] WARN [com.demo.MyClass][] - Some sample string at WARN level....
2016-04-11 12:32:31.245 [Thread: main] ERROR [com.demo.MyClass][] - Some sample string at ERROR level....

I am using log4j2-2.5 version and corresponding SLF4J API.

Could someone help me understand why is this happening?

Jamnes

Answer 1

Did you turn on Async Logger? (e.g. by system property -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector)

If so, it is one of the scenario that Location Information is not included. (Ref: https://logging.apache.org/log4j/2.x/manual/layouts.html#LocationInformation). You may explicitly turn on location info by

<Root level="debug" includeLocation="true"> 
    ....

However, I will strongly suggest not including method name in your log message, as taking such information from stack trace is expensive and slow

Ardine

Yes, I had enabled async logging. And, your solution works. Thanks a lot. While I agree location info has performance impacts, but its a vital information. I need to think how can I print it without making log4j extract it from stacktrace (may be reading method name through a spring aspect and writing it to MDC Context?). Anyways, I guess for non-prod environment, I can accommodate this performance cost, so, I will enable this flag on non-prod log configs and disable it in prod. – Jamnes

Java 9 has a new StackWalker API that log4j will be leveraging. While it still has overhead it is much faster than working with a stack trace from a Throwable. – Skill

@Jamnes imho, as long as it is not done in mission critical production system, that's fine doing so :) Using AOP approach, especially by proxy-based AOP of Spring, is going to cause you a lot of trouble if you want to have fine-grained method info (e.g. you won't be able to log the proper method if the method is called internally in the object) – Ardine

Answer 2

for me next configurations are working well (without includeLocation="true" option enabled):

src/main/resources/log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Properties>
        <Property name="PID">%5X{pid}</Property>
        <Property name="LOG_EXCEPTION_CONVERSION_WORD">%xEx</Property>
        <Property name="LOG_LEVEL_PATTERN">%5p</Property>
        <Property name="LOG_PATTERN">%style{%d{yyyy-MM-dd HH:mm:ss.SSS}}{dim} %highlight{${LOG_LEVEL_PATTERN}} %style{${sys:PID}}{magenta} %style{---}{dim} %style{[%15.15t]}{dim} %style{%-40.40c{1.}}{cyan} %style{%22.22M}{magenta} %style{:}{faint} %m%n${sys:LOG_EXCEPTION_CONVERSION_WORD}</Property>
    </Properties>
    <Appenders>
        <Console name="ConsoleAppender" target="SYSTEM_OUT" follow="true">
            <PatternLayout pattern="${LOG_PATTERN}" />
        </Console>
    </Appenders>
    <Loggers>
        <logger name="com.github.daggerok" level="ALL" additivity="false">
            <appender-ref ref="ConsoleAppender"/>
        </logger>
        <Root level="ALL">
            <AppenderRef ref="ConsoleAppender"/>
        </Root>
    </Loggers>
</Configuration>

build.gradle

dependencies {
    implementation(platform('org.apache.logging.log4j:log4j-bom:2.12.1'))
    implementation 'org.apache.logging.log4j:log4j-api'
    implementation 'org.apache.logging.log4j:log4j-core'
    // ...
}

checkout this Travis CI build log output

> Task :test
com.github.daggerok.usermanagement.domain.user.UserEventSourcedRepositoryTest > should save user STANDARD_OUT
    2019-08-17 18:23:53.358 DEBUG       --- [    Test worker] u.d.u.UserInMemoryEventSourcedRepository                   save : about to save User(efb230a1-679e-4aac-b6c2-7eb25142de30) aggregate...
    2019-08-17 18:23:53.375 DEBUG       --- [    Test worker] u.d.u.UserInMemoryEventSourcedRepository                   save : cleared User(efb230a1-679e-4aac-b6c2-7eb25142de30) aggregate events.
    2019-08-17 18:23:53.388 DEBUG       --- [    Test worker] u.d.u.UserInMemoryEventSourcedRepository                   save : aggregate User(efb230a1-679e-4aac-b6c2-7eb25142de30) saved.
    2019-08-17 18:23:53.392 DEBUG       --- [    Test worker] u.d.u.UserInMemoryEventSourcedRepository                   find : start rebuild process for aggregate: efb230a1-679e-4aac-b6c2-7eb25142de30

Reannareap

Answer 3

Below snippets were used to get Method name, time stamp, line number in the specific class with class name too.

This is Snippet for logging in Console You need to basically put this in log4j2.properties file which should be present in resource level in Maven projects

rootLogger.level = debug
appenders = console

appender.console.type = Console
appender.console.name = STDOUT
appender.console.layout.type = PatternLayout
appender.console.layout.pattern =%d{yyyy-MM-dd HH:mm:ss} (%F:%L) %M()- %m%n

This is Snippet for logging in a File

rootLogger.level = debug
property.filename = {path to log file}
appenders = R

  
appender.R.type = RollingFile
appender.R.name = File
appender.R.fileName = ${filename}
appender.R.filePattern = ${filename}.%d{yyyy-MM-dd}
appender.R.layout.type = PatternLayout
appender.R.layout.pattern = %d{yyyy-MM-dd HH:mm:ss} (%F:%L) %M()- %m%n
appender.R.policies.type = Policies
appender.R.policies.time.type = TimeBasedTriggeringPolicy
appender.R.policies.time.interval = 1

rootLogger.appenderRef.console.ref = STDOUT
rootLogger.appenderRef.R.ref = File

Here is the sample output

WaitForPageToLoad() is the Method where logger statement present

2021-12-24 05:51:47 (Utils.java:201) waitForPageToLoad() - Waiting for page to load

Imply