September 2009 - logback-dev

[JIRA] Created: (LBCORE-97) Starvation on AppenderBase.doAppend
by Joern Huxhorn (JIRA) 23 Mar '10

23 Mar '10

Starvation on AppenderBase.doAppend ----------------------------------- Key: LBCORE-97 URL: http://jira.qos.ch/browse/LBCORE-97 Project: logback-core Issue Type: Bug Components: Appender Affects Versions: 0.9.15 Reporter: Joern Huxhorn Assignee: Logback dev list Priority: Critical Attachments: AppenderBaseLock.patch The problem we are facing here is that several threads are trying to obtain the object monitor of the exact same resource, namely the Appender. The assumption that multiple threads waiting for ownership of a monitor would receive the monitor in the order that they tried to acquire it is simply incorrect. This is documented behavior. See the last paragraph of [1]: "Likewise, no assumptions should be made about the order in which threads are granted ownership of a monitor or the order in which threads wake in response to the notify or notifyAll method. An excellent reference for these topics is Chapter 9, "Threads," in Joshua Bloch's book Effective Java Programming Language Guide. " The documentation of Object.notifyAll() [2] states the following: "[..] The awakened threads will compete in the usual manner with any other threads that might be actively competing to synchronize on this object; for example, the awakened threads enjoy no reliable privilege or disadvantage in being the next thread to lock this object." The documentation in [5] also lists the following as a weak-spot of Built-in Synchronization in J2SE 1.4.x: "No way to alter the semantics of a lock, for example, with respect to reentrancy, read versus write protection, or fairness." In LBCORE-96 Ceki stated the following: "Logback is using the standard synchronization mechanism found in the JDK. You are saying that that mechanism is unsuitable which, truth be told, sounds quite suspicious." Yes, it's unsuitable in this situation because obtaining the object monitor is not guaranteed to be fair. It's not working in a "first come, first serve" manner. I assumed that, too, but it isn't the case. I had the exact same problem in Lilith some time ago because I made exactly this very same wrong assumption. Fairness of object monitor lock acquisition seems to be logical and a "good thing" but it's not specified that way, and for good reasons. Without fairness in place, the VM can optimize the execution of an application much better. A context switch is a costly operation for a CPU so performance is increased significantly if such a switch can be omitted. Concerning a test-case, this would be pretty hardcore to implement since it's 100% implementation dependent. One implementation *may* handle the locking of object monitors fairly while others don't. Therefore I'll try the following first: I assume I could convince you that object monitor acquisition (OMA) is not fair. If we take that for granted the following scenario should show my point: There are 4 Threads (e.g. 4 Threads handling concurrent webapp-requests) that have one single chokepoint, the appender. Since OMA isn't fair, it's possible that only some of those threads can work at all (see [3]). Exactly that is happening right now in our webapp running on a 4-core Solaris on JDK6. My next assumption is that we both agree that this isn't acceptable behavior. Logging should be handled "first come, first served" so that if Thread A is waiting to append an event and Thread B is waiting to append an event subsequently, the actual appending order should be A, then B. This is currently not the case. It *may* be the case but there is no guarantee of it. One could even argue that the logging system is working incorrectly (aside from the starvation problem) because events are appended in a different order than the actual execution of the logger call. The only way to prevent this is the introduction of fairness into the locking process. The way to do this is to use ReentrantLock [4]. >From the ReentrantLock 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." This is exactly what is absolutely necessary for a logging framework. Logging must *NOT* be able to introduce a starvation problem into a multi-threaded application! And it does exactly that right now. I doubt that the performance will decrease in a significant manner due to the use of a fair ReentrantLock but even if this would be the case it would be necessary anyway. Otherwise, appending simply isn't working correctly. [1] http://java.sun.com/j2se/1.5.0/docs/guide/vm/thread-priorities.html [2] http://java.sun.com/javase/6/docs/api/java/lang/Object.html#notifyAll() [3] http://en.wikipedia.org/wiki/Starvation_(computing) [4] http://java.sun.com/javase/6/docs/api/java/util/concurrent/locks/ReentrantL… [5] http://java.sun.com/developer/technicalArticles/J2SE/concurrency/ -- 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

13 75

[JIRA] Created: (LBCORE-93) FlushingPolicy
by Ceki Gulcu (JIRA) 18 Mar '10

18 Mar '10

FlushingPolicy -------------- Key: LBCORE-93 URL: http://jira.qos.ch/browse/LBCORE-93 Project: logback-core Issue Type: New Feature Reporter: Ceki Gulcu Assignee: Logback dev list Let flushing be a settable policy of WriteAppender. Thus, the user would be able to set the FlushingPolicy of a WriterAppender or any derived class which would allow you to flush the underlying output stream according to any criteria available to the shouldFlush() method (see below), including time. Here is the relevant interface: interface FlushingPolicy { booelan shouldFlush(LoggingEvent e); } We could easily imagine a policy flushing on every warning or error in addition to special markers. For example, Marker FLUSH = MarkerFactory.getMarker("FLUSH"); logger.info(FLUSH, "finished serving request {}", request.getId()); -- 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 1

[JIRA] Created: (LBCORE-113) SMTPAppender should have support for avoiding flooding
by Ceki Gulcu (JIRA) 03 Mar '10

03 Mar '10

SMTPAppender should have support for avoiding flooding ------------------------------------------------------ Key: LBCORE-113 URL: http://jira.qos.ch/browse/LBCORE-113 Project: logback-core Issue Type: New Feature Reporter: Ceki Gulcu Assignee: Logback dev list -- 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 1

[JIRA] Created: (LBCORE-109) FileAppender writing to a shared (networked) file system
by Ceki Gulcu (JIRA) 03 Mar '10

03 Mar '10

FileAppender writing to a shared (networked) file system -------------------------------------------------------- Key: LBCORE-109 URL: http://jira.qos.ch/browse/LBCORE-109 Project: logback-core Issue Type: Bug Affects Versions: 0.9.9, 0.9.10, 0.9.11, 0.9.12, 0.9.13, 0.9.14, 0.9.15 Reporter: Ceki Gulcu Assignee: Logback dev list FileAppender writing to a shared (networked) file system with lost networked connection. -- 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

3 7

[JIRA] Created: (LBCLASSIC-112) ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest hangs on Mac OS X
by Joern Huxhorn (JIRA) 03 Mar '10

03 Mar '10

ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest hangs on Mac OS X ------------------------------------------------------------------------- Key: LBCLASSIC-112 URL: http://jira.qos.ch/browse/LBCLASSIC-112 Project: logback-classic Issue Type: Bug Affects Versions: 0.9.16 Reporter: Joern Huxhorn Assignee: Logback dev list This test keeps hanging repeatedly at the very same spot. I'll attach a file with further info. -- 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

3 10

[JIRA] Created: (LBCLASSIC-102) Suggestion: Change logger name of inner classes.
by Joern Huxhorn (JIRA) 15 Dec '09

15 Dec '09

Suggestion: Change logger name of inner classes. ------------------------------------------------ Key: LBCLASSIC-102 URL: http://jira.qos.ch/browse/LBCLASSIC-102 Project: logback-classic Issue Type: Improvement Components: appender Affects Versions: 0.9.15 Reporter: Joern Huxhorn Assignee: Logback dev list At the moment, the logger name of inner classes is OuterClass$InnerClass. Because of that, the logging level of OuterClass isn't inherited by InnerClass at the moment. If LoggerFactory changed the logger name to OuterClass.InnerClass instead, InnerClass would inherit the logging level of OuterClass which seems intuitively correct. I'd suggest to accept both $InnerClass and .InnerClass style in logback configurations for compatibility and usability reasons. -- 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

4 14

[JIRA] Created: (LBCLASSIC-147) TwitterAppender
by Joern Huxhorn (JIRA) 04 Dec '09

04 Dec '09

TwitterAppender --------------- Key: LBCLASSIC-147 URL: http://jira.qos.ch/browse/LBCLASSIC-147 Project: logback-classic Issue Type: New Feature Components: appender Affects Versions: 0.917 Reporter: Joern Huxhorn Assignee: Logback dev list Attachments: twitter-appender.zip I've implemented a prototype of a TwitterAppender, as discussed on the mailinglist. http://www.nabble.com/Twitter-Appender--to24792908.html#a24792908 Please forget my message about the encoding problem, it was entirely my fault. -- 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 5

[JIRA] Created: (LBCLASSIC-120) Joran configuration not working in OSGi environment
by Pavol Juhos (JIRA) 03 Dec '09

03 Dec '09

Joran configuration not working in OSGi environment --------------------------------------------------- Key: LBCLASSIC-120 URL: http://jira.qos.ch/browse/LBCLASSIC-120 Project: logback-classic Issue Type: Bug Components: joran Affects Versions: 0.9.15 Environment: OSGi Service Platform Release 4 Reporter: Pavol Juhos Assignee: Logback dev list When running in OSGi environment, JoranConfigurator throws a ClassCastException when trying to parse the Logback XML configuration file. The problem seems to be caused by OSGi-unfriendly JAXP parser discovery mechanism as suggested by Dieter Wimberger in his blog post -- http://wimpi.coalevo.net/2008/04/hack-how-to-use-logback.html "[...] JAXP discovery mechanism assume visibility of the parser through the context ClassLoader of the actual thread, which may cause some troubles." Observed exception stack trace: Failed to auto configure default logger context Reported exception: ch.qos.logback.core.joran.spi.JoranException: Parser configuration error occured at ch.qos.logback.core.joran.event.SaxEventRecorder.recordEvents(SaxEventRecorder.java:63) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:105) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:76) at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:40) at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:47) at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:108) at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:85) at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:56) at org.slf4j.LoggerFactory.getSingleton(LoggerFactory.java:189) at org.slf4j.LoggerFactory.bind(LoggerFactory.java:112) at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:105) at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:235) at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:208) at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:221) at com.foo.bar.server.config.Configuration.<clinit>(Configuration.java:244) at com.foo.bar.server.ServerBundleActivator.start(ServerBundleActivator.java:39) at org.apache.felix.framework.util.SecureAction.startActivator(SecureAction.java:589) at org.apache.felix.framework.Felix._startBundle(Felix.java:1671) at org.apache.felix.framework.Felix.startBundle(Felix.java:1588) at org.apache.felix.framework.Felix.setFrameworkStartLevel(Felix.java:1180) at org.apache.felix.framework.StartLevelImpl.run(StartLevelImpl.java:265) at java.lang.Thread.run(Unknown Source) Caused by: java.lang.ClassCastException: org.apache.xerces.jaxp.SAXParserFactoryImpl at javax.xml.parsers.SAXParserFactory.newInstance(Unknown Source) at ch.qos.logback.core.joran.event.SaxEventRecorder.recordEvents(SaxEventRecorder.java:56) ... 21 more -- 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

3 4

[JIRA] Created: (LBCLASSIC-101) Problem with logback OSGi bundles
by Ceki Gulcu (JIRA) 03 Dec '09

03 Dec '09

Problem with logback OSGi bundles --------------------------------- Key: LBCLASSIC-101 URL: http://jira.qos.ch/browse/LBCLASSIC-101 Project: logback-classic Issue Type: Bug Affects Versions: 0.9.14 Reporter: Ceki Gulcu Assignee: Logback dev list Priority: Critical http://www.slf4j.org/pipermail/user/2009-January/000661.html http://www.slf4j.org/pipermail/user/2009-January/000663.html -- 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 3

[JIRA] Created: (LBCLASSIC-153) Excessive synchronization in ReconfigureOnChangeFilter.decide
by Anders Wallgren (JIRA) 03 Dec '09

03 Dec '09

Excessive synchronization in ReconfigureOnChangeFilter.decide ------------------------------------------------------------- Key: LBCLASSIC-153 URL: http://jira.qos.ch/browse/LBCLASSIC-153 Project: logback-classic Issue Type: Bug Affects Versions: 0.917 Reporter: Anders Wallgren Assignee: Logback dev list The synchronization in ReconfigureOnChangeFilter.decide hurts scalability. It seems unnecessary to serialize the code in changeDetected -- it should be possible to use atomic updates of nextCheck and lastModified and only serialize the actual reconfiguration. -- 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

3 9