0 Replies Latest reply on Dec 5, 2017 6:11 AM by Panos Konstantinidis

    write-timeout and ClosedChannelException

    Panos Konstantinidis Newbie

      Hello,

       

      we have a Wildfly installed (wildfly-10.1.0.Final) on standalone mode. We have added a write-timeout="45000" to http-listener & https-listener on production, but we noticed that we get a lot of ClosedChannelException errors:

       

      java.nio.channels.ClosedChannelException: null

      at io.undertow.conduits.WriteTimeoutStreamSinkConduit.handleWriteTimeout(WriteTimeoutStreamSinkConduit.java:106)

      at io.undertow.conduits.WriteTimeoutStreamSinkConduit.write(WriteTimeoutStreamSinkConduit.java:122)

       

      I would have expected to only see WriteTimeoutException errors, as described here (WildFly 10.0 Model Reference ), which we do, but very occasionally.

       

      By looking at the undertow code I noticed that the ClosedChannelException is thrown at the following piece of code:

       

              if (expireTimeVar != -1 && currentTime > expireTimeVar) {

                  IoUtils.safeClose(connection);

                  throw new ClosedChannelException();

              }

       

      We managed to reproduce the problem on the UAT environment, with the following settings:

       

                      <http-listener name="default" tcp-keep-alive="false" read-timeout="45000" write-timeout="10000" socket-binding="http" record-request-start-time="true" redirect-socket="https" enable-http2="true"/>

                      <https-listener name="https" tcp-keep-alive="false" read-timeout="45000" write-timeout="10000" socket-binding="https" record-request-start-time="true" security-realm="ApplicationRealm" enable-http2="true"/>

       

      I cloned the undertow code, I changed the WriteTimeoutStreamSinkConduit.java myself (I just added a few System.out statements for debugging purposes), rebuilt the undertow-core-1.4.0.Final.jar and replaced the one in the UAT with our custom version. I noticed the following

       

      [INFO ] 2017-12-05 12:48:57.240 [default task-6] [pt0_WuRKH4rsd6yPRrXen53Ee2OiPGlNed64iFrI] stdout [?:?] - Updating expire time to: currentTime: 1512470937239 + timeout: 10000

      [INFO ] 2017-12-05 12:49:11.452 [default task-4] [pt0_WuRKH4rsd6yPRrXen53Ee2OiPGlNed64iFrI] stdout [?:?] - Timeout is set to: 10000

      [INFO ] 2017-12-05 12:49:11.453 [default task-4] [pt0_WuRKH4rsd6yPRrXen53Ee2OiPGlNed64iFrI] stdout [?:?] - currentTime is: 1512470951453 and expireTime is: 1512470947239

      [INFO ] 2017-12-05 12:49:11.454 [default task-4] [pt0_WuRKH4rsd6yPRrXen53Ee2OiPGlNed64iFrI] stdout [?:?] - currentTime > expireTimeVar: true

      [ERROR] 2017-12-05 12:49:11.455 [default task-4] [pt0_WuRKH4rsd6yPRrXen53Ee2OiPGlNed64iFrI] g.c.RestExceptionHandler [RestExceptionHandler.java:24] - Exception Thrown: java.nio.channels.ClosedChannelException

       

      If you notice we are talking about two different requests (different thread name) under the same user (same session id) with 14'' delay. I *guess* this exception occurs because the same socket is reused for both requests (for both  threads) and thus the expire time applies for all requests over the same socket. But in this case I would expect a WriteTimeoutException, as explained in the docs. So my questions are:

       

      a) How exactly does the write-timeout work? I would have thought that each new request resets the timer.

      b) Why don't I get a WriteTimeoutException instead? There are days that we see hundreds of ClosedChannelException but no WriteTimeoutException.

      c) Is there any way to avoid the ClosedChannelException? None of our users has complained yet, but the stack traces clog our log files.

       

      Thank you.

       

      Panos