Deadlock due to logging inside classloaders

[jtnord]

Jetty version

9.4.35.v20201120

Java version

OpenJDK Runtime Environment (AdoptOpenJDK)(build 1.8.0_265-b01)
OpenJDK 64-Bit Server VM (AdoptOpenJDK)(build 25.265-b01, mixed mode)

OS type/version

Windows 10, (but also seen on Linux)

Description

It is possible to deadlock Jetty by enabling FINEST logging.
This is becsause the WebAppClassLoader itslef uses logging, and also that the act of logging can itself cause class loading. Due to locking in ClassLoaders this can this can cause deadlocks.

Therefore it is normal that classloaders never provide any synchronous form of logging, but Jetty's WebAppClassLoader does perform some logging - as follows

        at java.util.logging.Logger.log(Logger.java:738)
        at org.eclipse.jetty.util.log.JavaUtilLog.log(JavaUtilLog.java:169)
        at org.eclipse.jetty.util.log.JavaUtilLog.debug(JavaUtilLog.java:238)
        at org.eclipse.jetty.webapp.WebAppContext.isServerClass(WebAppContext.java:794)
        at org.eclipse.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:546)

(the classloading lock used by the AntClassLoader in the Jenkins project (take from the ant project) is using an overly broad lock for classloading by the looks of it, however should just increases the chance of the deadlock and not be a cause of it.

An example from the Jenkins project

"MapDB shutdown hook":
  waiting to lock monitor 0x000002bd96279508 (object 0x00000005c46e97f8, a hudson.util.MaskingClassLoader),
  which is held by "MVStore background writer nio:C:/workarea/source/github/jenkinsci/jenkins/DEADLOCK_TEST/run-time-state.mv.db"
"MVStore background writer nio:C:/workarea/source/github/jenkinsci/jenkins/DEADLOCK_TEST/run-time-state.mv.db":
  waiting to lock monitor 0x000002bd94e81de8 (object 0x00000005c4022040, a java.util.logging.ConsoleHandler),
  which is held by "jenkins.util.Timer [#6]"
"jenkins.util.Timer [#6]":
  waiting to lock monitor 0x000002bd97ff18b8 (object 0x00000005c477c9a0, a hudson.ClassicPluginStrategy$AntClassLoader2),
  which is held by "MVStore background writer nio:C:/workarea/source/github/jenkinsci/jenkins/DEADLOCK_TEST/run-time-state.mv.db"

Java stack information for the threads listed above:
===================================================
"MapDB shutdown hook":
        at org.mapdb.Store.lockAllWrite(Store.java:134)
        at org.mapdb.StoreWAL.close(StoreWAL.java:1071)
        at org.mapdb.EngineWrapper.close(EngineWrapper.java:81)
        at org.mapdb.Caches$HashTable.close(Caches.java:328)
        at org.mapdb.EngineWrapper.close(EngineWrapper.java:81)
        at org.mapdb.EngineWrapper$CloseOnJVMShutdown.close(EngineWrapper.java:586)
        at org.mapdb.EngineWrapper$CloseOnJVMShutdown$1.run(EngineWrapper.java:571)
        at java.lang.Thread.run(Thread.java:748)
"MapDB shutdown hook":
        at java.lang.ClassLoader.loadClass(ClassLoader.java:398)
        - waiting to lock <0x00000005c46e97f8> (a hudson.util.MaskingClassLoader)
        at hudson.util.MaskingClassLoader.loadClass(MaskingClassLoader.java:75)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:405)
        - locked <0x00000005c491c860> (a hudson.ClassicPluginStrategy$DependencyClassLoader)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:351)
        at jenkins.util.AntClassLoader.findBaseClass(AntClassLoader.java:1406)
        at jenkins.util.AntClassLoader.loadClass(AntClassLoader.java:1085)
        - locked <0x00000005c491c7f0> (a hudson.ClassicPluginStrategy$AntClassLoader2)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:351)
        at org.mapdb.Store.lockAllWrite(Store.java:134)
        at org.mapdb.StoreWAL.close(StoreWAL.java:1071)
        at org.mapdb.EngineWrapper.close(EngineWrapper.java:81)
        at org.mapdb.Caches$HashTable.close(Caches.java:328)
        at org.mapdb.EngineWrapper.close(EngineWrapper.java:81)
        at org.mapdb.EngineWrapper$CloseOnJVMShutdown.close(EngineWrapper.java:586)
        at org.mapdb.EngineWrapper$CloseOnJVMShutdown$1.run(EngineWrapper.java:571)
        at java.lang.Thread.run(Thread.java:748)
"MVStore background writer nio:C:/workarea/source/github/jenkinsci/jenkins/DEADLOCK_TEST/run-time-state.mv.db":
        at java.util.logging.StreamHandler.publish(StreamHandler.java:206)
        - waiting to lock <0x00000005c4022040> (a java.util.logging.ConsoleHandler)
        at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:116)
        at java.util.logging.Logger.log(Logger.java:738)
        at org.eclipse.jetty.util.log.JavaUtilLog.log(JavaUtilLog.java:169)
        at org.eclipse.jetty.util.log.JavaUtilLog.debug(JavaUtilLog.java:238)
        at org.eclipse.jetty.webapp.WebAppContext.isServerClass(WebAppContext.java:794)
        at org.eclipse.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:546)
        - locked <0x00000005c6bfaad8> (a java.lang.Object)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:405)
        - locked <0x00000005c46e97f8> (a hudson.util.MaskingClassLoader)
        at hudson.util.MaskingClassLoader.loadClass(MaskingClassLoader.java:75)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:405)
        - locked <0x00000005c4c8cef8> (a hudson.ClassicPluginStrategy$DependencyClassLoader)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:351)
        at jenkins.util.AntClassLoader.findBaseClass(AntClassLoader.java:1406)
        at jenkins.util.AntClassLoader.loadClass(AntClassLoader.java:1085)
        - locked <0x00000005c477c9a0> (a hudson.ClassicPluginStrategy$AntClassLoader2)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:351)
        at org.h2.mvstore.MVStore.collectReferencedChunks(MVStore.java:1446)
        at org.h2.mvstore.MVStore.freeUnusedChunks(MVStore.java:1407)
        at org.h2.mvstore.MVStore.freeUnusedIfNeeded(MVStore.java:1400)
        at org.h2.mvstore.MVStore.storeNow(MVStore.java:1208)
        at org.h2.mvstore.MVStore.store(MVStore.java:1190)
        at org.h2.mvstore.MVStore.tryCommit(MVStore.java:1135)
        at org.h2.mvstore.MVStore.writeInBackground(MVStore.java:2763)
        at org.h2.mvstore.MVStore$BackgroundWriterThread.run(MVStore.java:3123)
"jenkins.util.Timer [#6]":
        at com.cloudbees.opscenter.server.model.ConnectedMaster.getIdentityPublicKey(ConnectedMaster.java:1186)
        - locked <0x00000005c68e5570> (a java.lang.Object)
        at com.cloudbees.opscenter.server.model.ConnectedMaster.toString(ConnectedMaster.java:336)
        at java.text.MessageFormat.subformat(MessageFormat.java:1280)
        at java.text.MessageFormat.format(MessageFormat.java:865)
        at java.text.Format.format(Format.java:157)
        at java.text.MessageFormat.format(MessageFormat.java:841)
        at java.util.logging.Formatter.formatMessage(Formatter.java:138)
        - locked <0x00000005c42bd9d0> (a ColorFormatter)
        at java.util.logging.SimpleFormatter.format(SimpleFormatter.java:151)
        - locked <0x00000005c42bd9d0> (a ColorFormatter)
        at ColorFormatter.format(ColorFormatter.java:15)
        at java.util.logging.StreamHandler.publish(StreamHandler.java:211)
        - locked <0x00000005c4022040> (a java.util.logging.ConsoleHandler)
        at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:116)
        at java.util.logging.Logger.log(Logger.java:738)
        at java.util.logging.Logger.doLog(Logger.java:765)
        at java.util.logging.Logger.log(Logger.java:831)
        at com.cloudbees.opscenter.server.model.ConnectedMaster.updateRemoteContext(ConnectedMaster.java:756)
        at com.cloudbees.opscenter.server.model.ConnectedMaster$UpdateRemoteContexts.doRun(ConnectedMaster.java:2359)
        at hudson.triggers.SafeTimerTask.run(SafeTimerTask.java:91)
        at jenkins.security.ImpersonatingScheduledExecutorService$1.run(ImpersonatingScheduledExecutorService.java:67)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

Whilst one could argue that formatting a LogRecord should be done without holding locks on the underlying Handler
there is a reason why the JDK and other classloaders do not perform logging (and why the -verbose:class exists)

[joakime]

there is a reason why the JDK and other classloaders do not perform logging (and why the -verbose:class exists)

The entire -verbose:<arg> section of JVM command line arguments is for increasing the verboseness of the native code in the JVM.

The specific -verbose:class is logging events at the JVM level (not the classlib level), the ClassLoader logic has already occurred, and is asking JVM to realize the the Class object, which it will hand back to the ClassLoader for it to then do what it needs (security, jpms, package layer, caching, protection domain, etc).

Logging from the classlib level (be it either java.lang.logging, javax.management, or even java.lang.System.Logger) during a classloader is actually quite common within the JVM itself and isn't too tricky to trigger on the JVM (any of the following technology choices have been shown to trigger logging during classloading from the JVM itself: use JMX, use a URLStreamHandler, use JPMS, use a java Proxy class, use a Security manager, use a java.lang.instrumented.ClassFileTransformer). Also, if you use certain common, and popular technologies, you'll have an increased chance of triggering logging during classloading as well (OSGi, CDI, Spring, aop, etc).

This is the reality of world we live in as developers.

I see you have hudson/jenkins in the mix here.
The last time i recall a classloader issue appeared against Jetty on those CI's it was fixed with JENKINS-44330.

It also appears that you are encountering this during JVM shutdown as I see some JVM shutdown hooks.
This is an especially tricky time to start to use new classes, as many components necessary for proper operation are no longer valid.
If the WebAppContext was shutdown as a result of the server shutdown hook before your shutdown hooks then all bets are off, as the classloader tree is no longer sane for that specific WebAppContext.

[joakime]

This seems like it might be related to (or a duplicate of) the previous Issue #1563

[jtnord]

This seems like it might be related to (or a duplicate of) the previous Issue #1563

related in the way that - there is class loading going on during logging, and the class loader is logging....

It also appears that you are encountering this during JVM shutdown as I see some JVM shutdown hooks.

I see this not only at shutdown, that stack above was just an example stack trace I had to hand. I can cause this deadlock at startup.

This is the reality of world we live in as developers.

which is why when doing any of the above you need to be really careful about what you do or do not do,and when you do, or do not do it, especially when holding any locks, and especially when what you are interacting with is not under your direct control.

In other words open calls from classloaders (loadClass()) should be avoided.

This issue was uncovered after I fixed an issue in an associated transformer (not a ClassFileTransformer but you know how Jenkins likes to do its own thing :-p ).

--
For openness the locking of the (Jenkins not Jetty) classloader does appear overly broad in Jenkins and reducing that should help to reduce the chances of this occurring - but at the end of the day I would still say that this is a bug in Jetty in that it is making open calls during classloading with locks held.

[gregw]

I think we should just remove logging from WebAppClassLoader loading methods and any methods it calls from them.
It is more valuable to be able to ask users to turn on fine logging without risk, than it is to get debug from within load on the very rare times we have a problem. Actually when we do have a classloading problem, it is more often than not resolved by a dump/log of the static setup of the loader rather than any logging during an individual load

[joakime]

You are not just removing logging from WebAppClassLoader, you are also removing it from anything that WebAppClassLoader uses while it's attempting to resolve / load a class or resource.
That means quite a few places in jetty-util (all of TypeUtil, URIUtil, Resource tree, etc), jetty-servlet, and jetty-webapp as well.

[joakime]

Here's what's impacted ...

• org.eclipse.jetty.util.ClassVisibilityChecker
• org.eclipse.jetty.util.IO
• org.eclipse.jetty.util.TypeUtil
• org.eclipse.jetty.util.URIUtil
• org.eclipse.jetty.util.resource.Resource (and all derived versions)
• org.eclipse.jetty.util.resource.ResourceCollection (and all derived versions)
• org.eclipse.jetty.webapp.Context (and all derived versions)
• org.eclipse.jetty.webapp.WebAppClassLoader.Context (and all derived versions)

And that's just the shallow dive into what "remove logging from WebAppClassLoader" means.

[gregw]

@joakime I'm saying we should remove logging from just the methods called whilst loading a class. I do not believe the list is very extensive.. so it is worth investigating how extensive because I think there is a reasonable chance of a simple change avoiding this issue entirely.... but I could be wrong.

[joakime]

PR #5957 has been merged.
Release jetty-9.4.37.v20210219 has this change.