Return-Path: X-Original-To: apmail-tomcat-users-archive@www.apache.org Delivered-To: apmail-tomcat-users-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 8DA6169DA for ; Thu, 4 Aug 2011 21:28:09 +0000 (UTC) Received: (qmail 27227 invoked by uid 500); 4 Aug 2011 21:28:06 -0000 Delivered-To: apmail-tomcat-users-archive@tomcat.apache.org Received: (qmail 27050 invoked by uid 500); 4 Aug 2011 21:28:05 -0000 Mailing-List: contact users-help@tomcat.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: "Tomcat Users List" Delivered-To: mailing list users@tomcat.apache.org Received: (qmail 27041 invoked by uid 99); 4 Aug 2011 21:28:05 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 04 Aug 2011 21:28:05 +0000 X-ASF-Spam-Status: No, hits=-0.7 required=5.0 tests=FREEMAIL_FROM,RCVD_IN_DNSWL_LOW,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of alecswan@gmail.com designates 74.125.82.173 as permitted sender) Received: from [74.125.82.173] (HELO mail-wy0-f173.google.com) (74.125.82.173) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 04 Aug 2011 21:27:57 +0000 Received: by wye20 with SMTP id 20so1769822wye.18 for ; Thu, 04 Aug 2011 14:27:37 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :content-type:content-transfer-encoding; bh=wGW8laM+dAetVrcg/dkYM0M6ZdSi+3v2OprsdyYaC+s=; b=sq8huEREyYZAbUgzjzvMbfT1jENUBrwJ+TRb2nV3DXdttDyiS+14vL/C3loFRa6htH pk9cNh9a0wPW4BdKp4uyAE82Rh2qzbmXDFDdKVuzIp4WNj6VbwMjpCJUYUFZH1u+QMnC mojjF2MliFurjU8mvr9oNbgdlH5suLt83vEDA= MIME-Version: 1.0 Received: by 10.216.6.204 with SMTP id 54mr2220366wen.34.1312493257572; Thu, 04 Aug 2011 14:27:37 -0700 (PDT) Received: by 10.216.159.74 with HTTP; Thu, 4 Aug 2011 14:27:37 -0700 (PDT) In-Reply-To: References: <4E3AD14E.5070905@ice-sa.com> <4E3AF881.4080102@ice-sa.com> Date: Thu, 4 Aug 2011 15:27:37 -0600 Message-ID: Subject: Re: Tomcat 6.0.32 ClientAbortException java.io.IOException From: Alec Swan To: Tomcat Users List Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable X-Virus-Checked: Checked by ClamAV on apache.org Here is a little more information. Tomcat was processing HTTP request for 10 minutes sharp and was eventually ready to send the response back to the client. So, Tomcat generated a TCP [FIN, ACK] message with a valid SOAP response. However, the very next TCP message contained the following error: "Broken TCP. The acknowledge field is nonzero while the ACK flag is not set= ." Thanks, Alec On Thu, Aug 4, 2011 at 3:16 PM, Alec Swan wrote: > Thank you all for your suggestions. > > I've been sniffing TCP traffic all day today and noticed the following pa= ttern: > 1. Client sends an HTTP post to Tomcat > 2. Tomcat receives the request and takes 15 minutes to process it > 3. Tomcat eventually completes the request and attempts to write it > back to the client > 4. Client never receives the response > > So, you are right that the connection is dropped somewhere between the > client and Tomcat. I removed the load balancer from the equation by > hitting the app server directly. > > I am troubleshooting this in our customer's environment and have no > idea how to go about tracking down where the connection gets dropped. > I guess we could somehow track network hops? Any ideas on how to track > this down? > > Thanks, > > Alec > > On Thu, Aug 4, 2011 at 1:52 PM, Andr=E9 Warnier wrote: >> Alec Swan wrote: >>> >>> Hello, >>> >>> I agree that this is not a bug in Tomcat code, but I would appreciate >>> any help with troubleshooting this. >>> >>> Let me tell you about our app. We have a thousands of Metro SOAP >>> clients which hit our Tomcat server. Some SOAP HTTP requests take over >>> an hour to process because queries take a very long time to execute in >>> the database. The clients are configured to never timeout waiting on >>> the server response. >>> >> >> And could there be something else, between the client and the Tomcat, wh= ich >> could time out if no activity happens on that connection ? >> (I have known of routers/firewalls which did this, to save on connection= s to >> maintain). >> >>> So, I can see the following possible causes of the Client Abort >>> Exception logged by Tomcat: >>> >>> 1. The client drops its connection to the server - I would have >>> expected the client to get some sort of offline exception and >>> terminate the request. Instead, the client keeps waiting, so maybe >>> this is not the problem. >>> 2. Tomcat times out (our connectionTimeout is set to 600000) and >>> somehow fails to write the response back. >> >> I think that you can rule this one out. =A0The connectionTimeout, if I >> remember correctly, only applies to the time between >> - when the client establishes the HTTP connection to Tomcat >> - and the time when Tomcat receives the actual request on that connectio= n >> It is essentially meant to avoid attacks where many clients would create >> connections to Tomcat and never send a request (and thus block threads (= or >> at least connected sockets) for nothing). >> >> But check the documentation to see if maybe this parameter value is take= n as >> a default for other unspecified timeouts. >> >>> 3. Tomcat's DBCP connection pool times out >>> >>> Could anybody help us enable the right kind of logging to verify the >>> last two possible causes? Can you think of any other ways to >>> troubleshoot this? >>> >> >> You can set up an AccessLogValve and measure the time taken by each requ= est. >> And you can take thread dumps, as mentioned previously, to see what thes= e >> Tomcat threads are really doing while the client is waiting. >> You can also trace the real packets exchanged via an external protocol >> analyser such as Wireshark. That will tell you if it is the client dropp= ing >> the connection, or if something in-between is doing that. =A0Tomcat logs= can >> only tell you what happens in Tomcat. >> And for Tomcat, if an intermediate agent is dropping the connection, it = will >> also look like a Client Abort. >> >> >> Generally speaking, I don't think that there are many explanations for a >> "Client Abort" exception. =A0If it was Tomcat doing (or not doing) somet= hing >> and aborting the application, the error message would be different. >> So, considering that this is a clue, and that you have no other clue unt= il >> now, I would start by examining that as a possible cause, and not other >> hypothetical scenarios for which you have not seen a clue yet. >> >> >>> Thanks, >>> >>> Alec >>> >>> On Thu, Aug 4, 2011 at 11:05 AM, Andr=E9 Warnier wrote: >>>> >>>> Hi. >>>> >>>> It dos not look to me like the problem is in Tomcat per se, but rather= in >>>> the application running inside of Tomcat, and/or the client applicatio= n. >>>> >>>> Let me explain what leads me to that supposition : >>>> >>>> - according to (1) and (2) below, the SOAP request was sent by the >>>> client, >>>> received by Tomcat, and passed by Tomcat to the corresponding applicat= ion >>>> >>>> Then according to the log, an exception occurs *within the application >>>> classes* (not inside Tomcat code). =A0Scrolling down the log, it appea= rs >>>> that >>>> : >>>> >>>>> Caused by: ClientAbortException: java.io.IOException >>>> >>>> That would mean that when the webapp within the Tomcat application is >>>> trying >>>> to send some output to the client, it finds the client socket closed (= by >>>> the >>>> client). >>>> >>>> This could happen for instance if the client "got tired of waiting" so= to >>>> speak, hit some internal timeout waiting for a server response, and >>>> decided >>>> to give up and close the socket on which it was waiting for a response= . >>>> Then some time later the application tries to send some response, but >>>> hits >>>> the closed socket and throws the exception. >>>> >>>> That would explain (3) in your list, because from the point of view of >>>> Tomcat then, this application invocation is finished (with an error, b= ut >>>> finished). >>>> >>>> Now why the application appears in (4) to still be waiting, I can only >>>> then >>>> attribute to some logic error in the application : it gave up waiting = and >>>> closed the socket, but still says that it is waiting ? >>>> >>>> >>>> In any case, in a standard configuration, I do not think that Tomcat >>>> would >>>> kill an application by its own decision, even if this application took= 30 >>>> minutes to return a response. >>>> >>>> Maybe a few thread dumps a couple of seconds apart, when Tomcat has >>>> received >>>> the SOAP request, may explain what the responding thread is doing that >>>> takes >>>> so long before sending a response. =A0There is information in the Tomc= at >>>> FAQ >>>> about how to do that. >>>> >>>> I would also inspect the client code to check if there is a timeout fo= r a >>>> server response, and what it does exactly when that timeout is reached= . >>>> A standard browser would have a timeout of approx. 5 minutes, and then= it >>>> would display a page saying "the server is taking too long to respond.= ." >>>> etc.. >>>> Biut with other code, it depends on the code. >>>> >>>> >>>> Alec Swan wrote: >>>>> >>>>> Hello, >>>>> >>>>> We are experiencing a problem on our production servers causing our >>>>> HTTP clients to hang. I apologize for cross-posting with Metro forum >>>>> but this is a critical problem for us. >>>>> >>>>> It looks like client SOAP HTTP requests get dropped/terminated by >>>>> Tomcat or metro without notifying the client that request was >>>>> terminated leaving the client waiting indefinitely for response. >>>>> >>>>> Here is what we observed: >>>>> 1. Client makes a SOAP call to the server >>>>> 2. Tomcat receives HTTP request and we can see it listed on Tomcat >>>>> Manager >>>>> page >>>>> 3. After about 5 minutes HTTP request disappears from the list of >>>>> active HTTP request >>>>> 4. The client is still waiting for response >>>>> >>>>> We also noticed the following exception logged in catalina.out. It is >>>>> thrown around the same time when the problem above occurs but we are >>>>> not sure if there is a direct correlation between them. >>>>> >>>>> Aug 1, 2011 12:07:44 AM >>>>> com.sun.xml.ws.transport.http.servlet.WSServletDelegate doGet >>>>> >>>>> SEVERE: caught throwable >>>>> >>>>> javax.xml.ws.WebServiceException: com.ctc.wstx.exc.WstxIOException: n= ull >>>>> >>>>> =A0 =A0 =A0 at >>>>> com.sun.xml.ws.encoding.StreamSOAPCodec.encode(StreamSOAPCodec.java:1= 12) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> com.sun.xml.ws.encoding.SOAPBindingCodec.encode(SOAPBindingCodec.java= :278) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> com.sun.xml.ws.transport.http.HttpAdapter.encodePacket(HttpAdapter.ja= va:383) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> com.sun.xml.ws.transport.http.HttpAdapter.access$100(HttpAdapter.java= :93) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> com.sun.xml.ws.transport.http.HttpAdapter$HttpToolkit.handle(HttpAdap= ter.java:529) >>>>> >>>>> =A0 =A0 =A0 at >>>>> com.sun.xml.ws.transport.http.HttpAdapter.handle(HttpAdapter.java:288= ) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> com.sun.xml.ws.transport.http.servlet.ServletAdapter.handle(ServletAd= apter.java:143) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doGet(WSServl= etDelegate.java:155) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doPost(WSServ= letDelegate.java:189) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> com.sun.xml.ws.transport.http.servlet.WSServlet.doPost(WSServlet.java= :76) >>>>> >>>>> =A0 =A0 =A0 at javax.servlet.http.HttpServlet.service(HttpServlet.jav= a:637) >>>>> >>>>> =A0 =A0 =A0 at javax.servlet.http.HttpServlet.service(HttpServlet.jav= a:717) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Appl= icationFilterChain.java:290) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationF= ilterChain.java:206) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperV= alve.java:233) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.catalina.core.StandardContextValve.invoke(StandardContextV= alve.java:191) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.catalina.authenticator.AuthenticatorBase.invoke(Authentica= torBase.java:470) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.j= ava:127) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.j= ava:102) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineVal= ve.java:109) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.jav= a:298) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcesso= r.java:864) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.pr= ocess(Http11AprProtocol.java:579) >>>>> >>>>> =A0 =A0 =A0 at >>>>> org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:16= 65) >>>>> >>>>> =A0 =A0 =A0 at java.lang.Thread.run(Unknown Source) >>>>> >>>>> Caused by: com.ctc.wstx.exc.WstxIOException: null >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> com.ctc.wstx.sw.BaseStreamWriter.finishDocument(BaseStreamWriter.java= :1687) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> com.ctc.wstx.sw.BaseStreamWriter.writeEndDocument(BaseStreamWriter.ja= va:585) >>>>> >>>>> =A0 =A0 =A0 at >>>>> com.sun.xml.ws.message.saaj.SAAJMessage.writeTo(SAAJMessage.java:368) >>>>> >>>>> =A0 =A0 =A0 at >>>>> com.sun.xml.ws.encoding.StreamSOAPCodec.encode(StreamSOAPCodec.java:1= 09) >>>>> >>>>> =A0 =A0 =A0 ... 24 more >>>>> >>>>> Caused by: ClientAbortException: java.io.IOException >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:= 319) >>>>> >>>>> =A0 =A0 =A0 at >>>>> org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:28= 8) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputSt= ream.java:98) >>>>> >>>>> =A0 =A0 =A0 at com.ctc.wstx.io.UTF8Writer.flush(UTF8Writer.java:99) >>>>> >>>>> =A0 =A0 =A0 at >>>>> com.ctc.wstx.sw.BufferingXmlWriter.flush(BufferingXmlWriter.java:214) >>>>> >>>>> =A0 =A0 =A0 at >>>>> com.ctc.wstx.sw.BufferingXmlWriter.close(BufferingXmlWriter.java:194) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> com.ctc.wstx.sw.BaseStreamWriter.finishDocument(BaseStreamWriter.java= :1685) >>>>> >>>>> =A0 =A0 =A0 ... 27 more >>>>> >>>>> Caused by: java.io.IOException >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.coyote.http11.InternalAprOutputBuffer.flushBuffer(Internal= AprOutputBuffer.java:716) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.coyote.http11.InternalAprOutputBuffer.flush(InternalAprOut= putBuffer.java:304) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.coyote.http11.Http11AprProcessor.action(Http11AprProcessor= .java:1021) >>>>> >>>>> =A0 =A0 =A0 at org.apache.coyote.Response.action(Response.java:183) >>>>> >>>>> =A0 =A0 =A0 at >>>>> >>>>> org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:= 314) >>>>> >>>>> =A0 =A0 =A0 ... 33 more >>>>> >>>>> >>>>> Any help will be greatly appreciated. >>>>> >>>>> Thanks! >>>>> >>>>> Alec >>>>> >>>>> --------------------------------------------------------------------- >>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org >>>>> For additional commands, e-mail: users-help@tomcat.apache.org >>>>> >>>>> >>>> >>>> --------------------------------------------------------------------- >>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org >>>> For additional commands, e-mail: users-help@tomcat.apache.org >>>> >>>> >>> >>> --------------------------------------------------------------------- >>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org >>> For additional commands, e-mail: users-help@tomcat.apache.org >>> >>> >> >> >> --------------------------------------------------------------------- >> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org >> For additional commands, e-mail: users-help@tomcat.apache.org >> >> > --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org For additional commands, e-mail: users-help@tomcat.apache.org