New subject: [JIRA] Updated: (LBCLASSIC-203) simultaneously logging to all historical logs after rollover

16 Apr 2010

      simultaneously logging to all historical logs after rollover
------------------------------------------------------------

                 Key: LBCLASSIC-203
                 URL: http://jira.qos.ch/browse/LBCLASSIC-203
             Project: logback-classic
          Issue Type: Bug
    Affects Versions: 0.9.18, 0.9.20
         Environment: Windows XP, Windows 7; jdk1.6.0_16
            Reporter: Ellen Strnod
            Assignee: Logback dev list

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=!LOCAL_CLASSPATH!;%%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>

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira

[JIRA] Created: (LBCLASSIC-203) simultaneously logging to all historical logs after rollover

Ellen Strnod (JIRA)

Ellen Strnod (JIRA)

Ceki Gulcu (JIRA)

Ceki Gulcu (JIRA)

Ellen Strnod (JIRA)

Ceki Gulcu (JIRA)

tags

participants (2)