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@xxxxxxxxxxx]
Sent: Donnerstag, 30. September 2010 10:38
To: users@xxxxxxxxxxxxxxxx
Subject: Re: "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@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
|