April 2016 - logback-user - mailman3.qos.ch

Logback => TLS/SSL => Syslog ?
by Otis Gospodnetić 21 Feb '19

21 Feb '19

Hi, Does Logback support sending logs to Syslog servers via TLS/SSL? I have a feeling Logback doesn't have a SyslogAppender that can send data using TLS. I say that because I don't see a mention of "syslog" on http://logback.qos.ch/manual/usingSSL.html and I see http://jira.qos.ch/browse/LOGBACK-890 that mentions TLSSyslogAppender, but it looks like this never ended up in Logback. I've only found it committed here: https://github.com/balabit/logback/commit/e0d89de2536e0925a6c816a50793f6a74… Could anyone please clarify? Thanks, Otis -- Monitoring * Alerting * Anomaly Detection * Centralized Log Management Solr & Elasticsearch Support * http://sematext.com/

2 1

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

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

Question about SizeAndTimeBasedRollingPolicy
by Simon.Erhardt＠befine-solutions.com 11 Apr '16

11 Apr '16

Hello all, I've got a question about the SizeAndTimeBasedRollingPolicy. What I would like to achieve is a guaranteed upper boundary for the disk space used by log files and archives. I was happy to find the related option "totalSizeCap" for SizeAndTimeBasedRollingPolicy which seemed to help, but it turns out that this cap is applied only to files older than the time-based rollover trigger (in my case, a new day). The same seems to be the case for "maxHistory", it doesn't constrain the count of files created on the current day. So it is possible that, in worst case, a lot of files are created and flush disk space. Are there any ideas how to solve that? I read about FixedWindowRollingPolicy, but I need day based rollover. Here's my non-working approach so far: <appender name="FILE_DEFAULT" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>events.log</file> <encoder><Pattern>${defaultPattern}</Pattern></encoder> <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> <fileNamePattern>events_%d{yyyy-MM-dd}_%i.zip</fileNamePattern> <maxFileSize>1MB</maxFileSize> <maxHistory>5</maxHistory> <totalSizeCap>10MB</totalSizeCap> </rollingPolicy> </appender> I'm looking forward to any responses. Have a nice weekend! Simon Erhardt Senior Software Architect Befine Solutions AG - The Cryptshare company

2 2

produce configuration file from current configuration?
by Norbert Kiesel 07 Apr '16

07 Apr '16

Hi, we finally switched from a home-grown logging system to slf4j/logback and are overall happy. However, the old solution (which was much more limited) offered a web GUI for setting the root log level. We could of course implement that using the logback API. However, this will of not be reflected in our logback.xml. I'm also worried that any other change in that file will simply reset the log level given that we use the `scanPeriod` option. Is there a way to convert a current logback configuration back into an XML (or Groovy) configuration file? </nk> --- Norbert Kiesel Systems Architect | Engineering MetricStream 2600 E. Bayshore Road | Palo Alto, CA - 94303 +1-650-620-2954 | nkiesel(a)metricstream.com | www.metricstream.com Confidentiality Notice:This email and any files transmitted with it are confidential and intended solely for the use of the individual or entity to whom they are addressed. This message contains confidential information and is intended only for the individual named. If you are not the named addressee you should not disseminate, distribute or copy this e-mail. Please notify the sender immediately by e-mail if you have received this e-mail by mistake and delete this e-mail from your system. If you are not the intended recipient you are notified that disclosing, copying, distributing or taking any action in reliance on the contents of this information is strictly prohibited

2 3

new version of logback-json-classic
by David Byron 05 Apr '16

05 Apr '16

I would love to use this change to JsonLayout to make it easier to add custom data: https://github.com/qos-ch/logback-contrib/commit/eedebdfa83f012d13a76cb0658…. It made it to master in November of 2014, but from what I can tell, no version of logback-json-classic has been released since then. Any chance I can help motivate releasing a new version? Thanks much. -DB

1 0