[logback-dev] branch, master, updated. 3f49ee7c4b0e444dc6748509442a1ea1e6f4c5e5
added by portage for gitosis-gentoo
git-noreply at pixie.qos.ch
Thu Dec 3 16:21:11 CET 2009
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 <ceki at 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.
More information about the logback-dev
mailing list