CODEWITHSUNDEEP
javatomcatlog4jlog4j2java.util.logging
Raqua
Raqua

Reputation: 157

Logging levels not correct when using java.util.logging -> log4j2 -> Tomcat's JULI

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.

Upvotes: 2

Views: 1408

Answers (1)

jmehrens
jmehrens

Reputation: 11035

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.

Upvotes: 1

Related Questions