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?

Answer 1

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

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

Answer 3

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