On 17/11/2011 01:29, Jeremy wrote: > OK, I know this seems crazy, but I've looked long and hard and cannot > explain this as other than a Tomcat bug. I'm more than willing to dig up > extra information where I can, but this is a very rare problem seen in > production and not reproducible at will. Also, because this is in > production, there is very little I can change, and even if I did change it, > it would take a month or more to verify that it is really a fix. So what > I'm really looking for is a detailed understanding of the problem so we can > detect it when it happens and clean up the after-effects. > > What we are seeing is one POST request being handled twice by our web app. > It looks as though somehow the request is duplicated by Tomcat. Here's > our setup: > > Apache 2.2.14 using APR 1.3.8 and mod_jk 1.2.28 running on Ubuntu 10.04.3 > as front end, load balancing. > Tomcat 6.0.29 using built-in AJP/1.3 connector running on Ubuntu 9.04 with > 64-bit Sun Java 1.5.0_19. Tomcat is not using APR. > Tomcat mod_jk connector has keepAliveTimeout=5000 and > connectionTimeout=60000 (60 seconds). > > Here is a simplified timeline of what we see in various logs. I'm going to > leave some fields out and change others to protect confidentiality and make > it easier to follow, but I'll try to keep from changing anything important. > Timestamps are just minutes and seconds. > > > 51:48 POST request received by Apache over SSL. We see the request logged > in Apache's access.log with this timestamp, but the log entry is actually > written at 52:08 (or seems to be, since that is the time stamp of the next > entry in the access.log, though the entries immediately before this one > have timestamps of 52:02). > > 51:48 log4j application logs show processing of the request by the > application in thread TP-Processor18. Processing continues with updates > to database and external systems until: > > 51:55 last application log entry from TP-Processor18 shows normal > completion of processing, which should then return from handleRequest(). > The database and three external systems the app communicates with all show > normal processing. > > 51:55 log4j application log entries from TP-Processor6 show it beginning to > handle the request. Processing continues normally, just as it did in > TP-Processor18 until: > > 52:08 last application log entry from TP-Processor6. Again external > systems show normal processing. > > 52:08 Tomcat access log shows entry for post request stating it was handled > by TP-Processor6 in 7283ms > > 52:08 mod_jk.log: loadbalancer www.site.com 19.400742 > > 53:06 Tomcat access log shows entry for post request stating it was handled > by TP-Processor18 in 77440ms > > > How is it possible that Tomcat has 2 threads handling the same request?
Because I think there are two requests here, rather than one. My guess as to what is happening is as follows: - httpd sends request to Tomcat - Tomcat processes it - network glitch or similar means httpd never receives the response - httpd resends request to Tomcat - Tomcat processes it - httpd receives the response - httpd sends response to user Examining the mod_jk logs on httpd should show this although I don't know what level of logging you'll need to see it. The only hitch with the above is that I'd expect httpd to take longer to realise that there is a problem before re-trying the request. > How can we detect this as opposed to the user legitimately sending the same > request twice? Use mod_unique_id with mod_rewrite to add the unique ID as a url parameter and then include this in Tomcat's access log and/or write a filter that checks for duplicates. > Thanks for your help! The situation you describe could also be triggered by a Tomcat bug. You might want to try protocol="org.apache.coyote.ajp.AjpProtocol" on the connector to switch the the Coyote AJP BIO implementation. Mark > =Jeremy= > --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
