- logback-user - mailman3.qos.ch

FW: Antwort: Deadlock in case of console appender and system.out/err captured
by Dancewicz Grzegorz 22 May '14

22 May '14

Hi, Last days I had to update from logback 0.9.15 to the 1.1.2. Since this update the multithreaded test I have, dies in a deadlock. This test simply tries to simultaneously write to System.err and System.out in different threads. I use the logback under SLF4J(1.7.7) logging facade and additionally I also redirect the System.out and System.err into the the logback via SLF4J. For this purpose I have written my own OutputStream which I set as System.out and System.err (different instance for each). This stream writes forward using the ILogger (logback). Additionally the logback is configured in a way, that (among others) it has a ConsoleAppender from logback.core package. Finally, this results in the ConsoleTarget class using System.out/System.err to write to the console and here the deadlock happens. Does anyone had similar case or problems? Something must have changed in the locking system of Logback as the multithreaded test case passes with version 0.9.15 of Logback. I also tried to replace my own capturing stream written for System.out and System.err with the stuff from sysout-ver-slf4j from lidalia (project information link: http://projects.lidalia.org.uk/sysout-over-slf4j/project-summary.html) but the dealock behavior was exactly the same. I will appreciate any hints and help. Below there is a thread dump from jvisualvm and also the logback configuration used + test snippet: Found one Java-level deadlock: ============================= "Thread-226": waiting to lock monitor 0x19ebc774 (object 0x04621280, a java.io.PrintStream), which is held by "Thread-28" "Thread-28": waiting to lock monitor 0x188392e4 (object 0x0461afe8, a java.io.PrintStream), which is held by "Thread-27" "Thread-27": waiting for ownable synchronizer 0x0ab25c88, (a java.util.concurrent.locks.ReentrantLock$FairSync), which is held by "Thread-28" Java stack information for the threads listed above: =================================================== "Thread-226": at java.io.PrintStream.write(PrintStream.java:523) - waiting to lock <0x04621280> (a java.io.PrintStream) at java.io.PrintStream.print(PrintStream.java:669) at mhcc.cci.logging.SystemOutErrTest$4.run(SystemOutErrTest.java:349) at java.lang.Thread.run(Thread.java:744) "Thread-28": at java.io.PrintStream.write(PrintStream.java:478) - waiting to lock <0x0461afe8> (a java.io.PrintStream) at java.io.FilterOutputStream.write(FilterOutputStream.java:97) at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:36) at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:135) at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:194) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:219) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396) at ch.qos.logback.classic.Logger.error(Logger.java:563) at mhcc.cci.logging.internal.Slf4JLoggerWrapper.error(Slf4JLoggerWrapper.java:573) at mhcc.cci.logging.internal.LoggerOutputStream.writeToLog(LoggerOutputStream.java:223) at mhcc.cci.logging.internal.LoggerOutputStream.handleLogFragment(LoggerOutputStream.java:170) at mhcc.cci.logging.internal.LoggerOutputStream.flush(LoggerOutputStream.java:150) at java.io.PrintStream.write(PrintStream.java:482) - locked <0x04621280> (a java.io.PrintStream) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291) at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104) - locked <0x04621400> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185) at java.io.PrintStream.newLine(PrintStream.java:546) - locked <0x04621280> (a java.io.PrintStream) at java.io.PrintStream.println(PrintStream.java:807) - locked <0x04621280> (a java.io.PrintStream) at mhcc.cci.logging.SystemOutErrTest$4.run(SystemOutErrTest.java:353) at java.lang.Thread.run(Thread.java:744) "Thread-27": at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0ab25c88> (a java.util.concurrent.locks.ReentrantLock$FairSync) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:867) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197) at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:229) at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:290) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:217) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396) at ch.qos.logback.classic.Logger.info(Logger.java:620) at mhcc.cci.logging.internal.Slf4JLoggerWrapper.info(Slf4JLoggerWrapper.java:333) at mhcc.cci.logging.internal.LoggerOutputStream.writeToLog(LoggerOutputStream.java:213) at mhcc.cci.logging.internal.LoggerOutputStream.handleLogFragment(LoggerOutputStream.java:170) at mhcc.cci.logging.internal.LoggerOutputStream.flush(LoggerOutputStream.java:150) at java.io.PrintStream.write(PrintStream.java:482) - locked <0x0461afe8> (a java.io.PrintStream) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291) at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104) - locked <0x0461b168> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185) at java.io.PrintStream.newLine(PrintStream.java:546) - locked <0x0461afe8> (a java.io.PrintStream) at java.io.PrintStream.println(PrintStream.java:807) - locked <0x0461afe8> (a java.io.PrintStream) at mhcc.cci.logging.SystemOutErrTest$3.run(SystemOutErrTest.java:336) at java.lang.Thread.run(Thread.java:744) Found 1 deadlock. ================================ Logback configuration: <?xml version="1.0" encoding="UTF-8" ?>  <configuration scan="true" scanPeriod="120 seconds"> <jmxConfigurator /> <conversionRule conversionWord="bundle" converterClass="mhcc.cci.logging.internal.BundleMarkerConverter" /> <conversionRule conversionWord="category" converterClass="mhcc.cci.logging.internal.CategoryMarkerConverter" />  <appender name="TEST" class="mhcc.cci.logging.internal.test.LogbackAppenderQueue"/> <appender name="STDOUT" class="ch.qos.logback.core.MHCCConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <pattern>%date{HH:mm:ss.SSS} %-5level [%-15.15thread] %-25.25logger{25} [%mdc] %msg%n</pattern> </layout> </appender> <appender name="LOGFILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <File>${user.home}/dcvl/logs/component.log</File> <Append>true</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%d{ISO8601}\t*\t%level\t%category\t[%-29.29thread]\t%26.26bundle/%-36.36logger{36}\t[%mdc]\t*\t%msg%n </Pattern> </layout> <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy"> <FileNamePattern>${user.home}/dcvl/logs/component.%i.log.zip</FileNamePattern> <MinIndex>0</MinIndex> <MaxIndex>10</MaxIndex> </rollingPolicy> <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy"> <MaxFileSize>50MB</MaxFileSize> </triggeringPolicy> </appender> <appender name="AUDITLOGFILE" class="ch.qos.logback.core.FileAppender"> <Filter class="mhcc.cci.logging.internal.CategoryFilter"> <category>AUDIT</category> </Filter> <File>${user.home}/dcvl/logs/audit.log</File> <Append>true</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%d{ISO8601}\t*\t%level\t%category\t[%-29.29thread]\t%26.26bundle/%-36.36logger{36}\t[%mdc]\t*\t%msg%n</Pattern> </layout> </appender>  <logger name="TEST" level="TRACE"> <appender-ref ref="TEST" /> </logger> <logger name="mhcc.cci.configurator.dsl.modelprovider.internal.RuntimeMHCfgURIConverter" level="INFO" /> <logger name="mhcc.cci.logging.internal.Slf4jBundleEventLogger" level="INFO" /> <logger name="org.springframework" level="WARN" /> <logger name="org.springframework.osgi" level="WARN" /> <root level="debug"> <appender-ref ref="STDOUT" /> <appender-ref ref="LOGFILE" /> <appender-ref ref="AUDITLOGFILE" /> </root> </configuration> ================================= Test snippet: final int NUM_TEST_THREADS = 2 * 100; // must be en even number final ConcurrentLinkedQueue<Exception> exceptions = new ConcurrentLinkedQueue<Exception>(); final Runnable useOut = new Runnable() { @Override public void run() { try { System.out.print( "dummy text, " ); Thread.yield(); System.out.println( "rest of text" ); } catch ( Exception e ) { exceptions.add( e ); } } }; final Runnable useErr = new Runnable() { @Override public void run() { try { System.err.print( "dummy text, " ); Thread.yield(); System.err.println( "rest of text" ); } catch ( Exception e ) { exceptions.add( e ); } } }; Thread[] testThreads = new Thread[ NUM_TEST_THREADS ]; for ( int i = 0; i < NUM_TEST_THREADS; i += 2 ) { testThreads[ i ] = new Thread( useOut ); testThreads[ i + 1 ] = new Thread( useErr ); } // all threads run in parallel for ( int i = 0; i < NUM_TEST_THREADS; i++ ) { testThreads[ i ].start(); } for ( int i = 0; i < NUM_TEST_THREADS; i++ ) { testThreads[ i ].join(); } With best regards, Grzegorz Dancewicz

1 0

Re: [logback-user] Add header-lines to each log file
by Schoeftner, Thomas 20 May '14

20 May '14

Sorry to bump this topic again. Any ideas? Thanks, -Tom

3 2

Suppressing logging for select projects
by Mike Sukmanowsky 10 May '14

10 May '14

Hi there, We're currently developing project called streamparse which provides Pythonic tools for realtime stream development using Apache Storm. Although the project is Python-based, we maintain a command line interface, written in clojure, to provide JVM/Thrift interop capabilities https://github.com/Parsely/streamparse/tree/master/jvm. A requirement of one of our commands is to write a JSON object representation to STDOUT which our Python process would read and use downstream. The issue we have is that Apache Storm does some logging using logback upon calling certain functions which interferes with our expectation of only JSON being written to STDOUT. $ ./sparsej list --json 607 [main] INFO backtype.storm.thrift - Connecting to Nimbus at localhost:6627 [{"status":"ACTIVE","num-executors":52,"name":"meta_enricher","num-workers":4,"num-tasks":52,"uptime-secs":1211495,"id":"meta_enricher-49-1398354650"},{"status":"ACTIVE","num-executors":9,"name":"visits","num-workers":4,"num-tasks":9,"uptime-secs":53668,"id":"visits-7-1399512477"},{"status":"ACTIVE","num-executors":80,"name":"ptrack","num-workers":4,"num-tasks":80,"uptime-secs":76148,"id":"ptrack-3-1399489997"}] We added a logback-test.xml to a resources directory which is packaged with the JAR https://github.com/Parsely/streamparse/blob/master/jvm/resources/logback-te…. This isn't exactly what we want though since we really only need logging suppressed for the commands we run. What we're finding when our JAR is packaged with other dependencies is that all logging is suppressed. How can we go about suppressing logging for a single command like https://github.com/Parsely/streamparse/blob/master/jvm/src/streamparse/comm… ? Thanks! Mike -- Mike Sukmanowsky Product Lead, http://parse.ly 12 W 31st Street 8th floor New York, NY 10001 p: +1 (416) 953-4248 e: mike(a)parsely.com

3 2

Createing a java.util.Logger compatible object that logs to SFL4J?
by Christian Hammers 09 May '14

09 May '14

Hello Sometimes I encounter methods that accept a java.util.logging.Logger parameter with which one could customize the logging output. For example the debug facility of the Java EE7 REST implementations: import org.glassfish.jersey.filter.LoggingFilter; new LoggingFilter(java.util.logging.Logger.getLogger("my.rest.trace"), true)); Now I'm looking for a fake Logger that maybe extends java.util.logging.Logger but then really logs to SLF4J. In the above example only the info() method is actually used so I could write one myself but maybe somebody else has done the work? I already know about jul-to-slf4j but I don't want to redirect all JUL messages to log4j. tschüss, -christian-

1 0

FixedWindowRollingPolicy force rollover check at startup for short-lived applications
by foo 06 May '14

06 May '14

Hello Logback Team How can I achieve a "rollover check" at startup for the FixedWindowRollingPolicy (something like cleanHistoryOnStart for the TimeBasedRollingPolicy)? Thanks in advance and nice greetings Michael

1 0

Re: [logback-user] Logback-user Digest, Vol 31, Issue 15
by David Tkaczyk 30 Apr '14

30 Apr '14

Look at documentation for logger config. additivity = false... Or look for DuplicateMessageFilter... Or write your own filter. On Apr 30, 2014 6:00 AM, <logback-user-request(a)qos.ch> wrote: > Send Logback-user mailing list submissions to > logback-user(a)qos.ch > > To subscribe or unsubscribe via the World Wide Web, visit > http://mailman.qos.ch/mailman/listinfo/logback-user > or, via email, send a message with subject or body 'help' to > logback-user-request(a)qos.ch > > You can reach the person managing the list at > logback-user-owner(a)qos.ch > > When replying, please edit your Subject line so it is more specific > than "Re: Contents of Logback-user digest..." > > Today's Topics: > > 1. How to get a unique content rollingFileAppender? (hax0r(a)sina.com) > > > ---------- Forwarded message ---------- > From: <hax0r(a)sina.com> > To: "logback-user" <logback-user(a)qos.ch> > Cc: > Date: Wed, 30 Apr 2014 15:23:42 +0800 > Subject: [logback-user] How to get a unique content rollingFileAppender? > > I want such a rollingFileAppneder: > > Before appending new line to the current log file, the logger will check: > if there is any same line in the current log file, it will not write the > same content to the file. > > > I can not find such a file appender, so I want to customize it: > > > Firstly, I want to create a class extends the RollingFileAppneder, but I > find that the field which point to current file in RollingFileAppneder is > "friendly", I can not get the field in my own class. > > > There is an stupid option: I copy all the codes in the > RollingFileAppneder, and changed some logic in the append part. > > > Is there a elgant way to get such a unique content rollingFileAppender? > > > > > > _______________________________________________ > Logback-user mailing list > Logback-user(a)qos.ch > http://mailman.qos.ch/mailman/listinfo/logback-user >

1 0

How to get a unique content rollingFileAppender?
by hax0r＠sina.com 30 Apr '14

30 Apr '14

I want such a rollingFileAppneder:Before appending new line to the current log file, the logger will check: if there is any same line in the current log file, it will not write the same content to the file. I can not find such a file appender, so I want to customize it: Firstly, I want to create a class extends the RollingFileAppneder, but I find that the field which point to current file in RollingFileAppneder is "friendly", I can not get the field in my own class. There is an stupid option: I copy all the codes in the RollingFileAppneder, and changed some logic in the append part. Is there a elgant way to get such a unique content rollingFileAppender?

1 0

How does the custom ContextSelector work?
by Traktor Toni 28 Apr '14

28 Apr '14

I have posed this question on stackoverflow: http://stackoverflow.com/questions/23088466/what-is-the-point-of-logbacks-c… Unfortunately with no replies. My question is essentially: How can I get a specific context by name if there is no ".getContext(name)" method? Isn't that the point of the whole custom context selection mechanism? But on what grounds can I select a context if I can't pass a string (or anything else) to ".getContext()"? Thank you for your help in advance.

1 0

NoSuchProviderException for smtp when using JavaMail 1.5.x with logback 1.1.2 SMTPAppender in glassfish 4
by Ross Goldberg 23 Apr '14

23 Apr '14

I am attempting to use the SMTPAppender from logback 1.1.2 in glassfish 4 to send email alerts for all logged errors, whether they are logged by glassfish itself, by its various components / modules / libraries, or by my code in a deployed ear. At different times, I tried using either JavaMail 1.5.0 or 1.5.1; 1.5.0 because glassfish 4 includes JavaMail 1.5.0 in its modules directory. and I wanted to try to be consistent; and 1.5.1 because it is the current version of JavaMail. I have configured the SMTPAppender, but when it tries to log an error from code deployed in my ear, I get a NoSuchProviderException for smtp when logback SMTPAppenderBase calls Transport.send(MimeMessage). This seems to be a ClassLoader issue, but I'm not well versed in ClassLoaders, especially with their use in glassfish, JavaMail, or logback. In the ${GLASSFISH_HOME}/glassfish/domains/domain1/config directory, I have placed: logback.xml (my logback config file) As I read online somewhere (I forget where), I placed the following files in the ${GLASSFISH_HOME}/glassfish/lib/endorsed directory: logback-core-1.1.2.jar logback-classic-1.1.2.jar jul-to-slf4j-1.7.7.jar (to redirect glassfish's built-in java.util.logging to logback) slf4j-api-1.7.7.jar (the logging api used log to logback) guava-16.0.1.jar (used by my custom logback logging code) custom-logging.jar (my custom logback logging code) javax.mail-1.5.0.jar logback SMTPAppender configuration fails without including javax.mail-1.5.0.jar in lib/endorsed, or, alternately, mailapi-1.5.0.jar. Using javax.mail-api-1.5.0.jar instead results in numerous errors in logback configuration, so that is not an option. If I use mailapi-1.5.0.jar without smtp-1.5.0.jar instead of using javax.mail-1.5.0.jar, SMTPAppenderBase throws a NoSuchProviderException when attempting to email glassfish errors (these are not errors from my ear, but errors from outside my ear). If I use javax.mail-1.5.0.jar, SMTPAppenderBase emails glassfish errors perfectly fine. I have tried various permutations of included JavaMail & logback jars the WEB-INF/lib directory in the war in my ear, but I keep getting NoSuchProviderExceptions when attempting to email errors that where logged by code from my ear. The only other JavaMail-related jars that I've found are in the glassfish modules directory; I cannot remove them since (from what I've heard) they are an integral part of glassfish. If I run a simple test java main method outside of glassfish, with the aforementioned jars in the classpath, error emails are sent correctly, without any exceptions. Any help resolving this issue would be greatly appreciated. Thanks.

1 0

Lilith 0.9.44 has been released!
by Jörn Huxhorn 21 Apr '14

21 Apr '14

This release brings huge improvements to the usage of conditions. Take a look at "Focus" and "Exclude" in the popup and "Search" menu. Remember that you can save conditions using Cmd/Ctrl-I. Those will show up in the "Saved conditions" section of "Focus" and "Exclude". It will also most likely be the last Java 5 compatible version. Development will continue on Java 8. Changes: - The table of the view will now always receive the focus if the selected view changes. - Added alternative behavior for Focus/Exclude actions. By default, those actions are replacing the current views filter, if available, with the new combined filter. Hold shift to create a new view instead. - Status text is now properly updated in case of a replaced filter. - Renamed "Named" in the find combo to "Saved". - Renamed "Add condition..." to "Save condition..." and moved it from the "View" to the "Search" menu. Also added it to the popup menu. - Significantly enhanced tooltips of various condition-related components. They now show a pretty-printed string representation of the condition. - Enhanced "Focus" and "Exclude" popup menus. - Added corresponding "Focus" and "Exclude" menus to the "Search" menu. - Added two Substance look&feels to the mix. - Status text of main window is now properly updated on change of white/blacklisted list name. - Enhanced profiling output of TracingAspect. - Fixed of-by-one error in message renderer [+x lines]. Again. - servlet-api dependency of de.huxhorn.lilith.logback.servlet is now "provided". - Added "Paste StackTraceElement" (Cmd-shift V) which opens the respective source code in the IDE, if a proper plugin is installed. - ClassicLilithEncoder is now Encoder<ILoggingEvent> instead of Encoder<LoggingEvent>. - Fixed suppressed handling while parsing Throwables. This is also a partial workaround for LOGBACK-328. - Added fishing-for-compliments technology. - Groovy 2.2.2, Logback 1.1.2, SLF4J 1.7.7, Jackson 2.3.3, log4j2 2.0-beta9, rrd4j 2.2, aspectj 1.8.0, flying-saucer 9.0.4, Spring 4.0.2, macify 1.6, httpcore 4.3.2, httpclient 4.3.3, JCommander 1.35, servlet-api 3.0.1, jgoodies-looks 2.5.3, commons-lang3 3.3.2 Known Issues: - Lilith is built with log4j2 2.0-beta9 and won't work with log4j2 2.0-rc1. The reason for this is that SocketAppender isn't working properly in that version. See LOG4J2-542. - HTML tooltips are not working with the native Mac OS X menu bar so some tooltips, especially the nice condition tooltips, will look garbled. Use a different look&feel to circumvent this problem. Unfortunately, I can't do anything about it. - Flying Saucer related issues: - Selection in the HTML view is currently somewhat buggy, especially in case of scaled view. - The first line of the message in HTML view is not properly indented if it starts with whitespace. You can see this effect by examining the event created by LogPinupLargeRunnable (executed via "Log ASCII"). The HTML created is actually correct. - Jumping to anchors is currently not supported so the navigation in help and details view isn't as good as it could be. - Lilith may hang during startup while creating the preferences dialog. Just restart Lilith in that rare case. This is caused by Java bug #6995182 and I can't do anything about it. Sorry about it. It's a stupid Java-MediaTracker-ColorChooser-Bug with no workaround available. m( ----------------------------------------------------------------------------- bitcoin: 19UjvmrDJMBcGDYQoFcrjYPqLRFPSwznZn litecoin: LU6WM3nmGJy3N5PEE8yQwsAyenJs8dtbmV dogecoin: DJC1R683hfD4VSEDAJrvNpv6GsCg8ewvhm

1 0