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 --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
