Thanks for everyone's help... it was indeed app code.. some old ugly legacy
code was putting a reference to a request in a thread local variable and then
not cleaning up the thread local reference when the request ended. When the
thread was reused, it was referencing a request that was no longer valid (been
recycled) and all things went downhill from there.
We're still a bit confused as to why this code works fine in Tomcat 5.5 and
fails so gloriously in 6, but I suppose the recycling model and maybe the
thread handling model is different.
Thanks again!
-g.
On Feb 18, 2010, at 1:30 PM, George Baxter wrote:
> Hmm, well it's possible. However, I'm not entirely confident that each
> request has its own Cookies object. There is a 'setHeaders()' method on
> Cookies. What's it for? Checking myself. Will add more logging as you
> suggested.
>
>
> We are using Spring MVC which uses ThreadLocal to store requests... and these
> threads CAN spawn off child threads which 'inherit' the threadlocal
> variables. I'm not sure this is happening particularly often for us, but
> I'll be looking at that more closely.
>
> -g.
>
> On Feb 18, 2010, at 12:42 PM, Mark Thomas wrote:
>
>> On 18/02/2010 20:23, George Baxter wrote:
>>> So we think we've found a threading problem in the cookie handling.
>>
>> Hmm. Each request has its own Cookies object. The only way these would
>> be shared between threads is if two threads were using the same request
>> object. That usually happens when custom filters/valves wrap requests
>> and mix up the request/response objects. Putting requests and responses
>> into the session is another sign of things going awry.
>>
>> I'd add some logging to check which request and cookies objects are
>> being used and see if you can track down where they are getting mixed
>> up. My money is on application code.
>>
>> Mark
>>
>>>
>>> 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>
>>>
>>>
>>>
>>
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
>> For additional commands, e-mail: users-h...@tomcat.apache.org
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> For additional commands, e-mail: users-h...@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
