AMX errors prevent stopping (and removing) a clustered instance

glassfishrobot commented 12 years ago

The EJB Timer clustered hudson tests recently started failing when (not always) the previous test that created 2 clusters with 2 instances each, while reporting a successful cluster removal, still leaves 1 instance per cluster running (or in some weird state)

Attached zip has logs for in1 and in2 created by the test and c1in1 and c2in1 logs are left over from the previous test (where you can see AMX exceptions at the end of the server.log).

Affected Versions

[4.0]

glassfishrobot commented 6 years ago

Issue Imported From: https://github.com/javaee/glassfish/issues/18878
Original Issue Raised By:@glassfishrobot
Original Issue Assigned To: @yaminikb
Original Issue Closed By:@glassfishrobot

glassfishrobot commented 12 years ago

@glassfishrobot Commented tmueller said: Here are the exception messages from the instance log, where it shows that the AMX subsystem is having difficulties when the instance is being shutdown.

[#|2012-07-04T05:11:32.408-0700|SEVERE|44.0|javax.enterprise.system.amx.org.glassfish.admin.amx.impl|_ThreadID=31;_ThreadName=Thread-2;|AMX006: AMX Startup Service loading AMX MBeans

{0}

java.lang.IllegalStateException: BootAMX listener was not called at org.glassfish.admin.amx.impl.AMXStartupService._loadAMXMBeans(AMXStartupService.java:360) at org.glassfish.admin.amx.impl.AMXStartupService.loadAMXMBeans(AMXStartupService.java:228) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:93) at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:27) at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(MBeanIntrospector.java:208) at com.sun.jmx.mbeanserver.PerInterface.invoke(PerInterface.java:120) at com.sun.jmx.mbeanserver.MBeanSupport.invoke(MBeanSupport.java:262) at javax.management.StandardMBean.invoke(StandardMBean.java:391) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:836) at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:761) at org.glassfish.admin.mbeanserver.BootAMX.bootAMX(BootAMX.java:163) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.amxDomain(AdminAuthorizedMBeanServer.java:161) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.isAMX(AdminAuthorizedMBeanServer.java:156) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.isAMX(AdminAuthorizedMBeanServer.java:149) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.isAllowed(AdminAuthorizedMBeanServer.java:143) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.invoke(AdminAuthorizedMBeanServer.java:104) at $Proxy128.unregisterMBean(Unknown Source) at org.glassfish.admin.mbeanserver.JMXStartupService$JMXConnectorsStarterThread.shutdown(JMXStartupService.java:247) at org.glassfish.admin.mbeanserver.JMXStartupService.shutdown(JMXStartupService.java:191) at org.glassfish.admin.mbeanserver.JMXStartupService.access$000(JMXStartupService.java:94) at org.glassfish.admin.mbeanserver.JMXStartupService$ShutdownListener.event(JMXStartupService.java:161) at org.glassfish.kernel.event.EventsImpl.send(EventsImpl.java:128) at com.sun.enterprise.v3.server.AppServerStartup.stop(AppServerStartup.java:316) at com.sun.enterprise.glassfish.bootstrap.GlassFishImpl.stop(GlassFishImpl.java:88) at com.sun.enterprise.glassfish.bootstrap.GlassFishDecorator.stop(GlassFishDecorator.java:68) at com.sun.enterprise.v3.admin.StopServer.doExecute(StopServer.java:71) at com.sun.enterprise.v3.admin.cluster.StopInstanceInstanceCommand.execute(StopInstanceInstanceCommand.java:96) at com.sun.enterprise.v3.admin.CommandRunnerImpl$2.execute(CommandRunnerImpl.java:498) at org.glassfish.api.AsyncImpl$1$1.run(AsyncImpl.java:78)

| #] |

[#|2012-07-04T05:11:32.410-0700|WARNING|44.0|javax.enterprise.system.core.org.glassfish.kernel.event|_ThreadID=31;_ThreadName=Thread-2;|Exception while dispatching an event javax.management.RuntimeMBeanException: java.lang.RuntimeException: java.lang.IllegalStateException: BootAMX listener was not called at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.rethrow(DefaultMBeanServerInterceptor.java:856) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.rethrowMaybeMBeanException(DefaultMBeanServerInterceptor.java:869) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:838) at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:761) at org.glassfish.admin.mbeanserver.BootAMX.bootAMX(BootAMX.java:163) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.amxDomain(AdminAuthorizedMBeanServer.java:161) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.isAMX(AdminAuthorizedMBeanServer.java:156) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.isAMX(AdminAuthorizedMBeanServer.java:149) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.isAllowed(AdminAuthorizedMBeanServer.java:143) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.invoke(AdminAuthorizedMBeanServer.java:104) at $Proxy128.unregisterMBean(Unknown Source) at org.glassfish.admin.mbeanserver.JMXStartupService$JMXConnectorsStarterThread.shutdown(JMXStartupService.java:247) at org.glassfish.admin.mbeanserver.JMXStartupService.shutdown(JMXStartupService.java:191) at org.glassfish.admin.mbeanserver.JMXStartupService.access$000(JMXStartupService.java:94) at org.glassfish.admin.mbeanserver.JMXStartupService$ShutdownListener.event(JMXStartupService.java:161) at org.glassfish.kernel.event.EventsImpl.send(EventsImpl.java:128) at com.sun.enterprise.v3.server.AppServerStartup.stop(AppServerStartup.java:316) at com.sun.enterprise.glassfish.bootstrap.GlassFishImpl.stop(GlassFishImpl.java:88) at com.sun.enterprise.glassfish.bootstrap.GlassFishDecorator.stop(GlassFishDecorator.java:68) at com.sun.enterprise.v3.admin.StopServer.doExecute(StopServer.java:71) at com.sun.enterprise.v3.admin.cluster.StopInstanceInstanceCommand.execute(StopInstanceInstanceCommand.java:96) at com.sun.enterprise.v3.admin.CommandRunnerImpl$2.execute(CommandRunnerImpl.java:498) at org.glassfish.api.AsyncImpl$1$1.run(AsyncImpl.java:78) Caused by: java.lang.RuntimeException: java.lang.IllegalStateException: BootAMX listener was not called at org.glassfish.admin.amx.impl.AMXStartupService.loadAMXMBeans(AMXStartupService.java:231) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:93) at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:27) at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(MBeanIntrospector.java:208) at com.sun.jmx.mbeanserver.PerInterface.invoke(PerInterface.java:120) at com.sun.jmx.mbeanserver.MBeanSupport.invoke(MBeanSupport.java:262) at javax.management.StandardMBean.invoke(StandardMBean.java:391) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:836) ... 20 more Caused by: java.lang.IllegalStateException: BootAMX listener was not called at org.glassfish.admin.amx.impl.AMXStartupService._loadAMXMBeans(AMXStartupService.java:360) at org.glassfish.admin.amx.impl.AMXStartupService.loadAMXMBeans(AMXStartupService.java:228) ... 31 more

| #] |

[#|2012-07-04T05:11:32.420-0700|INFO|44.0|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=31;_ThreadName=Thread-2;|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, GlassFishConfigBean.org.glassfish.jdbc.config.JdbcConnectionPool, GlassFishConfigBean.org.glassfish.jdbc.config.JdbcResource]|#]

[#|2012-07-04T05:11:32.443-0700|INFO|44.0|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors.service|_ThreadID=37;_ThreadName=Thread-2;|RAR7094: __ds_jdbc_ra shutdown successful.|#]

[#|2012-07-04T05:11:32.450-0700|INFO|44.0|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=31;_ThreadName=Thread-2;|EJB5122:EJB Timer Service shutdown at [2012/07/04 05:11:32]|#]

[#|2012-07-04T05:11:32.467-0700|INFO|44.0|org.eclipse.persistence.session.file:/export/home/hudson/workspace/gf-ejb-timer-cluster-devtest/glassfish-trunk-image/glassfish3/glassfish/nodes/localhost-domain1/c1in1/applications/ejb-timer-service-app/WEB-INF/classes/_EJBTimerApp.connection|_ThreadID=31;ThreadName=Thread-2;|file:/export/home/hudson/workspace/gf-ejb-timer-cluster-devtest/glassfish-trunk-image/glassfish3/glassfish/nodes/localhost-domain1/c1in1/applications/ejb-timer-service-app/WEB-INF/classes/EJBTimerApp logout successful|#]

[#|2012-07-04T05:11:32.554-0700|INFO|44.0|javax.enterprise.system.amx.org.glassfish.admin.amx.impl|_ThreadID=31;_ThreadName=Thread-2;|AMX003: AMX Startup Service has been shut down and all AMX MBeans unregistered, remaining MBeans: []|#]

glassfishrobot commented 12 years ago

@glassfishrobot Commented @tjquinno said: Marina,

Can you be more specific about when the failures began to appear? Do you know that latest build with which the tests were consistently passing?

glassfishrobot commented 12 years ago

@glassfishrobot Commented @tjquinno said: I will take ownership of this, at least for the time being.

glassfishrobot commented 12 years ago

@glassfishrobot Commented @tjquinno said: I have checked in at least a partial fix.

It seems to me that AppServerStartup.stop should protect itself better from failures like this; it still should stop the JVM.

Transferring to admin for consideration of that side of things.

Project: glassfish Repository: svn Revision: 55055 Author: tjquinn Date: 2012-07-09 20:22:06 UTC Link:

Log Message:

Fix for 18878.

Use better filtering to decide if a particular MBean method invocation should be subject to access controls when JMX requests are sent to an instance.

The problem in this case was that AMX was being partially started up - during shutdown - just to get its JMX domain name for comparison with the MBean being accessed. Tests: QL

Revisions:

55055

Modified Paths:

trunk/main/nucleus/common/mbeanserver/src/main/java/org/glassfish/admin/mbeanserver/AdminAuthorizedMBeanServer.java

glassfishrobot commented 12 years ago

@glassfishrobot Commented mvatkina said: Tim, answering your question - I think it was happening for some time, but I started looking in more details when builds started failing every other day. I think somebody needs to look into the cause of the error because the location of the problem in the tests (2 clusters, not 1, and the 1st instance in each cluster) is deterministic.

glassfishrobot commented 11 years ago

@glassfishrobot Commented ymajoros said: Hey, we just had the same on our production environment (planned restart). In GF 3.1.2.2 but stack trace is quite similar, so I think the affected version should be adapted.

[#|2012-12-07T06:06:35.800+0100|WARNING|glassfish3.1.2|javax.enterprise.system.core.org.glassfish.kernel.event|_ThreadID=65;_ThreadName=Thread-1755;|Exception while dispatching an event javax.management.RuntimeMBeanException: java.lang.RuntimeException: java.lang.IllegalStateException: BootAMX listener was not called at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.rethrow(DefaultMBeanServerInterceptor.java:856) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.rethrowMaybeMBeanException(DefaultMBeanServerInterceptor.java:869) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:838) at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:761) at org.glassfish.admin.mbeanserver.BootAMX.bootAMX(BootAMX.java:163) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.amxDomain(AdminAuthorizedMBeanServer.java:154) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.isAMX(AdminAuthorizedMBeanServer.java:149) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.isAMX(AdminAuthorizedMBeanServer.java:142) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.isAllowed(AdminAuthorizedMBeanServer.java:136) at org.glassfish.admin.mbeanserver.AdminAuthorizedMBeanServer$Handler.invoke(AdminAuthorizedMBeanServer.java:101) at $Proxy525.unregisterMBean(Unknown Source) at org.glassfish.admin.mbeanserver.JMXStartupService$JMXConnectorsStarterThread.shutdown(JMXStartupService.java:239) at org.glassfish.admin.mbeanserver.JMXStartupService.shutdown(JMXStartupService.java:160) at org.glassfish.admin.mbeanserver.JMXStartupService.access$000(JMXStartupService.java:94) at org.glassfish.admin.mbeanserver.JMXStartupService$ShutdownListener.event(JMXStartupService.java:128) at org.glassfish.kernel.event.EventsImpl.send(EventsImpl.java:128) at com.sun.enterprise.v3.server.AppServerStartup.stop(AppServerStartup.java:439) at com.sun.enterprise.glassfish.bootstrap.GlassFishImpl.stop(GlassFishImpl.java:88) at com.sun.enterprise.glassfish.bootstrap.GlassFishDecorator.stop(GlassFishDecorator.java:68) at com.sun.enterprise.v3.admin.StopServer.doExecute(StopServer.java:70) at com.sun.enterprise.v3.admin.cluster.StopInstanceInstanceCommand.execute(StopInstanceInstanceCommand.java:94) at com.sun.enterprise.v3.admin.CommandRunnerImpl$1.execute(CommandRunnerImpl.java:348) at com.sun.enterprise.v3.admin.CommandRunnerImpl$2.run(CommandRunnerImpl.java:377) Caused by: java.lang.RuntimeException: java.lang.IllegalStateException: BootAMX listener was not called at org.glassfish.admin.amx.impl.AMXStartupService.loadAMXMBeans(AMXStartupService.java:247) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:93) at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:27) at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(MBeanIntrospector.java:208) at com.sun.jmx.mbeanserver.PerInterface.invoke(PerInterface.java:120) at com.sun.jmx.mbeanserver.MBeanSupport.invoke(MBeanSupport.java:262) at javax.management.StandardMBean.invoke(StandardMBean.java:391) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:836) ... 20 more Caused by: java.lang.IllegalStateException: BootAMX listener was not called at org.glassfish.admin.amx.impl.AMXStartupService._loadAMXMBeans(AMXStartupService.java:376) at org.glassfish.admin.amx.impl.AMXStartupService.loadAMXMBeans(AMXStartupService.java:244) ... 31 more

glassfishrobot commented 11 years ago

@glassfishrobot Commented tmueller said: Summarizing the status of this issue.

Based on Tim's previous comment, the remaining work for this issue is to modify AppServerStartup.stop so that it protects itself from exceptions that are thrown by the stop sequence. This includes the "send" calls that send events and the "proceedTo" calls that change the run level.

glassfishrobot commented 11 years ago

@glassfishrobot Commented tmueller said: Fixed on the trunk in revision 59321. This change added exception handling to the AppServerStartup.stop method.

glassfishrobot commented 12 years ago

@glassfishrobot Commented File: ejb-ee-timer-failover-logs.zip Attached By: mvatkina

glassfishrobot commented 12 years ago

@glassfishrobot Commented Issue-Links: is related to GLASSFISH-19602

glassfishrobot commented 12 years ago

@glassfishrobot Commented Was assigned to tmueller

glassfishrobot commented 7 years ago

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

glassfishrobot commented 12 years ago

@glassfishrobot Commented Reported by mvatkina

glassfishrobot commented 11 years ago

@glassfishrobot Commented Marked as fixed on Friday, February 8th 2013, 7:08:43 am

eclipse-ee4j / glassfish