- logback-user - mailman3.qos.ch

log file splits in multiple tmp files
by Suraj Mundada 19 May '16

19 May '16

Hi, I have configured log appenders to separate logs based on functionality. It looks as below: Appender: <appender name="MOBILE_APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>${application.home}/logs/mobile.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">  <fileNamePattern>${application.home}/logs/mobile-log-%d{dd-MM-yyyy}.gz</fileNamePattern>  <maxHistory>7</maxHistory> </rollingPolicy> <encoder> <pattern>%date{dd-MM-yyyy HH:mm:ss} %message%n</pattern>  <immediateFlush>false</immediateFlush> </encoder> </appender> Logger: <logger name="mobile" level="DEBUG" additivity="false"> <appender-ref ref="MOBILE_APPENDER" /> </logger> Code: Logger.of("mobile").debug("log statement"); Same configuration works well for other appenders and loggers for different log files. In the case of mobile log file, it gets split into multiple tmp files as below mobile.log1069573507939492.tmp mobile.log1156778511668518.tmp mobile.log1420697709142498.tmp mobile.log1503633156746801.tmp mobile.log1674487680335483.tmp mobile.log1761638721293414.tmp mobile.log1932597676801911.tmp Because of this, it does not get compressed at every midnight as per log rolling policy. Any idea why it happens? Regards, Suraj

2 5

Change FixedWindowRollingPolicy rolling behaviour
by DK 15 May '16

15 May '16

Hi can I change FixedWindowRollingPolicy to rollover as follows: foo.log active log file foo1.log first rollover foo2.log second rollover foo3.log third rollover Current behaviour is second rollover. foo1.log is renamed as foo2.log. foo.log is renamed as foo1.log -- View this message in context: http://logback.10977.n7.nabble.com/Change-FixedWindowRollingPolicy-rolling-… Sent from the Users mailing list archive at Nabble.com.

2 3

RollingFileAppender dropping messages
by Alex Hall 13 May '16

13 May '16

Greetings, logback-users. We recently switched from log4j to logback, and have observed some concerning behavior with RollingFileAppender - namely, it seems to be dropping log messages in what turns out to be a predictable manner. I'm including a simple test program that I wrote to illustrate the issue. Basically, the output of the test program indicates that the RollingFileAppender is dropping messages 16, 32, 64, 128, and so on. Is this a known issue with RollingFileAppender? Is there some sort of error in our logback configuration? Any help is appreciated! Regards, Alex Hall ========== Operating system: Ubuntu 14.04 LTS Java version: Oracle JDK 1.8.0u72 Test program: /lib: + logback-classic-1.1.7.jar + logback-core-1.1.7.jar + slf4j-api-1.7.21.jar /resources/logback-test.xml: ---------- <configuration> <appender name="FILE" class="ch.qos.logback.core.FileAppender"> <file>logs/test.log</file> <encoder> <pattern>%d [%thread] %-5level %logger{36} - %msg%n</pattern> </encoder> </appender> <appender name="ROLLING-FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>logs/rolling-test.log</file> <encoder> <pattern>%d [%thread] %-5level %logger{36} - %msg%n</pattern> </encoder> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <fileNamePattern>logs/rolling-test-%d{yyyy-MM-dd}.%i.log</fileNamePattern> <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP" /> <maxHistory>30</maxHistory> <cleanHistoryOnStart>true</cleanHistoryOnStart> </rollingPolicy> </appender> <root level="INFO"> <appender-ref ref="FILE" /> <appender-ref ref="ROLLING-FILE" /> </root> </configuration> ---------- /src/RollingAppenderTest.java: ---------- import org.slf4j.Logger; import org.slf4j.LoggerFactory; public class RollingAppenderTest { private static final Logger log = LoggerFactory.getLogger(RollingAppenderTest.class); public static void main(String[] args) throws Exception { if (args.length != 1) { System.out.println("Usage: java RollingAppenderTest <num-messages>"); System.exit(1); } int nMessages = Integer.parseInt(args[0]); for (int i = 1; i <= nMessages; i++) { log.info("Hello, " + i); } } } ---------- /run-test.sh ---------- #!/bin/sh rm -rf logs rm -rf classes echo "Compiling..." mkdir classes javac -cp 'lib/*' -d classes -sourcepath src src/*.java echo "Running..." java -cp 'lib/*:classes:resources' RollingAppenderTest $1 echo "FileAppender output lines: $(wc -l logs/test.log)" echo "RollingFileAppender output lines: $(wc -l logs/rolling-test.log)" diff logs/test.log logs/rolling-test.log ---------- Test output: ---------- alex@alex-ubuntu14:~/src/scratch/logback-drops-messages$ ./run-test.sh 1000 Compiling... Running... FileAppender output lines: 1000 logs/test.log RollingFileAppender output lines: 994 logs/rolling-test.log 16d15 < 2016-05-05 14:40:14,365 [main] INFO RollingAppenderTest - Hello, 16 32d30 < 2016-05-05 14:40:14,366 [main] INFO RollingAppenderTest - Hello, 32 64d61 < 2016-05-05 14:40:14,380 [main] INFO RollingAppenderTest - Hello, 64 128d124 < 2016-05-05 14:40:14,383 [main] INFO RollingAppenderTest - Hello, 128 256d251 < 2016-05-05 14:40:14,405 [main] INFO RollingAppenderTest - Hello, 256 512d506 < 2016-05-05 14:40:14,439 [main] INFO RollingAppenderTest - Hello, 512 ----------

2 2

LoggerInitializationException - logger timing out in Play application
by Suraj Mundada 13 May '16

13 May '16

Hi, I am using Play 2.4.6 on CentOS 6 server with Java 8 for deploying production application. I am using logback logging in Akka actors for doing my async tasks and sending email is one the tasks. >From last 2 days, I am getting following exception: akka.ConfigurationException: Could not start logger due to [akka. ConfigurationException: Logger specified in config can't be loaded [akka.event.Logging$DefaultLogger] due to [akka.event.Logging$LoggerInitializationException: Logger log1-Logging$DefaultLogger did not respond with LoggerInitialized, sent instead [TIMEOUT]]] at akka.event.LoggingBus$class.startDefaultLoggers(Logging.scala:144) at akka.event.EventStream.startDefaultLoggers(EventStream.scala:26) at akka.actor.LocalActorRefProvider.init(ActorRefProvider.scala:623) at akka.actor.ActorSystemImpl.liftedTree2$1(ActorSystem.scala:620) at akka.actor.ActorSystemImpl._start$lzycompute(ActorSystem.scala:617) at akka.actor.ActorSystemImpl._start(ActorSystem.scala:617) at akka.actor.ActorSystemImpl.start(ActorSystem.scala:634) at akka.actor.ActorSystem$.apply(ActorSystem.scala:142) at akka.actor.ActorSystem$.apply(ActorSystem.scala:109) at akka.actor.ActorSystem$.create(ActorSystem.scala:57) at akka.actor.ActorSystem.create(ActorSystem.scala) at manager.EmailManager.sendHtmlEmail(EmailManager.java:63) at My application.conf has below entry: akka { loggers = ["akka.event.slf4j.Slf4jLogger"] loglevel = "DEBUG" logging-filter = "akka.event.slf4j.Slf4jLoggingFilter" event-handlers = ["akka.event.slf4j.Slf4jEventHandler"] default-dispatcher { fork-join-executor { parallelism-min = 8 } } } logback.xml has following entries apart from other appender and logger declarations: <logger name="play" level="INFO" /> <logger name="application" level="DEBUG" /> <logger name="akka" level="INFO" /> However, I do not use akka logger reference defined above anywhere in my code. Instead, I use default logger configuration where timeout is happening: Logger.debug("EmailActor - onReceive() : MultiPartEmail message to xyz(a)abc.com"); Each time timeout happens, I have to restart my play application. Is it hardware issue which is restricting threads available for creating new actor instances or causing timeout for logger? or something else? My production box is 1 Core 4 GB with CentOS 6 and play application runs within a docker on this box. Regards, Suraj

2 1

Re: [logback-user] Logback becomes excruciatingly slow during rollover
by Vesuvius Prime 11 May '16

11 May '16

Hi, Thank you for the suggestion. This was the first thing I had suggested to the customer during the live session with them but then they said they didn't want to be a "testbed" for us, so they didn't do it. Now I asked our support guys to ask the customer again to do this and this time the customer agreed. After waiting a while for the logs to roll over, here's the feedback: "Hello, Customer just provided an update. Log file is not rolling over, however it has grown to over 90mb, but the [product] has not slowed down." So, there's an improvement -- at least now we're not becoming unusable due to excessive slowness. However, the log grows without a limit. The bottom line is that this is an improvement, but not a solution. I would still love somebody with deep knowledge of Logback (presumably its authors) to provide some feedback here. For example, if this is a known problem and it has been solved in some version of Logback, we may go ahead an modify the Virgo server to use that version. Alternatively, if Logback is unreliable, we may have to switch to some other logging framework. I've been seeing various reports about rollover problems, even in this mail list. We can't afford to lose customers due to logging. Besides, this creates a really bad image to Logback itself. Thank you for reading this. ________________________________________ Date: Thu, 28 Apr 2016 09:26:32 -0400 From: Chris Hamilton <chamilton-dev(a)compucafe.com> To: logback users list <logback-user(a)qos.ch> Subject: Re: [logback-user] Logback becomes excruciatingly slow during rollover Message-ID: <D1E6C509-E709-45E4-8381-D9751F4E477B(a)compucafe.com> Content-Type: text/plain; charset="windows-1252" I notice that you have defined the files to be rolled with a .zip extension. We am using Logback 1.0.13 in my project and experienced issues with log rolling causing the JVM effectively halt while the rolled log file is compressed (we were using GZ). It appears that the rolling of the log is protected by a synchronous lock (makes since) and the compression routine is being called within that lock (not good). My only evidence of this is empirical because as I said everything else just stopped. We resolved the problem by simply not using compression in the logback configuration. This was done by removing the gz extension (.zip in your case) in the FileNamePattern tag. We then wrote a cron job to find all the uncompressed log files and compress them. This moves the compression of old log files from your application’s process to another [cron initiated] process that is not (as) mission critical. You might want to give this a try... > On Apr 26, 2016, at 3:13 PM, Vesuvius Prime <vesuvius_prime(a)hotmail.com> wrote: > > An update: > > The customer disabled Splunk and are still reproducing the problem. They also report that Process Explorer indicates that no other process holds a handle to the log files. > > > From: Vesuvius Prime <vesuvius_prime(a)hotmail.com> > Sent: Sunday, April 24, 2016 6:57 PM > To: logback-user(a)qos.ch > Subject: Logback becomes excruciatingly slow during rollover > > Hi all, > > We use Virgo server and it comes with Logback 1.0.7.v20121108-1250. One of the users of our product started complaining that after about a week of using our product, it was becoming so slow that it was basically unusable. We had a live session with the client and it turned out that the problem was in Logback. The client uses Windows. So far the problem has not been reported on Linux. Here's what I did to determine that Logback was the cause of the problem: > > 1. The appender is defined as: > > <appender name="LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> > <file>D:/logs/product.log</file> > <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy"> > <FileNamePattern>D:/logs/product_%i.log.zip</FileNamePattern> > <MinIndex>0</MinIndex> > <MaxIndex>9</MaxIndex> > </rollingPolicy> > <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy"> > <MaxFileSize>50MB</MaxFileSize> > </triggeringPolicy> > <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> > <Pattern>[%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX}] [%-5level] %-28.28thread %X{sessionGuid} %-64.64logger{64} %X{medic.eventCode} %msg %ex%n</Pattern> > </encoder> > </appender> > > In the appender configuration above, I modified the directories and log names a little bit, so that the actual product name would not be visible. > > 2. All the rolled-over zip files were generated and present, and the main log file, product.log, had exceeded its maximum size of 50 MB and had reached 64 MB. We had something like: > > product.log <------- 64 MB > product_0.log.zip > product_1.log.zip > product_2.log.zip > product_3.log.zip > product_4.log.zip > product_5.log.zip > product_6.log.zip > product_7.log.zip > product_8.log.zip > product_9.log.zip > > 3. This was suspicious, so I examined the log file and saw many messages that were logged out of order, e.g. > > 09:55:43.676 > 09:55:42.836 > 09:55:46.165 > 09:55:44.583 > ... > > Furthermore, even the simplest operations, e.g. simply sending a redirect response back to the browser, was taking several seconds. (However, before sending the redirect, we were logging the URL to which we were redirecting, so I suspected that the logger was extremely slow.) > > 3. I moved the archived log files to a different directory and they got recreated *immediately*. I did this 7-8 times, each time with exactly the same result -- the .zip files got recreated immediately. > > 4. The main log, product.log, was locked by the JVM, so I couldn't move it or delete it. However, I opened it with a text editor, selected the whole content (Ctrl+A), deleted it (Del) and saved the file. As soon as I did that, the performance problems disappeared. The product began working normally. Also, the log file started growing with normal speed. Previously, it was growing super-slowly. > > > So, we told the users to do the following workaround when the preconditions from step 2 above were reached and the product became very slow: > > (1) Open the main log file, select all, delete, save. > (2) Delete all archived .zip files > > This workaround has been working fine so far. However, we still don't know why Logback behaves like this. That's why I'm writing this email. Can someone, who knows the Logback source code, figure out what might be happening and what triggers it? > > Here are some additional details that we've been able to figure out: > > 1. When the users were experiencing the problem during the live session with them, I opened ProcessExplorer and saw that Splunk was holding a lock onto the main log file -- product log. I asked the users to kill the Splunk service and they did, but that didn't solve the problem. However, depending on the way Logback is written, it may turn out that it indeed went crazy because of Splunk, but *after* it goes crazy, killing the other process that hold a lock on the file doesn't help. > > 2. We managed to reproduce the same behavior in our company by letting two different appenders write to the same log file. Then, as soon as the preconditions on step 2 above were reached, everything became extremely slow, the logs couldn't roll over and the main log started growing beyond its specified limit of 50 MB. However, the users do *not* have such a configuration in which two appenders write to the same file. I'm only giving you information on how we managed to reproduce the slowness in case it might help you figure out what's wrong. The end result is the same -- Logback slows down to a crawl, but apparently the trigger in our users' environment is different and it's not related to appenders writing to the same file. > > 3. A thread dump while we were reproducing the problem (with two appenders writing to the same file) reveals the following: > > 3.1. One thread holds a lock (0x00000000dfa5d600): > > "Thread-48" #199 daemon prio=5 os_prio=0 tid=0x0000000024b61000 nid=0x772c runnable [0x000000002422e000] > java.lang.Thread.State: RUNNABLE > at java.util.zip.Deflater.deflateBytes(Native Method) > at java.util.zip.Deflater.deflate(Deflater.java:442) > - locked <0x00000000fdb8dcf0> (a java.util.zip.ZStreamRef) > at java.util.zip.Deflater.deflate(Deflater.java:364) > at java.util.zip.DeflaterOutputStream.deflate(DeflaterOutputStream.java:251) > at java.util.zip.DeflaterOutputStream.write(DeflaterOutputStream.java:211) > at java.util.zip.ZipOutputStream.write(ZipOutputStream.java:331) > - locked <0x00000000fdb8da00> (a java.util.zip.ZipOutputStream) > at ch.qos.logback.core.rolling.helper.Compressor.zipCompress(Compressor.java:110) > at ch.qos.logback.core.rolling.helper.Compressor.compress(Compressor.java:58) > at ch.qos.logback.core.rolling.FixedWindowRollingPolicy.rollover(FixedWindowRollingPolicy.java:147) > at ch.qos.logback.core.rolling.RollingFileAppender.rollover(RollingFileAppender.java:111) > - locked <0x00000000dfa5d460> (a ch.qos.logback.core.spi.LogbackLock) > at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:144) > - locked <0x00000000dfa5d600> (a ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy) > 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:280) > at ch.qos.logback.classic.Logger.callAppenders(Logger.java:267) > at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:449) > at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:403) > at ch.qos.logback.classic.Logger.log(Logger.java:803) > at org.apache.commons.logging.impl.SLF4JLocationAwareLog.warn(SLF4JLocationAwareLog.java:185) > ... > > 3.2. A multitude of threads are blocked and waiting to acquire that lock, e.g.: > > "Thread-55" #206 daemon prio=5 os_prio=0 tid=0x000000001f50d000 nid=0x7288 waiting for monitor entry [0x00000000263ef000] > java.lang.Thread.State: BLOCKED (on object monitor) > at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:142) > - waiting to lock <0x00000000dfa5d600> (a ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy) > 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:280) > at ch.qos.logback.classic.Logger.callAppenders(Logger.java:267) > at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:449) > at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:403) > at ch.qos.logback.classic.Logger.log(Logger.java:803) > at org.apache.commons.logging.impl.SLF4JLocationAwareLog.warn(SLF4JLocationAwareLog.java:185) > ... > > > > I have attached the logging configuration from the Virgo server. It's called serviceability.xml. (That's the default configuration file name for the Virgo server.) > > I'm sorry the mail turned out so long. I hope this will not discourage you from reading it. I will be extremely grateful if you, guys, can help us figure out what makes Logback go crazy. > _______________________________________________ > logback-user mailing list > logback-user(a)qos.ch > http://mailman.qos.ch/mailman/listinfo/logback-user

2 1

not logging every message even with discardingThreshold set to 0
by Marcus Chen 06 May '16

06 May '16

Hi, We have a SpringBoot app that uses Logback. It uses Async appender and configured as this: <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender"> <queueSize>10000</queueSize> <discardingThreshold>0</discardingThreshold> <appender-ref ref="FILE" /> </appender> <root level="INFO"> <appender-ref ref="ASYNC" /> </root> The app (single instance) is configured to have up to 200 Jetty threads. Throughput is around 50 POSTs/sec. I find there are 2-4 minute gaps in messages logged after 30 minutes. The gaps appear every 20 to 30 minutes. Am I missing additional configurations? Also is Async appender the best way to go if logging fidelity is of high importance? If not what is the best configuration so not to lose any messages. Thanks in advance. ________________________________________________________ MARCUS CHEN - Senior Developer, AWS Certified Developer Associate marcus.chen(a)dev9.com<mailto:marcus.chen@dev9.com> <mailto:marcus.chen@dev9.com> | dev9.com Custom Software. Continuous Delivery.

2 1

Logback becomes excruciatingly slow during rollover
by Vesuvius Prime 28 Apr '16

28 Apr '16

Hi all, We use Virgo server and it comes with Logback 1.0.7.v20121108-1250. One of the users of our product started complaining that after about a week of using our product, it was becoming so slow that it was basically unusable. We had a live session with the client and it turned out that the problem was in Logback. The client uses Windows. So far the problem has not been reported on Linux. Here's what I did to determine that Logback was the cause of the problem: 1. The appender is defined as: <appender name="LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>D:/logs/product.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy"> <FileNamePattern>D:/logs/product_%i.log.zip</FileNamePattern> <MinIndex>0</MinIndex> <MaxIndex>9</MaxIndex> </rollingPolicy> <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy"> <MaxFileSize>50MB</MaxFileSize> </triggeringPolicy> <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> <Pattern>[%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX}] [%-5level] %-28.28thread %X{sessionGuid} %-64.64logger{64} %X{medic.eventCode} %msg %ex%n</Pattern> </encoder> </appender> In the appender configuration above, I modified the directories and log names a little bit, so that the actual product name would not be visible. 2. All the rolled-over zip files were generated and present, and the main log file, product.log, had exceeded its maximum size of 50 MB and had reached 64 MB. We had something like: product.log <------- 64 MB product_0.log.zip product_1.log.zip product_2.log.zip product_3.log.zip product_4.log.zip product_5.log.zip product_6.log.zip product_7.log.zip product_8.log.zip product_9.log.zip 3. This was suspicious, so I examined the log file and saw many messages that were logged out of order, e.g. 09:55:43.676 09:55:42.836 09:55:46.165 09:55:44.583 ... Furthermore, even the simplest operations, e.g. simply sending a redirect response back to the browser, was taking several seconds. (However, before sending the redirect, we were logging the URL to which we were redirecting, so I suspected that the logger was extremely slow.) 3. I moved the archived log files to a different directory and they got recreated *immediately*. I did this 7-8 times, each time with exactly the same result -- the .zip files got recreated immediately. 4. The main log, product.log, was locked by the JVM, so I couldn't move it or delete it. However, I opened it with a text editor, selected the whole content (Ctrl+A), deleted it (Del) and saved the file. As soon as I did that, the performance problems disappeared. The product began working normally. Also, the log file started growing with normal speed. Previously, it was growing super-slowly. So, we told the users to do the following workaround when the preconditions from step 2 above were reached and the product became very slow: (1) Open the main log file, select all, delete, save. (2) Delete all archived .zip files This workaround has been working fine so far. However, we still don't know why Logback behaves like this. That's why I'm writing this email. Can someone, who knows the Logback source code, figure out what might be happening and what triggers it? Here are some additional details that we've been able to figure out: 1. When the users were experiencing the problem during the live session with them, I opened ProcessExplorer and saw that Splunk was holding a lock onto the main log file -- product log. I asked the users to kill the Splunk service and they did, but that didn't solve the problem. However, depending on the way Logback is written, it may turn out that it indeed went crazy because of Splunk, but *after* it goes crazy, killing the other process that hold a lock on the file doesn't help. 2. We managed to reproduce the same behavior in our company by letting two different appenders write to the same log file. Then, as soon as the preconditions on step 2 above were reached, everything became extremely slow, the logs couldn't roll over and the main log started growing beyond its specified limit of 50 MB. However, the users do *not* have such a configuration in which two appenders write to the same file. I'm only giving you information on how we managed to reproduce the slowness in case it might help you figure out what's wrong. The end result is the same -- Logback slows down to a crawl, but apparently the trigger in our users' environment is different and it's not related to appenders writing to the same file. 3. A thread dump while we were reproducing the problem (with two appenders writing to the same file) reveals the following: 3.1. One thread holds a lock (0x00000000dfa5d600): "Thread-48" #199 daemon prio=5 os_prio=0 tid=0x0000000024b61000 nid=0x772c runnable [0x000000002422e000] java.lang.Thread.State: RUNNABLE at java.util.zip.Deflater.deflateBytes(Native Method) at java.util.zip.Deflater.deflate(Deflater.java:442) - locked <0x00000000fdb8dcf0> (a java.util.zip.ZStreamRef) at java.util.zip.Deflater.deflate(Deflater.java:364) at java.util.zip.DeflaterOutputStream.deflate(DeflaterOutputStream.java:251) at java.util.zip.DeflaterOutputStream.write(DeflaterOutputStream.java:211) at java.util.zip.ZipOutputStream.write(ZipOutputStream.java:331) - locked <0x00000000fdb8da00> (a java.util.zip.ZipOutputStream) at ch.qos.logback.core.rolling.helper.Compressor.zipCompress(Compressor.java:110) at ch.qos.logback.core.rolling.helper.Compressor.compress(Compressor.java:58) at ch.qos.logback.core.rolling.FixedWindowRollingPolicy.rollover(FixedWindowRollingPolicy.java:147) at ch.qos.logback.core.rolling.RollingFileAppender.rollover(RollingFileAppender.java:111) - locked <0x00000000dfa5d460> (a ch.qos.logback.core.spi.LogbackLock) at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:144) - locked <0x00000000dfa5d600> (a ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy) 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:280) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:267) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:449) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:403) at ch.qos.logback.classic.Logger.log(Logger.java:803) at org.apache.commons.logging.impl.SLF4JLocationAwareLog.warn(SLF4JLocationAwareLog.java:185) ... 3.2. A multitude of threads are blocked and waiting to acquire that lock, e.g.: "Thread-55" #206 daemon prio=5 os_prio=0 tid=0x000000001f50d000 nid=0x7288 waiting for monitor entry [0x00000000263ef000] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:142) - waiting to lock <0x00000000dfa5d600> (a ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy) 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:280) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:267) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:449) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:403) at ch.qos.logback.classic.Logger.log(Logger.java:803) at org.apache.commons.logging.impl.SLF4JLocationAwareLog.warn(SLF4JLocationAwareLog.java:185) ... I have attached the logging configuration from the Virgo server. It's called serviceability.xml. (That's the default configuration file name for the Virgo server.) I'm sorry the mail turned out so long. I hope this will not discourage you from reading it. I will be extremely grateful if you, guys, can help us figure out what makes Logback go crazy.

2 2

Migrating from Log4j
by Ligaya Cornelio 22 Apr '16

22 Apr '16

Hi, Could you please help me on migrating from log4j to logback. I am using a layout and appender. What I was trying to do is create a different log file for each thread. I really appreciate any help from anyone. Thank you so much in advance. Below is my codes: Log4j version of the layout: package com.selenium.reporting; import java.io.*; import java.nio.file.Paths; import java.text.SimpleDateFormat; import java.util.Date; import java.util.concurrent.ConcurrentHashMap; import org.apache.log4j.Level; import org.apache.log4j.Logger; import org.apache.log4j.PatternLayout; import org.apache.log4j.spi.LoggingEvent; import org.apache.log4j.spi.ThrowableInformation; import org.apache.commons.lang3.StringEscapeUtils; public class ReportNGTestLayout extends PatternLayout { public ConcurrentHashMap<String, String> threadTestName = new ConcurrentHashMap<String, String>(); public int consoleLevel = Level.DEBUG_INT; public String reportParentFolder = "test-output"; public String executionDate; @Override public String format(LoggingEvent event) { String logline = ""; String logFileName; String logPrefix; String consolePrefix; // Get test name by thread id String testName = threadTestName.get(Long.toString(Thread.currentThread().getId())); String curThreadName = Thread.currentThread().getName(); if (testName == null) { // log to a file by thread name, if no test name consolePrefix = logPrefix = " " + curThreadName + " : "; logFileName = Paths.get(reportParentFolder, "main.log").toString(); } else { // log to <test name>.log file logFileName = Paths.get(reportParentFolder, "DetailReport", "Attachments", testName + ".log").toString(); logPrefix = " : "; if (!curThreadName.contains("pool") && !curThreadName.equalsIgnoreCase("TestNG")) logPrefix = logPrefix + "[" + curThreadName + "] "; consolePrefix = testName + logPrefix; } // Console output if (event.getLevel().toInt() >= consoleLevel) { if (event.getLevel().toInt() > consoleLevel) consolePrefix += event.getLevel() + " : "; String consoleMessage = new SimpleDateFormat("HH:mm:ss.SSS ").format(new Date(event.timeStamp)) + consolePrefix + event.getMessage(); if (event.getLevel().toInt() >= Level.INFO_INT) consoleMessage = "\n" + consoleMessage; System.out.println(consoleMessage); } if (!reportParentFolder.isEmpty()){ // Create log file if needed File logFile = new File(logFileName); if (!logFile.exists()){ try { File parentFolder = new File(logFile.getParent()); parentFolder.mkdirs(); logFile.createNewFile(); } catch (IOException e) { // TODO Auto-generated catch block e.printStackTrace(); } } // Append to log file try(PrintWriter out = new PrintWriter(new BufferedWriter(new FileWriter(logFile, true)))) { out.println(new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS") .format(new Date(event.timeStamp)) + " [" + event.getLevel() + "]" + logPrefix + event.getMessage()); } catch (IOException e) { e.printStackTrace(); } } // Append to old report if INFO message if (event.getLevel().toInt() == Level.INFO_INT) { String newMsg = StringEscapeUtils.escapeHtml3(event.getMessage() .toString()); Throwable t = null; ThrowableInformation ti = event.getThrowableInformation(); if (ti != null) { t = ti.getThrowable(); } LoggingEvent encodedEvent = new LoggingEvent( event.fqnOfCategoryClass, Logger.getLogger(event .getLoggerName()), event.timeStamp, event.getLevel(), newMsg, t); String baseFmt = super.format(encodedEvent).replace("@{{", "<") .replace("@}}", ">"); logline = "<div class=step" + "event.level.toString()" + ">" + baseFmt + "</div><br/>"; } return logline; } } Logback version of the layout: It is the same as the Log4j version but the only difference is I am extending ch.qos.logback.classic.PatternLayout and I use ILoggingEvent in the format instead of LoggingEvent. //@Override public String format(ILoggingEvent event) { Log4j version of the appender: package com.selenium.reporting; import org.apache.log4j.AppenderSkeleton; import org.apache.log4j.spi.LoggingEvent; import org.testng.Reporter; public class TestNGAppender extends AppenderSkeleton { public TestNGAppender(String name) { super(); setName(name); } @Override protected void append(LoggingEvent event) { String logMessage = layout.format(event); if (!logMessage.isEmpty()) { Reporter.log(logMessage); String[] thorwableCrap = event.getThrowableStrRep(); if (thorwableCrap != null) { Reporter.log(thorwableCrap.toString()); } } } @Override public void close() { } @Override public boolean requiresLayout() { return true; } } Logback version of the appender: package com.selenium.reporting; import org.testng.Reporter; import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.core.AppenderBase; public class TestNGAppender extends AppenderBase<ILoggingEvent> { public TestNGAppender(String name) { super(); setName(name); } //@Override protected void append(ILoggingEvent event) { String logMessage = this.layout.format(event); ===> in here layout cannot be resolved. How can I access the format method in the ReportNGTestLayout class? if (!logMessage.isEmpty()) { Reporter.log(logMessage); } } @Override public void stop() { } /* @Override public boolean requiresLayout() { return true; }*/ } This is how I setup the appender and layout in the logger: Logger rootLogger = (Logger)LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); TestNGAppender testNGAppender = new TestNGAppender("TestNG"); ReportNGTestLayout logLayout = new ReportNGTestLayout(); logLayout.executionDate = new SimpleDateFormat("MM-dd-yyyy-HH-mm").format(new Date()); logLayout.reportParentFolder = Paths.get(System.getProperty("reportRootPath"), logLayout.executionDate).toString(); logLayout.consoleLevel = Level.toLevel(logLevel.toUpperCase(), Level.DEBUG).toInt(); testNGAppender.setLayout(logLayout); ==> I am also having an error on this line. The method setLayout(ReportNGTestLayout) is undefined for the type TestNGAppender testNGAppender.start(); rootLogger.addAppender(testNGAppender); logger.debug("Log4j appender configuration is successful !!"); ---------------------------- This message (including any attachments) contains confidential information intended for a specific individual and purpose, and is protected by law. If you are not the intended recipient of this e-mail (even if the e-mail address above is yours), (i) you may not use, copy or retransmit it, (ii) please delete this message and (iii) please notify the sender immediately. Any disclosure, copying, or distribution of this message or the taking of any action based on it, is strictly prohibited. ---------------------------- ---------------------------- This message (including any attachments) contains confidential information intended for a specific individual and purpose, and is protected by law. If you are not the intended recipient of this e-mail (even if the e-mail address above is yours), (i) you may not use, copy or retransmit it, (ii) please delete this message and (iii) please notify the sender immediately. Any disclosure, copying, or distribution of this message or the taking of any action based on it, is strictly prohibited. ----------------------------

1 0

The utf-8 encode setting doesn't take effect if no unicode log at beginning of application
by Cheng Bao 22 Apr '16

22 Apr '16

Hello, I am using slf4j with logback as backend log solution. When I trying to make the log file support Unicode, I add <encoder><charset>UTF-8</charset><encoder> to logback.xml, However I find problems. My slf4j-api version 1.7.20 Logback-classic and logback-core: 1.1.7 Code: package cbao.cmdtests; import org.slf4j.Logger; import org.slf4j.LoggerFactory; /** * @author cbao * */ public class LogTests { /** * @param args * @throws InterruptedException */ public static void main(String[] args) throws InterruptedException { Logger logger = LoggerFactory.getLogger("LogTests"); for (int i = 0; i < 5000; i++) { logger.info("This is ANSI text"); Thread.sleep(0); } logger.info("This is unicode text: 中文"); } } Logback.xml: <?xml version="1.0" encoding="UTF-8"?> <configuration scan="true"> <appender name="consoleAppender" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <charset>UTF-8</charset> <Pattern>%d %-4relative [%thread] %-5level %logger{35} - %msg%n</Pattern> </encoder> </appender> <appender name="FILE" class="ch.qos.logback.core.FileAppender"> <file>logs/application.log</file> <encoder> <charset>UTF-8</charset> <pattern>%d %-4relative [%thread] %-5level %logger{35} - %msg%n</pattern> <immediateFlush>true</immediateFlush> </encoder> </appender> <root level="DEBUG"> <appender-ref ref="consoleAppender" /> <appender-ref ref="FILE"/> </root> </configuration> After running above code, the log file format is 1252 (ANSI – Latin I) The end of log file: 2016-04-21 17:00:12,666 151328 [main] INFO LogTests - This is ANSI text 2016-04-21 17:00:12,717 151379 [main] INFO LogTests - This is ANSI text 2016-04-21 17:00:12,767 151429 [main] INFO LogTests - This is ANSI text 2016-04-21 17:00:12,817 151479 [main] INFO LogTests - This is ANSI text 2016-04-21 17:00:12,867 151529 [main] INFO LogTests - This is ANSI text 2016-04-21 17:00:12,918 151580 [main] INFO LogTests - This is ANSI text 2016-04-21 17:00:12,968 151630 [main] INFO LogTests - This is ANSI text 2016-04-21 17:00:13,019 151681 [main] INFO LogTests - This is ANSI text 2016-04-21 17:00:13,070 151732 [main] INFO LogTests - This is ANSI text 2016-04-21 17:00:13,120 151782 [main] INFO LogTests - This is ANSI text 2016-04-21 17:00:13,171 151833 [main] INFO LogTests - This is ANSI text 2016-04-21 17:00:13,222 151884 [main] INFO LogTests - This is ANSI text 2016-04-21 17:00:13,273 151935 [main] INFO LogTests - This is unicode text: ä¸æ–‡ As my test, if there is no unicode log, the newly created log file will be 1252 (ANSI – Latin I). As soon as first unicode string logged, the log file changed (unicode: UTF-8). However, if there are significant ansi text before first unicode text could be logged, the log file will stay as ANSI even after utf-8 logged, then the unicode log can’t be display correctly. Is there any switches in logback.xml can fix it? Thanks Cheng Bao

1 0

Logback Lock causing the app to lock up
by Greg Nitro 13 Apr '16

13 Apr '16

Hi, We are using Logback 1.1.3, and observed through jstack that quite a few threads were blocked in OutputStreamAppender.subAppend waiting to obtain the lock. This is a Play Framework app running in a dockerized environment, configured to log to STDOUT and papertrail. Stack trace: "New I/O worker #23" #75 prio=5 os_prio=0 tid=0x00007f6fc9764000 nid=0xaa waiting for monitor entry [0x00007f6edd3e7000] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:211) - waiting to lock <0x00000000ab0f8f50> (a ch.qos.logback.core.spi.LogbackLock) 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:600) at play.api.LoggerLike$class.info(Logger.scala:93) at play.api.Logger$.info(Logger.scala:167) Any suggestions on what may be going on here? Thanks -greg

2 3