[GLASSFISH-19602] BootAMX error logged during shutdown, even though shutdown completes Created: 29/Jan/13  Updated: 29/Jan/13

Status: Open
Project: glassfish
Component/s: amx
Affects Version/s: 3.1.2.2
Fix Version/s: future release

Type: Bug Priority: Minor
Reporter: Tim Quinn Assignee: prasads
Resolution: Unresolved Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
is related to GLASSFISH-18878 AMX errors prevent stopping (and remo... Resolved

 Description   

Sometimes during shutdown the server logs a BootAMX error. I have pasted Luis's comments from his forum posting here, as well as his stack trace.

Hi gentlemen,

We keep finding this exception every time we stop/restart any instance

  • > "AMXStartupServiceNew.loadAMXMBeans:
    java.lang.IllegalStateException: BootAMX listener was not called"

After doing some digging I believe that the instance is properly shut down.
However, there seem to be some other processes happening right after that
which cause the exception.

I have browsed the web finding similar issues with no results. Hence I come
here.

This stack trace is coming from the instance's log file:

[#|2013-01-21T15:37:12.692-0700|INFO|glassfish3.1.2|javax.enterprise.system.tools.admin.com.sun.enterprise.v3.admin.cluster|_ThreadID=47;_ThreadName=Thread-2;|Server
shutdown initiated|#]

[#|2013-01-21T15:37:14.821-0700|INFO|glassfish3.1.2|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=47;_ThreadName=Thread-2;|2013-01-21
15:37:14,821 PWAssessment[-1] INFO MessagingDispatcher.java:233
MessagingDispatcher - Shutting down transport LoopbackTransport
|#]

[#|2013-01-21T15:37:14.823-0700|INFO|glassfish3.1.2|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=47;_ThreadName=Thread-2;|2013-01-21
15:37:14,823 PWAssessment[-1] INFO MessagingDispatcher.java:233
MessagingDispatcher - Shutting down transport JMSTransport
|#]

[#|2013-01-21T15:37:14.832-0700|INFO|glassfish3.1.2|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=47;_ThreadName=Thread-2;|2013-01-21
15:37:14,831 PWAssessment[-1] INFO MessagingDispatcher.java:233
MessagingDispatcher - Shutting down transport HTTPTransport
|#]

[#|2013-01-21T15:37:14.870-0700|INFO|glassfish3.1.2|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=47;_ThreadName=Thread-2;|2013-01-21
15:37:14,870 PWBClinician[-1] INFO MessagingDispatcher.java:233
MessagingDispatcher - Shutting down transport LoopbackTransport
|#]

[#|2013-01-21T15:37:14.874-0700|INFO|glassfish3.1.2|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=47;_ThreadName=Thread-2;|2013-01-21
15:37:14,874 PWBClinician[-1] INFO MessagingDispatcher.java:233
MessagingDispatcher - Shutting down transport JMSTransport
|#]

[#|2013-01-21T15:37:14.881-0700|INFO|glassfish3.1.2|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=47;_ThreadName=Thread-2;|2013-01-21
15:37:14,881 PWBClinician[-1] INFO MessagingDispatcher.java:233
MessagingDispatcher - Shutting down transport HTTPTransport
|#]

[#|2013-01-21T15:37:14.928-0700|INFO|glassfish3.1.2|javax.resourceadapter.mqjmsra.lifecycle|_ThreadID=48;_ThreadName=Thread-2;|MQJMSRA_RA1101:
GlassFish MQ JMS Resource Adapter stopping...|#]

[#|2013-01-21T15:37:14.929-0700|INFO|glassfish3.1.2|javax.resourceadapter.mqjmsra.lifecycle|_ThreadID=48;_ThreadName=Thread-2;|MQJMSRA_RA1101:
GlassFish MQ JMS Resource Adapter stopped.|#]

[#|2013-01-21T15:37:14.929-0700|INFO|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors.service|_ThreadID=49;_ThreadName=Thread-2;|RAR7094:
jmsra shutdown successful.|#]

[#|2013-01-21T15:37:16.722-0700|INFO|glassfish3.1.2|javax.org.glassfish.gms.org.glassfish.gms|_ThreadID=47;_ThreadName=Thread-2;|GMSAD1008:
GMSAdapter for member: APOC-Assessment-n03x01 group: APOC-Assessment
received GlassfishEventType: server_shutdown|#]

[#|2013-01-21T15:37:16.724-0700|INFO|glassfish3.1.2|ShoalLogger|_ThreadID=47;_ThreadName=Thread-2;|GMS1096:
member: APOC-Assessment-n03x01 is leaving group: APOC-Assessment|#]

[#|2013-01-21T15:37:16.725-0700|INFO|glassfish3.1.2|ShoalLogger|_ThreadID=47;_ThreadName=Thread-2;|GMS1010:
Leaving GMS group: APOC-Assessment with shutdown type set to
InstanceShutdown|#]

[#|2013-01-21T15:37:16.729-0700|CONFIG|glassfish3.1.2|ShoalLogger|_ThreadID=50;_ThreadName=Thread-2;|GMS1065:
Completed processing outstanding master node messages for member:
APOC-Assessment-n03x01 group: APOC-Assessment outstandingMessages to
process: 0|#]

[#|2013-01-21T15:37:16.732-0700|INFO|glassfish3.1.2|ShoalLogger.monitor|_ThreadID=47;_ThreadName=Thread-2;|BlockingIOMulicastSender
monitoring stats: received: 30813 core poolsize:10 largest pool size:10
task count:30813 max queue size:0 rejected execution:0|#]

[#|2013-01-21T15:37:16.732-0700|INFO|glassfish3.1.2|ShoalLogger|_ThreadID=51;_ThreadName=Thread-2;|GMS1110:
Thread IP Multicast Listener for /228.9.158.231:13386 has completed.|#]

[#|2013-01-21T15:37:16.894-0700|INFO|glassfish3.1.2|ShoalLogger.monitor|_ThreadID=47;_ThreadName=Thread-2;|GMS1115:
router signal queue high water mark: 0 signal queue capacity: 600|#]

[#|2013-01-21T15:37:16.893-0700|INFO|glassfish3.1.2|ShoalLogger|_ThreadID=52;_ThreadName=Thread-2;|GMS1088:
MessageWindow thread for group: APOC-Assessment terminated due to shutdown
notification|#]

[#|2013-01-21T15:37:16.893-0700|INFO|glassfish3.1.2|ShoalLogger|_ThreadID=12;_ThreadName=Thread-2;|GMS1091:
View Window event processing thread for group: APOC-Assessment terminated
normally|#]

[#|2013-01-21T15:37:16.894-0700|INFO|glassfish3.1.2|ShoalLogger|_ThreadID=53;_ThreadName=Thread-2;|GMS1107:
SignalHandler task named GMS SignalHandler for Group-APOC-Assessment thread
exiting|#]

[#|2013-01-21T15:37:16.987-0700|INFO|glassfish3.1.2|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=47;_ThreadName=Thread-2;|Initialized
AMXStartupServiceNew in 27 ms, registered as
amx-support:type=amx-loader,name=startup|#]

[#|2013-01-21T15:37:17.096-0700|INFO|glassfish3.1.2|javax.enterprise.system.amx.org.glassfish.admin.amx.impl.mbean|_ThreadID=47;_ThreadName=Thread-2;|AMX024:
Register children for instance name APOC-Assessment-n03x01|#]

[#|2013-01-21T15:37:17.110-0700|INFO|glassfish3.1.2|javax.enterprise.system.amx.org.glassfish.admin.amx.impl.mbean|_ThreadID=47;_ThreadName=Thread-2;|AMX020:
AMX ComplianceMonitor: ValidationLevel = full, UnregisterNonCompliant =
false, LogInaccessibleAttributes = true|#]

[#|2013-01-21T15:37:17.147-0700|INFO|glassfish3.1.2|javax.enterprise.system.amx.org.glassfish.admin.amx.impl.config|_ThreadID=54;_ThreadName=Thread-2;|AMX012:
In AMXConfigLoader : Loading null|#]

[#|2013-01-21T15:37:18.089-0700|INFO|glassfish3.1.2|javax.enterprise.system.amx.org.glassfish.admin.amx.impl.config|_ThreadID=54;_ThreadName=Thread-2;|AMX013:
AMX domain config registered as amx:pp=/,type=domain|#]

[#|2013-01-21T15:37:18.346-0700|INFO|glassfish3.1.2|javax.enterprise.system.amx.org.glassfish.admin.amx.impl.j2ee.loader|_ThreadID=55;_ThreadName=Thread-2;|AMX014:
J2EEDomain registered at
amx:pp=/,type=J2EEDomain,j2eeType=J2EEDomain,name=amx|#]

[#|2013-01-21T15:37:18.349-0700|INFO|glassfish3.1.2|javax.enterprise.system.tools.admin.org.glassfish.server|_ThreadID=47;_ThreadName=Thread-2;|AMXStartupServiceNew:
AMX ready for use, DomainRoot = amx:pp=,type=domain-root|#]

[#|2013-01-21T15:37:18.350-0700|INFO|glassfish3.1.2|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=47;_ThreadName=Thread-2;|AMXStartupServiceNew.loadAMXMBeans:
java.lang.IllegalStateException: BootAMX listener was not called|#]

[#|2013-01-21T15:37:18.352-0700|WARNING|glassfish3.1.2|javax.enterprise.system.core.org.glassfish.kernel.event|_ThreadID=47;_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: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 $Proxy185.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
|#]

[#|2013-01-21T15:37:18.355-0700|INFO|glassfish3.1.2|javax.enterprise.system.core.com.sun.enterprise.v3.server|_ThreadID=47;_ThreadName=Thread-2;|Shutdown
procedure finished|#]

This stack trace is coming from the domain's log file:

[#|2013-01-21T15:37:12.598-0700|INFO|glassfish3.1.2|org.glassfish.admingui|_ThreadID=121;_ThreadName=Thread-2;|
https://localhost:4848/management/domain/servers/server/APOC-Assessment-n03x01/stop-instance|#
]

[#|2013-01-21T15:37:12.608-0700|INFO|glassfish3.1.2|javax.enterprise.system.tools.admin.com.sun.enterprise.v3.admin.cluster|_ThreadID=122;_ThreadName=Thread-2;|Instance
APOC-Assessment-n03x01 shutdown initiated|#]

[#|2013-01-21T15:37:16.720-0700|INFO|glassfish3.1.2|ShoalLogger|_ThreadID=25;_ThreadName=Thread-2;|GMS1092:
GMS View Change Received for group: APOC-Assessment : Members in view for
PEER_STOP_EVENT(before change analysis) are :
1: MemberId: APOC-Assessment-n01x01, MemberType: CORE, Address:
192.168.10.81:9140:228.9.158.231:13386
:APOC-Assessment:APOC-Assessment-n01x01
2: MemberId: APOC-Assessment-n02x01, MemberType: CORE, Address:
192.168.10.82:9200:228.9.158.231:13386
:APOC-Assessment:APOC-Assessment-n02x01
3: MemberId: server, MemberType: SPECTATOR, Address: 192.168.10.81:9119
:228.9.158.231:13386:APOC-Assessment:server
|#]

[#|2013-01-21T15:37:16.720-0700|INFO|glassfish3.1.2|ShoalLogger|_ThreadID=25;_ThreadName=Thread-2;|GMS1016:
Analyzing new membership snapshot received as part of event:
PEER_STOP_EVENT for member: APOC-Assessment-n03x01 of group:
APOC-Assessment|#]

[#|2013-01-21T15:37:16.720-0700|INFO|glassfish3.1.2|ShoalLogger|_ThreadID=25;_ThreadName=Thread-2;|GMS1017:
Received PlannedShutdownEvent Announcement from member:
APOC-Assessment-n03x01 with shutdown type: INSTANCE_SHUTDOWN of group:
APOC-Assessment|#]

[#|2013-01-21T15:37:16.720-0700|INFO|glassfish3.1.2|ShoalLogger|_ThreadID=111;_ThreadName=Thread-2;|GMS1008:
Sending PlannedShutdownSignals to registered Actions for shutdownType
INSTANCE_SHUTDOWN member: APOC-Assessment-n03x01 ...|#]


 Comments   
Comment by Tim Quinn [ 29/Jan/13 ]

This is related to part of 18878, a partial fix to which seemed to improve things a bit at least.

Comment by Tim Quinn [ 29/Jan/13 ]

A partial fix to 18878 made some improvement in this. Linking to that issue in case it's helpful.

Generated at Wed Jul 27 09:55:39 UTC 2016 using JIRA 6.2.3#6260-sha1:63ef1d6dac3f4f4d7db4c1effd405ba38ccdc558.