Bug 63251 - [JDK-8194653] Deadlock in FileSystems.getDefault on catalina startup
Summary: [JDK-8194653] Deadlock in FileSystems.getDefault on catalina startup
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 9
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 9.0.22
Hardware: PC Linux
: P2 major (vote)
Target Milestone: -----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-03-09 13:11 UTC by Dmitry Bedrin
Modified: 2019-09-09 14:17 UTC (History)
1 user (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Dmitry Bedrin 2019-03-09 13:11:07 UTC
Tomcat 9.0.14 fails to start with default logging settings intermittently.
Thread dump shows a dead lock (known issue in JRE: https://bugs.openjdk.java.net/browse/JDK-8194653)

Other libraries like Gatling, Payara and others workaround it by calling FileSystems.getDefault from main thread before starting other threads.

Full thread dump OpenJDK 64-Bit Server VM (25.201-b10 mixed mode):

"FileHandlerLogFilesCleaner-1" #11 daemon prio=5 os_prio=0 tid=0x00007fcfc41c4000 nid=0x27 waiting for monitor entry [0x00007fcf8fffa000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at java.lang.Runtime.loadLibrary0(Runtime.java:862)
	- waiting to lock <0x000000008001a690> (a java.lang.Runtime)
	at java.lang.System.loadLibrary(System.java:1122)
	at sun.nio.fs.UnixNativeDispatcher$1.run(UnixNativeDispatcher.java:573)
	at sun.nio.fs.UnixNativeDispatcher$1.run(UnixNativeDispatcher.java:571)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.nio.fs.UnixNativeDispatcher.<clinit>(UnixNativeDispatcher.java:571)
	at sun.nio.fs.UnixFileSystem.<init>(UnixFileSystem.java:67)
	at sun.nio.fs.LinuxFileSystem.<init>(LinuxFileSystem.java:39)
	at sun.nio.fs.LinuxFileSystemProvider.newFileSystem(LinuxFileSystemProvider.java:46)
	at sun.nio.fs.LinuxFileSystemProvider.newFileSystem(LinuxFileSystemProvider.java:39)
	at sun.nio.fs.UnixFileSystemProvider.<init>(UnixFileSystemProvider.java:56)
	at sun.nio.fs.LinuxFileSystemProvider.<init>(LinuxFileSystemProvider.java:41)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at java.lang.Class.newInstance(Class.java:442)
	at sun.nio.fs.DefaultFileSystemProvider.createProvider(DefaultFileSystemProvider.java:48)
	at sun.nio.fs.DefaultFileSystemProvider.create(DefaultFileSystemProvider.java:63)
	at java.nio.file.FileSystems$DefaultFileSystemHolder.getDefaultProvider(FileSystems.java:108)
	at java.nio.file.FileSystems$DefaultFileSystemHolder.access$000(FileSystems.java:89)
	at java.nio.file.FileSystems$DefaultFileSystemHolder$1.run(FileSystems.java:98)
	at java.nio.file.FileSystems$DefaultFileSystemHolder$1.run(FileSystems.java:96)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.nio.file.FileSystems$DefaultFileSystemHolder.defaultFileSystem(FileSystems.java:96)
	at java.nio.file.FileSystems$DefaultFileSystemHolder.<clinit>(FileSystems.java:90)
	at java.nio.file.FileSystems.getDefault(FileSystems.java:176)
	at java.io.File.toPath(File.java:2234)
	- locked <0x0000000080b1c268> (a java.io.File)
	at org.apache.juli.FileHandler.streamFilesForDelete(FileHandler.java:559)
	at org.apache.juli.FileHandler.lambda$clean$0(FileHandler.java:546)
	at org.apache.juli.FileHandler$$Lambda$1/20132171.run(Unknown Source)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	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)

"AsyncFileHandlerWriter-1259475182" #10 daemon prio=5 os_prio=0 tid=0x00007fcfc4141800 nid=0x25 waiting on condition [0x00007fcfb41f8000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x000000008011cac8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
	at java.util.concurrent.LinkedBlockingDeque.pollFirst(LinkedBlockingDeque.java:522)
	at java.util.concurrent.LinkedBlockingDeque.poll(LinkedBlockingDeque.java:684)
	at org.apache.juli.AsyncFileHandler$LoggerThread.run(AsyncFileHandler.java:159)

"Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007fcfc40cd800 nid=0x1c runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007fcfc40c6800 nid=0x1b waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007fcfc40c4000 nid=0x1a waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007fcfc40c2000 nid=0x19 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fcfc407a800 nid=0x18 in Object.wait() [0x00007fcfb47fe000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000080008ed0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
	- locked <0x0000000080008ed0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007fcfc4078000 nid=0x17 in Object.wait() [0x00007fcfc81c6000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000080006bf8> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	- locked <0x0000000080006bf8> (a java.lang.ref.Reference$Lock)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=0 tid=0x00007fcfc400a800 nid=0x15 in Object.wait() [0x00007fcfcb86e000]
   java.lang.Thread.State: RUNNABLE
	at java.nio.file.FileSystems.getDefault(FileSystems.java:176)
	at java.nio.file.Paths.get(Paths.java:138)
	at sun.misc.Launcher$ExtClassLoader.findLibrary(Launcher.java:235)
	at java.lang.ClassLoader.loadLibrary(ClassLoader.java:1830)
	at java.lang.Runtime.loadLibrary0(Runtime.java:870)
	- locked <0x000000008001a690> (a java.lang.Runtime)
	at java.lang.System.loadLibrary(System.java:1122)
	at sun.security.ec.SunEC$1.run(SunEC.java:60)
	at sun.security.ec.SunEC$1.run(SunEC.java:58)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.security.ec.SunEC.<clinit>(SunEC.java:58)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at java.lang.Class.newInstance(Class.java:442)
	at sun.security.jca.ProviderConfig$2.run(ProviderConfig.java:221)
	at sun.security.jca.ProviderConfig$2.run(ProviderConfig.java:206)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.security.jca.ProviderConfig.doLoadProvider(ProviderConfig.java:206)
	at sun.security.jca.ProviderConfig.getProvider(ProviderConfig.java:187)
	- locked <0x000000008005db60> (a sun.security.jca.ProviderConfig)
	at sun.security.jca.ProviderList.getProvider(ProviderList.java:233)
	at sun.security.jca.ProviderList.getIndex(ProviderList.java:263)
	at sun.security.jca.ProviderList.getProviderConfig(ProviderList.java:247)
	at sun.security.jca.ProviderList.getProvider(ProviderList.java:253)
	at java.net.URL.getURLStreamHandler(URL.java:1159)
	at java.net.URL.<init>(URL.java:421)
	at sun.misc.URLClassPath$JarLoader.<init>(URLClassPath.java:822)
	at sun.misc.URLClassPath$3.run(URLClassPath.java:575)
	at sun.misc.URLClassPath$3.run(URLClassPath.java:565)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.misc.URLClassPath.getLoader(URLClassPath.java:564)
	at sun.misc.URLClassPath.getLoader(URLClassPath.java:529)
	- locked <0x00000000808c3b48> (a sun.misc.URLClassPath)
	at sun.misc.URLClassPath.getNextLoader(URLClassPath.java:494)
	- locked <0x00000000808c3b48> (a sun.misc.URLClassPath)
	at sun.misc.URLClassPath.getResource(URLClassPath.java:248)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:363)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.net.URLClassLoader.findClass(URLClassLoader.java:362)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
	- locked <0x00000000808cf780> (a java.lang.Object)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
	at org.apache.catalina.startup.Bootstrap.init(Bootstrap.java:263)
	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:461)
	- locked <0x000000008086db40> (a java.lang.Object)

"VM Thread" os_prio=0 tid=0x00007fcfc406e800 nid=0x16 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007fcfc40d0800 nid=0x1d waiting on condition 

JNI global references: 322

Heap
 def new generation   total 157248K, used 13977K [0x0000000080000000, 0x000000008aaa0000, 0x00000000aaaa0000)
  eden space 139776K,  10% used [0x0000000080000000, 0x0000000080da67d8, 0x0000000088880000)
  from space 17472K,   0% used [0x0000000088880000, 0x0000000088880000, 0x0000000089990000)
  to   space 17472K,   0% used [0x0000000089990000, 0x0000000089990000, 0x000000008aaa0000)
 tenured generation   total 349568K, used 0K [0x00000000aaaa0000, 0x00000000c0000000, 0x0000000100000000)
   the space 349568K,   0% used [0x00000000aaaa0000, 0x00000000aaaa0000, 0x00000000aaaa0200, 0x00000000c0000000)
 Metaspace       used 6094K, capacity 6240K, committed 6400K, reserved 1056768K
  class space    used 664K, capacity 741K, committed 768K, reserved 1048576K
Comment 1 Mark Thomas 2019-03-15 16:54:38 UTC
Thanks for the report and the stack trace showing the problem.

Fixed in:
- master for 9.0.18 onwards
- 8.5.x for 8.5.40 onwards
- 7.0.x for 7.0.94 onwards
Comment 2 harristr 2019-09-09 14:09:23 UTC
The work-around of pre-loading the default FileSystem does not appear to solve the problem for logging, or maybe it only reduced the frequency of the occurrence.  I am still seeing the following stacktrace from a Spring Boot Microservice running Tomcat 9.0.22 with JDK 1.8.0_222 64-bit on RedHat 7.5:

2019-09-07 15:39:26
Full thread dump OpenJDK 64-Bit Server VM (25.222-b10 mixed mode):

"background-preinit" #9 prio=5 os_prio=0 tid=0x0000000002d11800 nid=0x726 waiting for monitor entry [0x00007f26ddd01000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at java.lang.Runtime.loadLibrary0(Runtime.java:862)
	- waiting to lock <0x00000000c010be00> (a java.lang.Runtime)
	at java.lang.System.loadLibrary(System.java:1122)
	at sun.nio.fs.UnixNativeDispatcher$1.run(UnixNativeDispatcher.java:573)
	at sun.nio.fs.UnixNativeDispatcher$1.run(UnixNativeDispatcher.java:571)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.nio.fs.UnixNativeDispatcher.<clinit>(UnixNativeDispatcher.java:571)
	at sun.nio.fs.UnixFileSystem.<init>(UnixFileSystem.java:67)
	at sun.nio.fs.LinuxFileSystem.<init>(LinuxFileSystem.java:39)
	at sun.nio.fs.LinuxFileSystemProvider.newFileSystem(LinuxFileSystemProvider.java:46)
	at sun.nio.fs.LinuxFileSystemProvider.newFileSystem(LinuxFileSystemProvider.java:39)
	at sun.nio.fs.UnixFileSystemProvider.<init>(UnixFileSystemProvider.java:56)
	at sun.nio.fs.LinuxFileSystemProvider.<init>(LinuxFileSystemProvider.java:41)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at java.lang.Class.newInstance(Class.java:442)
	at sun.nio.fs.DefaultFileSystemProvider.createProvider(DefaultFileSystemProvider.java:48)
	at sun.nio.fs.DefaultFileSystemProvider.create(DefaultFileSystemProvider.java:63)
	at java.nio.file.FileSystems$DefaultFileSystemHolder.getDefaultProvider(FileSystems.java:108)
	at java.nio.file.FileSystems$DefaultFileSystemHolder.access$000(FileSystems.java:89)
	at java.nio.file.FileSystems$DefaultFileSystemHolder$1.run(FileSystems.java:98)
	at java.nio.file.FileSystems$DefaultFileSystemHolder$1.run(FileSystems.java:96)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.nio.file.FileSystems$DefaultFileSystemHolder.defaultFileSystem(FileSystems.java:96)
	at java.nio.file.FileSystems$DefaultFileSystemHolder.<clinit>(FileSystems.java:90)
	at java.nio.file.FileSystems.getDefault(FileSystems.java:176)
	at org.apache.juli.logging.LogFactory.<init>(LogFactory.java:85)
	at org.apache.juli.logging.LogFactory.<clinit>(LogFactory.java:66)
	at org.apache.catalina.mbeans.MBeanFactory.<clinit>(MBeanFactory.java:59)
	at org.springframework.boot.autoconfigure.BackgroundPreinitializer$MBeanFactoryInitializer.run(BackgroundPreinitializer.java:139)
	at org.springframework.boot.autoconfigure.BackgroundPreinitializer$1.runSafely(BackgroundPreinitializer.java:102)
	at org.springframework.boot.autoconfigure.BackgroundPreinitializer$1.run(BackgroundPreinitializer.java:94)
	at java.lang.Thread.run(Thread.java:748)

"main" #1 prio=5 os_prio=0 tid=0x0000000000b52000 nid=0x687 in Object.wait() [0x00007f26fee02000]
   java.lang.Thread.State: RUNNABLE
	at java.nio.file.FileSystems.getDefault(FileSystems.java:176)
	at java.nio.file.Paths.get(Paths.java:138)
	at sun.misc.Launcher$ExtClassLoader.findLibrary(Launcher.java:235)
	at java.lang.ClassLoader.loadLibrary(ClassLoader.java:1830)
	at java.lang.Runtime.loadLibrary0(Runtime.java:870)
	- locked <0x00000000c010be00> (a java.lang.Runtime)
	at java.lang.System.loadLibrary(System.java:1122)
	at sun.security.ec.SunEC$1.run(SunEC.java:60)
	at sun.security.ec.SunEC$1.run(SunEC.java:58)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.security.ec.SunEC.<clinit>(SunEC.java:58)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at java.lang.Class.newInstance(Class.java:442)
	at sun.security.jca.ProviderConfig$2.run(ProviderConfig.java:221)
	at sun.security.jca.ProviderConfig$2.run(ProviderConfig.java:206)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.security.jca.ProviderConfig.doLoadProvider(ProviderConfig.java:206)
	at sun.security.jca.ProviderConfig.getProvider(ProviderConfig.java:187)
	- locked <0x00000000c055a6a0> (a sun.security.jca.ProviderConfig)
	at sun.security.jca.ProviderList.getProvider(ProviderList.java:233)
	at sun.security.jca.ProviderList.getService(ProviderList.java:331)
	at sun.security.jca.GetInstance.getInstance(GetInstance.java:157)
	at javax.net.ssl.SSLContext.getInstance(SSLContext.java:156)
	at javax.net.ssl.SSLContext.getDefault(SSLContext.java:96)
	- locked <0x00000000eb60aa50> (a java.lang.Class for javax.net.ssl.SSLContext)
	at javax.net.ssl.SSLSocketFactory.getDefault(SSLSocketFactory.java:122)
	- locked <0x00000000eb608ec8> (a java.lang.Class for javax.net.ssl.SSLSocketFactory)
	at javax.net.ssl.HttpsURLConnection.getDefaultSSLSocketFactory(HttpsURLConnection.java:332)
	at javax.net.ssl.HttpsURLConnection.<init>(HttpsURLConnection.java:289)
	at sun.net.www.protocol.https.HttpsURLConnectionImpl.<init>(HttpsURLConnectionImpl.java:99)
	at sun.net.www.protocol.https.Handler.openConnection(Handler.java:62)
	at sun.net.www.protocol.https.Handler.openConnection(Handler.java:57)
	at java.net.URL.openConnection(URL.java:991)
	at org.springframework.http.client.SimpleClientHttpRequestFactory.openConnection(SimpleClientHttpRequestFactory.java:187)
	at org.springframework.http.client.SimpleClientHttpRequestFactory.createRequest(SimpleClientHttpRequestFactory.java:145)
	at org.springframework.http.client.support.HttpAccessor.createRequest(HttpAccessor.java:87)
	at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:731)
	at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:691)
	at org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:618)