7 Replies Latest reply on Mar 2, 2017 6:09 AM by Balavignesh sethupathi

    Undertow doesn't process request sometimes

    Balavignesh sethupathi Newbie

      Hi,

           We are seeing this issue in undertow 1.4.8 where it fails to process a POST(HTTPS) request sent from the SOAPUI client sometimes.

      In the below screenshot you can see that the POST request has been received at undertow server at 14:16:13.015876 and we could see a tcp acknowledgement being sent immediately after that.

      As you can see the there is no further response sent and the client times out after 180 seconds and closes the connection.

      wireshark.jpg

       

      From the undertow logs it looks like the default-task that handled the previous request(14:16:13:006359) was taking some 20ms to print the request dump after the response had been sent on wire.

      The next request has been sent from the client before the previous task thread completes.

      this is shown below:

       

      Undertow logs:

      2017-01-26 14:16:13,008 TRACE [default task-124]-[io.undertow.server.HttpServerExchange] Starting to write response for HttpServerExchange{ POST /soap/ErrorHandlerServlet request {Connection=[Keep-Alive], SOAPAction=[""], Accept-Encoding=[gzip,deflate], Transfer-Encoding=[chunked], Content-Type=[text/xml;charset=UTF-8], User-Agent=[Apache-HttpClient/4.1.1 (java 1.5)], Host=[192.168.92.235:8443]} response {Expires=[0], Connection=[keep-alive], WWW-Authenticate=[Basic realm="NetworkInspectorRealm"], Cache-Control=[no-cache, no-store, must-revalidate], Pragma=[no-cache], Content-Length=[71], Date=[Thu, 26 Jan 2017 07:16:13 GMT]}}

      2017-01-26 14:16:13,026 INFO  [default task-124]-[io.undertow.request.dump]

      ----------------------------REQUEST---------------------------

                     URI=/soap/services/ApcRemotePort/9.5

      characterEncoding=null

           contentLength=-1

       

      We have added additional logs in XNIO as well and the logs show that the default task-124 resumes reading before it returns.

      XNIO logs:

       

      2017-01-26 14:16:13,008 TRACE [default I/O-12]-[org.xnio.nio.selector] Beginning select on sun.nio.ch.EPollSelectorImpl@2e90bec2 (with timeout)

      2017-01-26 14:16:13,026 TRACE [default task-124]-[org.xnio.nio] resuming sun.nio.ch.SelectionKeyImpl@1f8b66a3 on java.nio.channels.SocketChannel[connected local=/192.168.92.235:8443 remote=192.168.72.51/192.168.72.51:58756] ops 1

      2017-01-26 14:16:13,026 TRACE [default task-124]-[org.xnio.nio.selector] setOps key sun.nio.ch.SelectionKeyImpl@1f8b66a3 for java.nio.channels.SocketChannel[connected local=/192.168.92.235:8443 remote=192.168.72.51/192.168.72.51:58756] readyOps 1 interestOps 0 setOps 1

      2017-01-26 14:16:13,026 TRACE [default task-124]-[org.xnio.nio.selector] setOps normal

       

      Ideally after this point we expect the default I/O thread to select the SelectionKeyImpl@1f8b66a3 to start reading the request out from the channel, but this doesn't happen.

      The selectionkey is selected only after 180 seconds only to get cancelled.

       

      2017-01-26 14:19:13,016 TRACE [default I/O-12]-[org.xnio.nio.selector] Selected key sun.nio.ch.SelectionKeyImpl@1f8b66a3 for java.nio.channels.SocketChannel[connected local=/192.168.92.235:8443 remote=192.168.72.51/192.168.72.51:58756]

      2017-01-26 14:19:13,021 TRACE [default I/O-12]-[org.xnio.nio] suspending sun.nio.ch.SelectionKeyImpl@1f8b66a3 on java.nio.channels.SocketChannel[connected local=/192.168.92.235:8443 remote=192.168.72.51/192.168.72.51:58756] ops 1

      2017-01-26 14:19:13,021 TRACE [default I/O-12]-[org.xnio.nio.selector] clearOps key sun.nio.ch.SelectionKeyImpl@1f8b66a3 for java.nio.channels.SocketChannel[connected local=/192.168.92.235:8443 remote=192.168.72.51/192.168.72.51:58756] readyOps 1 interestOps 1 setOps 1

      2017-01-26 14:19:13,021 TRACE [default I/O-12]-[org.xnio.nio.selector] clearOps in current thread

      2017-01-26 14:19:13,022 TRACE [default I/O-12]-[org.xnio.nio] Cancelling key sun.nio.ch.SelectionKeyImpl@1f8b66a3 of java.nio.channels.SocketChannel[connected ishut local=/192.168.92.235:8443 remote=192.168.72.51/192.168.72.51:58756] (same thread)

       

      Its not clear on why the task thread that handled the previous request took around 18ms to wind up after it sent a response, also strange is the selector not selecting the SelectionKeyImpl@1f8b66a3 to process the next request.

       

      The default task thread usually takes between 1 to 2 ms to send the response back when the issue is not seen.

      Any help on tackling the issue is appreciated.

       

      Thanks,

      Vignesh

        • 1. Re: Undertow doesn't process request sometimes
          Balavignesh sethupathi Newbie

          some more info with additional logs enabled in JsseSslConduitEngineEngine.java.

          We have changed the engineUnwrap() method to log the stack info:

           

          log.logf(FQCN, Logger.Level.TRACE, null, "Unwrapping %s into %s", buffer, unwrappedBuffer);

                  if (Thread.currentThread().getName().startsWith("default task-")) {

                      log.logf(FQCN, Logger.Level.TRACE, new RuntimeException(), "Thread name %s, id %s", Thread.currentThread().getName(), Thread.currentThread().getId());

                  }

           

          And when the issue is seen the SevletBlockingHttpExchange.java close() method seems drain the requestChannel, thereby loosing the next POST request.

           

          2017-01-28 08:32:01,189 TRACE [default task-4]-[org.xnio.conduits] Thread name default task-4, id 1183: java.lang.RuntimeException

              at org.xnio.ssl.JsseSslConduitEngine.engineUnwrap(JsseSslConduitEngine.java:689)

              at org.xnio.ssl.JsseSslConduitEngine.unwrap(JsseSslConduitEngine.java:620)

              at org.xnio.ssl.JsseSslConduitEngine.unwrap(JsseSslConduitEngine.java:574)

              at org.xnio.ssl.JsseSslStreamSourceConduit.read(JsseSslStreamSourceConduit.java:91)

              at org.xnio.conduits.AbstractStreamSourceConduit.read(AbstractStreamSourceConduit.java:51)

              at io.undertow.conduits.ReadDataStreamSourceConduit.read(ReadDataStreamSourceConduit.java:67)

              at io.undertow.conduits.ChunkedStreamSourceConduit.read(ChunkedStreamSourceConduit.java:176)

              at org.xnio.conduits.ConduitStreamSourceChannel.read(ConduitStreamSourceChannel.java:127)

              at io.undertow.channels.DetachableStreamSourceChannel.read(DetachableStreamSourceChannel.java:209)

              at io.undertow.server.HttpServerExchange$ReadDispatchChannel.read(HttpServerExchange.java:2099)

              at org.xnio.channels.Channels.readBlocking(Channels.java:294)

              at io.undertow.servlet.spec.ServletInputStreamImpl.readIntoBuffer(ServletInputStreamImpl.java:170)

              at io.undertow.servlet.spec.ServletInputStreamImpl.close(ServletInputStreamImpl.java:246)

              at io.undertow.servlet.spec.HttpServletRequestImpl.closeAndDrainRequest(HttpServletRequestImpl.java:600)

              at io.undertow.servlet.core.ServletBlockingHttpExchange.close(ServletBlockingHttpExchange.java:87)

              at io.undertow.server.HttpServerExchange.endExchange(HttpServerExchange.java:1446)

              at io.undertow.server.Connectors.executeRootHandler(Connectors.java:222)

              at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:761)

              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

              at java.lang.Thread.run(Thread.java:745)

           

          The above stack trace is printed three or more times when the issue happens.

          Seems to some kind of Race condition.

          • 2. Re: Undertow doesn't process request sometimes
            Balavignesh sethupathi Newbie

            Is there a possibility of GC happening before the io.undertow.servlet.spec.HttpServletRequestImpl#closeAndDrainRequest() being invoked and soon after the VM wakes up and thus finding the second request already in the request channel

            • 3. Re: Undertow doesn't process request sometimes
              Balavignesh sethupathi Newbie

              We have found a way to easily reproduce this issue by adding 10ms sleep in the ServletInitialHandler.java under handleFirstRequest method, we have done this change in undertow 1.1.8 (also tried by upgrading to underttow-1.4.8 in wildfly 8.2.1)

               

              } finally {

                             logger.info("Sleep 10 ms");

                              Thread.sleep(10);

                              servletRequestContext.setRunningInsideHandler(false);

                              listeners.requestDestroyed(request);

                          }

               

              In the attach you can find the

              1) testSuite.tar.gz - soapui testsuite xml and the HelloWorld war that was deployed.

              2) undertow-servlet-1.1.8.Final.jar.zip - Servlet module with 10ms sleep added in ServletInitialHandler.java

               

              This issue is getting reproduced only in HTTPS mode.

               

              Thanks,

              Vignesh

              • 4. Re: Undertow doesn't process request sometimes
                Stuart Douglas Master

                I don't seem to be able to run the soapUI project.

                 

                io.undertow.conduits.ChunkedStreamSourceConduit is the class that is responsible for parsing chunked input, it sounds like in this case there may be a problem with how the chunking is being processed (or possibly with the chunked stream itself). Would it be possible to see exactly what is being sent over the wire?

                • 5. Re: Undertow doesn't process request sometimes
                  Balavignesh sethupathi Newbie

                  Hi Stuart,

                       Thanks for the reply.

                   

                       I have reproduced the issue and attached the zip file containing the tcpdump, the private key and the pre-master secret log of SOAPUI.

                  The timezone is in IST.

                   

                  In the tcpdump, the last POST request arrived at the server at 16:43:50.968384 and the ack has been sent back immediately.

                  A one minute timeout has been set in SOAPUI, so the SOAP UI has closed the tcp connection at 16:44:50.970269

                   

                  I will also check the io.undertow.conduits.ChunkedStreamSourceConduit class to see if i can add some logs there.

                  • 6. Re: Undertow doesn't process request sometimes
                    Balavignesh sethupathi Newbie

                    Hi Stuart,

                         Could you let us know if you see any anomalies in the packet dump. Any further clue will help us.

                     

                    Thanks,
                    Vignesh

                    • 7. Re: Undertow doesn't process request sometimes
                      Balavignesh sethupathi Newbie

                      Could you please let us know the issue you are facing while loading the SOAPUI project. Because this is a sure shot way of reproducing the issue locally.