[ http://jira.qos.ch/browse/LBCORE-63?page=com.atlassian.jira.plugin.system.is... ] Paweł Paprota commented on LBCORE-63: ------------------------------------- What is the current status of this issue? I think I got hit by this one, at least that's what I'm seeing right now in Eclipse when I suspend all threads in my application - one thread has callAppenders in its stack trace and it hanged (yesterday) on socketWrite. Some of the other threads seem to be waiting on a lock in callAppenders. As a result, I don't see any more logging appended to my log file and the console. I'm using logback-core/classic 0.9.9 with slf4j 1.5.3. Did the Ralph's patch make it to any of the newer logback releases? I was not able to find any change log or release announcement for releases newer than 0.9.9... I would really appreciate some feedback, thank you. Below is the stack trace of the "offending" thread (only relevant calls included): Thread [Thread-12] (Suspended) SocketOutputStream.socketWrite0(FileDescriptor, byte[], int, int) line: not available [native method] SocketOutputStream.socketWrite(byte[], int, int) line: 92 SocketOutputStream.write(byte[], int, int) line: 136 ObjectOutputStream$BlockDataOutputStream.drain() line: 1685 ObjectOutputStream$BlockDataOutputStream.write(byte[], int, int, boolean) line: 1649 ObjectOutputStream.defaultWriteFields(Object, ObjectStreamClass) line: 1368 ObjectOutputStream.writeSerialData(Object, ObjectStreamClass) line: 1347 ObjectOutputStream.writeOrdinaryObject(Object, ObjectStreamClass, boolean) line: 1290 ObjectOutputStream.writeObject0(Object, boolean) line: 1079 ObjectOutputStream.writeArray(Object, ObjectStreamClass, boolean) line: 1251 ObjectOutputStream.writeObject0(Object, boolean) line: 1075 ObjectOutputStream.defaultWriteFields(Object, ObjectStreamClass) line: 1375 ObjectOutputStream.defaultWriteObject() line: 391 LoggingEvent.writeObject(ObjectOutputStream) line: 288 GeneratedMethodAccessor1118.invoke(Object, Object[]) line: not available DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 25 Method.invoke(Object, Object...) line: 585 ObjectStreamClass.invokeWriteObject(Object, ObjectOutputStream) line: 917 ObjectOutputStream.writeSerialData(Object, ObjectStreamClass) line: 1339 ObjectOutputStream.writeOrdinaryObject(Object, ObjectStreamClass, boolean) line: 1290 ObjectOutputStream.writeObject0(Object, boolean) line: 1079 ObjectOutputStream.writeObject(Object) line: 302 SocketAppender(SocketAppenderBase<E>).append(E) line: 163 SocketAppender(AppenderBase<E>).doAppend(E) line: 81 AppenderAttachableImpl<E>.appendLoopOnAppenders(E) line: 51 Logger.appendLoopOnAppenders(LoggingEvent) line: 282 Logger.callAppenders(LoggingEvent) line: 266 Logger.buildLoggingEventAndAppend(String, Marker, Level, String, Object[], Throwable) line: 487 Logger.filterAndLog(String, Marker, Level, String, Object, Object, Throwable) line: 460 Logger.debug(String, Object, Object) line: 406 And those are the ones being blocked: Thread [Thread-4] (Suspended) Logger.callAppenders(LoggingEvent) line: 265 Logger.buildLoggingEventAndAppend(String, Marker, Level, String, Object[], Throwable) line: 487 Logger.filterAndLog(String, Marker, Level, String, Object[], Throwable) line: 479 Logger.debug(String, Throwable) line: 414 Daemon Thread [ActiveMQ Connection Worker: tcp://localhost/127.0.0.1:61616] (Suspended) Logger.callAppenders(LoggingEvent) line: 265 Logger.buildLoggingEventAndAppend(String, Marker, Level, String, Object[], Throwable) line: 487 Logger.filterAndLog(String, Marker, Level, String, Object[], Throwable) line: 479 Logger.log(Marker, String, int, String, Throwable) line: 818 SLF4JLocationAwareLog.info(Object, Throwable) line: 152 AdvisoryConsumer.dispose() line: 58 ActiveMQConnection.close() line: 563 CachingConnectionFactory(SingleConnectionFactory).closeConnection(Connection) line: 364 CachingConnectionFactory(SingleConnectionFactory).resetConnection() line: 302 CachingConnectionFactory.resetConnection() line: 120 CachingConnectionFactory(SingleConnectionFactory).onException(JMSException) line: 283 SingleConnectionFactory$InternalChainedExceptionListener(ChainedExceptionListener).onException(JMSException) line: 60 ActiveMQConnection$3.run() line: 1690 ThreadPoolExecutor$Worker.runTask(Runnable) line: 650 ThreadPoolExecutor$Worker.run() line: 675 Thread.run() line: 595

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