The branch, master has been updated via 3f49ee7c4b0e444dc6748509442a1ea1e6f4c5e5 (commit) from 6c5ba501831d19879e6865f795a1c294ad25bf7d (commit) Those revisions listed above that are new to this repository have not appeared on any other notification email; so we list those revisions in full, below. - Log ----------------------------------------------------------------- http://git.qos.ch/gitweb/?p=logback.git;a=commit;h=3f49ee7c4b0e444dc67485094... http://github.com/ceki/logback/commit/3f49ee7c4b0e444dc6748509442a1ea1e6f4c5... commit 3f49ee7c4b0e444dc6748509442a1ea1e6f4c5e5 Author: Ceki Gulcu <ceki@qos.ch> Date: Thu Dec 3 16:17:14 2009 +0100 - ongoing work on LBCLASSIC-154 and LBCLASSIC-153 diff --git a/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java b/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java index af5bc6a..fe36372 100644 --- a/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java +++ b/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java @@ -47,7 +47,9 @@ public class ReconfigureOnChangeFilter extends TurboFilter { long refreshPeriod = DEFAULT_REFRESH_PERIOD; File fileToScan; protected long nextCheck; - long lastModified; + volatile long lastModified; + + Object lock = new Object(); @Override public void start() { @@ -56,7 +58,7 @@ public class ReconfigureOnChangeFilter extends TurboFilter { if (url != null) { fileToScan = convertToFile(url); if (fileToScan != null) { - synchronized (context.getConfigurationLock()) { + synchronized (lock) { long inSeconds = refreshPeriod / 1000; addInfo("Will scan for changes in file [" + fileToScan + "] every " + inSeconds + " seconds. "); @@ -102,27 +104,35 @@ public class ReconfigureOnChangeFilter extends TurboFilter { return FilterReply.NEUTRAL; } - synchronized (context.getConfigurationLock()) { + synchronized (lock) { boolean changed = changeDetected(); if (changed) { - addInfo("Detected change in [" + fileToScan + "]"); - addInfo("Resetting and reconfiguring context [" + context.getName() - + "]"); - reconfigure(); + detachReconfigurationToNewThread(); + } } + return FilterReply.NEUTRAL; } + // by detaching reconfiguration to a new thread, we release the various + // locks held by the current thread, in particular, the AppenderAttachable + // reader lock. + private void detachReconfigurationToNewThread() { + // 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. + disableSubsequentRecofiguration(); + addInfo("Detected change in [" + fileToScan + "]"); + addInfo("Resetting and reconfiguring context [" + context.getName() + "]"); + new ReconfiguringThread().start(); + } + void updateNextCheck(long now) { nextCheck = now + refreshPeriod; } -// String stem() { -// return currentThreadName() + ", context " + context.getName() -// + ", nextCheck=" + (nextCheck - INIT); -// } - // This method is synchronized to prevent near-simultaneous re-configurations protected boolean changeDetected() { long now = System.currentTimeMillis(); @@ -141,25 +151,6 @@ public class ReconfigureOnChangeFilter extends TurboFilter { 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; - lc.reset(); - try { - jc.doConfigure(fileToScan); - } catch (JoranException e) { - addError("Failure during reconfiguration", e); - } - } - public long getRefreshPeriod() { return refreshPeriod; } @@ -167,4 +158,18 @@ public class ReconfigureOnChangeFilter extends TurboFilter { public void setRefreshPeriod(long refreshPeriod) { this.refreshPeriod = refreshPeriod; } + + class ReconfiguringThread extends Thread { + public void run() { + JoranConfigurator jc = new JoranConfigurator(); + jc.setContext(context); + LoggerContext lc = (LoggerContext) context; + lc.reset(); + try { + jc.doConfigure(fileToScan); + } catch (JoranException e) { + addError("Failure during reconfiguration", e); + } + } + } } diff --git a/logback-classic/src/test/input/turbo/scan 1.xml b/logback-classic/src/test/input/turbo/scan 1.xml index dc3d0fe..39878d3 100644 --- a/logback-classic/src/test/input/turbo/scan 1.xml +++ b/logback-classic/src/test/input/turbo/scan 1.xml @@ -2,6 +2,9 @@ <!DOCTYPE configuration> <configuration scan="true" scanPeriod="50 millisecond"> - <root level="ERROR"/> + + <root level="ERROR"> + </root> + </configuration> \ No newline at end of file diff --git a/logback-classic/src/test/input/turbo/scan_lbclassic154.xml b/logback-classic/src/test/input/turbo/scan_lbclassic154.xml new file mode 100644 index 0000000..7997d8a --- /dev/null +++ b/logback-classic/src/test/input/turbo/scan_lbclassic154.xml @@ -0,0 +1,19 @@ +<?xml version="1.0" encoding="UTF-8" ?> +<!DOCTYPE configuration> + +<configuration scan="true" scanPeriod="50 millisecond"> + + <appender name="default" class="ch.qos.logback.classic.issue.lbclassic154.LoggingAppender"> + <layout class="ch.qos.logback.classic.PatternLayout"> + <pattern>%msg%n"</pattern> + </layout> + </appender> + + <logger name="Ignore" level="ERROR" additivity="false"/> + + <root level="INFO"> + <appender-ref ref="default"/> + </root> + +</configuration> + \ No newline at end of file diff --git a/logback-classic/src/test/input/turbo/scan_perf.xml b/logback-classic/src/test/input/turbo/scan_perf.xml new file mode 100644 index 0000000..7ef7c83 --- /dev/null +++ b/logback-classic/src/test/input/turbo/scan_perf.xml @@ -0,0 +1,21 @@ +<?xml version="1.0" encoding="UTF-8" ?> +<!DOCTYPE configuration> + +<configuration scan="true" scanPeriod="50 millisecond"> + + <appender name="FILE" class="ch.qos.logback.core.FileAppender"> + <File>testFile.log</File> + <Append>true</Append> + + <layout class="ch.qos.logback.classic.PatternLayout"> + <Pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</Pattern> + </layout> + </appender> + + + <root level="DEBUG"> + <appender-ref ref="FILE"/> + </root> + +</configuration> + \ No newline at end of file diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic154/LoggingAppender.java b/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic154/LoggingAppender.java new file mode 100644 index 0000000..a95b2b5 --- /dev/null +++ b/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic154/LoggingAppender.java @@ -0,0 +1,41 @@ +/** + * Logback: the reliable, generic, fast and flexible logging framework. + * Copyright (C) 1999-2009, QOS.ch. All rights reserved. + * + * This program and the accompanying materials are dual-licensed under + * either the terms of the Eclipse Public License v1.0 as published by + * the Eclipse Foundation + * + * or (per the licensee's choosing) + * + * under the terms of the GNU Lesser General Public License version 2.1 + * as published by the Free Software Foundation. + */ +package ch.qos.logback.classic.issue.lbclassic154; + +import org.slf4j.Logger; + +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.AppenderBase; + +/** + * + * An appender which calls logback recursively + * + * @author Ralph Goers + */ + +public class LoggingAppender extends AppenderBase<ILoggingEvent> { + + Logger logger; + + public void start() { + super.start(); + logger = ((LoggerContext) getContext()).getLogger("Ignore"); + } + + protected void append(ILoggingEvent eventObject) { + logger.debug("Ignore this"); + } +} diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java b/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java index 6c6f52f..6c21e35 100644 --- a/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java +++ b/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java @@ -38,6 +38,7 @@ import ch.qos.logback.core.joran.spi.JoranException; import ch.qos.logback.core.status.InfoStatus; import ch.qos.logback.core.status.StatusChecker; import ch.qos.logback.core.testUtil.Env; +import ch.qos.logback.core.util.StatusPrinter; public class ReconfigureOnChangeTest { final static int THREAD_COUNT = 5; @@ -48,10 +49,13 @@ public class ReconfigureOnChangeTest { final static String SCAN1_FILE_AS_STR = TeztConstants.TEST_DIR_PREFIX + "input/turbo/scan 1.xml"; + final static String SCAN_LBCLASSIC_154_FILE_AS_STR = TeztConstants.TEST_DIR_PREFIX + + "input/turbo/scan_lbclassic154.xml"; + // it actually takes time for Windows to propagate file modification changes - // values below 100 milliseconds can be problematic - // the same propagation latency occurs in Linux but is even larger (>600 ms) - final static int DEFAULT_SLEEP_BETWEEN_UPDATES = 250; + // values below 100 milliseconds can be problematic the same propagation + // latency occurs in Linux but is even larger (>600 ms) + final static int DEFAULT_SLEEP_BETWEEN_UPDATES = 110; int sleepBetweenUpdates = DEFAULT_SLEEP_BETWEEN_UPDATES; @@ -113,8 +117,25 @@ public class ReconfigureOnChangeTest { verify(expectedRreconfigurations); } + // check for deadlocks + @Test(timeout = 20000) + public void scan_lbclassic154() throws JoranException, IOException, + InterruptedException { + File file = new File(SCAN_LBCLASSIC_154_FILE_AS_STR); + configure(file); + RunnableWithCounterAndDone[] runnableArray = buildRunnableArray(file); + harness.execute(runnableArray); + + loggerContext.getStatusManager().add( + new InfoStatus("end of execution ", this)); + + long expectedRreconfigurations = runnableArray[0].getCounter(); + verify(expectedRreconfigurations); + } + void verify(long expectedRreconfigurations) { StatusChecker checker = new StatusChecker(loggerContext); + StatusPrinter.print(loggerContext); assertTrue(checker.isErrorFree()); int effectiveResets = checker .matchCount("Resetting and reconfiguring context"); diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigurePerf.java b/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigurePerf.java new file mode 100644 index 0000000..e4165b9 --- /dev/null +++ b/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigurePerf.java @@ -0,0 +1,126 @@ +/** + * Logback: the reliable, generic, fast and flexible logging framework. + * Copyright (C) 1999-2009, QOS.ch. All rights reserved. + * + * This program and the accompanying materials are dual-licensed under + * either the terms of the Eclipse Public License v1.0 as published by + * the Eclipse Foundation + * + * or (per the licensee's choosing) + * + * under the terms of the GNU Lesser General Public License version 2.1 + * as published by the Free Software Foundation. + */ +package ch.qos.logback.classic.turbo; + +import java.io.File; +import java.io.IOException; +import java.net.MalformedURLException; + +import org.junit.Before; +import org.junit.Test; + +import ch.qos.logback.classic.Level; +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.CoreConstants; +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.InfoStatus; +import ch.qos.logback.core.testUtil.Env; + +public class ReconfigurePerf { + final static int THREAD_COUNT = 5; + final static int LOOP_LEN = 1000 * 1000; + + // the space in the file name mandated by + // http://jira.qos.ch/browse/LBCORE-119 + final static String CONF_FILE_AS_STR = TeztConstants.TEST_DIR_PREFIX + + "input/turbo/scan_perf.xml"; + + // it actually takes time for Windows to propagate file modification changes + // values below 100 milliseconds can be problematic the same propagation + // latency occurs in Linux but is even larger (>600 ms) + final static int DEFAULT_SLEEP_BETWEEN_UPDATES = 110; + + int sleepBetweenUpdates = DEFAULT_SLEEP_BETWEEN_UPDATES; + + static int totalTestDuration; + + LoggerContext loggerContext = new LoggerContext(); + Logger logger = loggerContext.getLogger(this.getClass()); + MultiThreadedHarness harness; + + @Before + public void setUp() { + // take into account propagation latency occurs on Linux + if (Env.isLinux()) { + sleepBetweenUpdates = 850; + totalTestDuration = sleepBetweenUpdates * 5; + } else { + totalTestDuration = sleepBetweenUpdates * 10; + } + harness = new MultiThreadedHarness(totalTestDuration); + } + + void configure(File file) throws JoranException { + JoranConfigurator jc = new JoranConfigurator(); + jc.setContext(loggerContext); + jc.doConfigure(file); + } + + RunnableWithCounterAndDone[] buildRunnableArray() { + RunnableWithCounterAndDone[] rArray = new RunnableWithCounterAndDone[THREAD_COUNT]; + for (int i = 0; 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 { + File file = new File(CONF_FILE_AS_STR); + configure(file); + doRun(); + doRun(); + doRun(); + System.out.println("ENTER :"); + System.in.read(); + doRun(); + } + + void doRun() throws InterruptedException { + RunnableWithCounterAndDone[] runnableArray = buildRunnableArray(); + harness.execute(runnableArray); + } + + ReconfigureOnChangeFilter initROCF() throws MalformedURLException { + ReconfigureOnChangeFilter rocf = new ReconfigureOnChangeFilter(); + rocf.setContext(loggerContext); + File file = new File(CONF_FILE_AS_STR); + loggerContext.putObject(CoreConstants.URL_OF_LAST_CONFIGURATION_VIA_JORAN, + file.toURI().toURL()); + rocf.start(); + return rocf; + } + + + public double directLoop(ReconfigureOnChangeFilter rocf) { + long start = System.nanoTime(); + for (int i = 0; i < LOOP_LEN; i++) { + rocf.decide(null, logger, Level.DEBUG, " ", null, null); + } + long end = System.nanoTime(); + return (end - start) / (1.0d * LOOP_LEN); + } + + void addInfo(String msg, Object o) { + loggerContext.getStatusManager().add(new InfoStatus(msg, o)); + } + +} ----------------------------------------------------------------------- Summary of changes: .../classic/turbo/ReconfigureOnChangeFilter.java | 67 ++++++----- logback-classic/src/test/input/turbo/scan 1.xml | 5 +- .../src/test/input/turbo/scan_lbclassic154.xml | 19 +++ logback-classic/src/test/input/turbo/scan_perf.xml | 21 ++++ .../issue/lbclassic154/LoggingAppender.java | 32 +++--- .../classic/turbo/ReconfigureOnChangeTest.java | 27 ++++- .../qos/logback/classic/turbo/ReconfigurePerf.java | 126 ++++++++++++++++++++ 7 files changed, 247 insertions(+), 50 deletions(-) create mode 100644 logback-classic/src/test/input/turbo/scan_lbclassic154.xml create mode 100644 logback-classic/src/test/input/turbo/scan_perf.xml copy logback-examples/src/main/java/chapter11/TrivialLogbackAppender.java => logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic154/LoggingAppender.java (55%) create mode 100644 logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigurePerf.java hooks/post-receive -- Logback: the generic, reliable, fast and flexible logging framework.