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

Logback Useful Appenders Project
by Robert Elliot 15 Apr '11

15 Apr '11

Just a heads up on some code that might be useful to people: https://github.com/Mahoney/lidalia-logging It's a couple of appenders I've found useful - basically a model for decorating other appenders (by extending DecoratingAppender) together with a couple of examples, one that cleanses Groovy stack traces so you don't get all the useless frames and one that makes any appender asynchronous with a configurable number of threads used. There's an example logback.xml showing how to use them: https://github.com/Mahoney/lidalia-logging/blob/master/src/main/resources/l… At some point I might try and release this as a library via Maven, but in the meantime if anyone finds them useful go ahead, and Ceki if you fancy them for Logback. Equally if anyone has any pointers (e.g. have I reinvented the wheel?) do let me know. Rob

2 1

logback 0.9.28 is noisy
by David Roussel 14 Apr '11

14 Apr '11

Hi, I've done a trial upgrade to 0.9.28 and I get alot more noise to stdout than I used to get. I've seen that the 'ERROR' below is a bug that will be fixed in the next release. But is all the other stuff just being output because of the error? Will it go away once the ERRROR goes away? Thanks David 16:27:45,613 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [com/example/gcm/pricing/batchpricer/logback.xml] at [jar:file:/D:/maven-lo cal-repository/com/example/gcm/pricing-controller/4.1.3-SNAPSHOT/pricing-controller-4.1.3-SNAPSHOT.jar!/com/example/gcm/pricing/batchpricer/logback.xml] 16:27:45,753 |-ERROR in ch.qos.logback.core.joran.spi.ConfigurationWatchList@e61a35 - URL [jar:file:/D:/maven-local-repository/com/example/gcm/pricing-controller /4.1.3-SNAPSHOT/pricing-controller-4.1.3-SNAPSHOT.jar!/com/example/gcm/pricing/batchpricer/logback.xml] is not of type file 16:27:46,597 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set 16:27:47,269 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.example.gcm] to INFO 16:27:47,269 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.example.gcm.launcher] to INFO 16:27:47,269 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.example.gcm.pricing.params.impl] to INFO 16:27:47,269 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.example.sky.service.DataSynapseClient] to INFO 16:27:47,269 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [httpclient] to WARN 16:27:47,269 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache] to WARN 16:27:47,269 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate] to WARN 16:27:47,269 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.cfg.AnnotationBinder] to WARN 16:27:47,269 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.cfg.annotations] to WARN 16:27:47,269 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.quartz] to WARN 16:27:47,269 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.springframework] to WARN 16:27:48,660 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.FileAppender] 16:27:48,707 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE] 16:27:48,816 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property 16:27:49,019 |-INFO in ch.qos.logback.core.FileAppender[FILE] - File property is set to [\\ldn\dfs01\SKY-DEV\DEV_DR\sky\log\EOD_MTM_2011-03-31_162735.txt] 16:27:49,035 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO 16:27:49,035 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT] Here is my config file, /com/example/gcm/pricing/batchpricer/logback.xml And, yes 'dealpricer.logback.file' is set, so the file output is used instead of stdout. <configuration> <logger name="com.example.gcm" level="${log.level}" /> <logger name="com.example.gcm.launcher" level="INFO" /> <logger name="com.example.gcm.pricing.params.impl" level="${log.level}" />  <logger name="com.example.sky.service.DataSynapseClient" level="INFO" /> <logger name="httpclient" level="WARN" /> <logger name="org.apache" level="WARN" /> <logger name="org.hibernate" level="WARN" /> <logger name="org.hibernate.cfg.AnnotationBinder" level="WARN" /> <logger name="org.hibernate.cfg.annotations" level="WARN" /> <logger name="org.quartz" level="WARN" /> <logger name="org.springframework" level="WARN" />  <if condition='!property("dealpricer.logback.file").isEmpty()'> <then> <appender name="FILE" class="ch.qos.logback.core.FileAppender"> <encoder> <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-16thread] %-5level %-35.35logger{30} - %msg%n</pattern> </encoder> <file>${dealpricer.logback.file}</file> </appender> <root level="${log.level}"> <appender-ref ref="FILE" /> </root> </then> <else> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-16thread] %-5level %-35.35logger{30} - %msg%n</pattern> </encoder> </appender> <root level="${log.level}"> <appender-ref ref="STDOUT" /> </root> </else> </if> </configuration> And here are my dependencies as configured in maven: <dependencies> <dependency> <groupId>commons-logging</groupId> <artifactId>commons-logging</artifactId> <version>1.1.1</version> <scope>provided</scope>  </dependency> <dependency> <groupId>org.slf4j</groupId> <artifactId>jcl-over-slf4j</artifactId> <version>1.6.1</version> </dependency> <dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-classic</artifactId> <version>0.9.28</version> </dependency> <dependency>  <groupId>janino</groupId> <artifactId>janino</artifactId> <version>2.5.10</version> </dependency> <dependency>  <groupId>org.slf4j</groupId> <artifactId>jul-to-slf4j</artifactId> <version>1.6.1</version> </dependency> </dependencies> -- View this message in context: http://old.nabble.com/logback-0.9.28-is-noisy-tp31368071p31368071.html Sent from the Logback User mailing list archive at Nabble.com.

3 2

Memory consumption problem with LRUMessageCache class
by François Petitit 13 Apr '11

13 Apr '11

Hello, we have problems of excessive memory consumption, due to the object LRUMessageCache that grows constantly, until it exceeds 100MB. Then we restart the JVM to avoid crashes. Could the anomaly http://jira.qos.ch/browse/LBCLASSIC-255 regarding the fact that the class LRUMessageCache is not multithread-safe explain the problem? Thank you in advance.

3 3

Richer logconfiguration naming scheme
by Urs Peter 12 Apr '11

12 Apr '11

Hi all, Recently I was reinventing once more a strategy to deal with different logging configurations based on environment. Logback offers a rather rigid approach by means of the -test naming scheme, which provides me with two options for logging configuration: one for real and one for test. For my usage, I'm looking for a richer naming scheme. Since I recently did some stuff with lift where they - in my eyes - found an elegant way to tackle this problem, I thought it might be handy to port this to logback. What lift does is the following: They use a naming scheme, which combines a run mode, and/or current user and/or host. Their convention looks as follows: > modeName.userName.hostName.props > > examples: > jack.aserver.props > test.jack.aserver.props > production.aserver.props > staging.jack.props > test.default.props > default.props The run mode (test/production/staging etc.) is nothing else than an JVM argument (-Drun.mode=test). The current user is related to the user.name default JVM argument. What do you guys think, would this be an interesting feature? Cheers Urs

2 1

MaxHistory not deleting old files in timeBasedFileNamingAndTriggeringPolicy
by Renuka Pathak 12 Apr '11

12 Apr '11

Hi, Please help me. MaxHistory not deleting old files in timeBasedFileNamingAndTriggeringPolicy. Which version i should use to have this fixed? I am using .9.20 version. Thanks Renuka

2 1

log4j performance comparison
by hostalp＠post.cz 11 Apr '11

11 Apr '11

Hello, based on the old topic archived here for example: http://old.nabble.com/logback-performance-clarification-td9390741.html I performed set of similar tests with debug level actually enabled to see how does logback perform when actually logging. - I noticed slightly worse (than log4j) logback performance in most cases, especially on my Windows machine - I was also interested in the effect of immediateFlush option which was giving us noticable performance improvement with log4j, but was removed from logback as of 0.9.19 (http://logback.qos.ch/manual/appenders.html) Here I noticed that immediateFlush was still giving something (I had to test on logback 0.9.18 in order to compare that). Sad that it was removed. - I've also done some more tests with info level and logback parametrized debug call combined with isDebugEnabled and this one shows typically better performance than plain parametrized debug call as well as classic debug call with isDebugLevel. The main question is - why was immediateFlush removed when it really gives some improvement? Here are some results (all tests performed on Java 1.5 due to its use by the application server we're running at): Windows: log4j 1.2.16, logback 0.9.28 immediateFlush true: ############################################### Log4j direct debug call: 13516 Log4j tested (isDebugEnabled) debug call: 13595 Logback direct debug call: 15593 Logback tested (isDebugEnabled) debug call: 17273 Logback parametrized debug call: 19011 ############################################### Windows: log4j 1.2.16, logback 0.9.18 immediateFlush true: ############################################### Log4j direct debug call: 13421 Log4j tested (isDebugEnabled) debug call: 13240 Logback direct debug call: 15562 Logback tested (isDebugEnabled) debug call: 17112 Logback parametrized debug call: 17981 ############################################### Windows: log4j 1.2.16, logback 0.9.18 immediateFlush false: ############################################### Log4j direct debug call: 6562 Log4j tested (isDebugEnabled) debug call: 6608 Logback direct debug call: 6137 Logback tested (isDebugEnabled) debug call: 7418 Logback parametrized debug call: 8273 ############################################### HP-UX: log4j 1.2.16, logback 0.9.28 immediateFlush true: ############################################### Log4j direct debug call: 17385 Log4j tested (isDebugEnabled) debug call: 17411 Logback direct debug call: 17351 Logback tested (isDebugEnabled) debug call: 17315 Logback parametrized debug call: 17677 ############################################### HP-UX: log4j 1.2.16, logback 0.9.18 immediateFlush true: ############################################### Log4j direct debug call: 17522 Log4j tested (isDebugEnabled) debug call: 17688 Logback direct debug call: 17418 Logback tested (isDebugEnabled) debug call: 17525 Logback parametrized debug call: 17071 ############################################### HP-UX machine: log4j 1.2.16, logback 0.9.18 immediateFlush false: ############################################### Log4j direct debug call: 9936 Log4j tested (isDebugEnabled) debug call: 10869 Logback direct debug call: 9900 Logback tested (isDebugEnabled) debug call: 9907 Logback parametrized debug call: 10346 ############################################### code used for testing ---------------------------------------------------------------------------------------------- package perfTest.ch.qos.logback; import org.slf4j.Logger; import org.slf4j.LoggerFactory; public class PerformanceComparator { static Logger logbacklogger = LoggerFactory.getLogger(PerformanceComparator.class); static org.apache.log4j.Logger log4jlogger = org.apache.log4j.Logger.getLogger(PerformanceComparator.class); // How many times should we try to log: static int loop = 1000000; public static void main(String[] args) throws InterruptedException { initConfig(); // Let's run once for Just In Time compiler log4jDirectDebugCall(); log4jTestedDebugCall(); logbackDirectDebugCall(); logbackTestedDebugCall(); logbackParametrizedDebugCall(); // let's run the tests and display the results: long result1 = log4jDirectDebugCall(); long result2 = log4jTestedDebugCall(); long result3 = logbackDirectDebugCall(); long result4 = logbackTestedDebugCall(); long result5 = logbackParametrizedDebugCall(); System.out.println("###############################################"); System.out.println("Log4j direct debug call: " + result1); System.out.println("Log4j tested (isDebugEnabled) debug call: " + result2); System.out.println("Logback direct debug call: " + result3); System.out.println("Logback tested (isDebugEnabled) debug call: " + result4); System.out.println("Logback parametrized debug call: " + result5); System.out.println("###############################################"); } private static long log4jDirectDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { log4jlogger.debug("SEE IF THIS IS LOGGED " + j + "."); } return (System.nanoTime() - start) / loop; } private static long log4jTestedDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { if (log4jlogger.isDebugEnabled()) { log4jlogger.debug("SEE IF THIS IS LOGGED " + j + "."); } } return (System.nanoTime() - start) / loop; } private static long logbackDirectDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { logbacklogger.debug("SEE IF THIS IS LOGGED " + j + "."); } return (System.nanoTime() - start) / loop; } private static long logbackTestedDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { if (logbacklogger.isDebugEnabled()) logbacklogger.debug("SEE IF THIS IS LOGGED " + j + "."); } return (System.nanoTime() - start) / loop; } private static long logbackParametrizedDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { //if (logbacklogger.isDebugEnabled()) //test logbacklogger.debug("SEE IF THIS IS LOGGED {}.", j); } return (System.nanoTime() - start) / loop; } private static void initConfig() { org.apache.log4j.Logger log4jRoot = org.apache.log4j.Logger.getRootLogger(); //log4jRoot.setLevel(org.apache.log4j.Level.INFO); ch.qos.logback.classic.Logger lbRoot = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger("ROOT"); //lbRoot.setLevel(ch.qos.logback.classic.Level.INFO); // create the loggers org.apache.log4j.Logger.getLogger("perfTest"); org.apache.log4j.Logger.getLogger("perfTest.ch"); org.apache.log4j.Logger.getLogger("perfTest.ch.qos"); org.apache.log4j.Logger.getLogger("perfTest.ch.qos.logback"); LoggerFactory.getLogger("perfTest"); LoggerFactory.getLogger("perfTest.ch"); LoggerFactory.getLogger("perfTest.ch.qos"); LoggerFactory.getLogger("perfTest.ch.qos.logback"); } } ---------------------------------------------------------------------------------------------- log4j configuration ---------------------------------------------------------------------------------------------- <?xml version="1.0" encoding="UTF-8"?> <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd"> <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false"> <appender name="TestLogfile" class="org.apache.log4j.RollingFileAppender"> <param name="File" value="testlog4j.log"/> <param name="MaxFileSize" value="1000KB"/> <param name="maxBackupIndex" value="1"/> <param name="immediateFlush" value="true"/> <layout class="org.apache.log4j.PatternLayout"> <param name="ConversionPattern" value="%d{ISO8601} %5p [%t] %c{1} %X{transactionId} - %m%n"/> </layout> </appender> <root> <level value="debug"/> <appender-ref ref="TestLogfile"/> </root> </log4j:configuration> ---------------------------------------------------------------------------------------------- logback 0.9.28 configuration ---------------------------------------------------------------------------------------------- <configuration> <appender name="TestLogfile" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>testlogback.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy"> <fileNamePattern>testlogback.log.%i</fileNamePattern> <minIndex>1</minIndex> <maxIndex>1</maxIndex> </rollingPolicy> <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy"> <maxFileSize>1000KB</maxFileSize> </triggeringPolicy> <encoder> <Pattern>%d{ISO8601} %5p [%t] %c{0} %X{transactionId} - %m%n</Pattern> <charset>UTF-8</charset> </encoder> </appender> <root> <level value="debug" /> <appender-ref ref="TestLogfile" /> </root> </configuration> ---------------------------------------------------------------------------------------------- logback 0.9.18 configuration ---------------------------------------------------------------------------------------------- <configuration> <appender name="TestLogfile" class="ch.qos.logback.core.rolling.RollingFileAppender"> <File>testlogback.log</File> <ImmediateFlush>true</ImmediateFlush> <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy"> <FileNamePattern>testlogback.log.%i</FileNamePattern> <MinIndex>1</MinIndex> <MaxIndex>1</MaxIndex> </rollingPolicy> <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy"> <MaxFileSize>1000KB</MaxFileSize> </triggeringPolicy> <Encoding>UTF-8</Encoding> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%d{ISO8601} %5p [%t] %c{0} %X{transactionId} - %m%n</Pattern> </layout> </appender> <root> <level value="debug" /> <appender-ref ref="TestLogfile" /> </root> </configuration> ----------------------------------------------------------------------------------------------

5 10

Spring -> SLF4J -> Logback
by Luciano Santos 11 Apr '11

11 Apr '11

Hello. I am trying to integrate Logback for the first time in a project of mine, and i'm having such a hard time trying to use it along with Spring 3.0.5. I declared jcl-over-slf4j dependency so it replaces commons-logging used by spring-core, but it seems like something is missing or wrong: java.lang.NoSuchMethodError: org.slf4j.spi.LocationAwareLogger.log(Lorg/slf4j/Marker;Ljava/lang/String;ILjava/lang/String;[Ljava/lang/Object;Ljava/lang/Throwable;)V at org.apache.commons.logging.impl.SLF4JLocationAwareLog.info(SLF4JLocationAwareLog.java:159) at org.springframework.jca.context.SpringContextResourceAdapter.start(SpringContextResourceAdapter.java:151) ... Here're my logging dependencies (No commons-logging or log4j are being used): <dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-core</artifactId> <version>0.9.28</version> <type>jar</type> <scope>runtime</scope> </dependency> <dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-classic</artifactId> <version>0.9.28</version> <type>jar</type> <scope>runtime</scope> </dependency> <dependency> <groupId>org.slf4j</groupId> <artifactId>slf4j-api</artifactId> <version>1.6.1</version> <type>jar</type> <scope>runtime</scope> </dependency> <dependency> <groupId>org.slf4j</groupId> <artifactId>jcl-over-slf4j</artifactId> <version>1.6.1</version> <type>jar</type> <scope>runtime</scope> </dependency> Any thoughts about what may be wrong? Thank you Luciano

3 2

ch.qos.logback.core.sift.SiftingAppender
by robemall 10 Apr '11

10 Apr '11

What does append property mean in case of SiftingAppender. I presume it means appending to the same unique file or not. Then why is it shown false in all the examples? -- View this message in context: http://old.nabble.com/ch.qos.logback.core.sift.SiftingAppender-tp31365900p3… Sent from the Logback User mailing list archive at Nabble.com.

1 0

logger wildcard name?
by Joseph Schmoley 08 Apr '11

08 Apr '11

I've got a logback.xml config (pasted below). All I'm trying to do is have a different logging level, as well as slightly different encoder pattern, for what shows up in the console vs. what gets written to a file. I understand that you have to create 2 different appenders, FILE and CONSOLE, then set root logger for console only with leve="info", and create a separate logger referencing FILE appender with a different logging level. I've done this, but I can't figure out how to set the logger name to a wildcard so I can get "ALL" output directed to the file. You see, just like the root logger that has no "name", I want that for the <logger> as well, but it requires a name and I've tried putting "*" in it and it doesn't work. I don't want to log just "com.acme.*" output, I want to log everything the root logger is logging. Help please! Thank you. <configuration> <appender name="FILE" class="ch.qos.logback.core.FileAppender"> <file>../logs/esign-app.log</file> <encoder> <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %level [%thread] [%class{0}:%line] %msg%n</pattern> </encoder> </appender> <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{HH:mm:ss.SSS} %level [%thread] [%class{0}:%line] %msg%n</pattern> </encoder> </appender> <logger name="com.acme" level="debug" additivity="false"> <appender-ref ref="FILE" /> </logger> <root level="info"> <appender-ref ref="CONSOLE" /> </root> </configuration>

3 3

Re: [logback-user] Multiple web-applications logging to same file
by David Roussel 08 Apr '11

08 Apr '11

Use prudent mode - http://logback.qos.ch/manual/appenders.html#FileAppender LogbackUser wrote: > > Are there any configuration properties through which multiple > web-applications using logback could be configured to log to the same log > file? This is taking into consideration that the messages would be logged > concurrently without losing any messages. > > The reason I ask this question is that - we have a clustered environment > of glassfish server instances where the same web application is installed > on all the server instances in the cluster. > -- View this message in context: http://old.nabble.com/Multiple-web-applications-logging-to-same-file-tp3125… Sent from the Logback User mailing list archive at Nabble.com.

3 5