2

I have multiple microservices, some run on Tomcat some are standalone jars. We used to log using java.util.logging framework. Later we made switch to Log4j2, but kept the JUL API for logging as to not to have to rewrite the code. This works (and it can not be changed although I would like to). Obviously there is some log level translation as JUL and Log4j2 use different log level. In non-Tomcat services, log levels look like this:

14:49:58.612 FINEST -            t1     Log level FINEST enabled
14:49:58.612 TRACE  -            t1     Log level FINER enabled
14:49:58.613 DEBUG  -            t1     Log level FINE enabled
14:49:58.613 CONFIG -            t1     Log level CONFIG enabled
14:49:58.613 INFO   -            t1     Log level INFO enabled
14:49:58.613 WARN   -            t1     Log level WARNING enabled
14:49:58.614 ERROR  -            t1     Log level SEVERE enabled

This is expected behavior.

However, on Tomcat, we get this:

14:46:38.393 TRACE  -            t1     Log level FINEST enabled
14:46:38.394 DEBUG  -            t1     Log level FINER enabled
14:46:38.394 DEBUG  -            t1     Log level FINE enabled
14:46:38.395 INFO   -            t1     Log level CONFIG enabled
14:46:38.396 INFO   -            t1     Log level INFO enabled
14:46:38.396 WARN   -            t1     Log level WARNING enabled
14:46:38.397 ERROR  -            t1     Log level SEVERE enabled

This is not correct. I belive it has something to do with the translation from-to JUL, since Tomcat's JULI is based on JUL.

In order to confirm my suspicion, I have switched Tomcat to use Log4j2 also for it's internal logging, which solved the log level issue but brought another. Thread context is not injected to Log4j2 logs anymore. I suspect it is because there are now running 2 Log4j instances - one for Tomcat and one for our app.

To solve my issue, I would be happy with either of the solutions

  1. Fix Tomcat using JULI to show correct Log4j2 log levels or
  2. Use Tomcat with Log4j instead of JULI but keep ThreadContext working

Number 1 is preferred solution if possible.

Raqua
  • 157
  • 2
  • 8

1 Answers1

1

Looks to be difference is versions of log4j2 at 2.14.0. Per Update LevelTranslator to use LevelConverter interface diff:

 LevelTranslator:48 - JDK_TO_LOG4J.put(java.util.logging.Level.FINEST, Level.TRACE);
 ...
 LevelTranslator:35 + public static final Level FINEST = Level.forName("FINEST", Level.TRACE.intLevel() + 100);

The commit is tagged 2.14.0 so I would imagine that the non-Tomcat services are using version 2.14.0 or greater and the Tomcat services are a version older than 2.14.0

Seems you need to be able to upgrade the log4j2 that Tomcat is using or perhaps your services are including multiple different versions of log4j2 and Tomcat class loading is just loading the older version. Make sure duplicate libs are removed from the project. Keep in mind you have to check the full classloader tree.

If Tomcat itself is not using log4j it then defaults to org.apache.juli.logging.DirectJDKLog. That translates the trace level to FINER so we know that is not the path of execution you are seeing.

@Override
public final void trace(Object message) {
    log(Level.FINER, String.valueOf(message), null);
}

The other possibility is that slf4j bridge handler is the output you are seeing as it maps to TRACE to FINEST.

jmehrens
  • 10,580
  • 1
  • 38
  • 47
  • Thank you for taking the effort to answer. I have double checked that my project uses 2.14.0, my war contains only 2.14.0 jars and after enabling debug mode in log4j I see that the used version is 2.14.0. You suggestion seemed pretty promising, but unfortunately old version used seems to be not the case here. – Raqua Dec 22 '20 at 11:44
  • @Raqua Were you able to examine the complete classloader tree in Tomcat? There are multiple locations where jars can be stored and included. 3rd party lib that is including an older version of log4j are another source of trouble. The other possibility is that slf4j bridge handler is the output you are seeing as it maps to TRACE to FINEST. – jmehrens Dec 22 '20 at 15:47
  • Yes, I have dug a bit deeper now into this and found out that it is indeed slf4j that is setting the levels (confirmed by debugging the code). I have explicitly excluded jul-to-slf4j package, it is not in my war anywhere, but it is still loaded and used somehow. I have to find out where it comes from and how to force Tomcat to use log4j-jul instead. – Raqua Dec 22 '20 at 17:28