Author: ceki Date: Tue Mar 11 20:43:31 2008 New Revision: 1635 Removed: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/net/SocketServer.java Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/net/SimpleSocketServer.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/net/SocketNode.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/PackageTest.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/SocketAppenderTest.java logback/trunk/logback-core/src/main/java/ch/qos/logback/core/net/SocketAppenderBase.java logback/trunk/logback-core/src/main/java/ch/qos/logback/core/util/StatusPrinter.java Log: - StatusPrinter can now print time of statii - Applied patch 10 mentioned in bug 105 onto SocketAppenderBase - SocketServer class has been removed and replaced by SimpleSocketServer - SimpleSocketServer is much more careful to track open client connections and to close them. Added relevant test cases. Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/net/SimpleSocketServer.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/net/SimpleSocketServer.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/net/SimpleSocketServer.java Tue Mar 11 20:43:31 2008 @@ -12,6 +12,8 @@ import java.io.IOException; import java.net.ServerSocket; import java.net.Socket; +import java.util.ArrayList; +import java.util.List; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -46,7 +48,8 @@ private final LoggerContext lc; private boolean closed = false; private ServerSocket serverSocket; - + private List<SocketNode> socketNodeList = new ArrayList<SocketNode>(); + public static void main(String argv[]) throws Exception { int port = -1; if (argv.length == 2) { @@ -77,18 +80,31 @@ Socket socket = serverSocket.accept(); logger.info("Connected to client at " + socket.getInetAddress()); logger.info("Starting new socket node."); - new Thread(new SocketNode(socket, lc)).start(); + SocketNode newSocketNode = new SocketNode(this, socket, lc); + synchronized (socketNodeList) { + socketNodeList.add(newSocketNode); + } + new Thread(newSocketNode).start(); + signalSocketNodeCreation(); } } catch (Exception e) { if(closed) { - logger.info("Exception in run method for a closed server. This is expected"); + logger.info("Exception in run method for a closed server. This is normal."); } else { - logger.error("Failure in run method", e); + logger.error("Unexpected failure in run method", e); } } } - + /** + * Signal another thread that we have established a conneciton + * This is useful for testing purposes. + */ + void signalSocketNodeCreation() { + synchronized(this) { + this.notifyAll(); + } + } public boolean isClosed() { return closed; } @@ -100,10 +116,29 @@ serverSocket.close(); } catch (IOException e) { logger.error("Failed to close serverSocket", e); + } finally { + serverSocket = null; } + } + + synchronized (socketNodeList) { + for(SocketNode sn: socketNodeList) { + sn.close(); + } + socketNodeList.clear(); } } + public void socketNodeClosing(SocketNode sn) { + logger.debug("Removing {}", sn); + + // don't allow simultaneous access to the socketNodeList + // (e.g. removal whole iterating on the list causes + // java.util.ConcurrentModificationException + synchronized (socketNodeList) { + socketNodeList.remove(sn); + } + } static void usage(String msg) { System.err.println(msg); System.err.println("Usage: java " + SimpleSocketServer.class.getName() Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/net/SocketNode.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/net/SocketNode.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/net/SocketNode.java Tue Mar 11 20:43:31 2008 @@ -14,6 +14,7 @@ import java.io.IOException; import java.io.ObjectInputStream; import java.net.Socket; +import java.net.SocketAddress; import ch.qos.logback.classic.Logger; import org.slf4j.LoggerFactory; @@ -42,11 +43,16 @@ Socket socket; LoggerContext context; ObjectInputStream ois; - + SocketAddress remoteSocketAddress; + static Logger logger = (Logger) LoggerFactory.getLogger(SocketNode.class); - - public SocketNode(Socket socket, LoggerContext context) { + boolean closed = false; + SimpleSocketServer socketServer; + + public SocketNode(SimpleSocketServer socketServer, Socket socket, LoggerContext context) { + this.socketServer = socketServer; this.socket = socket; + remoteSocketAddress = socket.getRemoteSocketAddress(); this.context = context; try { ois = new ObjectInputStream(new BufferedInputStream(socket @@ -67,7 +73,7 @@ Logger remoteLogger; try { - while (true) { + while (!closed) { // read an event from the wire event = (LoggingEvent) ois.readObject(); // get a logger from the hierarchy. The name of the logger is taken to @@ -90,10 +96,28 @@ logger.error("Unexpected exception. Closing connection.", e); } - try { - ois.close(); - } catch (Exception e) { - logger.info("Could not close connection.", e); + socketServer.socketNodeClosing(this); + close(); + } + + void close() { + if(closed) { + return; + } + closed = true; + if (ois != null) { + try { + ois.close(); + } catch (IOException e) { + logger.warn("Could not close connection.", e); + } finally { + ois = null; + } } } + + @Override + public String toString() { + return this.getClass().getName()+remoteSocketAddress.toString(); + } } Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/PackageTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/PackageTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/PackageTest.java Tue Mar 11 20:43:31 2008 @@ -10,6 +10,7 @@ package ch.qos.logback.classic.net; +import junit.framework.JUnit4TestAdapter; import junit.framework.Test; import junit.framework.TestCase; import junit.framework.TestSuite; @@ -20,7 +21,7 @@ TestSuite suite = new TestSuite(); suite.addTestSuite(SyslogAppenderTest.class); suite.addTestSuite(SMTPAppenderTest.class); - suite.addTestSuite(SocketAppenderTest.class); + suite.addTest(new JUnit4TestAdapter(SocketAppenderTest.class)); suite.addTestSuite(JMSTopicAppenderTest.class); return suite; } 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 Tue Mar 11 20:43:31 2008 @@ -9,10 +9,13 @@ */ package ch.qos.logback.classic.net; + +import static org.junit.Assert.*; + import java.util.Map; -import junit.framework.TestCase; +import org.junit.Test; import org.slf4j.MDC; import org.slf4j.Marker; import org.slf4j.MarkerFactory; @@ -24,8 +27,9 @@ import ch.qos.logback.classic.spi.LoggerRemoteView; import ch.qos.logback.classic.spi.LoggingEvent; import ch.qos.logback.core.read.ListAppender; +import ch.qos.logback.core.util.StatusPrinter; -public class SocketAppenderTest extends TestCase { +public class SocketAppenderTest { static final String LIST_APPENDER_NAME = "la"; int port = 4560; @@ -33,9 +37,9 @@ LoggerContext serverLC = new LoggerContext(); ListAppender<LoggingEvent> la = new ListAppender<LoggingEvent>(); - //private MockSocketServer mockSocketServer; private SimpleSocketServer simpleSocketServer; - + + @Test public void testStartFailNoRemoteHost() { SocketAppender appender = new SocketAppender(); appender.setContext(lc); @@ -44,8 +48,9 @@ assertEquals(1, lc.getStatusManager().getCount()); } + @Test public void testRecieveMessage() throws InterruptedException { - startServer(1); + fireServer(); configureClient(); Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); @@ -65,8 +70,9 @@ assertEquals(Level.DEBUG, remoteEvent.getLevel()); } + @Test public void testRecieveWithContext() throws InterruptedException { - startServer(1); + fireServer(); configureClient(); Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); @@ -94,8 +100,9 @@ assertEquals("testValue", props.get("testKey")); } + @Test public void testMessageWithMDC() throws InterruptedException { - startServer(1); + fireServer(); configureClient(); Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); @@ -117,8 +124,9 @@ assertEquals("testValue", MDCPropertyMap.get("key")); } + @Test public void testMessageWithMarker() throws InterruptedException { - startServer(1); + fireServer(); configureClient(); Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); @@ -139,8 +147,9 @@ assertEquals("testMarker", remoteEvent.getMarker().getName()); } + @Test public void testMessageWithUpdatedMDC() throws InterruptedException { - startServer(2); + fireServer(); configureClient(); Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); @@ -169,7 +178,33 @@ assertEquals("updatedTestValue", MDCPropertyMap.get("key")); } - private void startServer(int expectedNumberOfEvents) throws InterruptedException { + @Test + public void lateServerLaunch() throws InterruptedException { + configureClient(); + Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); + logger.debug("test msg"); + + fireServer(); + synchronized (simpleSocketServer) { + simpleSocketServer.wait(1000); + } + logger.debug("test msg 2"); + + StatusPrinter.print(lc); + + // Wait max 2 seconds for mock server to finish. However, it should + // finish much sooner than that. + simpleSocketServer.close(); + simpleSocketServer.join(2000); + assertTrue(simpleSocketServer.isClosed()); + assertEquals(1, la.list.size()); + + LoggingEvent remoteEvent = la.list.get(0); + assertEquals("test msg 2", remoteEvent.getMessage()); + assertEquals(Level.DEBUG, remoteEvent.getLevel()); + } + + private void fireServer() throws InterruptedException { Logger root = serverLC.getLogger("root"); la.setName(LIST_APPENDER_NAME); la.setContext(serverLC); Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/net/SocketAppenderBase.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/net/SocketAppenderBase.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/net/SocketAppenderBase.java Tue Mar 11 20:43:31 2008 @@ -20,9 +20,8 @@ /** * - * This is the base class for module specific SocketAppender - * implementations. - * + * This is the base class for module specific SocketAppender implementations. + * * @author Ceki Gülcü * @author Sébastien Pennec */ @@ -49,7 +48,6 @@ protected int port = DEFAULT_PORT; protected ObjectOutputStream oos; protected int reconnectionDelay = DEFAULT_RECONNECTION_DELAY; - private Connector connector; @@ -72,12 +70,16 @@ int errorCount = 0; if (port == 0) { errorCount++; - addError("No port was configured for appender" + name + " For more information, please visit http://logback.qos.ch/codes.html#socket_no_port"); + addError("No port was configured for appender" + + name + + " For more information, please visit http://logback.qos.ch/codes.html#socket_no_port"); } if (address == null) { errorCount++; - addError("No remote address was configured for appender" + name + " For more information, please visit http://logback.qos.ch/codes.html#socket_no_host"); + addError("No remote address was configured for appender" + + name + + " For more information, please visit http://logback.qos.ch/codes.html#socket_no_host"); } connect(address, port); @@ -149,7 +151,8 @@ return; if (address == null) { - addError("No remote host is set for SocketAppender named \"" + this.name + addError("No remote host is set for SocketAppender named \"" + + this.name + "\". For more information, please visit http://logback.qos.ch/codes.html#socket_no_host"); return; } @@ -168,6 +171,13 @@ oos.reset(); } } catch (IOException e) { + if (oos != null) { + try { + oos.close(); + } catch (IOException ignore) { + } + } + oos = null; addWarn("Detected problem with connection: " + e); if (reconnectionDelay > 0) { @@ -176,7 +186,7 @@ } } } - + protected abstract void postProcessEvent(E event); void fireConnector() { @@ -228,7 +238,6 @@ public int getPort() { return port; } - /** * The <b>ReconnectionDelay</b> option takes a positive integer representing Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/util/StatusPrinter.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/util/StatusPrinter.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/util/StatusPrinter.java Tue Mar 11 20:43:31 2008 @@ -11,6 +11,8 @@ package ch.qos.logback.core.util; import java.io.PrintStream; +import java.text.SimpleDateFormat; +import java.util.Date; import java.util.Iterator; import ch.qos.logback.core.Context; @@ -21,6 +23,8 @@ private static PrintStream ps = System.out; + static SimpleDateFormat simpleDateFormat = new SimpleDateFormat("HH:mm:ss,SSS"); + public static void setPrintStream(PrintStream printStream) { ps = printStream; } @@ -57,7 +61,15 @@ } else { prefix = indentation + "|-"; } - ps.println(prefix+s); + + if(simpleDateFormat != null) { + Date date = new Date(s.getDate()); + String dateStr = simpleDateFormat.format(date); + ps.print(dateStr); + ps.print(" "); + } + ps.println(prefix+s); + if (s.getThrowable() != null) { s.getThrowable().printStackTrace(ps); }