You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@httpd.apache.org by "King Holger (CI/AFP2)" <Ho...@de.bosch.com> on 2010/10/14 16:16:22 UTC
RE: [users@httpd] "proxy_balancer" | stickysession
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?
Any ideas?
-----Original Message-----
From: Rainer Jung [mailto:rainer.jung@kippdata.de]
Sent: Donnerstag, 30. September 2010 10:38
To: users@httpd.apache.org
Subject: Re: [users@httpd] "proxy_balancer" | stickysession
On 29.09.2010 16:53, King Holger (CI/AFP2) wrote:
> Dear mailing list,
>
> currently, we use the Apache2 version:
> - Apache2 2.2.16 64bit
> - standard "mod_proxy_balancer" module
>
> with the following V-HOST configuration including a proxy balancer directive (with two Apache Tomcat instances behind):
> <Proxy balancer://fs4server>
> BalancerMember ajp://rb-wcmstc1.xx.xxxxx.xxx:8009 loadfactor=100 retry=10 route=rb-wcmstc1
> BalancerMember ajp://rb-wcmstc2.xx.xxxxx.xxx:8009 loadfactor=100 retry=10 route=rb-wcmstc2
>
> ProxySet stickysession=JSESSIONID
> ProxySet lbmethod=byrequests
> #ProxySet nofailover=On
> ProxySet timeout=30
> </Proxy>
>
> In production environment, we discover connection switches from "rb-wcmstc1" to "rb-wcmstc2" and vice versa (documented in the Tomcat-Logs) for the same Session-ID:
>
> "rb-wcmstc1"
> tomcat@<rb-wcmstc1>:/opt/tomcat/logs $ grep -i "5893975846599935313" *
> log4j-catalina.log.13:TRACE 29.09.2010 14:16:58 (de.espirit.firstspirit.io.servlet.ClientIOServlet): Opening connection to 10.35.32.123, id=5893975846599935313
> log4j-catalina.log.13:TRACE 29.09.2010 14:16:58 (de.espirit.firstspirit.io.servlet.ClientIOServlet): Server call from 10.35.32.123, id=5893975846599935313, clientLength=82, serverLength=79, serverResponseLength=1, 455 ms
>
> "rb-wcmstc2"
> DEBUG 29.09.2010 14:16:58 (de.espirit.firstspirit.io.servlet.ClientIOServlet): IO error with 10.35.32.123, port=1088, host=rb-wcmsfs4.de.bosch.com - java.
> lang.IllegalStateException: Connection '5893975846599935313' not found
> java.lang.IllegalStateException: Connection '5893975846599935313' not found
> at de.espirit.firstspirit.io.servlet.ClientIOServlet.callServer(ClientIOServlet.java:194)
> at de.espirit.firstspirit.io.servlet.ClientIOServlet.doPost(ClientIOServlet.java:117)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
>
> Although, the "stickysession" attribute is set properly using the "JSESSIONID" cookie name and the Apache-Tomcat instances are up and running, the connection SWITCHES. Why?
How does stickyness work?
=========================
First it can use a cookie value or a value encoded in a URL. Java
webapps usually use a cookie named JSESSIONID, but when the client
doesn't support cookies, or if cookie usage is disabled on e.g. Tomcat,
it switches to URL encoding. Tomcat sometimes uses URL encoding when it
doesn't yet know, whether the client will support the cookie. URL
encoded session info is appended using ";jsessionid=...". Note the lower
case in the name of the id.
Since mod_proxy_balancer checks for the URL encoding and the cookie
using case sensitive strings, you need to configure both using the syntax:
stickysession=JSESSIONID|jsessionid
This is just to make sure, that an occasional URL encoded session info
is found as well.
Now by default mod_proxy_balancer looks for the URL encoded session info
as a parameter appended using "?" or "&", so as part of the query
string. Java Enterprise appends it using ";". To add that character to
the search list, you have to also set "scolonpathdelim On". Again this
is only necessary for occasional URL encoded sessions.
Now that mod_proxy_balancer can find the needed tokens (i.e. the value
of the JSESSIONID cookie, resp. the ;jsessionid URL encoded session
info), how does it detect the backend it should send the request to?
If there is a dot (".") in the token (session id), it only uses the part
after the dot as the "route", if not it uses the complete token.
Now it knows the "route" where it should send the request to it looks
for a balancer member, which has the same value set as its "route". In
the above example "rb-wcmstc1" respectively "rb-wcmstc2". This member
will handle the request - if the member is available, i.e. not broken or
disabled.
Finally: in order to let Tomcat attach the needed route to the end of
the session id you need to set the jvmRoute attribute in server.xml to
the respective route value.
How to track failures
=====================
1) Check whether your Tomcats send the correct route in the session id.
Look at the JSESSIONID cookie in the browser, whether it has
".rb-wcmstc1" resp. ".rb-wcmstc2" attached at the end of the id value.
2) Log the session ids send by the clients, and the session id set by
the server.
Activate the Tomcat access log and change the pattern to include
"%S "%{Cookie}i" "%{Set-Cookie}o""
Change your log format for the Apache access log using CustomLog and add
"%{JSESSIONID}C" "%{Set-Cookie}o"
or even
"%{Cookie}i" "%{JSESSIONID}C" "%{Set-Cookie}o"
On the docs page
http://httpd.apache.org/docs/2.2/mod/mod_proxy_balancer.html#environment
you will also find a list of Apache environment variables useful for
debugging when adding to the log format, e.g.
%{BALANCER_SESSION_STICKY}e %{BALANCER_SESSION_ROUTE}e
%{BALANCER_WORKER_NAME}e %{BALANCER_WORKER_ROUTE}e
%{BALANCER_ROUTE_CHANGED}e
3) Switch Apache to debug log level
CAUTION: High log volume by mod_proxy and also mod_ssl if used.
It will log e.g.
proxy: BALANCER: Found value <TOKEN> for stickysession <IS_STICKY>
(that's the token contained in the request)
proxy: BALANCER: Found route <ROUTE>
(that's the route info from the token, e.g. stripping everything in
front of a dot)
proxy: BALANCER: Route changed from <NEEDED> to <USED>
(if there is no worker available for the route <NEEDED>, the worker
which will be used instead is <USED>).
Final remarks
=============
You look for the string "5893975846599935313" in your above log
snippets. That does not look like a Tomcat session id. It doesn't have
the trailing route and it is purely decimal numeric, whereas a Tomcat
session id is hexadecimal. It is very unlikely that there are no [A-F]
digits in it.
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@httpd.apache.org
" from the digest: users-digest-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org
---------------------------------------------------------------------
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@httpd.apache.org
" from the digest: users-digest-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org
RE: [users@httpd] "proxy_balancer" | stickysession
Posted by "King Holger (CI/AFP2)" <Ho...@de.bosch.com>.
Hi Rainer,
we discovered the same Tomcat-"connection-switch" problem again. This time with the Apache2 ERROR-LOG, containing:
Apache2-ERROR-Log Output:
[Mon Oct 25 10:18:58 2010] [error] server is within MinSpareThreads of MaxClients, consider raising the MaxClients setting
[Mon Oct 25 11:46:35 2010] [error] server reached MaxClients setting, consider raising the MaxClients setting
[Mon Oct 25 11:50:02 2010] [error] (70007)The timeout specified has expired: ajp_ilink_receive() can't receive header
Apache2-ACCESS-Log Output:
10.35.32.123 - - [25/Oct/2010:11:50:04 +0200] "POST /servlet/ClientIO/1ojgw1th835ue/s6/y1 HTTP/1.1" 500 1258 "-" "Jakarta Commons-HttpClient/3.1" "JSESSIONID=A62BCC2B1054CA532C68CA409F41548C.rb-wcmstc1" "A62BCC2B1054CA532C68CA409F41548C.rb-wcmstc1" "JSESSIONID=56DB518EDE4EFED6337349F3478A4863.rb-wcmstc2; Path=/" 2795
When checking the configuration file for the MPM ("httpd-mpm.conf"), the central Apache2-configuration does not include that file:
# Server-pool management (MPM specific)
#Include conf/extra/httpd-mpm.conf
Currently, we use the "worker"-MPM as shown in the "apachectl"-output (AND NOT WORKER):
<hostname>:/opt/wcms/apache/bin $ ./apachectl -M | grep -i "worker"
Syntax OK
mpm_worker_module (static)
When monitoring the Apache2 via the "/server-status" resource, the following information is shown (see screenshot enclosed):
As you can see:
- the total amount of requests possibly being handled in parallel: 400
- the amount of idle workers sometimes reaches the critical value: 0 (not documented in the screenshot enclosed)
Our questions:
- why 400? We assumed a default value of 150 for "MaxClients" (see "httpd-mpm.conf")
- should we increase the "MaxClients"-value by explicitly defining it in "httpd-mpm.conf" (as mentioned in the "error.log" above)?
When monitoring one of the Tomcats below "/manager/status" (here: "rb-wcmstc2"), the screenshot enclosed shows the following information:
- MaxThreads: 500
- ThreadCount: 252
- Current Thread Busy: 239
The configuration for the Tomcats (here "rb-wcmstc2"):
<!-- Define an AJP 1.3 Connector on port 8009 -->
<Connector port="8009" protocol="AJP/1.3" redirectPort="8443" allowTrace="true" maxThreads="500" />
Consequence:
- it seems to be clear, that Apache2 is the bottleneck (the amount of connections available within the "connection-pool" does sporadically reach the value of "0")
What are your suggestions?
Kind regards,
Holger King
-----Original Message-----
From: Rainer Jung [mailto:rainer.jung@kippdata.de]
Sent: Freitag, 15. Oktober 2010 15:26
To: users@httpd.apache.org
Subject: Re: [users@httpd] "proxy_balancer" | stickysession
On 15.10.2010 12:32, King Holger (CI/AFP2) wrote:
> it's a pity - but the clocks are in sync (using NTP). On both Tomcats and the Apache2 instances.
Good to know.
> 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".
So we deduce, that either the request is still hanging inside Tomcat or
it never reached Tomcat. Although the latter is more likely, you can
check: if you have the Tomcat manager webapp deployed, you can look at
the status page, which shows a list of all in-flight requests.
> Due to an already overwritten error.log (log-rotation), I do not have any more access to the Apache2 error-log. :(
Then there's likely no way forward for this incident. We would nee dto
wait for the next one :(
> We will add the "%D" to the log format string on both Apache2 and Tomcat.
Good, it's helpful in a lot of situations anyhows.
> 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.
Sorry, to many possible reasons in the proxy for that. You need the
error log.
You can try to make your setup a bit more robust by looking at the
parameter table given at
http://httpd.apache.org/docs/current/mod/mod_proxy.html#proxypass
For the ajp workers, the following parameters come to mind:
- ping (e.g. ping=10s)
- connectiontimeout (e.g. connectiontimeout=10s)
- timeout (e.g. timeout=120s)
- keepalive=On
The 10 second timeouts could also be lowered to e.g. 5 or 2 seconds if
you are reasonably sure that you don't have any longer GC pauses on the
Java back-ends. A good value for the general timeout depends on your
expectation of response times the back-end will be able to support as
long as it is running well. The "%D" in the access log will help you get
some real numbers.
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@httpd.apache.org
" from the digest: users-digest-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org
Re: [users@httpd] "proxy_balancer" | stickysession
Posted by Rainer Jung <ra...@kippdata.de>.
On 15.10.2010 12:32, King Holger (CI/AFP2) wrote:
> it's a pity - but the clocks are in sync (using NTP). On both Tomcats and the Apache2 instances.
Good to know.
> 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".
So we deduce, that either the request is still hanging inside Tomcat or
it never reached Tomcat. Although the latter is more likely, you can
check: if you have the Tomcat manager webapp deployed, you can look at
the status page, which shows a list of all in-flight requests.
> Due to an already overwritten error.log (log-rotation), I do not have any more access to the Apache2 error-log. :(
Then there's likely no way forward for this incident. We would nee dto
wait for the next one :(
> We will add the "%D" to the log format string on both Apache2 and Tomcat.
Good, it's helpful in a lot of situations anyhows.
> 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.
Sorry, to many possible reasons in the proxy for that. You need the
error log.
You can try to make your setup a bit more robust by looking at the
parameter table given at
http://httpd.apache.org/docs/current/mod/mod_proxy.html#proxypass
For the ajp workers, the following parameters come to mind:
- ping (e.g. ping=10s)
- connectiontimeout (e.g. connectiontimeout=10s)
- timeout (e.g. timeout=120s)
- keepalive=On
The 10 second timeouts could also be lowered to e.g. 5 or 2 seconds if
you are reasonably sure that you don't have any longer GC pauses on the
Java back-ends. A good value for the general timeout depends on your
expectation of response times the back-end will be able to support as
long as it is running well. The "%D" in the access log will help you get
some real numbers.
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@httpd.apache.org
" from the digest: users-digest-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org
RE: [users@httpd] "proxy_balancer" | stickysession
Posted by "King Holger (CI/AFP2)" <Ho...@de.bosch.com>.
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@kippdata.de]
Sent: Freitag, 15. Oktober 2010 10:58
To: users@httpd.apache.org
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":
> 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@httpd.apache.org
" from the digest: users-digest-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org
---------------------------------------------------------------------
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@httpd.apache.org
" from the digest: users-digest-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org
Re: [users@httpd] "proxy_balancer" | stickysession
Posted by Rainer Jung <ra...@kippdata.de>.
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@httpd.apache.org
" from the digest: users-digest-unsubscribe@httpd.apache.org
For additional commands, e-mail: users-help@httpd.apache.org