- logback-dev - mailman3.qos.ch

[JIRA] Resolved: (LBCLASSIC-49) LoggerContext.getLogger(final String name) doesn't check if name is null
by Ceki Gulcu (JIRA) 30 Oct '08

30 Oct '08

[ http://jira.qos.ch/browse/LBCLASSIC-49?page=com.atlassian.jira.plugin.syste… ] Ceki Gulcu resolved LBCLASSIC-49. --------------------------------- Fix Version/s: 0.9.12 Resolution: Fixed The getLogger() method in LoggerContext class will now throw an IllegalArgumentException when invoked with a null argument. I think that is the best logback-classic can do, since a null name argument is illegal. LoggerContext.getLogger(null) has to return something but can't... > LoggerContext.getLogger(final String name) doesn't check if name is null > ------------------------------------------------------------------------ > > Key: LBCLASSIC-49 > URL: http://jira.qos.ch/browse/LBCLASSIC-49 > Project: logback-classic > Issue Type: Bug > Components: Other > Affects Versions: unspecified > Environment: Operating System: All > Platform: All > Reporter: Oliver Lietz > Assignee: Logback dev list > Fix For: 0.9.12 > > > hence loggerCache.get(name) could fail (NPE) in line 117: > java.lang.NullPointerException > at java.util.Hashtable.get(Hashtable.java:336) > at ch.qos.logback.classic.LoggerContext.getLogger(LoggerContext.java:117) > at ch.qos.logback.classic.LoggerContext.getLogger(LoggerContext.java:44) > at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:88) > at org.apache.sling.osgi.log.LogSupport.getLogger(LogSupport.java:322) > at org.apache.sling.osgi.log.LogSupport.logOut(LogSupport.java:333) > at org.apache.sling.osgi.log.LogSupport.fireLogEvent(LogSupport.java:167) > at org.apache.sling.osgi.log.LogSupport.bundleChanged(LogSupport.java:216) > at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:690) > at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:619) > at org.apache.felix.framework.util.EventDispatcher.run(EventDispatcher.java:816) > at org.apache.felix.framework.util.EventDispatcher.access$000(EventDispatcher.java:42) > at org.apache.felix.framework.util.EventDispatcher$1.run(EventDispatcher.java:94) > at java.lang.Thread.run(Thread.java:613) -- 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

1 0

svn commit: r1918 - in logback/trunk/logback-classic/src: main/java/ch/qos/logback/classic test/java/ch/qos/logback/classic
by noreply.ceki＠qos.ch 30 Oct '08

30 Oct '08

Author: ceki Date: Thu Oct 30 20:42:34 2008 New Revision: 1918 Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/LoggerContext.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerContextTest.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/PackageTest.java Log: Fixes LBCLASSIC-49 The getLogger() method in LoggerContext class will now throw an IllegalArgumentException when invoked with a null argument. Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/LoggerContext.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/LoggerContext.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/LoggerContext.java Thu Oct 30 20:42:34 2008 @@ -105,6 +105,10 @@ public final Logger getLogger(final String name) { + if(name == null) { + throw new IllegalArgumentException("name argument cannot be null"); + } + // if we are asking for the root logger, then let us return it without // wasting time if (ROOT_NAME.equalsIgnoreCase(name)) { Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerContextTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerContextTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerContextTest.java Thu Oct 30 20:42:34 2008 @@ -1,7 +1,7 @@ /** - * LOGBack: the generic, reliable, fast and flexible logging framework. + * Logback: the generic, reliable, fast and flexible logging framework. * - * Copyright (C) 1999-2006, QOS.ch + * Copyright (C) 2000-2008, QOS.ch * * This library is free software, you can redistribute it and/or modify it under * the terms of the GNU Lesser General Public License as published by the Free @@ -9,25 +9,33 @@ */ package ch.qos.logback.classic; -import junit.framework.TestCase; +import static org.junit.Assert.*; + +import org.junit.Before; +import org.junit.Test; +import org.slf4j.LoggerFactory; + import ch.qos.logback.core.status.StatusManager; -public class LoggerContextTest extends TestCase { +public class LoggerContextTest { LoggerContext lc; - protected void setUp() throws Exception { - Logger.instanceCount = 0; - lc = new LoggerContext(); - lc.setName("x"); + @Before + public void setUp() throws Exception { + Logger.instanceCount = 0; + lc = new LoggerContext(); + lc.setName("x"); } - public void testRootGetLogger() { + @Test + public void testRootGetLogger() { Logger root = lc.getLogger(LoggerContext.ROOT_NAME); assertEquals(Level.DEBUG, root.getLevel()); assertEquals(Level.DEBUG, root.getEffectiveLevel()); } - public void testLoggerX() { + @Test + public void testLoggerX() { Logger x = lc.getLogger("x"); assertNotNull(x); assertEquals("x", x.getName()); @@ -35,31 +43,44 @@ assertEquals(Level.DEBUG, x.getEffectiveLevel()); } - public void testEmpty() { + @Test + public void testNull() { + try { + lc.getLogger((String) null); + fail("null should cause an exception"); + } catch (IllegalArgumentException e) { + } + } + + @Test + public void testEmpty() { Logger empty = lc.getLogger(""); LoggerTestHelper.assertNameEquals(empty, ""); LoggerTestHelper.assertLevels(null, empty, Level.DEBUG); Logger dot = lc.getLogger("."); LoggerTestHelper.assertNameEquals(dot, "."); -// LoggerTestHelper.assertNameEquals(dot.parent, ""); -// LoggerTestHelper.assertNameEquals(dot.parent.parent, "root"); + // LoggerTestHelper.assertNameEquals(dot.parent, ""); + // LoggerTestHelper.assertNameEquals(dot.parent.parent, "root"); -// assertNull(dot.parent.parent.parent); + // assertNull(dot.parent.parent.parent); LoggerTestHelper.assertLevels(null, dot, Level.DEBUG); assertEquals(3, Logger.instanceCount); } + @Test public void testDotDot() { Logger dotdot = lc.getLogger(".."); assertEquals(4, Logger.instanceCount); LoggerTestHelper.assertNameEquals(dotdot, ".."); -// LoggerTestHelper.assertNameEquals(dotdot.parent, "."); -// LoggerTestHelper.assertNameEquals(dotdot.parent.parent, ""); -// LoggerTestHelper.assertNameEquals(dotdot.parent.parent.parent, "root"); + // LoggerTestHelper.assertNameEquals(dotdot.parent, "."); + // LoggerTestHelper.assertNameEquals(dotdot.parent.parent, ""); + // LoggerTestHelper.assertNameEquals(dotdot.parent.parent.parent, "root"); } - public void testLoggerXY() { + + @Test + public void testLoggerXY() { assertEquals(1, Logger.instanceCount); Logger xy = lc.getLogger("x.y"); @@ -78,26 +99,28 @@ assertEquals(3, Logger.instanceCount); } - public void testLoggerMultipleChildren() { - assertEquals(1, Logger.instanceCount); - Logger xy0 = lc.getLogger("x.y0"); - LoggerTestHelper.assertNameEquals(xy0, "x.y0"); - - Logger xy1 = lc.getLogger("x.y1"); - LoggerTestHelper.assertNameEquals(xy1, "x.y1"); - - LoggerTestHelper.assertLevels(null, xy0, Level.DEBUG); - LoggerTestHelper.assertLevels(null, xy1, Level.DEBUG); - assertEquals(4, Logger.instanceCount); - - for(int i = 0; i < 100; i++) { - Logger xy_i = lc.getLogger("x.y"+i); - LoggerTestHelper.assertNameEquals(xy_i, "x.y"+i); - LoggerTestHelper.assertLevels(null, xy_i, Level.DEBUG); - } - assertEquals(102, Logger.instanceCount); - } + @Test + public void testLoggerMultipleChildren() { + assertEquals(1, Logger.instanceCount); + Logger xy0 = lc.getLogger("x.y0"); + LoggerTestHelper.assertNameEquals(xy0, "x.y0"); + + Logger xy1 = lc.getLogger("x.y1"); + LoggerTestHelper.assertNameEquals(xy1, "x.y1"); + + LoggerTestHelper.assertLevels(null, xy0, Level.DEBUG); + LoggerTestHelper.assertLevels(null, xy1, Level.DEBUG); + assertEquals(4, Logger.instanceCount); + + for (int i = 0; i < 100; i++) { + Logger xy_i = lc.getLogger("x.y" + i); + LoggerTestHelper.assertNameEquals(xy_i, "x.y" + i); + LoggerTestHelper.assertLevels(null, xy_i, Level.DEBUG); + } + assertEquals(102, Logger.instanceCount); + } + @Test public void testMultiLevel() { Logger wxyz = lc.getLogger("w.x.y.z"); LoggerTestHelper.assertNameEquals(wxyz, "w.x.y.z"); @@ -110,22 +133,24 @@ LoggerTestHelper.assertLevels(null, lc.getLogger("w.x.y"), Level.INFO); LoggerTestHelper.assertLevels(null, wxyz, Level.INFO); } - + + @Test public void testStatusWithUnconfiguredContext() { - Logger logger = lc.getLogger(LoggerContextTest.class); - - for (int i = 0; i < 3; i++) { - logger.debug("test"); - } - - logger = lc.getLogger("x.y.z"); - - for (int i = 0; i < 3; i++) { - logger.debug("test"); - } - - StatusManager sm = lc.getStatusManager(); - assertTrue("StatusManager has recieved too many messages", sm.getCount() == 1); + Logger logger = lc.getLogger(LoggerContextTest.class); + + for (int i = 0; i < 3; i++) { + logger.debug("test"); + } + + logger = lc.getLogger("x.y.z"); + + for (int i = 0; i < 3; i++) { + logger.debug("test"); + } + + StatusManager sm = lc.getStatusManager(); + assertTrue("StatusManager has recieved too many messages", + sm.getCount() == 1); } } \ No newline at end of file Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/PackageTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/PackageTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/PackageTest.java Thu Oct 30 20:42:34 2008 @@ -15,7 +15,7 @@ public static Test suite() { TestSuite suite = new TestSuite(); - suite.addTestSuite(LoggerContextTest.class); + suite.addTest(new JUnit4TestAdapter(LoggerContextTest.class)); suite.addTest(new JUnit4TestAdapter(LoggerPerfTest.class)); suite.addTest(new JUnit4TestAdapter(DynamicLoggerContextTest.class)); suite.addTest(new JUnit4TestAdapter(PatternLayoutTest.class));

1 0

[JIRA] Commented: (LBCLASSIC-55) Report URL config has been loaded from when debug="true"
by Ceki Gulcu (JIRA) 30 Oct '08

30 Oct '08

[ http://jira.qos.ch/browse/LBCLASSIC-55?page=com.atlassian.jira.plugin.syste… ] Ceki Gulcu commented on LBCLASSIC-55: ------------------------------------- Hello Anton, At initialization time, logback will report whether it is reading logback-test.xml or logback.xml. Is this what you meant, or did you mean something else? > Report URL config has been loaded from when debug="true" > -------------------------------------------------------- > > Key: LBCLASSIC-55 > URL: http://jira.qos.ch/browse/LBCLASSIC-55 > Project: logback-classic > Issue Type: Improvement > Reporter: Anton Tagunov > Assignee: Ceki Gulcu > > Hi! > <configuration debug="true"> is nice. > It will be even nicer if it also reports what URL the config is being loaded from. > Thx! -- 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

1 0

[JIRA] Commented: (LBCORE-21) TimeBasedRollingPolicy do NOT work as expected
by Ceki Gulcu (JIRA) 30 Oct '08

30 Oct '08

[ http://jira.qos.ch/browse/LBCORE-21?page=com.atlassian.jira.plugin.system.i… ] Ceki Gulcu commented on LBCORE-21: ---------------------------------- The link to revision 1917 was mistakenly associated with this bug. It should have been associated with LBCORE-26. > TimeBasedRollingPolicy do NOT work as expected > ---------------------------------------------- > > Key: LBCORE-21 > URL: http://jira.qos.ch/browse/LBCORE-21 > Project: logback-core > Issue Type: Bug > Components: Rolling > Affects Versions: unspecified > Environment: Operating System: Linux > Platform: All > Reporter: Eric > Assignee: Logback dev list > Priority: Blocker > > When I use TimeBasedRollingPolicy as the rolling & triggering policy for the RollingFileAppender, only the last log line appears in the new log file after the 1st rolling trigger. > The reason is that the TimeBasedRollingPolicy kept rolling for every log event after the 1st rolling trigger. It causes by a bug in isTriggeringEvent() method - the method uses the un-initialized value of 'currentTime' (which is 0) to set the time of the 'lastCheck' Date object. > Original method : > public boolean isTriggeringEvent(File activeFile, final Object event) { > //currentTime= System.currentTimeMillis(); > if (getCurrentTime() >= nextCheck) { > //addInfo("Time to trigger roll-over"); > // We set the elapsedPeriodsFileName before we set the 'lastCheck' variable > // The elapsedPeriodsFileName corresponds to the file name of the period > // that just elapsed. > elapsedPeriodsFileName = activeFileNamePattern.convertDate(lastCheck); > //addInfo("elapsedPeriodsFileName set to "+elapsedPeriodsFileName); > lastCheck.setTime(currentTime); > nextCheck = rc.getNextCheckMillis(lastCheck); > > Date x = new Date(); > x.setTime(nextCheck); > //addInfo("Next check on "+ x); > return true; > } else { > return false; > } > } > Suggested Changes - uses a local long variable to store the value of getCurrentTime() and uses it in the method for comparison and assignment: > public boolean isTriggeringEvent(File activeFile, final Object event) { > //currentTime= System.currentTimeMillis(); > long curT = getCurrentTime(); > if (curT >= nextCheck) { > //addInfo("Time to trigger roll-over"); > // We set the elapsedPeriodsFileName before we set the 'lastCheck' variable > // The elapsedPeriodsFileName corresponds to the file name of the period > // that just elapsed. > elapsedPeriodsFileName = activeFileNamePattern.convertDate(lastCheck); > //addInfo("elapsedPeriodsFileName set to "+elapsedPeriodsFileName); > lastCheck.setTime(curT); > nextCheck = rc.getNextCheckMillis(lastCheck); > //Date x = new Date(); > //x.setTime(nextCheck); > //addInfo("Next check on "+ x); > return true; > } else { > return false; > } > } -- 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

1 0

[JIRA] Commented: (LBCORE-26) TimeBasedRollingPolicy append logs into a old log file, instead of rolling the log file.
by Ceki Gulcu (JIRA) 30 Oct '08

30 Oct '08

[ http://jira.qos.ch/browse/LBCORE-26?page=com.atlassian.jira.plugin.system.i… ] Ceki Gulcu commented on LBCORE-26: ---------------------------------- Details for this commit can be seen at http://svn.qos.ch/viewvc?root=svn&revision=1917&pathrev=1917&view=rev > TimeBasedRollingPolicy append logs into a old log file, instead of rolling the log file. > ---------------------------------------------------------------------------------------- > > Key: LBCORE-26 > URL: http://jira.qos.ch/browse/LBCORE-26 > Project: logback-core > Issue Type: Bug > Components: Rolling > Affects Versions: unspecified > Environment: Operating System: All > Platform: All > Reporter: Tsutomu YANO > Assignee: Logback dev list > Priority: Critical > Fix For: 0.9.12 > > > If you use TimeBasedRollingPolicy to rollover a log file and no log wasn't wrote into the log beyond the timing of rollover, and if you restart your application, the log file doesn't roll, then new log will be appended into old log file. > EVIDENCE: > 1. in logback.xml, set your FileNamePattern like 'log.%d{yyyy-MM-dd_HH-mm}.log'. > 2. Simply do a kind of thing, which will make some logs into your log file. > 3. Wait for some minutes. > 4. restart your application. > 5. do a kind of thing, which will make some logs into your log file. > the FileNamePattern is 'log.%d{yyyy-MM-dd_HH-mm}.log', so the log file will be roll every minutes. On case 5 of above example, the log file should be roll over, because some minutes already have passed after last logs wrote into the log file. But the file didn't be roll overed. > THE CAUSE: > In start() method of TimeBasedRollingPolicy, you initialize a variable 'lastCheck' to System.currentTimeStamp(). So if you restart your application, the last check time will be set to just NOW. > you should initialize the variable to a last modified time of a current log file. > See below source code. from '//modified by Tsutomu YANO' to '//until here'. > SOURCE: > public void start() { > // set the LR for our utility object > util.setContext(this.context); > compress.setContext(this.context); > // find out period from the filename pattern > if (fileNamePatternStr != null) { > fileNamePattern = new FileNamePattern(fileNamePatternStr, this.context); > determineCompressionMode(); > } else { > addWarn(FNP_NOT_SET); > addWarn(SEE_FNP_NOT_SET); > throw new IllegalStateException(FNP_NOT_SET + SEE_FNP_NOT_SET); > } > DateTokenConverter dtc = fileNamePattern.getDateTokenConverter(); > if (dtc == null) { > throw new IllegalStateException("FileNamePattern [" + fileNamePattern.getPattern() + "] does not contain a valid DateToken"); > } > int len = fileNamePatternStr.length(); > switch (compressionMode) { > case Compress.GZ: > activeFileNamePattern = new FileNamePattern(fileNamePatternStr.substring(0, len - 3), this.context); > break; > case Compress.ZIP: > activeFileNamePattern = new FileNamePattern(fileNamePatternStr.substring(0, len - 4), this.context); > break; > case Compress.NONE: > activeFileNamePattern = fileNamePattern; > } > addInfo("Will use the pattern " + activeFileNamePattern + " for the active file"); > rc = new RollingCalendar(); > rc.init(dtc.getDatePattern()); > addInfo("The date pattern is '" + dtc.getDatePattern() + "' from file name pattern '" + fileNamePattern.getPattern() + "'."); > rc.printPeriodicity(this); > > //modified by Tsutomu YANO > //if a current log file exists, initialize a 'lastCheck' variable to the > //last modified date of the file. > File currentFile = new File(getParentFileName()); > if(currentFile.exists() && currentFile.canRead()) { > lastCheck.setTime(currentFile.lastModified()); > } else { > // currentTime = System.currentTimeMillis(); > lastCheck.setTime(getCurrentTime()); > } > //until here > > nextCheck = rc.getNextCheckMillis(lastCheck); > // Date nc = new Date(); > // nc.setTime(nextCheck); > } -- 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

1 0

[JIRA] Resolved: (LBCORE-26) TimeBasedRollingPolicy append logs into a old log file, instead of rolling the log file.
by Ceki Gulcu (JIRA) 30 Oct '08

30 Oct '08

[ http://jira.qos.ch/browse/LBCORE-26?page=com.atlassian.jira.plugin.system.i… ] Ceki Gulcu resolved LBCORE-26. ------------------------------ Fix Version/s: 0.9.12 Resolution: Fixed Problem solved in revision 1917 which will be available in logback 0.9.12. > TimeBasedRollingPolicy append logs into a old log file, instead of rolling the log file. > ---------------------------------------------------------------------------------------- > > Key: LBCORE-26 > URL: http://jira.qos.ch/browse/LBCORE-26 > Project: logback-core > Issue Type: Bug > Components: Rolling > Affects Versions: unspecified > Environment: Operating System: All > Platform: All > Reporter: Tsutomu YANO > Assignee: Logback dev list > Priority: Critical > Fix For: 0.9.12 > > > If you use TimeBasedRollingPolicy to rollover a log file and no log wasn't wrote into the log beyond the timing of rollover, and if you restart your application, the log file doesn't roll, then new log will be appended into old log file. > EVIDENCE: > 1. in logback.xml, set your FileNamePattern like 'log.%d{yyyy-MM-dd_HH-mm}.log'. > 2. Simply do a kind of thing, which will make some logs into your log file. > 3. Wait for some minutes. > 4. restart your application. > 5. do a kind of thing, which will make some logs into your log file. > the FileNamePattern is 'log.%d{yyyy-MM-dd_HH-mm}.log', so the log file will be roll every minutes. On case 5 of above example, the log file should be roll over, because some minutes already have passed after last logs wrote into the log file. But the file didn't be roll overed. > THE CAUSE: > In start() method of TimeBasedRollingPolicy, you initialize a variable 'lastCheck' to System.currentTimeStamp(). So if you restart your application, the last check time will be set to just NOW. > you should initialize the variable to a last modified time of a current log file. > See below source code. from '//modified by Tsutomu YANO' to '//until here'. > SOURCE: > public void start() { > // set the LR for our utility object > util.setContext(this.context); > compress.setContext(this.context); > // find out period from the filename pattern > if (fileNamePatternStr != null) { > fileNamePattern = new FileNamePattern(fileNamePatternStr, this.context); > determineCompressionMode(); > } else { > addWarn(FNP_NOT_SET); > addWarn(SEE_FNP_NOT_SET); > throw new IllegalStateException(FNP_NOT_SET + SEE_FNP_NOT_SET); > } > DateTokenConverter dtc = fileNamePattern.getDateTokenConverter(); > if (dtc == null) { > throw new IllegalStateException("FileNamePattern [" + fileNamePattern.getPattern() + "] does not contain a valid DateToken"); > } > int len = fileNamePatternStr.length(); > switch (compressionMode) { > case Compress.GZ: > activeFileNamePattern = new FileNamePattern(fileNamePatternStr.substring(0, len - 3), this.context); > break; > case Compress.ZIP: > activeFileNamePattern = new FileNamePattern(fileNamePatternStr.substring(0, len - 4), this.context); > break; > case Compress.NONE: > activeFileNamePattern = fileNamePattern; > } > addInfo("Will use the pattern " + activeFileNamePattern + " for the active file"); > rc = new RollingCalendar(); > rc.init(dtc.getDatePattern()); > addInfo("The date pattern is '" + dtc.getDatePattern() + "' from file name pattern '" + fileNamePattern.getPattern() + "'."); > rc.printPeriodicity(this); > > //modified by Tsutomu YANO > //if a current log file exists, initialize a 'lastCheck' variable to the > //last modified date of the file. > File currentFile = new File(getParentFileName()); > if(currentFile.exists() && currentFile.canRead()) { > lastCheck.setTime(currentFile.lastModified()); > } else { > // currentTime = System.currentTimeMillis(); > lastCheck.setTime(getCurrentTime()); > } > //until here > > nextCheck = rc.getNextCheckMillis(lastCheck); > // Date nc = new Date(); > // nc.setTime(nextCheck); > } -- 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

1 0

svn commit: r1917 - in logback/trunk/logback-core/src: main/java/ch/qos/logback/core/rolling test/java/ch/qos/logback/core/rolling test/java/ch/qos/logback/core/util test/witness/rolling
by noreply.ceki＠qos.ch 30 Oct '08

30 Oct '08

Author: ceki Date: Thu Oct 30 19:43:22 2008 New Revision: 1917 Added: logback/trunk/logback-core/src/test/witness/rolling/tbr-test2.3 logback/trunk/logback-core/src/test/witness/rolling/tbr-test4.3 logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.0 logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.1 logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.2 logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.3 logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.4 Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.java logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/TimeBasedRollingTest.java logback/trunk/logback-core/src/test/java/ch/qos/logback/core/util/Compare.java logback/trunk/logback-core/src/test/witness/rolling/tbr-test2.2 logback/trunk/logback-core/src/test/witness/rolling/tbr-test4.2 Log: - fixed LBCORE-21, TimeBasedRollingPolicy will now check at initialization time to see if an existing target file needs to be rolled over - further refactoring of TimebasedRollingPolicyTest Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java Thu Oct 30 19:43:22 2008 @@ -1,7 +1,7 @@ /** - * Logback: the reliable, generic, fast and flexible logging framework. + * Logback: the generic, reliable, fast and flexible logging framework. * - * Copyright (C) 1999-2006, QOS.ch + * Copyright (C) 2000-2008, QOS.ch * * This library is free software, you can redistribute it and/or modify it under * the terms of the GNU Lesser General Public License as published by the Free @@ -25,7 +25,6 @@ * * @author Heinz Richter * @author Ceki Gülcü - * @since 1.3 * */ public class RollingFileAppender<E> extends FileAppender<E> { File activeFileCache; Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/TimeBasedRollingPolicy.java Thu Oct 30 19:43:22 2008 @@ -14,8 +14,8 @@ import java.util.concurrent.Future; import ch.qos.logback.core.rolling.helper.AsynchronousCompressor; -import ch.qos.logback.core.rolling.helper.Compressor; import ch.qos.logback.core.rolling.helper.CompressionMode; +import ch.qos.logback.core.rolling.helper.Compressor; import ch.qos.logback.core.rolling.helper.DateTokenConverter; import ch.qos.logback.core.rolling.helper.FileNamePattern; import ch.qos.logback.core.rolling.helper.RenameUtil; @@ -24,9 +24,8 @@ /** * <code>TimeBasedRollingPolicy</code> is both easy to configure and quite - * powerful. It allows the roll over to be made based on time. It is - * possible to specify that the roll over occur once per day, per week or - * per month. + * powerful. It allows the roll over to be made based on time. It is possible to + * specify that the roll over occur once per day, per week or per month. * * For more information, please refer to the online manual at * http://logback.qos.ch/manual/appenders.html#TimeBasedRollingPolicy @@ -37,21 +36,21 @@ TriggeringPolicy<E> { static final String FNP_NOT_SET = "The FileNamePattern option must be set before using TimeBasedRollingPolicy. "; static final String SEE_FNP_NOT_SET = "See also http://logback.qos.ch/codes.html#tbr_fnp_not_set"; - static final int DEFAULT_MAX_HISTORY = 0; + static final int NO_DELETE_HISTORY = 0; RollingCalendar rc; long currentTime; long nextCheck; // indicate whether the time has been forced or not boolean isTimeForced = false; - Date lastCheck = new Date(); + Date lastCheck = null; String elapsedPeriodsFileName; FileNamePattern activeFileNamePattern; RenameUtil util = new RenameUtil(); String lastGeneratedFileName; Future<?> future; - int maxHistory = DEFAULT_MAX_HISTORY; + int maxHistory = NO_DELETE_HISTORY; TimeBasedCleaner tbCleaner; public void setCurrentTime(long timeInMillis) { @@ -113,15 +112,32 @@ + "' from file name pattern '" + fileNamePattern.getPattern() + "'."); rc.printPeriodicity(this); - // currentTime = System.currentTimeMillis(); - lastCheck.setTime(getCurrentTime()); + // lastCheck can be set by test classes + // if it has not been set, we set it here + if (lastCheck == null) { + lastCheck = new Date(); + lastCheck.setTime(getCurrentTime()); + if (getParentFileName() != null) { + File currentFile = new File(getParentFileName()); + if (currentFile.exists() && currentFile.canRead()) { + lastCheck.setTime(currentFile.lastModified()); + } + } + } nextCheck = rc.getNextTriggeringMillis(lastCheck); - - if (maxHistory != DEFAULT_MAX_HISTORY) { + + if (maxHistory != NO_DELETE_HISTORY) { tbCleaner = new TimeBasedCleaner(fileNamePattern, rc, maxHistory); } } + + // allow Test classes to act on the lastCheck field to simulate old + // log files needing rollover + void setLastCheck(Date _lastCheck) { + this.lastCheck = _lastCheck; + } + public void rollover() throws RolloverFailure { // when rollover is called the elapsed period's file has @@ -140,7 +156,7 @@ if (tbCleaner != null) { tbCleaner.clean(new Date(getCurrentTime())); } - + // let's update the parent active file name setParentFileName(getNewActiveFileName()); @@ -183,19 +199,17 @@ * file equals the file name for the current period as computed by the * FileNamePattern option. * - * - * The RollingPolicy must know wether it is responsible for changing the name - * of the active file or not. If the active file name is set by the user via - * the configuration file, then the RollingPolicy must let it like it is. If - * the user does not specify an active file name, then the RollingPolicy + * The RollingPolicy must know wether it is responsible for changing the + * name of the active file or not. If the active file name is set by the user + * via the configuration file, then the RollingPolicy must let it like it is. + * If the user does not specify an active file name, then the RollingPolicy * generates one. * - * - * To be sure that the file name used by the parent class has been generated - * by the RollingPolicy and not specified by the user, we keep track of the - * last generated name object and compare its reference to the parent file - * name. If they match, then the RollingPolicy knows it's responsible for the - * change of the file name. + * To be sure that the file name used by the parent class has been + * generated by the RollingPolicy and not specified by the user, we keep track + * of the last generated name object and compare its reference to the parent + * file name. If they match, then the RollingPolicy knows it's responsible for + * the change of the file name. * */ public String getNewActiveFileName() { @@ -214,21 +228,13 @@ long time = getCurrentTime(); if (time >= nextCheck) { - // addInfo("Time to trigger roll-over"); - // We set the elapsedPeriodsFileName before we set the 'lastCheck' - // variable + // We set the elapsedPeriodsFileName before we set the 'lastCheck' variable // The elapsedPeriodsFileName corresponds to the file name of the period // that just elapsed. elapsedPeriodsFileName = activeFileNamePattern.convertDate(lastCheck); - // addInfo("elapsedPeriodsFileName set to "+elapsedPeriodsFileName); lastCheck.setTime(time); nextCheck = rc.getNextTriggeringMillis(lastCheck); - - Date x = new Date(); - x.setTime(nextCheck); - // addInfo("Next check on "+ x); - return true; } else { return false; Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/TimeBasedRollingTest.java ============================================================================== --- logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/TimeBasedRollingTest.java (original) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/TimeBasedRollingTest.java Thu Oct 30 19:43:22 2008 @@ -16,7 +16,6 @@ import java.sql.Date; import java.text.SimpleDateFormat; import java.util.ArrayList; -import java.util.Arrays; import java.util.Calendar; import java.util.List; import java.util.concurrent.TimeUnit; @@ -69,31 +68,27 @@ Calendar cal = Calendar.getInstance(); long currentTime; // initialized in setUp() long nextRolloverThreshold; // initialized in setUp() - List<String> filenameList = new ArrayList<String>(); + List<String> expectedFilenameList = new ArrayList<String>(); @Before public void setUp() { context.setName("test"); - cal.set(Calendar.MILLISECOND, 0); + cal.set(Calendar.MILLISECOND, 333); currentTime = cal.getTimeInMillis(); recomputeRolloverThreshold(currentTime); + System.out.println("currentTime=" + sdf.format(new Date(currentTime))); // Delete .log files - { - File target = new File(Constants.OUTPUT_DIR_PREFIX + "test4.log"); - target.mkdirs(); - target.delete(); - } - { - File target = new File(Constants.OUTPUT_DIR_PREFIX + "test5.log"); - target.mkdirs(); - target.delete(); - } - { - File target = new File(Constants.OUTPUT_DIR_PREFIX + "test6.log"); - target.mkdirs(); - target.delete(); - } + deleteStaleLogFile("test4.log"); + deleteStaleLogFile("test4B.log"); + deleteStaleLogFile("test5.log"); + deleteStaleLogFile("test6.log"); + } + + void deleteStaleLogFile(String filename) { + File target = new File(Constants.OUTPUT_DIR_PREFIX + filename); + target.mkdirs(); + target.delete(); } @After @@ -122,61 +117,35 @@ rfa.start(); } - void addFileName(String testId, Date date, boolean compression) { - String fn = Constants.OUTPUT_DIR_PREFIX + testId + sdf.format(date); - if (compression) { - fn += ".gz"; - } - filenameList.add(fn); - } - - String[] computeFilenames(String testStr, boolean compression, String lastFile) { - String[] filenames = new String[3]; - int oneBeforeLast = filenames.length - 1; - for (int i = 0; i < oneBeforeLast; i++) { - filenames[i] = Constants.OUTPUT_DIR_PREFIX + testStr - + sdf.format(cal.getTime()); - if (compression) { - filenames[i] += ".gz"; - } - cal.add(Calendar.SECOND, 1); - } - if (lastFile != null) { - filenames[oneBeforeLast] = Constants.OUTPUT_DIR_PREFIX + lastFile; - } else { - filenames[oneBeforeLast] = Constants.OUTPUT_DIR_PREFIX + testStr - + sdf.format(cal.getTime()); - } - return filenames; - } - /** * Test rolling without compression, file option left blank, no stop/start */ @Test public void noCompression_FileBlank_NoRestart_1() throws Exception { - String testId = "test1-"; + String testId = "test1"; initRFA(rfa1, null); - initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + testId + "%d{" + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + testId + "-%d{" + DATE_PATTERN + "}", currentTime, 0); // compute the current filename - addFileName(testId, getTimeForElapsedPeriod(), false); + addExpectedFileName_ByDate(testId, getDateOfCurrentPeriodsStart(), false); incCurrentTime(1100); tbrp1.setCurrentTime(currentTime); for (int i = 0; i < 3; i++) { - addFileNameIfNecessary(testId, false); rfa1.doAppend("Hello---" + i); + addExpectedFileNamedIfItsTime_ByDate(testId, false); incCurrentTime(500); tbrp1.setCurrentTime(currentTime); } + System.out.println(expectedFilenameList); + int i = 0; - for (String fn : filenameList) { + for (String fn : expectedFilenameList) { assertTrue(Compare.compare(fn, Constants.TEST_DIR_PREFIX - + "witness/rolling/tbr-test1." + i++)); + + "witness/rolling/tbr-" + testId + "." + i++)); } } @@ -185,19 +154,21 @@ */ @Test public void noCompression_FileBlank_StopRestart_2() throws Exception { - String testId = "test2-"; + String testId = "test2"; initRFA(rfa1, null); - initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + testId + "%d{" + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + testId + "-%d{" + DATE_PATTERN + "}", currentTime, 0); - addFileName(testId, getTimeForElapsedPeriod(), false); + // a new file is created by virtue of rfa.start(); + addExpectedFileName_ByDate(testId, getDateOfCurrentPeriodsStart(), false); + incCurrentTime(1100); tbrp1.setCurrentTime(currentTime); for (int i = 0; i <= 2; i++) { - addFileNameIfNecessary(testId, false); rfa1.doAppend("Hello---" + i); + addExpectedFileNamedIfItsTime_ByDate(testId, false); incCurrentTime(500); tbrp1.setCurrentTime(currentTime); } @@ -205,20 +176,20 @@ rfa1.stop(); initRFA(rfa2, null); - initTRBP(rfa2, tbrp2, Constants.OUTPUT_DIR_PREFIX + "test2-%d{" + initTRBP(rfa2, tbrp2, Constants.OUTPUT_DIR_PREFIX + testId + "-%d{" + DATE_PATTERN + "}", tbrp1.getCurrentTime(), 0); for (int i = 0; i <= 2; i++) { - addFileNameIfNecessary(testId, false); - rfa2.doAppend("Hello---" + i); + addExpectedFileNamedIfItsTime_ByDate(testId, false); + rfa2.doAppend("World---" + i); incCurrentTime(100); tbrp2.setCurrentTime(currentTime); } int i = 0; - for (String fn : filenameList) { + for (String fn : expectedFilenameList) { assertTrue(Compare.compare(fn, Constants.TEST_DIR_PREFIX - + "witness/rolling/tbr-test2." + i++)); + + "witness/rolling/tbr-" + testId + "." + i++)); } } @@ -227,35 +198,31 @@ */ @Test public void withCompression_FileBlank_NoRestart_3() throws Exception { - String testId = "test3-"; + String testId = "test3"; initRFA(rfa1, null); - initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + testId + "%d{" + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + testId + "-%d{" + DATE_PATTERN + "}.gz", currentTime, 0); - String[] filenames = computeFilenames(testId, true, null); - - addFileName(testId, getTimeForElapsedPeriod(), true); + addExpectedFileName_ByDate(testId, getDateOfCurrentPeriodsStart(), true); incCurrentTime(1100); tbrp1.setCurrentTime(currentTime); for (int i = 0; i < 3; i++) { - addFileNameIfNecessary(testId, true); + // when i == 2, file name should not have .gz extension + addExpectedFileNamedIfItsTime_ByDate(testId, i != 2); rfa1.doAppend("Hello---" + i); - tbrp1.setCurrentTime(addTime(tbrp1.getCurrentTime(), 500)); + incCurrentTime(500); + tbrp1.setCurrentTime(currentTime); } tbrp1.future.get(2000, TimeUnit.MILLISECONDS); - System.out.println(Arrays.toString(filenames)); - System.out.println(filenameList.toString()); - - for (int i = 0; i < 2; i++) { - assertTrue(Compare.gzCompare(filenameList.get(i), - Constants.TEST_DIR_PREFIX + "witness/rolling/tbr-test3." + i + ".gz")); + int i = 0; + for (String fn : expectedFilenameList) { + assertTrue(Compare.compare(fn, Constants.TEST_DIR_PREFIX + + "witness/rolling/tbr-" + testId + "." + i + addGZIfNotLast(i))); + i++; } - - assertTrue(Compare.compare(filenameList.get(2), Constants.TEST_DIR_PREFIX - + "witness/rolling/tbr-test3.2")); } /** @@ -263,95 +230,89 @@ */ @Test public void noCompression_FileSet_StopRestart_4() throws Exception { - initRFA(rfa1, Constants.OUTPUT_DIR_PREFIX + "test4.log"); - initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test4-%d{" + String testId = "test4"; + initRFA(rfa1, testId2FileName(testId)); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + testId + "-%d{" + DATE_PATTERN + "}", currentTime, 0); - String[] filenames = computeFilenames("test4-", false, "test4.log"); + addExpectedFileName_ByDate(testId, getDateOfCurrentPeriodsStart(), false); - System.out.println("CT=" + sdf.format(new Date(currentTime))); - System.out.println("tbrp1 CT=" - + sdf.format(new Date(tbrp1.getCurrentTime()))); - - tbrp1.setCurrentTime(addTime(currentTime, 1100)); - - System.out.println("tbrp1 CT=" - + sdf.format(new Date(tbrp1.getCurrentTime()))); + incCurrentTime(1100); + tbrp1.setCurrentTime(currentTime); for (int i = 0; i <= 2; i++) { rfa1.doAppend("Hello---" + i); - tbrp1.setCurrentTime(addTime(tbrp1.getCurrentTime(), 500)); + addExpectedFileNamedIfItsTime_ByDate(testId, false); + incCurrentTime(500); + tbrp1.setCurrentTime(currentTime); } rfa1.stop(); - initRFA(rfa2, Constants.OUTPUT_DIR_PREFIX + "test4.log"); - initTRBP(rfa2, tbrp2, Constants.OUTPUT_DIR_PREFIX + "test4-%d{" - + DATE_PATTERN + "}", tbrp1.getCurrentTime(), tbrp1.getCurrentTime()); + initRFA(rfa2, testId2FileName(testId)); + initTRBP(rfa2, tbrp2, Constants.OUTPUT_DIR_PREFIX + testId + "-%d{" + + DATE_PATTERN + "}", currentTime, currentTime); for (int i = 0; i <= 2; i++) { rfa2.doAppend("World---" + i); - tbrp2.setCurrentTime(addTime(tbrp2.getCurrentTime(), 100)); + addExpectedFileNamedIfItsTime_ByDate(testId, false); + incCurrentTime(100); + tbrp2.setCurrentTime(currentTime); } - for (int i = 0; i < 3; i++) { - assertTrue(Compare.compare(filenames[i], Constants.TEST_DIR_PREFIX - + "witness/rolling/tbr-test4." + i)); + massageExpectedFilesToCorresponToCurrentTarget("test4.log"); + + int i = 0; + for (String fn : expectedFilenameList) { + assertTrue(Compare.compare(fn, Constants.TEST_DIR_PREFIX + + "witness/rolling/tbr-" + testId + "." + i++)); } } @Test public void noCompression_FileSet_StopRestart_WithLongWait_4B() throws Exception { - initRFA(rfa1, Constants.OUTPUT_DIR_PREFIX + "test4B.log"); - initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test4B-%d{" + String testId = "test4B"; + initRFA(rfa1, testId2FileName(testId)); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + testId + "-%d{" + DATE_PATTERN + "}", currentTime, 0); - String[] filenames = computeFilenames("test4B-", false, "test4B.log"); - - System.out.println("CT=" + sdf.format(new Date(currentTime))); - System.out.println("tbrp1 CT=" - + sdf.format(new Date(tbrp1.getCurrentTime()))); - - tbrp1.setCurrentTime(addTime(currentTime, 1100)); + addExpectedFileName_ByDate(testId, getDateOfCurrentPeriodsStart(), false); - System.out.println("tbrp1 CT=" - + sdf.format(new Date(tbrp1.getCurrentTime()))); + incCurrentTime(1100); + tbrp1.setCurrentTime(currentTime); for (int i = 0; i <= 2; i++) { rfa1.doAppend("Hello---" + i); - tbrp1.setCurrentTime(addTime(tbrp1.getCurrentTime(), 500)); + addExpectedFileNamedIfItsTime_ByDate(testId, false); + incCurrentTime(500); + tbrp1.setCurrentTime(currentTime); } rfa1.stop(); - System.out.println("post stop tbrp1 CT=" - + sdf.format(new Date(tbrp1.getCurrentTime()))); - initRFA(rfa2, Constants.OUTPUT_DIR_PREFIX + "test4B.log"); - initTRBP(rfa2, tbrp2, Constants.OUTPUT_DIR_PREFIX + "test4B-%d{" - + DATE_PATTERN + "}", tbrp1.getCurrentTime() + 3000, tbrp1 - .getCurrentTime()); + long fileTimestamp = currentTime; + incCurrentTime(2000); - System.out.println("tbrp2 CT=" - + sdf.format(new Date(tbrp2.getCurrentTime()))); + initRFA(rfa2, Constants.OUTPUT_DIR_PREFIX + "test4B.log"); + initTRBP(rfa2, tbrp2, Constants.OUTPUT_DIR_PREFIX + testId +"-%d{" + + DATE_PATTERN + "}", currentTime, fileTimestamp); for (int i = 0; i <= 2; i++) { rfa2.doAppend("World---" + i); - System.out.println("in loop tbrp2 CT=" - + sdf.format(new Date(tbrp2.getCurrentTime()))); - tbrp2.setCurrentTime(addTime(tbrp2.getCurrentTime(), 500)); + addExpectedFileNamedIfItsTime_ByDate(testId, false); + incCurrentTime(100); + tbrp2.setCurrentTime(currentTime); } - System.out.println("tbrp2 CT=" - + sdf.format(new Date(tbrp2.getCurrentTime()))); + massageExpectedFilesToCorresponToCurrentTarget("test4B.log"); - if (1 == 1) { - return; - } - for (int i = 0; i < 3; i++) { - assertTrue(Compare.compare(filenames[i], Constants.TEST_DIR_PREFIX - + "witness/rolling/tbr-test4." + i)); + int i = 0; + for (String fn : expectedFilenameList) { + assertTrue(Compare.compare(fn, Constants.TEST_DIR_PREFIX + + "witness/rolling/tbr-test4B." + i++)); } + } /** @@ -359,22 +320,30 @@ */ @Test public void noCompression_FileSet_NoRestart_5() throws Exception { - initRFA(rfa1, Constants.OUTPUT_DIR_PREFIX + "test5.log"); - initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test5-%d{" + String testId = "test5"; + + initRFA(rfa1, testId2FileName(testId)); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + testId + "-%d{" + DATE_PATTERN + "}", currentTime, 0); - String[] filenames = computeFilenames("test5-", false, "test5.log"); + addExpectedFileName_ByDate(testId, getDateOfCurrentPeriodsStart(), false); - tbrp1.setCurrentTime(addTime(currentTime, 1100)); + incCurrentTime(1100); + tbrp1.setCurrentTime(currentTime); for (int i = 0; i < 3; i++) { rfa1.doAppend("Hello---" + i); - tbrp1.setCurrentTime(addTime(tbrp1.getCurrentTime(), 500)); + addExpectedFileNamedIfItsTime_ByDate(testId, false); + incCurrentTime(500); + tbrp1.setCurrentTime(currentTime); } - for (int i = 0; i < 3; i++) { - assertTrue(Compare.compare(filenames[i], Constants.TEST_DIR_PREFIX - + "witness/rolling/tbr-test5." + i)); + massageExpectedFilesToCorresponToCurrentTarget("test5.log"); + + int i = 0; + for (String fn : expectedFilenameList) { + assertTrue(Compare.compare(fn, Constants.TEST_DIR_PREFIX + + "witness/rolling/tbr-test5." + i++)); } } @@ -383,47 +352,93 @@ */ @Test public void withCompression_FileSet_NoRestart_6() throws Exception { - initRFA(rfa1, Constants.OUTPUT_DIR_PREFIX + "test6.log"); - initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test6-%d{" + + String testId = "test6"; + + initRFA(rfa1, testId2FileName(testId)); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + testId + "-%d{" + DATE_PATTERN + "}.gz", currentTime, 0); - String[] filenames = computeFilenames("test6-", true, "test6.log"); + addExpectedFileName_ByDate(testId, getDateOfCurrentPeriodsStart(), true); - tbrp1.setCurrentTime(addTime(currentTime, 1100)); + incCurrentTime(1100); + tbrp1.setCurrentTime(currentTime); for (int i = 0; i < 3; i++) { rfa1.doAppend("Hello---" + i); - tbrp1.setCurrentTime(addTime(tbrp1.getCurrentTime(), 500)); + addExpectedFileNamedIfItsTime_ByDate(testId, true); + incCurrentTime(500); + tbrp1.setCurrentTime(currentTime); } // wait for the compression task to finish tbrp1.future.get(1000, TimeUnit.MILLISECONDS); - for (int i = 0; i < 2; i++) { - assertTrue(Compare.gzCompare(filenames[i], Constants.TEST_DIR_PREFIX - + "witness/rolling/tbr-test6." + i + ".gz")); - } + massageExpectedFilesToCorresponToCurrentTarget("test6.log"); - assertTrue(Compare.compare(filenames[2], Constants.TEST_DIR_PREFIX - + "witness/rolling/tbr-test6.2")); + int i = 0; + for (String fn : expectedFilenameList) { + assertTrue(Compare.compare(fn, Constants.TEST_DIR_PREFIX + + "witness/rolling/tbr-" + testId + "." + i + addGZIfNotLast(i))); + i++; + } } // ========================================================================= // utility methods // ========================================================================= - void addFileNameIfNecessary(String testId, boolean compression) { + String testId2FileName(String testId) { + return Constants.OUTPUT_DIR_PREFIX + testId + ".log"; + } + + void massageExpectedFilesToCorresponToCurrentTarget(String file) { + // we added one too many files by date + expectedFilenameList.remove(expectedFilenameList.size() - 1); + // since file is set, we have to add it + addExpectedFileName_ByFile(file); + } + + String addGZIfNotLast(int i) { + int lastIndex = expectedFilenameList.size() - 1; + if (i != lastIndex) { + return ".gz"; + } else { + return ""; + } + } + + void addExpectedFileName_ByDate(String testId, Date date, boolean gzExtension) { + String fn = Constants.OUTPUT_DIR_PREFIX + testId + "-" + sdf.format(date); + if (gzExtension) { + fn += ".gz"; + } + expectedFilenameList.add(fn); + } + + void addExpectedFileNamedIfItsTime_ByDate(String testId, boolean gzExtension) { if (passThresholdTime(nextRolloverThreshold)) { - addFileName(testId, getTimeForElapsedPeriod(), compression); + addExpectedFileName_ByDate(testId, getDateOfCurrentPeriodsStart(), + gzExtension); recomputeRolloverThreshold(currentTime); } } - Date getTimeForElapsedPeriod() { + void addExpectedFileName_ByFile(String filenameSuffix) { + String fn = Constants.OUTPUT_DIR_PREFIX + filenameSuffix; + expectedFilenameList.add(fn); + } + + Date getDateOfCurrentPeriodsStart() { long delta = currentTime % 1000; return new Date(currentTime - delta); } + Date getDateOfPastPeriodsStart() { + long delta = currentTime % 1000; + return new Date(currentTime - delta - 1000); + } + static long addTime(long currentTime, long timeToWait) { return currentTime + timeToWait; } @@ -441,4 +456,9 @@ void incCurrentTime(long increment) { currentTime += increment; } + + void printLongAsDate(String msg, long time) { + SimpleDateFormat sdf = new SimpleDateFormat("yyyy-MM-dd_HH_mm_ss"); + System.out.println(msg + sdf.format(new Date(time))); + } } Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/util/Compare.java ============================================================================== --- logback/trunk/logback-core/src/test/java/ch/qos/logback/core/util/Compare.java (original) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/util/Compare.java Thu Oct 30 19:43:22 2008 @@ -18,15 +18,41 @@ import java.io.InputStreamReader; import java.util.zip.GZIPInputStream; - public class Compare { static final int B1_NULL = -1; static final int B2_NULL = -2; - public static boolean compare(String file1, String file2) - throws FileNotFoundException, IOException { + public static boolean compare(String file1, String file2) throws FileNotFoundException, IOException { + if (file1.endsWith(".gz")) { + //System.out.println(file1 +" is a gz file"); + return gzFileCompare(file1, file2); + } else { + return regularFileCompare(file1, file2); + } + } + + static BufferedReader gzFileToBufferedReader(String file) throws IOException { + FileInputStream fis = new FileInputStream(file); + GZIPInputStream gzis = new GZIPInputStream(fis); + BufferedReader br = new BufferedReader(new InputStreamReader(gzis)); + return br; + } + + public static boolean gzFileCompare(String file1, String file2) throws IOException { + BufferedReader in1 = gzFileToBufferedReader(file1); + BufferedReader in2 = gzFileToBufferedReader(file2); + return bufferCompare(in1, in2, file1, file2); + } + + public static boolean regularFileCompare(String file1, String file2) + throws FileNotFoundException, IOException { BufferedReader in1 = new BufferedReader(new FileReader(file1)); BufferedReader in2 = new BufferedReader(new FileReader(file2)); + return bufferCompare(in1, in2, file1, file2); + } + + public static boolean bufferCompare(BufferedReader in1, BufferedReader in2, + String file1, String file2) throws FileNotFoundException, IOException { String s1; int lineCounter = 0; @@ -37,9 +63,8 @@ String s2 = in2.readLine(); if (!s1.equals(s2)) { - System.out.println( - "Files [" + file1 + "] and [" + file2 + "] differ on line " - + lineCounter); + System.out.println("Files [" + file1 + "] and [" + file2 + + "] differ on line " + lineCounter); System.out.println("One reads: [" + s1 + "]."); System.out.println("Other reads:[" + s2 + "]."); outputFile(file1); @@ -51,8 +76,8 @@ // the second file is longer if (in2.read() != -1) { - System.out.println( - "File [" + file2 + "] longer than file [" + file1 + "]."); + System.out.println("File [" + file2 + "] longer than file [" + file1 + + "]."); outputFile(file1); outputFile(file2); @@ -62,13 +87,13 @@ return true; } - /** + /** * * Prints file on the console. - * + * */ - private static void outputFile(String file) - throws FileNotFoundException, IOException { + private static void outputFile(String file) throws FileNotFoundException, + IOException { BufferedReader in1 = new BufferedReader(new FileReader(file)); String s1; @@ -93,43 +118,44 @@ System.out.println(s1); } } - - public static boolean gzCompare(String file1, String file2) - throws FileNotFoundException, IOException { - BufferedReader in1 = new BufferedReader(new InputStreamReader(new GZIPInputStream(new FileInputStream(file1)))); - BufferedReader in2 = new BufferedReader(new InputStreamReader(new GZIPInputStream(new FileInputStream(file2)))); - String s1; - int lineCounter = 0; + public static boolean gzCompare(String file1, String file2) + throws FileNotFoundException, IOException { + BufferedReader in1 = new BufferedReader(new InputStreamReader( + new GZIPInputStream(new FileInputStream(file1)))); + BufferedReader in2 = new BufferedReader(new InputStreamReader( + new GZIPInputStream(new FileInputStream(file2)))); - while ((s1 = in1.readLine()) != null) { - lineCounter++; + String s1; + int lineCounter = 0; - String s2 = in2.readLine(); - - if (!s1.equals(s2)) { - System.out.println( - "Files [" + file1 + "] and [" + file2 + "] differ on line " - + lineCounter); - System.out.println("One reads: [" + s1 + "]."); - System.out.println("Other reads:[" + s2 + "]."); - outputFile(file1); - outputFile(file2); + while ((s1 = in1.readLine()) != null) { + lineCounter++; - return false; - } - } + String s2 = in2.readLine(); - // the second file is longer - if (in2.read() != -1) { - System.out.println( - "File [" + file2 + "] longer than file [" + file1 + "]."); + if (!s1.equals(s2)) { + System.out.println("Files [" + file1 + "] and [" + file2 + + "] differ on line " + lineCounter); + System.out.println("One reads: [" + s1 + "]."); + System.out.println("Other reads:[" + s2 + "]."); outputFile(file1); outputFile(file2); return false; } + } - return true; + // the second file is longer + if (in2.read() != -1) { + System.out.println("File [" + file2 + "] longer than file [" + file1 + + "]."); + outputFile(file1); + outputFile(file2); + + return false; } + + return true; + } } Modified: logback/trunk/logback-core/src/test/witness/rolling/tbr-test2.2 ============================================================================== --- logback/trunk/logback-core/src/test/witness/rolling/tbr-test2.2 (original) +++ logback/trunk/logback-core/src/test/witness/rolling/tbr-test2.2 Thu Oct 30 19:43:22 2008 @@ -1,4 +1,2 @@ Hello---2 -Hello---0 -Hello---1 -Hello---2 +World---0 \ No newline at end of file Added: logback/trunk/logback-core/src/test/witness/rolling/tbr-test2.3 ============================================================================== --- (empty file) +++ logback/trunk/logback-core/src/test/witness/rolling/tbr-test2.3 Thu Oct 30 19:43:22 2008 @@ -0,0 +1,2 @@ +World---1 +World---2 \ No newline at end of file Modified: logback/trunk/logback-core/src/test/witness/rolling/tbr-test4.2 ============================================================================== --- logback/trunk/logback-core/src/test/witness/rolling/tbr-test4.2 (original) +++ logback/trunk/logback-core/src/test/witness/rolling/tbr-test4.2 Thu Oct 30 19:43:22 2008 @@ -1,4 +1,2 @@ Hello---2 World---0 -World---1 -World---2 Added: logback/trunk/logback-core/src/test/witness/rolling/tbr-test4.3 ============================================================================== --- (empty file) +++ logback/trunk/logback-core/src/test/witness/rolling/tbr-test4.3 Thu Oct 30 19:43:22 2008 @@ -0,0 +1,2 @@ +World---1 +World---2 Added: logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.0 ============================================================================== Added: logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.1 ============================================================================== --- (empty file) +++ logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.1 Thu Oct 30 19:43:22 2008 @@ -0,0 +1,2 @@ +Hello---0 +Hello---1 \ No newline at end of file Added: logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.2 ============================================================================== --- (empty file) +++ logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.2 Thu Oct 30 19:43:22 2008 @@ -0,0 +1 @@ +Hello---2 Added: logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.3 ============================================================================== --- (empty file) +++ logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.3 Thu Oct 30 19:43:22 2008 @@ -0,0 +1 @@ +World---0 \ No newline at end of file Added: logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.4 ============================================================================== --- (empty file) +++ logback/trunk/logback-core/src/test/witness/rolling/tbr-test4B.4 Thu Oct 30 19:43:22 2008 @@ -0,0 +1,2 @@ +World---1 +World---2 \ No newline at end of file

1 0

svn commit: r1916 - in logback/trunk/logback-core/src/test: java/ch/qos/logback/core/rolling witness/rolling
by noreply.ceki＠qos.ch 30 Oct '08

30 Oct '08

Author: ceki Date: Thu Oct 30 15:07:11 2008 New Revision: 1916 Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/TimeBasedRollingTest.java logback/trunk/logback-core/src/test/witness/rolling/tbr-test4.2 Log: refactoring TimeBasedRollingTest.java for improved clarity Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/TimeBasedRollingTest.java ============================================================================== --- logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/TimeBasedRollingTest.java (original) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/TimeBasedRollingTest.java Thu Oct 30 15:07:11 2008 @@ -10,11 +10,15 @@ package ch.qos.logback.core.rolling; -import static org.junit.Assert.*; +import static org.junit.Assert.assertTrue; import java.io.File; +import java.sql.Date; import java.text.SimpleDateFormat; +import java.util.ArrayList; +import java.util.Arrays; import java.util.Calendar; +import java.util.List; import java.util.concurrent.TimeUnit; import org.junit.After; @@ -63,13 +67,16 @@ TimeBasedRollingPolicy tbrp2 = new TimeBasedRollingPolicy(); Calendar cal = Calendar.getInstance(); - long currentTime; + long currentTime; // initialized in setUp() + long nextRolloverThreshold; // initialized in setUp() + List<String> filenameList = new ArrayList<String>(); @Before public void setUp() { context.setName("test"); cal.set(Calendar.MILLISECOND, 0); currentTime = cal.getTimeInMillis(); + recomputeRolloverThreshold(currentTime); // Delete .log files { @@ -102,18 +109,28 @@ } void initTRBP(RollingFileAppender<Object> rfa, TimeBasedRollingPolicy tbrp, - String filenamePattern, long currentTime) { + String filenamePattern, long givenTime, long lastCheck) { tbrp.setContext(context); tbrp.setFileNamePattern(filenamePattern); tbrp.setParent(rfa); - tbrp.setCurrentTime(currentTime); + tbrp.setCurrentTime(givenTime); + if (lastCheck != 0) { + tbrp.setLastCheck(new Date(lastCheck)); + } tbrp.start(); rfa.setRollingPolicy(tbrp); rfa.start(); } - String[] computeFilenames(String testStr, - boolean compression, String lastFile) { + void addFileName(String testId, Date date, boolean compression) { + String fn = Constants.OUTPUT_DIR_PREFIX + testId + sdf.format(date); + if (compression) { + fn += ".gz"; + } + filenameList.add(fn); + } + + String[] computeFilenames(String testStr, boolean compression, String lastFile) { String[] filenames = new String[3]; int oneBeforeLast = filenames.length - 1; for (int i = 0; i < oneBeforeLast; i++) { @@ -137,70 +154,71 @@ * Test rolling without compression, file option left blank, no stop/start */ @Test - public void test1() throws Exception { + public void noCompression_FileBlank_NoRestart_1() throws Exception { + String testId = "test1-"; initRFA(rfa1, null); - initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test1-%d{" - + DATE_PATTERN + "}", currentTime); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + testId + "%d{" + + DATE_PATTERN + "}", currentTime, 0); - String[] filenames = computeFilenames("test1-", false, null); + // compute the current filename + addFileName(testId, getTimeForElapsedPeriod(), false); - // System.out.println("Waiting until next second and 100 millis."); - tbrp1.setCurrentTime(addTime(currentTime, 1100)); - // System.out.println("Done waiting."); + incCurrentTime(1100); + tbrp1.setCurrentTime(currentTime); for (int i = 0; i < 3; i++) { + addFileNameIfNecessary(testId, false); rfa1.doAppend("Hello---" + i); - tbrp1.setCurrentTime(addTime(tbrp1.getCurrentTime(), 500)); - // Thread.sleep(500); + incCurrentTime(500); + tbrp1.setCurrentTime(currentTime); } - // for (int i = 0; i < 3; i++) { - // System.out.println(i + " expected filename [" + filenames[i] + "]."); - // } - - for (int i = 0; i < 3; i++) { - assertTrue(Compare.compare(filenames[i], Constants.TEST_DIR_PREFIX - + "witness/rolling/tbr-test1." + i)); + int i = 0; + for (String fn : filenameList) { + assertTrue(Compare.compare(fn, Constants.TEST_DIR_PREFIX + + "witness/rolling/tbr-test1." + i++)); } } /** - * No compression, with stop/restart, file option left blank + * No compression, file option left blank, with stop/restart, */ @Test - public void test2() throws Exception { + public void noCompression_FileBlank_StopRestart_2() throws Exception { + String testId = "test2-"; initRFA(rfa1, null); - initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test2-%d{" - + DATE_PATTERN + "}", currentTime); - - String[] filenames = computeFilenames("test2-", false, null); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + testId + "%d{" + + DATE_PATTERN + "}", currentTime, 0); - // System.out.println("Waiting until next second and 100 millis."); - tbrp1.setCurrentTime(addTime(currentTime, 1100)); - // System.out.println("Done waiting."); + addFileName(testId, getTimeForElapsedPeriod(), false); + incCurrentTime(1100); + tbrp1.setCurrentTime(currentTime); for (int i = 0; i <= 2; i++) { + addFileNameIfNecessary(testId, false); rfa1.doAppend("Hello---" + i); - tbrp1.setCurrentTime(addTime(tbrp1.getCurrentTime(), 500)); - // Thread.sleep(500); + incCurrentTime(500); + tbrp1.setCurrentTime(currentTime); } rfa1.stop(); initRFA(rfa2, null); initTRBP(rfa2, tbrp2, Constants.OUTPUT_DIR_PREFIX + "test2-%d{" - + DATE_PATTERN + "}", tbrp1.getCurrentTime()); + + DATE_PATTERN + "}", tbrp1.getCurrentTime(), 0); for (int i = 0; i <= 2; i++) { + addFileNameIfNecessary(testId, false); rfa2.doAppend("Hello---" + i); - tbrp2.setCurrentTime(addTime(tbrp2.getCurrentTime(), 100)); - // Thread.sleep(100); + incCurrentTime(100); + tbrp2.setCurrentTime(currentTime); } - for (int i = 0; i < 3; i++) { - assertTrue(Compare.compare(filenames[i], Constants.TEST_DIR_PREFIX - + "witness/rolling/tbr-test2." + i)); + int i = 0; + for (String fn : filenameList) { + assertTrue(Compare.compare(fn, Constants.TEST_DIR_PREFIX + + "witness/rolling/tbr-test2." + i++)); } } @@ -208,28 +226,35 @@ * With compression, file option left blank, no stop/restart */ @Test - public void test3() throws Exception { + public void withCompression_FileBlank_NoRestart_3() throws Exception { + String testId = "test3-"; initRFA(rfa1, null); - initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test3-%d{" - + DATE_PATTERN + "}.gz", currentTime); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + testId + "%d{" + + DATE_PATTERN + "}.gz", currentTime, 0); - String[] filenames = computeFilenames("test3-", true, null); + String[] filenames = computeFilenames(testId, true, null); - tbrp1.setCurrentTime(addTime(currentTime, 1100)); + addFileName(testId, getTimeForElapsedPeriod(), true); + incCurrentTime(1100); + tbrp1.setCurrentTime(currentTime); for (int i = 0; i < 3; i++) { + addFileNameIfNecessary(testId, true); rfa1.doAppend("Hello---" + i); tbrp1.setCurrentTime(addTime(tbrp1.getCurrentTime(), 500)); } tbrp1.future.get(2000, TimeUnit.MILLISECONDS); + System.out.println(Arrays.toString(filenames)); + System.out.println(filenameList.toString()); + for (int i = 0; i < 2; i++) { - assertTrue(Compare.gzCompare(filenames[i], Constants.TEST_DIR_PREFIX - + "witness/rolling/tbr-test3." + i + ".gz")); + assertTrue(Compare.gzCompare(filenameList.get(i), + Constants.TEST_DIR_PREFIX + "witness/rolling/tbr-test3." + i + ".gz")); } - assertTrue(Compare.compare(filenames[2], Constants.TEST_DIR_PREFIX + assertTrue(Compare.compare(filenameList.get(2), Constants.TEST_DIR_PREFIX + "witness/rolling/tbr-test3.2")); } @@ -237,16 +262,21 @@ * Without compression, file option set, with stop/restart */ @Test - public void test4() throws Exception { + public void noCompression_FileSet_StopRestart_4() throws Exception { initRFA(rfa1, Constants.OUTPUT_DIR_PREFIX + "test4.log"); initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test4-%d{" - + DATE_PATTERN + "}", currentTime); + + DATE_PATTERN + "}", currentTime, 0); String[] filenames = computeFilenames("test4-", false, "test4.log"); - // System.out.println("Waiting until next second and 100 millis."); + System.out.println("CT=" + sdf.format(new Date(currentTime))); + System.out.println("tbrp1 CT=" + + sdf.format(new Date(tbrp1.getCurrentTime()))); + tbrp1.setCurrentTime(addTime(currentTime, 1100)); - // System.out.println("Done waiting."); + + System.out.println("tbrp1 CT=" + + sdf.format(new Date(tbrp1.getCurrentTime()))); for (int i = 0; i <= 2; i++) { rfa1.doAppend("Hello---" + i); @@ -257,10 +287,10 @@ initRFA(rfa2, Constants.OUTPUT_DIR_PREFIX + "test4.log"); initTRBP(rfa2, tbrp2, Constants.OUTPUT_DIR_PREFIX + "test4-%d{" - + DATE_PATTERN + "}", tbrp1.getCurrentTime()); + + DATE_PATTERN + "}", tbrp1.getCurrentTime(), tbrp1.getCurrentTime()); for (int i = 0; i <= 2; i++) { - rfa2.doAppend("Hello---" + i); + rfa2.doAppend("World---" + i); tbrp2.setCurrentTime(addTime(tbrp2.getCurrentTime(), 100)); } @@ -270,14 +300,68 @@ } } + @Test + public void noCompression_FileSet_StopRestart_WithLongWait_4B() + throws Exception { + initRFA(rfa1, Constants.OUTPUT_DIR_PREFIX + "test4B.log"); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test4B-%d{" + + DATE_PATTERN + "}", currentTime, 0); + + String[] filenames = computeFilenames("test4B-", false, "test4B.log"); + + System.out.println("CT=" + sdf.format(new Date(currentTime))); + System.out.println("tbrp1 CT=" + + sdf.format(new Date(tbrp1.getCurrentTime()))); + + tbrp1.setCurrentTime(addTime(currentTime, 1100)); + + System.out.println("tbrp1 CT=" + + sdf.format(new Date(tbrp1.getCurrentTime()))); + + for (int i = 0; i <= 2; i++) { + rfa1.doAppend("Hello---" + i); + tbrp1.setCurrentTime(addTime(tbrp1.getCurrentTime(), 500)); + } + + rfa1.stop(); + System.out.println("post stop tbrp1 CT=" + + sdf.format(new Date(tbrp1.getCurrentTime()))); + + initRFA(rfa2, Constants.OUTPUT_DIR_PREFIX + "test4B.log"); + initTRBP(rfa2, tbrp2, Constants.OUTPUT_DIR_PREFIX + "test4B-%d{" + + DATE_PATTERN + "}", tbrp1.getCurrentTime() + 3000, tbrp1 + .getCurrentTime()); + + System.out.println("tbrp2 CT=" + + sdf.format(new Date(tbrp2.getCurrentTime()))); + + for (int i = 0; i <= 2; i++) { + rfa2.doAppend("World---" + i); + System.out.println("in loop tbrp2 CT=" + + sdf.format(new Date(tbrp2.getCurrentTime()))); + tbrp2.setCurrentTime(addTime(tbrp2.getCurrentTime(), 500)); + } + + System.out.println("tbrp2 CT=" + + sdf.format(new Date(tbrp2.getCurrentTime()))); + + if (1 == 1) { + return; + } + for (int i = 0; i < 3; i++) { + assertTrue(Compare.compare(filenames[i], Constants.TEST_DIR_PREFIX + + "witness/rolling/tbr-test4." + i)); + } + } + /** * No compression, file option set, without stop/restart */ @Test - public void test5() throws Exception { + public void noCompression_FileSet_NoRestart_5() throws Exception { initRFA(rfa1, Constants.OUTPUT_DIR_PREFIX + "test5.log"); initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test5-%d{" - + DATE_PATTERN + "}", currentTime); + + DATE_PATTERN + "}", currentTime, 0); String[] filenames = computeFilenames("test5-", false, "test5.log"); @@ -298,10 +382,10 @@ * With compression, file option set, no stop/restart, */ @Test - public void test6() throws Exception { + public void withCompression_FileSet_NoRestart_6() throws Exception { initRFA(rfa1, Constants.OUTPUT_DIR_PREFIX + "test6.log"); initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test6-%d{" - + DATE_PATTERN + "}.gz", currentTime); + + DATE_PATTERN + "}.gz", currentTime, 0); String[] filenames = computeFilenames("test6-", true, "test6.log"); @@ -324,8 +408,37 @@ + "witness/rolling/tbr-test6.2")); } + // ========================================================================= + // utility methods + // ========================================================================= + + void addFileNameIfNecessary(String testId, boolean compression) { + if (passThresholdTime(nextRolloverThreshold)) { + addFileName(testId, getTimeForElapsedPeriod(), compression); + recomputeRolloverThreshold(currentTime); + } + } + + Date getTimeForElapsedPeriod() { + long delta = currentTime % 1000; + return new Date(currentTime - delta); + } + static long addTime(long currentTime, long timeToWait) { return currentTime + timeToWait; } + boolean passThresholdTime(long nextRolloverThreshold) { + return currentTime >= nextRolloverThreshold; + } + + // assuming rollover every second + void recomputeRolloverThreshold(long ct) { + long delta = ct % 1000; + nextRolloverThreshold = (ct - delta) + 1000; + } + + void incCurrentTime(long increment) { + currentTime += increment; + } } Modified: logback/trunk/logback-core/src/test/witness/rolling/tbr-test4.2 ============================================================================== --- logback/trunk/logback-core/src/test/witness/rolling/tbr-test4.2 (original) +++ logback/trunk/logback-core/src/test/witness/rolling/tbr-test4.2 Thu Oct 30 15:07:11 2008 @@ -1,4 +1,4 @@ Hello---2 -Hello---0 -Hello---1 -Hello---2 +World---0 +World---1 +World---2

1 0

[JIRA] Created: (LBCORE-64) TimeBasedRollingPolicy doesn't roll if the date change happens when the application is not currently running
by Gamaliel Amaudruz (JIRA) 30 Oct '08

30 Oct '08

TimeBasedRollingPolicy doesn't roll if the date change happens when the application is not currently running ------------------------------------------------------------------------------------------------------------ Key: LBCORE-64 URL: http://jira.qos.ch/browse/LBCORE-64 Project: logback-core Issue Type: Bug Components: Rolling Affects Versions: unspecified Environment: Windows, JSE6 Reporter: Gamaliel Amaudruz Assignee: Logback dev list Priority: Minor I discovered the same. I've been using log4j for years and it behaves differently than logback in this context, it will roll the log according to the configuration regardless of the execution context, which is imho a better behavior. I hope it would be possible to fix this issue or at least give an option between the two behaviors. Here is how I use it: - I have a monitoring task that is run every ten minutes and lasts for a dozen of seconds. I set logback to roll the logs everyday but it never happens because logback rolls ONLY if it is running while the date changes. I end up with a very huge log file that never rolls. Log4j will roll it during the first new execution after the date has changed. More info: http://www.qos.ch/pipermail/logback-user/2008-October/000626.html -- 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

2 4

svn commit: r1915 - logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling
by noreply.ceki＠qos.ch 29 Oct '08

29 Oct '08

Author: ceki Date: Wed Oct 29 23:04:19 2008 New Revision: 1915 Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/PackageTest.java logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/TimeBasedRollingTest.java Log: - refactoring TimeBasedRollingTest for improved clarity Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/PackageTest.java ============================================================================== --- logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/PackageTest.java (original) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/PackageTest.java Wed Oct 29 23:04:19 2008 @@ -11,7 +11,7 @@ TestSuite suite = new TestSuite(); suite.addTestSuite(RenamingTest.class); suite.addTest(new JUnit4TestAdapter(SizeBasedRollingTest.class)); - suite.addTestSuite(TimeBasedRollingTest.class); + suite.addTest(new JUnit4TestAdapter(TimeBasedRollingTest.class)); suite.addTest(ch.qos.logback.core.rolling.helper.PackageTest.suite()); return suite; } Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/TimeBasedRollingTest.java ============================================================================== --- logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/TimeBasedRollingTest.java (original) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/rolling/TimeBasedRollingTest.java Wed Oct 29 23:04:19 2008 @@ -10,14 +10,17 @@ package ch.qos.logback.core.rolling; +import static org.junit.Assert.*; + import java.io.File; import java.text.SimpleDateFormat; import java.util.Calendar; import java.util.concurrent.TimeUnit; -import junit.framework.Test; -import junit.framework.TestCase; -import junit.framework.TestSuite; +import org.junit.After; +import org.junit.Before; +import org.junit.Test; + import ch.qos.logback.core.Context; import ch.qos.logback.core.ContextBase; import ch.qos.logback.core.layout.EchoLayout; @@ -45,19 +48,29 @@ * * @author Ceki Gülcü */ -public class TimeBasedRollingTest extends TestCase { +public class TimeBasedRollingTest { static final String DATE_PATTERN = "yyyy-MM-dd_HH_mm_ss"; + SimpleDateFormat sdf = new SimpleDateFormat(DATE_PATTERN); EchoLayout<Object> layout = new EchoLayout<Object>(); Context context = new ContextBase(); - public TimeBasedRollingTest(String name) { - super(name); - } + RollingFileAppender<Object> rfa1 = new RollingFileAppender<Object>(); + TimeBasedRollingPolicy tbrp1 = new TimeBasedRollingPolicy(); + + RollingFileAppender<Object> rfa2 = new RollingFileAppender<Object>(); + TimeBasedRollingPolicy tbrp2 = new TimeBasedRollingPolicy(); + Calendar cal = Calendar.getInstance(); + long currentTime; + + @Before public void setUp() { context.setName("test"); + cal.set(Calendar.MILLISECOND, 0); + currentTime = cal.getTimeInMillis(); + // Delete .log files { File target = new File(Constants.OUTPUT_DIR_PREFIX + "test4.log"); @@ -76,47 +89,68 @@ } } + @After public void tearDown() { } - /** - * Test rolling without compression, file option left blank, no stop/start - */ - public void test1() throws Exception { - Calendar cal = Calendar.getInstance(); - cal.set(Calendar.MILLISECOND, 0); - long currentTime = cal.getTimeInMillis(); - - RollingFileAppender<Object> rfa = new RollingFileAppender<Object>(); + void initRFA(RollingFileAppender<Object> rfa, String filename) { rfa.setContext(context); rfa.setLayout(layout); + if (filename != null) { + rfa.setFile(filename); + } + } - TimeBasedRollingPolicy tbrp = new TimeBasedRollingPolicy(); + void initTRBP(RollingFileAppender<Object> rfa, TimeBasedRollingPolicy tbrp, + String filenamePattern, long currentTime) { tbrp.setContext(context); - tbrp.setFileNamePattern(Constants.OUTPUT_DIR_PREFIX + "test1-%d{" - + DATE_PATTERN + "}"); + tbrp.setFileNamePattern(filenamePattern); tbrp.setParent(rfa); tbrp.setCurrentTime(currentTime); tbrp.start(); rfa.setRollingPolicy(tbrp); rfa.start(); + } - SimpleDateFormat sdf = new SimpleDateFormat(DATE_PATTERN); + String[] computeFilenames(String testStr, + boolean compression, String lastFile) { String[] filenames = new String[3]; - - for (int i = 0; i < 3; i++) { - filenames[i] = Constants.OUTPUT_DIR_PREFIX + "test1-" + int oneBeforeLast = filenames.length - 1; + for (int i = 0; i < oneBeforeLast; i++) { + filenames[i] = Constants.OUTPUT_DIR_PREFIX + testStr + sdf.format(cal.getTime()); + if (compression) { + filenames[i] += ".gz"; + } cal.add(Calendar.SECOND, 1); } + if (lastFile != null) { + filenames[oneBeforeLast] = Constants.OUTPUT_DIR_PREFIX + lastFile; + } else { + filenames[oneBeforeLast] = Constants.OUTPUT_DIR_PREFIX + testStr + + sdf.format(cal.getTime()); + } + return filenames; + } + + /** + * Test rolling without compression, file option left blank, no stop/start + */ + @Test + public void test1() throws Exception { + initRFA(rfa1, null); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test1-%d{" + + DATE_PATTERN + "}", currentTime); + + String[] filenames = computeFilenames("test1-", false, null); // System.out.println("Waiting until next second and 100 millis."); - tbrp.setCurrentTime(addTime(currentTime, 1100)); + tbrp1.setCurrentTime(addTime(currentTime, 1100)); // System.out.println("Done waiting."); for (int i = 0; i < 3; i++) { - rfa.doAppend("Hello---" + i); - tbrp.setCurrentTime(addTime(tbrp.getCurrentTime(), 500)); + rfa1.doAppend("Hello---" + i); + tbrp1.setCurrentTime(addTime(tbrp1.getCurrentTime(), 500)); // Thread.sleep(500); } @@ -133,33 +167,14 @@ /** * No compression, with stop/restart, file option left blank */ + @Test public void test2() throws Exception { - Calendar cal = Calendar.getInstance(); - cal.set(Calendar.MILLISECOND, 0); - long currentTime = cal.getTimeInMillis(); - RollingFileAppender<Object> rfa1 = new RollingFileAppender<Object>(); - rfa1.setContext(context); - rfa1.setLayout(layout); - - TimeBasedRollingPolicy tbrp1 = new TimeBasedRollingPolicy(); - tbrp1.setFileNamePattern(Constants.OUTPUT_DIR_PREFIX + "test2-%d{" - + DATE_PATTERN + "}"); - tbrp1.setContext(context); - tbrp1.setParent(rfa1); - tbrp1.setCurrentTime(currentTime); - tbrp1.start(); - rfa1.setRollingPolicy(tbrp1); - rfa1.start(); - - SimpleDateFormat sdf = new SimpleDateFormat(DATE_PATTERN); - String[] filenames = new String[3]; + initRFA(rfa1, null); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test2-%d{" + + DATE_PATTERN + "}", currentTime); - for (int i = 0; i < 3; i++) { - filenames[i] = Constants.OUTPUT_DIR_PREFIX + "test2-" - + sdf.format(cal.getTime()); - cal.add(Calendar.SECOND, 1); - } + String[] filenames = computeFilenames("test2-", false, null); // System.out.println("Waiting until next second and 100 millis."); tbrp1.setCurrentTime(addTime(currentTime, 1100)); @@ -173,19 +188,9 @@ rfa1.stop(); - RollingFileAppender<Object> rfa2 = new RollingFileAppender<Object>(); - rfa2.setContext(context); - rfa2.setLayout(layout); - - TimeBasedRollingPolicy tbrp2 = new TimeBasedRollingPolicy(); - tbrp2.setContext(context); - tbrp2.setFileNamePattern(Constants.OUTPUT_DIR_PREFIX + "test2-%d{" - + DATE_PATTERN + "}"); - tbrp2.setParent(rfa2); - tbrp2.setCurrentTime(tbrp1.getCurrentTime()); - tbrp2.start(); - rfa2.setRollingPolicy(tbrp2); - rfa2.start(); + initRFA(rfa2, null); + initTRBP(rfa2, tbrp2, Constants.OUTPUT_DIR_PREFIX + "test2-%d{" + + DATE_PATTERN + "}", tbrp1.getCurrentTime()); for (int i = 0; i <= 2; i++) { rfa2.doAppend("Hello---" + i); @@ -202,90 +207,42 @@ /** * With compression, file option left blank, no stop/restart */ + @Test public void test3() throws Exception { - Calendar cal = Calendar.getInstance(); - cal.set(Calendar.MILLISECOND, 0); - long currentTime = cal.getTimeInMillis(); + initRFA(rfa1, null); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test3-%d{" + + DATE_PATTERN + "}.gz", currentTime); - RollingFileAppender<Object> rfa = new RollingFileAppender<Object>(); - rfa.setContext(context); - rfa.setLayout(layout); + String[] filenames = computeFilenames("test3-", true, null); - TimeBasedRollingPolicy tbrp = new TimeBasedRollingPolicy(); - tbrp.setContext(context); - tbrp.setFileNamePattern(Constants.OUTPUT_DIR_PREFIX + "test3-%d{" - + DATE_PATTERN + "}.gz"); - tbrp.setParent(rfa); - tbrp.setCurrentTime(currentTime); - tbrp.start(); - rfa.setRollingPolicy(tbrp); - rfa.start(); - - SimpleDateFormat sdf = new SimpleDateFormat(DATE_PATTERN); - String[] filenames = new String[4]; - - for (int i = 0; i < 2; i++) { - filenames[i] = Constants.OUTPUT_DIR_PREFIX + "test3-" - + sdf.format(cal.getTime()) + ".gz"; - cal.add(Calendar.SECOND, 1); - } - - filenames[3] = Constants.OUTPUT_DIR_PREFIX + "test3-" - + sdf.format(cal.getTime()); - - // System.out.println("Waiting until next second and 100 millis."); - tbrp.setCurrentTime(addTime(currentTime, 1100)); - // System.out.println("Done waiting."); + tbrp1.setCurrentTime(addTime(currentTime, 1100)); for (int i = 0; i < 3; i++) { - rfa.doAppend("Hello---" + i); - tbrp.setCurrentTime(addTime(tbrp.getCurrentTime(), 500)); + rfa1.doAppend("Hello---" + i); + tbrp1.setCurrentTime(addTime(tbrp1.getCurrentTime(), 500)); } - tbrp.future.get(2000, TimeUnit.MILLISECONDS); + tbrp1.future.get(2000, TimeUnit.MILLISECONDS); for (int i = 0; i < 2; i++) { assertTrue(Compare.gzCompare(filenames[i], Constants.TEST_DIR_PREFIX + "witness/rolling/tbr-test3." + i + ".gz")); } - assertTrue(Compare.compare(filenames[3], Constants.TEST_DIR_PREFIX + assertTrue(Compare.compare(filenames[2], Constants.TEST_DIR_PREFIX + "witness/rolling/tbr-test3.2")); } /** * Without compression, file option set, with stop/restart */ + @Test public void test4() throws Exception { - Calendar cal = Calendar.getInstance(); - cal.set(Calendar.MILLISECOND, 0); - long currentTime = cal.getTimeInMillis(); + initRFA(rfa1, Constants.OUTPUT_DIR_PREFIX + "test4.log"); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test4-%d{" + + DATE_PATTERN + "}", currentTime); - RollingFileAppender<Object> rfa1 = new RollingFileAppender<Object>(); - rfa1.setContext(context); - rfa1.setLayout(layout); - rfa1.setFile(Constants.OUTPUT_DIR_PREFIX + "test4.log"); - - TimeBasedRollingPolicy tbrp1 = new TimeBasedRollingPolicy(); - tbrp1.setContext(context); - // tbrp1.setActiveFileName(Constants.TEST_DIR_PREFIX + "output/test4.log"); - tbrp1.setFileNamePattern(Constants.OUTPUT_DIR_PREFIX + "test4-%d{" - + DATE_PATTERN + "}"); - tbrp1.setParent(rfa1); - tbrp1.setCurrentTime(currentTime); - tbrp1.start(); - rfa1.setRollingPolicy(tbrp1); - rfa1.start(); - - SimpleDateFormat sdf = new SimpleDateFormat(DATE_PATTERN); - String[] filenames = new String[3]; - - for (int i = 0; i < 2; i++) { - filenames[i] = Constants.OUTPUT_DIR_PREFIX + "test4-" - + sdf.format(cal.getTime()); - cal.add(Calendar.SECOND, 1); - } - filenames[2] = Constants.OUTPUT_DIR_PREFIX + "test4.log"; + String[] filenames = computeFilenames("test4-", false, "test4.log"); // System.out.println("Waiting until next second and 100 millis."); tbrp1.setCurrentTime(addTime(currentTime, 1100)); @@ -298,21 +255,9 @@ rfa1.stop(); - RollingFileAppender<Object> rfa2 = new RollingFileAppender<Object>(); - rfa2.setContext(context); - rfa2.setLayout(layout); - rfa2.setFile(Constants.OUTPUT_DIR_PREFIX + "test4.log"); - - TimeBasedRollingPolicy tbrp2 = new TimeBasedRollingPolicy(); - tbrp2.setContext(context); - tbrp2.setFileNamePattern(Constants.OUTPUT_DIR_PREFIX + "test4-%d{" - + DATE_PATTERN + "}"); - // tbrp2.setActiveFileName(Constants.TEST_DIR_PREFIX + "output/test4.log"); - tbrp2.setParent(rfa2); - tbrp2.setCurrentTime(tbrp1.getCurrentTime()); - tbrp2.start(); - rfa2.setRollingPolicy(tbrp2); - rfa2.start(); + initRFA(rfa2, Constants.OUTPUT_DIR_PREFIX + "test4.log"); + initTRBP(rfa2, tbrp2, Constants.OUTPUT_DIR_PREFIX + "test4-%d{" + + DATE_PATTERN + "}", tbrp1.getCurrentTime()); for (int i = 0; i <= 2; i++) { rfa2.doAppend("Hello---" + i); @@ -328,45 +273,19 @@ /** * No compression, file option set, without stop/restart */ + @Test public void test5() throws Exception { - Calendar cal = Calendar.getInstance(); - cal.set(Calendar.MILLISECOND, 0); - long currentTime = cal.getTimeInMillis(); + initRFA(rfa1, Constants.OUTPUT_DIR_PREFIX + "test5.log"); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test5-%d{" + + DATE_PATTERN + "}", currentTime); - RollingFileAppender<Object> rfa = new RollingFileAppender<Object>(); - rfa.setContext(context); - rfa.setLayout(layout); - rfa.setFile(Constants.OUTPUT_DIR_PREFIX + "test5.log"); + String[] filenames = computeFilenames("test5-", false, "test5.log"); - TimeBasedRollingPolicy tbrp = new TimeBasedRollingPolicy(); - tbrp.setContext(context); - tbrp.setFileNamePattern(Constants.OUTPUT_DIR_PREFIX + "test5-%d{" - + DATE_PATTERN + "}"); - // tbrp.setActiveFileName(Constants.TEST_DIR_PREFIX + "output/test5.log"); - tbrp.setParent(rfa); - tbrp.setCurrentTime(currentTime); - tbrp.start(); - rfa.setRollingPolicy(tbrp); - rfa.start(); - - SimpleDateFormat sdf = new SimpleDateFormat(DATE_PATTERN); - String[] filenames = new String[4]; - - for (int i = 0; i < 2; i++) { - filenames[i] = Constants.OUTPUT_DIR_PREFIX + "test5-" - + sdf.format(cal.getTime()); - cal.add(Calendar.SECOND, 1); - } - - filenames[2] = Constants.OUTPUT_DIR_PREFIX + "test5.log"; - - // System.out.println("Waiting until next second and 100 millis."); - tbrp.setCurrentTime(addTime(currentTime, 1100)); - // System.out.println("Done waiting."); + tbrp1.setCurrentTime(addTime(currentTime, 1100)); for (int i = 0; i < 3; i++) { - rfa.doAppend("Hello---" + i); - tbrp.setCurrentTime(addTime(tbrp.getCurrentTime(), 500)); + rfa1.doAppend("Hello---" + i); + tbrp1.setCurrentTime(addTime(tbrp1.getCurrentTime(), 500)); } for (int i = 0; i < 3; i++) { @@ -378,54 +297,24 @@ /** * With compression, file option set, no stop/restart, */ + @Test public void test6() throws Exception { - Calendar cal = Calendar.getInstance(); - cal.set(Calendar.MILLISECOND, 0); - long currentTime = cal.getTimeInMillis(); + initRFA(rfa1, Constants.OUTPUT_DIR_PREFIX + "test6.log"); + initTRBP(rfa1, tbrp1, Constants.OUTPUT_DIR_PREFIX + "test6-%d{" + + DATE_PATTERN + "}.gz", currentTime); - RollingFileAppender<Object> rfa = new RollingFileAppender<Object>(); - rfa.setContext(context); - rfa.setLayout(layout); - rfa.setFile(Constants.OUTPUT_DIR_PREFIX+ "test6.log"); + String[] filenames = computeFilenames("test6-", true, "test6.log"); - TimeBasedRollingPolicy tbrp = new TimeBasedRollingPolicy(); - tbrp.setContext(context); - tbrp.setFileNamePattern(Constants.OUTPUT_DIR_PREFIX + "test6-%d{" - + DATE_PATTERN + "}.gz"); - // tbrp.setActiveFileName(Constants.TEST_DIR_PREFIX + "output/test6.log"); - tbrp.setParent(rfa); - tbrp.setCurrentTime(currentTime); - tbrp.start(); - rfa.setRollingPolicy(tbrp); - rfa.start(); - - SimpleDateFormat sdf = new SimpleDateFormat(DATE_PATTERN); - String[] filenames = new String[4]; - - for (int i = 0; i < 2; i++) { - filenames[i] = Constants.OUTPUT_DIR_PREFIX + "test6-" - + sdf.format(cal.getTime()) + ".gz"; - cal.add(Calendar.SECOND, 1); - } - - filenames[2] = Constants.OUTPUT_DIR_PREFIX + "test6.log"; - - // System.out.println("Waiting until next second and 100 millis."); - tbrp.setCurrentTime(addTime(currentTime, 1100)); - // System.out.println("Done waiting."); + tbrp1.setCurrentTime(addTime(currentTime, 1100)); for (int i = 0; i < 3; i++) { - rfa.doAppend("Hello---" + i); - tbrp.setCurrentTime(addTime(tbrp.getCurrentTime(), 500)); + rfa1.doAppend("Hello---" + i); + tbrp1.setCurrentTime(addTime(tbrp1.getCurrentTime(), 500)); } - // for (int i = 0; i < 4; i++) { - // System.out.println(i + " expected filename [" + filenames[i] + "]."); - // } - // wait for the compression task to finish - tbrp.future.get(1000, TimeUnit.MILLISECONDS); - + tbrp1.future.get(1000, TimeUnit.MILLISECONDS); + for (int i = 0; i < 2; i++) { assertTrue(Compare.gzCompare(filenames[i], Constants.TEST_DIR_PREFIX + "witness/rolling/tbr-test6." + i + ".gz")); @@ -435,12 +324,6 @@ + "witness/rolling/tbr-test6.2")); } - public static Test suite() { - TestSuite suite = new TestSuite(); - suite.addTestSuite(TimeBasedRollingTest.class); - return suite; - } - static long addTime(long currentTime, long timeToWait) { return currentTime + timeToWait; }

1 0