-
Bug
-
Resolution: Won't Fix
-
P3
-
None
-
7u25
-
linux
FULL PRODUCT VERSION :
java version " 1.7.0_25 "
Java(TM) SE Runtime Environment (build 1.7.0_25-b15)
Java HotSpot(TM) 64-Bit Server VM (build 23.25-b01, mixed mode)
ADDITIONAL OS VERSION INFORMATION :
Linux jmmc-laurent 2.6.35.14-106.fc14.x86_64 #1 SMP Wed Nov 23 13:07:52 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux
EXTRA RELEVANT SYSTEM CONFIGURATION :
Aspro2 application hosted at jmmc.fr: http://apps.jmmc.fr/~swmgr/Aspro2/Aspro2.jnlp
A DESCRIPTION OF THE PROBLEM :
When I quit my Aspro2 (Swing) application running in Java Web Start environement, shutdown hooks are not run properly:
- java.util.logging log statements are 'lost' as reported in openjdk's core libs mailing list:
- the open source JSamp library does not properly stop: .samp lock file is still present in the user's home directory (http://software.astrogrid.org/doc/p/jsamp/)
When I start again the application, the JSamp library reads the lock file and tries to connect to the dead hub which causes a slow startup.
1/ I reported few comments without any feeback:
http://mail.openjdk.java.net/pipermail/core-libs-dev/2013-June/018460.html
I think the main issue is that application's hook are executed at the same time with jvm's hooks like LogManager or StreamCloser although the JVM Shutdown class supports hook priorities !
2/ I successfully performed a debugger session of my application (with JSamp source code) using netbeans attached to javaws JVM (socket) using the following script:
[bourgesl@jmmc-laurent$ cat javaws-debug.sh
#!/bin/sh
export JAVAWS_TRACE_NATIVE=1
export JAVAWS_VM_ARGS= " -Xdebug -Xnoagent -Djava.compiler=NONE -Xrunjdwp:transport=dt_socket,address=8989,server=y,suspend=n "
javaws " $@ "
I added System.out and printStackTrace statements (j.u.l Logger is unusable) to JSamp ShutdownManager class:
/**
* Invoked on shutdown by runtime.
*/
private void doCleanup() {
Hook[] hooks;
synchronized ( this ) {
hooks = (Hook[]) hookMap_.values().toArray( new Hook[ 0 ] );
}
Arrays.sort( hooks );
// NOTE: JUL Logs are disabled by the LogManager shutdown hook !
// TODO Mark: always use both log and System.out to log messages in shutdown / stop methods everywhere
// (Hub, HubServiceMode, HubProfile, HttpServer ...)
logger_.info( " SAMP shutdown start " );
System.out.println( " SAMP shutdown start " );
for ( int ih = 0; ih < hooks.length; ih++ ) {
try {
hooks[ ih ].runnable_.run();
}
catch ( RuntimeException e ) {
logger_.log( Level.WARNING, " Shutdown hook failure: " + e, e );
System.err.println( " Shutdown hook failure: " + e );
e.printStackTrace(System.err);
}
}
logger_.info( " SAMP shutdown end " );
System.out.println( " SAMP shutdown end " );
}
And I got the following exception:
Shutdown hook failure:java.lang.IllegalStateException: zip file closed
java.lang.IllegalStateException: zip file closed
at java.util.zip.ZipFile.ensureOpen(ZipFile.java:634)
at java.util.zip.ZipFile.getEntry(ZipFile.java:305)
at java.util.jar.JarFile.getEntry(JarFile.java:226)
at com.sun.deploy.cache.CachedJarFile.getEntry(Unknown Source)
at java.util.jar.JarFile.getJarEntry(JarFile.java:209)
at com.sun.deploy.security.DeployURLClassPath$JarLoader.getResource(Unknown Source)
at com.sun.deploy.security.DeployURLClassPath.getResource(Unknown Source)
at java.net.URLClassLoader$1.run(URLClassLoader.java:358)
at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
at java.security.AccessController.doPrivileged(Native Method)
at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
at com.sun.jnlp.JNLPClassLoader.findClass(Unknown Source)
at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at org.astrogrid.samp.hub.HubServiceMode$2$1.shutdown(HubServiceMode.java:256)
at org.astrogrid.samp.hub.Hub.shutdown(Hub.java:105)
at org.astrogrid.samp.hub.Hub$4.run(Hub.java:521)
at org.astrogrid.samp.ShutdownManager.doCleanup(ShutdownManager.java:94)
at org.astrogrid.samp.ShutdownManager.access$000(ShutdownManager.java:16)
at org.astrogrid.samp.ShutdownManager$1.run(ShutdownManager.java:41)
The exception cause is in the HubServiceMode... shutdown() method:
public void shutdown() {
super.shutdown();
SwingUtilities.invokeLater( new Runnable() {
public void run() {
if ( tidier != null ) {
tidier.tidyGui();
}
}
} );
}
The problem occurs when the JVM loads the Runnable class beacuse the JarFile was closed !!!
maybe it is related to JNLPClassLoader.findClass() ?
I fixed the JSamp library applying a very simple work around:
- instanciate the Runnable class in constructor()
/* LBO: preload runnable callback */
private Runnable tidierCallback = null;
public void start() {
...
SwingUtilities.invokeLater( new Runnable() {
public void run() {
...
final Tidier tidier = configureHubWindow( window,
profiles,
runners,
service );
if (tidier != null) {
// LBO: load callback ASAP
tidierCallback = new Runnable() {
public void run() {
tidier.tidyGui();
}
};
}
...
}
} );
}
- invoke that Runnable instance in the stop() method:
public void shutdown() {
super.shutdown();
/* LBO: fix tidier call */
if (tidierCallback != null) {
SwingUtilities.invokeLater(tidierCallback);
}
}
Whereas I found a workaround, I do not want to patch the JSamp library (again) because it will impact many other applications (delays ...)
Finally I suspect a bug in JNLP class loader or a conflict between shutdown hooks: why is the Jar file closed ?
REGRESSION. Last worked in version 7u10
STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
1/ Start Aspro2 with javaws (+ Java Console enabled):
javaws http://apps.jmmc.fr/~swmgr/Aspro2/Aspro2.jnlp
2/ Close the window and Click on 'Don't Save' to the confirmation dialog
3/ Does the .samp lock file still exist ?
[bourgesl@jmmc-laurent jmmc]$ ll ~/.samp
-rw-------. 1 bourgesl laogsite 396 7 ao??t 13:48 /home/bourgesl/.samp
It means that the JSamp shutdown hook failed.
4/ Restart the application:
javaws http://apps.jmmc.fr/~swmgr/Aspro2/Aspro2.jnlp
5/ Look at the Java console:
Several exceptions are present indicating that JSamp loaded the .samp lock file and failed to connect the hub:
11:50:09.681 WARN [AWT-EventQueue-2] org.astrogrid.samp.client.HubConnector - Hub connection attempt failed
org.astrogrid.samp.client.SampException: Connexion refus??e
at org.astrogrid.samp.xmlrpc.XmlRpcHubConnection.rawExec(XmlRpcHubConnection.java:187) ~[jsamp-1.3-3.jar:1.3-3]
at org.astrogrid.samp.xmlrpc.XmlRpcHubConnection.<init>(XmlRpcHubConnection.java:53) ~[jsamp-1.3-3.jar:1.3-3]
at org.astrogrid.samp.xmlrpc.StandardHubConnection.<init>(StandardHubConnection.java:31) ~[jsamp-1.3-3.jar:1.3-3]
at org.astrogrid.samp.xmlrpc.StandardClientProfile.register(StandardClientProfile.java:121) ~[jsamp-1.3-3.jar:1.3-3]
at org.astrogrid.samp.client.HubConnector.createConnection(HubConnector.java:745) ~[jsamp-1.3-3.jar:1.3-3]
at org.astrogrid.samp.client.HubConnector.getConnection(HubConnector.java:663) ~[jsamp-1.3-3.jar:1.3-3]
at org.astrogrid.samp.client.HubConnector.setActive(HubConnector.java:476) ~[jsamp-1.3-3.jar:1.3-3]
at fr.jmmc.jmcs.network.interop.SampManager.<init>(SampManager.java:148) ~[jmcs.jar:na]
at fr.jmmc.jmcs.network.interop.SampManager.getInstance(SampManager.java:69) ~[jmcs.jar:na]
ERROR MESSAGES/STACK TRACES THAT OCCUR :
java.lang.IllegalStateException: zip file closed
at java.util.zip.ZipFile.ensureOpen(ZipFile.java:634)
at java.util.zip.ZipFile.getEntry(ZipFile.java:305)
at java.util.jar.JarFile.getEntry(JarFile.java:226)
at com.sun.deploy.cache.CachedJarFile.getEntry(Unknown Source)
at java.util.jar.JarFile.getJarEntry(JarFile.java:209)
at com.sun.deploy.security.DeployURLClassPath$JarLoader.getResource(Unknown Source)
at com.sun.deploy.security.DeployURLClassPath.getResource(Unknown Source)
at java.net.URLClassLoader$1.run(URLClassLoader.java:358)
at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
at java.security.AccessController.doPrivileged(Native Method)
at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
at com.sun.jnlp.JNLPClassLoader.findClass(Unknown Source)
at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at org.astrogrid.samp.hub.HubServiceMode$2$1.shutdown(HubServiceMode.java:256)
at org.astrogrid.samp.hub.Hub.shutdown(Hub.java:105)
at org.astrogrid.samp.hub.Hub$4.run(Hub.java:521)
at org.astrogrid.samp.ShutdownManager.doCleanup(ShutdownManager.java:94)
at org.astrogrid.samp.ShutdownManager.access$000(ShutdownManager.java:16)
at org.astrogrid.samp.ShutdownManager$1.run(ShutdownManager.java:41)
REPRODUCIBILITY :
This bug can be reproduced always.
java version " 1.7.0_25 "
Java(TM) SE Runtime Environment (build 1.7.0_25-b15)
Java HotSpot(TM) 64-Bit Server VM (build 23.25-b01, mixed mode)
ADDITIONAL OS VERSION INFORMATION :
Linux jmmc-laurent 2.6.35.14-106.fc14.x86_64 #1 SMP Wed Nov 23 13:07:52 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux
EXTRA RELEVANT SYSTEM CONFIGURATION :
Aspro2 application hosted at jmmc.fr: http://apps.jmmc.fr/~swmgr/Aspro2/Aspro2.jnlp
A DESCRIPTION OF THE PROBLEM :
When I quit my Aspro2 (Swing) application running in Java Web Start environement, shutdown hooks are not run properly:
- java.util.logging log statements are 'lost' as reported in openjdk's core libs mailing list:
- the open source JSamp library does not properly stop: .samp lock file is still present in the user's home directory (http://software.astrogrid.org/doc/p/jsamp/)
When I start again the application, the JSamp library reads the lock file and tries to connect to the dead hub which causes a slow startup.
1/ I reported few comments without any feeback:
http://mail.openjdk.java.net/pipermail/core-libs-dev/2013-June/018460.html
I think the main issue is that application's hook are executed at the same time with jvm's hooks like LogManager or StreamCloser although the JVM Shutdown class supports hook priorities !
2/ I successfully performed a debugger session of my application (with JSamp source code) using netbeans attached to javaws JVM (socket) using the following script:
[bourgesl@jmmc-laurent$ cat javaws-debug.sh
#!/bin/sh
export JAVAWS_TRACE_NATIVE=1
export JAVAWS_VM_ARGS= " -Xdebug -Xnoagent -Djava.compiler=NONE -Xrunjdwp:transport=dt_socket,address=8989,server=y,suspend=n "
javaws " $@ "
I added System.out and printStackTrace statements (j.u.l Logger is unusable) to JSamp ShutdownManager class:
/**
* Invoked on shutdown by runtime.
*/
private void doCleanup() {
Hook[] hooks;
synchronized ( this ) {
hooks = (Hook[]) hookMap_.values().toArray( new Hook[ 0 ] );
}
Arrays.sort( hooks );
// NOTE: JUL Logs are disabled by the LogManager shutdown hook !
// TODO Mark: always use both log and System.out to log messages in shutdown / stop methods everywhere
// (Hub, HubServiceMode, HubProfile, HttpServer ...)
logger_.info( " SAMP shutdown start " );
System.out.println( " SAMP shutdown start " );
for ( int ih = 0; ih < hooks.length; ih++ ) {
try {
hooks[ ih ].runnable_.run();
}
catch ( RuntimeException e ) {
logger_.log( Level.WARNING, " Shutdown hook failure: " + e, e );
System.err.println( " Shutdown hook failure: " + e );
e.printStackTrace(System.err);
}
}
logger_.info( " SAMP shutdown end " );
System.out.println( " SAMP shutdown end " );
}
And I got the following exception:
Shutdown hook failure:java.lang.IllegalStateException: zip file closed
java.lang.IllegalStateException: zip file closed
at java.util.zip.ZipFile.ensureOpen(ZipFile.java:634)
at java.util.zip.ZipFile.getEntry(ZipFile.java:305)
at java.util.jar.JarFile.getEntry(JarFile.java:226)
at com.sun.deploy.cache.CachedJarFile.getEntry(Unknown Source)
at java.util.jar.JarFile.getJarEntry(JarFile.java:209)
at com.sun.deploy.security.DeployURLClassPath$JarLoader.getResource(Unknown Source)
at com.sun.deploy.security.DeployURLClassPath.getResource(Unknown Source)
at java.net.URLClassLoader$1.run(URLClassLoader.java:358)
at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
at java.security.AccessController.doPrivileged(Native Method)
at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
at com.sun.jnlp.JNLPClassLoader.findClass(Unknown Source)
at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at org.astrogrid.samp.hub.HubServiceMode$2$1.shutdown(HubServiceMode.java:256)
at org.astrogrid.samp.hub.Hub.shutdown(Hub.java:105)
at org.astrogrid.samp.hub.Hub$4.run(Hub.java:521)
at org.astrogrid.samp.ShutdownManager.doCleanup(ShutdownManager.java:94)
at org.astrogrid.samp.ShutdownManager.access$000(ShutdownManager.java:16)
at org.astrogrid.samp.ShutdownManager$1.run(ShutdownManager.java:41)
The exception cause is in the HubServiceMode... shutdown() method:
public void shutdown() {
super.shutdown();
SwingUtilities.invokeLater( new Runnable() {
public void run() {
if ( tidier != null ) {
tidier.tidyGui();
}
}
} );
}
The problem occurs when the JVM loads the Runnable class beacuse the JarFile was closed !!!
maybe it is related to JNLPClassLoader.findClass() ?
I fixed the JSamp library applying a very simple work around:
- instanciate the Runnable class in constructor()
/* LBO: preload runnable callback */
private Runnable tidierCallback = null;
public void start() {
...
SwingUtilities.invokeLater( new Runnable() {
public void run() {
...
final Tidier tidier = configureHubWindow( window,
profiles,
runners,
service );
if (tidier != null) {
// LBO: load callback ASAP
tidierCallback = new Runnable() {
public void run() {
tidier.tidyGui();
}
};
}
...
}
} );
}
- invoke that Runnable instance in the stop() method:
public void shutdown() {
super.shutdown();
/* LBO: fix tidier call */
if (tidierCallback != null) {
SwingUtilities.invokeLater(tidierCallback);
}
}
Whereas I found a workaround, I do not want to patch the JSamp library (again) because it will impact many other applications (delays ...)
Finally I suspect a bug in JNLP class loader or a conflict between shutdown hooks: why is the Jar file closed ?
REGRESSION. Last worked in version 7u10
STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
1/ Start Aspro2 with javaws (+ Java Console enabled):
javaws http://apps.jmmc.fr/~swmgr/Aspro2/Aspro2.jnlp
2/ Close the window and Click on 'Don't Save' to the confirmation dialog
3/ Does the .samp lock file still exist ?
[bourgesl@jmmc-laurent jmmc]$ ll ~/.samp
-rw-------. 1 bourgesl laogsite 396 7 ao??t 13:48 /home/bourgesl/.samp
It means that the JSamp shutdown hook failed.
4/ Restart the application:
javaws http://apps.jmmc.fr/~swmgr/Aspro2/Aspro2.jnlp
5/ Look at the Java console:
Several exceptions are present indicating that JSamp loaded the .samp lock file and failed to connect the hub:
11:50:09.681 WARN [AWT-EventQueue-2] org.astrogrid.samp.client.HubConnector - Hub connection attempt failed
org.astrogrid.samp.client.SampException: Connexion refus??e
at org.astrogrid.samp.xmlrpc.XmlRpcHubConnection.rawExec(XmlRpcHubConnection.java:187) ~[jsamp-1.3-3.jar:1.3-3]
at org.astrogrid.samp.xmlrpc.XmlRpcHubConnection.<init>(XmlRpcHubConnection.java:53) ~[jsamp-1.3-3.jar:1.3-3]
at org.astrogrid.samp.xmlrpc.StandardHubConnection.<init>(StandardHubConnection.java:31) ~[jsamp-1.3-3.jar:1.3-3]
at org.astrogrid.samp.xmlrpc.StandardClientProfile.register(StandardClientProfile.java:121) ~[jsamp-1.3-3.jar:1.3-3]
at org.astrogrid.samp.client.HubConnector.createConnection(HubConnector.java:745) ~[jsamp-1.3-3.jar:1.3-3]
at org.astrogrid.samp.client.HubConnector.getConnection(HubConnector.java:663) ~[jsamp-1.3-3.jar:1.3-3]
at org.astrogrid.samp.client.HubConnector.setActive(HubConnector.java:476) ~[jsamp-1.3-3.jar:1.3-3]
at fr.jmmc.jmcs.network.interop.SampManager.<init>(SampManager.java:148) ~[jmcs.jar:na]
at fr.jmmc.jmcs.network.interop.SampManager.getInstance(SampManager.java:69) ~[jmcs.jar:na]
ERROR MESSAGES/STACK TRACES THAT OCCUR :
java.lang.IllegalStateException: zip file closed
at java.util.zip.ZipFile.ensureOpen(ZipFile.java:634)
at java.util.zip.ZipFile.getEntry(ZipFile.java:305)
at java.util.jar.JarFile.getEntry(JarFile.java:226)
at com.sun.deploy.cache.CachedJarFile.getEntry(Unknown Source)
at java.util.jar.JarFile.getJarEntry(JarFile.java:209)
at com.sun.deploy.security.DeployURLClassPath$JarLoader.getResource(Unknown Source)
at com.sun.deploy.security.DeployURLClassPath.getResource(Unknown Source)
at java.net.URLClassLoader$1.run(URLClassLoader.java:358)
at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
at java.security.AccessController.doPrivileged(Native Method)
at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
at com.sun.jnlp.JNLPClassLoader.findClass(Unknown Source)
at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at org.astrogrid.samp.hub.HubServiceMode$2$1.shutdown(HubServiceMode.java:256)
at org.astrogrid.samp.hub.Hub.shutdown(Hub.java:105)
at org.astrogrid.samp.hub.Hub$4.run(Hub.java:521)
at org.astrogrid.samp.ShutdownManager.doCleanup(ShutdownManager.java:94)
at org.astrogrid.samp.ShutdownManager.access$000(ShutdownManager.java:16)
at org.astrogrid.samp.ShutdownManager$1.run(ShutdownManager.java:41)
REPRODUCIBILITY :
This bug can be reproduced always.