Log4j2 doesn't log the PID properly

[wilkinsona]

The logging of the PID with Log4j2 is behaving rather strangely. For the first few log lines its ????, it then changes to the process's actual PID, before changing back to ????:

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                        

2017-04-07 14:37:36.443  INFO ???? --- [           main] s.a.l.SampleActuatorLog4J2Application    : Starting SampleActuatorLog4J2Application on aw-rmbp.home with PID 56404 (/Users/awilkinson/dev/spring/spring-boot/master/spring-boot-samples/spring-boot-sample-actuator-log4j2/target/classes started by awilkinson in /Users/awilkinson/dev/spring/spring-boot/master/spring-boot-samples/spring-boot-sample-actuator-log4j2)
2017-04-07 14:37:36.450  INFO ???? --- [           main] s.a.l.SampleActuatorLog4J2Application    : No active profile set, falling back to default profiles: default
2017-04-07 14:37:36.505  INFO ???? --- [           main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@7776ab: startup date [Fri Apr 07 14:37:36 BST 2017]; root of context hierarchy
2017-04-07 14:37:37.815  INFO ???? --- [           main] o.s.b.w.e.t.TomcatWebServer              : Tomcat initialized with port(s): 8080 (http)
2017-04-07 14:37:37.838  INFO 56404 --- [           main] o.a.c.c.StandardService                  : Starting service Tomcat
2017-04-07 14:37:37.839  INFO 56404 --- [           main] o.a.c.c.StandardEngine                   : Starting Servlet Engine: Apache Tomcat/8.5.13
2017-04-07 14:37:37.924  INFO 56404 --- [ost-startStop-1] o.a.c.c.C.[.[.[/]                        : Initializing Spring embedded WebApplicationContext
2017-04-07 14:37:37.925  INFO ???? --- [ost-startStop-1] o.s.w.c.ContextLoader                    : Root WebApplicationContext: initialization completed in 1425 ms
2017-04-07 14:37:38.155  INFO ???? --- [ost-startStop-1] o.s.b.w.s.FilterRegistrationBean         : Mapping filter: 'metricsFilter' to: [/*]
2017-04-07 14:37:38.155  INFO ???? --- [ost-startStop-1] o.s.b.w.s.FilterRegistrationBean         : Mapping filter: 'characterEncodingFilter' to: [/*]
2017-04-07 14:37:38.155  INFO ???? --- [ost-startStop-1] o.s.b.w.s.FilterRegistrationBean         : Mapping filter: 'hiddenHttpMethodFilter' to: [/*]

The pid is made available to Log4j2 as a system property and the system property is resolved during initialisation. If that initialisation is now happening earlier than before, it would explain why we see ????. Interestingly, the three lines where the PID is correct are from Tomcat. It uses JUL so it's taking a different route into Log4j2 than the other logging which is all from Spring Boot or Spring Framework.

Two related changes have been made recently that might have triggered this:

• Upgrading to Log4j 2.8 (from 2.7)
• The introduction of Spring Framework's own Commons Logging adapter which delegates to Log4j2 when it's on the classpath

[wilkinsona]

It's the change in Spring Framework that's caused the change in behaviour. If I add org.slf4j:jcl-over-slf4j to the classpath before spring-core the problem goes away.

[jhoeller]

So by putting jcl-over-slf4j on the classpath, you're forcing it to go through SLF4J which in turn goes through Log4J 2 then? Some specific setup might be hiding in the Log4J adapter behind SLF4J in that case...

We could reconsider the order of detection: Currently it's Log4J first, then SLF4J. This means that we always go to Log4J 2 directly when available, which seems sensible. That said, we could reverse the check and go through SLF4J whenever possible...

[wilkinsona]

I've found the underlying cause. Going via SLF4J, Log4j2's binding calls LogManager.getContext(cl, false) whereas Spring Framework's LoggerFactory calls LogManager.getContext(). The latter asks for the current context, whereas the former (thanks to false) does not.

[wilkinsona]

The cl in the example above is the class loader that loaded org.apache.commons.logging.impl.SLF4JLogFactory so LoggerFactory.class.getClassLoader() would be appropriate.

[jhoeller]

OK, I've pushed a corresponding change :-)

[wilkinsona]

And it's working now thanks to @jhoeller's change in Spring Framework