DEADLOCK: Between Throwable.PrintStackTrace and ConsoleHandler

FULL PRODUCT VERSION :
java version "1.6.0_05"
Java(TM) SE Runtime Environment (build 1.6.0_05-b13)
Java HotSpot(TM) Client VM (build 10.0-b19, mixed mode, sharing)

and

java version "1.4.2_13"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.2_13-b06)
Java HotSpot(TM) Client VM (build 1.4.2_13-b06, mixed mode)


ADDITIONAL OS VERSION INFORMATION :
All:

e.g.

SunOS server 5.10 Generic_118833-24 sun4u sparc SUNW,Sun-Fire-V210

CYGWIN_NT-5.1 desktop 1.5.25(0.156/4/2) 2008-04-17 12:11 i686 Cygwin


A DESCRIPTION OF THE PROBLEM :
Deadlock between j.u.l.Logger.log() to ConsoleHandler in one thread and j.l.Throwable.printStackTrace() in another where the Throwable.getLocalizedMessage() call chain results in a call to j.u.l.Logger.log() to ConsoleHandler.

For example:

Found one Java-level deadlock:
=============================
"[T126] Started [Jun 17 06:09:07] Worker-42":
  waiting to lock monitor 0x000e1c18 (object 0x942d1448, a java.io.PrintStream),
  which is held by "main"
"main":
  waiting to lock monitor 0x000e1ba8 (object 0x94530dd0, a java.util.logging.ConsoleHandler),
  which is held by "[T126] Started [Jun 17 06:09:07] Worker-42"

Java stack information for the threads listed above:
===================================================
"[T126] Started [Jun 17 06:09:07] Worker-42":
at java.io.PrintStream.write(PrintStream.java:256)
- waiting to lock <0x942d1448> (a java.io.PrintStream)
at sun.nio.cs.StreamEncoder$ConverterSE.implFlushBuffer(StreamEncoder.java:236)
at sun.nio.cs.StreamEncoder$ConverterSE.implFlush(StreamEncoder.java:242)
at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:152)
- locked <0x94531020> (a java.io.OutputStreamWriter)
at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:213)
at java.util.logging.StreamHandler.flush(StreamHandler.java:224)
- locked <0x94530dd0> (a java.util.logging.ConsoleHandler)
at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:88)
at java.util.logging.Logger.log(Logger.java:424)
at java.util.logging.Logger.doLog(Logger.java:446)
at java.util.logging.Logger.log(Logger.java:469)
at java.util.logging.Logger.fine(Logger.java:1016)
at com.digitalriver.integration.job.JobImpl.notifyLogs(JobImpl.java:753)
at com.digitalriver.integration.job.RealtimeJobImpl$JobNotifierHelper.run(RealtimeJobImpl.java:735)
at com.digitalriver.integration.job.RealtimeJobImpl$8.doWork(RealtimeJobImpl.java:670)
at com.digitalriver.system.task.AbstractTask.execute(AbstractTask.java:21)
at sun.reflect.GeneratedMethodAccessor257.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:324)
at com.atlassian.util.profiling.object.ObjectProfiler.profiledInvoke(ObjectProfiler.java:138)
at com.atlassian.util.profiling.object.TimerInvocationHandler.invoke(ObjectProfiler.java:234)
at $Proxy90.execute(Unknown Source)
at com.digitalriver.system.task.ThreadPoolTaskRunner$RunnableTaskAdapter.run(ThreadPoolTaskRunner.java:133)
at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:735)
at com.digitalriver.logging.ThreadTagger.run(ThreadTagger.java:19)
at java.lang.Thread.run(Thread.java:534)
"main":
at java.util.logging.StreamHandler.publish(StreamHandler.java:173)
- waiting to lock <0x94530dd0> (a java.util.logging.ConsoleHandler)
at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:87)
at java.util.logging.Logger.log(Logger.java:424)
at java.util.logging.Logger.doLog(Logger.java:446)
at java.util.logging.Logger.log(Logger.java:469)
at java.util.logging.Logger.warning(Logger.java:968)
at com.digitalriver.site.Site.getAttribute(Site.java:749)
at com.digitalriver.site.Site.getAttribute(Site.java:727)
at com.digitalriver.site.Site.getAttribute(Site.java:720)
at com.digitalriver.site.Site.getAttribute(Site.java:714)
at com.digitalriver.site.Site.getAttribute(Site.java:710)
at com.digitalriver.site.Site.getAttributeValue(Site.java:605)
at com.digitalriver.util.MMResources.getStringForSite(MMResources.java:42)
at com.digitalriver.util.MMResources.getStringForSite(MMResources.java:33)
at com.digitalriver.system.MException.localize(MException.java:460)
at com.digitalriver.system.MException.getLocalizedMessage(MException.java:390)
at java.lang.Throwable.toString(Throwable.java:343)
at java.lang.String.valueOf(String.java:2131)
at java.io.PrintStream.print(PrintStream.java:462)
at java.io.PrintStream.println(PrintStream.java:599)
- locked <0x942d1448> (a java.io.PrintStream)
at java.lang.Throwable.printStackTrace(Throwable.java:461)
- locked <0x942d1448> (a java.io.PrintStream)
at java.lang.Throwable.printStackTrace(Throwable.java:451)
at com.digitalriver.payment.adapter.cpg.CpgAdapter.execute(CpgAdapter.java:686)
at com.digitalriver.payment.PaymentModuleImpl.execute(PaymentModuleImpl.java:715)
at sun.reflect.GeneratedMethodAccessor351.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:324)
at org.picocontainer.alternatives.ImplementationHidingComponentAdapter$1.invoke(ImplementationHidingComponentAdapter.java:81)
at dynaop.util.Classes.invoke(Classes.java:110)
at dynaop.InvocationImpl.invokeTarget(InvocationImpl.java:50)
at dynaop.InvocationImpl.proceed(InvocationImpl.java:37)
at org.nanocontainer.aop.dynaop.InvocationAdapter.proceed(InvocationAdapter.java:57)
at com.digitalriver.system.interceptor.ProfilingInterceptor.invoke(ProfilingInterceptor.java:22)
at org.nanocontainer.aop.dynaop.MethodInterceptorAdapter.intercept(MethodInterceptorAdapter.java:40)
at dynaop.InvocationImpl.proceed(InvocationImpl.java:31)
at dynaop.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:125)
at dynaop.DynamicProxyInvocationHandler.invoke(DynamicProxyInvocationHandler.java:28)
at $Proxy34.execute(Unknown Source)
at com.digitalriver.requisitioning.RequisitioningModuleImpl.authorize(RequisitioningModuleImpl.java:1268)
at com.digitalriver.requisitioning.RequisitioningModuleImpl.authorize(RequisitioningModuleImpl.java:1208)
at com.digitalriver.requisitioning.RequisitioningModuleImpl.authorize(RequisitioningModuleImpl.java:1195)
at com.digitalriver.requisitioning.RequisitioningModuleImpl.placeRequisition(RequisitioningModuleImpl.java:1041)
at sun.reflect.GeneratedMethodAccessor323.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:324)
at org.picocontainer.alternatives.ImplementationHidingComponentAdapter$1.invoke(ImplementationHidingComponentAdapter.java:81)
at dynaop.util.Classes.invoke(Classes.java:110)
at dynaop.InvocationImpl.invokeTarget(InvocationImpl.java:50)
at dynaop.InvocationImpl.proceed(InvocationImpl.java:37)
at org.nanocontainer.aop.dynaop.InvocationAdapter.proceed(InvocationAdapter.java:57)
at com.digitalriver.system.interceptor.ProfilingInterceptor.invoke(ProfilingInterceptor.java:22)
at org.nanocontainer.aop.dynaop.MethodInterceptorAdapter.intercept(MethodInterceptorAdapter.java:40)
at dynaop.InvocationImpl.proceed(InvocationImpl.java:31)
at dynaop.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:125)
at dynaop.DynamicProxyInvocationHandler.invoke(DynamicProxyInvocationHandler.java:28)
at $Proxy30.placeRequisition(Unknown Source)
at com.digitalriver.subscription.CreateNewOrder.create(CreateNewOrder.java:93)
at com.digitalriver.subscription.SubscriptionImpl.requestRenewal(SubscriptionImpl.java:460)
at com.digitalriver.subscription.SubscriptionModuleImpl.renewSubscription(SubscriptionModuleImpl.java:183)
at sun.reflect.GeneratedMethodAccessor301.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:324)
at org.picocontainer.alternatives.ImplementationHidingComponentAdapter$1.invoke(ImplementationHidingComponentAdapter.java:81)
at dynaop.util.Classes.invoke(Classes.java:110)
at dynaop.InvocationImpl.invokeTarget(InvocationImpl.java:50)
at dynaop.InvocationImpl.proceed(InvocationImpl.java:37)
at org.nanocontainer.aop.dynaop.InvocationAdapter.proceed(InvocationAdapter.java:57)
at com.digitalriver.system.interceptor.ProfilingInterceptor.invoke(ProfilingInterceptor.java:22)
at org.nanocontainer.aop.dynaop.MethodInterceptorAdapter.intercept(MethodInterceptorAdapter.java:40)
at dynaop.InvocationImpl.proceed(InvocationImpl.java:31)
at dynaop.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:125)
at dynaop.DynamicProxyInvocationHandler.invoke(DynamicProxyInvocationHandler.java:28)
at $Proxy56.renewSubscription(Unknown Source)
at com.digitalriver.subscription.RenewalJobManager.doWork(RenewalJobManager.java:96)
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:324)
at com.atlassian.util.profiling.object.ObjectProfiler.profiledInvoke(ObjectProfiler.java:138)
at com.atlassian.util.profiling.object.TimerInvocationHandler.invoke(ObjectProfiler.java:234)
at $Proxy107.doWork(Unknown Source)
at com.digitalriver.schedule.JobRunner.startJob(JobRunner.java:70)
at com.digitalriver.schedule.JobRunner.main(JobRunner.java:30)

Found 1 deadlock.

In this example, the localization implementation for the message indirectly invokes code which tries to log a message using j.u.l.Logger, but printStackTrace has already grabbed a lock on the console stream.

Calling Throwable.printStackTrace() in one thread and Logger.log() in another do not seem, on the face of it, like practices that an application could reasonably avoid. It seems like the only recourse for the application developer is to ensure that Throwable.toString() **never** executes code which calls j.u.l.Logger.log() ... which is a tall order.

Alternatively, printStackTrace might buffer its output to, for example, a ByteArrayOutputStream, so that calls to non-final methods (particularly, toString(), getMessage(), getLocalizedMessage(), etc) are not executed while holding the lock on the output stream argument.


STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
In a Java application whose java.util.logging configuration sends all log message to a ConsoleHandler, have two threads:

1) in a tight loop invoke Logger.info("log message").
2) in a tight loop invoke MyException.printStackTrace() where MyException.getLocalizedMessage() invokes Logger.info("localization message").

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
Console output contains mixture of "log message", "localization messages" and stack traces.
ACTUAL -
Application deadlocks.

ERROR MESSAGES/STACK TRACES THAT OCCUR :
See description.

REPRODUCIBILITY :
This bug can be reproduced often.

---------- BEGIN SOURCE ----------
import static org.junit.Assert.*;

import java.io.PrintStream;
import java.util.logging.Logger;

import org.apache.commons.lang.Validate;
import org.junit.Test;
import org.apache.commons.io.output.NullOutputStream;

/**
 * JUnit 4 test case for deadlock condition.
 */
@SuppressWarnings("all")
public class TestCase {
    /**
     * Number of logging iterations ... adjust as necessary to
     * produce deadlock ...
     */
    static final int ITERATION_COUNT = 1000;

    /**
     * The thread which produces log messages
     */
    public static class LoggingThread implements Runnable {
        private int iterations;
        public LoggingThread(final int iterationCount) {
            Validate.isTrue(iterationCount >= 0);
            this.iterations = iterationCount;
            return;
        }

        @Override
        public void run() {
            final Logger logger = Logger.getLogger(this.getClass().getName());
            for (int i = 0; i < this.iterations; i++) {
                logger.info("log message");
            }
        }
    }

    /**
     * An exception that causes a log message as part of localization.
     */
    public static class MyException extends RuntimeException {
        private static final long serialVersionUID = 7622101544691825647L;

        @Override
        public String getLocalizedMessage() {
            final Logger logger = Logger.getLogger(this.getClass().getName());
            logger.info("localization message");
            return super.getLocalizedMessage();
        }
    }

    /**
     * The test case ...
     */
    @Test
    public void testBug() {
        PrintStream stdErr = System.err;
        try {
            System.setErr(new PrintStream(new NullOutputStream()));
            final Throwable throwable = new MyException();
            final Thread loggingThread = new Thread(new LoggingThread(TestCase.ITERATION_COUNT));
            loggingThread.start();
            for (int i = 0; i < TestCase.ITERATION_COUNT; i++) {
                throwable.printStackTrace();
            }
        } finally {
            System.setErr(stdErr);
        }
    }
}

---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
public class Throwable implements Serializable {

...

    public void printStackTrace(PrintStream s) {
        ByteArrayOutputStream baos = new ByteArrayOutputStream();
        PrintStream buffer = new PrintStream(baos);
        buffer.println(this);
        StackTraceElement[] trace = getOurStackTrace();
        for (int i=0; i < trace.length; i++)
            buffer.println("\tat " + trace[i]);

        Throwable ourCause = getCause();
        if (ourCause != null)
            ourCause.printStackTraceAsCause(buffer, trace);
        buffer.close();
        synchronized (s) {
            s.write(baos.toByteArray(), 0, baos.size());
        }
    }


    public void printStackTrace(PrintWriter s) {
        CharArrayWriter caw = new CharArrayWriter();
        PrintWriter buffer = new PrintWriter(caw);
        buffer.println(this);
        StackTraceElement[] trace = getOurStackTrace();
        for (int i=0; i < trace.length; i++)
            buffer.println("\tat " + trace[i]);

        Throwable ourCause = getCause();
        if (ourCause != null)
            ourCause.printStackTraceAsCause(buffer, trace);
        buffer.close();
        synchronized (s) {
            s.write(caw.toCharArray(), 0, caw.size());
        }
    }