Author: ceki Date: Wed Jul 15 10:54:51 2009 New Revision: 2349 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/turbo/ReconfigureOnChangeFilter.java logback/trunk/logback-classic/src/test/input/turbo/scan1.xml logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java Log: - Tested version of ReconfigureOnChnage. Related to LBCORE-59 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 Wed Jul 15 10:54:51 2009 @@ -66,6 +66,8 @@ boolean started = false; + int resetCount = 0; + public LoggerContext() { super(); this.loggerCache = new Hashtable<String, Logger>(); @@ -207,6 +209,7 @@ */ @Override public void reset() { + resetCount++; super.reset(); root.recursiveReset(); resetTurboFilterList(); @@ -347,5 +350,10 @@ public void setMaxCallerDataDepth(int maxCallerDataDepth) { this.maxCallerDataDepth = maxCallerDataDepth; } + + @Override + public String getName() { + return "resetCount="+resetCount; + } } Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java Wed Jul 15 10:54:51 2009 @@ -30,6 +30,9 @@ */ public class ReconfigureOnChangeFilter extends TurboFilter { + final static long INIT = System.currentTimeMillis(); + final static long SENTINEL = Long.MAX_VALUE; + final static long DEFAULT_REFRESH_PERIOD = 60 * 1000; // 1 minute long refreshPeriod = DEFAULT_REFRESH_PERIOD; File fileToScan; @@ -43,15 +46,17 @@ if (url != null) { fileToScan = convertToFile(url); if (fileToScan != null) { - long inSeconds = refreshPeriod / 1000; - addInfo("Will scan for changes in file [" + fileToScan + "] every " - + inSeconds + " seconds"+ " Thread "+currentThreadName()); - lastModified = fileToScan.lastModified(); - updateNextCheck(System.currentTimeMillis()); + synchronized (context) { + long inSeconds = refreshPeriod / 1000; + addInfo("Will scan for changes in file [" + fileToScan + "] every " + + inSeconds + " seconds. "+stem()); + lastModified = fileToScan.lastModified(); + updateNextCheck(System.currentTimeMillis()); + } super.start(); } } else { - addError("Could not find URL of file to scan. Thread "+currentThreadName()); + addError("Could not find URL of file to scan."); } } @@ -86,11 +91,15 @@ return FilterReply.NEUTRAL; } - boolean changed = changeDetected(); - if (changed) { - addInfo("[" + fileToScan + "] change detected. Reconfiguring "+currentThreadName()); - addInfo("Resetting and reconfiguring context [" + context.getName() + "]"); - reconfigure(); + synchronized (context) { + boolean changed = changeDetected(); + if (changed) { + addInfo("[" + fileToScan + "] change detected. Reconfiguring. "+stem()); + + addInfo("Resetting and reconfiguring context [" + context.getName() + + "]"); + reconfigure(); + } } return FilterReply.NEUTRAL; } @@ -99,12 +108,17 @@ nextCheck = now + refreshPeriod; } + String stem() { + return currentThreadName() + ", context " + context.getName() + + ", nextCheck=" + (nextCheck - INIT); + } + // This method is synchronized to prevent near-simultaneous re-configurations - protected synchronized boolean changeDetected() { + protected boolean changeDetected() { long now = System.currentTimeMillis(); if (now >= nextCheck) { updateNextCheck(now); - return (lastModified != fileToScan.lastModified()); + return (lastModified != fileToScan.lastModified() && lastModified != SENTINEL); } return false; } @@ -112,7 +126,19 @@ String currentThreadName() { return Thread.currentThread().getName(); } + + void disableSubsequentRecofiguration() { + lastModified = SENTINEL; + } + protected void reconfigure() { + // Even though this method resets the loggerContext, which clears the list + // of turbo filters including this instance, it is still possible for this + // instance to be subsequently invoked by another thread if it was already + // executing when the context was reset. + // We prevent multiple reconfigurations (for the same file change event) by + // setting an appropriate sentinel value for lastMofidied field. + disableSubsequentRecofiguration(); JoranConfigurator jc = new JoranConfigurator(); jc.setContext(context); LoggerContext lc = (LoggerContext) context; Modified: logback/trunk/logback-classic/src/test/input/turbo/scan1.xml ============================================================================== --- logback/trunk/logback-classic/src/test/input/turbo/scan1.xml (original) +++ logback/trunk/logback-classic/src/test/input/turbo/scan1.xml Wed Jul 15 10:54:51 2009 @@ -1,7 +1,7 @@ <?xml version="1.0" encoding="UTF-8" ?> <!DOCTYPE configuration> -<configuration scan="true" scanPeriod="1 millisecond"> +<configuration scan="true" scanPeriod="10 millisecond"> <root level="ERROR"/> </configuration> \ No newline at end of file Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java Wed Jul 15 10:54:51 2009 @@ -1,6 +1,5 @@ package ch.qos.logback.classic.turbo; -import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertTrue; import java.io.File; @@ -13,7 +12,6 @@ import ch.qos.logback.classic.issue.lbclassic135.LoggingRunnable; import ch.qos.logback.classic.joran.JoranConfigurator; import ch.qos.logback.classic.util.TeztConstants; - import ch.qos.logback.core.contention.MultiThreadedHarness; import ch.qos.logback.core.contention.RunnableWithCounterAndDone; import ch.qos.logback.core.joran.spi.JoranException; @@ -23,13 +21,15 @@ public class ReconfigureOnChangeTest { LoggerContext loggerContext = new LoggerContext(); Logger logger = loggerContext.getLogger(this.getClass()); - final static int THREAD_COUNT = 3; + final static int THREAD_COUNT = 5; + + static int TOTAL_TEST_DURATION = 2000; + // it actually takes time for Windows to propagate file modification changes + // values below 100 milliseconds can be problematic + static int SLEEP_BETWEEN_UPDATES = 300; - static int TOTAL_TEST_DURATION = 10000; - static int SLEEP_BETWEEN_UPDATES = 1000; - MultiThreadedHarness harness = new MultiThreadedHarness(TOTAL_TEST_DURATION); - + void configure(String file) throws JoranException { JoranConfigurator jc = new JoranConfigurator(); jc.setContext(loggerContext); @@ -57,36 +57,38 @@ File file = new File(configFileAsStr); RunnableWithCounterAndDone[] runnableArray = buildRunnableArray(file); harness.execute(runnableArray); - + long expectedRreconfigurations = runnableArray[0].getCounter(); - + StatusChecker checker = new StatusChecker(loggerContext); StatusPrinter.print(loggerContext); assertTrue(checker.isErrorFree()); int result = checker.matchCount("Resetting and reconfiguring context"); - assertEquals(expectedRreconfigurations, result); - + assertTrue(expectedRreconfigurations >= result); } + + class Updater extends RunnableWithCounterAndDone { File configFile; + Updater(File configFile) { this.configFile = configFile; } + public void run() { while (!isDone()) { try { Thread.sleep(SLEEP_BETWEEN_UPDATES); } catch (InterruptedException e) { } - if(isDone()) { + if (isDone()) { return; } counter++; configFile.setLastModified(System.currentTimeMillis()); } } - } }