So we think we've found a threading problem in the cookie handling.
Running on Solaris 10, jdk 1.5, tomcat 6.0.24.
We built our 'own' version of 6.0.24, adding logging in some places, and
ultimately, this is what we discovered:
A bit of information: in these log entries, we're looking at 2 threads : 66
and 228.
We're also looking at 2 Cookies entities : 2021596579 and 1706042601.
Here's the modified 'getCookieCount()' method in Cookies:
public int getCookieCount() {
log("processed = " + !unprocessed);
if( unprocessed ) {
unprocessed=false;
log("calling process cookies");
processCookies(headers);
}
return cookieCount;
}
First, thread 66 receives a request (from a monitoring process, has no cookies):
Feb 18, 2010 11:31:04 AM org.apache.catalina.connector.CoyoteAdapter
parseSessionCookiesId
INFO: 66-parseSessionCookie for request: R( /)
Next, it's checking its cookie count, and here's something wrong already : the
unprocessed flag in Cookies is already set to false.. for Cookies 1706042601.
Feb 18, 2010 11:31:04 AM org.apache.tomcat.util.http.Cookies log
INFO: 66,1706042601-C:processed = true
Next, we jump to thread 228: it seems to be busy ending a request using
Cookies 2021596579
Feb 18, 2010 11:31:04 AM org.apache.tomcat.util.http.Cookies log
INFO: 228,2021596579-C:recycling Cookies
Back to thread 66, who suddenly seems to be using THE SAME COOKIES OBJECT:
Feb 18, 2010 11:31:04 AM org.apache.tomcat.util.http.Cookies log
INFO: 66,2021596579-C:processed = false
Feb 18, 2010 11:31:04 AM org.apache.tomcat.util.http.Cookies log
INFO: 66,2021596579-C:calling process cookies
Then, its now recycling Cookies.. in fact, it's recycling Cookies 1706042601
twice!
Feb 18, 2010 11:31:04 AM org.apache.tomcat.util.http.Cookies log
INFO: 66,1706042601-C:recycling Cookies
Feb 18, 2010 11:31:04 AM org.apache.tomcat.util.http.Cookies log
INFO: 66,1706042601-C:recycling Cookies
Back to 228, which is going to try to handle a new request. Note that at this
time, 2021596579 has not yet been recycled:
Feb 18, 2010 11:31:04 AM org.apache.catalina.connector.CoyoteAdapter
parseSessionCookiesId
INFO: 228-parseSessionCookie for request: R( /nav/mysfly.sfly)
Feb 18, 2010 11:31:04 AM org.apache.tomcat.util.http.Cookies log
INFO: 228,2021596579-C:processed = true
Feb 18, 2010 11:31:04 AM org.apache.tomcat.util.http.Cookies log
INFO: 228,2021596579-C:recycling Cookies
And thus, we've lost our session reference.
God I hope the formatting holds when I send this....
-George
On Feb 17, 2010, at 12:00 PM, George Baxter wrote:
Downloaded src code of tomcat for debugging purposes and sure enough, our
cookies are of type byte, so the fact that the code can parse the cookie
'string' just fine means diddly-squat.
Next plan, build my own tomcat 6.0.24 version with lots of logging and checks
for debugging purposes...
-g.
On Feb 16, 2010, at 4:22 PM, George Baxter wrote:
Well.. we parsed the header that failed, and it parsed just fine.
Note that we're parsing via the 'old deprecated' parse by string entity. I
guess I'll try parsing by bytes next.
-g.
On Feb 16, 2010, at 2:47 PM, Konstantin Kolinko wrote:
2010/2/17 George Baxter <gbax...@shutterfly.com<mailto:gbax...@shutterfly.com>>:
Hi Konstantin,
Thanks for your reply.
Yes, the getHeaders("cookie") returns what seems to be a valid set of cookies,
thus we're not losing them in any of the proxies we might have set up.
(Currently, we're only in development mode for tomcat 6 and we're not going
through any proxies, just directly to the server.)
We get this problem in all sorts of browsers (FF, Safari, IE).
The thing that really bugs me is the inconsistency. It's almost as if there
were a race condition going on, but the request is basically single threaded,
isn't it? My only fear is some parser used in the tomcat code is being used in
a non-thread safe manner, but then *everybody* would be having this problem,
neh?
I'm finding out about the connectors, but we may not be using any as :
Jan 28, 2010 6:52:56 PM org.apache.catalina.core.AprLifecycleListener init
INFO: The APR based Apache Tomcat Native library which allows optimal
performance in production environments was not found on the java.library.path:
/dist/sfsite/obj
Hopefully, this is just in our development environments!
Thanks,
-George
On Feb 12, 2010, at 2:32 PM, Konstantin Kolinko wrote:
2010/2/13 George Baxter <gbax...@shutterfly.com<mailto:gbax...@shutterfly.com>>:
Hello,
We're running into an issue with tomcat 6.0.18 running on solaris.
Occasionally a request will come through that has cookies in the header, but
the request.getCookies() returns no cookies.
How do you observe that? You mean that it is present in
HttpServletRequest.getHeaders("Cookie") ?
This causes the user to lose
session since even the JSESSIONID cookie is not recognized, and of course
all our custom cookies are lost. It seems to happen randomly, across our
web site, and varies in frequency from every 2-3 requests to over 200
requests before it happens again.
There's no change to the cookie values (or very little) between requests.
In addition, this only seems to be a problem on solaris. Running on MacOSx
or Linux and we don't see the issue. Also, we don't have the problem in
Tomcat 5.5.
Any other details on your configuration?
What connectors are you using? HTTP/AJP? Nio/Bio/Apr? (usually some
org.apache.coyote.* class is mentioned in the startup log in a
"Starting Coyote .." message) Do you have Apache HTTPD in front of
Tomcat? Do you have HTTP proxies around? Are failing requests
coming from some specific client? Are they coming from some specific
browser?
Best regards,
Konstantin Kolinko
1. What is the default character encoding for your environment?
2. Cookies are parsed in
org.apache.tomcat.util.http.Cookies.processCookies()
You may
1) Look in your logs for a WARN message with the text "Cookies:
Parsing cookie as String. Expected bytes."
2) You can consider enabling FINE logging for the above mentioned
class. Add this to the logging.properties:
org.apache.tomcat.util.http.Cookies.level=FINE
It will log what headers it parsed.
Though it might be hard to match what is logged to your specific
request, so it might be useless.
3) When an issue is encountered, log the headers.
Then post them here or try to parse them yourselves,
copying the code from Cookies.processCookieHeader() for the Tomcat
version that you are using.
3. Have you considered trying it with a more recent Tomcat version?
Best regards,
Konstantin Kolinko
---------------------------------------------------------------------
To unsubscribe, e-mail:
users-unsubscr...@tomcat.apache.org<mailto:users-unsubscr...@tomcat.apache.org>
For additional commands, e-mail:
users-h...@tomcat.apache.org<mailto:users-h...@tomcat.apache.org>
---------------------------------------------------------------------
To unsubscribe, e-mail:
users-unsubscr...@tomcat.apache.org<mailto:users-unsubscr...@tomcat.apache.org>
For additional commands, e-mail:
users-h...@tomcat.apache.org<mailto:users-h...@tomcat.apache.org>
---------------------------------------------------------------------
To unsubscribe, e-mail:
users-unsubscr...@tomcat.apache.org<mailto:users-unsubscr...@tomcat.apache.org>
For additional commands, e-mail:
users-h...@tomcat.apache.org<mailto:users-h...@tomcat.apache.org>
