Re: WoMonitor "Failed to contact ..."
Re: WoMonitor "Failed to contact ..."
- Subject: Re: WoMonitor "Failed to contact ..."
- From: Kieran Kelleher <email@hidden>
- Date: Thu, 30 Apr 2009 20:16:07 -0400
Hi Chuck,
Great news ..... I have had 3 error emails already from Wonder's
SessionStore Deadlock detection! Here they are .... session IDs
modified to protect the innocent :-) What do you make of this then?
Not sure how much it tells me. What logging would you recommend now
that we have this detection happening? ... should I override
ERXApplication's SessionInfo to capture some more info? ... if so, what?
<snip>
5094158 ERROR 2009-04-30 18:59:17,353
506.69 MB total/27.26 MB used/479.43 MB free
[WorkerThread15]
(er.extensions.appserver.ERXApplication$SessionInfo,
exceptionMessageForCheckout, ERXApplication.java:2003) -
There is an error in the session check-out: old context: contextId: 5
request: <er.extensions.appserver.ERXRequest
(<er.extensions.appserver.ERXRequest httpVersion=HTTP/1.1
headers={remote_host = (67.61.91.110); user-agent = (Mozilla/5.0
(Windows; U; Windows NT 6.0; en-US) AppleWebKit/525.19 (KHTML, like
Gecko) Chrome/1.0.154.59 Safari/525.19); document_root = (/Library/
WebServer/Documents); accept-charset = (ISO-8859-1,*,utf-8); accept =
(text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/
plain;q=0.8,image/png,*/*;q=0.5); server_name =
(www.smartleadsusa.net); server_admin = (email@hidden);
original_context_id = ("4"); remote_port = (50122); connection =
(close); server_software = (Apache/1.3.33); host = (www.smartleadsusa.net
); referer = (http://www.smartleadsusa.net/app/20/wo/kueXGID3VjTiM*******/3.0.21.13.1
); x-webobjects-adaptor-version = ("Apache"); remote_addr =
(67.61.91.110); x-webobjects-request-id = (49f893080000013e0000050b);
script_uri = (http://www.smartleadsusa.net/app/20/wo/kueXGID3VjTiMRY*******/4.0.21.13.1.1.0.5.1.1.3.0.3
); script_filename = (passthrough:/cgi-bin/WebObjects/cheetah.woa/20/
wo/kueXGID3VjTiM*******/4.0.21.13.1.1.0.5.1.1.3.0.3); x-webobjects-
request-method = (GET); accept-encoding = (gzip,deflate,bzip2,sdch);
server_port = (80); script_url = (/app/20/wo/kueXGID3VjTiM*******/
4.0.21.13.1.1.0.5.1.1.3.0.3); accept-language = (en-US,en); } content-
length=0 cookies=null userInfo=null>) method=GET uri=/cgi-bin/
WebObjects/cheetah.woa/20/wo/kueXGID3VjTiM*******/
4.0.21.13.1.1.0.5.1.1.3.0.3 defaultFormValueEncoding=UTF-8
formValueEncodingDetectionEnabled=NO formValueEncoding=UTF-8
formValues={} >
java.lang.Exception
at er.extensions.appserver.ERXApplication
$SessionInfo.<init>(ERXApplication.java:1979)
at
er
.extensions
.appserver.ERXApplication.restoreSessionWithID(ERXApplication.java:2056)
at
com
.webobjects
.appserver
._private
.WOComponentRequestHandler
._dispatchWithPreparedApplication(WOComponentRequestHandler.java:314)
at
com
.webobjects
.appserver
._private
.WOComponentRequestHandler
._handleRequest(WOComponentRequestHandler.java:358)
at
com
.webobjects
.appserver
._private
.WOComponentRequestHandler
.handleRequest(WOComponentRequestHandler.java:432)
at
com
.webobjects.appserver.WOApplication.dispatchRequest(WOApplication.java:
1306)
at
er
.extensions
.appserver
.ERXApplication.dispatchRequestImmediately(ERXApplication.java:1769)
at
er
.extensions
.appserver.ERXApplication.dispatchRequest(ERXApplication.java:1734)
at
wk
.webobjects.appserver.WKApplication.dispatchRequest(WKApplication.java:
95)
at
com
.webobjects
.appserver._private.WOWorkerThread.runOnce(WOWorkerThread.java:173)
at
com
.webobjects.appserver._private.WOWorkerThread.run(WOWorkerThread.java:
254)
at java.lang.Thread.run(Thread.java:613)
</snip>
<snip>
5107803 ERROR 2009-04-30 18:59:30,998
506.69 MB total/30.29 MB used/476.39 MB free
[WorkerThread1]
(er.extensions.appserver.ERXApplication$SessionInfo,
exceptionMessageForCheckout, ERXApplication.java:2003) -
There is an error in the session check-out: old context: contextId: 5
request: <er.extensions.appserver.ERXRequest
(<er.extensions.appserver.ERXRequest httpVersion=HTTP/1.1
headers={remote_host = (67.61.91.110); user-agent = (Mozilla/5.0
(Windows; U; Windows NT 6.0; en-US) AppleWebKit/525.19 (KHTML, like
Gecko) Chrome/1.0.154.59 Safari/525.19); document_root = (/Library/
WebServer/Documents); accept-charset = (ISO-8859-1,*,utf-8); accept =
(text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/
plain;q=0.8,image/png,*/*;q=0.5); server_name =
(www.smartleadsusa.net); server_admin = (email@hidden);
original_context_id = ("4"); remote_port = (50122); connection =
(close); server_software = (Apache/1.3.33); host = (www.smartleadsusa.net
); referer = (http://www.smartleadsusa.net/app/20/wo/kueXGID3VjTiM*******/3.0.21.13.1
); x-webobjects-adaptor-version = ("Apache"); remote_addr =
(67.61.91.110); x-webobjects-request-id = (49f893080000013e0000050b);
script_uri = (http://www.smartleadsusa.net/app/20/wo/kueXGID3VjTiM*******/4.0.21.13.1.1.0.5.1.1.3.0.3
); script_filename = (passthrough:/cgi-bin/WebObjects/cheetah.woa/20/
wo/kueXGID3VjTiM*******/4.0.21.13.1.1.0.5.1.1.3.0.3); x-webobjects-
request-method = (GET); accept-encoding = (gzip,deflate,bzip2,sdch);
server_port = (80); script_url = (/app/20/wo/kueXGID3VjTiM*******/
4.0.21.13.1.1.0.5.1.1.3.0.3); accept-language = (en-US,en); } content-
length=0 cookies=null userInfo=null>) method=GET uri=/cgi-bin/
WebObjects/cheetah.woa/20/wo/kueXGID3VjTiM*******/
4.0.21.13.1.1.0.5.1.1.3.0.3 defaultFormValueEncoding=UTF-8
formValueEncodingDetectionEnabled=NO formValueEncoding=UTF-8
formValues={} >
java.lang.Exception
at er.extensions.appserver.ERXApplication
$SessionInfo.<init>(ERXApplication.java:1979)
at
er
.extensions
.appserver.ERXApplication.restoreSessionWithID(ERXApplication.java:2056)
at
com
.webobjects
.appserver
._private
.WOComponentRequestHandler
._dispatchWithPreparedApplication(WOComponentRequestHandler.java:314)
at
com
.webobjects
.appserver
._private
.WOComponentRequestHandler
._handleRequest(WOComponentRequestHandler.java:358)
at
com
.webobjects
.appserver
._private
.WOComponentRequestHandler
.handleRequest(WOComponentRequestHandler.java:432)
at
com
.webobjects.appserver.WOApplication.dispatchRequest(WOApplication.java:
1306)
at
er
.extensions
.appserver
.ERXApplication.dispatchRequestImmediately(ERXApplication.java:1769)
at
er
.extensions
.appserver.ERXApplication.dispatchRequest(ERXApplication.java:1734)
at
wk
.webobjects.appserver.WKApplication.dispatchRequest(WKApplication.java:
95)
at
com
.webobjects
.appserver._private.WOWorkerThread.runOnce(WOWorkerThread.java:173)
at
com
.webobjects.appserver._private.WOWorkerThread.run(WOWorkerThread.java:
254)
at java.lang.Thread.run(Thread.java:613)
</snip>
<snip>
5084824 ERROR 2009-04-30 19:02:49,802
506.69 MB total/28.9 MB used/477.79 MB free
[WorkerThread11]
(er.extensions.appserver.ERXApplication$SessionInfo,
exceptionMessageForCheckout, ERXApplication.java:2003) -
There is an error in the session check-out: old context: contextId: 4
request: <er.extensions.appserver.ERXRequest
(<er.extensions.appserver.ERXRequest httpVersion=HTTP/1.1
headers={remote_host = (67.61.91.110); user-agent = (Mozilla/5.0
(Windows; U; Windows NT 6.0; en-US) AppleWebKit/525.19 (KHTML, like
Gecko) Chrome/1.0.154.59 Safari/525.19); document_root = (/Library/
WebServer/Documents); accept-charset = (ISO-8859-1,*,utf-8); accept =
(text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/
plain;q=0.8,image/png,*/*;q=0.5); server_name =
(www.smartleadsusa.net); server_admin = (email@hidden);
original_context_id = ("3"); remote_port = (50147); connection =
(close); server_software = (Apache/1.3.33); host = (www.smartleadsusa.net
); referer = (http://www.smartleadsusa.net/app/22/wo/tfVVfuWHuybcGbF*******/2.0.21.13.1
); x-webobjects-adaptor-version = ("Apache"); remote_addr =
(67.61.91.110); x-webobjects-request-id = (49f893080000013e00000486);
script_uri = (http://www.smartleadsusa.net/app/22/wo/tfVVfuWHuybcGbF*******/3.0.21.13.1.1.0.5.1.1.3.0.3
); script_filename = (passthrough:/cgi-bin/WebObjects/cheetah.woa/22/
wo/tfVVfuWHuybcGbF*******/3.0.21.13.1.1.0.5.1.1.3.0.3); x-webobjects-
request-method = (GET); accept-encoding = (gzip,deflate,bzip2,sdch);
server_port = (80); script_url = (/app/22/wo/tfVVfuWHuybcGbF*******/
3.0.21.13.1.1.0.5.1.1.3.0.3); accept-language = (en-US,en); } content-
length=0 cookies=null userInfo=null>) method=GET uri=/cgi-bin/
WebObjects/cheetah.woa/22/wo/tfVVfuWHuybcGbF*******/
3.0.21.13.1.1.0.5.1.1.3.0.3 defaultFormValueEncoding=UTF-8
formValueEncodingDetectionEnabled=NO formValueEncoding=UTF-8
formValues={} >
java.lang.Exception
at er.extensions.appserver.ERXApplication
$SessionInfo.<init>(ERXApplication.java:1979)
at
er
.extensions
.appserver.ERXApplication.restoreSessionWithID(ERXApplication.java:2056)
at
com
.webobjects
.appserver
._private
.WOComponentRequestHandler
._dispatchWithPreparedApplication(WOComponentRequestHandler.java:314)
at
com
.webobjects
.appserver
._private
.WOComponentRequestHandler
._handleRequest(WOComponentRequestHandler.java:358)
at
com
.webobjects
.appserver
._private
.WOComponentRequestHandler
.handleRequest(WOComponentRequestHandler.java:432)
at
com
.webobjects.appserver.WOApplication.dispatchRequest(WOApplication.java:
1306)
at
er
.extensions
.appserver
.ERXApplication.dispatchRequestImmediately(ERXApplication.java:1769)
at
er
.extensions
.appserver.ERXApplication.dispatchRequest(ERXApplication.java:1734)
at
wk
.webobjects.appserver.WKApplication.dispatchRequest(WKApplication.java:
95)
at
com
.webobjects
.appserver._private.WOWorkerThread.runOnce(WOWorkerThread.java:173)
at
com
.webobjects.appserver._private.WOWorkerThread.run(WOWorkerThread.java:
254)
at java.lang.Thread.run(Thread.java:613)
</snip>
On Apr 30, 2009, at 6:15 PM, Chuck Hill wrote:
Hi Kieran,
On Apr 30, 2009, at 2:30 PM, Kieran Kelleher wrote:
Resurrecting this old discussion again :-(
OK, a while ago, one xserve "omega" (running Leopard Server 10.5.6,
WO 5.4.X wotaskd with fully embedded WO 5.3.3 apps) showed up in
WOMonitor as Failed to Contact again. Remember WOMonitor is running
on Tiger Server 10.4.8 with the wotaskd from WO 5.3.3.
Rather than assume this is a wotaskd/networking problem this time,
I decided to check the WO apps on that server "192.168.3.154" using
lsof and jstack to see if I can find anything unusual and I did:
OK, 192.168.3.154 has 2 apps running on it. pid-479 port 2001) and
pid-43 (port 2004). Also wotaskd is running as pid 43
app pid-479 lsof -i tcp:2001 shows nothing unusual
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
java 479 _appserver 7u IPv6 0x830bb2c 0t0 TCP [::
192.168.3.154]:dc (LISTEN)
app pid-947 has unusual output, lsof -i tcp:2004 reveals 256
CLOSE_WAITs!!! .... this app is not allowing logins
http://67.78.26.66:81/~kieran/misc/lsof_tcp_2004_pid_43.txt
BTW, the other IP 192.168.3.149 shown on the CLOSE_WAIT lines is
the machine that is running WOMonitor/apache, so this would seem to
indicate a lot of hung requests? (that's a question, Chuck ;-) )
Ha? Wha? Time to wake up?
Yeah, this is indicative of hung requests.
lsof for wotaskd itself gives this, which doesn't seem unusual
bash-3.2# lsof -i tcp:1085
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
java 43 _appserver 8u IPv6 0x6e1d258 0t0 TCP [::
192.168.3.154]:webobjects (LISTEN)
java 43 _appserver 11u IPv6 0x830b664 0t0 TCP [::
192.168.3.154]:webobjects->[::192.168.3.154]:49665 (ESTABLISHED)
java 43 _appserver 12u IPv6 0x8e41cd4 0t0 TCP [::
192.168.3.154]:webobjects->[::192.168.3.154]:53449 (ESTABLISHED)
java 479 _appserver 10u IPv6 0x830b8c8 0t0 TCP [::
192.168.3.154]:49665->[::192.168.3.154]:webobjects (ESTABLISHED)
java 947 _appserver 10u IPv6 0x8e7d344 0t0 TCP [::
192.168.3.154]:53449->[::192.168.3.154]:webobjects (ESTABLISHED)
Now looking at the jstack outputs, we also have more useful clues.
jstack on the pid-947 (port 2004) app reveals it has session store
deadlocks!! This is the same app with all the CLOSE_WAITs
http://67.78.26.66:81/~kieran/misc/jstack_pid_947.txt
You did not mention deadlocked application the last time you
complained of this!
So, it would seem that the stupid 'Failed to contact" stuff I have
been seeing are really caused by Session Store deadlocks.
Yes. More generally by anything that deadlocks the application or
otherwise makes it slow to respond to wotaskd. That message
actually means "Failed to contact one of the instances running
on ....". Was that not clear? :-P
So, the first thing I am going to do now is turn OFF concurrent
request handling and turn on Wonder Session Store Deadlock
detection for this app ...... however, I would wager that I will
not see any Sesion Store deadlocks with concurrent request handling
turned off!
I'll take your money. Cash, checks, cheques, and money orders
accepted.
Any ideas on a strategy for deadlock detection with concurrent
request handling ON?
Yes. The logic in Wonder does not seem quite right to me. How does
this sound:
- when a session is created or restored, set a flag in the thread
(using ThreadLocal)
- when a session is checked in, clear the flag
- at the end of request handling (this is the tricky bit), check if
the flag is set and throw/log/terminate/whatever
Chuck
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Webobjects-dev mailing list (email@hidden)
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden