Httpd – Apache httpd creates new sessions every time (2.2.16 and 2.4.6)

apache-2.2httpdPROXYsessionsticky-sessions

I have a server running Apahce httpd 2.2.16 on Debian 6.0.7

I use the proxy balancer directive to reverse proxy traffic using ajp protocol to tomcat backends

<Proxy balancer://tomcatapp-cluster>
    BalancerMember ajp://server-01.siminn.is:8000 route=tomcatapp-01 loadfactor=50 connectiontimeout=10
    BalancerMember ajp://server-02.siminn.is:8000 route=tomcatapp-02 loadfactor=50 connectiontimeout=10
</Proxy>
ProxyPass /app balancer://tomcatapp-cluster/app stickysession=JSESSIONID|jsessionid
ProxyPassReverse /app balancer://tomcatapp-cluster/app stickysession=JSESSIONID|jsessionid

Requests mad to the application within a life time of a session where a new session is started on a nother backend

GET /app/gsm/prepaid/buy HTTP/1.1
Cookie: JSESSIONID=C20AE8FC06F2A9A7136179FCAA7043FD.tomcatapp-02; _ga=GA1.2.1159250103.1389354702; __utma=159157733.1159250103.1389354702.1389606393.1389609120.7; __utmz=159157733.1389362294.3.2.utmcsr=siminn.is|utmccn=(referral)|utmcmd=referral|utmcct=/; userstyles=off; __utmc=159157733; __utmmobile=0xd4b5e4e4320505f5; __utmb=159157733.21.10.1389609120; is_returning=1; autoLogin.disabled=true; s_cc=true; s_sq=siminnliveinnri%3D%2526pid%253Dfors%2525u00ED%2525F0a%2526pidt%253D1%2526oid%253DInnskr%2525u00E1%2526oidt%253D3%2526ot%253DSUBMIT; USER_CACHE_KEY=D6D0DCFD773406CA8EE5D690A4AF1368.tomcattf-02
Set-Cookie: JSESSIONID=A95480808617EA3ABB3C1A4FB079DD99.tomcatapp-01; Path=/app/; Secure; HttpOnly

GET /app/site.jsp&guid=ON HTTP/1.1
Cookie: JSESSIONID=A95480808617EA3ABB3C1A4FB079DD99.tomcatapp-01; _ga=GA1.2.1159250103.1389354702; __utma=159157733.1159250103.1389354702.1389606393.1389609120.7; __utmz=159157733.1389362294.3.2.utmcsr=siminn.is|utmccn=(referral)|utmcmd=referral|utmcct=/; userstyles=off; __utmc=159157733; __utmmobile=0xd4b5e4e4320505f5; __utmb=159157733.21.10.1389609120; is_returning=1; autoLogin.disabled=true; s_cc=true; s_sq=siminnliveinnri%3D%2526pid%253Dfors%2525u00ED%2525F0a%2526pidt%253D1%2526oid%253DInnskr%2525u00E1%2526oidt%253D3%2526ot%253DSUBMIT; USER_CACHE_KEY=D6D0DCFD773406CA8EE5D690A4AF1368.tomcattf-02
Set-Cookie: JSESSIONID=26097E35B6B0C9B6652A7A6F8FF77992.tomcatapp-02; Path=/app/; Secure; HttpOnly
Set-Cookie: __utmmobile=x; Expires=Wed, 13-Jan-2016 11:34:06 GMT; Path=/

GET /app/gsm/prepaid/buy HTTP/1.1
Cookie: JSESSIONID=26097E35B6B0C9B6652A7A6F8FF77992.tomcatapp-02; _ga=GA1.2.1159250103.1389354702; __utma=159157733.1159250103.1389354702.1389606393.1389609120.7; __utmz=159157733.1389362294.3.2.utmcsr=siminn.is|utmccn=(referral)|utmcmd=referral|utmcct=/; userstyles=off; __utmc=159157733; __utmmobile=0xd4b5e4e4320505f5; __utmb=159157733.21.10.1389609120; is_returning=1; autoLogin.disabled=true; s_cc=true; s_sq=siminnliveinnri%3D%2526pid%253Dfors%2525u00ED%2525F0a%2526pidt%253D1%2526oid%253DInnskr%2525u00E1%2526oidt%253D3%2526ot%253DSUBMIT; USER_CACHE_KEY=D6D0DCFD773406CA8EE5D690A4AF1368.tomcattf-02
Set-Cookie: JSESSIONID=1C5A65534437F3F3E4D252B8671650A6.tomcatapp-01; Path=/app/; Secure; HttpOnly

But every once in a while the apache server initiates new sessions every time a request comes in with a new JSESSIONID, this issue is resolved temporarily by restarting the webserver.

Same behavior happens with httpd 2.4.6. Error log with LogLevel Debug for a single requesting client:

[client IP:56456] AH01964: Connection to child 714 established (server www.x.com:443)
[client IP:56456] AH02043: SSL virtual host for servername www.x.com found
[client IP:56456] AH02041: Protocol: TLSv1, Cipher: ECDHE-RSA-AES256-SHA (256/256 bits)

[client IP:56456] AH02034: Initial (No.1) HTTPS request received for child 714 (server www.x.com:443), referer: http://www.x.com/
[client IP:56456] AH01628: authorization result: granted (no directives), referer: http://www.x.com/
[client IP:56456] AH01160: Found value (J2EE4847100)ID1435349250DBfa8033a3ce4db1f64ba8d682cf8c5736533dc780End for stickysession JSESSIONID, referer: http://www.x.com/
[client IP:56456] AH01172: balancer://ssl-cluster: worker (ajp://tomcat1.x.com:9108) rewritten to ajp://tomcat1.x.com:9108/vefsms/, referer: http://www.x.com/
[client IP:56456] AH01143: Running scheme balancer handler (attempt 0), referer: http://www.x.com/
[client IP:56456] AH01113: HTTP: declining URL ajp://tomcat1.x.com:9108/vefsms/, referer: http://www.x.com/
[client IP:56456] AH00895: serving URL ajp://tomcat1.x.com:9108/vefsms/, referer: http://www.x.com/
[client IP:56456] AH00944: connecting ajp://tomcat1.x.com:9108/vefsms/ to tomcat1.x.com:9108, referer: http://www.x.com/
[client IP:56456] AH00947: connected /vefsms/ to tomcat1.x.com:9108, referer: http://www.x.com/
[client IP:56456] AH00872: APR_BUCKET_IS_EOS, referer: http://www.x.com/
[client IP:56456] AH00873: data to read (max 8186 at 4), referer: http://www.x.com/
[client IP:56456] AH00875: got 0 bytes of data, referer: http://www.x.com/
[client IP:56456] AH01384: Zlib: Compressed 2299 to 988 : URL /vefsms/, referer: http://www.x.com/
[client IP:56456] AH00892: got response from x.15:9108 (tomcat1.x.com), referer: http://www.x.com/
[client IP:56456] AH01176: proxy_balancer_post_request for (balancer://ssl-cluster), referer: http://www.x.com/

[client IP:56457] AH01964: Connection to child 707 established (server www.x.com:443)

[client IP:56456] AH02034: Subsequent (No.2) HTTPS request received for child 714 (server www.x.com:443), referer: https://www.x.com/vefsms/
[client IP:56456] AH01628: authorization result: granted (no directives), referer: https://www.x.com/vefsms/

[client IP:56457] AH02043: SSL virtual host for servername www.x.com found
[client IP:56457] AH02041: Protocol: TLSv1, Cipher: ECDHE-RSA-AES256-SHA (256/256 bits)

[client IP:56457] AH02034: Initial (No.1) HTTPS request received for child 707 (server www.x.com:443), referer: https://www.x.com/vefsms/
[client IP:56457] AH01628: authorization result: granted (no directives), referer: https://www.x.com/vefsms/

[client IP:56456] AH01160: Found value 4A0775A9DDFBFB1FE2B6AE14F62C5904.tomcat2 for stickysession JSESSIONID, referer: https://www.x.com/vefsms/
[client IP:56456] AH01161: Found route tomcat2, referer: https://www.x.com/vefsms/
[client IP:56456] AH01172: balancer://ssl-cluster: worker (ajp://tomcat2.x.com:9108) rewritten to ajp://tomcat2.x.com:9108/vefsms-portlets/dwr/interface/Controller.js, referer: https://www.x.com/vefsms/
[client IP:56456] AH01143: Running scheme balancer handler (attempt 0), referer: https://www.x.com/vefsms/
[client IP:56456] AH01113: HTTP: declining URL ajp://tomcat2.x.com:9108/vefsms-portlets/dwr/interface/Controller.js, referer: https://www.x.com/vefsms/
[client IP:56456] AH00895: serving URL ajp://tomcat2.x.com:9108/vefsms-portlets/dwr/interface/Controller.js, referer: https://www.x.com/vefsms/
[client IP:56456] AH00944: connecting ajp://tomcat2.x.com:9108/vefsms-portlets/dwr/interface/Controller.js to tomcat2.x.com:9108, referer: https://www.x.com/vefsms/
[client IP:56456] AH00947: connected /vefsms-portlets/dwr/interface/Controller.js to tomcat2.x.com:9108, referer: https://www.x.com/vefsms/
[client IP:56456] AH00872: APR_BUCKET_IS_EOS, referer: https://www.x.com/vefsms/
[client IP:56456] AH00873: data to read (max 8186 at 4), referer: https://www.x.com/vefsms/
[client IP:56456] AH00875: got 0 bytes of data, referer: https://www.x.com/vefsms/

[client IP:56457] AH01160: Found value 4A0775A9DDFBFB1FE2B6AE14F62C5904.tomcat2 for stickysession JSESSIONID, referer: https://www.x.com/vefsms/
[client IP:56457] AH01161: Found route tomcat2, referer: https://www.x.com/vefsms/
[client IP:56457] AH01172: balancer://ssl-cluster: worker (ajp://tomcat2.x.com:9108) rewritten to ajp://tomcat2.x.com:9108/vefsms-portlets/dwr/engine.js, referer: https://www.x.com/vefsms/
[client IP:56457] AH01143: Running scheme balancer handler (attempt 0), referer: https://www.x.com/vefsms/
[client IP:56457] AH01113: HTTP: declining URL ajp://tomcat2.x.com:9108/vefsms-portlets/dwr/engine.js, referer: https://www.x.com/vefsms/
[client IP:56457] AH00895: serving URL ajp://tomcat2.x.com:9108/vefsms-portlets/dwr/engine.js, referer: https://www.x.com/vefsms/
[client IP:56457] AH00944: connecting ajp://tomcat2.x.com:9108/vefsms-portlets/dwr/engine.js to tomcat2.x.com:9108, referer: https://www.x.com/vefsms/
[client IP:56456] AH01384: Zlib: Compressed 1999 to 349 : URL /vefsms-portlets/dwr/interface/Controller.js, referer: https://www.x.com/vefsms/

[client IP:56457] AH00947: connected /vefsms-portlets/dwr/engine.js to tomcat2.x.com:9108, referer: https://www.x.com/vefsms/

[client IP:56456] AH00892: got response from x.16:9108 (tomcat2.x.com), referer: https://www.x.com/vefsms/
[client IP:56456] AH01176: proxy_balancer_post_request for (balancer://ssl-cluster), referer: https://www.x.com/vefsms/

[client IP:56457] AH00872: APR_BUCKET_IS_EOS, referer: https://www.x.com/vefsms/
[client IP:56457] AH00873: data to read (max 8186 at 4), referer: https://www.x.com/vefsms/
[client IP:56457] AH00875: got 0 bytes of data, referer: https://www.x.com/vefsms/
[client IP:56457] AH01384: Zlib: Compressed 45758 to 11910 : URL /vefsms-portlets/dwr/engine.js, referer: https://www.x.com/vefsms/
[client IP:56457] AH00892: got response from x.16:9108 (tomcat2.x.com), referer: https://www.x.com/vefsms/
[client IP:56457] AH01176: proxy_balancer_post_request for (balancer://ssl-cluster), referer: https://www.x.com/vefsms/
[client IP:56457] AH02034: Subsequent (No.2) HTTPS request received for child 707 (server www.x.com:443)
[client IP:56457] AH01628: authorization result: granted (no directives)
[client IP:56457] AH01160: Found value (J2EE4847100)ID1435349250DBfa8033a3ce4db1f64ba8d682cf8c5736533dc780End for stickysession JSESSIONID
[client IP:56457] AH01172: balancer://ssl-cluster: worker (ajp://tomcat1.x.com:9108) rewritten to ajp://tomcat1.x.com:9108/favicon.ico
[client IP:56457] AH01143: Running scheme balancer handler (attempt 0)
[client IP:56457] AH01113: HTTP: declining URL ajp://tomcat1.x.com:9108/favicon.ico
[client IP:56457] AH00895: serving URL ajp://tomcat1.x.com:9108/favicon.ico
[client IP:56457] AH00944: connecting ajp://tomcat1.x.com:9108/favicon.ico to tomcat1.x.com:9108
[client IP:56457] AH00947: connected /favicon.ico to tomcat1.x.com:9108
[client IP:56457] AH00872: APR_BUCKET_IS_EOS
[client IP:56457] AH00873: data to read (max 8186 at 4)
[client IP:56457] AH00875: got 0 bytes of data
[client IP:56457] AH00892: got response from x.15:9108 (tomcat1.x.com)
[client IP:56457] AH01176: proxy_balancer_post_request for (balancer://ssl-cluster)
[client IP:56457] AH02034: Subsequent (No.3) HTTPS request received for child 707 (server www.x.com:443), referer: https://www.x.com/vefsms/
[client IP:56457] AH01628: authorization result: granted (no directives), referer: https://www.x.com/vefsms/
[client IP:56457] AH01160: Found value (J2EE4847100)ID1435349250DBfa8033a3ce4db1f64ba8d682cf8c5736533dc780End for stickysession JSESSIONID, referer: https://www.x.com/vefsms/
[client IP:56457] AH01172: balancer://ssl-cluster: worker (ajp://tomcat2.x.com:9108) rewritten to ajp://tomcat2.x.com:9108/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber, referer: https://www.x.com/vefsms/
[client IP:56457] AH01143: Running scheme balancer handler (attempt 0), referer: https://www.x.com/vefsms/
[client IP:56457] AH01113: HTTP: declining URL ajp://tomcat2.x.com:9108/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber, referer: https://www.x.com/vefsms/
[client IP:56457] AH00895: serving URL ajp://tomcat2.x.com:9108/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber, referer: https://www.x.com/vefsms/
[client IP:56457] AH00944: connecting ajp://tomcat2.x.com:9108/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber to tomcat2.x.com:9108, referer: https://www.x.com/vefsms/
[client IP:56457] AH00947: connected /vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber to tomcat2.x.com:9108, referer: https://www.x.com/vefsms/
[client IP:56457] AH00873: data to read (max 8186 at 4), referer: https://www.x.com/vefsms/
[client IP:56457] AH00875: got 1 bytes of data, referer: https://www.x.com/vefsms/
[client IP:56457] AH01384: Zlib: Compressed 3032 to 1232 : URL /vefsms/, referer: https://www.x.com/vefsms/
[client IP:56457] AH00892: got response from x.16:9108 (tomcat2.x.com), referer: https://www.x.com/vefsms/
[client IP:56457] AH01176: proxy_balancer_post_request for (balancer://ssl-cluster), referer: https://www.x.com/vefsms/

[client IP:56456] AH02034: Subsequent (No.3) HTTPS request received for child 714 (server www.x.com:443), referer: https://www.x.com/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber
[client IP:56456] AH01628: authorization result: granted (no directives), referer: https://www.x.com/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber
[client IP:56456] AH01160: Found value 4A0775A9DDFBFB1FE2B6AE14F62C5904.tomcat2 for stickysession JSESSIONID, referer: https://www.x.com/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber
[client IP:56456] AH01161: Found route tomcat2, referer: https://www.x.com/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber
[client IP:56456] AH01172: balancer://ssl-cluster: worker (ajp://tomcat2.x.com:9108) rewritten to ajp://tomcat2.x.com:9108/vefsms-portlets/dwr/engine.js, referer: https://www.x.com/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber
[client IP:56456] AH01143: Running scheme balancer handler (attempt 0), referer: https://www.x.com/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber
[client IP:56456] AH01113: HTTP: declining URL ajp://tomcat2.x.com:9108/vefsms-portlets/dwr/engine.js, referer: https://www.x.com/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber
[client IP:56456] AH00895: serving URL ajp://tomcat2.x.com:9108/vefsms-portlets/dwr/engine.js, referer: https://www.x.com/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber
[client IP:56456] AH00944: connecting ajp://tomcat2.x.com:9108/vefsms-portlets/dwr/engine.js to tomcat2.x.com:9108, referer: https://www.x.com/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber
[client IP:56456] AH00947: connected /vefsms-portlets/dwr/engine.js to tomcat2.x.com:9108, referer: https://www.x.com/vefsms/?portal:componentId=1529&portal:type=action&portal:isSecure=false&portal:portletMode=view&action=phonenumber

Has any one seen similar issues with the use of Proxy balancer?

Best Answer

It actually looks pretty hard for what you describe to happen. The route is parsed from the incoming cookie/param which seems fairly simple, then the route is looked up in the balance members. Only then does it get into the more complex load based member selection if the route can't be found. So maybe the members are going down causing the lookup to fail or httpd loses it's knowledge of the balance members. This does involve shared data between httpd threads so that's always a possible cause for troubles.

Maybe try the standard 2.2.26 release, to be fair not a lot of the balancer or proxy code has changed since 2.2.16. Debian does have bits and pieces back ported, mainly security stuff, so could be something weird going on there.

See if you can gracefully restart httpd with LogLevel debug while the problem is occurring. If the error state remains you'll get a heap of detail in your error log about balancer member selections which should give you a better idea of what is happening underneath.

Failing the logging, try adding the balancer environment variables to a LogFormat definition so you get them in your access.log. You might be able to better trace what is happening from them:

\"%{BALANCER_NAME}e\"
\"%{BALANCER_WORKER_NAME}e\"
\"%{BALANCER_WORKER_ROUTE}e\"
\"%{BALANCER_SESSION_STICKY}e\"
\"%{BALANCER_SESSION_ROUTE}e\"
\"%{BALANCER_ROUTE_CHANGED}e\"
Related Topic