Issue Type: Bug Bug
Affects Versions: 1.0.13
Assignee: Logback dev list
Attachments: logback-test.xml
Components: logback-core
Created: 05/Nov/13 5:19 PM
Description:

The following JUnit test case shows that the latest 1.0.13 Logback does not limit the size of the files as requested. Depending of the maxFileSize, the inaccuracy varies between 15% and 600%. E.g.

java.lang.AssertionError: nogzip_1mb_each_1max.log.1 size is 3.3MB which is 328% of 1.0MB requested
java.lang.AssertionError: nogzip_1mb_each_5max.log.1 size is 6.6MB which is 655% of 1.0MB requested
java.lang.AssertionError: nogzip_1mb_each_9max.log.1 size is 6.6MB which is 655% of 1.0MB requested
java.lang.AssertionError: nogzip_10mb_each_1max.log.1 size is 13.2MB which is 132% of 10.0MB requested
java.lang.AssertionError: nogzip_10mb_each_5max.log.1 size is 13.2MB which is 132% of 10.0MB requested
java.lang.AssertionError: nogzip_20mb_each_3max.log.1 size is 23.0MB which is 115% of 20.0MB requested
package third.party.logback;

import static org.junit.Assert.*;
import java.io.File;
import java.util.Date;
import java.util.Random;
import org.junit.BeforeClass;
import org.junit.Test;
import org.slf4j.LoggerFactory;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.encoder.PatternLayoutEncoder;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.rolling.FixedWindowRollingPolicy;
import ch.qos.logback.core.rolling.RollingFileAppender;
import ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy;

public class SizeRotationTest {
  private static File _tmpDir;

  @BeforeClass
  public static void setup() throws Exception {
    _tmpDir = new File(System.getProperty("java.io.tmpdir") + "/fixedwindowlogbacktest/" + System.currentTimeMillis());
    for(String p : new String[]{ "java.vendor", "java.version", "os.name", "os.version", "os.arch" } ) {
      System.out.println(p + "=" + System.getProperty(p));
    }
    System.out.println("using " + _tmpDir.getAbsolutePath());
  }

  private static void verifyFileSize(File file, long requestedMaxSize) {
    String msg = String.format("%s size is %.1fMB which is %.0f%% of %.1fMB requested",
            file.getName(), file.length()/1024f/1024,
            100f * file.length() / requestedMaxSize, requestedMaxSize/1024f/1024);
    assertTrue(msg, file.length() <= requestedMaxSize);
  }

  private void doTest(final String name, boolean compress, int maxFiles, long maxSize) {
    File testDir = new File(_tmpDir, name);
    File basename = new File(testDir, name + ".log");
    File rotated  = new File(testDir, name + (compress ? ".log.%i.gz" : ".log.%i"));

    LoggerContext ctx = (LoggerContext) LoggerFactory.getILoggerFactory();

    FixedWindowRollingPolicy rollingPolicy = new FixedWindowRollingPolicy();
    rollingPolicy.setContext(ctx); 
    rollingPolicy.setMinIndex(1);
    rollingPolicy.setMaxIndex(maxFiles - 1);
    rollingPolicy.setFileNamePattern(rotated.getPath());

    SizeBasedTriggeringPolicy<ILoggingEvent> triggeringPolicy = new SizeBasedTriggeringPolicy<ILoggingEvent>(String.valueOf(maxSize));
    RollingFileAppender<ILoggingEvent> appender = new RollingFileAppender<ILoggingEvent>();
    appender.setFile(basename.getPath());
    appender.setAppend(false);
    appender.setRollingPolicy(rollingPolicy);
    appender.setTriggeringPolicy(triggeringPolicy);
    rollingPolicy.setParent(appender);
    rollingPolicy.start();
    triggeringPolicy.start();

    PatternLayoutEncoder layout = new PatternLayoutEncoder();
    layout.setPattern("%d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %level %logger %msg%n");
    layout.setContext(ctx);
    layout.start();

    appender.setEncoder(layout);
    appender.setContext(ctx);
    appender.start();

    Logger log = (Logger) LoggerFactory.getLogger(name); 
    log.addAppender(appender);

    // do log quite a few msgs
    Random rnd = new Random();
    String msg = "{} During the application {} in the case long-lived application on {} when {} is another random";
    for(int i = 0; i < 200000; ++i) {
      log.info(msg, System.nanoTime(), new Date(), rnd.nextGaussian());
    }

    // verify all file sizes
    for(int i = 1; i < maxFiles; ++i) {
      String file = String.format(rotated.getPath().replace("%i", "%d"), i);
      verifyFileSize(new File(file), maxSize);
    }

    verifyFileSize(basename, maxSize);
  }

  @Test public void test_NoGzip_2rot_1MB() { doTest("nogzip_1mb_each_1max", false, 2, 1 * 1024 * 1024); }
  @Test public void test_NoGzip_5rot_1MB() { doTest("nogzip_1mb_each_5max", false, 5, 1 * 1024 * 1024); }
  @Test public void test_NoGzip_9rot_1MB() { doTest("nogzip_1mb_each_9max", false, 9, 1 * 1024 * 1024); }

  @Test public void test_NoGzip_2rot_10MB() { doTest("nogzip_10mb_each_1max", false, 2, 10 * 1024 * 1024); }
  @Test public void test_NoGzip_5rot_10MB() { doTest("nogzip_10mb_each_5max", false, 5, 10 * 1024 * 1024); }

  @Test public void test_NoGzip_3rot_20MB() { doTest("nogzip_20mb_each_3max", false, 3, 20 * 1024 * 1024); }

  // gzipped
  @Test public void test_gzipped_2rot_1MB() { doTest("gzipped_1mb_each_2max", true, 2, 1 * 1024 * 1024); }
  @Test public void test_gzipped_5rot_1MB() { doTest("gzipped_1mb_each_5max", true, 5, 1 * 1024 * 1024); }

  @Test public void test_gzipped_2rot_10MB() { doTest("gzipped_10mb_each_2max", true, 2, 10 * 1024 * 1024); }
}
Environment:
java.vendor=Sun Microsystems Inc.
java.version=1.6.0_45
os.name=Windows 7
os.version=6.1
os.arch=amd64
Project: logback
Priority: Critical Critical
Reporter: Michal Jacykiewicz
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira