[GLASSFISH-18878] AMX errors prevent stopping (and removing) a clustered instance Created: 09/Jul/12  Updated: 08/Feb/13  Resolved: 08/Feb/13

Status: Resolved
Project: glassfish
Component/s: admin
Affects Version/s: 4.0
Fix Version/s: 4.0_b74

Type: Bug Priority: Major
Reporter: marina vatkina Assignee: Tom Mueller
Resolution: Fixed Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Zip Archive ejb-ee-timer-failover-logs.zip    
Issue Links:
Related
is related to GLASSFISH-19602 BootAMX error logged during shutdown,... Open

 Description   

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).



 Comments   
Comment by Tom Mueller [ 09/Jul/12 ]

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/___EJB__Timer__App.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/___EJB__Timer__App 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: []|#]

Comment by Tim Quinn [ 09/Jul/12 ]

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?

Comment by Tim Quinn [ 09/Jul/12 ]

I will take ownership of this, at least for the time being.

Comment by Tim Quinn [ 09/Jul/12 ]

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

Comment by marina vatkina [ 09/Jul/12 ]

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.

Comment by ymajoros [ 07/Dec/12 ]

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

Comment by Tom Mueller [ 24/Dec/12 ]

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.

Comment by Tom Mueller [ 08/Feb/13 ]

Fixed on the trunk in revision 59321.
This change added exception handling to the AppServerStartup.stop method.

Generated at Sat Mar 28 01:13:16 UTC 2015 using JIRA 6.2.3#6260-sha1:63ef1d6dac3f4f4d7db4c1effd405ba38ccdc558.