> From: Mark Thomas <ma...@apache.org> > Sent: Monday, November 2, 2020 5:38 AM > To: users@tomcat.apache.org > Subject: Re: Weirdest Tomcat Behavior Ever? > > On 02/11/2020 11:18, Eric Robinson wrote: > >> -----Original Message----- > >> From: Mark Thomas <ma...@apache.org> > >> Sent: Sunday, November 1, 2020 11:50 AM > >> To: users@tomcat.apache.org > >> Subject: Re: Weirdest Tomcat Behavior Ever? > >> > >> On 01/11/2020 16:25, Mark Thomas wrote: > >>> <snip/> > >>> > >>> Keeping the previous logs for reference: > >>> > >>>>> Source Time Activity > >>>>> ==================================================== > >>>>> pcap 15:14:25.375451 SYN proxy to Tomcat > >>>>> pcap 15:14:25.375493 SYN, ACK Tomcat to proxy > >>>>> pcap 15:14:25.375839 ACK proxy to Tomcat > >>>>> pcap 15:14:25.375892 GET request proxy to Tomcat > >>>>> pcap 15:14:25.375911 ACK Tomcat to proxy > >>>>> debug 15:14:25.376 o.a.c.http11.InternalOutputBuffer.init > >>>>> pcap 15:14:25.376777 FIN Tomcat to proxy > >>>>> pcap 15:14:25.377036 FIN, ACK proxy to Tomcat > >>>>> pcap 15:14:25.377048 ACK Tomcat proxy > >>>>> debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer.commit > >>>>> debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer$1.doWrite > >>>>> debug 15:14:25.383 > o.a.c.http11.InternalOutputBuffer$1.nextRequest > >>>>> debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer$1.recycle > >>>>> > >>>>> Tomcat writes the request body to the buffer but when Tomcat tries > >>>>> to flush those bytes out to the network it finds that the socket > >>>>> has been closed. That normally indicates that the client has > >>>>> dropped the connection. This is sufficiently common that Tomcat > >>>>> swallows the exception. However, we know (from the pcap file) that > >>>>> the client did not drop the connection, Tomcat did. > >>> > >>> The next round of logging added a little more detail for the > >>> InternalOutputBuffer and wrapped the Socket to see when close() was > >> called. > >>> > >>> The results from the next round of logging are: > >>> > >>> Source Time Activity > >>> ==================================================== > >>> pcap 13:31:26.344453 SYN proxy to Tomcat > >>> pcap 13:31:26.344481 SYN, ACK Tomcat to proxy > >>> debug 13:31:26.345 DebugSocket object created > >>> debug 13:31:26.345 o.a.c.http11.InternalOutputBuffer.init > >>> pcap 13:31:26.345138 ACK proxy to Tomcat > >>> pcap 13:31:26.345174 GET request proxy to Tomcat > >>> pcap 13:31:26.345194 ACK Tomcat to proxy > >>> pcap 13:31:26.395281 FIN, ACK Tomcat to proxy > >>> pcap 13:31:26.395725 ACK proxy to Tomcat > >>> pcap 13:31:26.395741 FIN, ACK proxy to Tomcat > >>> pcap 13:31:26.395754 ACK Tomcat to proxy > >>> debug 13:31:26.403 o.a.c.http11.InternalOutputBuffer.commit > >>> debug 13:31:26.403 o.a.c.http11.InternalOutputBuffer$1.doWrite > >>> debug 13:31:26.404 o.a.c.http11.InternalOutputBuffer$1.nextRequest > >>> debug 13:31:26.404 o.a.c.http11.InternalOutputBuffer$1.recycle > >>> debug 13:31:26.404 DebugSocket.close called > >>> > >>> This shows that the socket is closed long before Tomcat tries to > >>> write to it (that would be after the doWrite but before nextRequest) > >>> or Tomcat explicitly closes the socket. > >>> > >>> This also shows that neither Tomcat nor the application are directly > >>> calling close() on the socket to trigger the close shown by pcap. > >>> > >>> I continue to come up with theories as to what might be happening > >>> but they all seem unlikely. > >>> > >>> This is the BIO connector so the only time the socket should change > >>> state is during a method call. While it might seem a little over the > >>> top I think the next step is to log every single method call to > >>> DebugSocket along with any exception generated. We need to try and > >>> correlate the premature socket closure with something in the JVM. If > >>> there is no correlation to find then we really are into the realm of > >>> very strange JVM and/or OS bugs. > >>> > >>> I'll start work on v3 of the debug patch. > >> > >> http://home.apache.org/~markt/dev/v7.0.72-custom-patch-v3/ > >> > >> I opted to wrap both the InputStream and OutputStream associated with > >> the socket and log every method call and every exception thrown. I > >> opted not to log parameters with the exception of socket timeout > >> since that might be relevant. > >> > >> The debug logs will be noticeably more verbose that last time. Feel > >> free to adjust the number/size of debug log files as suits your > environment. > >> > >> Mark > >> > > > > I applied the V3 patch and confirmed that content is being written to > debug0.log, but right away I noticed an error recurring repeatedly. See > below. > > Thanks for getting that done over a weekend. Much appreciated. > > Don't worry, the exception isn't an error. It is an exception created (but not > thrown) by the debug code so we can see the call stack when the socket was > closed. It is the result of something like: > > log.debug("Message goes here", new Exception()); > > I was hoping to see some unexpected code calling close() - no luck. All the > calls to close were exactly what I would expect from normal operations. v3 > will provide more insight on the I/O operations. Fingers crossed that sheds > some light on what is triggering this socket closure. > > Mark
Gotcha, thanks for the clarification. Let's see what happens when the users start hitting it at 8:00 am Eastern. -Eric Disclaimer : This email and any files transmitted with it are confidential and intended solely for intended recipients. If you are not the named addressee you should not disseminate, distribute, copy or alter this email. Any views or opinions presented in this email are solely those of the author and might not represent those of Physician Select Management. Warning: Although Physician Select Management has taken reasonable precautions to ensure no viruses are present in this email, the company cannot accept responsibility for any loss or damage arising from the use of this email or attachments. --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
