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,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,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,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,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 of broker 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