[logback-dev] svn commit: r2349 - in logback/trunk/logback-classic/src: main/java/ch/qos/logback/classic main/java/ch/qos/logback/classic/turbo test/input/turbo test/java/ch/qos/logback/classic/turbo

noreply.ceki at qos.ch noreply.ceki at qos.ch
Wed Jul 15 10:54:52 CEST 2009


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());
       }
     }
-
   }
 
 }


More information about the logback-dev mailing list