users@glassfish.java.net

Re: OpenMQ unexpected shutdown

From: Márcio Geovani Jasinski <marciogj_at_gmail.com>
Date: Wed, 27 Apr 2011 14:03:35 -0300

Hi Ed,

Mentioned issue is still happening. We registered 2 unexpected shutdown on
April 20th and yesterday April 26th.
In order to get more details of what´s happening I changed log level on
several Glassfish components to finest.

I did the same log adjustment in .ear application and there´s no signal of
error neither context destroy information as we have coded.
Moreover Glassfish did realize that something went wrong - but it tells that
an admin requested a shutdown which nobody did...
Glassfish is installed as a service and there´s no entry on Event Viewer
about a service restart/stop.

Heres the log (attached as well):

[#|2011-04-26T16:58:25.579-0300|FINEST|sun-appserver2.1|javax.enterprise.system.container.web|_ThreadID=48;_ThreadName=httpSSLWorkerThread-8585-3;ClassName=com.sun.enterprise.web.PESessionLockingStandardPipeline;MethodName=unlockSession;_RequestID=f4b3f4f9-196d-49b5-a767-4a4e08836f78;|finished
unlocking session: sess =StandardSession[f52117d126e161b94ad468361421]|#]

[#|2011-04-26T16:58:25.579-0300|FINEST|sun-appserver2.1|javax.enterprise.system.container.web|_ThreadID=48;_ThreadName=httpSSLWorkerThread-8585-3;ClassName=com.sun.enterprise.web.PESessionLockingStandardPipeline;MethodName=unlockSession;_RequestID=f4b3f4f9-196d-49b5-a767-4a4e08836f78;|LOCK
= _lockType= null
foregroundRefCount= 0|#]

[#|2011-04-26T16:58:25.579-0300|FINE|sun-appserver2.1|org.apache.coyote.tomcat5.OutputBuffer|_ThreadID=48;_ThreadName=httpSSLWorkerThread-8585-3;ClassName=org.apache.coyote.tomcat5.OutputBuffer;MethodName=realWriteBytes;_RequestID=f4b3f4f9-196d-49b5-a767-4a4e08836f78;|realWrite(b,
0, 135) org.apache.coyote.Response_at_1fc9529|#]

[#|2011-04-26T16:58:25.579-0300|FINEST|sun-appserver2.1|org.apache.coyote.tomcat5.InputBuffer|_ThreadID=48;_ThreadName=httpSSLWorkerThread-8585-3;ClassName=org.apache.coyote.tomcat5.InputBuffer;MethodName=recycle;_RequestID=f4b3f4f9-196d-49b5-a767-4a4e08836f78;|recycle()|#]

[#|2011-04-26T16:58:25.579-0300|FINE|sun-appserver2.1|org.apache.coyote.tomcat5.OutputBuffer|_ThreadID=48;_ThreadName=httpSSLWorkerThread-8585-3;ClassName=org.apache.coyote.tomcat5.OutputBuffer;MethodName=recycle;_RequestID=f4b3f4f9-196d-49b5-a767-4a4e08836f78;|recycle()|#]

[#|2011-04-26T16:58:25.579-0300|FINEST|sun-appserver2.1|javax.enterprise.system.container.web|_ThreadID=48;_ThreadName=httpSSLWorkerThread-8585-3;ClassName=com.sun.enterprise.web.connector.grizzly.DefaultReadTask;MethodName=registerKey;_RequestID=f4b3f4f9-196d-49b5-a767-4a4e08836f78;|registerKey|#]

[#|2011-04-26T16:58:25.767-0300|FINER|sun-appserver2.1|javax.resourceadapter.mqjmsra.outbound.connection|_ThreadID=56;_ThreadName=iMQEventHandler-1214;ClassName=com.sun.messaging.jms.ra.ConnectionEventListener;MethodName=onEvent();E201:[E201]:
Connection closed due to admin requested shutdown: localhost:6767(1995),
com.sun.messaging.jms.notification.ConnectionClosedEvent[source=BrokerAddress=localhost:6767(1995),
ConnectionID=8082324740562242048, ReconnectEnabled: true,
IsConnectedToHABroker:
false];_RequestID=6dea1acb-2d02-4e22-aa9e-cc68fccb3956;|ENTRY E201:[E201]:
Connection closed due to admin requested shutdown: localhost:6767(1995),
com.sun.messaging.jms.notification.ConnectionClosedEvent[source=BrokerAddress=localhost:6767(1995),
ConnectionID=8082324740562242048, ReconnectEnabled: true,
IsConnectedToHABroker: false]|#]


From OpenMQ, the issue is caught by the shutdown hook:

[26/Apr/2011:16:58:17 GMT-03:00] Creating new Producer 8082324791354713856
on Q:COMMAND_OUT for connection 8082324740562242048
[26/Apr/2011:16:58:18 GMT-03:00] Creating new Producer 8082324791355121920
on Q:COMMAND_OUT for connection 8082324740562242048
[26/Apr/2011:16:58:20 GMT-03:00] Creating new Producer 8082324791355521792
on Q:COMMAND_OUT for connection 8082324740562242048
[26/Apr/2011:16:58:25 GMT-03:00] Shutdown requested by brokerShutdownHook
[26/Apr/2011:16:58:25 GMT-03:00] [B1047]: Shutting down broker...
[26/Apr/2011:16:58:25 GMT-03:00] [B1077]: Broadcast good-bye to all
connections ...
[26/Apr/2011:16:58:25 GMT-03:00] [B1078]: Flushing good-bye messages ...
[26/Apr/2011:16:58:25 GMT-03:00] Close Session 8082324680546840832
[26/Apr/2011:16:58:25 GMT-03:00] Detaching Consumer
[consumer:8082324680546844929, type=CLIENT_ACKNOWLEDGE] on connection
8082324680546829056 from Session 8082324680546840832 last id was null
[26/Apr/2011:16:58:25 GMT-03:00] Session: Pausing Session
[8082324680546840832][1]Consumer.java: Detatch consumer A Consumer -
Q:EVENT_IN:[consumer:8082324680546844929, type=CLIENT_ACKNOWLEDGE]
[26/Apr/2011:16:58:25 GMT-03:00] Session: Resuming Session
[8082324680546840832][0]Consumer.java: resuming after detatch Consumer -
Q:EVENT_IN:[consumer:8082324680546844929, type=CLIENT_ACKNOWLEDGE]
[26/Apr/2011:16:58:25 GMT-03:00] Cleaning up transactions on connection
IMQConn[CLOSED,guest_at_127.0.0.1:2023,null]


We got access to the server as soon they realized the system was down and I
could verify that Glassfish was not working.
Following listeners didn´t respond at all after OpenMQ shutdown. Example:
HTTP (8585) HTTP(4949), JMX (8686. Attached is all open ports at this time).

Ed, is it possible to check what´s going on with those logs using finest
level?
We are looking forward to find a suitable solution since those shutdowns are
stopping client employees to get access to their areas.

Any thoughts will be very appreciated. Thanks.

Regards,
Márcio Geovani Jasinski
Blumenau, Santa Catarina
Fone: +55 47 9653 4899