Author: seb Date: Fri Sep 8 12:29:30 2006 New Revision: 535 Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/MDC.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEvent.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/SocketAppenderTest.java Log: - Updated MDC to create a new map instance each time a property is added - Modified method name in MDC: getContext is now getPropertyMap - Updated LoggingEvent to provide access to the MDC Properties - Updated SocketAppenderTest to verify that the LoggingEvent always exposes the last version of the MDC Properties Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/MDC.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/MDC.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/MDC.java Fri Sep 8 12:29:30 2006 @@ -30,16 +30,23 @@ * <p> * If the current thread does not have a context map it is created as a side * effect of this call. + * + * <p> + * Each time a value is added, a new instance of the map is created. This is + * to be certain that the serialization process will operate on the updated map + * and not send a reference to the old map, thus not allowing the remote logback + * component to see the latest changes. */ public static void put(String key, String val) { - HashMap<String, String> hashMap = threadLocal.get(); + HashMap<String, String> oldMap = threadLocal.get(); - if (hashMap == null) { - hashMap = new HashMap<String, String>(); - threadLocal.set(hashMap); + HashMap<String, String> newMap = new HashMap<String, String>(); + if (oldMap != null) { + newMap.putAll(oldMap); } - - hashMap.put(key, val); + threadLocal.set(newMap); + + newMap.put(key, val); } /** @@ -60,13 +67,22 @@ /** * Remove the the context identified by the <code>key</code> parameter. + * + * <p> + * Each time a value is removed, a new instance of the map is created. This is + * to be certain that the serialization process will operate on the updated map + * and not send a reference to the old map, thus not allowing the remote logback + * component to see the latest changes. */ public static void remove(String key) { - HashMap<String, String> hashMap = threadLocal.get(); + HashMap<String, String> oldMap = threadLocal.get(); - if (hashMap != null) { - hashMap.remove(key); + HashMap<String, String> newMap = new HashMap<String, String>(); + if (oldMap != null) { + newMap.putAll(oldMap); } + + newMap.remove(key); } /** @@ -85,7 +101,7 @@ * Get the current thread's MDC as a map. This method is intended to be used * internally. */ - public static Map<String, String> getContext() { + public static Map<String, String> getPropertyMap() { return threadLocal.get(); } Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEvent.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEvent.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEvent.java Fri Sep 8 12:29:30 2006 @@ -14,13 +14,14 @@ import java.io.ObjectInputStream; import java.io.ObjectOutputStream; import java.io.Serializable; +import java.util.Map; import org.slf4j.Marker; import org.slf4j.impl.MessageFormatter; - -import ch.qos.logback.classic.Logger; import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.MDC; /** * The internal representation of logging events. When an affirmative decision @@ -84,8 +85,10 @@ private CallerData[] callerDataArray; private LoggerRemoteView loggerRemoteView; - + private Marker marker; + + private Map<String, String> MDCPropertyMap; /** * The number of milliseconds elapsed from 1/1/1970 until logging event was @@ -262,20 +265,22 @@ public String getFormattedMessage() { return formattedMessage; } + + public Map<String, String> getMDCPropertyMap() { + //no lazy init since the MDC might + //change its map instance. + this.MDCPropertyMap = MDC.getPropertyMap(); + return MDCPropertyMap; + } private void writeObject(ObjectOutputStream out) throws IOException { out.defaultWriteObject(); - //out.writeObject(loggerView); - out.writeInt(level.levelInt); } private void readObject(ObjectInputStream in) throws IOException, ClassNotFoundException { in.defaultReadObject(); - //String loggerName = (String) in.readObject(); - //logger = LoggerFactory.getLogger(loggerName); - //loggerView = (LoggerView)in.readObject(); int levelInt = in.readInt(); level = Level.toLevel(levelInt); } Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/SocketAppenderTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/SocketAppenderTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/SocketAppenderTest.java Fri Sep 8 12:29:30 2006 @@ -3,16 +3,21 @@ import java.util.Map; import junit.framework.TestCase; +import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Logger; import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.MDC; import ch.qos.logback.classic.spi.LoggerContextRemoteView; import ch.qos.logback.classic.spi.LoggerRemoteView; import ch.qos.logback.classic.spi.LoggingEvent; public class SocketAppenderTest extends TestCase { + private LoggerContext lc; + private MockSocketServer mockSocketServer; + public void testStartFailNoRemoteHost() { - LoggerContext lc = new LoggerContext(); + lc = new LoggerContext(); SocketAppender appender = new SocketAppender(); appender.setContext(lc); appender.setPort(123); @@ -21,36 +26,39 @@ } public void testRecieveMessage() throws InterruptedException { - MockSocketServer mockServer = new MockSocketServer(1); - mockServer.start(); - // give MockSyslogServer head start - Thread.sleep(100); + startServer(1); + configureClient(); + + Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); + logger.debug("test msg"); + // Wait max 2 seconds for mock server to finish. However, it should + // finish much sooner than that. + mockSocketServer.join(2000); + assertTrue(mockSocketServer.finished); + assertEquals(1, mockSocketServer.loggingEventList.size()); + + LoggingEvent remoteEvent = mockSocketServer.loggingEventList.get(0); + assertEquals("test msg", remoteEvent.getMessage()); + assertEquals(Level.DEBUG, remoteEvent.getLevel()); + } + + public void testRecieveWithContext() throws InterruptedException { + startServer(1); + configureClient(); - // client configuration - LoggerContext lc = new LoggerContext(); - lc.setName("test"); - lc.setProperty("testKey", "testValue"); - Logger root = lc.getLogger(LoggerContext.ROOT_NAME); - SocketAppender socketAppender = new SocketAppender(); - socketAppender.setContext(lc); - socketAppender.setName("socket"); - socketAppender.setPort(4560); - socketAppender.setRemoteHost("localhost"); - root.addAppender(socketAppender); - socketAppender.start(); - Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); logger.debug("test msg"); // Wait max 2 seconds for mock server to finish. However, it should // finish much sooner than that. - mockServer.join(2000); - assertTrue(mockServer.finished); - assertEquals(1, mockServer.loggingEventList.size()); - LoggingEvent remoteEvent = mockServer.loggingEventList.get(0); + mockSocketServer.join(2000); + assertTrue(mockSocketServer.finished); + assertEquals(1, mockSocketServer.loggingEventList.size()); + + LoggingEvent remoteEvent = mockSocketServer.loggingEventList.get(0); + LoggerRemoteView loggerRemoteView = remoteEvent.getLoggerRemoteView(); - assertEquals("test msg", remoteEvent.getMessage()); assertNotNull(loggerRemoteView); assertEquals("root", loggerRemoteView.getName()); @@ -60,4 +68,71 @@ Map<String, String> props = loggerContextRemoteView.getPropertyMap(); assertEquals("testValue", props.get("testKey")); } + + + public void testMessageWithMDC() throws InterruptedException { + startServer(1); + configureClient(); + + Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); + + MDC.put("key", "testValue"); + logger.debug("test msg"); + + // Wait max 2 seconds for mock server to finish. However, it should + // finish much sooner than that. + mockSocketServer.join(2000); + assertTrue(mockSocketServer.finished); + assertEquals(1, mockSocketServer.loggingEventList.size()); + + LoggingEvent remoteEvent = mockSocketServer.loggingEventList.get(0); + Map<String, String> MDCPropertyMap = remoteEvent.getMDCPropertyMap(); + assertEquals("testValue", MDCPropertyMap.get("key")); + } + + public void testMessageWithUpdatedMDC() throws InterruptedException { + startServer(2); + configureClient(); + + Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); + + MDC.put("key", "testValue"); + logger.debug("test msg"); + + MDC.put("key", "updatedTestValue"); + logger.debug("test msg 2"); + + // Wait max 2 seconds for mock server to finish. However, it should + // finish much sooner than that. + mockSocketServer.join(2000); + assertTrue(mockSocketServer.finished); + assertEquals(2, mockSocketServer.loggingEventList.size()); + + //We observe the second logging event. It should provide us with + //the updated MDC property. + LoggingEvent remoteEvent = mockSocketServer.loggingEventList.get(1); + Map<String, String> MDCPropertyMap = remoteEvent.getMDCPropertyMap(); + assertEquals("updatedTestValue", MDCPropertyMap.get("key")); + } + + private void startServer(int expectedEventNumber) throws InterruptedException { + mockSocketServer = new MockSocketServer(expectedEventNumber); + mockSocketServer.start(); + // give MockSocketServer head start + Thread.sleep(100); + } + + private void configureClient() { + lc = new LoggerContext(); + lc.setName("test"); + lc.setProperty("testKey", "testValue"); + Logger root = lc.getLogger(LoggerContext.ROOT_NAME); + SocketAppender socketAppender = new SocketAppender(); + socketAppender.setContext(lc); + socketAppender.setName("socket"); + socketAppender.setPort(4560); + socketAppender.setRemoteHost("localhost"); + root.addAppender(socketAppender); + socketAppender.start(); + } }