May 2009 - logback-dev - mailman3.qos.ch

[JIRA] Created: (LBCLASSIC-132) Please add a sequence number to LoggingEvent
by Joern Huxhorn (JIRA) 23 May '09

23 May '09

Please add a sequence number to LoggingEvent -------------------------------------------- Key: LBCLASSIC-132 URL: http://jira.qos.ch/browse/LBCLASSIC-132 Project: logback-classic Issue Type: New Feature Components: appender Affects Versions: 0.9.16 Reporter: Joern Huxhorn Assignee: Logback dev list It would be very nice to have an optional Long sequenceNumber in LoggingEvent, similar to what java.util.logging is providing. This would be useful in case of e.g. a SocketAppender where some events are lost between two connections. Another use-case would be a central logging server receiving the events. In that case, the sequence number - in combination with logger context info - could be used to uniquely reference events. The way I'd see this implemented is in the respective appenders, not in the LoggerContext itself, because otherwise one would have gaps in case of filtered-out events. An implementation would set the sequence number of the LoggingEvent, serialize it by whatever means and reset the sequence number to null afterwards so it doesn't leak to other appenders. Comments? -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

1 0

[JIRA] Updated: (LBCORE-63) Deadlock when running on multiple core processors
by Joern Huxhorn (JIRA) 19 May '09

19 May '09

[ http://jira.qos.ch/browse/LBCORE-63?page=com.atlassian.jira.plugin.system.i… ] Joern Huxhorn updated LBCORE-63: -------------------------------- Attachment: AppenderBaseLock.patch Hi guys, Our webapp running on a 4-core solaris is suffering* the same problem as described in http://jira.qos.ch/browse/LBCORE-63 and http://jira.qos.ch/browse/LBCORE-96 and I think I have an idea about the reason behind this. Threading policy has changed from 1.5 to 1.6. I can't give you a reference for this, it's purely based on observation. In 1.5, a thread waiting for a lock was somewhat preferred by the VM over threads that would arrive at the wait() at a later time. In 1.6, however, a thread that releases synchronization is much more likely to immediately obtain the object lock again if it's in a consumer/producer loop. for(;;) { synchronized(obj) { // thread is likely to reobtain lock } } The same is the case for wait/notifyAll combinations. One can not assume that a longer waiting thread will likely obtain the lock after notifyAll. This is documented in http://java.sun.com/javase/6/docs/api/java/lang/Object.html#notifyAll() so the changed behavior between 1.5 and 1.6 is perfectly legal. My assumption is that the perceived deadlock, which is actually a congestion/starvation problem, occurs if one thread is logging "like crazy" while the other thread is sluggish as hell because he can't obtain the lock. This should be solvable by using a fair ReentrantLock (See http://java.sun.com/javase/6/docs/api/java/util/concurrent/locks/ReentrantL… ) >From the javadoc: "The constructor for this class accepts an optional fairness parameter. When set true, under contention, locks favor granting access to the longest-waiting thread. Otherwise this lock does not guarantee any particular access order. Programs using fair locks accessed by many threads may display lower overall throughput (i.e., are slower; often much slower) than those using the default setting, but have smaller variances in times to obtain locks and guarantee lack of starvation." The guaranteed lack of starvation is what we are looking for, I think, This is something that pure synchronization simply can't provide. I'd suggest to give the attached patch a try, I can't do so myself because I can't risk our webapp and I have no other chance to test this right now. I'll crosspost this to both tickets cause I'm not sure which one is more "active" right now. * The webapp shows that behavior in case of either console, file and/or lilith/socket appenders. It's just much more likely to happen with the lilith/socket appender in place since it takes significantly longer to send events over the wire than just writing them to disk or console. > Deadlock when running on multiple core processors > ------------------------------------------------- > > Key: LBCORE-63 > URL: http://jira.qos.ch/browse/LBCORE-63 > Project: logback-core > Issue Type: Sub-task > Affects Versions: 0.9.9 > Environment: Operating System: Windows > Platform: PC > Reporter: Toni Heimala > Assignee: Ceki Gulcu > Priority: Blocker > Attachments: AppenderBaseLock.patch, patch.txt, patch2.txt, patch3.txt > > > When you run logging into same file from many threads on a system that has more than one physical processor (Dual Core for example), a deadlock will occur after a while. This can not be reproduced on HyperThreading processors. Here's an example program that will demonstrate the behavior: > ----------------------------- > Main.java > ----------------------------- > import java.util.Date; > import java.util.concurrent.ScheduledThreadPoolExecutor; > import java.util.concurrent.TimeUnit; > import org.slf4j.Logger; > import org.slf4j.LoggerFactory; > import ch.qos.logback.classic.LoggerContext; > import ch.qos.logback.classic.joran.JoranConfigurator; > import ch.qos.logback.core.joran.spi.JoranException; > public class Main extends Thread > { > private final static String LOGGER_CONFIGURATION_FILE = "logger.xml"; > private final Logger logger = LoggerFactory.getLogger(Main.class); > > private final long start; > > public Main() > throws JoranException > { > start = new Date().getTime(); > LoggerContext lc = (LoggerContext)LoggerFactory.getILoggerFactory(); > JoranConfigurator configurator = new JoranConfigurator(); > lc.shutdownAndReset(); > configurator.setContext(lc); > configurator.doConfigure(LOGGER_CONFIGURATION_FILE); > } > > public void start() > { > ScheduledThreadPoolExecutor ex1 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex2 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex3 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex4 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex5 = new ScheduledThreadPoolExecutor(1); > ex1.scheduleAtFixedRate(new Task("EX1"), 10, 10, TimeUnit.MICROSECONDS); > ex2.scheduleAtFixedRate(new Task("EX2"), 10, 10, TimeUnit.MICROSECONDS); > ex3.scheduleAtFixedRate(new Task("EX3"), 10, 10, TimeUnit.MICROSECONDS); > ex4.scheduleAtFixedRate(new Task("EX4"), 10, 10, TimeUnit.MICROSECONDS); > ex5.scheduleAtFixedRate(new Task("EX5"), 10, 10, TimeUnit.MICROSECONDS); > > super.start(); > } > > public void run() > { > try > { > while(true) > { > logger.debug("[MAIN] {}", new Date().getTime() - start); > Thread.sleep(10); > } > } > catch (InterruptedException e) > { > logger.info("[MAIN]: Interrupted: {}", e.getMessage()); > } > } > > public static void main(String[] args) > { > try > { > Main main = new Main(); > main.start(); > } > catch (JoranException e) > { > System.out.println("Failed to load application: " + e.getMessage()); > } > } > } > ------------------------------- > Task.java > ------------------------------- > import java.util.Date; > import org.slf4j.Logger; > import org.slf4j.LoggerFactory; > public class Task implements Runnable > { > private final Logger logger = LoggerFactory.getLogger(Task.class); > private final Logger logger_main = LoggerFactory.getLogger(Main.class); > private final String name; > private final long start; > > public Task(final String name) > { > this.name = name; > start = new Date().getTime(); > } > public void run() > { > logger.debug("[{}] {}", name, new Date().getTime() - start); > logger_main.debug("[MAIN] - [{}] {}", name, new Date().getTime() - start); > } > } -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

1 0

[JIRA] Created: (LBCLASSIC-129) SimpleSocketServer suppresses error messages or Exceptions
by Rick Janda (JIRA) 15 May '09

15 May '09

SimpleSocketServer suppresses error messages or Exceptions ---------------------------------------------------------- Key: LBCLASSIC-129 URL: http://jira.qos.ch/browse/LBCLASSIC-129 Project: logback-classic Issue Type: Bug Components: Other Affects Versions: 0.9.15 Reporter: Rick Janda Assignee: Logback dev list Hello Logback team, It seems, that the SimpleSocketServer is suppressing various error messages or Exceptions. There are several conditions, where I do not get an error message at all, e.g. - if a logger is referring to an appender that is not defined in the logback.xml - if the FileAppender or RollingFileAppender is not able to write a file, either caused by wrong permissions or non existence of the target directory - if the server port is already used by another application This makes debugging of the configuration file really time consuming. Better output could make config debugging much faster here. Thanx in advance for improving this. Regards, Rick -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

1 0

[JIRA] Created: (LBCLASSIC-128) SocketAppender missing log messages after restart of SimpleSocketServer
by Rick Janda (JIRA) 15 May '09

15 May '09

SocketAppender missing log messages after restart of SimpleSocketServer ----------------------------------------------------------------------- Key: LBCLASSIC-128 URL: http://jira.qos.ch/browse/LBCLASSIC-128 Project: logback-classic Issue Type: Bug Components: appender Affects Versions: 0.9.15 Reporter: Rick Janda Assignee: Logback dev list Hello Logback team, I have a couple of web apps running in a tomcat and sending some log messages to a SimpleSocketServer. Every webapp is using its own LoggingContext by means of the JNDIContextSelector. The SocketAppender is configures as followed: <appender name="SOCKET" class="ch.qos.logback.classic.net.SocketAppender"> <RemoteHost>192.168.100.161</RemoteHost> <Port>6000</Port> <ReconnectionDelay>1000</ReconnectionDelay> <IncludeCallerData>false</IncludeCallerData> </appender> In general, this constellation works fine for me. But if I restart the SimpleSocketServer only some of the webapps seem properly reconnect to the SimpleSocketServer. Newly created log messages of a few of the webapps do not show up on the SimpleSocketServer side at all any more. After restart of the Tomcat with all the webapps, all new log entries are transmitted properly again to the SimpleSocketServer. Fixing this issue would really helps me as I do not have to restart all the Tomcats delivering there log messages to the single SimpleSocketServer after restarting it. Thanx in advance for your help and have a good weekend, Rick -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

1 0

[JIRA] Created: (LBCLASSIC-127) RollingFileAppender does not roll the files in SimpleSocketServer
by Rick Janda (JIRA) 15 May '09

15 May '09

RollingFileAppender does not roll the files in SimpleSocketServer ----------------------------------------------------------------- Key: LBCLASSIC-127 URL: http://jira.qos.ch/browse/LBCLASSIC-127 Project: logback-classic Issue Type: Bug Components: Other Affects Versions: 0.9.15 Reporter: Rick Janda Assignee: Logback dev list Hello Logback team, I use the RollingFileAppender in a SimpleSocketServer. The Messages are correctly written to the files but the files are not rolled at all. If I use the same appender config directly in my applications locally, it rolls the files as expected. The appender is configures as followed: <appender name="PAYLOAD_SIFT" class="ch.qos.logback.classic.sift.SiftingAppender"> <discriminator class="com.swisscom.allip.logback.ContextBasedDiscriminator"> <DefaultValue>unknown</DefaultValue> </discriminator> <sift> <appender name="FILE-PAYLOAD-${contextName}" class="ch.qos.logback.core.rolling.RollingFileAppender"> <File>${LOG_DIR}/payload-${contextName}.log</File> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">  <FileNamePattern>${LOG_DIR}/archive/payload-${contextName}_%d{yyyy-MM-dd}.log </FileNamePattern>  <MaxHistory>${MAX_HISTORY_DAYS}</MaxHistory> </rollingPolicy> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%d{HH:mm:ss.SSS} refId: %mdc{refId} - %msg%n%xEx{full}</Pattern> </layout> </appender> </sift> </appender> Can you please have a look at this issue. Thank you in advance, Rick -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

1 0

[JIRA] Created: (LBCLASSIC-126) NDC implementation
by Anders Wallgren (JIRA) 08 May '09

08 May '09

NDC implementation ------------------ Key: LBCLASSIC-126 URL: http://jira.qos.ch/browse/LBCLASSIC-126 Project: logback-classic Issue Type: New Feature Affects Versions: 0.9.15 Reporter: Anders Wallgren Assignee: Logback dev list Attachments: NDC.java The discussion about NDC vs. MDC has been done going for quite a while. I don't think MDC is a suitable replacement for NDC, except insofar as NDC can be implemented using MDC. Enclosed is the NDC implementation we're started using at Electric Cloud. Please feel free to adapt/modify/enhance it as you see fit. We place this code in the public domain in case others find it useful. Attachment to come as well. // NDC.java -- // // NDC.java is part of the ElectricCommander server. // // Copyright (c) 2005-2009 Electric Cloud, Inc. // All rights reserved. // package com.electriccloud.log; import java.util.Deque; import java.util.LinkedList; import org.jetbrains.annotations.NonNls; import org.jetbrains.annotations.NotNull; import org.slf4j.MDC; /** * Utility object that implements NDC using MDC. */ @SuppressWarnings({"UtilityClass", "StringContatenationInLoop"}) public class NDC { //~ Static fields/initializers --------------------------------------------- private static final ThreadLocal<Deque<String>> s_stack = new ThreadLocal<Deque<String>>() { @Override @SuppressWarnings({"RefusedBequest"}) protected Deque<String> initialValue() { return new LinkedList<String>(); } }; //~ Constructors ----------------------------------------------------------- private NDC() { } //~ Methods ---------------------------------------------------------------- public static void pop() { Deque<String> stack = s_stack.get(); // Pop the stack if isn't already empty if (!stack.isEmpty()) { stack.pop(); } // Put the previous value in the MDC (null if the stack is now empty) MDC.put("NDC", stack.peek()); } @SuppressWarnings({"HardCodedStringLiteral"}) public static void push(@NonNls @NotNull String format, Object... args) { Deque<String> stack = s_stack.get(); String previous = stack.peek(); String segment = args.length == 0 ? format : String.format(format, args); String newValue = previous == null ? segment : String.format("%s %s", previous, segment); stack.push(newValue); MDC.put("NDC", newValue); } } -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

2 2