Just to bring the rest of this list up to speed -- we asked Márcio to
turn on Broker debugging and we did look at the MQ broker and Server
logs which he supplied. It appeared that something was shutting down the
Application Server -- which then sent a shutdown command to the Embedded
broker -- as would be expected. Otherwise, there was nothing unusual in
the broker logs.
Short answer is, I'm not aware of anything in MQ or GlassFish that would
cause this behavior. I am reasonably certain that many users run their
brokers for days/weeks/months without any unusual events as described.
Has anyone else had any experience debugging phantom shutdown signals
with GlassFish? Any useful debug levels that might be helpful for
Márcio? We have already supplied him with the debugging settings for the
broker so, at this point, I think he's looking for help on the
instrumentation/debug side.
Márcio, please feel free to add any more details you'd like.
Thanks,
-- Ed
On 4/17/2011 6:18 PM, Márcio Geovani Jasinski wrote:
> Hi,
>
> I got a very odd situation regarding Glassfish and OpenMQ behavior.
> We have an EAR application which communicate with physical security
> devices to keep them online in order to control who has access to
> certain areas.
>
> Last Friday 16/04 at 9:05 AM and also Saturday at 9:08 AM the OpenMQ
> did a shutdown without any request. At least I couldn't see any...
> We work with Glassfish v2.1.1 using cluster profile although we use
> only server-config on this case.
> We also keep all JMS default configuration which means Embeeded type.
>
> I'm sending some logs below (blue means my Glassfish restart reaction).
>
> OpenMQ Logs (From 9:07 AM to 9:22 AM):
>
> [16/Apr/2011:09:08:53 GMT-03:00] Close Session 2690952844214422785
> [16/Apr/2011:09:08:53 GMT-03:00] Cleaning up transactions on
> connection IMQDirectConn[CLOSED,guest_at_null:0,jmsdirect:0]
> [16/Apr/2011:09:08:53 GMT-03:00] Cleaning up transactions on
> connection IMQDirectConn[CLOSED,guest_at_null:0,jmsdirect:0]
> [16/Apr/2011:09:08:53 GMT-03:00] [B1066]: Closing:
> guest_at_null:0->jmsdirect:0 because "[B0059]: Client closed the
> connection". Count: service=0 broker=4
> [16/Apr/2011:09:08:53 GMT-03:00] Shutdown requested by BrokerProcess
> [16/Apr/2011:09:08:53 GMT-03:00] [B1047]: Shutting down broker...
> [16/Apr/2011:09:08:53 GMT-03:00] [B1077]: Broadcast good-bye to
> all connections ...
> [16/Apr/2011:09:08:53 GMT-03:00] [B1078]: Flushing good-bye
> messages ...
> [16/Apr/2011:09:08:53 GMT-03:00] [B1007]: Stopping Service admin
> with protocol tcp(host = *, port=0, mode=dedicated)
> [16/Apr/2011:09:08:53 GMT-03:00] Exception shutting down
> protocol, ignoring since we are exiting:
> java.io.IOException: Unexpected Broker Exception: [can not close
> un-opened protocol]
> at
> com.sun.messaging.jmq.jmsserver.net.tcp.TcpProtocol.close(TcpProtocol.java:353)
> at
> com.sun.messaging.jmq.jmsserver.service.imq.IMQIPService.stopService(IMQIPService.java:292)
> at
> com.sun.messaging.jmq.jmsserver.service.ServiceInfo.stop(ServiceManager.java:674)
> at
> com.sun.messaging.jmq.jmsserver.service.ServiceManager.stopService(ServiceManager.java:317)
> at
> com.sun.messaging.jmq.jmsserver.service.ServiceManager.stopAllActiveServices(ServiceManager.java:440)
> at
> com.sun.messaging.jmq.jmsserver.BrokerStateHandler$ShutdownRunnable.shutdown(BrokerStateHandler.java:502)
> at
> com.sun.messaging.jmq.jmsserver.BrokerStateHandler.initiateShutdown(BrokerStateHandler.java:262)
> at
> com.sun.messaging.jmq.jmsserver.Broker.destroyBroker(Broker.java:261)
> at
> com.sun.messaging.jmq.jmsserver.Broker.destroyBroker(Broker.java:252)
> at
> com.sun.messaging.jmq.jmsserver.BrokerProcess.stop(BrokerProcess.java:233
> at
> com.sun.messaging.jmq.jmsclient.runtime.impl.BrokerInstanceImpl.stop(BrokerInstanceImpl.java:162)
> at
> com.sun.messaging.jms.ra.EmbeddedBrokerRunner.stop(EmbeddedBrokerRunner.java:290)
> at
> com.sun.messaging.jms.ra.LifecycleManagedBroker.stop(LifecycleManagedBroker.java:373)
> at
> com.sun.messaging.jms.ra.ResourceAdapter.stop(ResourceAdapter.java:387)
> at
> com.sun.enterprise.connectors.ActiveInboundResourceAdapter.stopResourceAdapter(ActiveInboundResourceAdapter.java:362)
> at
> com.sun.enterprise.connectors.ActiveInboundResourceAdapter.destroy(ActiveInboundResourceAdapter.java:336)
> at
> com.sun.enterprise.connectors.ResourceAdapterAdminServiceImpl$RAShutdownThread.run(ResourceAdapterAdminServiceImpl.java:686)
> [16/Apr/2011:09:08:53 GMT-03:00] [B1007]: Stopping Service
> jmsdirect with protocol
> [16/Apr/2011:09:08:53 GMT-03:00] Cleaning up transactions on
> connection IMQDirectConn[CLOSED,guest_at_null:0,jmsdirect:0]
> [16/Apr/2011:09:08:53 GMT-03:00] Requested close of already closed
> connection:IMQDirectConn[DESTROYING,guest_at_null:0,jmsdirect:0]
> [16/Apr/2011:09:08:53 GMT-03:00] [B1066]: Closing:
> guest_at_null:0->jmsdirect:0 because "[B0060]: Service shutting
> down". Count: service=0 broker=3
> [16/Apr/2011:09:08:53 GMT-03:00] Cleaning up transactions on
> connection IMQDirectConn[CLOSED,guest_at_null:0,jmsdirect:0]
> [16/Apr/2011:09:08:53 GMT-03:00] Requested close of already closed
> connection:IMQDirectConn[DESTROYING,guest_at_null:0,jmsdirect:0]
> [16/Apr/2011:09:08:53 GMT-03:00] [B1066]: Closing:
> guest_at_null:0->jmsdirect:0 because "[B0060]: Service shutting
> down". Count: service=0 broker=2
> [16/Apr/2011:09:08:53 GMT-03:00] [B1007]: Stopping Service
> mqdirect2 with protocol none
> [16/Apr/2011:09:08:53 GMT-03:00] [B1007]: Stopping Service jms
> with protocol tcp(host = *, port=0, mode=dedicated)
> [16/Apr/2011:09:08:53 GMT-03:00] Cleaning up transactions on
> connection IMQConn[CLOSED,guest_at_10.20.5.81:1318
> <http://guest@10.20.5.81:1318>,null]
> [16/Apr/2011:09:08:53 GMT-03:00] Requested close of already closed
> connection:IMQConn[DESTROYING,guest_at_10.20.5.81:1318
> <http://guest@10.20.5.81:1318>,null]
> [16/Apr/2011:09:08:53 GMT-03:00] [B1066]: Closing:
> guest_at_10.20.5.81:1318->jms:1314 because "[B0060]: Service shutting
> down". Count: service=0 broker=1
> [16/Apr/2011:09:08:53 GMT-03:00] Cleaning up transactions on
> connection IMQConn[CLOSED,guest_at_10.20.5.81:1379
> <http://guest@10.20.5.81:1379>,null]
> [16/Apr/2011:09:08:53 GMT-03:00] Requested close of already closed
> connection:IMQConn[DESTROYING,guest_at_10.20.5.81:1379
> <http://guest@10.20.5.81:1379>,null]
> [16/Apr/2011:09:08:53 GMT-03:00] [B1066]: Closing:
> guest_at_10.20.5.81:1379->jms:1314 because "[B0060]: Service shutting
> down". Count: service=0 broker=0
> [16/Apr/2011:09:08:53 GMT-03:00] JMX Connector Server jmxrmi
> stopped successfully
> [16/Apr/2011:09:08:53 GMT-03:00] [B1048]: Shutdown ofbroker complete.
> Java Runtime: 1.6.0_18 Sun Microsystems Inc.
> D:\Senior_Server\Vetorh\SP\CSMCenter\jdk\jre
> [16/Apr/2011:09:23:19 GMT-03:00] Syncing message store: false
> [16/Apr/2011:09:23:19 GMT-03:00]
> IMQ_HOME=D:\Senior_Server\Vetorh\SP\CSMCenter\glassfish\imq
>
>
>
> Glassfish logs (From 9:07 AM to 9:22 AM)
>
> [#|2011-04-16T09:07:12.543-0300|WARNING|sun-appserver2.1|javax.jms.Connection.mqjmsra|_ThreadID=17;_ThreadName=p:
> thread-pool-1; w:
> 5;_RequestID=51c27c97-e9ad-452b-ba92-ae117cda541f;|MQJMSRA_DC2001:
> Unsupported:stop():inACC=false:connectionId=2690952844228279041|#]
> [#|2011-04-16T09:07:12.637-0300|INFO|sun-appserver2.1|javax.enterprise.system.stream.out|_ThreadID=20;_ThreadName=p:
> thread-pool-1; w: 9;|
> [DOP2JAVA] Warning: WinSock.htons is not fully supported in Java.|#]
> [#|2011-04-16T09:07:12.637-0300|INFO|sun-appserver2.1|javax.enterprise.system.stream.out|_ThreadID=20;_ThreadName=p:
> thread-pool-1; w: 9;|
> [DOP2JAVA] Warning: setsockopt SO_SNDTIMEO is not supported in
> Java.|#]
> [#|2011-04-16T09:08:12.620-0300|INFO|sun-appserver2.1|javax.enterprise.system.stream.out|_ThreadID=31;_ThreadName=p:
> thread-pool-1; w: 13;|
> [DOP2JAVA] Warning: WinSock.htons is not fully supported in Java.|#]
> [#|2011-04-16T09:08:12.620-0300|INFO|sun-appserver2.1|javax.enterprise.system.stream.out|_ThreadID=31;_ThreadName=p:
> thread-pool-1; w: 13;|
> [DOP2JAVA] Warning: setsockopt SO_SNDTIMEO is not supported in
> Java.|#]
>
> Apr 16, 2011 9:22:49 AM
> com.sun.enterprise.admin.servermgmt.launch.ASLauncher buildCommand
>
>
>
> As you can see from logs, Glassfish didn't notice that OpenMQ was
> going down. More than that - at 9:10 for example I could access
> Glassfish http listeners:
> - Administration at http://localhost:4949 was working fine
> - Application War at http://localhost:8585 was working fine as well
>
> Saturday afternoon I changed JMS type from Embeeded to Local and today
> (17/04 - Sunday) the issue didn't show up.
> It's pretty hard to say that such change would avoid OpenMQ shutdown -
> I will monitor this system tomorrow to ensure that everything is all
> right.
>
> Moreover, we have same application running in another client and never
> got such situation.
> Is it possible or does anybody got similar case where an external tool
> could trigger OpenMQ shutdown?
>
> Any input will be appreciated. Thanks.
>
> Cheers.
> Márcio Geovani Jasinski
> Blumenau, Santa Catarina
> Fone: +55 47 9653 4899