March 2009 - logback-dev - mailman3.qos.ch

[JIRA] Commented: (LBCORE-63) Deadlock when running on multiple core processors
by Ceki Gulcu (JIRA) 23 Mar '09

23 Mar '09

[ http://jira.qos.ch/browse/LBCORE-63?page=com.atlassian.jira.plugin.system.i… ] Ceki Gulcu commented on LBCORE-63: ---------------------------------- In that case, please open a new jira issue. It would also be very helpful if you could provide the full thread dump. Please do not continue to comment on the present issue. (I intend to mark it as closed.) > Deadlock when running on multiple core processors > ------------------------------------------------- > > Key: LBCORE-63 > URL: http://jira.qos.ch/browse/LBCORE-63 > Project: logback-core > Issue Type: Sub-task > Affects Versions: 0.9.9 > Environment: Operating System: Windows > Platform: PC > Reporter: Toni Heimala > Assignee: Ceki Gulcu > Priority: Blocker > Attachments: patch.txt, patch2.txt, patch3.txt > > > When you run logging into same file from many threads on a system that has more than one physical processor (Dual Core for example), a deadlock will occur after a while. This can not be reproduced on HyperThreading processors. Here's an example program that will demonstrate the behavior: > ----------------------------- > Main.java > ----------------------------- > import java.util.Date; > import java.util.concurrent.ScheduledThreadPoolExecutor; > import java.util.concurrent.TimeUnit; > import org.slf4j.Logger; > import org.slf4j.LoggerFactory; > import ch.qos.logback.classic.LoggerContext; > import ch.qos.logback.classic.joran.JoranConfigurator; > import ch.qos.logback.core.joran.spi.JoranException; > public class Main extends Thread > { > private final static String LOGGER_CONFIGURATION_FILE = "logger.xml"; > private final Logger logger = LoggerFactory.getLogger(Main.class); > > private final long start; > > public Main() > throws JoranException > { > start = new Date().getTime(); > LoggerContext lc = (LoggerContext)LoggerFactory.getILoggerFactory(); > JoranConfigurator configurator = new JoranConfigurator(); > lc.shutdownAndReset(); > configurator.setContext(lc); > configurator.doConfigure(LOGGER_CONFIGURATION_FILE); > } > > public void start() > { > ScheduledThreadPoolExecutor ex1 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex2 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex3 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex4 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex5 = new ScheduledThreadPoolExecutor(1); > ex1.scheduleAtFixedRate(new Task("EX1"), 10, 10, TimeUnit.MICROSECONDS); > ex2.scheduleAtFixedRate(new Task("EX2"), 10, 10, TimeUnit.MICROSECONDS); > ex3.scheduleAtFixedRate(new Task("EX3"), 10, 10, TimeUnit.MICROSECONDS); > ex4.scheduleAtFixedRate(new Task("EX4"), 10, 10, TimeUnit.MICROSECONDS); > ex5.scheduleAtFixedRate(new Task("EX5"), 10, 10, TimeUnit.MICROSECONDS); > > super.start(); > } > > public void run() > { > try > { > while(true) > { > logger.debug("[MAIN] {}", new Date().getTime() - start); > Thread.sleep(10); > } > } > catch (InterruptedException e) > { > logger.info("[MAIN]: Interrupted: {}", e.getMessage()); > } > } > > public static void main(String[] args) > { > try > { > Main main = new Main(); > main.start(); > } > catch (JoranException e) > { > System.out.println("Failed to load application: " + e.getMessage()); > } > } > } > ------------------------------- > Task.java > ------------------------------- > import java.util.Date; > import org.slf4j.Logger; > import org.slf4j.LoggerFactory; > public class Task implements Runnable > { > private final Logger logger = LoggerFactory.getLogger(Task.class); > private final Logger logger_main = LoggerFactory.getLogger(Main.class); > private final String name; > private final long start; > > public Task(final String name) > { > this.name = name; > start = new Date().getTime(); > } > public void run() > { > logger.debug("[{}] {}", name, new Date().getTime() - start); > logger_main.debug("[MAIN] - [{}] {}", name, new Date().getTime() - start); > } > } -- 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 0

[JIRA] Commented: (LBCORE-63) Deadlock when running on multiple core processors
by Robert Dale (JIRA) 23 Mar '09

23 Mar '09

[ http://jira.qos.ch/browse/LBCORE-63?page=com.atlassian.jira.plugin.system.i… ] Robert Dale commented on LBCORE-63: ----------------------------------- I'm getting that deadlock in logback core (0.9.14 and 0.9.15). No console plugin or socket appenders, just plain RollingFileAppender. > Deadlock when running on multiple core processors > ------------------------------------------------- > > Key: LBCORE-63 > URL: http://jira.qos.ch/browse/LBCORE-63 > Project: logback-core > Issue Type: Sub-task > Affects Versions: 0.9.9 > Environment: Operating System: Windows > Platform: PC > Reporter: Toni Heimala > Assignee: Ceki Gulcu > Priority: Blocker > Attachments: patch.txt, patch2.txt, patch3.txt > > > When you run logging into same file from many threads on a system that has more than one physical processor (Dual Core for example), a deadlock will occur after a while. This can not be reproduced on HyperThreading processors. Here's an example program that will demonstrate the behavior: > ----------------------------- > Main.java > ----------------------------- > import java.util.Date; > import java.util.concurrent.ScheduledThreadPoolExecutor; > import java.util.concurrent.TimeUnit; > import org.slf4j.Logger; > import org.slf4j.LoggerFactory; > import ch.qos.logback.classic.LoggerContext; > import ch.qos.logback.classic.joran.JoranConfigurator; > import ch.qos.logback.core.joran.spi.JoranException; > public class Main extends Thread > { > private final static String LOGGER_CONFIGURATION_FILE = "logger.xml"; > private final Logger logger = LoggerFactory.getLogger(Main.class); > > private final long start; > > public Main() > throws JoranException > { > start = new Date().getTime(); > LoggerContext lc = (LoggerContext)LoggerFactory.getILoggerFactory(); > JoranConfigurator configurator = new JoranConfigurator(); > lc.shutdownAndReset(); > configurator.setContext(lc); > configurator.doConfigure(LOGGER_CONFIGURATION_FILE); > } > > public void start() > { > ScheduledThreadPoolExecutor ex1 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex2 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex3 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex4 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex5 = new ScheduledThreadPoolExecutor(1); > ex1.scheduleAtFixedRate(new Task("EX1"), 10, 10, TimeUnit.MICROSECONDS); > ex2.scheduleAtFixedRate(new Task("EX2"), 10, 10, TimeUnit.MICROSECONDS); > ex3.scheduleAtFixedRate(new Task("EX3"), 10, 10, TimeUnit.MICROSECONDS); > ex4.scheduleAtFixedRate(new Task("EX4"), 10, 10, TimeUnit.MICROSECONDS); > ex5.scheduleAtFixedRate(new Task("EX5"), 10, 10, TimeUnit.MICROSECONDS); > > super.start(); > } > > public void run() > { > try > { > while(true) > { > logger.debug("[MAIN] {}", new Date().getTime() - start); > Thread.sleep(10); > } > } > catch (InterruptedException e) > { > logger.info("[MAIN]: Interrupted: {}", e.getMessage()); > } > } > > public static void main(String[] args) > { > try > { > Main main = new Main(); > main.start(); > } > catch (JoranException e) > { > System.out.println("Failed to load application: " + e.getMessage()); > } > } > } > ------------------------------- > Task.java > ------------------------------- > import java.util.Date; > import org.slf4j.Logger; > import org.slf4j.LoggerFactory; > public class Task implements Runnable > { > private final Logger logger = LoggerFactory.getLogger(Task.class); > private final Logger logger_main = LoggerFactory.getLogger(Main.class); > private final String name; > private final long start; > > public Task(final String name) > { > this.name = name; > start = new Date().getTime(); > } > public void run() > { > logger.debug("[{}] {}", name, new Date().getTime() - start); > logger_main.debug("[MAIN] - [{}] {}", name, new Date().getTime() - start); > } > } -- 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 0

[JIRA] Commented: (LBCORE-63) Deadlock when running on multiple core processors
by Ceki Gulcu (JIRA) 23 Mar '09

23 Mar '09

[ http://jira.qos.ch/browse/LBCORE-63?page=com.atlassian.jira.plugin.system.i… ] Ceki Gulcu commented on LBCORE-63: ---------------------------------- Hello Robert, Any progress on what exactly? This issue is related to logback console plug-in for eclipse as such as logback's threading model. Are you using the the logback console plug-in for eclipse? > Deadlock when running on multiple core processors > ------------------------------------------------- > > Key: LBCORE-63 > URL: http://jira.qos.ch/browse/LBCORE-63 > Project: logback-core > Issue Type: Sub-task > Affects Versions: 0.9.9 > Environment: Operating System: Windows > Platform: PC > Reporter: Toni Heimala > Assignee: Ceki Gulcu > Priority: Blocker > Attachments: patch.txt, patch2.txt, patch3.txt > > > When you run logging into same file from many threads on a system that has more than one physical processor (Dual Core for example), a deadlock will occur after a while. This can not be reproduced on HyperThreading processors. Here's an example program that will demonstrate the behavior: > ----------------------------- > Main.java > ----------------------------- > import java.util.Date; > import java.util.concurrent.ScheduledThreadPoolExecutor; > import java.util.concurrent.TimeUnit; > import org.slf4j.Logger; > import org.slf4j.LoggerFactory; > import ch.qos.logback.classic.LoggerContext; > import ch.qos.logback.classic.joran.JoranConfigurator; > import ch.qos.logback.core.joran.spi.JoranException; > public class Main extends Thread > { > private final static String LOGGER_CONFIGURATION_FILE = "logger.xml"; > private final Logger logger = LoggerFactory.getLogger(Main.class); > > private final long start; > > public Main() > throws JoranException > { > start = new Date().getTime(); > LoggerContext lc = (LoggerContext)LoggerFactory.getILoggerFactory(); > JoranConfigurator configurator = new JoranConfigurator(); > lc.shutdownAndReset(); > configurator.setContext(lc); > configurator.doConfigure(LOGGER_CONFIGURATION_FILE); > } > > public void start() > { > ScheduledThreadPoolExecutor ex1 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex2 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex3 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex4 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex5 = new ScheduledThreadPoolExecutor(1); > ex1.scheduleAtFixedRate(new Task("EX1"), 10, 10, TimeUnit.MICROSECONDS); > ex2.scheduleAtFixedRate(new Task("EX2"), 10, 10, TimeUnit.MICROSECONDS); > ex3.scheduleAtFixedRate(new Task("EX3"), 10, 10, TimeUnit.MICROSECONDS); > ex4.scheduleAtFixedRate(new Task("EX4"), 10, 10, TimeUnit.MICROSECONDS); > ex5.scheduleAtFixedRate(new Task("EX5"), 10, 10, TimeUnit.MICROSECONDS); > > super.start(); > } > > public void run() > { > try > { > while(true) > { > logger.debug("[MAIN] {}", new Date().getTime() - start); > Thread.sleep(10); > } > } > catch (InterruptedException e) > { > logger.info("[MAIN]: Interrupted: {}", e.getMessage()); > } > } > > public static void main(String[] args) > { > try > { > Main main = new Main(); > main.start(); > } > catch (JoranException e) > { > System.out.println("Failed to load application: " + e.getMessage()); > } > } > } > ------------------------------- > Task.java > ------------------------------- > import java.util.Date; > import org.slf4j.Logger; > import org.slf4j.LoggerFactory; > public class Task implements Runnable > { > private final Logger logger = LoggerFactory.getLogger(Task.class); > private final Logger logger_main = LoggerFactory.getLogger(Main.class); > private final String name; > private final long start; > > public Task(final String name) > { > this.name = name; > start = new Date().getTime(); > } > public void run() > { > logger.debug("[{}] {}", name, new Date().getTime() - start); > logger_main.debug("[MAIN] - [{}] {}", name, new Date().getTime() - start); > } > } -- 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 0

[JIRA] Commented: (LBCORE-63) Deadlock when running on multiple core processors
by Robert Dale (JIRA) 23 Mar '09

23 Mar '09

[ http://jira.qos.ch/browse/LBCORE-63?page=com.atlassian.jira.plugin.system.i… ] Robert Dale commented on LBCORE-63: ----------------------------------- Any progress on this issue? I'm getting: java.lang.Thread.State: BLOCKED on ch.qos.logback.core.rolling.RollingFileAppender@2db3f4 owned by: http-127.0.0.1-8080-2 at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:439) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:393) at ch.qos.logback.classic.Logger.debug(Logger.java:500) Thanks. > Deadlock when running on multiple core processors > ------------------------------------------------- > > Key: LBCORE-63 > URL: http://jira.qos.ch/browse/LBCORE-63 > Project: logback-core > Issue Type: Sub-task > Affects Versions: 0.9.9 > Environment: Operating System: Windows > Platform: PC > Reporter: Toni Heimala > Assignee: Ceki Gulcu > Priority: Blocker > Attachments: patch.txt, patch2.txt, patch3.txt > > > When you run logging into same file from many threads on a system that has more than one physical processor (Dual Core for example), a deadlock will occur after a while. This can not be reproduced on HyperThreading processors. Here's an example program that will demonstrate the behavior: > ----------------------------- > Main.java > ----------------------------- > import java.util.Date; > import java.util.concurrent.ScheduledThreadPoolExecutor; > import java.util.concurrent.TimeUnit; > import org.slf4j.Logger; > import org.slf4j.LoggerFactory; > import ch.qos.logback.classic.LoggerContext; > import ch.qos.logback.classic.joran.JoranConfigurator; > import ch.qos.logback.core.joran.spi.JoranException; > public class Main extends Thread > { > private final static String LOGGER_CONFIGURATION_FILE = "logger.xml"; > private final Logger logger = LoggerFactory.getLogger(Main.class); > > private final long start; > > public Main() > throws JoranException > { > start = new Date().getTime(); > LoggerContext lc = (LoggerContext)LoggerFactory.getILoggerFactory(); > JoranConfigurator configurator = new JoranConfigurator(); > lc.shutdownAndReset(); > configurator.setContext(lc); > configurator.doConfigure(LOGGER_CONFIGURATION_FILE); > } > > public void start() > { > ScheduledThreadPoolExecutor ex1 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex2 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex3 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex4 = new ScheduledThreadPoolExecutor(1); > ScheduledThreadPoolExecutor ex5 = new ScheduledThreadPoolExecutor(1); > ex1.scheduleAtFixedRate(new Task("EX1"), 10, 10, TimeUnit.MICROSECONDS); > ex2.scheduleAtFixedRate(new Task("EX2"), 10, 10, TimeUnit.MICROSECONDS); > ex3.scheduleAtFixedRate(new Task("EX3"), 10, 10, TimeUnit.MICROSECONDS); > ex4.scheduleAtFixedRate(new Task("EX4"), 10, 10, TimeUnit.MICROSECONDS); > ex5.scheduleAtFixedRate(new Task("EX5"), 10, 10, TimeUnit.MICROSECONDS); > > super.start(); > } > > public void run() > { > try > { > while(true) > { > logger.debug("[MAIN] {}", new Date().getTime() - start); > Thread.sleep(10); > } > } > catch (InterruptedException e) > { > logger.info("[MAIN]: Interrupted: {}", e.getMessage()); > } > } > > public static void main(String[] args) > { > try > { > Main main = new Main(); > main.start(); > } > catch (JoranException e) > { > System.out.println("Failed to load application: " + e.getMessage()); > } > } > } > ------------------------------- > Task.java > ------------------------------- > import java.util.Date; > import org.slf4j.Logger; > import org.slf4j.LoggerFactory; > public class Task implements Runnable > { > private final Logger logger = LoggerFactory.getLogger(Task.class); > private final Logger logger_main = LoggerFactory.getLogger(Main.class); > private final String name; > private final long start; > > public Task(final String name) > { > this.name = name; > start = new Date().getTime(); > } > public void run() > { > logger.debug("[{}] {}", name, new Date().getTime() - start); > logger_main.debug("[MAIN] - [{}] {}", name, new Date().getTime() - start); > } > } -- 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 0

Replacing CallerData class
by Ceki Gulcu 20 Mar '09

20 Mar '09

Hello, I would like to replace the CallerData class with StackTraceElement. The two classes contain the same fields. StackTraceElement is part of the JDK. I can think of no valid reason to duplicate a class found in the JDK. Comments/objections? -- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch

5 17

svn commit: r2252 - in logback/trunk/logback-classic/src: main/java/ch/qos/logback/classic/db main/java/ch/qos/logback/classic/log4j main/java/ch/qos/logback/classic/pattern main/java/ch/qos/logback/classic/spi test/java/ch/qos/logback/classic/corpus test/java/ch/qos/logback/classic/db test/java/ch/qos/logback/classic/spi
by noreply.ceki＠qos.ch 20 Mar '09

20 Mar '09

Author: ceki Date: Fri Mar 20 16:35:21 2009 New Revision: 2252 Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/db/DBAppender.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/log4j/XMLLayout.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/CallerDataConverter.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/ClassOfCallerConverter.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/FileOfCallerConverter.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/LineOfCallerConverter.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/MethodOfCallerConverter.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/CallerData.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/ILoggingEvent.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEvent.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEventVO.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/corpus/CorpusModel.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/db/DBAppenderTest.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/CallerDataTest.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/PubLoggingEventVO.java Log: As discussed in the dev mailing list, LoggingEvent now stores caller data in the form of StackTraceElement[] instead of CallerData[]. CallerData class now only extracts caller data. It has no instance variables. Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/db/DBAppender.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/db/DBAppender.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/db/DBAppender.java Fri Mar 20 16:35:21 2009 @@ -19,7 +19,6 @@ import java.util.Map; import java.util.Set; -import ch.qos.logback.classic.spi.CallerData; import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.classic.spi.StackTraceElementProxy; import ch.qos.logback.core.db.DBAppenderBase; @@ -106,9 +105,9 @@ stmt.setShort(6, DBHelper.computeReferenceMask(event)); } - void bindCallerDataWithPreparedStatement(PreparedStatement stmt, CallerData[] callerDataArray) + void bindCallerDataWithPreparedStatement(PreparedStatement stmt, StackTraceElement[] callerDataArray) throws SQLException { - CallerData callerData = callerDataArray[0]; + StackTraceElement callerData = callerDataArray[0]; if (callerData != null) { stmt.setString(7, callerData.getFileName()); stmt.setString(8, callerData.getClassName()); Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/log4j/XMLLayout.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/log4j/XMLLayout.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/log4j/XMLLayout.java Fri Mar 20 16:35:21 2009 @@ -13,7 +13,6 @@ import java.util.Set; import java.util.Map.Entry; -import ch.qos.logback.classic.spi.CallerData; import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.classic.spi.IThrowableProxy; import ch.qos.logback.classic.spi.StackTraceElementProxy; @@ -137,9 +136,9 @@ } if (locationInfo) { - CallerData[] callerDataArray = event.getCallerData(); + StackTraceElement[] callerDataArray = event.getCallerData(); if (callerDataArray != null && callerDataArray.length > 0) { - CallerData immediateCallerData = callerDataArray[0]; + StackTraceElement immediateCallerData = callerDataArray[0]; buf.append(" <log4j:locationInfo class=\""); buf.append(immediateCallerData.getClassName()); buf.append("\"\r\n"); Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/CallerDataConverter.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/CallerDataConverter.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/CallerDataConverter.java Fri Mar 20 16:35:21 2009 @@ -110,7 +110,7 @@ } } - CallerData[] cda = le.getCallerData(); + StackTraceElement[] cda = le.getCallerData(); if (cda != null && cda.length > 0) { int limit = depth < cda.length ? depth : cda.length; Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/ClassOfCallerConverter.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/ClassOfCallerConverter.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/ClassOfCallerConverter.java Fri Mar 20 16:35:21 2009 @@ -16,7 +16,7 @@ protected String getFullyQualifiedName(ILoggingEvent event) { - CallerData[] cda = event.getCallerData(); + StackTraceElement[] cda = event.getCallerData(); if (cda != null && cda.length > 0) { return cda[0].getClassName(); } else { Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/FileOfCallerConverter.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/FileOfCallerConverter.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/FileOfCallerConverter.java Fri Mar 20 16:35:21 2009 @@ -15,7 +15,7 @@ public class FileOfCallerConverter extends ClassicConverter { public String convert(ILoggingEvent le) { - CallerData[] cda = le.getCallerData(); + StackTraceElement[] cda = le.getCallerData(); if (cda != null && cda.length > 0) { return cda[0].getFileName(); } else { Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/LineOfCallerConverter.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/LineOfCallerConverter.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/LineOfCallerConverter.java Fri Mar 20 16:35:21 2009 @@ -15,7 +15,7 @@ public class LineOfCallerConverter extends ClassicConverter { public String convert(ILoggingEvent le) { - CallerData[] cda = le.getCallerData(); + StackTraceElement[] cda = le.getCallerData(); if (cda != null && cda.length > 0) { return Integer.toString(cda[0].getLineNumber()); } else { Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/MethodOfCallerConverter.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/MethodOfCallerConverter.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/MethodOfCallerConverter.java Fri Mar 20 16:35:21 2009 @@ -15,7 +15,7 @@ public class MethodOfCallerConverter extends ClassicConverter { public String convert(ILoggingEvent le) { - CallerData[] cda = le.getCallerData(); + StackTraceElement[] cda = le.getCallerData(); if (cda != null && cda.length > 0) { return cda[0].getMethodName(); } else { Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/CallerData.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/CallerData.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/CallerData.java Fri Mar 20 16:35:21 2009 @@ -12,13 +12,13 @@ import ch.qos.logback.core.CoreConstants; /** - * The internal representation of caller location information. + * This class computes caller data returning the result in the form + * of a StackTraceElement array. * * @author Ceki Gülcü */ -public class CallerData implements java.io.Serializable { +public class CallerData { - private static final long serialVersionUID = 2473626903716082403L; /** * When caller information is not available this constant is used for file @@ -40,58 +40,21 @@ /** * This value is returned in case no caller data could be extracted. */ - public static CallerData[] EMPTY_CALLER_DATA_ARRAY = new CallerData[0]; + public static StackTraceElement[] EMPTY_CALLER_DATA_ARRAY = new StackTraceElement[0]; - /** - * Caller's line number. - */ - int lineNumber; - - /** - * Caller's file name. - */ - String fileName; - - /** - * Caller's fully qualified class name. - */ - String className; - - /** - * Caller's method name. - */ - String methodName; - - boolean nativeMethod = false; - - public CallerData(String fileName, String className, String methodName, - int lineNumber) { - this.fileName = fileName; - this.className = className; - this.methodName = methodName; - this.lineNumber = lineNumber; - } - - public CallerData(StackTraceElement ste) { - className = ste.getClassName(); - fileName = ste.getFileName(); - methodName = ste.getMethodName(); - lineNumber = ste.getLineNumber(); - nativeMethod = ste.isNativeMethod(); - } /** * Extract caller data information as an array based on a Throwable passed as * parameter */ - public static CallerData[] extract(Throwable t, String fqnOfInvokingClass, - final int maxDepth) { + public static StackTraceElement[] extract(Throwable t, + String fqnOfInvokingClass, final int maxDepth) { if (t == null) { return null; } StackTraceElement[] steArray = t.getStackTrace(); - CallerData[] callerDataArray; + StackTraceElement[] callerDataArray; int found = LINE_NA; for (int i = 0; i < steArray.length; i++) { @@ -114,9 +77,9 @@ int availableDepth = steArray.length - found; int desiredDepth = maxDepth < (availableDepth) ? maxDepth : availableDepth; - callerDataArray = new CallerData[desiredDepth]; + callerDataArray = new StackTraceElement[desiredDepth]; for (int i = 0; i < desiredDepth; i++) { - callerDataArray[i] = new CallerData(steArray[found+i]); + callerDataArray[i] = steArray[found + i]; } return callerDataArray; } @@ -134,95 +97,4 @@ } } - public boolean equals(Object o) { - // LogLog.info("equals called"); - if (this == o) { - return true; - } - - if (!(o instanceof CallerData)) { - // LogLog.info("inequality point 1"); - return false; - } - - CallerData r = (CallerData) o; - - if (!getClassName().equals(r.getClassName())) { - // LogLog.info("inequality point 2"); - return false; - } - - if (!getFileName().equals(r.getFileName())) { - // LogLog.info("inequality point 3"); - return false; - } - - if (!getMethodName().equals(r.getMethodName())) { - // LogLog.info("inequality point 4"); - return false; - } - - if (!(lineNumber == r.lineNumber)) { - // LogLog.info("inequality point 5"); - return false; - } - - return true; - } - - /** - * Return the fully qualified class name of the caller making the logging - * request. - */ - public String getClassName() { - return className; - } - - /** - * Return the file name of the caller. - * - * <p> This information is not always available. - */ - public String getFileName() { - return fileName; - } - - /** - * Returns the line number of the caller. - * - * <p> This information is not always available. - */ - public int getLineNumber() { - return lineNumber; - } - - /** - * Returns the method name of the caller. - */ - public String getMethodName() { - return methodName; - } - - public String toString() { - StringBuffer buf = new StringBuffer(); - buf.append(getClassName()); - buf.append('.'); - buf.append(getMethodName()); - buf.append('('); - if (isNativeMethod()) { - buf.append("Native Method"); - } else if (getFileName() == null) { - buf.append("Unknown Source"); - } else { - buf.append(getFileName()); - buf.append(':'); - buf.append(getLineNumber()); - } - buf.append(')'); - return buf.toString(); - } - - public boolean isNativeMethod() { - return nativeMethod; - } } Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/ILoggingEvent.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/ILoggingEvent.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/ILoggingEvent.java Fri Mar 20 16:35:21 2009 @@ -31,14 +31,14 @@ public IThrowableProxy getThrowableProxy(); /** - * Return {@link CallerData} associated with this event. Note that calling + * Return caller data associated with this event. Note that calling * this event may trigger the computation of caller data. * - * @return the CallerData associated with this event. + * @return the caller data associated with this event. * * @see #hasCallerData() */ - public CallerData[] getCallerData(); + public StackTraceElement[] getCallerData(); /** * If this event has caller data, then true is returned. Otherwise the Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEvent.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEvent.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEvent.java Fri Mar 20 16:35:21 2009 @@ -75,7 +75,7 @@ private ThrowableProxy throwableProxy; - private CallerData[] callerDataArray; + private StackTraceElement[] callerDataArray; private Marker marker; @@ -241,7 +241,7 @@ * <p> Note that after serialization it is impossible to correctly extract * caller information. </p> */ - public CallerData[] getCallerData() { + public StackTraceElement[] getCallerData() { if (callerDataArray == null) { callerDataArray = CallerData.extract(new Throwable(), fqnOfLoggerClass, loggerContext.getMaxCallerDataDepth()); } @@ -252,7 +252,7 @@ return (callerDataArray != null); } - public void setCallerData(CallerData[] callerDataArray) { + public void setCallerData(StackTraceElement[] callerDataArray) { this.callerDataArray = callerDataArray; } Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEventVO.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEventVO.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEventVO.java Fri Mar 20 16:35:21 2009 @@ -41,7 +41,7 @@ private transient Object[] argumentArray; private ThrowableProxyVO throwableProxy; - private CallerData[] callerDataArray; + private StackTraceElement[] callerDataArray; private Marker marker; private Map<String, String> mdcPropertyMap; private long timeStamp; @@ -103,7 +103,7 @@ return throwableProxy; } - public CallerData[] getCallerData() { + public StackTraceElement[] getCallerData() { return callerDataArray; } Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/corpus/CorpusModel.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/corpus/CorpusModel.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/corpus/CorpusModel.java Fri Mar 20 16:35:21 2009 @@ -14,7 +14,6 @@ import ch.qos.logback.classic.Level; import ch.qos.logback.classic.LoggerContext; -import ch.qos.logback.classic.spi.CallerData; import ch.qos.logback.classic.spi.ClassPackagingData; import ch.qos.logback.classic.spi.LoggerContextVO; import ch.qos.logback.classic.spi.StackTraceElementProxy; @@ -184,15 +183,15 @@ } } - public CallerData[] getRandomCallerData(int depth, String loggerName) { - CallerData[] cda = new CallerData[depth]; - CallerData cd = new CallerData(extractLastPart(loggerName), loggerName, - getRandomJavaIdentifier(), 0); + public StackTraceElement[] getRandomCallerData(int depth, String loggerName) { + StackTraceElement[] cda = new StackTraceElement[depth]; + StackTraceElement cd = new StackTraceElement(loggerName, + getRandomJavaIdentifier(), extractLastPart(loggerName), 0); cda[0] = cd; for (int i = 1; i < depth; i++) { String ln = getRandomLoggerNameFromPool(loggerNamePool); - cda[i] = new CallerData(extractLastPart(ln), ln, - getRandomJavaIdentifier(), i * 10); + cda[i] = new StackTraceElement(ln, getRandomJavaIdentifier(), + extractLastPart(ln), i * 10); } return cda; } Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/db/DBAppenderTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/db/DBAppenderTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/db/DBAppenderTest.java Fri Mar 20 16:35:21 2009 @@ -15,7 +15,6 @@ import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Logger; import ch.qos.logback.classic.LoggerContext; -import ch.qos.logback.classic.spi.CallerData; import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.classic.spi.LoggingEvent; import ch.qos.logback.core.db.DriverManagerConnectionSource; @@ -77,7 +76,7 @@ assertEquals(event.getLevel().toString(), rs.getString(4)); assertEquals(event.getThreadName(), rs.getString(5)); assertEquals(DBHelper.computeReferenceMask(event), rs.getShort(6)); - CallerData callerData = event.getCallerData()[0]; + StackTraceElement callerData = event.getCallerData()[0]; assertEquals(callerData.getFileName(), rs.getString(7)); assertEquals(callerData.getClassName(), rs.getString(8)); assertEquals(callerData.getMethodName(), rs.getString(9)); Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/CallerDataTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/CallerDataTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/CallerDataTest.java Fri Mar 20 16:35:21 2009 @@ -14,7 +14,7 @@ Throwable t = new Throwable(); StackTraceElement[] steArray = t.getStackTrace(); - CallerData[] cda = CallerData.extract(t, CallerDataTest.class.getName(), 50); + StackTraceElement[] cda = CallerData.extract(t, CallerDataTest.class.getName(), 50); assertNotNull(cda); assertTrue(cda.length > 0); assertEquals(steArray.length - 1, cda.length); @@ -27,7 +27,7 @@ */ @Test public void testDeferredProcessing() { - CallerData[] cda = CallerData.extract(new Throwable(), "com.inexistent.foo", 10); + StackTraceElement[] cda = CallerData.extract(new Throwable(), "com.inexistent.foo", 10); assertNotNull(cda); assertEquals(0, cda.length); } Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/PubLoggingEventVO.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/PubLoggingEventVO.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/PubLoggingEventVO.java Fri Mar 20 16:35:21 2009 @@ -46,7 +46,7 @@ public Object[] argumentArray; public IThrowableProxy throwableProxy; - public CallerData[] callerDataArray; + public StackTraceElement[] callerDataArray; public Marker marker; public Map<String, String> mdcPropertyMap; public long timeStamp; @@ -95,7 +95,7 @@ return throwableProxy; } - public CallerData[] getCallerData() { + public StackTraceElement[] getCallerData() { return callerDataArray; }

1 0

Small LoggingEvent suggestion
by Joern Huxhorn 20 Mar '09

20 Mar '09

Hi all, I'd like to suggest to include thread id (in addition to the name) in LoggingEvent. I'd use a Long as the data type instead of long so it's possible to distinguish if it was initialized or not. The name alone isn't guaranteed to be unique so the id wouldn't hurt, imho. Joern.

2 5

[JIRA] Commented: (LBCORE-26) TimeBasedRollingPolicy append logs into a old log file, instead of rolling the log file.
by Pavel (JIRA) 19 Mar '09

19 Mar '09

[ http://jira.qos.ch/browse/LBCORE-26?page=com.atlassian.jira.plugin.system.i… ] Pavel commented on LBCORE-26: ----------------------------- I experience the described issue with latest 0.9.15 version. Configuration file: <?xml version="1.0" encoding="UTF-8" ?> <configuration debug="true"> <jmxConfigurator/>  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <FileNamePattern>D:\My Projects\cgp\Script\src\de\cgp\script\test\${script.name}.%d{yyyy-MM-dd_HH-mm}.log.zip</FileNamePattern> <MaxHistory>30</MaxHistory> </rollingPolicy> <param name="file" value="D:\My Projects\cgp\Script\src\de\cgp\script\test\${script.name}.log"/> <layout class="ch.qos.logback.classic.PatternLayout"> <param name="Pattern" value="%d{ISO8601} %-5p [%t] %c{1}: %m%n"/> </layout> </appender> <root level="info"> <appender-ref ref="FILE"/> </root> </configuration> Java Code: public class TestRollOver { private static Logger logger = LoggerFactory.getLogger(TestRollOver.class); public TestRollOver() { //Load Context LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory(); try { JoranConfigurator configurator = new JoranConfigurator(); configurator.setContext(lc); //reset config lc.reset(); //set property lc.putProperty("script.name", this.getClass().getSimpleName()); //configure try { configurator.doConfigure(new FileInputStream( "somepath\\logback.xml")); } catch (FileNotFoundException e) { System.err.println(e); } } catch (JoranException je) { System.err.println(je); } //Test logger.info("Test"); //Second test message logger.info("Test"); } public static void main(String[] args) { new TestRollOver(); } } if we start the script once per 2-3 minutes - log is written in the same file - expected behavior - roll over every minute. But if in step by step debug we call the first info method, wait for 1 minute and then step to the second call - log file is rolled over as expected. conclusion - roll over policy seems to be not preserved between application starts (configuration routines). > TimeBasedRollingPolicy append logs into a old log file, instead of rolling the log file. > ---------------------------------------------------------------------------------------- > > Key: LBCORE-26 > URL: http://jira.qos.ch/browse/LBCORE-26 > Project: logback-core > Issue Type: Bug > Components: Rolling > Affects Versions: unspecified > Environment: Operating System: All > Platform: All > Reporter: Tsutomu YANO > Assignee: Logback dev list > Priority: Critical > Fix For: 0.9.12 > > > If you use TimeBasedRollingPolicy to rollover a log file and no log wasn't wrote into the log beyond the timing of rollover, and if you restart your application, the log file doesn't roll, then new log will be appended into old log file. > EVIDENCE: > 1. in logback.xml, set your FileNamePattern like 'log.%d{yyyy-MM-dd_HH-mm}.log'. > 2. Simply do a kind of thing, which will make some logs into your log file. > 3. Wait for some minutes. > 4. restart your application. > 5. do a kind of thing, which will make some logs into your log file. > the FileNamePattern is 'log.%d{yyyy-MM-dd_HH-mm}.log', so the log file will be roll every minutes. On case 5 of above example, the log file should be roll over, because some minutes already have passed after last logs wrote into the log file. But the file didn't be roll overed. > THE CAUSE: > In start() method of TimeBasedRollingPolicy, you initialize a variable 'lastCheck' to System.currentTimeStamp(). So if you restart your application, the last check time will be set to just NOW. > you should initialize the variable to a last modified time of a current log file. > See below source code. from '//modified by Tsutomu YANO' to '//until here'. > SOURCE: > public void start() { > // set the LR for our utility object > util.setContext(this.context); > compress.setContext(this.context); > // find out period from the filename pattern > if (fileNamePatternStr != null) { > fileNamePattern = new FileNamePattern(fileNamePatternStr, this.context); > determineCompressionMode(); > } else { > addWarn(FNP_NOT_SET); > addWarn(SEE_FNP_NOT_SET); > throw new IllegalStateException(FNP_NOT_SET + SEE_FNP_NOT_SET); > } > DateTokenConverter dtc = fileNamePattern.getDateTokenConverter(); > if (dtc == null) { > throw new IllegalStateException("FileNamePattern [" + fileNamePattern.getPattern() + "] does not contain a valid DateToken"); > } > int len = fileNamePatternStr.length(); > switch (compressionMode) { > case Compress.GZ: > activeFileNamePattern = new FileNamePattern(fileNamePatternStr.substring(0, len - 3), this.context); > break; > case Compress.ZIP: > activeFileNamePattern = new FileNamePattern(fileNamePatternStr.substring(0, len - 4), this.context); > break; > case Compress.NONE: > activeFileNamePattern = fileNamePattern; > } > addInfo("Will use the pattern " + activeFileNamePattern + " for the active file"); > rc = new RollingCalendar(); > rc.init(dtc.getDatePattern()); > addInfo("The date pattern is '" + dtc.getDatePattern() + "' from file name pattern '" + fileNamePattern.getPattern() + "'."); > rc.printPeriodicity(this); > > //modified by Tsutomu YANO > //if a current log file exists, initialize a 'lastCheck' variable to the > //last modified date of the file. > File currentFile = new File(getParentFileName()); > if(currentFile.exists() && currentFile.canRead()) { > lastCheck.setTime(currentFile.lastModified()); > } else { > // currentTime = System.currentTimeMillis(); > lastCheck.setTime(getCurrentTime()); > } > //until here > > nextCheck = rc.getNextCheckMillis(lastCheck); > // Date nc = new Date(); > // nc.setTime(nextCheck); > } -- 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 0

[JIRA] Created: (LBCLASSIC-115) LoggerContextRemoteView is "leaking" the property map to different appenders
by Joern Huxhorn (JIRA) 16 Mar '09

16 Mar '09

LoggerContextRemoteView is "leaking" the property map to different appenders ---------------------------------------------------------------------------- Key: LBCLASSIC-115 URL: http://jira.qos.ch/browse/LBCLASSIC-115 Project: logback-classic Issue Type: Bug Components: appender Affects Versions: 0.9.15 Reporter: Joern Huxhorn Assignee: Logback dev list Priority: Minor The map returned by LoggerContextRemoteView.getPropertyMap() is the same for every attached appender. This means that appenders are able to change the map for other appenders. I didn't really expect this. Suggestion: Return either a copy of the map or an unmodifiable version of it. -- 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 0

[JIRA] Created: (LBCLASSIC-107) thrown from toString exception swallowed
by Anton Lebedevich (JIRA) 15 Mar '09

15 Mar '09

thrown from toString exception swallowed ---------------------------------------- Key: LBCLASSIC-107 URL: http://jira.qos.ch/browse/LBCLASSIC-107 Project: logback-classic Issue Type: Bug Affects Versions: 0.9.15 Environment: java version "1.6.0_12" Java(TM) SE Runtime Environment (build 1.6.0_12-b04) Java HotSpot(TM) Client VM (build 11.2-b01, mixed mode, sharing) slf4j-api:1.5.6 Reporter: Anton Lebedevich Assignee: Logback dev list package loggerbug; import org.slf4j.Logger; import org.slf4j.LoggerFactory; public class Loggerbug { private static final Logger logger = LoggerFactory.getLogger(Loggerbug.class); static class ThrowsToString { @Override public String toString() { throw new RuntimeException("from toString"); } } public static void main(String[] args) { ThrowsToString probe = new ThrowsToString(); logger.info("probe is {}", probe); System.out.println("no exception"); } } prints "no exception" with logback-classic, but with slf4j-simple output is: Exception in thread "main" java.lang.RuntimeException: from toString at loggerbug.Loggerbug$ThrowsToString.toString(Loggerbug.java:13) at java.lang.String.valueOf(String.java:2827) at java.lang.StringBuffer.append(StringBuffer.java:219) at org.slf4j.helpers.MessageFormatter.deeplyAppendParameter(MessageFormatter.java:237) at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:196) at org.slf4j.helpers.MessageFormatter.format(MessageFormatter.java:138) at org.slf4j.impl.SimpleLogger.formatAndLog(SimpleLogger.java:222) at org.slf4j.impl.SimpleLogger.info(SimpleLogger.java:258) at loggerbug.Loggerbug.main(Loggerbug.java:20) -- 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 2