This is an automated email from the git hooks/post-receive script. It was generated because a ref change was pushed to the repository containing the project "Logback: the generic, reliable, fast and flexible logging framework.". The branch, master has been updated via 7a2e02bca24d872d580694ab89a865542103e570 (commit) from 3c983ccd0dd39ca006d78a0c086966e99693821c (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=7a2e02bca24d872d580694ab8... http://github.com/ceki/logback/commit/7a2e02bca24d872d580694ab89a865542103e5... commit 7a2e02bca24d872d580694ab89a865542103e570 Author: Ceki Gulcu <ceki@qos.ch> Date: Tue Sep 20 21:50:42 2011 +0200 fix http://jira.qos.ch/browse/LBCLASSIC-289 diff --git a/logback-classic/src/main/java/ch/qos/logback/classic/util/LogbackMDCAdapter.java b/logback-classic/src/main/java/ch/qos/logback/classic/util/LogbackMDCAdapter.java index 4d494e9..b045016 100644 --- a/logback-classic/src/main/java/ch/qos/logback/classic/util/LogbackMDCAdapter.java +++ b/logback-classic/src/main/java/ch/qos/logback/classic/util/LogbackMDCAdapter.java @@ -15,8 +15,10 @@ package ch.qos.logback.classic.util; import java.util.HashMap; import java.util.Map; +import java.util.Collections; import java.util.Set; + import org.slf4j.spi.MDCAdapter; /** @@ -49,7 +51,7 @@ public final class LogbackMDCAdapter implements MDCAdapter { // Initially the contents of the thread local in parent and child threads // reference the same map. However, as soon as a thread invokes the put() // method, the maps diverge as they should. - final InheritableThreadLocal<HashMap<String, String>> copyOnInheritThreadLocal = new InheritableThreadLocal<HashMap<String, String>>(); + final InheritableThreadLocal<Map<String, String>> copyOnInheritThreadLocal = new InheritableThreadLocal<Map<String, String>>(); private static final int WRITE_OPERATION = 1; private static final int READ_OPERATION = 2; @@ -70,11 +72,16 @@ public final class LogbackMDCAdapter implements MDCAdapter { return lastOp == null || lastOp.intValue() == READ_OPERATION; } - private HashMap<String, String> duplicateAndInsertNewMap(HashMap<String, String> oldMap) { - HashMap<String, String> newMap = new HashMap<String, String>(); - if (oldMap != null) - newMap.putAll(oldMap); - // the newMap replaces the old one for serialisation's sake + private Map<String, String> duplicateAndInsertNewMap(Map<String, String> oldMap) { + Map<String, String> newMap = Collections.synchronizedMap(new HashMap<String, String>()); + if (oldMap != null) { + // we don't want the parent thread modifying oldMap while we are + // iterating over it + synchronized (oldMap) { + newMap.putAll(oldMap); + } + } + copyOnInheritThreadLocal.set(newMap); return newMap; } @@ -95,11 +102,13 @@ public final class LogbackMDCAdapter implements MDCAdapter { throw new IllegalArgumentException("key cannot be null"); } - HashMap<String, String> oldMap = copyOnInheritThreadLocal.get(); + Map<String, String> oldMap = copyOnInheritThreadLocal.get(); + //System.out.println(Thread.currentThread().toString()+", "+oldMap); + Integer lastOp = getAndSetLastOperation(WRITE_OPERATION); if (wasLastOpReadOrNull(lastOp) || oldMap == null) { - HashMap<String, String> newMap = duplicateAndInsertNewMap(oldMap); + Map<String, String> newMap = duplicateAndInsertNewMap(oldMap); newMap.put(key, val); } else { oldMap.put(key, val); @@ -114,13 +123,13 @@ public final class LogbackMDCAdapter implements MDCAdapter { if (key == null) { return; } - HashMap<String, String> oldMap = copyOnInheritThreadLocal.get(); + Map<String, String> oldMap = copyOnInheritThreadLocal.get(); if (oldMap == null) return; Integer lastOp = getAndSetLastOperation(WRITE_OPERATION); if (wasLastOpReadOrNull(lastOp)) { - HashMap<String, String> newMap = duplicateAndInsertNewMap(oldMap); + Map<String, String> newMap = duplicateAndInsertNewMap(oldMap); newMap.remove(key); } else { oldMap.remove(key); @@ -177,10 +186,8 @@ public final class LogbackMDCAdapter implements MDCAdapter { * null. */ public Map getCopyOfContextMap() { - // why aren't we setting lastOperation as follows? - // lastOperation.set(READ_OPERATION); - - HashMap<String, String> hashMap = copyOnInheritThreadLocal.get(); + lastOperation.set(READ_OPERATION); + Map<String, String> hashMap = copyOnInheritThreadLocal.get(); if (hashMap == null) { return null; } else { @@ -192,7 +199,7 @@ public final class LogbackMDCAdapter implements MDCAdapter { public void setContextMap(Map contextMap) { lastOperation.set(WRITE_OPERATION); - HashMap<String, String> newMap = new HashMap<String, String>(); + Map<String, String> newMap = Collections.synchronizedMap(new HashMap<String, String>()); newMap.putAll(contextMap); // the newMap replaces the old one for serialisation's sake diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/spi/LoggingEventSerializationPerfTest.java b/logback-classic/src/test/java/ch/qos/logback/classic/spi/LoggingEventSerializationPerfTest.java index f759df2..9703f58 100644 --- a/logback-classic/src/test/java/ch/qos/logback/classic/spi/LoggingEventSerializationPerfTest.java +++ b/logback-classic/src/test/java/ch/qos/logback/classic/spi/LoggingEventSerializationPerfTest.java @@ -22,6 +22,7 @@ import java.io.ObjectOutputStream; import org.junit.After; import org.junit.Before; import org.junit.Test; +import org.slf4j.MDC; import org.slf4j.helpers.BogoPerf; import ch.qos.logback.classic.net.NOPOutputStream; @@ -53,6 +54,7 @@ public class LoggingEventSerializationPerfTest { @Before public void setUp() throws Exception { + MDC.clear(); oos = new ObjectOutputStream(noos); } diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/util/LogbackMDCAdapterTest.java b/logback-classic/src/test/java/ch/qos/logback/classic/util/LogbackMDCAdapterTest.java index c8251a1..dca0e26 100644 --- a/logback-classic/src/test/java/ch/qos/logback/classic/util/LogbackMDCAdapterTest.java +++ b/logback-classic/src/test/java/ch/qos/logback/classic/util/LogbackMDCAdapterTest.java @@ -20,11 +20,10 @@ import static org.junit.Assert.assertTrue; import java.util.HashMap; import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.CountDownLatch; import org.junit.Test; -import org.slf4j.MDC; - import ch.qos.logback.core.testUtil.RandomUtil; public class LogbackMDCAdapterTest { @@ -34,6 +33,8 @@ public class LogbackMDCAdapterTest { int diff = RandomUtil.getPositiveInt(); + private final LogbackMDCAdapter mdcAdapter = new LogbackMDCAdapter(); + /** * Test that CopyOnInheritThreadLocal does not barf when the @@ -43,12 +44,10 @@ public class LogbackMDCAdapterTest { */ @Test public void lbclassic77Test() throws InterruptedException { - LogbackMDCAdapter lma = new LogbackMDCAdapter(); - - HashMap<String, String> parentHM = getHashMapFromMDCAdapter(lma); + Map<String, String> parentHM = getMapFromMDCAdapter(mdcAdapter); assertNull(parentHM); - ChildThreadForMDCAdapter childThread = new ChildThreadForMDCAdapter(lma); + ChildThreadForMDCAdapter childThread = new ChildThreadForMDCAdapter(mdcAdapter); childThread.start(); childThread.join(); assertTrue(childThread.successul); @@ -57,57 +56,34 @@ public class LogbackMDCAdapterTest { @Test public void removeForNullKeyTest() { - LogbackMDCAdapter lma = new LogbackMDCAdapter(); - lma.remove(null); + mdcAdapter.remove(null); } @Test public void removeInexistentKey() { - LogbackMDCAdapter lma = new LogbackMDCAdapter(); - lma.remove("abcdlw0"); + mdcAdapter.remove("abcdlw0"); } @Test public void sequenceWithGet() { - LogbackMDCAdapter lma = new LogbackMDCAdapter(); - lma.put("k0", "v0"); - Map<String, String> map0 = lma.copyOnInheritThreadLocal.get(); - lma.get("k0"); // point 0 - lma.put("k0", "v1"); + mdcAdapter.put("k0", "v0"); + Map<String, String> map0 = mdcAdapter.copyOnInheritThreadLocal.get(); + mdcAdapter.get("k0"); // point 0 + mdcAdapter.put("k0", "v1"); // verify that map0 is that in point 0 assertEquals("v0", map0.get("k0")); } @Test public void sequenceWithGetPropertyMap() { - LogbackMDCAdapter lma = new LogbackMDCAdapter(); - lma.put("k0", "v0"); - Map<String, String> map0 = lma.getPropertyMap(); // point 0 - lma.put("k0", "v1"); + mdcAdapter.put("k0", "v0"); + Map<String, String> map0 = mdcAdapter.getPropertyMap(); // point 0 + mdcAdapter.put("k0", "v1"); // verify that map0 is that in point 0 assertEquals("v0", map0.get("k0")); } - - class ChildThreadForMDCAdapter extends Thread { - - LogbackMDCAdapter logbackMDCAdapter; - boolean successul; - HashMap<String, String> childHM; - - ChildThreadForMDCAdapter(LogbackMDCAdapter logbackMDCAdapter) { - this.logbackMDCAdapter = logbackMDCAdapter; - } - - @Override - public void run() { - childHM = getHashMapFromMDCAdapter(logbackMDCAdapter); - logbackMDCAdapter.get(""); - successul = true; - } - } - // ================================================= /** @@ -121,18 +97,18 @@ public class LogbackMDCAdapterTest { CountDownLatch countDownLatch = new CountDownLatch(1); String firstKey = "x" + diff; String secondKey = "o" + diff; - MDC.put(firstKey, firstKey + A_SUFFIX); + mdcAdapter.put(firstKey, firstKey + A_SUFFIX); - ChildThreadForMDC childThread = new ChildThreadForMDC(firstKey, secondKey, countDownLatch); + ChildThread childThread = new ChildThread(mdcAdapter, firstKey, secondKey, countDownLatch); childThread.start(); countDownLatch.await(); - MDC.put(firstKey, firstKey + B_SUFFIX); + mdcAdapter.put(firstKey, firstKey + B_SUFFIX); childThread.join(); - assertNull(MDC.get(secondKey)); - assertTrue(childThread.successul); + assertNull(mdcAdapter.get(secondKey)); + assertTrue(childThread.successful); - HashMap<String, String> parentHM = getHashMapFromMDC(); + Map<String, String> parentHM = getMapFromMDCAdapter(mdcAdapter); assertTrue(parentHM != childThread.childHM); HashMap<String, String> parentHMWitness = new HashMap<String, String>(); @@ -152,36 +128,104 @@ public class LogbackMDCAdapterTest { String firstKey = "x" + diff; String secondKey = "o" + diff; - MDC.put(firstKey, firstKey+A_SUFFIX); - assertEquals(firstKey+A_SUFFIX, MDC.get(firstKey)); + mdcAdapter.put(firstKey, firstKey + A_SUFFIX); + assertEquals(firstKey + A_SUFFIX, mdcAdapter.get(firstKey)); - Thread clearer = new ChildThreadForMDC(firstKey, secondKey) { + Thread clearer = new ChildThread(mdcAdapter, firstKey, secondKey) { @Override public void run() { - MDC.clear(); - assertNull(MDC.get(firstKey)); + mdcAdapter.clear(); + assertNull(mdcAdapter.get(firstKey)); } }; clearer.start(); clearer.join(); - assertEquals(firstKey+A_SUFFIX, MDC.get(firstKey)); + assertEquals(firstKey + A_SUFFIX, mdcAdapter.get(firstKey)); } - class ChildThreadForMDC extends Thread { + // see http://jira.qos.ch/browse/LBCLASSIC-289 + // this test used to fail without synchronization code in LogbackMDCAdapter + @Test + public void nearSimultaneousPutsShouldNotCauseConcurrentModificationException() throws InterruptedException { + // For the weirdest reason, modifications to mdcAdapter must be done + // before the definition anonymous ChildThread class below. Otherwise, the + // map in the child thread, the one contained in mdcAdapter.copyOnInheritThreadLocal, + // is null. How strange is that? + + // let the map have lots of elements so that copying it takes time + for (int i = 0; i < 2048; i++) { + mdcAdapter.put("k" + i, "v" + i); + } + + ChildThread childThread = new ChildThread(mdcAdapter, null, null) { + @Override + public void run() { + for (int i = 0; i < 16; i++) { + mdcAdapter.put("ck" + i, "cv" + i); + Thread.yield(); + } + successful = true; + } + }; + + + childThread.start(); + Thread.sleep(1); + for (int i = 0; i < 16; i++) { + mdcAdapter.put("K" + i, "V" + i); + } + childThread.join(); + assertTrue(childThread.successful); + } + + Map<String, String> getMapFromMDCAdapter(LogbackMDCAdapter lma) { + InheritableThreadLocal<Map<String, String>> copyOnInheritThreadLocal = lma.copyOnInheritThreadLocal; + return copyOnInheritThreadLocal.get(); + } + + // ========================== various thread classes + class ChildThreadForMDCAdapter extends Thread { + + LogbackMDCAdapter logbackMDCAdapter; + boolean successul; + Map<String, String> childHM; + + ChildThreadForMDCAdapter(LogbackMDCAdapter logbackMDCAdapter) { + this.logbackMDCAdapter = logbackMDCAdapter; + } + + @Override + public void run() { + childHM = getMapFromMDCAdapter(logbackMDCAdapter); + logbackMDCAdapter.get(""); + successul = true; + } + } + + + class ChildThread extends Thread { + + LogbackMDCAdapter logbackMDCAdapter; String firstKey; String secondKey; - boolean successul; - HashMap<String, String> childHM; + boolean successful; + Map<String, String> childHM; CountDownLatch countDownLatch; - ChildThreadForMDC(String firstKey, String secondKey) { - this(firstKey, secondKey, null); + ChildThread(LogbackMDCAdapter logbackMDCAdapter) { + this(logbackMDCAdapter, null, null); + } + + ChildThread(LogbackMDCAdapter logbackMDCAdapter, String firstKey, String secondKey) { + this(logbackMDCAdapter, firstKey, secondKey, null); } - ChildThreadForMDC(String firstKey, String secondKey, CountDownLatch countDownLatch) { + ChildThread(LogbackMDCAdapter logbackMDCAdapter, String firstKey, String secondKey, CountDownLatch countDownLatch) { + super("chil"); + this.logbackMDCAdapter = logbackMDCAdapter; this.firstKey = firstKey; this.secondKey = secondKey; this.countDownLatch = countDownLatch; @@ -189,24 +233,13 @@ public class LogbackMDCAdapterTest { @Override public void run() { - MDC.put(secondKey, secondKey + A_SUFFIX); - assertNotNull(MDC.get(firstKey)); - assertEquals(firstKey + A_SUFFIX, MDC.get(firstKey)); - if(countDownLatch != null) countDownLatch.countDown(); - assertEquals(secondKey + A_SUFFIX, MDC.get(secondKey)); - successul = true; - childHM = getHashMapFromMDC(); + logbackMDCAdapter.put(secondKey, secondKey + A_SUFFIX); + assertNotNull(logbackMDCAdapter.get(firstKey)); + assertEquals(firstKey + A_SUFFIX, logbackMDCAdapter.get(firstKey)); + if (countDownLatch != null) countDownLatch.countDown(); + assertEquals(secondKey + A_SUFFIX, logbackMDCAdapter.get(secondKey)); + successful = true; + childHM = getMapFromMDCAdapter(logbackMDCAdapter); } } - - HashMap<String, String> getHashMapFromMDCAdapter(LogbackMDCAdapter lma) { - InheritableThreadLocal<HashMap<String, String>> copyOnInheritThreadLocal = lma.copyOnInheritThreadLocal; - return copyOnInheritThreadLocal.get(); - } - - HashMap<String, String> getHashMapFromMDC() { - LogbackMDCAdapter lma = (LogbackMDCAdapter) MDC.getMDCAdapter(); - InheritableThreadLocal<HashMap<String, String>> copyOnInheritThreadLocal = lma.copyOnInheritThreadLocal; - return copyOnInheritThreadLocal.get(); - } } diff --git a/logback-site/src/site/pages/news.html b/logback-site/src/site/pages/news.html index 2233c5e..7cfd392 100644 --- a/logback-site/src/site/pages/news.html +++ b/logback-site/src/site/pages/news.html @@ -40,9 +40,12 @@ <p>In the <code>ILoggingEvent</code> interface the <code>getMDC</code> method is now deprecated and replaced by - <code>getMDCPropertyMap</code>. The latter methof was already part + <code>getMDCPropertyMap</code>. The latter method was already part of the <code>ILoggingEvent</code> interface in prior versions of - logback-classic.</p> + logback-classic. Furthermore, the value returned by + <code>ILoggingEvent.getMDCPropertyMap</code> can now be an empty + map but never null.</p> + <p><code>LoggingEvent</code> no longer assumes that <code>LogbackMDCAdapter</code> is the only possible implementation @@ -51,6 +54,13 @@ reported by Chris Dolan. </p> + <p><code>LogbackMDCAdapter</code> now synchronizes over its thread + local map. This prevents + <code>ConcurrentModificationException</code> from occuring while a + child thread copies the map from the parent. This fixes <a + href="http://jira.qos.ch/browse/LBCLASSIC-289">LBCLASSIC-289</a> + reported by Josh Oddman.</p> + <p>It is now possible to specify multiple destination addresses separated by commas in the the <span class="option">to</span> property of <code>SMTPAppender</code>. This fixes <a @@ -60,7 +70,7 @@ addresses could only be specified by using multiple <span class="option">to</span> properties. As of version 0.9.30 both comma separated addresses and multiple <span - class="option">to</span> properties are suported. + class="option">to</span> properties are supported. </p> <p>When debug attribute is set to true within the ----------------------------------------------------------------------- Summary of changes: .../logback/classic/util/LogbackMDCAdapter.java | 37 +++-- .../spi/LoggingEventSerializationPerfTest.java | 2 + .../classic/util/LogbackMDCAdapterTest.java | 181 ++++++++++++-------- logback-site/src/site/pages/news.html | 16 ++- 4 files changed, 144 insertions(+), 92 deletions(-) hooks/post-receive -- Logback: the generic, reliable, fast and flexible logging framework.