[concurrency-interest] deadlock in java.util.logging

David Holmes dcholmes at optusnet.com.au
Mon Sep 25 20:43:19 EDT 2006


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: concurrency-interest-bounces at cs.oswego.edu
> [mailto:concurrency-interest-bounces at cs.oswego.edu]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
> Concurrency-interest at altair.cs.oswego.edu
> http://altair.cs.oswego.edu/mailman/listinfo/concurrency-interest



More information about the Concurrency-interest mailing list