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