Hello Rainer,
it's a pity - but the clocks are in sync (using NTP). On both Tomcats and the Apache2 instances.
According to the following command output:
grep -i "52C326B80A73EFF19CEE49B013533F06" localhost_access_log.2010-10-14.log
the last pattern match for the JSessionID mentioned below is:
10.35.32.123 - - [14/Oct/2010:11:45:01 +0200] POST /servlet/ClientIO/90i8dcztq97l/s6/21i HTTP/1.1 200 197 52C326B80A73EFF19CEE49B013533F06.rb-wcmstc2
So, I cannot find any further request logged further down in Tomcat "rb-wcmstc2".
Due to an already overwritten error.log (log-rotation), I do not have any more access to the Apache2 error-log. :(
We will add the "%D" to the log format string on both Apache2 and Tomcat.
Any more hints to identify the problem? The problematik POST request seems to be:
> 10.35.32.123 - - [14/Oct/2010:11:45:03 +0200] "POST /servlet/ClientIO/90i8dcztq97l/s6/21j HTTP/1.1" 500 1258
> "-" "Jakarta Commons-HttpClient/3.1" "JSESSIONID=52C326B80A73EFF19CEE49B013533F06.rb-wcmstc2"
> "52C326B80A73EFF19CEE49B013533F06.rb-wcmstc2" "JSESSIONID=B3C4AABB5F983A0E9D6478C42C88A5C4.rb-wcmstc1; Path=/"
This POST throws a 500 status code.
-----Original Message-----
From: Rainer Jung [mailto:rainer.jung@xxxxxxxxxxx]
Sent: Freitag, 15. Oktober 2010 10:58
To: users@xxxxxxxxxxxxxxxx
Subject: Re: "proxy_balancer" | stickysession
Hi Holger,
On 14.10.2010 16:16, King Holger (CI/AFP2) wrote:
> Unfortunately, after having activated the:
> - Tomcat-AccessLog
> - custom-LogFormat using Cookie-OutPut in Apache2 2.2.16
> LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-agent}i\" \"%{Cookie}i\" \"%{JSESSIONID}C\" \"%{Set-Cookie}o\""
> - "stickysession=JSESSIONID|jsessionid" and "scolonpathdelim On" for the "proxy_balancer" module in Apache2 2.2.16
>
> we re-discovered a connection switch from one to the other Tomcat (here: from "rb-wcmstc2" to "rb-wcmstc1") instances.
>
> Below you can see how Apache2 switches (recording a 500-HTTP-StatusCode) and tries to set a new JSESSIONID-Cookie containe "rb-wcmstc1":
> 10.35.32.123 - - [14/Oct/2010:11:45:03 +0200] "POST /servlet/ClientIO/90i8dcztq97l/s6/21j HTTP/1.1" 500 1258 "-" "Jakarta Commons-H
> ttpClient/3.1" "JSESSIONID=52C326B80A73EFF19CEE49B013533F06.rb-wcmstc2" "52C326B80A73EFF19CEE49B013533F06.rb-wcmstc2" "JSESSIONID=B
> 3C4AABB5F983A0E9D6478C42C88A5C4.rb-wcmstc1; Path=/"
>
> Here the Tomcat-AccessLog of "rb-wcmstc2" recorded during the connection-switch around "14/Oct/2010:11:45:03":
> 10.35.32.123 - - [14/Oct/2010:11:44:59 +0200] GET /fs4webedit/do.MessageEventServlet HTTP/1.1 200 55 CB41BCFB1D44C27047137CF9DED7A088.rb-wcmstc2
> 10.35.32.123 - - [14/Oct/2010:11:45:00 +0200] GET /fs4webedit/do.MessageEventServlet HTTP/1.1 200 55 40198501CD70083C31AAFD862923E4AA.rb-wcmstc2
> 10.35.32.123 - - [14/Oct/2010:11:45:01 +0200] POST /servlet/ClientIO/1nttjvwlaiwyl/s6/2gb HTTP/1.1 200 197 2FBA856A4DF56B2CA6F61C67E5411E0B.rb-wcmstc2
> 10.35.32.123 - - [14/Oct/2010:11:45:01 +0200] POST /servlet/ClientIO/90i8dcztq97l/s6/21i HTTP/1.1 200 197 52C326B80A73EFF19CEE49B013533F06.rb-wcmstc2
> 10.35.32.123 - - [14/Oct/2010:11:45:01 +0200] GET /fs4webedit/preview/6719107/site/DE/current/6719288/8617824/mode=2 HTTP/1.1 200 1248 D29A5CD8F3C60AFAC5
> 684F4BA49282EC.rb-wcmstc2
> 10.35.32.123 - - [14/Oct/2010:11:45:01 +0200] GET /favicon.ico HTTP/1.1 304 - -
> 10.35.32.123 - - [14/Oct/2010:11:45:02 +0200] GET /fs4webedit/preview/6719107/site/DE/current/6719288/8617824/pagestoreId=8617816/contentFrame=1/WEBedit=
> 1/mode=2 HTTP/1.1 200 70998 D29A5CD8F3C60AFAC5684F4BA49282EC.rb-wcmstc2
> 10.35.32.123 - - [14/Oct/2010:11:45:12 +0200] GET /fs4webedit/do.MessageEventServlet HTTP/1.1 200 55 EF67E8AB7E1C2FAAE548623479CF0BDE.rb-
>
> Hints: the above mentioned JSESSIONID "52C326B80A73EFF19CEE49B013533F06" can just be found on "rb-wcmstc2", of course. A blocking garbage collection run on "rb-wcmstc2" can be excluded (according to the tomcat GC-logs)!
>
> The whole proxy balancer configuration you can see below.
>
> We wonder:
> - why does it happen, although "rb-wcmstc2" seems to be physically available?
> - how to determine the root-cause?
I assume the clocks on the Apache and Tomcat servers are in sync? In the
Apache access log the timestamp is "11:45:03". Apache uses as timestamp
the time when the request arrived. Tomcat logs using the time when the
request finished. In the access log snippet for the Tomcat access log
you provided, we can see no POST for this session id at or after
"11:45:03". The only entry that fits the URL is already two seconds
before. I hope the clocks are right ...
So either the request is logged further down, which would indicate that
it took quite long, or it didn't actually reach Tomcat, or it is still
stuck in it. I would hope and expect, that your Apache error log does
contain an indication for the failure. Remember that it could be logged
in the error log later than "11:45:03", because the timestamp in the
error log will be when the actual error happened, the timestamp in the
Apache access log when the request came in.
Anything in the error log? Any corresponding POST with the right session
id further down in the Tomcat access log?
If we suspect, that some kind of timeout is happening, then we would
want to add "%D" to the access log formats in Apache and Tomcat. %D logs
the duration of the request, for Apache in microseconds, for Tomcat in
milliseconds.
Regards,
Rainer
---------------------------------------------------------------------
The official User-To-User support forum of the Apache HTTP Server Project.
See <URL:http://httpd.apache.org/userslist.html> for more info.
To unsubscribe, e-mail: users-unsubscribe@xxxxxxxxxxxxxxxx
" from the digest: users-digest-unsubscribe@xxxxxxxxxxxxxxxx
For additional commands, e-mail: users-help@xxxxxxxxxxxxxxxx
---------------------------------------------------------------------
The official User-To-User support forum of the Apache HTTP Server Project.
See <URL:http://httpd.apache.org/userslist.html> for more info.
To unsubscribe, e-mail: users-unsubscribe@xxxxxxxxxxxxxxxx
" from the digest: users-digest-unsubscribe@xxxxxxxxxxxxxxxx
For additional commands, e-mail: users-help@xxxxxxxxxxxxxxxx
|