November 2011 - logback-dev

[JIRA] Created: (LBCORE-213) Do not restrict SMTPAppender <to> to only 1 email address
by Alexandre Garnier (JIRA) 06 Mar '12

06 Mar '12

Do not restrict SMTPAppender <to> to only 1 email address --------------------------------------------------------- Key: LBCORE-213 URL: http://jira.qos.ch/browse/LBCORE-213 Project: logback-core Issue Type: Bug Reporter: Alexandre Garnier Assignee: Logback dev list It's not possible to have multiple email address in <to> element of SMTPAppender because only the first one is used (https://github.com/ceki/logback/blob/master/logback-core/src/main/java/ch/q…) When using a property, multiple <to> element is not really easy (if even possible)... Example: <appender name="email" class="ch.qos.logback.classic.net.SMTPAppender"> ... <to>${mail.log.to}</to> ... </appender> With properties : mail.log.to = admin@domain.com,dev@domain.com,op@domain.com => Only admin(a)domain.com get the email ! -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

2 5

[JIRA] Created: (LBCLASSIC-221) SMTPAppender includes irrelevant logging events
by Chris Cheshire (JIRA) 06 Mar '12

06 Mar '12

SMTPAppender includes irrelevant logging events ----------------------------------------------- Key: LBCLASSIC-221 URL: http://jira.qos.ch/browse/LBCLASSIC-221 Project: logback-classic Issue Type: Bug Components: appender Affects Versions: 0.9.24 Environment: Java6, Tomcat6 Reporter: Chris Cheshire Assignee: Logback dev list The BufferSize parameter to SMTPAppender has been removed with no replacement. When the SMTPAppender is triggered by an error event it also includes the previous 255 logging events, whether they were errors or not (now that the buffer size is fixed). By using BufferSize = 1, I was able to send a single error email every time an error occurred with just that error. Now I get completely irrelevant logging events, potentially days old with nothing to do with the error being logged and no simple way to change this. I'm not sure what version this was introduced - I just upgraded from 0.9.17 to 0.9.24. -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

5 5

[JIRA] Created: (LBCORE-210) Upgrade Janino support to latest 2.6.1
by Jason Klapste (JIRA) 21 Feb '12

21 Feb '12

Upgrade Janino support to latest 2.6.1 -------------------------------------- Key: LBCORE-210 URL: http://jira.qos.ch/browse/LBCORE-210 Project: logback-core Issue Type: Improvement Components: Joran Affects Versions: 0.9.28, 0.9.29 Reporter: Jason Klapste Assignee: Logback dev list Logback officially supports 2.4.3 (from 2006!) and should probably be upgraded to a more recent version. Janino 2.6.1 *WAS* working previously in logback (0.9.27) until EnvUtil.isJaninoAvailable()'s check was added. org.codehaus.janino.Cookable does not exist in 2.6.1. -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

7 10

[JIRA] Created: (LBCLASSIC-281) Don't evaluate formattedMessage in LoggingEvent constructor
by Andrew Brett (JIRA) 16 Feb '12

16 Feb '12

Don't evaluate formattedMessage in LoggingEvent constructor ----------------------------------------------------------- Key: LBCLASSIC-281 URL: http://jira.qos.ch/browse/LBCLASSIC-281 Project: logback-classic Issue Type: Improvement Affects Versions: 0.9.29 Reporter: Andrew Brett Assignee: Logback dev list Whenever a ch.qos.logback.classic.spi.LoggingEvent is constructed, MessageFormatter.arrayFormat(...) is called, and the formattedMessage member variable assigned. This involves calling toString() on all arguments in argArray, which can be slow, and occurs even if the formattedMessage is not part of any appender layouts. For my project's purposes, I have a custom formatter which only outputs an abbreviated string form of certain objects with expensive toString() methods; however, I am still paying the overhead in the toString() calls, since they're made even when getFormattedMessage() is never called. Note that I don't control the source of the objects with expensive toString() methods, nor do I control the source everywhere they're logged, so I can't simply change them directly. formattedMessage is already evaluated lazily in getFormattedMessage(), so the only side effect of this change is the introspection of argsArray to look for a Throwable at the end, which is a trivial operation to perform separately. -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

3 3

[JIRA] Created: (LBCORE-146) SiftingAppender TimeBasedRollingPolicy MaxHistory not deleting old files
by Hrotkó Gábor (JIRA) 03 Feb '12

03 Feb '12

SiftingAppender TimeBasedRollingPolicy MaxHistory not deleting old files ------------------------------------------------------------------------ Key: LBCORE-146 URL: http://jira.qos.ch/browse/LBCORE-146 Project: logback-core Issue Type: Bug Components: Rolling Affects Versions: 0.9.18 Environment: linux64, jdk1.6.0_17-b04, apache-tomcat-6.0.24 Reporter: Hrotkó Gábor Assignee: Logback dev list When I use SiftingAppender with TimeBasedRollingPolicy, old files does not get deleted when the MaxHistory is set. logback.xml snipet: <configuration debug="true" scan="true" scanPeriod="5 seconds"> <appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender"> <discriminator> <Key>userid</Key> <DefaultValue>base</DefaultValue> </discriminator> <sift> <appender name="FILE-${userid}" class="ch.qos.logback.core.rolling.RollingFileAppender"> <File>/usr/local/tomcat6/logs/myLog_${userid}.log</File> <Append>false</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%d [%thread] %level %mdc %logger.%method:%line - %msg%n</Pattern> </layout> <RollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <FileNamePattern>/usr/local/tomcat6/logs/myLog_${userid}.%d{yyyy-MM-dd}.log</FileNamePattern>  <MaxHistory>2</MaxHistory> </RollingPolicy> </appender> </sift> </appender> ... With the config above, the files gets sifted and rolled well, but old files not deleted. When I change the filenames, and delete the ${userid} sifting, it works well. ... <File>/usr/local/tomcat6/logs/myLog.log</File> ... <FileNamePattern>/usr/local/tomcat6/logs/myLog.%d{yyyy-MM-dd}.log</FileNamePattern> ... -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

1 1

[JIRA] Created: (LBCLASSIC-298) improve RollingCalendar and TimeBasedFileNamingAndTriggeringPolicyBase to enable periodic loggic
by Murali Rath (JIRA) 20 Dec '11

20 Dec '11

improve RollingCalendar and TimeBasedFileNamingAndTriggeringPolicyBase to enable periodic loggic ------------------------------------------------------------------------------------------------ Key: LBCLASSIC-298 URL: http://jira.qos.ch/browse/LBCLASSIC-298 Project: logback-classic Issue Type: New Feature Components: appender Affects Versions: 0.9.29 Environment: all Reporter: Murali Rath Assignee: Logback dev list logback currently allows logging periodically however it is limited to every 1 sec, 1 min, 1 hr , 1 day etc. When I want the log file to roll over say every 10 sec or 20 minutes it is not possible. RollingCalendar and TimeBasedFileNamingAndTriggeringPolicyBase can be improved or extened to provide this functionality. -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

1 3

[JIRA] Created: (LBCLASSIC-284) Make it possible to log to different appenders at different levels from the same logger
by Iwein Fuld (JIRA) 10 Dec '11

10 Dec '11

Make it possible to log to different appenders at different levels from the same logger --------------------------------------------------------------------------------------- Key: LBCLASSIC-284 URL: http://jira.qos.ch/browse/LBCLASSIC-284 Project: logback-classic Issue Type: Improvement Affects Versions: 0.9.28 Reporter: Iwein Fuld Assignee: Logback dev list I found a requirement in the wild to log trace and above statements to one appender, and debug and above to another. This needed to be configured for a particular package. My preferred solution would be to use something like https://gist.github.com/1104145, but that doesn't work. There is a workaround of using a filter inside the appender, but that isn't as pretty as I would like. ( http://iweinfuld.posterous.com/ ) -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

2 2

Logback initialization time analysis
by Phil Clay 22 Nov '11

22 Nov '11

In an effort to speed up a CLI program that uses slf4j and logback, I've done some analysis on logback initialization time. This came about because logback initialization was dominating our CLI execution time. Mainly this was because of XML configuration. Therefore, in our CLIs, I have replaced XML configuration with programmatic configuration in java. This reduced the logback initialization overhead drastically. But I wanted to analyze this further to see if more enhancements could be made. With the yourkit profiler, I identified several 'hotspots' in the code and made various tweeks to remove those hotspots. I measured each change individually to see what kind of benefit (if any) it gave. Skip down to the CONCLUSION if you don't care about the details. == TEST SETUP == I created a class as follows: public class LoggerInitTest { public static void main(String[] args) { LoggerFactory.getILoggerFactory(); } } No xml or grovy configuration files exist on the classpath. XML/groovy configuration is expensive. We get the greatest benefit by just not using it, so I didn't bother trying to speed it up. == TEST EXECUTION == Each case below was executed 200 times from the cli. (i.e. the loop was in bash, not java). The min/max/avg times were calculated for each case. == TEST CASE A == Baseline test case using slf4j-nop instead of logback. == TEST CASE B == logback 0.9.29 (unmodified) == TEST CASE C == logback 1.0.1 (unmodified) Git cloned last week. Don't have the exact change number in front of me... == TEST CASE D == logback 1.0.1 with the following modification 1) Loader.HAS_GET_CLASS_LOADER_PERMISSION converted to be lazily initialized See attached 1_Loader.diff Classloading the Loader class was identified as a hotspot because of static initialization. By lazily loading HAS_GET_CLASS_LOADER_PERMISSION, we can avoid the performance hit unless it is needed. In my CLIs, HAS_GET_CLASS_LOADER_PERMISSION is never needed, therefore the initialization cost is completely avoided. == TEST CASE E == logback 1.0.1 with the following modifications 1) (from above) 2) ContextBase.executorService converted to be lazily initialized See attached 2_ContextBase.diff Initializing the executorService was identified as a hotspot. By lazily loading executorService, we can avoid the performance hit unless it is needed. In my tests, executorService is never needed. == TEST CASE F == logback 1.0.1 with the following modifications 1) (from above) 2) (from above) 3) PatternLayout.defaultConverterMap classes lazily loaded See attached 3_PatternLayout.diff Since the classnames are populated in the defaultConverterMap by statically referencing the class, and calling getName(). For example: ch.qos.logback.classic.pattern.DateConverter.class.getName(); This causes all of the converter classes to be loaded, even if they are not used. I converted the classnames to be string literals instead. For example: "ch.qos.logback.classic.pattern.DateConverter" This allows the converter classes to not be loaded until/unless they are actually used. I don't need many of the converters. The downside of this change is that you lose compile-time safety on the class names. == TEST CASE G == logback 1.0.1 with the following modifications 1) (from above) 2) (from above) 3) (from above) Also, The LoggerInitTest class was modified to perform additional configuration beyond BasicConfigurator This test case is to provide a baseline to see if the change proposed in http://jira.qos.ch/browse/LBCLASSIC-300 has any benefit. == TEST CASE H == logback 1.0.1 with the following modifications 1) (from above) 2) (from above) 3) (from above) 4) ContextInitializer changed to allow configuration by java class (and skip configuration file lookup and BasicConfigurator logic). See attached 4_ContextInitializer.diff The LoggerInitTest class was modified to provide LoggerContext configuration (via hook into #4). Therefore the logic to search the classpath for XML/groovy files and the configuration logic in BasicConfigurator was avoided. The results of this test case can be compared against test case #G to see if the change proposed in http://jira.qos.ch/browse/LBCLASSIC-300 has any benefit. == TEST RESULTS == Numbers are in milliseconds. Case min max avg A 131 247 165 B 281 496 293 C 331 546 347 D 282 499 296 E 281 496 292 F 280 450 287 G 282 492 307 H 282 450 300 See this in graph form in attached results.png == ANALYSIS == Initialization time increased significantly between (B) 0.9.29 and (C) the current 1.0.1 head. After change #1 from (D) was made, performance was back on-par with 0.9.29. I identified that the HAS_GET_CLASS_LOADER_PERMISSION was introduced after 0.9.29 (http://jira.qos.ch/browse/LBCLASSIC-263) so this is further evidence that this caused the increase seen in (C). None of the other changes from E, F, G, or H, had any noticable impact to initialization performance. When profiling with yourkit, I can see the performance difference. But, when executing the test without profiling, no change can be seen. I was unable to make any changes that decreased initialization time below that of (B) 0.9.29. After further profiling of individual tests runs with yourkit, I can see that most of the initialization time is spent in the following areas: - classloading (mainly because of static initialization) - Pattern compiling / parsing I could not identify any other places to reduce the number of classes loaded by logback. == CONCLUSION == The only change that I can recommend incorporating into logback to decrease initialization time is from test case (D): 1) Loader.HAS_GET_CLASS_LOADER_PERMISSION converted to be lazily initialized See attached 1_Loader.diff This would get initialization time of 1.0.1 back down to the initialization time of (B) 0.9.29. == ACTION ITEMS == I'll file a JIRA issue for incorporating change #1 into logback. I'm going to close http://jira.qos.ch/browse/LBCLASSIC-300 (filed by me) because the proposed change had no impact to initialization performance. If you have any other suggestions on ways to improve initialization performance, please let me know. Other thoughts are welcome as well. Thanks, Phil

4 5

[JIRA] Created: (LBCLASSIC-300) Add ability to manually specify configuration BEFORE autoconfiguration
by Phil (JIRA) 18 Nov '11

18 Nov '11

Add ability to manually specify configuration BEFORE autoconfiguration ---------------------------------------------------------------------- Key: LBCLASSIC-300 URL: http://jira.qos.ch/browse/LBCLASSIC-300 Project: logback-classic Issue Type: Improvement Affects Versions: 0.9.29 Reporter: Phil Assignee: Logback dev list Priority: Minor In order to make logback initialization faster, I would like the ability to programmatically configure logback and avoid the logic that happens in ContextInitializer.autoConfig(). Specifically, refer to this stack that occurs when getILoggerFactory() is initially called... ch.qos.logback.classic.util.ContextInitializer.autoConfig() line: 147 org.slf4j.impl.StaticLoggerBinder.init() line: 85 org.slf4j.impl.StaticLoggerBinder.<clinit>() line: 55 org.slf4j.LoggerFactory.bind() line: 121 org.slf4j.LoggerFactory.performInitialization() line: 111 org.slf4j.LoggerFactory.getILoggerFactory() line: 268 Now, for some background... I am using logback for a fast executing CLI program. Right now, initializing logback dominates the execution time of my CLIs. For example... When I started with logback, I was using logback.xml. If one of my CLIs took 1.5 seconds to run, I would see that initializing logback was taking 1 of those seconds (I used the yourkit profiler to identify this). 66% of the execution time is unacceptable. So, I switched from using logback.xml to programatically configuring logback in Java with the following code.. {code} LoggerContext loggingContext = (LoggerContext) LoggerFactory.getILoggerFactory(); loggingContext.reset(); ... FileAppender<ILoggingEvent> fileAppender = new FileAppender<ILoggingEvent>(); ... Logger rootLogger = loggingContext.getLogger(Logger.ROOT_LOGGER_NAME); rootLogger.addAppender(fileAppender); {code} This reduced the initialization time quite a bit. Now logback initialization is taking about .3 seconds. This is much better. However, I still think this can be improved by completely skipping the auto config logic. The initial call to LoggerFactory.getILoggerFactory() will attempt to auto configure logback.... which searches for groovy files, xml files, and falls back to BasicConfigurator. I don't need this auto configuration logic, since I am just going reset it and configure it myself anyway. I would like the ability to programmatically configure logback and totally avoid this auto configuration. Ideally I would be able to construct a LoggerContext instance, or the root Logger, or something. Then allow slf4j to bind to it without going through the auto config steps. -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

2 7

[JIRA] Created: (LBCORE-237) Change ch.qos.logback.core.pattern.CompositeConverter#transform access to protected
by Martin Caslavsky (JIRA) 15 Nov '11

15 Nov '11

Change ch.qos.logback.core.pattern.CompositeConverter#transform access to protected ----------------------------------------------------------------------------------- Key: LBCORE-237 URL: http://jira.qos.ch/browse/LBCORE-237 Project: logback-core Issue Type: Improvement Components: Pattern Reporter: Martin Caslavsky Assignee: Logback dev list Priority: Minor I would like to suugest to change ch.qos.logback.core.pattern.CompositeConverter#transform access from package protected to protected, which allow successor classes to be placed in package different from ch.qos.logback.core.pattern -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira

1 1