Re: WoMonitor "Failed to contact ..."
Re: WoMonitor "Failed to contact ..."
- Subject: Re: WoMonitor "Failed to contact ..."
- From: Chuck Hill <email@hidden>
- Date: Thu, 30 Apr 2009 17:44:01 -0700
On Apr 30, 2009, at 5:16 PM, Kieran Kelleher wrote:
Hi Chuck,
Great news ..... I have had 3 error emails already from Wonder's
SessionStore Deadlock detection!
"I would wager that I will not see any Sesion Store deadlocks with
concurrent request handling turned off!"
Looks like I won the bet! :-P
Here they are .... session IDs modified to protect the innocent :-)
Not sure what anyone could tell from those. If you have restarted the
apps, they are useless now.
What do you make of this then?
You have a bug in your code.
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?
Well, you need to ask yourself what in your code immediately
_preceeded_ this. I try to have enough logging that I can tell what
the user is doing just from looking at the log. Something like this:
[2009-04-30 16:23:19,627] <WorkerThread13>
WOApplication.dispatchRequest - =========== Cycle Start for URI /cgi-
bin/WebObjects/FooApp.woa/-3456/wo/3.0.9.3.1.3.1?
0.9.3.1.3.1.1.10.0
=
&0.9.3.1.3.1.1.12.0
=
S
&0.9.3.1.3.1.1.14.0
=
&0.9.3.1.3.1.1.16.0.0
=
&0.9.3.1.3.1.1.18
=
WONoSelectionString
&0.9.3.1.3.1.1.20=WONoSelectionString&0.9.3.1.3.1.1.29=Search
[2009-04-30 16:23:19,628] <WorkerThread13>
WOApplication.dispatchRequest - Request's headers: {remote_host = ("::
1"); user-agent = ("Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_5_6;
en-us) AppleWebKit/525.27.1 (KHTML, like Gecko) Version/3.2.1 Safari/
525.27.1"); document_root = ("/Library/WebServer/Documents");
server_name = ("localhost"); accept = ("text/xml,application/
xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/
*;q=0.5"); remote_addr = ("::1"); server_admin = ("email@hidden");
remote_port = ("51682"); connection = ("close"); server_software =
("Apache/2.2.9 (Unix) mod_ssl/2.2.9 OpenSSL/0.9.7l DAV/2"); cookie =
("woinst=-3456; wosid=Udis2u5xusYyWaXgb8eRXg;"); host = ("localhost");
referer = ("http://localhost/cgi-bin/WebObjects/FooApp.woa/-3456/wo/2.0.9.1.1.23.0.1.3.1.1.1
"); accept-encoding = ("gzip, deflate"); x-webobjects-request-id =
("49ea0411000000200001755e"); script_uri = ("http://localhost/cgi-bin/WebObjects/FooApp.woa/-3456/wo/3.0.9.3.1.3.1
"); script_filename = ("/cgi-bin"); x-webobjects-request-method =
("GET"); x-webobjects-adaptor-version = ("Apache"); accept-language =
("en-us"); script_url = ("/cgi-bin/WebObjects/FooApp.woa/-3456/wo/
3.0.9.3.1.3.1"); server_port = ("80"); }
[2009-04-30 16:23:19,628] <WorkerThread13>
WOApplication.dispatchRequest - cookies: woinst=-3456;
wosid=Udis2u5xusYyWaXgb8eRXg;
[2009-04-30 16:23:19,628] <WorkerThread13>
WOApplication.dispatchRequest - form values: {0.9.3.1.3.1.1.10.0
= (""); 0.9.3.1.3.1.1.12.0 = ("S"); 0.9.3.1.3.1.1.14.0 = ("");
0.9.3.1.3.1.1.18 = ("WONoSelectionString"); 0.9.3.1.3.1.1.16.0.0 =
(""); 0.9.3.1.3.1.1.29 = ("Search"); 0.9.3.1.3.1.1.20 =
("WONoSelectionString"); }
[2009-04-30 16:23:19,629] <WorkerThread13>
ERXNSLogLog4jBridge.appendln - Awake session Udis2u5xusYyWaXgb8eRXg
[2009-04-30 16:23:19,629] <WorkerThread13>
ERXNSLogLog4jBridge.appendln - ====================================
[2009-04-30 16:23:19,629] <WorkerThread13> FooAppSession - User chill2
[2009-04-30 16:23:19,629] <WorkerThread13> FooAppThread - Attaching
chill2 to thread WorkerThread13
[2009-04-30 16:23:19,630] <chill2 WorkerThread13> FooAppSession -
Request being handled by net.foo.FooApp.pages.adcontrol.EditDisplayAds
[2009-04-30 16:23:19,645] <chill2 WorkerThread13>
FooAppEditingPageSearchComponent - Searching for: {adName =
(order.adName caseinsensitivelike '*S*'); excludeCompletedCycles =
(publications CONTAINS at least 1 match(es) for ((isCycleComplete =
(java.lang.Boolean)'false')); } {}
[2009-04-30 16:23:19,647] <chill2 WorkerThread13>
FooAppEditingPageSearchComponent - Qualifier ((order.adName
caseinsensitivelike '*S*') and (publications CONTAINS at least 1
match(es) for ((isCycleComplete = (java.lang.Boolean)'false')))
[2009-04-30 16:23:19,647] <chill2 WorkerThread13> FooAppSession -
Response is net.foo.FooApp.pages.adcontrol.EditDisplayAds
[2009-04-30 16:23:19,698] <chill2 WorkerThread13>
FooAppAjaxGridComponent - Search matched: 0
[2009-04-30 16:23:19,698] <chill2 WorkerThread13>
FooAppEditingPageComponent - Search Results: rendering
net.foo.FooApp.pages.adcontrol.DisplayAdResults
So, in the absence of that, what can we tell?
user-agent = (Mozilla/5.0 (Windows; U; Windows NT 6.0; en-US)
Windows loser. :-P
script_uri = (http://www.smartleadsusa.net/app/20/wo/kueXGID3VjTiMRY*******/4.0.21.13.1.1.0.5.1.1.3.0.3
);
That tells us that it is a component action, not a direct action
causing this.
They were on their fourth click. You have something triggering this
that has an element ID of 0.21.13.1.1.0.5.1.1.3.0.3
I'd search the HTML source for that (e.g. the source in the browser).
That will be the link that causes the error
script_uri = (http://www.smartleadsusa.net/app/20/wo/kueXGID3VjTiM*******/
4.0.21.13.1.1.0.5.1.1.3.0.3);
script_uri = (http://www.smartleadsusa.net/app/22/wo/tfVVfuWHuybcGbF*******/3.0.21.13.1.1.0.5.1.1.3.0.3
);
It is always the same link / submit that causes this.
It is always the same IP: 67.61.91.110
Perhaps someone has garbled data in their account? They are persistent.
Chuck
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
--
Chuck Hill Senior Consultant / VP Development
Come to WOWODC'09 in San Fran this June!
http://www.wocommunity.org/wowodc09/
_______________________________________________
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