Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8042694

javaws Shutdown hook failure: zip file closed

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Won't Fix
    • Icon: P3 P3
    • None
    • 7u25
    • deploy

      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.

            aivanov Alexey Ivanov
            webbuggrp Webbug Group
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: