sun/security/tools/jarsigner/warnings/HasUnsignedEntryTest.java may fail with timeout.
Please see attached log for details.
Comments
I don't think this is a problem with HasUnsignedEntryTest.java. It looks like other tests may leave daemon threads (see linked bugs) which may slow down test execution in agent VM. If there are other factors which can slow down the test (slow machine, something else is running, etc), then the test may fail with timeout. I couldn't reproduce this failure.
I am closing this bug. Please file a new one if the test fails again.
23-08-2016
NoLoopbackPackets thread is started by java/net/MulticastSocket/NoLoopbackPackets.java test. The test starts a daemon thread which has an infinite loop. Looks like the loop runs forever:
http://hg.openjdk.java.net/jdk9/dev/jdk/file/0cd4b4def24f/test/java/net/MulticastSocket/NoLoopbackPackets.java#l127
...
Thread sender = new Thread(new Sender(groups));
sender.setDaemon(true); // we want sender to stop when main thread exits
sender.start();
...
static class Sender implements Runnable {
private List<SocketAddress> sendToGroups;
public Sender(List<SocketAddress> groups) {
sendToGroups = groups;
}
public void run() {
byte[] buf = "hello world".getBytes();
List<DatagramPacket> packets = new ArrayList<DatagramPacket>();
try {
for (SocketAddress group : sendToGroups) {
DatagramPacket packet = new DatagramPacket(buf, buf.length, group);
packets.add(packet);
}
MulticastSocket msock = new MulticastSocket();
msock.setLoopbackMode(true); // disable loopback mode
for (;;) {
for (DatagramPacket packet : packets) {
msock.send(packet);
}
Thread.sleep(1000); // 1 second
}
} catch (Exception e) {
throw new RuntimeException(e);
}
}
}
...
Filed JDK-8164592.
23-08-2016
Keep-Alive-SocketCleaner thread is started in KeepAliveStream.java
http://hg.openjdk.java.net/jdk9/dev/jdk/file/0cd4b4def24f/src/java.base/share/classes/sun/net/www/http/KeepAliveStream.java#l172
...
if (startCleanupThread) {
java.security.AccessController.doPrivileged(
new java.security.PrivilegedAction<Void>() {
public Void run() {
cleanerThread = InnocuousThread.newSystemThread("Keep-Alive-SocketCleaner", queue);
cleanerThread.setDaemon(true);
cleanerThread.setPriority(Thread.MAX_PRIORITY - 2);
cleanerThread.start();
return null;
}
});
}
...
"queue" is an instance of KeepAliveStreamCleaner:
http://hg.openjdk.java.net/jdk9/dev/jdk/file/0cd4b4def24f/src/java.base/share/classes/sun/net/www/http/KeepAliveStreamCleaner.java#l90
...
@Override
public void run()
{
KeepAliveCleanerEntry kace = null;
do {
try {
synchronized(this) {
long before = System.currentTimeMillis();
long timeout = TIMEOUT;
while ((kace = poll()) == null) {
this.wait(timeout);
long after = System.currentTimeMillis();
long elapsed = after - before;
if (elapsed > timeout) {
/* one last try */
kace = poll();
break;
}
before = after;
timeout -= elapsed;
}
}
if(kace == null)
break;
...
It calls wait() with timeout. At first glance, it doesn't look like there is a problem with this.
23-08-2016
Many InnocuousThread threads might be created by AsynchronousChannelGroup.withFixedThreadPool() call which results to LinuxAsynchronousChannelProvider.openAsynchronousChannelGroup() invocation. This method creates an instance of EPollPort which can be observed in jstack output:
"InnocuousThread-33" #2203 daemon prio=5 os_prio=0 tid=0x00007fec1c040800 nid=0x580a waiting on condition [0x00007fec34fd6000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@9-ea/Native Method)
- parking to wait for <0x00000000e10e35e0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(java.base@9-ea/LockSupport.java:190)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@9-ea/AbstractQueuedSynchronizer.java:2064)
at java.util.concurrent.ArrayBlockingQueue.take(java.base@9-ea/ArrayBlockingQueue.java:387)
at sun.nio.ch.EPollPort$EventHandlerTask.run(java.base@9-ea/EPollPort.java:262)
at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(java.base@9-ea/AsynchronousChannelGroupImpl.java:112)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@9-ea/ThreadPoolExecutor.java:1158)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@9-ea/ThreadPoolExecutor.java:632)
at java.lang.Thread.run(java.base@9-ea/Thread.java:843)
at jdk.internal.misc.InnocuousThread.run(java.base@9-ea/InnocuousThread.java:122)
The following tests use withFixedThreadPool() method:
1. java/nio/channels/AsynchronousSocketChannel/Leaky.java
The test uses daemon threads, and doesn't shutdown AsynchronousChannelGroup. This looks like a bug.
2. java/nio/channels/AsynchronousChannelGroup/Basic.java
The test doesn't use daemon threads, and seems to shutdown AsynchronousChannelGroup.
3. java/nio/channels/AsynchronousChannelGroup/Restart.java
The test doesn't use daemon threads, so it doesn't seem to cause problems. But it would be better that the test called shutdown() in "finally" block.
4. java/nio/channels/AsynchronousChannelGroup/AsExecutor.java
The test uses daemon threads, but it also calls shutdown() in "finally" block, so it doesn't seem to cause any problem.
5. java/nio/channels/AsynchronousChannelGroup/GroupOfOne.java
The test doesn't use daemon threads, so it doesn't seem to cause problems.
6. java/nio/channels/AsynchronousChannelGroup/Identity.java
The test uses daemon threads, but it calls shutdownNow() method. But shutdownNow() is called not in "finally" block, so that it may be possible that the test leaves daemon threads.
Filed JDK-8164166.
17-08-2016
Threads which use UpdateInterference class seemed to be created by java/nio/file/WatchService/UpdateInterference.java test:
http://hg.openjdk.java.net/jdk9/dev/jdk/file/tip/test/java/nio/file/WatchService/UpdateInterference.java
The test starts a couple of daemon threads which has an infinite "while" loop. Probabaly "FileSystemWatchService" thread was created by this test as well. Here is a piece of jstack output for UpdateInterference.java test:
"Thread-2" #16 daemon prio=5 os_prio=0 tid=0x00007f157804a000 nid=0x2b29 in Object.wait() [0x00007f15adaf9000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base@9-internal/Native Method)
- waiting on <no object reference available>
at java.lang.Object.wait(java.base@9-internal/Object.java:516)
at sun.nio.fs.AbstractPoller$Request.awaitResult(java.base@9-internal/AbstractPoller.java:200)
- waiting to re-lock in wait() <0x00000006d6712cc8> (a sun.nio.fs.AbstractPoller$Request)
at sun.nio.fs.AbstractPoller.invoke(java.base@9-internal/AbstractPoller.java:229)
at sun.nio.fs.AbstractPoller.register(java.base@9-internal/AbstractPoller.java:129)
at sun.nio.fs.LinuxWatchService.register(java.base@9-internal/LinuxWatchService.java:90)
at sun.nio.fs.UnixPath.register(java.base@9-internal/UnixPath.java:891)
at java.nio.file.Path.register(java.base@9-internal/Path.java:781)
at UpdateInterference$2.run(UpdateInterference.java:76)
"Thread-1" #15 daemon prio=5 os_prio=0 tid=0x00007f1578048800 nid=0x2b28 waiting on condition [0x00007f15adbfa000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(java.base@9-internal/Native Method)
at UpdateInterference$1.run(UpdateInterference.java:59)
"FileSystemWatchService" #14 daemon prio=5 os_prio=0 tid=0x00007f157803e800 nid=0x2b27 runnable [0x00007f15adcfb000]
java.lang.Thread.State: RUNNABLE
at sun.nio.fs.UnixNativeDispatcher.read(java.base@9-internal/Native Method)
at sun.nio.fs.LinuxWatchService$Poller.run(java.base@9-internal/LinuxWatchService.java:320)
at java.lang.Thread.run(java.base@9-internal/Thread.java:843)
Filed JDK-8164159.
16-08-2016
JDK-8162757 is a similar test failure (in net-libs) which has similar jstack output. There were lots of daemon processes which might slow down the test execution which resulted to timeout.
16-08-2016
Accoriding to jstack output, the test failed by timeout while waiting for jarsigner to verify jar file. See HasUnsignedEntryTest.java, line 85:
http://hg.openjdk.java.net/jdk9/dev/jdk/file/tip/test/sun/security/tools/jarsigner/warnings/HasUnsignedEntryTest.java#l83
...
// verify jar
analyzer = jarsigner(
"-verify",
"-verbose",
"-keystore", KEYSTORE,
"-storepass", PASSWORD,
"-keypass", PASSWORD,
UPDATED_SIGNED_JARFILE);
...
"SameVMThread" #2833 prio=5 os_prio=0 tid=0x00007feda4381800 nid=0x3a53 in Object.wait() [0x00007feb72cea000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base@9-ea/Native Method)
- waiting on <no object reference available>
at java.lang.Object.wait(java.base@9-ea/Object.java:516)
at java.lang.ProcessImpl.waitFor(java.base@9-ea/ProcessImpl.java:498)
- waiting to re-lock in wait() <0x00000000e44c4840> (a java.lang.ProcessImpl)
at jdk.testlibrary.ProcessTools.executeProcess(ProcessTools.java:400)
at jdk.testlibrary.ProcessTools.executeProcess(ProcessTools.java:374)
at jdk.testlibrary.ProcessTools.executeProcess(ProcessTools.java:427)
at jdk.testlibrary.ProcessTools.executeCommand(ProcessTools.java:477)
at HasUnsignedEntryTest.start(HasUnsignedEntryTest.java:85)
at HasUnsignedEntryTest.main(HasUnsignedEntryTest.java:44)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@9-ea/Native Method)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@9-ea/NativeMethodAccessorImpl.java:62)
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@9-ea/DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(java.base@9-ea/Method.java:533)
at com.sun.javatest.regtest.agent.MainActionHelper$SameVMRunnable.run(MainActionHelper.java:226)
at java.lang.Thread.run(java.base@9-ea/Thread.java:843)
Logs from jarsigner is not available because the test doesn't print them out. But I think logs wouldn't be available even if the test tried to print them out because jtreg would have killed the test before it printed out the messages from jarsigner. A wrapper can be used to make those logs available, see JDK-8158011 for details.
I noticed in jstack logs that there are lots of daemon threads, and I am not sure that they are realted to the test:
- UpdateInterference threads
- One FileSystemWatchService thread
- 33+ InnocuousThread threads
- Keep-Alive-SocketCleaner thread
- NoLoopbackPackets thread
- Lots of C1, C2, G1 and GC threads
I am wondering if some other tests left those threads (the test doesn't run in othervm mode), and if those threads cound slow down the test, so that it failed by timeout.
15-08-2016
I removed jstack output from description because it's huge. Please see logs in attachment.