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