[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