tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Mark Thomas <ma...@apache.org>
Subject Re: slow or timeout with client certificate and some http client against tomcat 8.5 with Nio2 OpenSSL implementation
Date Wed, 02 May 2018 10:22:03 GMT
On 02/05/18 09:31, Rémy Maucherat wrote:
> On Wed, May 2, 2018 at 5:19 AM Hugh H <xuhu_sec@outlook.com> wrote:
> 
>> Hi Mark,
>>
>> Here are the logs you requested
>>
>> client:
>> https://1drv.ms/t/s!Aii8T4l0bnqVlyAuRIjSuluBe8vy
>>
>> server:
>> https://1drv.ms/u/s!Aii8T4l0bnqVlx-TGo6I0dMXZxG1
>>
>>
>> I checked the system clock right before my testing and the server and the
>> client are synchronized.
>>
> 
> Ok, so all seems fine with the SSL handshake, reading the request data, but
> then there is some error processing the request. The processor is already
> recycled and the ERROR status leads to closing.
> 
> I have no idea what could fail or how since it's a 100% super simple
> request. Maybe enable FINE for everything and trying to see what happens
> between these two:
> 01-May-2018 15:22:25.854 FINE [https-openssl-nio2-11443-exec-5]
> org.apache.coyote.AbstractProcessorLight.process Socket:
> [org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper@ed820bc
> :org.apache.tomcat.util.net.SecureNio2Channel@2878c1ae:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
> local=/1***.***.***.*67:11443 remote=/1**.***.***.*81:24776]], Status in:
> [OPEN_READ], State out: [OPEN]
> 01-May-2018 15:22:25.854 FINE [https-openssl-nio2-11443-exec-5]
> org.apache.coyote.AbstractProtocol$ConnectionHandler.release Pushed
> Processor [org.apache.coyote.http11.Http11Processor@739e50bf]

I read those logs slightly differently. The first request appears to be
processed normally. The "State out: [OPEN]" indicates that.

The processing thread (https-openssl-nio2-11443-exec-5) completes
normally. There is no pipelined data else it would be processed on this
same thread.

The next log message is on a new thread:

01-May-2018 15:22:25.867 FINE [https-openssl-nio2-11443-exec-6]
org.apache.coyote.AbstractProtocol$ConnectionHandler.process Processing
socket
[org.apache.tomcat.util.net.SecureNio2Channel@2878c1ae:sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/1***.***.***.*67:11443 remote=/1**.***.***.*81:24776]] with
status [ERROR]

That indicates to me that at some point during the processing of the
request, an error occurred and a call was made to endpoint.processSocket
with SocketEvent.ERROR. Because we only allow a single thread to use a
socket at a time, this event was queued until the previous thread
completed. As soon as exec-5 completed, this event was processed on
exec-6 and closed the socket.

Since the client never receives the response, my guess is that there is
an I/O error on the write.

I've looked at all the places were SocketEvent.ERROR is triggered. If
you exclude Async requests, HTTP/2 and WebSocket and anything associated
with the NIO or APR connectors, the only thing left is the NIO2
completion handlers. It looks like one of the completion handlers is
failing. The problem is that we don't know why.

I think it makes sense to add some debug logging to each of the NIO2
completion handlers that logs the exception in case of a failure.

If I do this, are you able to build Tomcat trunk from source and re-test
with that?

Mark

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Mime
View raw message