eclipse-ee4j / glassfish

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

Exceptions on server shutdown when using JMSJCA resource adapter #10664

Closed glassfishrobot closed 15 years ago

glassfishrobot commented 15 years ago

If I deploy the JMSJCA Resource adapter sun-jms-adapter.rar, run (successfully) an application that uses it, and then shut down the server, the JMSRA Resource adapter is shut down before the JMSJCA resource adapter. This is the wrong order and will cause problems since JMSJCA may be using the embedded broker started by JMSRA.

The following extract from the server log clearly shows the order in which the RA are shut down. This was for an application that created Managed Connections but not MDBs.

INFO: Server shutdown initiated INFO: MQJMSRA_RA1101: SJSMQ JMSRA stopping... INFO: MQJMSRA_RA1101: SJSMQ JMSRA stopped. INFO: ra.stop-successful INFO: ra.stop-successful SEVERE: rardeployment.ra_removal_registry_failure SEVERE: com.sun.appserv.connectors.internal.api.ConnectorRuntimeException: Failed to remove Active Resource Adapter at com.sun.enterprise.connectors.service.ResourceAdapterAdminServiceImpl.destroyActiveResourceAdapter(ResourceAdapterAdminServiceImpl.java:106) at com.sun.enterprise.connectors.service.ResourceAdapterAdminServiceImpl.stopActiveResourceAdapter(ResourceAdapterAdminServiceImpl.java:409) at com.sun.enterprise.connectors.ConnectorRuntime.destroyActiveResourceAdapter(ConnectorRuntime.java:368) at com.sun.enterprise.connectors.module.ConnectorDeployer.unload(ConnectorDeployer.java:211) at com.sun.enterprise.connectors.module.ConnectorDeployer.unload(ConnectorDeployer.java:82) at org.glassfish.internal.data.EngineRef.unload(EngineRef.java:146) at org.glassfish.internal.data.ModuleInfo.unload(ModuleInfo.java:268) at org.glassfish.internal.data.ApplicationInfo.unload(ApplicationInfo.java:263) at com.sun.enterprise.v3.server.ApplicationLoaderService.preDestroy(ApplicationLoaderService.java:388) at com.sun.hk2.component.AbstractWombInhabitantImpl.dispose(AbstractWombInhabitantImpl.java:74) at com.sun.hk2.component.SingletonInhabitant.release(SingletonInhabitant.java:66) at com.sun.hk2.component.LazyInhabitant.release(LazyInhabitant.java:112) at com.sun.enterprise.v3.server.AppServerStartup.stop(AppServerStartup.java:393) at org.jvnet.hk2.osgiadapter.HK2Main.stop(HK2Main.java:141) at org.apache.felix.framework.util.SecureAction.stopActivator(SecureAction.java:661) at org.apache.felix.framework.Felix.stopBundle(Felix.java:2071) at org.apache.felix.framework.BundleImpl.stop(BundleImpl.java:951) at org.apache.felix.framework.BundleImpl.stop(BundleImpl.java:938) at org.jvnet.hk2.osgiadapter.OSGiModuleImpl.detach(OSGiModuleImpl.java:245) at org.jvnet.hk2.osgiadapter.OSGiModuleImpl.stop(OSGiModuleImpl.java:228) at com.sun.enterprise.v3.admin.StopDomainCommand.execute(StopDomainCommand.java:86) at com.sun.enterprise.v3.admin.CommandRunnerImpl$1.execute(CommandRunnerImpl.java:305) at com.sun.enterprise.v3.admin.CommandRunnerImpl$2.run(CommandRunnerImpl.java:333) WARNING: unable to stop resource adapter [ sun-jms-adapter ] INFO: JMXStartupService: shutting down AMX and JMX INFO: JMXStartupService: Stopped JMXConnectorServer: service:jmx:rmi://129.156.69.199:8686/jndi/rmi://129.156.69.199:8686/jmxrmi INFO: Shutdown procedure finished INFO: [Thread[GlassFish Kernel Main Thread,5,main]] exiting

If the JMSJCA application being shut down uses MDBs (as well as Managed Connections, then even more exceptions are generated because Glassfish does not appear to be shutting down the application before shutting down JMSRA.

INFO: Server shutdown initiated INFO: MQJMSRA_RA1101: SJSMQ JMSRA stopping... INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: JMSJCA-E014: [sync-QueueReceiver(lookup://jms/inboundJMSJCAQueue)

{JMSJCAMDB-NewJCAMessageBean-Context} @ [mq://localhost:7676]]: the following exception was encountered while initiating or during message delivery: [[C4063]: Cannot perform operation, consumer is closed.]; attempts will be made to (re-)start message delivery (auto reconnect mode). com.sun.messaging.jms.JMSException: [C4063]: Cannot perform operation, consumer is closed. at com.sun.messaging.jmq.jmsclient.MessageConsumerImpl.receive(MessageConsumerImpl.java:489) at com.stc.jmsjca.core.SyncDelivery$SyncWorker.runOnceStdXA(SyncDelivery.java:573) at com.stc.jmsjca.core.SyncDelivery$SyncWorker.run(SyncDelivery.java:792) Caused by: javax.jms.JMSException: [C4056]: Received goodbye message from broker. at com.sun.messaging.jmq.jmsclient.ReadChannel.processBrokerGoodbye(ReadChannel.java:712) at com.sun.messaging.jmq.jmsclient.ReadChannel.dispatch(ReadChannel.java:288) at com.sun.messaging.jmq.jmsclient.ReadChannel.run(ReadChannel.java:1222) at java.lang.Thread.run(Thread.java:619) WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending INFO: Closing XA session with a transaction pending WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. INFO: MQJMSRA_RA1101: SJSMQ JMSRA stopped. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. INFO: ra.stop-successful INFO: javax.jms.JMSException: [C4056]: Received goodbye message from broker. at com.sun.messaging.jmq.jmsclient.ReadChannel.processBrokerGoodbye(ReadChannel.java:712) at com.sun.messaging.jmq.jmsclient.ReadChannel.dispatch(ReadChannel.java:288) at com.sun.messaging.jmq.jmsclient.ReadChannel.run(ReadChannel.java:1222) at java.lang.Thread.run(Thread.java:619) WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. WARNING: [I500]: Caught JVM Exception: javax.jms.JMSException: [C4056]: Received goodbye message from broker. SEVERE: doSelect exception java.lang.RuntimeException: Error invoking PortMapperClientHandler.handleRequest. Cause - null at com.sun.enterprise.connectors.jms.system.ActiveJmsResourceAdapter.handleRequest(ActiveJmsResourceAdapter.java:2019) at com.sun.enterprise.v3.services.impl.ServiceInitializerHandler.onAcceptInterest(ServiceInitializerHandler.java:108) at com.sun.grizzly.SelectorHandlerRunner.handleSelectedKey(SelectorHandlerRunner.java:295) at com.sun.grizzly.SelectorHandlerRunner.handleSelectedKeys(SelectorHandlerRunner.java:258) at com.sun.grizzly.SelectorHandlerRunner.doSelect(SelectorHandlerRunner.java:195) at com.sun.grizzly.SelectorHandlerRunner.run(SelectorHandlerRunner.java:130) 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:619) Caused by: java.lang.reflect.InvocationTargetException at sun.reflect.GeneratedMethodAccessor52.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at com.sun.enterprise.connectors.jms.system.ActiveJmsResourceAdapter.handleRequest(ActiveJmsResourceAdapter.java:2014) ... 8 more Caused by: java.lang.IllegalStateException: Cannot access PortMapperClientHandler until embedded broker has been started at com.sun.messaging.jms.ra.LifecycleManagedBroker.getPortMapperClientHandler(LifecycleManagedBroker.java:1202) at com.sun.messaging.jms.ra.ResourceAdapter.getPortMapperClientHandler(ResourceAdapter.java:1605) ... 12 more WARNING: [C4003]: Error occurred on connection creation [localhost:7676]. - cause: java.net.ConnectException: Connection refused: connect WARNING: poolmgr.create_resource_error WARNING: resource_pool.resize_pool_error WARNING: [C4003]: Error occurred on connection creation [localhost:7676]. - cause: java.net.ConnectException: Connection refused: connect WARNING: poolmgr.create_resource_error WARNING: resource_pool.resize_pool_error WARNING: [C4003]: Error occurred on connection creation [localhost:7676]. - cause: java.net.ConnectException: Connection refused: connect WARNING: poolmgr.create_resource_error WARNING: resource_pool.resize_pool_error WARNING: [C4003]: Error occurred on connection creation [localhost:7676]. - cause: java.net.ConnectException: Connection refused: connect WARNING: poolmgr.create_resource_error WARNING: resource_pool.resize_pool_error WARNING: [C4003]: Error occurred on connection creation [localhost:7676]. - cause: java.net.ConnectException: Connection refused: connect WARNING: poolmgr.create_resource_error WARNING: resource_pool.resize_pool_error WARNING: [C4003]: Error occurred on connection creation [localhost:7676]. - cause: java.net.ConnectException: Connection refused: connect WARNING: poolmgr.create_resource_error WARNING: resource_pool.resize_pool_error WARNING: [C4003]: Error occurred on connection creation [localhost:7676]. - cause: java.net.ConnectException: Connection refused: connect WARNING: poolmgr.create_resource_error WARNING: resource_pool.resize_pool_error WARNING: [C4003]: Error occurred on connection creation [localhost:7676]. - cause: java.net.ConnectException: Connection refused: connect WARNING: poolmgr.create_resource_error WARNING: resource_pool.resize_pool_error WARNING: RA [ sun-jms-adapter ] stop timeout occured java.util.concurrent.TimeoutException at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:228) at java.util.concurrent.FutureTask.get(FutureTask.java:91) at com.sun.enterprise.connectors.service.ResourceAdapterAdminServiceImpl.sendStopToResourceAdapter(ResourceAdapterAdminServiceImpl.java:497) at com.sun.enterprise.connectors.service.ResourceAdapterAdminServiceImpl.stopAndRemoveActiveResourceAdapter(ResourceAdapterAdminServiceImpl.java:357) at com.sun.enterprise.connectors.service.ResourceAdapterAdminServiceImpl.destroyActiveResourceAdapter(ResourceAdapterAdminServiceImpl.java:105) at com.sun.enterprise.connectors.service.ResourceAdapterAdminServiceImpl.stopActiveResourceAdapter(ResourceAdapterAdminServiceImpl.java:409) at com.sun.enterprise.connectors.service.ResourceAdapterAdminServiceImpl.stopAllActiveResourceAdapters(ResourceAdapterAdminServiceImpl.java:398) at com.sun.enterprise.connectors.ConnectorRuntime.cleanUpResourcesAndShutdownAllActiveRAs(ConnectorRuntime.java:791) at org.glassfish.javaee.services.ResourceManager.preDestroy(ResourceManager.java:171) at com.sun.hk2.component.AbstractWombInhabitantImpl.dispose(AbstractWombInhabitantImpl.java:74) at com.sun.hk2.component.SingletonInhabitant.release(SingletonInhabitant.java:66) at com.sun.hk2.component.LazyInhabitant.release(LazyInhabitant.java:112) at com.sun.enterprise.v3.server.AppServerStartup.stop(AppServerStartup.java:383) at org.jvnet.hk2.osgiadapter.HK2Main.stop(HK2Main.java:141) at org.apache.felix.framework.util.SecureAction.stopActivator(SecureAction.java:661) at org.apache.felix.framework.Felix.stopBundle(Felix.java:2071) at org.apache.felix.framework.BundleImpl.stop(BundleImpl.java:951) at org.apache.felix.framework.BundleImpl.stop(BundleImpl.java:938) at org.jvnet.hk2.osgiadapter.OSGiModuleImpl.detach(OSGiModuleImpl.java:245) at org.jvnet.hk2.osgiadapter.OSGiModuleImpl.stop(OSGiModuleImpl.java:228) at com.sun.enterprise.v3.admin.StopDomainCommand.execute(StopDomainCommand.java:86) at com.sun.enterprise.v3.admin.CommandRunnerImpl$1.execute(CommandRunnerImpl.java:305) at com.sun.enterprise.v3.admin.CommandRunnerImpl$2.run(CommandRunnerImpl.java:333) INFO: cancelling the shutdown of RA [ sun-jms-adapter ] status : true WARNING: ra.stop-unsuccessful WARNING: JMSJCA-E011: [sync-QueueReceiver(lookup://jms/inboundJMSJCAQueue){JMSJCAMDB-NewJCAMessageBean-Context}

@ [mq://localhost:7676]]: stop() operation was interrupted; state is now Connecting SEVERE: Exception in thread "MQTimer-Thread" SEVERE: java.lang.NullPointerException at com.sun.messaging.jmq.jmsserver.data.handlers.GoodbyeTask.run(GoodbyeHandler.java:225) at java.util.TimerThread.mainLoop(Timer.java:512) at java.util.TimerThread.run(Timer.java:462) WARNING: [MDBContainer] Current thread done cleanup()... SEVERE: rardeployment.ra_removal_registry_failure SEVERE: com.sun.appserv.connectors.internal.api.ConnectorRuntimeException: Failed to remove Active Resource Adapter at com.sun.enterprise.connectors.service.ResourceAdapterAdminServiceImpl.destroyActiveResourceAdapter(ResourceAdapterAdminServiceImpl.java:106) at com.sun.enterprise.connectors.service.ResourceAdapterAdminServiceImpl.stopActiveResourceAdapter(ResourceAdapterAdminServiceImpl.java:409) at com.sun.enterprise.connectors.ConnectorRuntime.destroyActiveResourceAdapter(ConnectorRuntime.java:368) at com.sun.enterprise.connectors.module.ConnectorDeployer.unload(ConnectorDeployer.java:211) at com.sun.enterprise.connectors.module.ConnectorDeployer.unload(ConnectorDeployer.java:82) at org.glassfish.internal.data.EngineRef.unload(EngineRef.java:146) at org.glassfish.internal.data.ModuleInfo.unload(ModuleInfo.java:268) at org.glassfish.internal.data.ApplicationInfo.unload(ApplicationInfo.java:263) at com.sun.enterprise.v3.server.ApplicationLoaderService.preDestroy(ApplicationLoaderService.java:388) at com.sun.hk2.component.AbstractWombInhabitantImpl.dispose(AbstractWombInhabitantImpl.java:74) at com.sun.hk2.component.SingletonInhabitant.release(SingletonInhabitant.java:66) at com.sun.hk2.component.LazyInhabitant.release(LazyInhabitant.java:112) at com.sun.enterprise.v3.server.AppServerStartup.stop(AppServerStartup.java:393) at org.jvnet.hk2.osgiadapter.HK2Main.stop(HK2Main.java:141) at org.apache.felix.framework.util.SecureAction.stopActivator(SecureAction.java:661) at org.apache.felix.framework.Felix.stopBundle(Felix.java:2071) at org.apache.felix.framework.BundleImpl.stop(BundleImpl.java:951) at org.apache.felix.framework.BundleImpl.stop(BundleImpl.java:938) at org.jvnet.hk2.osgiadapter.OSGiModuleImpl.detach(OSGiModuleImpl.java:245) at org.jvnet.hk2.osgiadapter.OSGiModuleImpl.stop(OSGiModuleImpl.java:228) at com.sun.enterprise.v3.admin.StopDomainCommand.execute(StopDomainCommand.java:86) at com.sun.enterprise.v3.admin.CommandRunnerImpl$1.execute(CommandRunnerImpl.java:305) at com.sun.enterprise.v3.admin.CommandRunnerImpl$2.run(CommandRunnerImpl.java:333) WARNING: unable to stop resource adapter [ sun-jms-adapter ] WARNING: [MDBContainer] Current thread done cleanup()... INFO: JMXStartupService: shutting down AMX and JMX INFO: JMXStartupService: Stopped JMXConnectorServer: service:jmx:rmi://129.156.69.24:8686/jndi/rmi://129.156.69.24:8686/jmxrmi INFO: Shutdown procedure finished INFO: [Thread[GlassFish Kernel Main Thread,5,main]] exiting

Environment

Operating System: All Platform: PC

Affected Versions

[V3]

glassfishrobot commented 6 years ago
glassfishrobot commented 15 years ago

@glassfishrobot Commented sats said: The sequence of stopping the RAs is handled by the connector's module. Reassigning the issue to Jagadish.

glassfishrobot commented 15 years ago

@glassfishrobot Commented @h2002044 said: Issue seems to be due to the ordering of calls to "PreDestroy" implementations

1) org.glassfish.javaee.services.ResourceManager is esponsible for shutdown of system-rars (and any other available Rars) and its resources, pools. (eg: jms-ra) 2) ApplicationLoaderService is responsible for shutdown of all applications including Rars, in-turn its resources and pools (eg: any deployed Rars)

(2) must happen before (1). In this case, it is the opposite that is causing the issue.

glassfishrobot commented 15 years ago

@glassfishrobot Commented @h2002044 said: After talking to Jerome, transferring to Jerome for further investigation.

glassfishrobot commented 15 years ago

@glassfishrobot Commented dochez said: implemented a priority concept so ApplicationLoaderService is started last on startup and implemented a reverse order preDestroy call. This should fix this ordering issue.

glassfishrobot commented 15 years ago

@glassfishrobot Commented Was assigned to dochez

glassfishrobot commented 7 years ago

@glassfishrobot Commented This issue was imported from java.net JIRA GLASSFISH-10664

glassfishrobot commented 15 years ago

@glassfishrobot Commented Reported by nigeldeakin

glassfishrobot commented 15 years ago

@glassfishrobot Commented Marked as fixed on Monday, November 2nd 2009, 2:37:21 pm