December 2009 - logback-dev

[JIRA] Created: (LBCLASSIC-166) Static logger references in shared classes doesn't work with JNDIContextSelector
by Gabriele Contini (JIRA) 26 Mar '10

26 Mar '10

Static logger references in shared classes doesn't work with JNDIContextSelector -------------------------------------------------------------------------------- Key: LBCLASSIC-166 URL: http://jira.qos.ch/browse/LBCLASSIC-166 Project: logback-classic Issue Type: New Feature Components: Other Affects Versions: 0.917 Reporter: Gabriele Contini Assignee: Logback dev list The issue was already described in: LBCLASSIC-87 by Lars Ködderitzsch {quote} As Jens already pointed out the most common pattern to logging (even in common libaries as Jakarta Commons, Spring whatsoever) is using a static logger, eg. public class XY { private static [final] Logger log = LoggerFactory.getLogger(XY.class); ... } If such libraries are shared (either by being in tomcats shared libs, or by being directly in the ear) by multiple webapps, the logger context wins in which the original loading of the logging class (aka XY, see above) happens. To make an example. An ear contains two webapplications A and B, both have different logger context CtxA and CtxB. A library (say Spring for instance) is place in the ear and both webapps reference the library through their MANIFEST.MF. On application startup webapp A gets initialized first, during initialisation the classes of the shared libary (Spring) are loaded, therefor static loggers initialized with the context CtxA. Now webapp B gets initialized, classes of the shared libary are already loaded by the EARClassloader, the loggers continue to use CtxA. At runtime regardless of wich logger context will be set by context selectors of the webapps, all logging done by the shared classes will always go to CtxA. One can argue that common libaries should not use static loggers, but always obtain loggers freshly from the LoggerFactory. But that is a pipe dream, because the de-facto pattern in obtaining and using a logger is through a static field as depicted above. To achieve true per-webapp logging, already initialized loggers need to be able to switch logger contexts, for instance through TreadLocal or other mechanisms. {quote} And was closed with: {quote} If you need static references problem to be dealt with, then please file a *new* jira issue. {quote} I want to separate hibernate logs in my j2ee application (under jboss). Hibernate is included in server libs, and it uses static loggers: {code} public class XY { private static [final] Logger log = LoggerFactory.getLogger(XY.class); ... } {code} I also want to use separate configuration files for each j2ee application (so sifting appender is not enough), thus i'm using the JndiContextSelector. Logback is unable to switch context once hibernate is initialized, and the logger separation doesn't work for static loggers in shared libraries. --- I also tried to do my own ContextSelector in order to have a Logger that perform a jndi lookup when it's needed but: * ''LoggerContext'' has a method ''getLogger(String)'' that is final. I can't override LoggerContext and return my own instance of Logger. * In my opinion the ''contextSelector.getLoggerContext()'' could return a ''ILoggerFactory'' (there is no need it returns a full ''LoggerContext'' Best regards. Gabriele Contini -- 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 4

[JIRA] Created: (LBACCESS-11) Jetty 7.x support for logback-access
by Daniel Peters (JIRA) 25 Mar '10

25 Mar '10

Jetty 7.x support for logback-access ------------------------------------ Key: LBACCESS-11 URL: http://jira.qos.ch/browse/LBACCESS-11 Project: logback-access Issue Type: Improvement Affects Versions: 0.9.18 Environment: Jetty 7.0.1 - http://eclipse.org/jetty/ Reporter: Daniel Peters Assignee: Logback dev list Since Jetty moved to the Eclipse Foundation, all package names changed from "mortbay" to "eclipse", which is why logback-access 0.9.18 doesnt work with Jetty7. When configured like described in http://logback.qos.ch/access.html I get this: Caused by: java.lang.NoClassDefFoundError: org/mortbay/jetty/RequestLog Can you maybe create a 2nd Jetty RequestLogImpl that uses the new "org.eclipse.jetty"-imports? Thanks! -- 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 5

[JIRA] Created: (LBCORE-95) BurstFilter
by Ceki Gulcu (JIRA) 25 Mar '10

25 Mar '10

BurstFilter ----------- Key: LBCORE-95 URL: http://jira.qos.ch/browse/LBCORE-95 Project: logback-core Issue Type: New Feature Reporter: Ceki Gulcu Assignee: Ceki Gulcu A filter to regulate log message bursts, useful for things like throttling the number of logs sent to an e-mail appender when the database is unavailable. See http://www.qos.ch/pipermail/logback-dev/2009-March/003921.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

1 4

[JIRA] Created: (LBCLASSIC-148) Deadlock with DBAppender
by Mel T. (JIRA) 24 Mar '10

24 Mar '10

Deadlock with DBAppender ------------------------ Key: LBCLASSIC-148 URL: http://jira.qos.ch/browse/LBCLASSIC-148 Project: logback-classic Issue Type: Bug Affects Versions: 0.917 Environment: MacBook Pro 17" Intel Core 2 Duo 2.33 GHz OS X 10.5.7 (9J61) java version "1.6.0_13" slf4j 1.5.8 c3p0 0.9.1.2 Reporter: Mel T. Assignee: Logback dev list A deadlock occurs when running the attached application. For this lock to occur, we need to: - load a configuration other than the default in java app. - not have any default logback.xml in the classpath. - have these jars in the classpath c3p0-0.9.1.2.jar logback-core-0.9.17.jar logback-classic-0.9.17.jar log4j-over-slf4j-1.5.8.jar slf4j-api-1.5.8.jar mysql.jar - Place attached the logback2.xml file in the same package as the attached MainTest class. - adapt the logback2.xml file to your DB schema. (note that you do not need to have the DB tables created for the lock to occur, but the test is more conclusive if you have a valid DB connection and schema.) - Execute this java -cp ".:../c3p0-0.9.1.2.jar:../logback-core-0.9.17.jar:../logback-classic-0.9.17.jar:../log4j-over-slf4j-1.5.8.jar:../slf4j-api-1.5.8.jar:../mysql.jar" MainTest The application should output the logger status and hang. Workaround: - Do not include log4j-over-slf4j in the classpath, - or add a default logback.xml that will be loaded first (just copy and rename logback2.xml in same default package) - or use the attached logback2-works.xml instead of logback2.xml (modify MainTest to load that file instead.) In this last one, the change is that the DB appender is only used in a logger element instead of the root. I did not spend the time to look at the cause of this locking problem as the workarounds allow me to move on. So I hope this really belong in jira, and not a config/usage error on my part. -- Mel T. -- 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 11

[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: (LBCLASSIC-170) DbAppender discards all exception' details
by Tomasz Nurkiewicz (JIRA) 23 Mar '10

23 Mar '10

DbAppender discards all exception' details ------------------------------------------ Key: LBCLASSIC-170 URL: http://jira.qos.ch/browse/LBCLASSIC-170 Project: logback-classic Issue Type: Bug Components: appender Affects Versions: 0.9.18 Reporter: Tomasz Nurkiewicz Assignee: Logback dev list DbAppender uses a single table logging_event_exception to persist stack traces, inserting one row per each stack frame. Also, each row has its parent event id. Unfortunately this approach loses a lot of exception details, making it unable to fully recreate ILoggingEvent instance that was logged by the DbAppender. List of attributes that are missing: * exception message * exception class name * exception root cause Also logging_event_exception saves the result of ch.qos.logback.classic.spi.StackTraceElementProxy#toString (which refers to java.lang.StackTraceElement#toString) instead of saving each element of java.lang.StackTraceElement separately. Now, in order to recreate StackTraceElement instance one must parse (probably using regular expression) string saved in trace_line attribute. My suggestion would be to create two tables: * logging_event_throwable with columns: message, class_name and cause foreign key referencing other logging_event_throwable instance * logging_event_stack_frame with columns: class_name, method, file, line and a foreign key referencing logging_event_throwable + indexing column Also logging_event would have a optional foreign key to logging_event_throwable. This modifications in database schema would allow to fully recreate ILoggingEvent. For backward compatibility ch.qos.logback.classic.db.DBAppender should remain untouched. The idea is to subclass it and override ch.qos.logback.classic.db.DBAppender#insertThrowable. -- 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 5

[JIRA] Created: (LBCORE-126) ch.qos.logback.core.db.DBAppenderBase tries to use column "EVENT_ID" but does not exist
by Brian Edwards (JIRA) 22 Mar '10

22 Mar '10

ch.qos.logback.core.db.DBAppenderBase tries to use column "EVENT_ID" but does not exist --------------------------------------------------------------------------------------- Key: LBCORE-126 URL: http://jira.qos.ch/browse/LBCORE-126 Project: logback-core Issue Type: Bug Components: Appender Affects Versions: 0.9.17 Environment: postgresql Reporter: Brian Edwards Assignee: Logback dev list on line 91 in ch.qos.logback.core.db.DBAppenderBase append creates a java.sql.PreparedStatement by calling connection.prepareStatement(getInsertSQL(), new String[] {"EVENT_ID"}); but because postgres is case sensitive the column does not exist because it is called event_id -- 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

[JIRA] Created: (LBCORE-128) Please support implementation of binary log files in RollingFileAppender/FileAppender
by Joern Huxhorn (JIRA) 22 Mar '10

22 Mar '10

Please support implementation of binary log files in RollingFileAppender/FileAppender ------------------------------------------------------------------------------------- Key: LBCORE-128 URL: http://jira.qos.ch/browse/LBCORE-128 Project: logback-core Issue Type: Improvement Components: Appender Affects Versions: 0.9.17 Reporter: Joern Huxhorn Assignee: Logback dev list This was discussed briefly at http://marc.info/?l=logback-dev&m=124905434331308&w=2 and I forgot to file a ticket about this. Currently, RandomFileAppender => FileAppender => WriterAppender is using the following method in WriterAppender to actually write the data: protected void writerWrite(String s, boolean flush) throws IOException Please add an additional method like protected void writerWrite(byte[] bytes, boolean flush) throws IOException to write to the underlying stream directly. writerWrite(String, boolean) could call that method after performing the transformation internally, making this change transparent for the rest of the implementation. Using a binary format for logfiles could have tremendous performance impact as can be seen here: http://sourceforge.net/apps/trac/lilith/wiki/SerializationPerformance -- 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

6 42

[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: (LBCLASSIC-169) Customizing table names used by DbAppender
by Tomasz Nurkiewicz (JIRA) 10 Mar '10

10 Mar '10

Customizing table names used by DbAppender ------------------------------------------ Key: LBCLASSIC-169 URL: http://jira.qos.ch/browse/LBCLASSIC-169 Project: logback-classic Issue Type: Improvement Components: appender Affects Versions: 0.9.18 Reporter: Tomasz Nurkiewicz Assignee: Logback dev list Priority: Minor ch.qos.logback.classic.db.DBAppender uses hard-coded table names for logging events: logging_event, logging_event_property and logging_event_exception. Allowing to change these default names has two benefits: * There are systems where database table names must follow some naming conventions (prefixes, using underscores vs. camel case) * One could create several Db appenders, each operating on different set of tables (for performance reasons or more fine grained logging and filtering) Each table name would be configured using a property in logback.xml. Default values for table names would be the same as present ones to maintain backward compatibility. If you are interested in this feature let me know, I can implement it and provide a patch. -- 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

5 16