deadlock in java.util.logging

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

deadlock in java.util.logging

Gregg Wonderly-2
I've encountered a deadlocking situation in java.util.logging where a thread has
asserted a lock on a classloader which is logging some progress information.
The java.util.logging.ConsoleHandler is at issue.  Below are the associated
stack traces.

It seems to me that the primary issue is that StreamHandler.publish() method is
synchronized.  It seems to me that only the doneHeader stuff is really at issue
here.  If that section becomes the only synchronized(this) section, and writer
is declared as volatile (to cover the setOutputStream() path to modification
from another thread), would publish still be thread safe?

I'd like to find a solution to this and submit a bug report ASAP.

Gregg Wonderly

Java stack information for the threads listed above:
===================================================
"task":
         at java.util.logging.StreamHandler.publish(StreamHandler.java:174)
         - waiting to lock <0x1f6babc0> (a java.util.logging.ConsoleHandler)
         at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:88)
         at java.util.logging.Logger.log(Logger.java:428)
         at java.util.logging.Logger.doLog(Logger.java:450)
         at java.util.logging.Logger.log(Logger.java:473)
         at java.util.logging.Logger.fine(Logger.java:1024)
         at
net.jini.loader.pref.PreferredClassLoader.isPreferredResource(PreferredClassLoader.java:750)
         at
org.wonderly.jini2.browse.JiniDeskTop$12.isPreferredResource(JiniDeskTop.java:920)
         at
net.jini.loader.pref.PreferredClassLoader.loadClass(PreferredClassLoader.java:924)
         - locked <0x1f7484d8> (a org.wonderly.jini2.browse.JiniDeskTop$12)
         at org.wonderly.jini2.browse.JiniDeskTop$12.loadClass(JiniDeskTop.java:933)
         at java.lang.ClassLoader.loadClass(ClassLoader.java:299)
         - locked <0x1f87a3a0> (a net.jini.loader.pref.PreferredClassLoader)
         at
net.jini.loader.pref.PreferredClassLoader.loadClass(PreferredClassLoader.java:942)
         - locked <0x1f87a3a0> (a net.jini.loader.pref.PreferredClassLoader)
         at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
         at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)
         - locked <0x1f87a3a0> (a net.jini.loader.pref.PreferredClassLoader)
         at com.sun.jini.reggie.$Proxy2.getConstraints(Unknown Source)
         at
com.sun.jini.proxy.ConstrainableProxyUtil.verifyConsistentConstraints(ConstrainableProxyUtil.java:184)
         at
com.sun.jini.reggie.ConstrainableRegistrarProxy.readObject(ConstrainableRegistrarProxy.java:146)
         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:585)
         at java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:946)
         at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1818)
         at
java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1718)
         at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1304)
         at java.io.ObjectInputStream.readObject(ObjectInputStream.java:349)
         at net.jini.io.MarshalledInstance.get(MarshalledInstance.java:402)
         at
com.sun.jini.discovery.DiscoveryV1.doUnicastDiscovery(DiscoveryV1.java:397)
         at net.jini.discovery.LookupDiscovery$10.run(LookupDiscovery.java:3327)
         at java.security.AccessController.doPrivileged(Native Method)
         at
net.jini.discovery.LookupDiscovery.doUnicastDiscovery(LookupDiscovery.java:3324)
         at net.jini.discovery.LookupDiscovery.access$3900(LookupDiscovery.java:696)
         at
net.jini.discovery.LookupDiscovery$UnicastDiscoveryTask$1.performDiscovery(LookupDiscovery.java:1763)
         at
com.sun.jini.discovery.internal.MultiIPDiscovery.getSingleResponse(MultiIPDiscovery.java:152)
         at
com.sun.jini.discovery.internal.MultiIPDiscovery.getResponse(MultiIPDiscovery.java:83)
         at
net.jini.discovery.LookupDiscovery$UnicastDiscoveryTask.run(LookupDiscovery.java:1756)
         at
net.jini.discovery.LookupDiscovery$DecodeAnnouncementTask.run(LookupDiscovery.java:1599)
         at com.sun.jini.thread.TaskManager$TaskThread.run(TaskManager.java:331)
"task":
         at
net.jini.loader.pref.PreferredClassLoader.loadClass(PreferredClassLoader.java:920)
         - waiting to lock <0x1f7484d8> (a org.wonderly.jini2.browse.JiniDeskTop$12)
         at org.wonderly.jini2.browse.JiniDeskTop$12.loadClass(JiniDeskTop.java:933)
         at java.lang.ClassLoader.loadClass(ClassLoader.java:299)
         - locked <0x1f879270> (a net.jini.loader.pref.PreferredClassLoader)
         at
net.jini.loader.pref.PreferredClassLoader.loadClass(PreferredClassLoader.java:942)
         - locked <0x1f879270> (a net.jini.loader.pref.PreferredClassLoader)
         at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
         at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)
         - locked <0x1f879270> (a net.jini.loader.pref.PreferredClassLoader)
         at com.sun.jini.reggie.RegistrarProxy.toString(RegistrarProxy.java:448)
         at java.lang.String.valueOf(String.java:2615)
         at java.lang.StringBuilder.append(StringBuilder.java:116)
         at
com.sun.jini.discovery.UnicastResponse.toString(UnicastResponse.java:118)
         at java.text.MessageFormat.subformat(MessageFormat.java:1237)
         at java.text.MessageFormat.format(MessageFormat.java:828)
         at java.text.Format.format(Format.java:133)
         at java.text.MessageFormat.format(MessageFormat.java:804)
         at java.util.logging.Formatter.formatMessage(Formatter.java:130)
         - locked <0x1f6ccc30> (a com.cytetech.log.StreamFormatter)
         at com.cytetech.log.StreamFormatter.format(StreamFormatter.java:127)
         at java.util.logging.StreamHandler.publish(StreamHandler.java:179)
         - locked <0x1f6babc0> (a java.util.logging.ConsoleHandler)
         at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:88)
         at java.util.logging.Logger.log(Logger.java:428)
         at java.util.logging.Logger.doLog(Logger.java:450)
         at java.util.logging.Logger.log(Logger.java:514)
         at
com.sun.jini.discovery.DiscoveryV1.doUnicastDiscovery(DiscoveryV1.java:414)
         at net.jini.discovery.LookupDiscovery$10.run(LookupDiscovery.java:3327)
         at java.security.AccessController.doPrivileged(Native Method)
         at
net.jini.discovery.LookupDiscovery.doUnicastDiscovery(LookupDiscovery.java:3324)
         at
net.jini.discovery.LookupDiscovery.doUnicastDiscovery(LookupDiscovery.java:3355)
         at net.jini.discovery.LookupDiscovery.access$3700(LookupDiscovery.java:696)
         at
net.jini.discovery.LookupDiscovery$UnicastDiscoveryTask.run(LookupDiscovery.java:1744)
         at com.sun.jini.thread.TaskManager$TaskThread.run(TaskManager.java:331)
_______________________________________________
Concurrency-interest mailing list
[hidden email]
http://altair.cs.oswego.edu/mailman/listinfo/concurrency-interest
Reply | Threaded
Open this post in threaded view
|

Re: deadlock in java.util.logging

David Holmes-3
Hi Gregg,

I'm not sure if the StreamHandler can rely on its OutputStream correctly
synchronizing writes so that messages are written atomically. However, even
if it can't I think it should be able to do the formatter related actions
outside of the synchronized block. That would prevent the cycle that causes
the deadlock here. eg something like:

    public void publish(LogRecord record) {
        if (!isLoggable(record)) {
            return;
        }
        String msg;
        Formatter formatter = getFormatter();
        try {
     msg = formatter.format(record);
        } catch (Exception ex) {
            // We don't want to throw an exception here, but we
            // report the exception to any registered ErrorManager.
            reportError(null, ex, ErrorManager.FORMAT_FAILURE);
            return;
        }

        String head = formatter.getHead(this); // does this need sync?
       synchronized(this) {
           try {
               if (!doneHeader) {
                 writer.write(head);
                  doneHeader = true;
               }
               writer.write(msg);
           } catch (Exception ex) {
             // We don't want to throw an exception here, but we
             // report the exception to any registered ErrorManager.
             reportError(null, ex, ErrorManager.WRITE_FAILURE);
           }
       }
    }



That said, the classloader isn't blameless here as it performs logging while
holding its own lock, thus violating the open-call principle. :)

Cheers,
David Holmes

> -----Original Message-----
> From: [hidden email]
> [mailto:[hidden email]]On Behalf Of Gregg
> Wonderly
> Sent: Tuesday, 26 September 2006 8:13 AM
> To: concurrency-interest
> Subject: [concurrency-interest] deadlock in java.util.logging
>
>
> I've encountered a deadlocking situation in java.util.logging
> where a thread has
> asserted a lock on a classloader which is logging some progress
> information.
> The java.util.logging.ConsoleHandler is at issue.  Below are the
> associated
> stack traces.
>
> It seems to me that the primary issue is that
> StreamHandler.publish() method is
> synchronized.  It seems to me that only the doneHeader stuff is
> really at issue
> here.  If that section becomes the only synchronized(this)
> section, and writer
> is declared as volatile (to cover the setOutputStream() path to
> modification
> from another thread), would publish still be thread safe?
>
> I'd like to find a solution to this and submit a bug report ASAP.
>
> Gregg Wonderly
>
> Java stack information for the threads listed above:
> ===================================================
> "task":
>          at
> java.util.logging.StreamHandler.publish(StreamHandler.java:174)
>          - waiting to lock <0x1f6babc0> (a
> java.util.logging.ConsoleHandler)
>          at
> java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:88)
>          at java.util.logging.Logger.log(Logger.java:428)
>          at java.util.logging.Logger.doLog(Logger.java:450)
>          at java.util.logging.Logger.log(Logger.java:473)
>          at java.util.logging.Logger.fine(Logger.java:1024)
>          at
> net.jini.loader.pref.PreferredClassLoader.isPreferredResource(Pref
erredClassLoader.java:750)

>          at
> org.wonderly.jini2.browse.JiniDeskTop$12.isPreferredResource(JiniD
> eskTop.java:920)
>          at
> net.jini.loader.pref.PreferredClassLoader.loadClass(PreferredClass
> Loader.java:924)
>          - locked <0x1f7484d8> (a
> org.wonderly.jini2.browse.JiniDeskTop$12)
>          at
> org.wonderly.jini2.browse.JiniDeskTop$12.loadClass(JiniDeskTop.java:933)
>          at java.lang.ClassLoader.loadClass(ClassLoader.java:299)
>          - locked <0x1f87a3a0> (a
> net.jini.loader.pref.PreferredClassLoader)
>          at
> net.jini.loader.pref.PreferredClassLoader.loadClass(PreferredClass
> Loader.java:942)
>          - locked <0x1f87a3a0> (a
> net.jini.loader.pref.PreferredClassLoader)
>          at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
>          at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)
>          - locked <0x1f87a3a0> (a
> net.jini.loader.pref.PreferredClassLoader)
>          at com.sun.jini.reggie.$Proxy2.getConstraints(Unknown Source)
>          at
> com.sun.jini.proxy.ConstrainableProxyUtil.verifyConsistentConstrai
> nts(ConstrainableProxyUtil.java:184)
>          at
> com.sun.jini.reggie.ConstrainableRegistrarProxy.readObject(Constra
inableRegistrarProxy.java:146)

>          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>          at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorIm
> pl.java:39)
>          at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAc
> cessorImpl.java:25)
>          at java.lang.reflect.Method.invoke(Method.java:585)
>          at
> java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:946)
>          at
> java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1818)
>          at
> java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1718)
>          at
> java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1304)
>          at
> java.io.ObjectInputStream.readObject(ObjectInputStream.java:349)
>          at
> net.jini.io.MarshalledInstance.get(MarshalledInstance.java:402)
>          at
> com.sun.jini.discovery.DiscoveryV1.doUnicastDiscovery(DiscoveryV1.
> java:397)
>          at
> net.jini.discovery.LookupDiscovery$10.run(LookupDiscovery.java:3327)
>          at java.security.AccessController.doPrivileged(Native Method)
>          at
> net.jini.discovery.LookupDiscovery.doUnicastDiscovery(LookupDiscov
> ery.java:3324)
>          at
> net.jini.discovery.LookupDiscovery.access$3900(LookupDiscovery.java:696)
>          at
> net.jini.discovery.LookupDiscovery$UnicastDiscoveryTask$1.performD
> iscovery(LookupDiscovery.java:1763)
>          at
> com.sun.jini.discovery.internal.MultiIPDiscovery.getSingleResponse
> (MultiIPDiscovery.java:152)
>          at
> com.sun.jini.discovery.internal.MultiIPDiscovery.getResponse(Multi
> IPDiscovery.java:83)
>          at
> net.jini.discovery.LookupDiscovery$UnicastDiscoveryTask.run(Lookup
> Discovery.java:1756)
>          at
> net.jini.discovery.LookupDiscovery$DecodeAnnouncementTask.run(Look
upDiscovery.java:1599)

>          at
> com.sun.jini.thread.TaskManager$TaskThread.run(TaskManager.java:331)
> "task":
>          at
> net.jini.loader.pref.PreferredClassLoader.loadClass(PreferredClass
> Loader.java:920)
>          - waiting to lock <0x1f7484d8> (a
> org.wonderly.jini2.browse.JiniDeskTop$12)
>          at
> org.wonderly.jini2.browse.JiniDeskTop$12.loadClass(JiniDeskTop.java:933)
>          at java.lang.ClassLoader.loadClass(ClassLoader.java:299)
>          - locked <0x1f879270> (a
> net.jini.loader.pref.PreferredClassLoader)
>          at
> net.jini.loader.pref.PreferredClassLoader.loadClass(PreferredClass
> Loader.java:942)
>          - locked <0x1f879270> (a
> net.jini.loader.pref.PreferredClassLoader)
>          at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
>          at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)
>          - locked <0x1f879270> (a
> net.jini.loader.pref.PreferredClassLoader)
>          at
> com.sun.jini.reggie.RegistrarProxy.toString(RegistrarProxy.java:448)
>          at java.lang.String.valueOf(String.java:2615)
>          at java.lang.StringBuilder.append(StringBuilder.java:116)
>          at
> com.sun.jini.discovery.UnicastResponse.toString(UnicastResponse.java:118)
>          at java.text.MessageFormat.subformat(MessageFormat.java:1237)
>          at java.text.MessageFormat.format(MessageFormat.java:828)
>          at java.text.Format.format(Format.java:133)
>          at java.text.MessageFormat.format(MessageFormat.java:804)
>          at java.util.logging.Formatter.formatMessage(Formatter.java:130)
>          - locked <0x1f6ccc30> (a com.cytetech.log.StreamFormatter)
>          at
> com.cytetech.log.StreamFormatter.format(StreamFormatter.java:127)
>          at
> java.util.logging.StreamHandler.publish(StreamHandler.java:179)
>          - locked <0x1f6babc0> (a java.util.logging.ConsoleHandler)
>          at
> java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:88)
>          at java.util.logging.Logger.log(Logger.java:428)
>          at java.util.logging.Logger.doLog(Logger.java:450)
>          at java.util.logging.Logger.log(Logger.java:514)
>          at
> com.sun.jini.discovery.DiscoveryV1.doUnicastDiscovery(DiscoveryV1.
> java:414)
>          at
> net.jini.discovery.LookupDiscovery$10.run(LookupDiscovery.java:3327)
>          at java.security.AccessController.doPrivileged(Native Method)
>          at
> net.jini.discovery.LookupDiscovery.doUnicastDiscovery(LookupDiscov
> ery.java:3324)
>          at
> net.jini.discovery.LookupDiscovery.doUnicastDiscovery(LookupDiscov
> ery.java:3355)
>          at
> net.jini.discovery.LookupDiscovery.access$3700(LookupDiscovery.java:696)
>          at
> net.jini.discovery.LookupDiscovery$UnicastDiscoveryTask.run(Lookup
> Discovery.java:1744)
>          at
> com.sun.jini.thread.TaskManager$TaskThread.run(TaskManager.java:331)
> _______________________________________________
> Concurrency-interest mailing list
> [hidden email]
> http://altair.cs.oswego.edu/mailman/listinfo/concurrency-interest

_______________________________________________
Concurrency-interest mailing list
[hidden email]
http://altair.cs.oswego.edu/mailman/listinfo/concurrency-interest
Reply | Threaded
Open this post in threaded view
|

Re: deadlock in java.util.logging

Gregg Wonderly-2


David Holmes wrote:
> I'm not sure if the StreamHandler can rely on its OutputStream correctly
> synchronizing writes so that messages are written atomically. However, even
> if it can't I think it should be able to do the formatter related actions
> outside of the synchronized block. That would prevent the cycle that causes
> the deadlock here. eg something like:

I've coded such a solution as you suggest to see if anything else falls out.

> That said, the classloader isn't blameless here as it performs logging while
> holding its own lock, thus violating the open-call principle. :)

Yes, that is perhaps the bigger problem.  It's my fault that it is logging with
a lock held.  There are moments when that is unavoidable given some of the
execution paths that expose classloading operations.  I will remove some of the
debugging in that ClassLoader, or at least try and reduce some of the exposures.

But, I think this reveals an interesting path of circular dependencies involving
unanticipated class loading operations.

Thanks for your views on this David!  I think I will file an enhancement request
to at least get the call into the formating to not be synchronized.

Gregg Wonderly
_______________________________________________
Concurrency-interest mailing list
[hidden email]
http://altair.cs.oswego.edu/mailman/listinfo/concurrency-interest
Reply | Threaded
Open this post in threaded view
|

Re: deadlock in java.util.logging

Jason Mehrens
In reply to this post by Gregg Wonderly-2
I've had similar deadlock issues with the EDT/app thread logging.  One trick
you can use is the java.util.logging.Filter interface to perform deadlock
detection and prevention.  Or even log an alternate message to the original
logger.  Here is another deadlock bug with RMI that was reported:
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4939307

>Thanks for your views on this David!  I think I will file an enhancement
>request
>to at least get the call into the formating to not be synchronized.
I think the lock scope could be narrowed on almost all of the handlers.

Regards,

Jason Mehrens


_______________________________________________
Concurrency-interest mailing list
[hidden email]
http://altair.cs.oswego.edu/mailman/listinfo/concurrency-interest