httpd-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "King Holger (CI/AFP2)" <>
Subject RE: [users@httpd] "proxy_balancer" | stickysession
Date Fri, 15 Oct 2010 10:32:58 GMT
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: - - [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:
> - - [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;

This POST throws a 500 status code.

-----Original Message-----
From: Rainer Jung [] 
Sent: Freitag, 15. Oktober 2010 10:58
Subject: Re: [users@httpd] "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":
> - - [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"
> 3C4AABB5F983A0E9D6478C42C88A5C4.rb-wcmstc1; Path=/"
> Here the Tomcat-AccessLog of "rb-wcmstc2" recorded during the connection-switch around
> - - [14/Oct/2010:11:44:59 +0200] GET /fs4webedit/do.MessageEventServlet
HTTP/1.1 200 55 CB41BCFB1D44C27047137CF9DED7A088.rb-wcmstc2
> - - [14/Oct/2010:11:45:00 +0200] GET /fs4webedit/do.MessageEventServlet
HTTP/1.1 200 55 40198501CD70083C31AAFD862923E4AA.rb-wcmstc2
> - - [14/Oct/2010:11:45:01 +0200] POST /servlet/ClientIO/1nttjvwlaiwyl/s6/2gb
HTTP/1.1 200 197 2FBA856A4DF56B2CA6F61C67E5411E0B.rb-wcmstc2
> - - [14/Oct/2010:11:45:01 +0200] POST /servlet/ClientIO/90i8dcztq97l/s6/21i
HTTP/1.1 200 197 52C326B80A73EFF19CEE49B013533F06.rb-wcmstc2
> - - [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
> - - [14/Oct/2010:11:45:01 +0200] GET /favicon.ico HTTP/1.1 304 - -
> - - [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
> - - [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 



The official User-To-User support forum of the Apache HTTP Server Project.
See <URL:> for more info.
To unsubscribe, e-mail:
   "   from the digest:
For additional commands, e-mail:

The official User-To-User support forum of the Apache HTTP Server Project.
See <URL:> for more info.
To unsubscribe, e-mail:
   "   from the digest:
For additional commands, e-mail:

View raw message