JDK-8014218 : test/java/util/logging/DrainFindDeadlockTest.java failing intermittently
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.util.logging
  • Affected Version: 8
  • Priority: P3
  • Status: Resolved
  • Resolution: Duplicate
  • Submitted: 2013-05-08
  • Updated: 2013-07-01
  • Resolved: 2013-07-01
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 8
8Resolved
Related Reports
Relates :  
JDK-8016304 - ThreadMXBean.getDeadlockedThreads reports bogus deadlocks on JDK 8
Description
With an up-to-date build of jdk8/tl then this one has failed for me a few times when running the tests in -agentvm -concurrency:auto mode.


#Test Results (version 2)
#Wed May 08 12:18:59 IST 2013
#checksum:7b3ee9dc29c2885a
#-----testdescription-----
$file=/u/alanb/ws/tl/jdk/test/java/util/logging/DrainFindDeadlockTest.java
$root=/u/alanb/ws/tl/jdk/test
author=jim.gish@oracle.com
keywords=bug8010939 othervm
maxTimeout=10
run=USER_SPECIFIED build DrainFindDeadlockTest\nUSER_SPECIFIED main/othervm/timeout\=10 DrainFindDeadlockTest\n
source=DrainFindDeadlockTest.java
title=check for deadlock between findLogger() and drainLoggerRefQueueBounded()

#-----environment-----

#-----testresult-----
description=file\:/u/alanb/ws/tl/jdk/test/java/util/logging/DrainFindDeadlockTest.java
elapsed=292 0\:00\:00.292
end=Wed May 08 12\:18\:59 IST 2013
environment=regtest
execStatus=Failed. Execution failed\: `main' threw exception\: java.lang.RuntimeException\: TEST FAILED\: Deadlock detected
hostname=ashtown.ie.oracle.com
javatestOS=Linux 3.2.0-23-generic (amd64)
javatestVersion=4.4
jtregVersion=jtreg 4.1 dev b00
script=com.sun.javatest.regtest.RegressionScript 
sections=script_messages build compile build main
start=Wed May 08 12\:18\:58 IST 2013
test=java/util/logging/DrainFindDeadlockTest.java
user.name=albatem
work=/u/alanb/testing/jtreg/JTwork/java/util/logging

#section:script_messages
----------messages:(5/271)----------
JDK under test: (/u/alanb/ws/tl/build/linux-x86_64-normal-server-release/images/j2sdk-image)
java version "1.8.0-internal"
Java(TM) SE Runtime Environment (build 1.8.0-internal-albatem_2013_05_02_10_11-b00)
Java HotSpot(TM) 64-Bit Server VM (build 25.0-b30, mixed mode)


#section:build
----------messages:(3/131)----------
command: build DrainFindDeadlockTest
reason: User specified action: run build DrainFindDeadlockTest 
elapsed time (seconds): 0.056
result: Passed. Build successful

#section:compile
----------messages:(3/193)----------
command: compile -XDignore.symbol.file=true /u/alanb/ws/tl/jdk/test/java/util/logging/DrainFindDeadlockTest.java
reason: .class file out of date or does not exist
elapsed time (seconds): 0.056
result: Passed. Compilation successful

#section:build
----------messages:(3/104)----------
command: build DrainFindDeadlockTest
reason: Named class compiled on demand
elapsed time (seconds): 0.0
result: Passed. All files up to date

#section:main
----------messages:(3/148)----------
command: main DrainFindDeadlockTest
reason: User specified action: run main/othervm/timeout=10 DrainFindDeadlockTest 
elapsed time (seconds): 0.235
----------System.out:(53/2638)----------
Deadlock detection is available.
Running DeadlockChecker
Running ReadConfig
Running SetupLogger
threads blocked
checking for deadlock
We may have a deadlock
Thread:SetupLogger: BLOCKED
   java.util.Hashtable.get(Hashtable.java:405)
   java.util.Properties.getProperty(Properties.java:968)
   java.util.logging.LogManager.getProperty(LogManager.java:1192)
   java.util.logging.LogManager.getLevelProperty(LogManager.java:1242)
   java.util.logging.LogManager$LoggerContext.addLocalLogger(LogManager.java:566)
   java.util.logging.LogManager.addLogger(LogManager.java:888)
   java.util.logging.LogManager.demandLogger(LogManager.java:442)
   java.util.logging.Logger.demandLogger(Logger.java:346)
   java.util.logging.Logger.getLogger(Logger.java:391)
   DrainFindDeadlockTest$SetupLogger.run(DrainFindDeadlockTest.java:112)
   java.lang.Thread.run(Thread.java:724)
Thread:ReadConfig: BLOCKED
   java.util.logging.LogManager$LoggerContext.findLogger(LogManager.java:526)
   java.util.logging.LogManager.setLevelsOnExistingLoggers(LogManager.java:1414)
   java.util.logging.LogManager.readConfiguration(LogManager.java:1155)
   java.util.logging.LogManager.readConfiguration(LogManager.java:1028)
   DrainFindDeadlockTest$ReadConfig.run(DrainFindDeadlockTest.java:124)
   java.lang.Thread.run(Thread.java:724)
threads blocked
checking for deadlock
We detected a deadlock! 
"ReadConfig" Id=12 BLOCKED on java.util.logging.LogManager$LoggerContext@31f15848 owned by "SetupLogger" Id=11
	at java.util.logging.LogManager$LoggerContext.findLogger(LogManager.java:526)
	-  blocked on java.util.logging.LogManager$LoggerContext@31f15848
	at java.util.logging.LogManager.setLevelsOnExistingLoggers(LogManager.java:1414)
	-  locked java.util.logging.LogManager@26fec78d
	at java.util.logging.LogManager.readConfiguration(LogManager.java:1155)
	at java.util.logging.LogManager.readConfiguration(LogManager.java:1028)
	at DrainFindDeadlockTest$ReadConfig.run(DrainFindDeadlockTest.java:124)
	at java.lang.Thread.run(Thread.java:724)


"SetupLogger" Id=11 RUNNABLE
	at java.util.Hashtable.get(Hashtable.java:405)
	at java.util.Properties.getProperty(Properties.java:968)
	at java.util.logging.LogManager.getProperty(LogManager.java:1192)
	at java.util.logging.LogManager.getLevelProperty(LogManager.java:1242)
	at java.util.logging.LogManager$LoggerContext.addLocalLogger(LogManager.java:566)
	-  locked java.util.logging.LogManager$LoggerContext@31f15848
	at java.util.logging.LogManager.addLogger(LogManager.java:888)
	at java.util.logging.LogManager.demandLogger(LogManager.java:442)
	at java.util.logging.Logger.demandLogger(Logger.java:346)
	...


----------System.err:(5/361)----------
java.lang.RuntimeException: TEST FAILED: Deadlock detected
	at DrainFindDeadlockTest$DeadlockChecker.checkState(DrainFindDeadlockTest.java:164)
	at DrainFindDeadlockTest$DeadlockChecker.run(DrainFindDeadlockTest.java:188)
	at java.lang.Thread.run(Thread.java:724)
STATUS:Failed.`main' threw exception: java.lang.RuntimeException: TEST FAILED: Deadlock detected
result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: TEST FAILED: Deadlock detected


test result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: TEST FAILED: Deadlock detected
Comments
Caused and fixed by JDK-8016304.
01-07-2013
I believe this test fail because of JDK-8016304.
17-06-2013
The test failed again on windows_x64-product-c2, but the traces do not show dead locked threads. I am starting believing that the result of threadMXBean.findDeadlockedThreads() cannot be relied upon. -------------------------------------------------- TEST: java/util/logging/DrainFindDeadlockTest.java JDK under test: (C:\jprt\products\T1\JDK8-L~1\JDK18~1.0) java version "1.8.0-ea" Java(TM) SE Runtime Environment (build 1.8.0-ea-b94) Java HotSpot(TM) 64-Bit Server VM (build 25.0-b36, mixed mode) ACTION: build -- Passed. Build successful REASON: User specified action: run build DrainFindDeadlockTest TIME: 0.053 seconds messages: command: build DrainFindDeadlockTest reason: User specified action: run build DrainFindDeadlockTest elapsed time (seconds): 0.053 ACTION: compile -- Passed. Compilation successful REASON: .class file out of date or does not exist TIME: 0.053 seconds messages: command: compile -XDignore.symbol.file=true C:\jprt\T\T1\104814.danielfuchs\s\jdk\test\java\util\logging\DrainFindDeadlockTest.java reason: .class file out of date or does not exist elapsed time (seconds): 0.053 ACTION: build -- Passed. All files up to date REASON: Named class compiled on demand TIME: 0.0 seconds messages: command: build DrainFindDeadlockTest reason: Named class compiled on demand elapsed time (seconds): 0.0 ACTION: main -- Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: TEST FAILED: Deadlock detected REASON: User specified action: run main/othervm/timeout=10 DrainFindDeadlockTest TIME: 0.201 seconds messages: command: main DrainFindDeadlockTest reason: User specified action: run main/othervm/timeout=10 DrainFindDeadlockTest elapsed time (seconds): 0.201 STDOUT: Deadlock detection is available. Running DeadlockChecker Running SetupLogger Running ReadConfig threads blocked checking for deadlock We detected a deadlock! "ReadConfig" Id=13 RUNNABLE at java.util.Properties.load0(Properties.java:350) at java.util.Properties.load(Properties.java:346) - locked java.util.Properties@246f9732 at java.util.logging.LogManager.readConfiguration(LogManager.java:1138) at java.util.logging.LogManager.readConfiguration(LogManager.java:1028) at DrainFindDeadlockTest$ReadConfig.run(DrainFindDeadlockTest.java:124) at java.lang.Thread.run(Thread.java:724) STDERR: java.lang.RuntimeException: TEST FAILED: Deadlock detected at DrainFindDeadlockTest$DeadlockChecker.checkState(DrainFindDeadlockTest.java:164) at DrainFindDeadlockTest$DeadlockChecker.run(DrainFindDeadlockTest.java:188) at java.lang.Thread.run(Thread.java:724) STATUS:Failed.`main' threw exception: java.lang.RuntimeException: TEST FAILED: Deadlock detected TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: TEST FAILED: Deadlock detected
14-06-2013
It does not look like a dead lock to me. I see that by the time the ThreadInfo is printed, one of the two threads ("SetupLogger" Id=11) has become RUNNABLE. How reliable is threadMXBean.findDeadlockedThreads() ?
13-06-2013
I have not changed the test. It is possible that the extra load of running the tests concurrently leads to the conditions to duplicate it. It's not easy to duplicate.
08-05-2013
I know that, but I was confused by your -agentvm -concurrency:auto mode comment -- I thought maybe you had changed the test to use agentvm. Regardless, this deadlock shouldn't happen.
08-05-2013
This bug has @run main/othervm so it will always run in its own VM.
08-05-2013
The problem with any logger test running in agentvm mode is that jtreg itself uses and thus causes logging to be initialized. That being said, this test failure points to a different deadlock than the one being tested for.
08-05-2013