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>