July 2013 - logback-user - mailman3.qos.ch

RollingFileAppender overwriting old files
by Sean Rhea 23 Jul '13

23 Jul '13

All, I'm using RollingFileAppender under jetty, and it occasionally seems to overwrite the contents of log files it has rotated in the past. My logback configuration is attached. Also attached is a terminal session in which you can see that the first line of the rotated log files *usually* is from the right timeframe, but occasionally is from a completely different time. For example, the file named jetty/logs/app.2013-07-22-1000.log contains a log message from the 1300 hour. In those cases, the messages that were once in that log file have been overwritten. Also in that terminal session is the contents of /proc/xxx/fd for the jetty process, where you can see that the process is maintaining open file descriptors to past rotated files. That seems like a bug to me. I see this same behavior with both logback versions 0.9.28 and 1.0.13. I'm using jetty 7.3.1.v20110307. I would appreciate any pointers you could give to help me track this down. If it's just a simple misconfiguration on my part, I'd love to know that, too, of course. I've searched for past mentions of this behavior and haven't found one. Apologies if I overlooked any that exist. Thanks, Sean === Configuration === <configuration> <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>logs/nmr.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <fileNamePattern>logs/nmr.%d{yyyy-MM-dd-HH}00.log</fileNamePattern> <maxHistory>672</maxHistory> </rollingPolicy> <encoder> <pattern>%date [%thread] %-5level %msg%n</pattern> </encoder> </appender> <appender name="EMAIL" class="ch.qos.logback.classic.net.SMTPAppender"> <evaluator class="RateLimitingEvaluator" /> <smtpHost>localhost</smtpHost> <to>jetty-errors(a)company.com</to> <from>Jetty Errors <jetty-errors(a)company.com></from> <subject>%mdc{environment} %mdc{shard} error: %msg</subject> <layout class="ch.qos.logback.classic.PatternLayout"> <pattern>Date: %date%n{}Message: %msg%n{}Context: %mdc%n</pattern> </layout> <cyclicBufferTracker class="ch.qos.logback.core.spi.CyclicBufferTrackerImpl"> <bufferSize>1</bufferSize>  </cyclicBufferTracker> </appender> <root level="INFO"> <appender-ref ref="FILE" /> <appender-ref ref="EMAIL" /> </root> </configuration> === Notes from terminal session === user@host:/var/local/webapp$ head -1 jetty/logs/app.2013-07-22-* ==> jetty/logs/app.2013-07-22-0000.log <== 2013-07-22 00:00:06,253 [qtp28715691-220085] INFO ... ==> jetty/logs/app.2013-07-22-0100.log <== 2013-07-22 01:00:04,447 [qtp28715691-220283] INFO ... ==> jetty/logs/app.2013-07-22-0200.log <== 2013-07-22 10:00:04,406 [qtp28715691-221647] INFO ... ==> jetty/logs/app.2013-07-22-0300.log <== 2013-07-22 03:00:00,047 [qtp28715691-220456] INFO ... ==> jetty/logs/app.2013-07-22-0400.log <== 2013-07-22 04:00:00,621 [qtp28715691-220497] INFO ... ==> jetty/logs/app.2013-07-22-0500.log <== 2013-07-22 05:00:03,765 [qtp28715691-220332] INFO ... ==> jetty/logs/app.2013-07-22-0600.log <== 2013-07-22 06:00:02,535 [qtp28715691-220805] INFO ... ==> jetty/logs/app.2013-07-22-0700.log <== 2013-07-22 07:00:02,687 [qtp28715691-221141] INFO ... ==> jetty/logs/app.2013-07-22-0800.log <== 2013-07-22 08:00:00,891 [qtp28715691-220805] INFO ... ==> jetty/logs/app.2013-07-22-0900.log <== 2013-07-22 09:00:00,537 [qtp28715691-221493] INFO ... ==> jetty/logs/app.2013-07-22-1000.log <== 2013-07-22 13:00:00,000 [qtp28715691-222323] INFO ... ==> jetty/logs/app.2013-07-22-1100.log <== 2013-07-22 11:00:02,096 [qtp28715691-221933] INFO ... ==> jetty/logs/app.2013-07-22-1200.log <== 2013-07-22 12:00:00,054 [qtp28715691-222149] INFO ... ==> jetty/logs/app.2013-07-22-1300.log <== 2013-07-22 13:12:57,841 [qtp28715691-222370] INFO ... user@host:/var/local/webapp$ ps auxww | grep -v grep | grep jetty jetty 13570 2.8 1.3 1153892 870036 ? Sl May13 2832:30 /usr/bin/java -Xss1m -Xmx128m -Duser.timezone=America/Los_Angeles -Djetty.port=30800 -jar start.jar user@host:/var/local/webapp$ sudo ls -l /proc/13570/fd | grep 'app\.' l-wx------ 1 jetty jetty 64 Jul 22 14:03 102 -> /var/local/webapp/jetty/logs/app.log l-wx------ 1 jetty jetty 64 Jul 22 14:03 105 -> /var/local/webapp/jetty/logs/app.2013-06-12-1400.log (deleted) l-wx------ 1 jetty jetty 64 Jul 22 14:03 112 -> /var/local/webapp/jetty/logs/app.2013-06-26-1600.log l-wx------ 1 jetty jetty 64 Jul 22 14:03 118 -> /var/local/webapp/jetty/logs/app.2013-07-17-1600.log l-wx------ 1 jetty jetty 64 Jul 22 14:03 122 -> /var/local/webapp/jetty/logs/app.2013-06-11-1100.log (deleted) l-wx------ 1 jetty jetty 64 Jul 22 14:03 130 -> /var/local/webapp/jetty/logs/app.2013-07-22-0200.log l-wx------ 1 jetty jetty 64 Jul 22 14:03 144 -> /var/local/webapp/jetty/logs/app.2013-07-22-1000.log l-wx------ 1 jetty jetty 64 Jul 22 14:03 20 -> /var/local/webapp/jetty/logs/app.2013-07-15-1400.log l-wx------ 1 jetty jetty 64 Jul 22 14:03 4 -> /var/local/webapp/jetty/logs/app.2013-07-22-1300.log l-wx------ 1 jetty jetty 64 Jul 22 14:03 85 -> /var/local/webapp/jetty/logs/app.2013-07-10-1200.log l-wx------ 1 jetty jetty 64 Jul 22 14:03 99 -> /var/local/webapp/jetty/logs/app.2013-07-10-1000.log

2 1

AUTO: Manfred Kuhlmann is out of office. (Rückkehr am 07.08.2013)
by manfred.kuhlmann＠steria-mummert.de 22 Jul '13

22 Jul '13

Ich werde ab dem 20.07.2013 nicht im Büro sein. Ich kehre zurück am 07.08.2013. I will be out of the office starting 20.07.2013. I will be back on 07.08.2013. Ihre Nachricht werde ich nach meiner Rückkehr beantworten. Mit freundlichen Grüßen Manfred Kuhlmann Hinweis: Dies ist eine automatische Antwort auf Ihre Nachricht " [logback-user] RollingFileAppender overwriting old files" gesendet am 22.07.2013 23:23:59. Diese ist die einzige Benachrichtigung, die Sie empfangen werden, während diese Person abwesend ist. Steria Mummert Consulting AG Vorsitzender des Aufsichtsrates: François Enaud - Vorstand: Dr. Fritz Moser Gesellschaftssitz: Hamburg - HR B 61 116 Amtsgericht Hamburg - USt-ID-Nr.: DE118671351 Bitte denken Sie an Ihre Verantwortung gegenüber der Umwelt: Jede ausgedruckte E-Mail verursacht ca. 0,3 Gramm CO2 pro Seite. Diese Nachricht kann vertrauliche Informationen enthalten und ist allein für den Adressaten bestimmt. Wenn Sie nicht der rechtmäßige Empfänger sind, sind der Zugriff, die Weiterleitung, das Kopieren, die Veröffentlichung oder anderweitige Verwendung des Inhalts untersagt. In diesem Fall bitten wir Sie, den Absender unverzüglich zu informieren und diese E-Mail sowie sämtliche Kopien dieser E-Mail zu löschen. Der Inhalt von E-Mails innerhalb des Netzwerks kann überprüft werden, um die Übereinstimmung mit den geltenden Firmenrichtlinien und Vorgehensweisen zu gewährleisten. E-Mails können auf dem Transportweg von Dritten verändert werden, so dass deren Vollständigkeit und Echtheit nicht garantiert werden können. This e-mail communication may contain confidential information and is intended only for the recipient. If you are not the intended recipient you are not allowed to read, copy, distribute, publicize or use the content of this e-mail in any way. Please notify the sender and delete the e-mail and any copies of it. The content of e-mails within our network may be monitored to ensure compliance with company policies and procedures. E-mails can be alterated by third parties in transit. Therefore any e-mail is susceptible to alteration and its integrity cannot be assured.

1 0

Configure RollingFileAppender to keep a back up of Fifty log files in Logback
by Govardhana 18 Jul '13

18 Jul '13

Hi, I have used *RollingFileAppender *in logback Configuration file. My requirement is to keep 50 log files [ maxIndex ]as back up. Please give me some idea on this to fulfill my requirement. Example: myLog.log , myLog.log.1, ........ myLog.log.50 Regards, Reddy -- View this message in context: http://logback.10977.n7.nabble.com/Configure-RollingFileAppender-to-keep-a-… Sent from the Users mailing list archive at Nabble.com.

3 5

class name is displayed incorrectly for java inner classes
by Andrew E. Davidson 17 Jul '13

17 Jul '13

Hi I am using log back-1.0.13. Bellow is the output and sample java code I used to test log back with. noticed that I have an inner class how ever the log output always displays the class name as the outer class. Is there a way to set up log back so that it prints something like outer.inner ??? Also has anyone given any thought to defining an XSD file? This would allow my ice (eclipse) to catch a lot of configuration problems for me. I really appreciate all the hard work everyone has put into this project thanks in advance andy [SLF4JConsoleTest.java] [line 50] [thr main] [class SLF4JConsoleTest] [execute()] Test: INFO level message. [SLF4JConsoleTest.java] [line 53] [thr main] [class SLF4JConsoleTest] [execute()] Test: WARN level message. [SLF4JConsoleTest.java] [line 56] [thr main] [class SLF4JConsoleTest] [execute()] Test: ERROR level message. [SLF4JConsoleTest.java] [line 73] [thr main] [class SLF4JConsoleTest] [execute()] MyInnerClass: INFO level message. [SLF4JConsoleTest.java] [line 76] [thr main] [class SLF4JConsoleTest] [execute()] MyInnerClass: WARN level message. [SLF4JConsoleTest.java] [line 79] [thr main] [class SLF4JConsoleTest] [execute()] MyInnerClass: ERROR level message. <?xml version="1.0" encoding="UTF-8"?> <configuration>  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout">  <Pattern>[%15file] [line %4L] [thr %4t] [class %17c{0}] [%method] %m %n</Pattern> </layout> </appender> <root level="INFO"> <appender-ref ref="STDOUT" /> </root> </configuration> public class SLF4JConsoleTest { static final Logger LOG = LoggerFactory.getLogger(SLF4JConsoleTest.class); /** * @param args */ public static void main(String[] args) { SLF4JConsoleTest console = new SLF4JConsoleTest(); console.execute(); } public SLF4JConsoleTest() { } public void execute() { if (LOG.isTraceEnabled()) { LOG.trace("Test: TRACE level message."); } if (LOG.isDebugEnabled()) { LOG.debug("Test: DEBUG level message."); } if (LOG.isInfoEnabled()) { LOG.info("Test: INFO level message."); } if (LOG.isWarnEnabled()) { LOG.warn("Test: WARN level message."); } if (LOG.isErrorEnabled()) { LOG.error("Test: ERROR level message."); } MyInnerClass mic = new MyInnerClass(); mic.execute(); } public class MyInnerClass { public void execute() { if (LOG.isTraceEnabled()) { LOG.trace("MyInnerClass: TRACE level message."); } if (LOG.isDebugEnabled()) { LOG.debug("MyInnerClass: DEBUG level message."); } if (LOG.isInfoEnabled()) { LOG.info("MyInnerClass: INFO level message."); } if (LOG.isWarnEnabled()) { LOG.warn("MyInnerClass: WARN level message."); } if (LOG.isErrorEnabled()) { LOG.error("MyInnerClass: ERROR level message."); } } } }

2 7

Plugin execution not covered by lifecycle
by Leonardo Souza 17 Jul '13

17 Jul '13

How to deal with this? Do i have to configure m2e plugin? Description Resource Path Location Type Plugin execution not covered by lifecycle configuration: org.apache.felix:maven-bundle-plugin:2.1.0:manifest (execution: bundle-manifest, phase: process-classes) pom.xml /logback-access line 127 Maven Project Build Lifecycle Mapping Problem commit 72d76165ac3272d8e6d466e258de6449e89d30f3 Author: Ceki Gulcu <ceki(a)qos.ch> Date: Wed Jul 3 13:24:11 2013 +0200 document LOGBACK-617 fix, minor changes -- Leonardo S Souza Amtera Semantic Technologies Rua da Quitanda, 194, sala 1201 - Centro Rio de Janeiro - RJ - Brasil Tel: + 55 21 2213 3220 Cel: + 55 21 9877 7081 www.amtera.com.br

2 1

Re: [logback-user] class name is displayed incorrectly for java inner classes
by Stuart Rossiter 17 Jul '13

17 Jul '13

On 17 July 2013 09:23, David Roussel <nabble(a)diroussel.xsmail.com> wrote: > Andy, > > The name of the logger is set when the logger is created form the > LoggerFactory. You are creating LOG in your outer class. Try creating > another logger in your inner class. > Yes, it is slightly subtle that the loggers just have the name you pass to them: they don't 'know' the class structure of what's calling them, and we don't want them to since we might want our own arbitrary set of loggers where each covers some specific set of classes (say). Even though you are using the getLogger(Class clazz) form, it still just generates a logger name, which multiple classes could reuse if they wanted to (by passing that name in their Logger setup code). BTW (general question to the mailing list): this code suggests that the getLogger(Class clazz) form sets the logger name using the source file name (e.g., SLF4JConsoleTest.java here, cf. SLF4JConsoleTest). I've always used the getLogger(String name) form, passing SLF4JConsoleTest.class.getCanonicalName(), or getSimpleName() if I don't want the full name. (It might even be that I changed to that because of this ugly .java suffix, though I can't explicitly remember that.) Is there a reason for that? If it's to link to the file producing it (rather than the class), that doesn't seem very useful without a path. Apologies if this is stated somewhere obvious in the manual. Stuart -- ________________________________ Stuart Rossiter stuart.p.rossiter(a)gmail.com Research Fellow: EPSRC Care Life Cycle Project http://www.southampton.ac.uk/clc

2 4

Logback defaulting to debug mode for some third party libraries
by amit shah 16 Jul '13

16 Jul '13

We use slf4j and logback for logging in our java ee web application. Recently in order to move these libraries to a common location in the glassfish app server (to glassfish\lib directory specifically) we made a couple of configuration changes. We made changes in the web.xml file to add JNDI entries and renamed the logback.xml to logback-<context-name>.xml as specified in here <http://logback.qos.ch/manual/loggingSeparation.html>. The logback-<context-name>.xml is placed in WEB-INF\classes directory. After this change, logging for hibernate and http-client libraries is defaulting to debug mode and hence there is lot of logging being done. The root logger has INFO log level and there are no specific loggers defined for hibernate & http-client libraries. If I revert this change i.e. remove the jndi entry in web.xml and rename the configuration file to logback.xml, only INFO logs are logged as expected. Any suggestions on what could be the issue? Thanks, Amit.

2 2

Use multiple receivers to log multiple remote server appenders
by Chris Hamilton 15 Jul '13

15 Jul '13

I have multiple web servers configured in a cluster. I have set up a "server" appender on each instance of the application. I have used the Receiver example to create a program that will connect to the remote server appenders and log the messages received from each cluster member to a single remote file. The problem I have is identifying the source server in the remote remote log file. What I'm looking for is a way to identify the source server of each message. I have enhanced the SocketReceiver and added a field called ReceiverAlias which is set in logback.xml. Currently I am prepending this string to the log message. This works but doesn't look or feel right. I'm thinking that there ought to be a better way. Is there an established pattern for this use case? Thanks

1 0

Too much time for processing logback.xml
by Arioco 13 Jul '13

13 Jul '13

Hello. I have just discovered SLF4J and Logback and I am testing it in local before using it in my projects. I downloaded SLF4J 1.7.5 and Logback 1.0.13, created a new project in Eclipse with workspace in local, put slf4j-api-1.7.5.jar, logback-classic-1.0.13.jar and logback-core-1.0.13.jar in CLASSPATH and wrote a very simple test class: package com.compa.prueba.logging.slf4j; import org.slf4j.Logger; import org.slf4j.LoggerFactory; public class Pruebas { private final static Logger logger = LoggerFactory.getLogger(Pruebas.class); public static void main(String... args) { logger.info("let me see..."); logger.debug("\\{} {} {} {} {} {}", "1", 2, new Double(3), "4", "5"); } } Everything was just fine, execution time was almost nothing (of course) until I added a logback.xml file. Since then I got a 10 secs longer startup time. I found a post with a problem very similar to mine, but with no answer to me: http://logback.10977.n7.nabble.com/Elongated-system-startup-time-because-of… I have been doing a bunch of tests and I think problem is XML-processing-time, and I don't have a clue about why. Briefing: * Replace Logback with NOP: execution time 0.x milisecs * Delete logback.xml file from classpath: execution time 0.x milisecs * Adding debug="true" to configuration tag. Here is where I am now. My actual logback.xml file is: <?xml version="1.0" encoding="UTF-8"?> <configuration debug="true"> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %logger{36} - %msg%n</pattern> </encoder> </appender> <root level="debug"> <appender-ref ref="STDOUT" /> </root> </configuration> And after execution my console shows this: 12:55:41,819 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy] 12:55:41,819 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] *12:55:41,819* |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/Volumes/Macintosh%20HD/workspace/PruebaLogging/bin/logback.xml] *12:55:51,925* |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] 12:55:51,929 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT] 12:55:51,951 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property 12:55:51,998 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG 12:55:51,999 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT] 12:55:51,999 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. 12:55:52,001 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@4b9237a - Registering current configuration as safe fallback point 2013-07-13 12:55:52.005 INFO c.compa.prueba.logging.slf4j.Pruebas - let me see... 2013-07-13 12:55:52.008 DEBUG c.compa.prueba.logging.slf4j.Pruebas - {} 1 2 3.0 4 5 I highlighted two timestamps in log output just for pointing the 10 secs difference. A very curious fact is that delay is always 10 secs, no matter how many times I execute. I hope I have write information enough for you to help me. Thank you very much to all. Regards Carlos -- View this message in context: http://logback.10977.n7.nabble.com/Too-much-time-for-processing-logback-xml… Sent from the Users mailing list archive at Nabble.com.

1 0

Double logging in console
by sadiq81 12 Jul '13

12 Jul '13

Hey I have been trying like crazy to figure out what is going. All my console logs are coming out twice. Perhaps someone can tell me what idiot mistake i have made. <?xml version="1.0" encoding="UTF-8"?> <configuration debug="true"> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern> </encoder> </appender> <logger name="dk.eazyit.eazyregnskab" level="DEBUG"> <appender-ref ref="STDOUT"></appender-ref> </logger> <root level="WARN"> <appender-ref ref="STDOUT"/> </root> </configuration> -- View this message in context: http://logback.10977.n7.nabble.com/Double-logging-in-console-tp12662.html Sent from the Users mailing list archive at Nabble.com.

2 2