search

payara / Payara

Payara Server is an open source middleware platform that supports reliable and secure deployments of Java EE (Jakarta EE) and MicroProfile applications in any environment: on premise, in the cloud or hybrid.
http://www.payara.fish
Other
880 stars 302 forks source link

Bug Report: Server shutdown causes unexpected exceptions from monitoring module/FISH-9222 #6879

Closed lprimak closed 2 weeks ago

lprimak commented 1 month ago

Brief Summary

Monitoring console is trying to call Grizzly after server is shut down from another thread. This is causing exceptions to happen and prevents a clean shutdown.

This doesn't happen every time, but about 1/30 shutdowns.

Expected Outcome

No exceptions are produced

Current Outcome

[2024-08-09T05:07:59.243-0500] [Payara 6.2024.7] [INFO] [NCLS-CORE-00092] [javax.enterprise.system.core] [tid: _ThreadID=675 _ThreadName=Thread-38] [timeMillis: 1723198079243] [levelValue: 800] [[
  Server shutdown initiated]]

[2024-08-09T05:07:59.265-0500] [Payara 6.2024.7] [INFO] [] [] [tid: _ThreadID=675 _ThreadName=Thread-38] [timeMillis: 1723198079265] [levelValue: 800] [[
  FileMonitoring shutdown]]

[2024-08-09T05:07:59.278-0500] [Payara 6.2024.7] [INFO] [NCLS-JMX-00002] [javax.enterprise.system.jmx] [tid: _ThreadID=675 _ThreadName=Thread-38] [timeMillis: 1723198079278] [levelValue: 800] [[
  JMXStartupService: Stopped JMXConnectorServer: null]]

[2024-08-09T05:07:59.278-0500] [Payara 6.2024.7] [INFO] [NCLS-JMX-00001] [javax.enterprise.system.jmx] [tid: _ThreadID=675 _ThreadName=Thread-38] [timeMillis: 1723198079278] [levelValue: 800] [[
  JMXStartupService and JMXConnectors have been shut down.]]

[2024-08-09T05:07:59.304-0500] [Payara 6.2024.7] [INFO] [] [fish.payara.nucleus.hazelcast.HazelcastCore] [tid: _ThreadID=678 _ThreadName=RunLevelControllerThread-1723198079280] [timeMillis: 1723198079304] [levelValue: 800] [[
  Hazelcast Instance Unbound from JNDI at payara/Hazelcast]]

[2024-08-09T05:07:59.304-0500] [Payara 6.2024.7] [INFO] [] [fish.payara.nucleus.hazelcast.HazelcastCore] [tid: _ThreadID=678 _ThreadName=RunLevelControllerThread-1723198079280] [timeMillis: 1723198079304] [levelValue: 800] [[
  JSR107 Caching Provider Unbound from JNDI at payara/CachingProvider]]

[2024-08-09T05:07:59.305-0500] [Payara 6.2024.7] [INFO] [] [fish.payara.nucleus.hazelcast.HazelcastCore] [tid: _ThreadID=678 _ThreadName=RunLevelControllerThread-1723198079280] [timeMillis: 1723198079305] [levelValue: 800] [[
  JSR107 Cache Manager Unbound from JNDI at payara/CacheManager]]

[2024-08-09T05:07:59.333-0500] [Payara 6.2024.7] [INFO] [] [fish.payara.nucleus.hazelcast.HazelcastCore] [tid: _ThreadID=678 _ThreadName=RunLevelControllerThread-1723198079280] [timeMillis: 1723198079333] [levelValue: 800] [[
  Shutdown Hazelcast]]

[2024-08-09T05:07:59.363-0500] [Payara 6.2024.7] [INFO] [] [] [tid: _ThreadID=680 _ThreadName=RunLevelControllerThread-1723198079280] [timeMillis: 1723198079363] [levelValue: 800] [[
  JdbcRuntimeExtension,  getAllSystemRAResourcesAndPools = [GlassFishConfigBean.org.glassfish.jdbc.config.JdbcResource, GlassFishConfigBean.org.glassfish.jdbc.config.JdbcResource, GlassFishConfigBean.org.glassfish.jdbc.config.JdbcConnectionPool, GlassFishConfigBean.org.glassfish.jdbc.config.JdbcConnectionPool]]]

[2024-08-09T05:07:59.384-0500] [Payara 6.2024.7] [WARNING] [] [fish.payara.appserver.micro.services.PayaraInstanceImpl] [tid: _ThreadID=143 _ThreadName=payara-executor-service-scheduled-task] [timeMillis: 1723198079384] [levelValue: 900] [[
  Failed to get running Grizzly listener.
MultiException stack 1 of 1
java.lang.IllegalStateException: Service com.sun.enterprise.v3.services.impl.GrizzlyService was started at level 1 but it has a run level of 10.  The full descriptor is SystemDescriptor(
    implementation=com.sun.enterprise.v3.services.impl.GrizzlyService
    contracts={com.sun.enterprise.v3.services.impl.GrizzlyService,org.glassfish.api.container.RequestDispatcher,fish.payara.monitoring.collect.MonitoringDataSource}
    scope=org.glassfish.hk2.runlevel.RunLevel
    qualifiers={}
    descriptorType=CLASS
    descriptorVisibility=NORMAL
    metadata=runLevelValue={10},Bundle-SymbolicName={fish.payara.server.core.nucleus.kernel},Bundle-Version={6.17.0}
    rank=50
    loader=OsgiPopulatorPostProcessor.HK2Loader(OSGiModuleImpl:: Bundle = [fish.payara.server.core.nucleus.kernel [322]], State = [READY],1913685535)
    proxiable=null
    proxyForSameScope=null
    analysisName=null
    id=636
    locatorId=0
    identityHashCode=1091399088
    reified=true)
    at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.validate(AsyncRunLevelContext.java:422)
    at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.findOrCreate(AsyncRunLevelContext.java:275)
    at org.glassfish.hk2.runlevel.RunLevelContext.findOrCreate(RunLevelContext.java:65)
    at org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2103)
    at org.jvnet.hk2.internal.ServiceLocatorImpl.internalGetAllServiceHandles(ServiceLocatorImpl.java:1497)
    at org.jvnet.hk2.internal.ServiceLocatorImpl.getAllServices(ServiceLocatorImpl.java:810)
    at org.jvnet.hk2.internal.ServiceLocatorImpl.getAllServices(ServiceLocatorImpl.java:798)
    at fish.payara.monitoring.runtime.MonitoringConsoleRuntimeImpl.lambda$init$0(MonitoringConsoleRuntimeImpl.java:186)
    at fish.payara.monitoring.internal.adapt.MonitoringConsoleImpl.lambda$new$0(MonitoringConsoleImpl.java:92)
    at fish.payara.monitoring.internal.data.InMemorySeriesRepository.collectAll(InMemorySeriesRepository.java:225)
    at fish.payara.monitoring.internal.data.InMemorySeriesRepository.collectSourcesToMemory(InMemorySeriesRepository.java:196)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
    at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:358)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
    at java.base/java.lang.Thread.run(Thread.java:1570)
]]

[2024-08-09T05:07:59.385-0500] [Payara 6.2024.7] [WARNING] [] [fish.payara.appserver.micro.services.PayaraInstanceImpl] [tid: _ThreadID=143 _ThreadName=payara-executor-service-scheduled-task] [timeMillis: 1723198079385] [levelValue: 900] [[
  Failed to get running Grizzly listener.
MultiException stack 1 of 1
java.lang.IllegalStateException: Service com.sun.enterprise.v3.services.impl.GrizzlyService was started at level 1 but it has a run level of 10.  The full descriptor is SystemDescriptor(
    implementation=com.sun.enterprise.v3.services.impl.GrizzlyService
    contracts={com.sun.enterprise.v3.services.impl.GrizzlyService,org.glassfish.api.container.RequestDispatcher,fish.payara.monitoring.collect.MonitoringDataSource}
    scope=org.glassfish.hk2.runlevel.RunLevel
    qualifiers={}
    descriptorType=CLASS
    descriptorVisibility=NORMAL
    metadata=runLevelValue={10},Bundle-SymbolicName={fish.payara.server.core.nucleus.kernel},Bundle-Version={6.17.0}
    rank=50
    loader=OsgiPopulatorPostProcessor.HK2Loader(OSGiModuleImpl:: Bundle = [fish.payara.server.core.nucleus.kernel [322]], State = [READY],1913685535)
    proxiable=null
    proxyForSameScope=null
    analysisName=null
    id=636
    locatorId=0
    identityHashCode=1091399088
    reified=true)
    at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.validate(AsyncRunLevelContext.java:422)
    at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.findOrCreate(AsyncRunLevelContext.java:275)
    at org.glassfish.hk2.runlevel.RunLevelContext.findOrCreate(RunLevelContext.java:65)
    at org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2103)
    at org.jvnet.hk2.internal.ServiceLocatorImpl.internalGetAllServiceHandles(ServiceLocatorImpl.java:1497)
    at org.jvnet.hk2.internal.ServiceLocatorImpl.getAllServices(ServiceLocatorImpl.java:810)
    at org.jvnet.hk2.internal.ServiceLocatorImpl.getAllServices(ServiceLocatorImpl.java:798)
    at fish.payara.monitoring.runtime.MonitoringConsoleRuntimeImpl.lambda$init$0(MonitoringConsoleRuntimeImpl.java:186)
    at fish.payara.monitoring.internal.adapt.MonitoringConsoleImpl.lambda$new$0(MonitoringConsoleImpl.java:92)
    at fish.payara.monitoring.internal.data.InMemorySeriesRepository.collectAll(InMemorySeriesRepository.java:225)
    at fish.payara.monitoring.internal.data.InMemorySeriesRepository.collectSourcesToMemory(InMemorySeriesRepository.java:196)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
    at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:358)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
    at java.base/java.lang.Thread.run(Thread.java:1570)
]]

[2024-08-09T05:07:59.387-0500] [Payara 6.2024.7] [WARNING] [] [fish.payara.appserver.micro.services.PayaraInstanceImpl] [tid: _ThreadID=143 _ThreadName=payara-executor-service-scheduled-task] [timeMillis: 1723198079387] [levelValue: 900] [[
  Failed to get running Grizzly listener.
MultiException stack 1 of 1
java.lang.IllegalStateException: Service com.sun.enterprise.v3.services.impl.GrizzlyService was started at level 1 but it has a run level of 10.  The full descriptor is SystemDescriptor(
    implementation=com.sun.enterprise.v3.services.impl.GrizzlyService
    contracts={com.sun.enterprise.v3.services.impl.GrizzlyService,org.glassfish.api.container.RequestDispatcher,fish.payara.monitoring.collect.MonitoringDataSource}
    scope=org.glassfish.hk2.runlevel.RunLevel
    qualifiers={}
    descriptorType=CLASS
    descriptorVisibility=NORMAL
    metadata=runLevelValue={10},Bundle-SymbolicName={fish.payara.server.core.nucleus.kernel},Bundle-Version={6.17.0}
    rank=50
    loader=OsgiPopulatorPostProcessor.HK2Loader(OSGiModuleImpl:: Bundle = [fish.payara.server.core.nucleus.kernel [322]], State = [READY],1913685535)
    proxiable=null
    proxyForSameScope=null
    analysisName=null
    id=636
    locatorId=0
    identityHashCode=1091399088
    reified=true)
    at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.validate(AsyncRunLevelContext.java:422)
    at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.findOrCreate(AsyncRunLevelContext.java:275)
    at org.glassfish.hk2.runlevel.RunLevelContext.findOrCreate(RunLevelContext.java:65)
    at org.jvnet.hk2.internal.Utilities.createService(Utilities.java:2103)
    at org.jvnet.hk2.internal.ServiceLocatorImpl.internalGetAllServiceHandles(ServiceLocatorImpl.java:1497)
    at org.jvnet.hk2.internal.ServiceLocatorImpl.getAllServices(ServiceLocatorImpl.java:810)
    at org.jvnet.hk2.internal.ServiceLocatorImpl.getAllServices(ServiceLocatorImpl.java:798)
    at fish.payara.monitoring.runtime.MonitoringConsoleRuntimeImpl.lambda$init$0(MonitoringConsoleRuntimeImpl.java:186)
    at fish.payara.monitoring.internal.adapt.MonitoringConsoleImpl.lambda$new$0(MonitoringConsoleImpl.java:92)
    at fish.payara.monitoring.internal.data.InMemorySeriesRepository.collectAll(InMemorySeriesRepository.java:225)
    at fish.payara.monitoring.internal.data.InMemorySeriesRepository.collectSourcesToMemory(InMemorySeriesRepository.java:196)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
    at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:358)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
    at java.base/java.lang.Thread.run(Thread.java:1570)
]]

[2024-08-09T05:07:59.588-0500] [Payara 6.2024.7] [INFO] [] [javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors.service] [tid: _ThreadID=692 _ThreadName=RA Shutdown] [timeMillis: 1723198079588] [levelValue: 800] [[
  RAR7094: __ds_jdbc_ra shutdown successful.]]

Reproducer

Unable to consistently reproduce. However, there is good debugging information so I will submit a PR

Operating System

Any

JDK Version

Any

Payara Distribution

Payara Server Full Profile, Payara Server Web Profile

felixif commented 4 weeks ago

Hello @lprimak,

Thank you for the report and for submitting the PR that would fix the issue. The PR will be analysed by our Platform Development team.

Best regards, Felix