On Wed, May 2, 2018 at 12:22 PM Mark Thomas <ma...@apache.org> wrote:
> On 02/05/18 09:31, Rémy Maucherat wrote: > > On Wed, May 2, 2018 at 5:19 AM Hugh H <xuhu_...@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? > If it is only blocking writes causing an error, then it's not using any completion handlers, it's the future write in SecureNio2Channel.FutureWrite. Ok with adding debug logging for the "fails", it doesn't hurt obviously. Rémy
