Hi Márcio
I'm sorry to hear that you're still having trouble with this.
From what I can see:
GlassFish 2.1.1
MQ 4.4
Running Windows 2003
JDK 1.6.0_18
* It appears you are now running the broker as LOCAL (please correct
me, if that's wrong)
* I think you also said you never saw this problem in your own tests
* One interesting observation is, according to your first report,
this was also happening when you ran the broker with the EMBEDDED
configuration.
Could you try another possible work-around and configure the broker as
REMOTE. That would disable all "life-cycle" services from GlassFish --
so, if the problem is somehow related to an errant signal from
GlassFish, this should prevent that from occurring. (Not that we are
aware of any issue in this part of GlassFish, but this is certainly a
mystery so, trying different configurations could help us isolate this.)
If you can do this, and you can run for a long period of time, without
seeing this problem again, that could be significant. If you go this
route, you'll need to start-up and shutdown MQ separately, from GlassFish.
The server log doesn't cover the time of the first error, on April 21.
For the event on April 26th, sadly, I don't see anything you didn't
already highlight in the logs. I can't see a benefit from continuing
with FINEST logging since that hasn't exposed anything useful and, I'm
sure it's consuming lots of disk-space.
Can you review for us, the differences between what you ran in your
testing versus what is running at this customer site? (OS, JDK, GF, MQ
versions, do you use shell processes to start/stop, or are you using
Windows Service manager to start/stop?) It might help us to understand
what's different, and perhaps, why this wasn't apparent when you ran
your tests prior to delivery to your customer.
I'll ask around and see if anyone else here has any further ideas for
diagnosing this issue.
If you do reconfigure with REMOTE broker, and the problem goes away,
please let us know so that we can try to investigate this further. We
have seen occasional posts, similar to this on the lists, but I don't
recall a definitive conclusion ever being posted. Our presumption, in
the past, was that the user found the problem and didn't feel the need
for us to take further action. That may or may not be correct and we'd
certainly like to get to the bottom of this.
Thanks,
-- Ed
On 4/27/2011 10:03 AM, Márcio Geovani Jasinski wrote:
> 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
> <http://guest@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