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=3f49ee7c4b0e444dc6748509442a1ea1e6f4c5e5
http://github.com/ceki/logback/commit/3f49ee7c4b0e444dc6748509442a1ea1e6f4c5e5
commit 3f49ee7c4b0e444dc6748509442a1ea1e6f4c5e5
Author: Ceki Gulcu <[email protected]>
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.
_______________________________________________
logback-dev mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-dev
