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

org.slf4j.impl.StaticLoggerBinder.SINGLETON
by Rusty Wright 25 Oct '11

25 Oct '11

I'm unable to create a bugzilla account at http://bugzilla.slf4j.org/createaccount.cgi Could someone enter this bug report for me? If I change my version of logback to 0.9.11 I don't get this. I get it when I use logback version 0.9.13. I'm using version 1.5.5 of slf4j. Thanks Running TestSuite org.apache.maven.surefire.booter.SurefireExecutionException: Cannot instantiate class edu.berkeley.ist.cars.net.email.EmailTest; nested exception is org.testng.TestNGException: Cannot instantiate class edu.berkeley.ist.cars.net.email.EmailTest org.testng.TestNGException: Cannot instantiate class edu.berkeley.ist.cars.net.email.EmailTest at org.testng.internal.ObjectFactoryImpl.newInstance(ObjectFactoryImpl.java:35) at org.testng.internal.ClassHelper.createInstance(ClassHelper.java:330) at org.testng.internal.ClassImpl.getDefaultInstance(ClassImpl.java:62) at org.testng.internal.ClassImpl.getInstances(ClassImpl.java:81) at org.testng.internal.TestNGClassFinder.<init>(TestNGClassFinder.java:114) at org.testng.TestRunner.initMethods(TestRunner.java:281) at org.testng.TestRunner.init(TestRunner.java:227) at org.testng.TestRunner.init(TestRunner.java:189) at org.testng.TestRunner.<init>(TestRunner.java:138) at org.testng.SuiteRunner$DefaultTestRunnerFactory.newTestRunner(SuiteRunner.java:477) at org.testng.SuiteRunner.privateRun(SuiteRunner.java:244) at org.testng.SuiteRunner.run(SuiteRunner.java:198) at org.testng.TestNG.createAndRunSuiteRunners(TestNG.java:821) at org.testng.TestNG.runSuitesLocally(TestNG.java:788) at org.testng.TestNG.run(TestNG.java:708) at org.apache.maven.surefire.testng.TestNGExecutor.run(TestNGExecutor.java:62) at org.apache.maven.surefire.testng.TestNGDirectoryTestSuite.execute(TestNGDirectoryTestSuite.java:141) at org.apache.maven.surefire.Surefire.run(Surefire.java:177) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338) at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997) Caused by: java.lang.reflect.InvocationTargetException at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27) at java.lang.reflect.Constructor.newInstance(Constructor.java:494) at org.testng.internal.ObjectFactoryImpl.newInstance(ObjectFactoryImpl.java:26) ... 23 more Caused by: java.lang.IllegalAccessError: tried to access field org.slf4j.impl.StaticLoggerBinder.SINGLETON from class org.slf4j.LoggerFactory at org.slf4j.LoggerFactory.staticInitialize(LoggerFactory.java:83) at org.slf4j.LoggerFactory.<clinit>(LoggerFactory.java:73) at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:155) at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:131) at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:272) at org.springframework.test.context.testng.AbstractTestNGSpringContextTests.<init>(AbstractTestNGSpringContextTests.java:77) at edu.berkeley.ist.cars.net.email.EmailTest.<init>(EmailTest.java:21) ... 28 more

4 5

Best practices to avoid deadlocks while logging
by Olivier Cailloux 13 Jun '09

13 Jun '09

Dear list, I recently had a deadlock problem related to logging and I am wondering if it comes from a problem in the logging framework (I must say I doubt it) or from the way I use logging, in which case I'd like to hear advices about how others avoid this kind of problems. The pattern is the following. (Please see hereby the java classes which might be clearer.) - In a class "Worker", a method "work()" locks the object instance of the class Worker to do some work and calls the logging framework to print the result (while still holding the lock). - In the same class "Worker", an other method "getStatus()" obtains the current status of the object instance of the class Worker and returns it as a String (method used for logging). That method locks the object at some point to make sure it reads consistent internal status information. - In an other class "Accessor", a method "access()" performs some work (not locking anything), then logs the status of an object of the class Worker by using its getStatus() method. Now the deadlock scenario is the following. - A thread "WorkerThread" is executing the method "work()". It has acquired the lock for the Worker object and has not reached the logging statement yet. - An other thread "AccessorThread" is executing the method "access()", and is executing the logging statement. AFAIU, logback console logger has some sort of "central" locking point: when a thread is logging, an other thread may not log in parallel (that seems good as the user does not want his different logging statements to be mixed together)... Thus, the following happens. - AccessorThread has a lock to the Logger, and waits to acquire the Worker lock to execute the synchronized block in getStatus(). - WorkerThread is holding that precise lock, and will never release it, because arriving at the logging statement in "work()", it starts waiting for the Logger lock acquired by AccessorThread. These two threads are caught in a deadlock. I feel the problem comes from not respecting the general rule that a block of code holding a lock should not call a method on an externally controlled object (possibly shared with other threads) whose locking behavior is unknown. (Note that both my code and the logging framework do not respect this rule, AFAIK.) So I should not have issued the log statement in my synchronized block in "work()". In my case, I can remove this logging statement from the synchronized block, but it is not clear to me whether it is always possible (or easy) to do so, especially if the thing you want to log depends on an internal state which might change as soon as you release the lock. An other way to solve that problem is to not use the parametrized message system in SLF4J. Indeed, it would disable the possibility of the AccessorThread to try to acquire the lock on Worker while being in the SLF4J method. I am wondering however if there is not a way that slf4j implementation (logback) release the lock on its logger, then gets the Worker lock, then re-acquire the lock on its logger only after having released the Worker lock, so that it has only one lock at a time? I tend to think that it would enable a user of the logging framework to pay no attention of the deadlock possibilities incurred by the logging framework, and to avoid him introducing subtle bugs with logging statements... But I may be wrong and I am not an expert in multithread programming. More generally speaking, what would be the advices from experienced programmers to avoid this problem? How do you log in a multithreading context? Also I am wondering if that (anti-)pattern could be documented on the logback page, to avoid others to do the same mistake as me? Or even on the SLF4J page, if it is not logback-specific? The attached classes provide a test case showing the deadlock scenario. The test fails reliably on my box. Thank you for any help. Olivier

3 7

Logback with Postfix
by Brian Moschel 02 Jun '09

02 Jun '09

I'm trying to set up logback for use with Postfix running locally on the same machine as my app. I am using the following: <appender name="EMAIL" class="ch.qos.logback.classic.net.SMTPAppender"> <SMTPHost>localhost</SMTPHost> <To>brian.moschel(a)gmail.com</To> <From>brian.moschel(a)gmail.com</From> <Subject>TESTING: %logger{20} - %m</Subject> <layout class="ch.qos.logback.classic.html.HTMLLayout"/> </appender> This does not work though. It hangs forever and my local mail logs never receive a request. The local mail server is running at port 25. I can run "mail <some email address> to sucessfully mail someone on this machine. Any ideas how to debug this? Thanks, Brian

3 2

AUTO: Manfred Kuhlmann is out of office. (Rückkehr am 25.05.2009)
by Manfred.Kuhlmann＠steria-mummert.de 20 May '09

20 May '09

Ich werde ab dem 20.05.2009 nicht im Büro sein. Ich kehre zurück am 25.05.2009. I will be out of the office starting 20.05.2009. I will be back on 25.05.2009. Ihre Nachricht werde ich nach meiner Rückkehr beantworten. I will answer your message after my return. Mit freundlichen Grüßen Best regards Manfred Kuhlmann Hinweis: Dies ist eine automatische Antwort auf Ihre Nachricht " [logback-user] Best practices to avoid deadlocks while logging" gesendet am 20.05.2009 18:31:46. Diese ist die einzige Benachrichtigung, die Sie empfangen werden, während diese Person abwesend ist.

1 0

Best practices to avoid deadlocks while logging - test case
by Olivier Cailloux 20 May '09

20 May '09

Dear list, I recently had a deadlock problem related to logging and I am wondering if it comes from a problem in the logging framework (I must say I doubt it) or from the way I use logging, in which case I'd like to hear advices about how others avoid this kind of problems. The pattern is the following. (Please see hereby the java classes which might be clearer.) - In a class "Worker", a method "work()" locks the object instance of the class Worker to do some work and calls the logging framework to print the result (while still holding the lock). - In the same class "Worker", an other method "getStatus()" obtains the current status of the object instance of the class Worker and returns it as a String (method used for logging). That method locks the object at some point to make sure it reads consistent internal status information. - In an other class "Accessor", a method "access()" performs some work (not locking anything), then logs the status of an object of the class Worker by using its getStatus() method. Now the deadlock scenario is the following. - A thread "WorkerThread" is executing the method "work()". It has acquired the lock for the Worker object and has not reached the logging statement yet. - An other thread "AccessorThread" is executing the method "access()", and is executing the logging statement. AFAIU, logback console logger has some sort of "central" locking point: when a thread is logging, an other thread may not log in parallel (that seems good as the user does not want his different logging statements to be mixed together)... Thus, the following happens. - AccessorThread has a lock to the Logger, and waits to acquire the Worker lock to execute the synchronized block in getStatus(). - WorkerThread is holding that precise lock, and will never release it, because arriving at the logging statement in "work()", it starts waiting for the Logger lock acquired by AccessorThread. These two threads are caught in a deadlock. I feel the problem comes from not respecting the general rule that a block of code holding a lock should not call a method on an externally controlled object (possibly shared with other threads) whose locking behavior is unknown. (Note that both my code and the logging framework do not respect this rule, AFAIK.) So I should not have issued the log statement in my synchronized block in "work()". In my case, I can remove this logging statement from the synchronized block, but it is not clear to me whether it is always possible (or easy) to do so, especially if the thing you want to log depends on an internal state which might change as soon as you release the lock. An other way to solve that problem is to not use the parametrized message system in SLF4J. Indeed, it would disable the possibility of the AccessorThread to try to acquire the lock on Worker while being in the SLF4J method. I am wondering however if there is not a way that slf4j implementation (logback) release the lock on its logger, then gets the Worker lock, then re-acquire the lock on its logger only after having released the Worker lock, so that it has only one lock at a time? I tend to think that it would enable a user of the logging framework to pay no attention of the deadlock possibilities incurred by the logging framework, and to avoid him introducing subtle bugs with logging statements... But I may be wrong and I am not an expert in multithread programming. More generally speaking, what would be the advices from experienced programmers to avoid this problem? How do you log in a multithreading context? Also I am wondering if that (anti-)pattern could be documented on the logback page, to avoid others to do the same mistake as me? Or even on the SLF4J page, if it is not logback-specific? The attached classes provide a test case showing the deadlock scenario. The test fails reliably on my box. Thank you for any help. Olivier

1 0

Log4j LoggingEvent
by Greg Flex 14 May '09

14 May '09

Hi Ceki, I (again) have some questions about log4j. (I guess Logback works the same way....) I was wondering if there's a way to save a "logger object" to a data structure like a queue or something before sending it to some appender. For example: The socket appender will cause the log4j client to lock/freeze if there's no link to the server. I verified it and it does lock the client. I need to deal with this issue so I'd like to store "logger objects" (or something) before they go to the socket or some other appender first. At the moment I have a wrapper around the log4j that when the debug method is called I'm just calling the log4j debug method passing some args etc. so I have: logger.debug("some stuff"); The configuration file does the trick and outputs to the console (at the moment) all the info: the class name, the method name, the line number etc. I'd like to save this info somehow to some object that I can store in a queue or something. How do I retrieve this information programmatically? Is there a way? I know about LoggingEvent object, could I use it and pass the above stated information to its constructor then store it in a queue? Logger gets me for free (like method name etc.) Any suggestion? Thanks a lot. Greg.

3 7

breaking on startup
by Brian Moschel 13 May '09

13 May '09

Hey guys, I am noticing an error on startup: java.lang.ClassCastException: org.slf4j.impl.SimpleLoggerFactory I am trying to run the following lines to load my config, which I got from the startup guide: LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory(); JoranConfigurator configurator = new JoranConfigurator(); lc.reset(); configurator.setContext(lc); configurator.doConfigure(my_path); StatusPrinter.printInCaseOfErrorsOrWarnings(lc); The error occurs at the first line in the above code. I got this working at some point, but somehow am back in a non-working state. This is a Jetty app. Any tips? Thanks, Brian

3 8

Exception Handler
by Brian Moschel 12 May '09

12 May '09

Hey guys, I have a Jetty application that I configured with Logback. I am trying to set it up so any errors that occur during execution are emailed to me. I am a bit of a noobie, and so far I haven't had any luck with this. I can only get exceptions emailed to me if I explicitly set a try/catch block in my code everywhere and call logger.error(...). Is there an easy way to cause all exceptions to be logged and emailed to me via my SMTPAppender? Here is the config I have attempted to use so far: <configuration debug="true"> <appender name="EMAIL" class="ch.qos.logback.classic.net.SMTPAppender"> <SMTPHost>smtp.gmail.com</SMTPHost> <SMTPPort>465</SMTPPort> <SSL>true</SSL> <Username>myemail</Username> <Password>my password</Password> <To> myemail</To> <From> myemail</From> <Subject>TESTING: %logger{20} - %m</Subject> <layout class="ch.qos.logback.classic.html.HTMLLayout"/> </appender> <root level="debug"> <appender-ref ref="EMAIL" /> </root> <logger name="exception" level="ERROR"> <appender-ref ref="EMAIL"></appender-ref> </logger> <logger name="org.mortbay" level="error"> <appender-ref name="EMAIL"> </appender-ref></logger> <logger name="developerworks.jetty6" level="error"> <appender-ref name="EMAIL"> </appender-ref></logger> <logger name="jupiter.filters" level="error"> <appender-ref name="EMAIL"> </appender-ref></logger> <logger name="jupiter.messaging" level="error"> <appender-ref name="EMAIL"> </appender-ref></logger> </configuration> Thanks, Brian

3 2

Lilith 0.9.35 has been released!
by Joern Huxhorn 02 May '09

02 May '09

This release brings a big performance increase in both the Lilith application itself and the Lilith appenders Additionally, Lilith now supports the import of LOG4J and java.util.logging XML files Please see changes for more details on whats new. http://sourceforge.net/project/shownotes.php?group_id=219536&release_id=679… http://lilith.huxhorn.de At this point, the Lilith artifacts hav reached the central maven repository. Regards, Joern.

1 0