May 2011 - logback-dev - mailman3.qos.ch

[JIRA] Created: (LBCORE-147) RollingPolicy MaxHistory not deleting old files
by Rafael Diaz Maurin (JIRA) 04 Oct '11

04 Oct '11

RollingPolicy MaxHistory not deleting old files ----------------------------------------------- Key: LBCORE-147 URL: http://jira.qos.ch/browse/LBCORE-147 Project: logback-core Issue Type: Bug Components: Rolling Affects Versions: 0.9.18 Environment: linux 2.6.18 64bits apache-tomcat-6.0.20 java/jre1.6.0_18 Reporter: Rafael Diaz Maurin Assignee: Logback dev list The MaxHistory does not do the trick : the old files are not deleted at all : cat logging.xml <appender name="IDP_ACCESS" class="ch.qos.logback.core.rolling.RollingFileAppender"> <File>/shibboleth-idp/logs/idp-access.log</File> <Append>false</Append> <ImmediateFlush>true</ImmediateFlush> <RollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <FileNamePattern>/shibboleth-idp/logs/old/idp-access-%d{yyyy-MM-dd_HH-mm}.log.gz</FileNamePattern> <MaxHistory>3</MaxHistory> </RollingPolicy> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%msg%n</Pattern> </layout> </appender> -- 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

11 35

[JIRA] Created: (LBACCESS-17) LogbackValve overrides final start() method from LifecycleBase in Tomcat 7
by Grzegorz Grzybek (JIRA) 30 Sep '11

30 Sep '11

LogbackValve overrides final start() method from LifecycleBase in Tomcat 7 -------------------------------------------------------------------------- Key: LBACCESS-17 URL: http://jira.qos.ch/browse/LBACCESS-17 Project: logback-access Issue Type: Bug Affects Versions: 0.9.26 Reporter: Grzegorz Grzybek Assignee: Logback dev list Priority: Critical {code} java.lang.VerifyError: class ch.qos.logback.access.tomcat.LogbackValve overrides final method start.()V {code} Tomcat 7 has changed the LifecycleBase implementation - it should not override start() but rather startInternal() -- 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: (LBCLASSIC-217) Exception stack trace printing starting from root cause
by Tomasz Nurkiewicz (JIRA) 24 Sep '11

24 Sep '11

Exception stack trace printing starting from root cause ------------------------------------------------------- Key: LBCLASSIC-217 URL: http://jira.qos.ch/browse/LBCLASSIC-217 Project: logback-classic Issue Type: New Feature Affects Versions: 0.9.22 Reporter: Tomasz Nurkiewicz Assignee: Logback dev list A typical exception in multi-tier application looks similar to this: com.acme.BusinessException: Can't process request at ... at ... Caused by: com.acme.dao.PersistenceException: Can't access database at ... at ... ... 49 common frames omitted Caused by: org.springframework.jdbc.datasource.lookup.DataSourceLookupFailureException: Unable to locate datasource at ... at ... ... 65 common frames omitted Caused by: java.net.UnknownHostException: Unknown host localhostt at ... at ... ... 84 common frames omitted The deeper exception, the more specific information it gives. Typically the last "Caused by" is the most interesting one. So it seems like reversing the order in which the exceptions are thrown (from most specific to consecutive, less specific wrappers) might be more intuitive: java.net.UnknownHostException: Unknown host localhostt at ... at ... Wrapped by: org.springframework.jdbc.datasource.lookup.DataSourceLookupFailureException: Unable to connect to the database at ... at ... Wrapped by: com.acme.dao.PersistenceException: Can't access database at ... at ... Wrapped by: com.acme.BusinessException: Can't process request at ... at ... It is not only easier to read and follow (business exception is interesting for the end user while the most precise, technical information is for developers and system administrators - so it should be easily accessible in the logs), but also the stack trace isn't mixed. You can read stack frames in exactly the same order as they were executed, no need to jump from one stack trace line to another (see attachment from the real application). This also means that the beginning of the thread is always at the bottom and the line that caused the very first exception - at the top. (look at the attached real exception) I already implemented this feature by adding RootCauseFirstThrowableProxyConverter extending ch.qos.logback.classic.pattern.ExtendedThrowableProxyConverter. It is turned on by appending "%rEx" to the encoder pattern. If you like this feature, I will push the changes (just few classes have changed) into my GitHub fork. -- 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 8

[JIRA] Created: (LBCLASSIC-267) Intermittent ConcurrentModificationException in LoggingEvent.prepareForDeferredProcessing
by Anders Wallgren (JIRA) 20 Sep '11

20 Sep '11

Intermittent ConcurrentModificationException in LoggingEvent.prepareForDeferredProcessing ----------------------------------------------------------------------------------------- Key: LBCLASSIC-267 URL: http://jira.qos.ch/browse/LBCLASSIC-267 Project: logback-classic Issue Type: Bug Affects Versions: 0.9.28 Reporter: Anders Wallgren Assignee: Logback dev list Occasionally seeing this type of exception: 02:02:27,883 |-ERROR in com.electriccloud.log.AsyncAppender[ASYNC_FILE] - Appender [ASYNC_FILE] failed to append. java.util.ConcurrentModificationExceptionjava.util.ConcurrentModificationException at java.util.HashMap$HashIterator.nextEntry(HashMap.java:793) at java.util.HashMap$EntryIterator.next(HashMap.java:834) at java.util.HashMap$EntryIterator.next(HashMap.java:832) at java.util.HashMap.putAllForCreate(HashMap.java:435) at java.util.HashMap.<init>(HashMap.java:225) at ch.qos.logback.classic.spi.LoggingEvent.prepareForDeferredProcessing(LoggingEvent.java:213) at com.electriccloud.log.AsyncAppender.append(AsyncAppender.java:132) at com.electriccloud.log.AsyncAppender.append(AsyncAppender.java:36) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:85) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:64) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:285) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:272) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:473) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:427) at ch.qos.logback.classic.Logger.debug(Logger.java:534) at com.electriccloud.log.Slf4jLog.debug(Slf4jLog.java:66) at com.electriccloud.log.Slf4jLog.log(Slf4jLog.java:202) at com.electriccloud.util.timer.Timer.logElapsed(Timer.java:324) at com.electriccloud.operations.OperationTimingAspect.logOperationPerformance(OperationTimingAspect.java:107) at sun.reflect.GeneratedMethodAccessor124.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:627) at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:616) at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:64) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:160) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204) at $Proxy23.perform(Unknown Source) at com.electriccloud.operations.OperationInvoker.invoke(OperationInvoker.java:273) at com.electriccloud.operations.OperationCaller.call(OperationCaller.java:127) at com.electriccloud.operations.OperationCaller.call(OperationCaller.java:42) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) at java.util.concurrent.FutureTask.run(FutureTask.java:138) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) at com.electriccloud.util.CommanderThread.run(CommanderThread.java:105) -- 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 3

[JIRA] Created: (LBCLASSIC-268) ConcurrentModificationException in LogbackMDCAdapter
by Scott Stanton (JIRA) 20 Sep '11

20 Sep '11

ConcurrentModificationException in LogbackMDCAdapter ---------------------------------------------------- Key: LBCLASSIC-268 URL: http://jira.qos.ch/browse/LBCLASSIC-268 Project: logback-classic Issue Type: Bug Affects Versions: 0.9.28 Environment: JRE 1.6.0_25, Windows 7 64-bit Reporter: Scott Stanton Assignee: Logback dev list Priority: Critical I'm seeing ConcurrentModificationException errors like the following: {panel} 011-05-23T04:53:31.997 | ERROR | Dispatch-001 | | | | OperationCaller | null | java.util.ConcurrentModificationException: null at java.util.HashMap$HashIterator.nextEntry(HashMap.java:793) ~[na:1.6.0_21] at java.util.HashMap$EntryIterator.next(HashMap.java:834) ~[na:1.6.0_21] at java.util.HashMap$EntryIterator.next(HashMap.java:832) ~[na:1.6.0_21] at java.util.HashMap.putAll(HashMap.java:523) ~[na:1.6.0_21] at ch.qos.logback.classic.util.LogbackMDCAdapter.put(LogbackMDCAdapter.java:76) ~[logback-classic.jar:na] at org.slf4j.MDC.put(MDC.java:112) ~[slf4j-api.jar:1.6.1] {panel} -- 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 3

[JIRA] Created: (LBCLASSIC-263) Logback Classic causes SecurityException
by NC (JIRA) 11 Sep '11

11 Sep '11

Logback Classic causes SecurityException ---------------------------------------- Key: LBCLASSIC-263 URL: http://jira.qos.ch/browse/LBCLASSIC-263 Project: logback-classic Issue Type: Bug Affects Versions: 0.9.28 Reporter: NC Assignee: Logback dev list PackagingDataCalculator invokes Class.getClassLoader(). This method throws a SecurityException when running under a security manager and that manager denies access to the ClassLoader. I'm submitting a PackagingDataCalculator patch which wraps the getClassLoader() invocation in a doPrivileged block. This allows these calls to succeed when the getClassLoader RuntimePermission is granted to logback-classic. -- 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 8

[JIRA] Created: (LBCORE-79) FixedWindowRollingPolicy performs compression on the logging thread
by Szel Zoltan (JIRA) 02 Sep '11

02 Sep '11

FixedWindowRollingPolicy performs compression on the logging thread ------------------------------------------------------------------- Key: LBCORE-79 URL: http://jira.qos.ch/browse/LBCORE-79 Project: logback-core Issue Type: Improvement Components: Rolling Affects Versions: 0.9.13 Reporter: Szel Zoltan Assignee: Logback dev list Hi, the FixedWindowRollingPolicy performs the compression on the logging thread which can bring the application to halt, when compressing large files. Please consider modifing the FixedWindowRollingPolicy to perform the operation on a background thread as requested in LBCORE-48. Regards, Zoltan Szel -- 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

[JIRA] Created: (LBCORE-179) conversion word %ex length handling is off by one
by Michael Osipov (JIRA) 26 Aug '11

26 Aug '11

conversion word %ex length handling is off by one ------------------------------------------------- Key: LBCORE-179 URL: http://jira.qos.ch/browse/LBCORE-179 Project: logback-core Issue Type: Bug Components: Pattern Affects Versions: 0.9.26 Reporter: Michael Osipov Assignee: Logback dev list The %ex and %xEx define a stack trace length. The integer spec is somewhat faulty and misleading. First of all this is a stack trace depth imho and not length. Anyway, I was poking around with the SMTPAppender and wanted to include the sole exception message into the subject. The outcome was: 1. The docs do not define a valid interval for the integer value. You can only deduce from logic. 2. I defined %ex{short} and it included 2 lines of the stack trace. 3. I defined %ex{2} and it included 3 lines of the stack trace. 4. I defined %ex{0} and it included 1 line of the stack trace. 5. Defining any negative number omits the stack trace. But it does not make sense at all to have a negative stack trace depth. I checked also the source of the [https://github.com/ceki/logback/blob/master/logback-classic/src/main/java/c… converter], the lines 54 and 58 cause the problem. -- 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 3

[JIRA] Created: (LBCLASSIC-264) MDC of parent thread can be wiped from child thread
by Iwein Fuld (JIRA) 25 Aug '11

25 Aug '11

MDC of parent thread can be wiped from child thread --------------------------------------------------- Key: LBCLASSIC-264 URL: http://jira.qos.ch/browse/LBCLASSIC-264 Project: logback-classic Issue Type: Bug Affects Versions: 0.9.28 Reporter: Iwein Fuld Assignee: Logback dev list In our web framework we're using the MDC, but because we use multiple rendering threads we need to copy context from one thread to another. With log4j this worked fine, with logback it doesn't. It seems that there is an issue at least with setContextMap, which can influence the MDC in other (non child) threads. I've reproduced one such issue in a small project: https://github.com/iwein/logback-testdrive Look at this testcase in particular: {code} @Test public void shouldCopyContextToOtherThread() throws Exception { final AtomicReference<Map> contextMap = new AtomicReference<Map>(); MDC.put("first", "Dorothy"); MDC.put("last", "Parker"); contextMap.set(MDC.getCopyOfContextMap()); //some context is set in a different thread Executors.newSingleThreadExecutor().execute(new Runnable() { public void run() { //not needed, but shouldn't break anything in the parent right? MDC.setContextMap(contextMap.get()); logger.info("Check enclosed."); } }); //If I don't do this I have lost my context. That seems wrong.. //MDC.setContextMap(contextMap.get()); logger.debug("The most beautiful two words in English."); } {code} I'll try to reproduce the issue with some sibling threads for the heck of it, but I think the above already illustrates the problem. -- 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 3

[JIRA] Created: (LBGENERAL-35) TimeBasedRollingWithArchiveRemovalTest failed
by Ralph Goers (JIRA) 25 Aug '11

25 Aug '11

TimeBasedRollingWithArchiveRemovalTest failed --------------------------------------------- Key: LBGENERAL-35 URL: http://jira.qos.ch/browse/LBGENERAL-35 Project: logback-general Issue Type: Sub-task Affects Versions: 0.9.17 Environment: Mac OSX Reporter: Ralph Goers Assignee: Logback dev list This is not a frequent occurence. ------------------------------------------------------------------------------- Test set: ch.qos.logback.core.rolling.TimeBasedRollingWithArchiveRemovalTest ------------------------------------------------------------------------------- Tests run: 6, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 1.411 sec <<< FAILURE! montlyRollover(ch.qos.logback.core.rolling.TimeBasedRollingWithArchiveRemovalTest) Time elapsed: 0.114 sec montlyRolloverOverManyPeriods(ch.qos.logback.core.rolling.TimeBasedRollingWithArchiveRemovalTest) Time elapsed: 0.253 sec dailyRollover(ch.qos.logback.core.rolling.TimeBasedRollingWithArchiveRemovalTest) Time elapsed: 0.058 sec dailyCronologRollover(ch.qos.logback.core.rolling.TimeBasedRollingWithArchiveRemovalTest) Time elapsed: 0.108 sec dailySizeBasedRollover(ch.qos.logback.core.rolling.TimeBasedRollingWithArchiveRemovalTest) Time elapsed: 0.454 sec dailyChronologSizeBasedRollover(ch.qos.logback.core.rolling.TimeBasedRollingWithArchiveRemovalTest) Time elapsed: 0.417 sec <<< ERROR! java.util.concurrent.TimeoutException at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:228) at java.util.concurrent.FutureTask.get(FutureTask.java:91) at ch.qos.logback.core.rolling.TimeBasedRollingWithArchiveRemovalTest.doRollover(TimeBasedRollingWithArchiveRemovalTest.java:194) at ch.qos.logback.core.rolling.TimeBasedRollingWithArchiveRemovalTest.dailyChronologSizeBasedRollover(TimeBasedRollingWithArchiveRemovalTest.java:157) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.junit.internal.runners.TestMethod.invoke(TestMethod.java:59) at org.junit.internal.runners.MethodRoadie.runTestMethod(MethodRoadie.java:98) at org.junit.internal.runners.MethodRoadie$2.run(MethodRoadie.java:79) at org.junit.internal.runners.MethodRoadie.runBeforesThenTestThenAfters(MethodRoadie.java:87) at org.junit.internal.runners.MethodRoadie.runTest(MethodRoadie.java:77) at org.junit.internal.runners.MethodRoadie.run(MethodRoadie.java:42) at org.junit.internal.runners.JUnit4ClassRunner.invokeTestMethod(JUnit4ClassRunner.java:88) at org.junit.internal.runners.JUnit4ClassRunner.runMethods(JUnit4ClassRunner.java:51) at org.junit.internal.runners.JUnit4ClassRunner$1.run(JUnit4ClassRunner.java:44) at org.junit.internal.runners.ClassRoadie.runUnprotected(ClassRoadie.java:27) at org.junit.internal.runners.ClassRoadie.runProtected(ClassRoadie.java:37) at org.junit.internal.runners.JUnit4ClassRunner.run(JUnit4ClassRunner.java:42) at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:62) at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140) at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127) at org.apache.maven.surefire.Surefire.run(Surefire.java:177) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338) at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997) -- 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 7