glassfish
  1. glassfish
  2. GLASSFISH-17256

"java.lang.IllegalStateException: zip file closed" from ResourceBundle.getBundle called during logging

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 3.1.1
    • Fix Version/s: 3.1.2_b02, 4.0
    • Component/s: logging, OSGi
    • Labels:
      None

      Description

      For some reasons, I have started to see some random failures in my tests in embedded mode. All the failures were accompanied by following kinds of exception in log file:

      ERROR: JarContent: Unable to read bytes. (java.lang.IllegalStateException: zip file closed)
      java.lang.IllegalStateException: zip file closed
      at java.util.zip.ZipFile.ensureOpen(ZipFile.java:404)
      at java.util.zip.ZipFile.getEntry(ZipFile.java:148)
      at org.apache.felix.framework.util.ZipFileX.getEntry(ZipFileX.java:52)
      at org.apache.felix.framework.cache.JarContent.getEntryAsBytes(JarContent.java:122)
      at org.apache.felix.framework.ModuleImpl$ModuleClassLoader.findClass(ModuleImpl.java:1816)
      at org.apache.felix.framework.ModuleImpl.findClassOrResourceByDelegation(ModuleImpl.java:727)
      at org.apache.felix.framework.ModuleImpl.access$400(ModuleImpl.java:71)
      at org.apache.felix.framework.ModuleImpl$ModuleClassLoader.loadClass(ModuleImpl.java:1768)
      at java.lang.ClassLoader.loadClass(ClassLoader.java:248)
      at java.util.ResourceBundle$Control.newBundle(ResourceBundle.java:2289)
      at java.util.ResourceBundle.loadBundle(ResourceBundle.java:1364)
      at java.util.ResourceBundle.findBundle(ResourceBundle.java:1328)
      at java.util.ResourceBundle.findBundle(ResourceBundle.java:1282)
      at java.util.ResourceBundle.getBundleImpl(ResourceBundle.java:1224)
      at java.util.ResourceBundle.getBundle(ResourceBundle.java:952)
      at com.sun.logging.LogDomains$1.getResourceBundle(LogDomains.java:373)
      at org.glassfish.webservices.WebServicesDeployer.<init>(WebServicesDeployer.java:110)
      at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
      at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
      at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
      at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
      at java.lang.Class.newInstance0(Class.java:355)
      at java.lang.Class.newInstance(Class.java:308)
      at com.sun.hk2.component.ConstructorCreator.create(ConstructorCreator.java:65)
      at com.sun.hk2.component.AbstractCreatorImpl.get(AbstractCreatorImpl.java:80)
      at com.sun.hk2.component.SingletonInhabitant.get(SingletonInhabitant.java:67)
      at com.sun.hk2.component.EventPublishingInhabitant.get(EventPublishingInhabitant.java:139)
      at com.sun.hk2.component.AbstractInhabitantImpl.get(AbstractInhabitantImpl.java:76)
      at org.jvnet.hk2.component.Habitat.getBy(Habitat.java:1048)
      at org.jvnet.hk2.component.Habitat.getByType(Habitat.java:1029)
      at org.jvnet.hk2.component.Habitat.getComponent(Habitat.java:779)
      at com.sun.enterprise.v3.server.ApplicationLifecycle.startContainers(ApplicationLifecycle.java:965)
      at com.sun.enterprise.v3.server.ApplicationLifecycle.setupContainerInfos(ApplicationLifecycle.java:667)
      at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:368)
      at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:240)
      at org.glassfish.osgijavaeebase.OSGiDeploymentRequest.deploy(OSGiDeploymentRequest.java:183)
      at org.glassfish.osgijavaeebase.OSGiDeploymentRequest.execute(OSGiDeploymentRequest.java:118)
      at org.glassfish.osgijavaeebase.AbstractOSGiDeployer.deploy(AbstractOSGiDeployer.java:121)
      at org.glassfish.osgijavaeebase.OSGiContainer.deploy(OSGiContainer.java:154)
      at org.glassfish.osgijavaeebase.JavaEEExtender.deploy(JavaEEExtender.java:107)
      at org.glassfish.osgijavaeebase.JavaEEExtender.access$200(JavaEEExtender.java:61)
      at org.glassfish.osgijavaeebase.JavaEEExtender$HybridBundleTrackerCustomizer$1.call(JavaEEExtender.java:151)
      at org.glassfish.osgijavaeebase.JavaEEExtender$HybridBundleTrackerCustomizer$1.call(JavaEEExtender.java:148)
      at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
      at java.util.concurrent.FutureTask.run(FutureTask.java:138)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:662)

      I profiled the JDK to collect more information like the zip file name and the code path(s) that are closing the zip files that are being accessed subsequently and some timestamp to correlate with other messages in log. I found the following very useful information:

      ERROR: JarContent: Unable to read bytes. (java.lang.IllegalStateException: zip file /export/home1/java_re/BUILD_AREA/workspace/gf-3.1.2-fighterfish-it/ff/fighterfish-gf3.1.1/test/test.it/target/osgi-cache/Felix/bundle208/version0.0/bundle.jar closed. See the exception chain details to find out which code has closed it - Mon Aug 29 09:44:39 PDT 2011)
      java.lang.IllegalStateException: zip file /export/home1/java_re/BUILD_AREA/workspace/gf-3.1.2-fighterfish-it/ff/fighterfish-gf3.1.1/test/test.it/target/osgi-cache/Felix/bundle208/version0.0/bundle.jar closed. See the exception chain details to find out which code has closed it - Mon Aug 29 09:44:39 PDT 2011
      at java.util.zip.ZipFile.ensureOpen(ZipFile.java:404)
      at java.util.zip.ZipFile.getEntry(ZipFile.java:148)
      at org.apache.felix.framework.util.ZipFileX.getEntry(ZipFileX.java:52)
      at org.apache.felix.framework.cache.JarContent.getEntryAsBytes(JarContent.java:122)
      at org.apache.felix.framework.ModuleImpl$ModuleClassLoader.findClass(ModuleImpl.java:1816)
      at org.apache.felix.framework.ModuleImpl.findClassOrResourceByDelegation(ModuleImpl.java:727)
      at org.apache.felix.framework.ModuleImpl.access$400(ModuleImpl.java:71)
      at org.apache.felix.framework.ModuleImpl$ModuleClassLoader.loadClass(ModuleImpl.java:1768)
      at java.lang.ClassLoader.loadClass(ClassLoader.java:248)
      at java.util.ResourceBundle$Control.newBundle(ResourceBundle.java:2289)
      at java.util.ResourceBundle.loadBundle(ResourceBundle.java:1364)
      at java.util.ResourceBundle.findBundle(ResourceBundle.java:1328)
      at java.util.ResourceBundle.findBundle(ResourceBundle.java:1282)
      at java.util.ResourceBundle.getBundleImpl(ResourceBundle.java:1224)
      at java.util.ResourceBundle.getBundle(ResourceBundle.java:952)
      at com.sun.logging.LogDomains$1.getResourceBundle(LogDomains.java:373)
      at org.glassfish.webservices.WebServicesDeployer.<init>(WebServicesDeployer.java:110)
      at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
      at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
      at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
      at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
      at java.lang.Class.newInstance0(Class.java:355)
      at java.lang.Class.newInstance(Class.java:308)
      at com.sun.hk2.component.ConstructorCreator.create(ConstructorCreator.java:65)
      at com.sun.hk2.component.AbstractCreatorImpl.get(AbstractCreatorImpl.java:80)
      at com.sun.hk2.component.SingletonInhabitant.get(SingletonInhabitant.java:67)
      at com.sun.hk2.component.EventPublishingInhabitant.get(EventPublishingInhabitant.java:139)
      at com.sun.hk2.component.AbstractInhabitantImpl.get(AbstractInhabitantImpl.java:76)
      at org.jvnet.hk2.component.Habitat.getBy(Habitat.java:1048)
      at org.jvnet.hk2.component.Habitat.getByType(Habitat.java:1029)
      at org.jvnet.hk2.component.Habitat.getComponent(Habitat.java:779)
      at com.sun.enterprise.v3.server.ApplicationLifecycle.startContainers(ApplicationLifecycle.java:965)
      at com.sun.enterprise.v3.server.ApplicationLifecycle.setupContainerInfos(ApplicationLifecycle.java:667)
      at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:368)
      at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:240)
      at org.glassfish.osgijavaeebase.OSGiDeploymentRequest.deploy(OSGiDeploymentRequest.java:183)
      at org.glassfish.osgijavaeebase.OSGiDeploymentRequest.execute(OSGiDeploymentRequest.java:118)
      at org.glassfish.osgijavaeebase.AbstractOSGiDeployer.deploy(AbstractOSGiDeployer.java:121)
      at org.glassfish.osgijavaeebase.OSGiContainer.deploy(OSGiContainer.java:154)
      at org.glassfish.osgijavaeebase.JavaEEExtender.deploy(JavaEEExtender.java:107)
      at org.glassfish.osgijavaeebase.JavaEEExtender.access$200(JavaEEExtender.java:61)
      at org.glassfish.osgijavaeebase.JavaEEExtender$HybridBundleTrackerCustomizer$1.call(JavaEEExtender.java:151)
      at org.glassfish.osgijavaeebase.JavaEEExtender$HybridBundleTrackerCustomizer$1.call(JavaEEExtender.java:148)
      at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
      at java.util.concurrent.FutureTask.run(FutureTask.java:138)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:662)
      Caused by: java.lang.Throwable: Mon Aug 29 09:44:12 PDT 2011
      at java.util.zip.ZipFile.close(ZipFile.java:361)
      at org.apache.felix.framework.cache.JarRevision.close(JarRevision.java:121)
      at org.apache.felix.framework.cache.BundleArchive.close(BundleArchive.java:663)
      at org.apache.felix.framework.BundleImpl.close(BundleImpl.java:105)
      at org.apache.felix.framework.Felix$SystemBundleActivator.run(Felix.java:4406)
      ... 1 more

      The caused by exception in the above stack points to the code that has closed the zip file and the associated time stamp.

      I suspected some kind of stale class loader being used and found that our looging code is responsible in leaking module class loaders into JDK. LogDomains.getLogger(Class, String) creates a new Logger which maintains strong reference to a module class loader. In JDK logging API, there is no way to remove/replace a logger. JDK's LogManager maintains only a wek map of logger names to loggers, so if GC has not cleared the weak references before framework is restarted in the same VM, Logger.getLogger can return the old logger which will then use the old class loader causing the "zip file closed" exception.

        Activity

        Hide
        Sanjeeb Sahoo added a comment -

        The fix is to cache resource bundle at the time of logger creation so that we don't need the class loader subsequently.
        3.1.2:
        Sending common/common-util/src/main/java/com/sun/logging/LogDomains.java
        Transmitting file data .
        Committed revision 49113.

        trunk:
        Sending common-util/src/main/java/com/sun/logging/LogDomains.java
        Transmitting file data .
        Committed revision 49116.

        Show
        Sanjeeb Sahoo added a comment - The fix is to cache resource bundle at the time of logger creation so that we don't need the class loader subsequently. 3.1.2: Sending common/common-util/src/main/java/com/sun/logging/LogDomains.java Transmitting file data . Committed revision 49113. trunk: Sending common-util/src/main/java/com/sun/logging/LogDomains.java Transmitting file data . Committed revision 49116.

          People

          • Assignee:
            Sanjeeb Sahoo
            Reporter:
            Sanjeeb Sahoo
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: