Author: ceki Date: Tue Jul 14 22:47:17 2009 New Revision: 2348 Added: logback/trunk/logback-classic/src/test/input/turbo/ logback/trunk/logback-classic/src/test/input/turbo/scan1.xml logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic135/LoggingRunnable.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/joran/JoranConfiguratorTest.java logback/trunk/logback-core/src/test/java/ch/qos/logback/core/contention/MultiThreadedHarness.java logback/trunk/logback-core/src/test/java/ch/qos/logback/core/status/StatusChecker.java Log: - testing auto reconfiguration in a multi-threaded environment. Related to LBCORE-59 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 Tue Jul 14 22:47:17 2009 @@ -25,66 +25,71 @@ /** * Reconfigure a LoggerContext when the configuration file changes. * - * @author Ceki Gulcu - * - * */ + * @author Ceki Gulcu + * + */ public class ReconfigureOnChangeFilter extends TurboFilter { - final static long DEFAULT_REFRESH_PERIOD = 60*1000; // 1 minute + final static long DEFAULT_REFRESH_PERIOD = 60 * 1000; // 1 minute long refreshPeriod = DEFAULT_REFRESH_PERIOD; File fileToScan; protected long nextCheck; long lastModified; - @Override public void start() { - URL url = (URL) context.getObject(CoreConstants.URL_OF_LAST_CONFIGURATION_VIA_JORAN); - if(url != null) { + URL url = (URL) context + .getObject(CoreConstants.URL_OF_LAST_CONFIGURATION_VIA_JORAN); + if (url != null) { fileToScan = convertToFile(url); - if(fileToScan != null) { - long inSeconds = refreshPeriod/1000; - addInfo("Will scan for changes in file ["+fileToScan+"] every "+inSeconds+" seconds"); + 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()); super.start(); } } else { - addError("Could not find URL of file to scan."); + addError("Could not find URL of file to scan. Thread "+currentThreadName()); } } - + File convertToFile(URL url) { String protocol = url.getProtocol(); - if("file".equals(protocol)) { + if ("file".equals(protocol)) { File file = new File(url.getFile()); return file; } else { - addError("URL ["+url+"] is not of type file"); + addError("URL [" + url + "] is not of type file"); return null; } } - + // a counter of the number of time the decide method is called - private volatile int invocationCounter = 0; - + // IMPORTANT: This field can be updated by multiple threads. It follows that + // its values may not be incremented sequentially. However, we don't care + // about the actual value of the field except that from time to time the + // expression (invocationCounter++ & 0xF) == 0xF) should be true. + + private int invocationCounter = 0; + @Override - public FilterReply decide(Marker marker, Logger logger, Level level, String format, Object[] params, Throwable t) { - if(!isStarted()) { + public FilterReply decide(Marker marker, Logger logger, Level level, + String format, Object[] params, Throwable t) { + if (!isStarted()) { return FilterReply.NEUTRAL; } - - System.out.println("counter="+invocationCounter+", format="+format); + // for performance reasons, check for changes every 16 invocations - if(((invocationCounter++) & 0xF) != 0xF) { + if (((invocationCounter++) & 0xF) != 0xF) { return FilterReply.NEUTRAL; } - boolean changed = changeDetected(); - if(changed) { - addInfo("["+fileToScan + "] change detected. Reconfiguring"); - addInfo("Resetting and reconfiguring context ["+context.getName()+"]"); + if (changed) { + addInfo("[" + fileToScan + "] change detected. Reconfiguring "+currentThreadName()); + addInfo("Resetting and reconfiguring context [" + context.getName() + "]"); reconfigure(); } return FilterReply.NEUTRAL; @@ -93,17 +98,20 @@ void updateNextCheck(long now) { nextCheck = now + refreshPeriod; } - - protected boolean changeDetected() { + + // This method is synchronized to prevent near-simultaneous re-configurations + protected synchronized boolean changeDetected() { long now = System.currentTimeMillis(); - if(now >= nextCheck) { + if (now >= nextCheck) { updateNextCheck(now); return (lastModified != fileToScan.lastModified()); } return false; } - - + + String currentThreadName() { + return Thread.currentThread().getName(); + } protected void reconfigure() { JoranConfigurator jc = new JoranConfigurator(); jc.setContext(context); @@ -113,7 +121,7 @@ jc.doConfigure(fileToScan); } catch (JoranException e) { addError("Failure during reconfiguration", e); - } + } } public long getRefreshPeriod() { Added: logback/trunk/logback-classic/src/test/input/turbo/scan1.xml ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/test/input/turbo/scan1.xml Tue Jul 14 22:47:17 2009 @@ -0,0 +1,7 @@ +<?xml version="1.0" encoding="UTF-8" ?> +<!DOCTYPE configuration> + +<configuration scan="true" scanPeriod="1 millisecond"> + <root level="ERROR"/> +</configuration> + \ No newline at end of file Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic135/LoggingRunnable.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic135/LoggingRunnable.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic135/LoggingRunnable.java Tue Jul 14 22:47:17 2009 @@ -16,7 +16,7 @@ Logger logger; - LoggingRunnable(Logger logger) { + public LoggingRunnable(Logger logger) { this.logger = logger; } Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/joran/JoranConfiguratorTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/joran/JoranConfiguratorTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/joran/JoranConfiguratorTest.java Tue Jul 14 22:47:17 2009 @@ -248,6 +248,7 @@ assertEquals("hello user2", le.getMessage()); } + // Tests whether ConfigurationAction is installing ReconfigureOnChangeFilter @Test public void scan1() throws JoranException, IOException, InterruptedException { @@ -267,6 +268,5 @@ assertTrue(checker.isErrorFree()); assertTrue(checker.containsMatch("Resetting and reconfiguring context")); StatusPrinter.print(loggerContext); - } } Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java Tue Jul 14 22:47:17 2009 @@ -0,0 +1,92 @@ +package ch.qos.logback.classic.turbo; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertTrue; + +import java.io.File; +import java.io.IOException; + +import org.junit.Test; + +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.LoggerContext; +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; +import ch.qos.logback.core.status.StatusChecker; +import ch.qos.logback.core.util.StatusPrinter; + +public class ReconfigureOnChangeTest { + LoggerContext loggerContext = new LoggerContext(); + Logger logger = loggerContext.getLogger(this.getClass()); + final static int THREAD_COUNT = 3; + + 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); + jc.doConfigure(file); + } + + RunnableWithCounterAndDone[] buildRunnableArray(File configFile) { + + RunnableWithCounterAndDone[] rArray = new RunnableWithCounterAndDone[THREAD_COUNT]; + rArray[0] = new Updater(configFile); + for (int i = 1; i < THREAD_COUNT; i++) { + rArray[i] = new LoggingRunnable(logger); + } + return rArray; + } + + // Tests whether ConfigurationAction is installing ReconfigureOnChangeFilter + @Test + public void scan1() throws JoranException, IOException, InterruptedException { + + String configFileAsStr = TeztConstants.TEST_DIR_PREFIX + + "input/turbo/scan1.xml"; + configure(configFileAsStr); + + 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); + + } + + 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()) { + return; + } + counter++; + configFile.setLastModified(System.currentTimeMillis()); + } + } + + } + +} Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/contention/MultiThreadedHarness.java ============================================================================== --- logback/trunk/logback-core/src/test/java/ch/qos/logback/core/contention/MultiThreadedHarness.java (original) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/contention/MultiThreadedHarness.java Tue Jul 14 22:47:17 2009 @@ -47,7 +47,7 @@ Thread[] threadArray = new Thread[runnableArray.length]; for (int i = 0; i < runnableArray.length; i++) { - threadArray[i] = new Thread(runnableArray[i]); + threadArray[i] = new Thread(runnableArray[i], "Harness["+i+"]"); } for (Thread t : threadArray) { t.start(); Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/status/StatusChecker.java ============================================================================== --- logback/trunk/logback-core/src/test/java/ch/qos/logback/core/status/StatusChecker.java (original) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/status/StatusChecker.java Tue Jul 14 22:47:17 2009 @@ -61,6 +61,19 @@ return false; } + public int matchCount(String regex) { + int count = 0; + Pattern p = Pattern.compile(regex); + for(Status status: sm.getCopyOfStatusList()) { + String msg = status.getMessage(); + Matcher matcher = p.matcher(msg); + if (matcher.lookingAt()) { + count++; + } + } + return count; + } + public boolean containsException(Class exceptionType) { Iterator stati = sm.getCopyOfStatusList().iterator(); while (stati.hasNext()) {