How to get war file to run with logback and TomEE 9.1.0

Question

I'm updating TomEE to 8.0.14 to TomEE 9.1.0.

The war file uses logback as log system which worked fine with TomEE 8.0.14.

Now I get the war file to run but the logging is not working anymore in the expected behaviour.

In the /opt/tomee/lib directory I see two slf4j libaries slf4j-api-1.7.36.jar and slf4j-jdk14-1.7.36.jar.

The logback.xml is located after the deployment in the directory /opt/tomee/webapps/myDeployment/WEB-INF/classes/. It creates a dedicated log file.

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true">

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>logs/theDedicatedLogFile.log</file>
    [...]
    <root level="DEBUG">
        <appender-ref ref="FILE" />
    </root>

</configuration>

When the deployment start the logback configuration file will be detected and read.

15-Aug-2023 16:32:23.648 INFO [main] org.apache.openejb.config.ConfigurationFactory.configureApplication Configuring enterprise application: /var/lib/tomee/webapps/myDeployment
16:32:24,151 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version ?
16:32:24,153 |-INFO in ch.qos.logback.classic.util.ContextInitializer@68fa8ea5 - No custom configurators were discovered as a service.
16:32:24,153 |-INFO in ch.qos.logback.classic.util.ContextInitializer@68fa8ea5 - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
16:32:24,154 |-INFO in ch.qos.logback.classic.util.ContextInitializer@68fa8ea5 - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
16:32:24,156 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
16:32:24,157 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
16:32:24,164 |-INFO in ch.qos.logback.classic.util.ContextInitializer@68fa8ea5 - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 3 milliseconds. ExecutionStatus=IN
VOKE_NEXT_IF_ANY
16:32:24,164 |-INFO in ch.qos.logback.classic.util.ContextInitializer@68fa8ea5 - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
16:32:24,164 |-INFO in ch.qos.logback.classic.util.ContextInitializer@68fa8ea5 - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
16:32:24,165 |-INFO in ch.qos.logback.classic.util.ContextInitializer@68fa8ea5 - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
16:32:24,165 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
16:32:24,165 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/opt/tomee/webapps/myDeployment/WEB-INF/classes/logback.xml]
16:32:24,296 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [FILE]

[...]
16:32:25,264 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [FILE] to Logger[ROOT]
16:32:25,264 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@6ce1cc03 - End of configuration.
16:32:25,265 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@301c622d - Registering current configuration as safe fallback point
16:32:25,265 |-INFO in ch.qos.logback.classic.util.ContextInitializer@68fa8ea5 - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 1101 milliseconds. ExecutionStatus=DO_NOT_INVOKE_NEXT_IF_ANY

From my point of view everything looks correct. But now the logger comes into the game. It does not log anymore into the dedicated file which was created. Now it logs the messages with INFO level into the file catalina.out. By debugging I found out that the logger has the type org.slf4j.impl.JDK14LoggerAdapter. I would expect the type ch.qos.logback.classic.Logger.

In the classpath /opt/tomee/webapps/myDeployment/WEB-INF/lib are this libs which have something to do with logging (in my understanding)

jcl-over-slf4j-1.7.36.jar
jul-to-slf4j-2.0.7.jar
liquibase-slf4j-5.0.0.jar
logback-classic-1.4.11.jar
logback-core-1.4.11.jar

I wonder that lib logback-classic-1.4.11.jar is not used anymore (prior version was 1.2.11). In my understanding the lib slf4j-jdk14-1.7.36.jar is used from /opt/tomee/lib.

I played around with logback-core and logback-classic versions 1.2.11 and 1.4.11 but I was not able to tell TomEE 9.1.0 to use the logback version shipped inside the war. My first assumption was that the Class path contains multiple SLF4J bindings problem which I can not confirm. There is no log entry inside catalina.out.

Does anybody have an idea how to tell TomEE to use logback for the deployed war file?

EDIT: Today I added the logback-classic-1.2.11.jar and logback-core-1.2.11.jar into the /opt/tomee/lib folder, changed owner and the logging works now.

I see the expected multiple binding warnings as expected:

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/opt/tomee/lib/slf4j-jdk14-1.7.36.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/opt/lib/tomee/lib/logback-classic-1.2.11.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.JDK14LoggerFactory]

I wonder is it really possible to seperate logging of myDeployment from org.slf4j.impl.JDK14LoggerFactory?

At the moment I get a double logging - inside catalina.out and inside the dedicated log file.^^

Thanks, Markus

How to get war file to run with logback and TomEE 9.1.0

0 Answers0