Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-416

simultaneously logging to all historical logs after rollover

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 0.9.18, 0.9.20
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None
    • Environment:

      Windows XP, Windows 7; jdk1.6.0_16

      Description

      Logs will roll over (using sifted rolling file appender) and then start logging simultaneously to all the historical log files for that application (log_1.log, log_2.log, etc.) as well as the current one (log.log). Once this happens, application performance is severely degraded.

      I made a test app using first the same versions of logback & slf4j as used by dm server 2.0, where the problem was first witnessed. (logback 0.9.18, slf4j api 1.5.10). It seems to continue to work fine as long as only one thread is logging. 5 threads, and it will happen occasionally/eventually. 10 threads, and it is pretty likely to happen as soon as it rolls over the first time.

      I then updated it to use current versions (logback 0.9.20, slf4j api 1.5.11), and witnessed the same behavior.

      I have a release zip I can provide if possible (not sure attachments are allowed with JIRA); otherwise, here are contents of project files for the test case:

      --------------------------------------------------------------
      logback.xml contents:
      ---------------------------------------------------------------
      <configuration>
      <!--
      <appender name="LOG_FILE"
      class="ch.qos.logback.core.rolling.RollingFileAppender">
      <file>logs/test_rollover_daily.log</file> <rollingPolicy
      class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> rollover
      daily
      <FileNamePattern>logs/test_rollover-%d

      {yyyy-MM-dd}

      .%i.log</FileNamePattern>
      <timeBasedFileNamingAndTriggeringPolicy
      class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"> or whenever
      the file size reaches 1000MB <MaxFileSize>1MB</MaxFileSize>
      </timeBasedFileNamingAndTriggeringPolicy> </rollingPolicy> <encoder>
      <pattern>%msg</pattern> </encoder> </appender>
      -->
      <appender name="SIFTED_LOG_FILE" class="ch.qos.logback.classic.sift.SiftingAppender">
      <discriminator>
      <Key>applicationName</Key>
      <DefaultValue>default</DefaultValue>
      </discriminator>
      <sift>
      <appender name="$

      {applicationName}_LOG_FILE"
      class="ch.qos.logback.core.rolling.RollingFileAppender">
      <file>../logs/${applicationName}

      /log.log
      </file>
      <rollingPolicy
      class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
      <FileNamePattern>../logs/$

      {applicationName}

      /log_%i.log
      </FileNamePattern>
      <MinIndex>1</MinIndex>
      <MaxIndex>4</MaxIndex>
      </rollingPolicy>
      <triggeringPolicy
      class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
      <MaxFileSize>10MB</MaxFileSize>
      </triggeringPolicy>
      <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>%d

      {yyyy-MM-dd HH:mm:ss.SSS}

      |%t|%p|%c

      {35}.%M:%L|%msg %ex%n</Pattern>
      </layout>
      </appender>
      </sift>
      </appender>


      <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
      <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS}|%t|%p|%c{35}

      .%M:%L|%msg %ex%n</Pattern>
      </layout>
      </appender>

      <logger level="trace" additivity="false" name="Standard.out">
      <appender-ref ref="STDOUT" />
      </logger>

      <logger level="trace" additivity="false" name="com.annealsoft">
      <appender-ref ref="SIFTED_LOG_FILE" />
      </logger>
      <root level="info" additivity="false">
      <appender-ref ref="SIFTED_LOG_FILE" />
      </root>
      </configuration>

      ----------------------------------------------------------------
      Java test app LogbackRolloverTest.java:
      -------------------------------------------------------------------
      package com.annealsoft.test;

      import java.util.Date;

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

      public class LogbackRolloverTest extends Thread {
      private static Logger log = LoggerFactory.getLogger(LogbackRolloverTest.class);
      private static final int DEFAULT_THREAD_COUNT = 10;
      private static int threadcount = 10;

      public static void main(String[] args){
      if (args.length > 0) {
      try

      { threadcount = Integer.parseInt(args[0]); }

      catch (Exception e)

      { System.out.println("Usage: LogbackRolloverTest [<thread count>] (defaults to " + DEFAULT_THREAD_COUNT + " threads)"); System.exit(1); }

      }
      System.out.println("Logging from " + threadcount + (threadcount == 1 ? " thread":" threads") + " (optional thread count parameter defaults to " + DEFAULT_THREAD_COUNT + ")");

      for (int i = 0; i < threadcount; i++)

      { new LogbackRolloverTest().start(); }

      }

      public void run() {
      int count = 0;
      while (true)

      { doLog(count++); }

      }

      private void doLog(int count) {
      log.debug("The current date is " + new Date() + " the count is " + count);
      log.info("Info Message");
      log.warn("Warn Message");
      log.trace("Trace message");
      log.error("Error message");
      log.info("Info Message");
      log.warn("Warn Message");
      log.trace("Trace message");
      log.error("Error message");
      try

      { throw new Exception("throwing exception " + count + " to create a stack trace"); }

      catch (Exception e)

      { log.error("caught " + e.toString(), e); }

      if (count % 10 == 0) {
      try

      { Thread.sleep(100); }

      catch (InterruptedException e)

      { log.error("Thread interrupted: " + e.toString(), e); }

      }

      }
      }
      -------------------------------------------------------------
      Batch file contents logbacktest.bat:
      -------------------------------------------------------------
      @ECHO OFF
      IF "%OS%" == "Windows_NT" SETLOCAL

      IF NOT "%JAVA_HOME%" == "" goto JavaHomeSet
      echo The JAVA_HOME environment variable is not defined
      GOTO:EOF

      :JavaHomeSet

      SET SCRIPT_DIR=%~dp0%
      SET APP_HOME="%SCRIPT_DIR%.."

      setlocal ENABLEDELAYEDEXPANSION
      if defined LOCAL_CLASSPATH (set LOCAL_CLASSPATH=%LOCAL_CLASSPATH%;.) else (set LOCAL_CLASSPATH=.)
      FOR /R ..\lib %%G IN (*.jar) DO set LOCAL_CLASSPATH=Unable to render embedded object: File (LOCAL_CLASSPATH) not found.;%%G
      Echo The Classpath definition is %LOCAL_CLASSPATH%

      "%JAVA_HOME%"\bin\java -Dhomedir="%APP_HOME%" -classpath "%LOCAL_CLASSPATH%" com.annealsoft.test.LogbackRolloverTest %1

      ------------------------------------------------------------------
      Maven pom.xml:
      ------------------------------------------------------------------

      <project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/maven-v4_0_0.xsd">
      <modelVersion>4.0.0</modelVersion>
      <groupId>com.annealsoft</groupId>
      <artifactId>logback-test</artifactId>
      <packaging>jar</packaging>
      <version>$

      {release-version}</version>

      <name>logback-test</name>
      <repositories>

      </repositories>

      <dependencies>
      <dependency>
      <groupId>ch.qos.logback</groupId>
      <artifactId>logback-classic</artifactId>
      <version>${logback}</version>
      </dependency>
      <dependency>
      <groupId>org.slf4j</groupId>
      <artifactId>slf4j-api</artifactId>
      <version>${slf4j-api}</version>
      </dependency>
      </dependencies>
      <profiles>
      <profile>
      <id>logback-test</id>
      <activation>
      <activeByDefault>true</activeByDefault>
      </activation>
      <properties>
      <JDK_VERSION>1.6</JDK_VERSION>
      <release-version>1.0</release-version>
      <!-- dependency versions same as used in dm-server
      <logback>0.9.18</logback>
      <slf4j-api>1.5.10</slf4j-api>
      -->
      <!-- dependencies for current release version -->
      <logback>0.9.20</logback>
      <slf4j-api>1.5.11</slf4j-api>
      </properties>

      <build>
      <plugins>
      <plugin>
      <groupId>org.apache.maven.plugins
      </groupId>
      <artifactId>maven-compiler-plugin
      </artifactId>
      <configuration>
      <source>${JDK_VERSION}</source>
      <target>${JDK_VERSION}</target>
      </configuration>
      </plugin>
      <plugin>

      <artifactId>maven-assembly-plugin</artifactId>
      <configuration>
      <descriptor>release.xml</descriptor>
      <outputDirectory>release</outputDirectory>
      </configuration>
      </plugin>
      </plugins>
      <finalName>logback-test</finalName>
      <defaultGoal>package</defaultGoal>
      </build>
      </profile>
      </profiles>
      </project>


      --------------------------------------------------------------------------
      Maven release.xml:
      --------------------------------------------------------------------------
      <assembly>
      <id>${release-version}

      </id>
      <formats>
      <format>zip</format>
      </formats>

      <includeBaseDirectory>false</includeBaseDirectory>

      <fileSets>
      <fileSet>
      <directory>bin</directory>
      <outputDirectory>bin</outputDirectory>
      </fileSet>
      <fileSet>
      <directory>lib</directory>
      <outputDirectory>lib</outputDirectory>
      </fileSet>
      <fileSet>
      <directory>src</directory>
      <outputDirectory>src</outputDirectory>
      </fileSet>
      <fileSet>
      <directory>src/main/resources</directory>
      <outputDirectory>config</outputDirectory>
      </fileSet>
      <fileSet>
      <directory>logs</directory>
      <outputDirectory>logs</outputDirectory>
      </fileSet>
      </fileSets>
      <dependencySets>
      <dependencySet>
      <unpack>false</unpack>
      <scope>runtime</scope>
      <outputDirectory>lib</outputDirectory>
      </dependencySet>
      </dependencySets>
      </assembly>

        Activity

        Hide
        estrnod Ellen Strnod added a comment -

        This is a release zip of test case reproducing the problem

        Show
        estrnod Ellen Strnod added a comment - This is a release zip of test case reproducing the problem
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment -

        Thank you for this report. Using SiftingAppender and the application name as discriminating criteria is really pointless. The application name will be the same throughout the life-cycle of the application. Thus, SiftingAppender will always wrap the same appender corresponding to the application's name.

        However, the test case you provided clearly shows that there is a synchronization problem in SiftingAppender which was fixed a few moments ago subsequent to this report. Thank you. Due to the aforementioned synchronization problem SiftingAppender will initialize 10 different RollignFileAppender instances all identical and all tripping over each other which explains the performance degradation you observe.

        If you would like to see the various rollingfileappender tripping over each other, add the following line to your config file:

        <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - Thank you for this report. Using SiftingAppender and the application name as discriminating criteria is really pointless. The application name will be the same throughout the life-cycle of the application. Thus, SiftingAppender will always wrap the same appender corresponding to the application's name. However, the test case you provided clearly shows that there is a synchronization problem in SiftingAppender which was fixed a few moments ago subsequent to this report. Thank you. Due to the aforementioned synchronization problem SiftingAppender will initialize 10 different RollignFileAppender instances all identical and all tripping over each other which explains the performance degradation you observe. If you would like to see the various rollingfileappender tripping over each other, add the following line to your config file: <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />
        Hide
        estrnod Ellen Strnod added a comment -

        Thanks for your quick response. The sifting appender is useful in the environment in which we deploying, which is dm server.

        Will the fix be in the next release then? Is there an estimated time that this will be out?

        Show
        estrnod Ellen Strnod added a comment - Thanks for your quick response. The sifting appender is useful in the environment in which we deploying, which is dm server. Will the fix be in the next release then? Is there an estimated time that this will be out?
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment -

        Fixed in 0.9.21.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - Fixed in 0.9.21.

          People

          • Assignee:
            noreply.ceki@qos.ch Ceki Gulcu
            Reporter:
            estrnod Ellen Strnod
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: