search

arquillian / arquillian-extension-warp

Warp fills the void between client-side and server-side testing.
https://github.com/lfryc/arquillian.github.com/blob/warp-docs/docs/warp.adoc
Apache License 2.0
14 stars 30 forks source link

Update GlassFish to a version beyond 4.0 #131

Open WolfgangHG opened 1 year ago

WolfgangHG commented 1 year ago

Currently, the tests use GlassFish 4.0

Updating to a newer version causes severe timing problems: each test runs about 2 minutes (but in the end works), which makes the test suite unusable. This happens with 4.1.2 and 5.1.0.

When using a remote GlassFish server, there is console output like this:

[2023-05-18T11:37:07.402+0200] [glassfish 4.1] [SEVERE] [] [javax.enterprise.web.util] [tid: _ThreadID=52 _ThreadName=admin-listener(3)] [timeMillis: 1684402627402] [levelValue: 1000] [[
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.impl.ManagerImpl$1] (value [org.jboss.arquillian.core.impl.ManagerImpl$1@4180ca55]) and a value of type [java.util.HashSet] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.]]

But this is also printed with 4.0, so I don't think it is related.

WolfgangHG commented 1 year ago

Might really be related to the "ThreadLocal" warning.

I found https://github.com/mjiderhamn/classloader-leak-prevention, and when adding the necessary three jars in "org.jboss.arquillian.warp.impl.client.deployment.DeploymentEnricher.addWarpExtensionsDeployment" to the deployed WAR file, the time for excuting a single test goes down to 30 seconds (which is still horrible, but better than 90 seconds).

    private void addWarpExtensionsDeployment(WebArchive archive) {
        final Collection<WarpDeploymentEnrichmentExtension> lifecycleExtensions = serviceLoader.get().all(WarpDeploymentEnrichmentExtension.class);

        for (WarpDeploymentEnrichmentExtension extension : lifecycleExtensions) {
            ...
        }

        archive.addAsLibrary(new java.io.File("C:\\path\\to\\classloader-leak-prevention-core-2.7.0.jar"));
        archive.addAsLibrary(new java.io.File("C:\\path\\to\\classloader-leak-prevention-servlet3-2.7.0.jar"));
        archive.addAsLibrary(new java.io.File("C:\\path\\to\\classloader-leak-prevention-servlet-2.7.0.jar"));
    }

@chengfang Do you have further knowledge of arquillian internals?

Below is the glassfish output when running only a single test with this command - all ThreadLocal messages point to arquillian core classes, so I don't know where they are linked to the warp extension:

mvnw install -Pglassfish-remote-4-0 -Dtest="org.jboss.arquillian.warp.ftest.cdi.CdiWarpTest.java" -DfailIfNoTests=false`
[#|2023-05-19T22:47:20.539+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240539;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@4a4a36ed]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.540+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240540;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@51d418d6]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.540+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240540;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.impl.ManagerImpl$1] (value [org.jboss.arquillian.core.impl.ManagerImpl$1@1310e023]) and a value of type [java.util.HashSet] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.540+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240540;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@49cc8b9c]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.540+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240540;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@52aa3116]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.540+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240540;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@2349813d]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.541+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240541;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@4a4a36ed]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.541+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240541;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@51d418d6]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.541+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240541;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.impl.ManagerImpl$1] (value [org.jboss.arquillian.core.impl.ManagerImpl$1@1310e023]) and a value of type [java.util.HashSet] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.541+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240541;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@49cc8b9c]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.541+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240541;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@52aa3116]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.542+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240542;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@2349813d]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.542+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240542;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@4a4a36ed]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.542+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240542;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@51d418d6]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.542+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240542;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.impl.ManagerImpl$1] (value [org.jboss.arquillian.core.impl.ManagerImpl$1@1310e023]) and a value of type [java.util.HashSet] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.542+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240542;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@49cc8b9c]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.542+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240542;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@52aa3116]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.543+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240543;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@2349813d]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.543+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240543;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@51d418d6]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.543+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240543;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.impl.ManagerImpl$1] (value [org.jboss.arquillian.core.impl.ManagerImpl$1@1310e023]) and a value of type [java.util.HashSet] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.543+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240543;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@52aa3116]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.543+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240543;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@4a4a36ed]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.544+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240544;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@49cc8b9c]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.544+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240544;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@2349813d]) and a value of type [java.util.Stack] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.544+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240544;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.impl.ManagerImpl$1] (value [org.jboss.arquillian.core.impl.ManagerImpl$1@1310e023]) and a value of type [java.util.HashSet] (value [[]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]

[#|2023-05-19T22:47:20.544+0200|SEVERE|glassfish 4.1|javax.enterprise.web.util|_ThreadID=49;_ThreadName=admin-listener(5);_TimeMillis=1684529240544;_LevelValue=1000;|
  The web application [/test] created a ThreadLocal with key of type [org.jboss.arquillian.core.spi.context.AbstractContext$1] (value [org.jboss.arquillian.core.spi.context.AbstractContext$1@49cc8b9c]) and a value of type [java.util.Stack] (value [[org.jboss.arquillian.core.spi.context.AbstractContext$StoreHolder@37cc7c8f]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.|#]
chengfang commented 1 year ago

@WolfgangHG I don't know off the top of my head. It could be a removal is missing in some application stop callback somewhere in arquillian-core or glassfish container impl, or more complicated if there is no obvious place to do so. I'll take a closer look.

WolfgangHG commented 1 year ago

@chengfang How do we continue with this? Do you have any idea or know someone to ask ;-)?

chengfang commented 1 year ago

We don't have necessary glassfish knowledge to tackle it. As this is a glassfish specific issue, I think we should be able to lower its priority and move forward without fixing it now.

WolfgangHG commented 1 year ago

I still would like to sort it out... Probably, the ThreadLocal warnings are not related to the delay, but they are the only hint currently.

Seems the problems are caused by org.jboss.arquillian.core.spi.context.AbstractContext which really contains a threadlocal stack.

I tried to add a "javax.servlet.ServletContextListener" to the deployment and can confirm that "contextDestroyed" is called before the ThreadLocal warnings are printed. Maybe it would be sufficient to call "AbstractContext.destroy" in this method. But how to get the context?

The inspiration for this came from https://stackoverflow.com/questions/22032045/why-am-i-receiving-jdbc-driver-warning-and-threadlocal-errors

WolfgangHG commented 1 year ago

@chengfang Do you have any idea on how to access the Arquillian context?

WolfgangHG commented 1 year ago

WildFly might have the same ThreadLocal leak issue - when adding the "classloader-leak-prevention" jars to the testing war files, the same message is printed as for GlassFish.

I have the suspicion that it is caused by org.jboss.arquillian.warp.impl.server.execution.WarpFilter: "init" creates a org.jboss.arquillian.core.impl.ManagerImpl, and "destroy" tries to clean up. But as "destroy" is called on a different thread, the ThreadLocals in org.jboss.arquillian.core.spi.context.AbstractContext, that were created by "init", are not reachable and thus untouched.

WolfgangHG commented 1 year ago

I tried two approaches to work around the ThreadLocal leaks. They are both applied to org.jboss.arquillian.core.spi.context.AbstractContext.clearAll and org.jboss.arquillian.core.impl.ManagerImpl.shutdown Both remove the ThreadLocal warning from the glassfish console, but the timing problem is not fixed.

First approach: force-cleanup ThreadLocals by using reflection (inspired by https://stackoverflow.com/questions/3869026/how-to-clean-up-threadlocals ). Here is the diff: cleanup_threadlocal_diff.txt

Second approach: remove the usage of ThreadLocal und use a HashTable that maps a thread id to a value. Here is the diff: custom_threadlocal_diff.txt

Running a single test still takes about 1 minute, os there is no improvement at all. Using the "classloader-leak-prevention", the time goes down to 30 seconds, but the tool does not provide any information whether it fixes anything. Further research is necessary...

WolfgangHG commented 1 year ago

The delay does not occur when using linux. Seems to be a windows issue.

This thread pointed me to a possible cause: https://stackoverflow.com/questions/48296933/glassfish-undeployment-does-not-work-on-windows-but-works-fine-on-linux Linked from this post is a glassfish issue that was closed as "not reproduceable": https://github.com/eclipse-ee4j/glassfish/issues/21283

After the "test.war" file was undeployed, all jar files from "WEB-INF\lib" still reside in the glassfish deploy directory, and I cannot delete them using Windows explorer, until glassfish is stopped. glassfish_jars So glassfish seems to lock itself: it tries to delete jars from the application, but cannot do so.

Maybe used by some classloader?

WolfgangHG commented 1 year ago

I sent a pull request (and forgot to create a branch first...) - the glassfish profiles are now linux only ;-). After updating to JakartaEE10 and recent GlassFish versions, we could take another look at it. But as it works on linux, it does not block further progress with this extension.

@chengfang I would like to get rid of the "ThreadLocal" warnings in glassfish console, which means a change to arquillian. What do you think of my suggestion (file "cleanup_threadlocal_diff.txt" in previous comment)?

chengfang commented 12 months ago

@WolfgangHG if seems quite some hacks including using reflection to get non-public data. I'm not sure if all these hard-to-maintain code is worth it to fix the warning.

WolfgangHG commented 12 months ago

@chengfang I don't know whether those ThreadLocals could cause memory issues e.g. on a WildFly server (where this warning is not reported). So it gives me a better feeling to clean them up properly ;-). Unfortunately, the usage of Arquillian in the warp extension (where cleanup is done in a javax.servlet.Filter) does not allow a better way to clean it up, as the init method is called on another thread than destroy. So there is no chance to do cleanup in Warp itself I think. Do you have any better idea?

WolfgangHG commented 11 months ago

I did some research on the "locked files prevent undeploy" issue with the help of File Leak Detector.

For my own records: start it with this command and attach it to a running GlassFish process (processid is "1234" in the sample):

java -jar file-leak-detector-1.14-jar-with-dependencies.jar 1234 strong,trace=c:\temp\fileleaks.txt

Run it with the same java version that GlassFish uses. That's the reason why I use 1.14 - newer versions are not compatible.

It prints out a file with stack traces for each file opened and closed. I filtered only operations for one of the "WEB-INF\lib" jar files (here: "arquillian-jacoco.jar") and removed all open/close pairs. This left two "open without close" calls.

The first call stack is a GlassFish internal class:

Opened C:\Temp\glassfish412\glassfish\domains\domain1\applications\test\WEB-INF\lib\arquillian-jacoco.jar by thread:admin-listener(2) on Sun Sep 17 11:41:51 CEST 2023
    at java.util.zip.ZipFile.<init>(ZipFile.java:157)
    at java.util.jar.JarFile.<init>(JarFile.java:168)
    at java.util.jar.JarFile.<init>(JarFile.java:132)
    at com.sun.enterprise.deployment.deploy.shared.InputJarArchive.getJarFile(InputJarArchive.java:315)
    at com.sun.enterprise.deployment.deploy.shared.InputJarArchive.open(InputJarArchive.java:304)
    at com.sun.enterprise.deploy.shared.ArchiveFactory.openArchive(ArchiveFactory.java:210)
    at com.sun.enterprise.deploy.shared.ArchiveFactory.openArchive(ArchiveFactory.java:115)
    at com.sun.enterprise.deploy.shared.FileArchive.getSubArchive(FileArchive.java:333)
    at org.glassfish.weld.BeanDeploymentArchiveImpl.populate(BeanDeploymentArchiveImpl.java:462)
    at org.glassfish.weld.BeanDeploymentArchiveImpl.<init>(BeanDeploymentArchiveImpl.java:150)
    at org.glassfish.weld.RootBeanDeploymentArchive.createModuleBda(RootBeanDeploymentArchive.java:94)
    at org.glassfish.weld.RootBeanDeploymentArchive.<init>(RootBeanDeploymentArchive.java:87)
    at org.glassfish.weld.RootBeanDeploymentArchive.<init>(RootBeanDeploymentArchive.java:75)
    at org.glassfish.weld.DeploymentImpl.createModuleBda(DeploymentImpl.java:712)
    at org.glassfish.weld.DeploymentImpl.<init>(DeploymentImpl.java:131)
    at org.glassfish.weld.WeldDeployer.load(WeldDeployer.java:473)
    at org.glassfish.weld.WeldDeployer.load(WeldDeployer.java:101)
    at org.glassfish.internal.data.ModuleInfo.load(ModuleInfo.java:206)
    at org.glassfish.internal.data.ApplicationInfo.load(ApplicationInfo.java:313)
    at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:496)
    at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:219)
    at org.glassfish.deployment.admin.DeployCommand.execute(DeployCommand.java:491)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$2$1.run(CommandRunnerImpl.java:539)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$2$1.run(CommandRunnerImpl.java:535)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.security.auth.Subject.doAs(Subject.java:360)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$2.execute(CommandRunnerImpl.java:534)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$3.run(CommandRunnerImpl.java:565)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$3.run(CommandRunnerImpl.java:557)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.security.auth.Subject.doAs(Subject.java:360)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:556)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:1464)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl.access$1300(CommandRunnerImpl.java:109)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1846)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1722)
    at org.glassfish.admin.rest.utils.ResourceUtil.runCommand(ResourceUtil.java:253)
    at org.glassfish.admin.rest.utils.ResourceUtil.runCommand(ResourceUtil.java:231)
    at org.glassfish.admin.rest.utils.ResourceUtil.runCommand(ResourceUtil.java:275)
    at org.glassfish.admin.rest.resources.TemplateListOfResource.createResource(TemplateListOfResource.java:328)
    at org.glassfish.admin.rest.resources.TemplateListOfResource.post(TemplateListOfResource.java:163)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
    at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160)
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
    at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:309)
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:267)
    at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
    at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:292)
    at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1139)
    at org.glassfish.jersey.grizzly2.httpserver.GrizzlyHttpContainer.service(GrizzlyHttpContainer.java:375)
    at org.glassfish.admin.rest.adapter.RestAdapter$2.service(RestAdapter.java:316)
    at org.glassfish.admin.rest.adapter.RestAdapter.service(RestAdapter.java:179)
    at com.sun.enterprise.v3.services.impl.ContainerMapper$HttpHandlerCallable.call(ContainerMapper.java:459)
    at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:167)
    at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:206)
    at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:180)
    at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:235)
    at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:283)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:200)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:132)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:111)
    at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
    at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:536)
    at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:137)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:591)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:571)
    at java.lang.Thread.run(Thread.java:750)

Here is the code for BeanDeploymentArchiveImpl.populate and GlassFish 5.0. And here is the same file for recent 7.0. There were changes about closing files in 2022.

So hopefully this is fixed with recent versions.

The other "file open" stacktrace is by arquillian, see following reply.

WolfgangHG commented 11 months ago

The second "file open" is caused by arquillian:

Opened C:\Temp\glassfish412\glassfish\domains\domain1\applications\test\WEB-INF\lib\arquillian-jacoco.jar by thread:admin-listener(2) on Sun Sep 17 11:41:52 CEST 2023
    at java.util.zip.ZipFile.<init>(ZipFile.java:157)
    at java.util.jar.JarFile.<init>(JarFile.java:168)
    at java.util.jar.JarFile.<init>(JarFile.java:105)
    at sun.net.www.protocol.jar.URLJarFile.<init>(URLJarFile.java:93)
    at sun.net.www.protocol.jar.URLJarFile.getJarFile(URLJarFile.java:69)
    at sun.net.www.protocol.jar.JarFileFactory.getOrCreate(JarFileFactory.java:115)
    at sun.net.www.protocol.jar.JarURLConnection.connect(JarURLConnection.java:129)
    at sun.net.www.protocol.jar.JarURLConnection.getInputStream(JarURLConnection.java:172)
    at java.net.URL.openStream(URL.java:1092)
    at org.jboss.arquillian.container.test.impl.RemoteExtensionLoader.load(RemoteExtensionLoader.java:188)
    at org.jboss.arquillian.container.test.impl.RemoteExtensionLoader.all(RemoteExtensionLoader.java:93)
    at org.jboss.arquillian.container.test.impl.RemoteExtensionLoader.load(RemoteExtensionLoader.java:67)
    at org.jboss.arquillian.core.impl.loadable.LoadableExtensionLoader.load(LoadableExtensionLoader.java:69)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.jboss.arquillian.core.impl.ObserverImpl.invoke(ObserverImpl.java:86)
    at org.jboss.arquillian.core.impl.EventContextImpl.invokeObservers(EventContextImpl.java:103)
    at org.jboss.arquillian.core.impl.EventContextImpl.proceed(EventContextImpl.java:90)
    at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:134)
    at org.jboss.arquillian.core.impl.ManagerImpl.fire(ManagerImpl.java:106)
    at org.jboss.arquillian.core.impl.ManagerImpl.fireProcessing(ManagerImpl.java:299)
    at org.jboss.arquillian.core.impl.ManagerImpl.<init>(ManagerImpl.java:93)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at org.jboss.arquillian.core.spi.SecurityActions.newInstance(SecurityActions.java:144)
    at org.jboss.arquillian.core.spi.SecurityActions.newInstance(SecurityActions.java:89)
    at org.jboss.arquillian.core.spi.ManagerBuilder.create(ManagerBuilder.java:68)
    at org.jboss.arquillian.warp.impl.server.execution.WarpFilter.init(WarpFilter.java:70)
    at org.apache.catalina.core.ApplicationFilterConfig.getFilter(ApplicationFilterConfig.java:275)
    at org.apache.catalina.core.ApplicationFilterConfig.<init>(ApplicationFilterConfig.java:131)
    at org.apache.catalina.core.StandardContext.filterStart(StandardContext.java:5329)
    at org.apache.catalina.core.StandardContext.start(StandardContext.java:5974)
    at com.sun.enterprise.web.WebModule.start(WebModule.java:691)
    at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:1041)
    at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:1024)
    at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:747)
    at com.sun.enterprise.web.WebContainer.loadWebModule(WebContainer.java:2286)
    at com.sun.enterprise.web.WebContainer.loadWebModule(WebContainer.java:1932)
    at com.sun.enterprise.web.WebApplication.start(WebApplication.java:139)
    at org.glassfish.internal.data.EngineRef.start(EngineRef.java:122)
    at org.glassfish.internal.data.ModuleInfo.start(ModuleInfo.java:291)
    at org.glassfish.internal.data.ApplicationInfo.start(ApplicationInfo.java:352)
    at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:500)
    at com.sun.enterprise.v3.server.ApplicationLifecycle.deploy(ApplicationLifecycle.java:219)
    at org.glassfish.deployment.admin.DeployCommand.execute(DeployCommand.java:491)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$2$1.run(CommandRunnerImpl.java:539)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$2$1.run(CommandRunnerImpl.java:535)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.security.auth.Subject.doAs(Subject.java:360)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$2.execute(CommandRunnerImpl.java:534)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$3.run(CommandRunnerImpl.java:565)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$3.run(CommandRunnerImpl.java:557)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.security.auth.Subject.doAs(Subject.java:360)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:556)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl.doCommand(CommandRunnerImpl.java:1464)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl.access$1300(CommandRunnerImpl.java:109)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1846)
    at com.sun.enterprise.v3.admin.CommandRunnerImpl$ExecutionContext.execute(CommandRunnerImpl.java:1722)
    at org.glassfish.admin.rest.utils.ResourceUtil.runCommand(ResourceUtil.java:253)
    at org.glassfish.admin.rest.utils.ResourceUtil.runCommand(ResourceUtil.java:231)
    at org.glassfish.admin.rest.utils.ResourceUtil.runCommand(ResourceUtil.java:275)
    at org.glassfish.admin.rest.resources.TemplateListOfResource.createResource(TemplateListOfResource.java:328)
    at org.glassfish.admin.rest.resources.TemplateListOfResource.post(TemplateListOfResource.java:163)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
    at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160)
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
    at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:309)
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:267)
    at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
    at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:292)
    at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1139)
    at org.glassfish.jersey.grizzly2.httpserver.GrizzlyHttpContainer.service(GrizzlyHttpContainer.java:375)
    at org.glassfish.admin.rest.adapter.RestAdapter$2.service(RestAdapter.java:316)
    at org.glassfish.admin.rest.adapter.RestAdapter.service(RestAdapter.java:179)
    at com.sun.enterprise.v3.services.impl.ContainerMapper$HttpHandlerCallable.call(ContainerMapper.java:459)
    at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:167)
    at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:206)
    at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:180)
    at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:235)
    at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:283)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:200)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:132)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:111)
    at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
    at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:536)
    at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:117)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:137)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:591)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:571)
    at java.lang.Thread.run(Thread.java:750)

The code in org.jboss.arquillian.container.test.impl.RemoteExtensionLoader.load really seems to have an issue. First of all, there is no closing of InputStream is. But this would not prevent the file leak. It is caused by this line:

final InputStream is = url.openStream();

openStream is a shortcut to openConnection().getInputStream(), and openConnection() returns a java.net.URLConnection, which has a subclass sun.net.www.protocol.jar.JarURLConnection (code e.g. here). This class uses a cache by default (see method connect). This cache causes the file leak. There is no API to flush the cache.

But you can simply avoid using the cache by calling setUseCaches(false):

    private <T> Set<Class<? extends T>> load(Class<T> serviceClass, ClassLoader loader) {
        ...

        try {
            Enumeration<URL> enumeration = loader.getResources(serviceFile);
            while (enumeration.hasMoreElements()) {
                final URL url = enumeration.nextElement();
                java.net.URLConnection jarConn = url.openConnection();
                jarConn.setUseCaches(false);
                final InputStream is = jarConn.getInputStream();
                ...

                try {
                    ...
                } finally {
                    if (is != null) {
                      is.close();
                    }
                    ...
                }
            }
        } catch (Exception e) {
            ....
        }
        ...
    }

Now, the InputStream.close call really releases the file handle.

@chengfang What do you think about this change to arquillian? Unfortunately, we cannot test whether this fixes the windows file leak issues until we upgrade to GlassFish 7 ;-). So we could also keep this on hold until we upgrade arquillian-warp to JakartaEE10.

I think there is no reason to cache the jar files in Arquillian, as they are accessed only once. So, there should be no performance impact.

WildFly is not affected by this issue, because the implementation of "URLConnection" is completely different (org.jboss.vfs.protocol.VirtualFileURLConnection) and does not do caching/file locking.

WolfgangHG commented 11 months ago

@chengfang I can reproduce an OutOfMemoryException when running the warp tests in the "wildfly-remote" profile after several runs (about 5-7 turns). After testing with an arquillian 1.7.2-SNAPSHOT including my ThreadLocal workaround, I did not observe this error after 20 test runs. So it seems to really have a positive effect ;-). Can I convince you to add this cleanup to arquillian? I can send a pull request, if it is OK for you.

chengfang commented 11 months ago

@WolfgangHG can you open a PR to arquillian-core so it will be easier to review and also get input from wider audience? Thanks for looking into these difficult issues.

WolfgangHG commented 11 months ago

Pull requests sent....

WolfgangHG commented 1 month ago

The arquillian pull requests for file leak and ThreadLocal leak were accepted. Just for the records: the ThreadLocal cleanup workaround had to be reworked and ThreadLocal was replaced with a custom implementation: https://github.com/arquillian/arquillian-core/pull/588

So, this issue is about upgrading to a JakartaEE10 version of glassfish, where hopefully more file leaks were fixed, see comment above.