[FIXED] Using Logback to catalina.out

Issue

I am using Logback in an application running in Tomcat. While my application works and, in the debugger, I see my logging statements reached, these statements never reach /opt/tomcat/logs/catalina.out. (By the way, I do see these statements in the IntelliJ IDEA debugger console, but upon deployment, they don't reach catalina.out.) Where do I begin?

In my WAR, WEB-INF/classes/logback.xml looks like this:

<configuration>
  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${catalina.base}/logs/catalina.out</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <maxFileSize>10MB</maxFileSize>
      <maxHistory>10</maxHistory>
    </rollingPolicy>
    <immediateFlush>true</immediateFlush>
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
      <pattern>%date %level [%thread] %logger{40} %msg%n</pattern>
    </encoder>
  </appender>

  <root level="INFO">
    <appender-ref ref="FILE" />
  </root>
</configuration>

In code, I do this for example:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Validator
{
  private static final Logger logger = LoggerFactory.getLogger( Validator.class );
  ...

  public void foo()
  {
    logger.info( "Called foo()" );

Correspondingly, in pom.xml dependencies, I have this:

<dependency>
  <groupId>ch.qos.logback</groupId>
  <artifactId>logback-classic</artifactId>
  <version>${logback-version}</version>
</dependency>
<dependency>
  <groupId>ch.qos.logback</groupId>
  <artifactId>logback-access</artifactId>
  <version>${logback-version}</version>
</dependency>
<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>slf4j-api</artifactId>
  <version>${slf4j.version}</version>
</dependency>
<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>slf4j-simple</artifactId>
  <version>${slf4j.version}</version>
</dependency>

I also tried this in logback.xml. It didn't create the file. All logfiles are owned by tomcat:tomcat. Tomcat owns the thread that writes to the log.

<file>${catalina.base}/logs/test.log</file>

Solution

The problem turned out to be the slf4j JARs and multiple bindings. See

https://www.slf4j.org/codes.html#multiple_bindings.

I eliminated slf4j-simple from my dependencies as shown above. The fact that two slf4j JARs were in conflict barred in essence logback.xml from having any effect upon logging behavior. Upon fixing this, JUnit tests still worked, the IDE-embedded Tomcat began to reveal TRACE-level statements when the level was set to TRACE, ditto when deployed to a real Tomcat installation where the statements come out (in catalina.out in my case).

One additional observation I can make is that if a log-level configuration change is made (say, by hand directly on logback.xml on the path /opt/tomcat/webapps/application/WEB-INF/classes/logback.xml), I found that Tomcat had to be bounced for it to take effect (even though I played with <configuration scan="true">, etc.).

Answered By - Russ Bateman
Answer Checked By - Dawn Plyler (JavaFixing Volunteer)