search

eclipse-ee4j / glassfish

Eclipse GlassFish
https://eclipse-ee4j.github.io/glassfish/
386 stars 145 forks source link

Deploy command never ends and asadmin becomes unusable (JMXStartupService: Stopped JMXConnectorServer: null]) #24323

Open szarza opened 1 year ago

szarza commented 1 year ago

After a try to deploy a big ear (which is working perfectly in glassfish 6) the command deploy never ends (though it seems it has finished) and asadmin doesn't respond to any command. I have attached the last logs:

`[2023-02-27T11:54:07.769900+01:00] [GlassFish 7.0] [INFO] [AS-WEB-GLUE-00172] [jakarta.enterprise.web] [tid: _ThreadID=119 _ThreadName=admin-listener(3)] [levelValue: 800] [[ Loading application [calypso.server#server.frontend-3.0.0.war] at [/calypso]]]

[2023-02-27T11:54:07.906838+01:00] [GlassFish 7.0] [INFO] [] [org.glassfish.soteria.servlet.SamRegistrationInstaller] [tid: _ThreadID=119 _ThreadName=admin-listener(3)] [levelValue: 800] [[ Initializing Soteria 3.0.2 for context '/admin']]

[2023-02-27T11:54:08.230759+01:00] [GlassFish 7.0] [INFO] [] [jakarta.enterprise.logging.stdout] [tid: _ThreadID=18 _ThreadName=GlassFish Shutdown Hook] [levelValue: 800] [[ FileMonitoring shutdown]]

[2023-02-27T11:54:08.248777+01:00] [GlassFish 7.0] [INFO] [NCLS-JMX-00002] [jakarta.enterprise.system.jmx] [tid: _ThreadID=18 _ThreadName=GlassFish Shutdown Hook] [levelValue: 800] [[ JMXStartupService: Stopped JMXConnectorServer: null]]

[2023-02-27T11:54:08.249604+01:00] [GlassFish 7.0] [INFO] [NCLS-JMX-00001] [jakarta.enterprise.system.jmx] [tid: _ThreadID=18 _ThreadName=GlassFish Shutdown Hook] [levelValue: 800] [[ JMXStartupService and JMXConnectors have been shut down.]] `

Environment Details

I don't know how to provide more information because my application needs a lot of settings to deploy (connects to a webservice, use a database, and so on) and I do not have a "little" demonstrator. If I should enable some logs, please let me know.

dmatej commented 1 year ago

Hi, the server.log excerpt you posted is from a server shutdown - something stops the server. That is intentional after the deploy or you don't know what invoked the shutdown? It is quite suspicious if the deploy finished in one second without any log and then is immediately followed by server's shutdown. The simplest idea I have is that it is something in your script. The worst is that it is something in the war file or in the server ...?

You can try to edit logging.properties, comment out all logger settings and except handlers leave there just 

.logger=FINEST

Then try to find out what is before the first line executed by the ThreadName=GlassFish Shutdown Hook. Something asked the server to stop, you have to find out what.

szarza commented 1 year ago

I've found the culprit: an updated ZK Framework library from my web module from the ear application, but I don't understand why. I got the error just changing 9.6.0 by 9.6.3 version of https://www.zkoss.org/product/zk.

The effect in Glassfish 6.2.5 is a Glassfish crash (the java process still running but asadmin port doesn't listen). The effect in Glassfish 7.0.2 is deploy get stuck until timeout and asadmin stops working.

I did the change on logging.properties and only see:

[2023-02-27T15:29:10.938743+01:00] [GlassFish 7.0] [INFO] [] [org.eclipse.krazo.servlet.KrazoContainerInitializer] [tid: _ThreadID=117 _ThreadName=admin-listener(1)] [levelValue: 800] [[
  Eclipse Krazo version 3.0.1 started]]

[2023-02-27T15:29:10.943743+01:00] [GlassFish 7.0] [INFO] [] [org.glassfish.soteria.servlet.SamRegistrationInstaller] [tid: _ThreadID=117 _ThreadName=admin-listener(1)] [levelValue: 800] [[
  Initializing Soteria 3.0.2 for context '/calypso']]

[2023-02-27T15:29:11.315832+01:00] [GlassFish 7.0] [INFO] [AS-WEB-GLUE-00172] [jakarta.enterprise.web] [tid: _ThreadID=117 _ThreadName=admin-listener(1)] [levelValue: 800] [[
  Loading application [calypso.server#server.frontend-3.0.0.war] at [/calypso]]]

[2023-02-27T15:29:11.415241+01:00] [GlassFish 7.0] [INFO] [] [org.glassfish.soteria.servlet.SamRegistrationInstaller] [tid: _ThreadID=117 _ThreadName=admin-listener(1)] [levelValue: 800] [[
  Initializing Soteria 3.0.2 for context '/admin']]

[2023-02-27T15:29:11.728270+01:00] [GlassFish 7.0] [SEVERE] [] [jakarta.enterprise.logging.stderr] [tid: _ThreadID=117 _ThreadName=admin-listener(1)] [levelValue: 1000] [[
  Your ZK binary is being altered and may not work as expected. Please contact us at info@zkoss.org for assistance.]]

[2023-02-27T15:29:11.729729+01:00] [GlassFish 7.0] [INFO] [] [jakarta.enterprise.logging.stdout] [tid: _ThreadID=18 _ThreadName=GlassFish Shutdown Hook] [levelValue: 800] [[
  FileMonitoring shutdown]]

[2023-02-27T15:29:11.746148+01:00] [GlassFish 7.0] [INFO] [NCLS-JMX-00002] [jakarta.enterprise.system.jmx] [tid: _ThreadID=18 _ThreadName=GlassFish Shutdown Hook] [levelValue: 800] [[
  JMXStartupService: Stopped JMXConnectorServer: null]]

[2023-02-27T15:29:11.746594+01:00] [GlassFish 7.0] [INFO] [NCLS-JMX-00001] [jakarta.enterprise.system.jmx] [tid: _ThreadID=18 _ThreadName=GlassFish Shutdown Hook] [levelValue: 800] [[
  JMXStartupService and JMXConnectors have been shut down.]]

[2023-02-27T15:29:12.017128+01:00] [GlassFish 7.0] [INFO] [] [org.glassfish.web.loader.WebappClassLoader] [tid: _ThreadID=287 _ThreadName=RunLevelControllerThread-1677508151749] [levelValue: 800] [[
  close(), this:
org.glassfish.web.loader.WebappClassLoader@28838cca[name=], urls=[
file:/home/szarza/bin/glassfish7-calypso/glassfish/lib/install/applications/__admingui/WEB-INF/classes/
file:/home/szarza/bin/glassfish7-calypso/glassfish/lib/install/applications/__admingui/WEB-INF/lib/console-core-7.0.2.jar
file:/home/szarza/bin/glassfish7-calypso/glassfish/lib/install/applications/__admingui/WEB-INF/lib/console-core-7.0.2-SNAPSHOT.jar
file:/home/szarza/bin/glassfish7-calypso/glassfish/domains/calypso/generated/ejb/__admingui//
file:/home/szarza/bin/glassfish7-calypso/glassfish/lib/install/applications/__admingui/WEB-INF/extra/woodstock-webui-jsf-suntheme-6.0.0.jar
file:/home/szarza/bin/glassfish7-calypso/glassfish/lib/install/applications/__admingui/WEB-INF/extra/dojo-ajax-nodemo-1.12.4.jar
file:/home/szarza/bin/glassfish7-calypso/glassfish/lib/install/applications/__admingui/WEB-INF/extra/woodstock-webui-jsf-6.0.0.jar
file:/home/szarza/bin/glassfish7-calypso/glassfish/lib/install/applications/__admingui/WEB-INF/extra/json-2.0.jar
file:/home/szarza/bin/glassfish7-calypso/glassfish/lib/install/applications/__admingui/WEB-INF/extra/prototype-1.7.3.jar
file:/home/szarza/bin/glassfish7-calypso/glassfish/lib/install/applications/__admingui/WEB-INF/extra/commons-io-2.11.0.jar
file:/home/szarza/bin/glassfish7-calypso/glassfish/domains/calypso/generated/__admingui/
][delegate=true, context=, status=RUNNING, antiJARLocking=false, securityManager=false, packageDefinitionSecurityEnabled=false, repositories=RepositoryManager[WEB-INF/classes/], notFound.size=297, pathTimestamps.size=2, resourceEntryCache.size=0]]]

Below the output of my deploy ant task:

  [echo] [1528] Deploy calypso.server-3.0.0-r692-8abe6e0 as calypso.server
  [asadmin] Command deploy failed.
  [asadmin] No response from Domain Admin Server after 600 seconds.
  [asadmin] The command is either taking too long to complete or the server has failed.
  [asadmin] Please see the server log files for command status.

BUILD FAILED
....

Total time: 20 minutes 1 second

I opened a support ticket to ZK (https://potix.freshdesk.com/support/tickets/15723), but... It is the first time that I see glassfish "knocked out" by a library of a war.

OndroMih commented 1 year ago

Is this easy to reproduce with a simple app and the ZK library? If yes, can you create a reproducer and post it here? It would be interesting to see how a library in an EAR can trigger GlassFish shut down and prevent it if possible.

dmatej commented 1 year ago

One idea I have now is that something in the war executes System.exit or something like that. I am not sure if it worked in GF6, but maybe I could create a test for that. Perhaps GlassFish could also do some filtering and block signals from war files. Now it is rather hypothetical.

OndroMih commented 1 year ago

Calls to System.exit() can be prevented by the security manager if it's enabled. Although the Security Manager is deprecated in Java 17 for removal, it's currently the only option and there are yet no concrete plans to provide an alternative after the sec manager is removed: https://bugs.openjdk.org/browse/JDK-8199704

szarza commented 1 year ago

Is this easy to reproduce with a simple app and the ZK library? If yes, can you create a reproducer and post it here? It would be interesting to see how a library in an EAR can trigger GlassFish shut down and prevent it if possible.

It will take me a few days because I'm really busy right now. I'll try next week.

szarza commented 1 year ago

Zk's support has answered me.

When ZK libraries show the binary warning, "Your ZK binary is being altered and may not work as expected. Please contact us at info@zkoss.org for assistance.", it stops the whole system (application server). Theoretically, this only happens by mixing artifacts from the "enterprise" (commercial) edition with others from the community (free) edition. But this is not the case, because I was mixing (by error) artifacts of version 9.6.0 (in ear module) with others from version 9.6.3 in war module, but all of them from the "enterprise" edition.

The same support people have created a feature request for this server-stopping behavior: https://tracker.zkoss.org/browse/ZK-5139, to evaluate and change it in the future. But they have not told me how they are able to knock out the server.

So I think I will not be able to create a reproducer with sources since the commercial libraries have restricted access because are under protected repositories. Would it be useful for you if I send you a binary reproducer ear file?

OndroMih commented 1 year ago

Yes, I think a binary reproducer could be enough to understand what's going on if I can reproduce the issue with it.

szarza commented 1 year ago

Hello again:

This is the way to reproduce: image 1.- Start an instance of Glassfish 6.2.5 or 7.0.2 2.- Deploy the ear you can download here (github doesn't allow me to attach an .ear file).

As you can see in server.log, after the message Your ZK binary is being altered and may not work as expected. Please contact us at info@zkoss.org for assistance. the process of Glassfish Server is still alive, but has become unusable.

I hope this helps. I you need anything else, please let me know.

dmatej commented 1 year ago

You told that the ear works well with Glassfish6, but I couldn't even deploy it - it ended the same way on GF7.0.3-SNAPSHOT except GF7 provides more logs (we reimplemented logging, so now it doesn't depend on HK2 and is able to cover whole JVM lifecycle).

It seems to me that the application does something "against rules", "criminal".

This is on GF6:

[2023-03-19T20:48:09.262+0100] [glassfish 6.2] [SEVERE] [] [jakarta.enterprise.system.tools.deployment.common] [tid: _ThreadID=183 _ThreadName=admin-listener(7)] [timeMillis: 1679255289262] [levelValue: 1000] [[
Exception while visiting sun.security.util.KnownOIDs]]
...
[2023-03-19T20:48:09.986+0100] [glassfish 6.2] [WARNING] [AS-WEB-UTIL-00035] [jakarta.enterprise.web.util] [tid: _ThreadID=183 _ThreadName=admin-listener(7)] [timeMillis: 1679255289986] [levelValue: 900] [[
Unable to load class org.zkoss.zkmax.au.websocket.WebSocketEndPoint, reason: java.lang.ClassNotFoundException: org.zkoss.zkmax.au.websocket.WebSocketEndPoint]]

[2023-03-19T20:48:09.993+0100] [glassfish 6.2] [WARNING] [AS-WEB-UTIL-00035] [jakarta.enterprise.web.util] [tid: _ThreadID=183 _ThreadName=admin-listener(7)] [timeMillis: 1679255289993] [levelValue: 900] [[
Unable to load class org.zkoss.zkmax.au.websocket.WebSocketEndPoint, reason: java.lang.ClassNotFoundException: org.zkoss.zkmax.au.websocket.WebSocketEndPoint]]

Both GF6 and GF7 end in some weird "zombie state" - they do not respond, but the JVM is still alive.

This log is just on GF7 - but again, we improved logging in GF7, so now it can collect STDERR too:

[2023-03-19T20:57:16.288398+01:00] [GF 7.0.3-SNAPSHOT] [SEVERE] [] [jakarta.enterprise.logging.stderr] [tid: _ThreadID=69 _ThreadName=admin-listener(4)] [levelValue: 1000] [[
Your ZK binary is being altered and may not work as expected. Please contact us at info@zkoss.org for assistance.]]

I can try yet once on GF7 with full logging, but I don't think we can help you without sources of the callypso.ear.... there's quite lot of exception, nothing about what it does with GlassFish, but missing classes, CDI, etc.

Is there a beans.xml file? Which bean-discovery-mode it uses? This might or might not be ok, it depends ...

[2023-03-19T21:08:53.755157+01:00] [GF 7.0.3-SNAPSHOT] [FINE] [] [org.glassfish.weld.BeanManagerNamingProxy] [tid: _ThreadID=69 _ThreadName=admin-listener(4)] [levelValue: 500] [[
Cannot handle the java:comp/BeanManager, because no CDI bean deployment archive found for descriptor.name=calypso.server-3.0.0#cestel.calypso-server.admin-3.0.0.war
org.glassfish.weld.BeanManagerNamingProxy$BeanManagerException: Cannot handle the java:comp/BeanManager, because no CDI bean deployment archive found for descriptor.name=calypso.server-3.0.0#cestel.calypso-server.admin-3.0.0.war
at org.glassfish.weld.BeanManagerNamingProxy.getBeanManager(BeanManagerNamingProxy.java:118)
at org.glassfish.weld.BeanManagerNamingProxy.handle(BeanManagerNamingProxy.java:85)
at com.sun.enterprise.naming.impl.NamedNamingObjectManager.tryNamedProxies(NamedNamingObjectManager.java:74)
at com.sun.enterprise.naming.impl.JavaURLContext.lookupOrCollectException(JavaURLContext.java:550)
at com.sun.enterprise.naming.impl.JavaURLContext.lookup(JavaURLContext.java:147)
at com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:818)
at com.sun.enterprise.naming.impl.SerialContext.lookup(SerialContext.java:257)
at java.naming/javax.naming.InitialContext.lookup(InitialContext.java:409)
at java.naming/javax.naming.InitialContext.lookup(InitialContext.java:409)
at org.glassfish.soteria.cdi.CdiUtils.jndiLookup(CdiUtils.java:225)
at org.glassfish.soteria.cdi.CdiUtils.getBeanManager(CdiUtils.java:117)

Then it could not find some classes (again, might be ok):

On the GF side:

On the application side:

szarza commented 1 year ago

Sorry, I was wrong In my first post when I told you it works fine in Glassfish 6. In my last post, I commented that you can reproduce the problem both in GF 6 and in GF 7.

If I don't mix artefacts from different version numbers and set the same version in all modules, the application deploys, and everything goes well.

Certainly, the behaviour of GF is really weird and I can't imagine how the libraries can do it either.

github-actions[bot] commented 8 months ago

This issue has been marked as inactive and old and will be closed in 7 days if there is no further activity. If you want the issue to remain open please add a comment

dmatej commented 8 months ago

@szarza Is it still happening with 7.0.13? In #24616 we improved closing resources, so I am curious if something might change on your side too.

szarza commented 8 months ago

HI @dmatej: Unfortunately, it is still happening with 7.0.13. Accidentally I removed the reproducer (the "reduced" version of my application), but I've tested with my whole app and the problem remains.