10 Replies Latest reply on Oct 10, 2014 4:40 PM by gyang2

    What could be the reason of "UT000004: getResponseChannel() has already been called"?

    gyang2

      We have a Wildfly 8.0 application, using Restlet RESTful framework. Some client's POST requests caused server down time. We kept receiving following error messages in log file and finally Wildfly undeployed the WAR. Unfortunately we don't know client's payloads and the reason. Can somebody give us a hint?

       

      2014-06-28 20:25:12,070 ERROR [io.undertow.request] (default task-173) Blocking request failed HttpServerExchange{ POST /postAndSend}: java.lang.IllegalStateException: UT000004: getResponseChannel() has already been called

              at io.undertow.server.protocol.http.HttpContinue.createResponseSender(HttpContinue.java:78)

              at io.undertow.server.handlers.HttpContinueReadHandler$ContinueConduit.read(HttpContinueReadHandler.java:104)

              at org.xnio.conduits.ConduitStreamSourceChannel.read(ConduitStreamSourceChannel.java:127) [xnio-api-3.2.0.Final.jar:3.2.0.Final]

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

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

              at org.xnio.channels.Channels.readBlocking(Channels.java:294) [xnio-api-3.2.0.Final.jar:3.2.0.Final]

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

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

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

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

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

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

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

              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_55]

              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_55]

              at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_55]

       

      2014-06-28 20:25:12,075 ERROR [stderr] (default task-173) Exception in thread "default task-173" java.lang.IllegalStateException: UT000004: getResponseChannel() has already been called

      2014-06-28 20:25:12,076 ERROR [stderr] (default task-173)       at io.undertow.server.protocol.http.HttpContinue.createResponseSender(HttpContinue.java:78)

      2014-06-28 20:25:12,076 ERROR [stderr] (default task-173)       at io.undertow.server.handlers.HttpContinueReadHandler$ContinueConduit.read(HttpContinueReadHandler.java:104)

      2014-06-28 20:25:12,076 ERROR [stderr] (default task-173)       at org.xnio.conduits.AbstractStreamSourceConduit.read(AbstractStreamSourceConduit.java:51)

      2014-06-28 20:25:12,076 ERROR [stderr] (default task-173)       at io.undertow.server.handlers.HttpContinueReadHandler$ContinueConduit.read(HttpContinueReadHandler.java:112)

      2014-06-28 20:25:12,076 ERROR [stderr] (default task-173)       at org.xnio.conduits.ConduitStreamSourceChannel.read(ConduitStreamSourceChannel.java:127)

      2014-06-28 20:25:12,077 ERROR [stderr] (default task-173)       at io.undertow.channels.DetachableStreamSourceChannel.read(DetachableStreamSourceChannel.java:181)

      2014-06-28 20:25:12,077 ERROR [stderr] (default task-173)       at io.undertow.server.HttpServerExchange$ReadDispatchChannel.read(HttpServerExchange.java:1897)

      2014-06-28 20:25:12,077 ERROR [stderr] (default task-173)       at org.xnio.channels.Channels.readBlocking(Channels.java:294)

      2014-06-28 20:25:12,077 ERROR [stderr] (default task-173)       at io.undertow.servlet.spec.ServletInputStreamImpl.readIntoBuffer(ServletInputStreamImpl.java:138)

      2014-06-28 20:25:12,078 ERROR [stderr] (default task-173)       at io.undertow.servlet.spec.ServletInputStreamImpl.close(ServletInputStreamImpl.java:218)

      2014-06-28 20:25:12,078 ERROR [stderr] (default task-173)       at io.undertow.servlet.spec.HttpServletRequestImpl.closeAndDrainRequest(HttpServletRequestImpl.java:589)

      2014-06-28 20:25:12,078 ERROR [stderr] (default task-173)       at io.undertow.servlet.core.ServletBlockingHttpExchange.close(ServletBlockingHttpExchange.java:69)

      2014-06-28 20:25:12,078 ERROR [stderr] (default task-173)       at io.undertow.server.HttpServerExchange.endExchange(HttpServerExchange.java:1363)

      2014-06-28 20:25:12,078 ERROR [stderr] (default task-173)       at io.undertow.server.Connectors.executeRootHandler(Connectors.java:191)

      2014-06-28 20:25:12,079 ERROR [stderr] (default task-173)       at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:687)

      2014-06-28 20:25:12,079 ERROR [stderr] (default task-173)       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

      2014-06-28 20:25:12,079 ERROR [stderr] (default task-173)       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

      2014-06-28 20:25:12,079 ERROR [stderr] (default task-173)       at java.lang.Thread.run(Thread.java:745)

       

      Thanks

       

      Gary

        • 1. Re: What could be the reason of "UT000004: getResponseChannel() has already been called"?
          gyang2

          From the code seems the HTTP Response is already sent

           

          public boolean isResponseStarted() {
          return allAreSet(state, FLAG_RESPONSE_SENT);
          }

           

          In what conditions that response is already sent but undertow wants to send  again?

           

          This function is called by

          /**
          * Creates a response sender that can be used to send a HTTP 100-continue response.
          *
          * @param exchange The exchange
          * @return The response sender
          */
          public static ContinueResponseSender createResponseSender(final HttpServerExchange exchange) {
              if (!exchange.isResponseChannelAvailable()) {
                  throw UndertowMessages.MESSAGES.responseChannelAlreadyProvided();
             

          }

           

          HTTP 100-continue response. Is it a response of Keep-Alive requests?

          • 2. Re: What could be the reason of "UT000004: getResponseChannel() has already been called"?
            ctomc

            Can you reproduce this also on 8.1?

            • 3. Re: What could be the reason of "UT000004: getResponseChannel() has already been called"?
              gyang2

              Thank you, Tomaz

               

              We captured this on our production servers.Our plan was to upgrade JBoss 4 to Wildfly. New we rolled back to JBoss 4. As we are serving millions RESTful requests every day, we don't know what requests caused the issue. We are trying to reproduce by ourselves.

               

              Before the problem is solved, we can't put Wildfly 8.1 online:-(

               

              I guess we just ran into a Wildfly 8.0 issue, that a client sends "Expect : 100-continue" requests in a strange way that Undertow fails to process

              • 4. Re: What could be the reason of "UT000004: getResponseChannel() has already been called"?
                gyang2

                I just reproduced it with Apache HTTP client, here is the code:

                 

                  HttpPost request = new HttpPost(postAndSend);

                  StringEntity input = new StringEntity (payLoad);

                  input.setContentType("text/xml");

                  request.setHeader("Expect", "100-continue");

                  request.setEntity(input);

                  request.setHeader("Connection", "keep-alive");

                  HttpResponse response = httpclient.execute(request);

                  response = httpclient.execute(request);

                  response = httpclient.execute(request);

                  response = httpclient.execute(request);

                 

                 

                Server side log:

                2014-06-29 11:12:14,721 ERROR [io.undertow.request] (default task-26) Blocking request failed HttpServerExchange{ POST /enterprise/composite/postAndSend}: java.lang.IllegalStateException: UT000004: getResponseChannel() has already been called

                        at io.undertow.server.protocol.http.HttpContinue.createResponseSender(HttpContinue.java:78)

                        at io.undertow.server.handlers.HttpContinueReadHandler$ContinueConduit.read(HttpContinueReadHandler.java:104)

                        at org.xnio.conduits.ConduitStreamSourceChannel.read(ConduitStreamSourceChannel.java:127) [xnio-api-3.2.0.Final.jar:3.2.0.Final]

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

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

                        at org.xnio.channels.Channels.readBlocking(Channels.java:294) [xnio-api-3.2.0.Final.jar:3.2.0.Final]

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

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

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

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

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

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

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

                        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_55]

                        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_55]

                        at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_55]

                 

                If Wildfly ignores the issue, we are fine. We can claim we don't support this situation anymore. But the problem is, after sending hundreds requests like this, Wildfly eventually undeployed our WARs. Now I'm 99.995% sure this is a Wildfly bug.

                 

                Will try Wildfly 8.1

                • 5. Re: What could be the reason of "UT000004: getResponseChannel() has already been called"?
                  gyang2

                  Wildfly 8.1 has a same issue:-(

                   

                  15:29:16,634 INFO  [org.jboss.as] (MSC service thread 1-2) JBAS015899: WildFly 8.1.0.Final "Kenny” starting

                  15:30:51,351 ERROR [io.undertow.request] (default task-12) Blocking request failed HttpServerExchange{ POST /enterprise/composite/subscribeAndSend}: java.lang.IllegalStateException: UT000004: getResponseChannel() has already been called

                      at io.undertow.server.protocol.http.HttpContinue.createResponseSender(HttpContinue.java:78)

                      at io.undertow.server.handlers.HttpContinueReadHandler$ContinueConduit.read(HttpContinueReadHandler.java:104)

                      at org.xnio.conduits.ConduitStreamSourceChannel.read(ConduitStreamSourceChannel.java:127) [xnio-api-3.2.2.Final.jar:3.2.2.Final]

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

                   

                  BTW, AWS' load balancer doesn't allow a such request, 100-continue requests are sent together in a keep-alive connection. The client side receives "parameter error". I used SSH tunneling to reproduce on my AWS instance.

                  • 6. Re: What could be the reason of "UT000004: getResponseChannel() has already been called"?
                    gyang2

                    Our workaround is on load balancer, we drop "Expect" header.

                    • 7. Re: What could be the reason of "UT000004: getResponseChannel() has already been called"?
                      x046866x

                      Folks,

                       

                      .NET solicitors will be sending the "Expect: 100-continue" by default.  The way to turn that off is:

                        System.Net.ServicePointManager.Expect100Continue = false;

                       

                       

                      or, for an individual request:

                      var req = (HttpWebRequest) WebRequest.Create(...);

                      req.ServicePoint.Expect100Continue = false;

                       

                       

                      This workaround works for us only because we know the client (and there is only one).  If you can't and have a public facing service you may have some challenges.

                      • 8. Re: What could be the reason of "UT000004: getResponseChannel() has already been called"?
                        ctomc

                        Russell,

                        any chance you can try with 9.0.0.Alpha1 as it has newer undertow in it that should contain fix for your problem.

                         

                        Or build 8.x (has same undertow) branch which will soon become 8.2.0.Final, we would like to have it fixed in 8.2 but cannot be sure without testing.

                        • 9. Re: What could be the reason of "UT000004: getResponseChannel() has already been called"?
                          x046866x

                          Tomaz,

                           

                          I'm not sure I'll get an opportunity, but will try.  Apparently there is a code sample that will duplicate it but I have not tried it:

                          HttpPost request = new HttpPost(postAndSend);

                            StringEntity input = new StringEntity (payLoad);

                            input.setContentType("text/xml");

                            request.setHeader("Expect", "100-continue");

                            request.setEntity(input);

                            request.setHeader("Connection", "keep-alive");

                            HttpResponse response = httpclient.execute(request);

                            response = httpclient.execute(request);

                            response = httpclient.execute(request);

                            response = httpclient.execute(request);

                          • 10. Re: What could be the reason of "UT000004: getResponseChannel() has already been called"?
                            gyang2

                            It is https://issues.jboss.org/browse/WFLY-3560

                             

                            I tried 9.0.0alpha1. The problem was not solved.

                             

                            According to the ticket it has been fixed in 9.0.0beta1.

                             

                            You don't need to use Java/Apache client to test. A simple curl command line could reproduce:

                            curl -X POST -H Content-Type:application/json -H Expect:100-continue -d '"name":"joe"' http://localhost:8080/