The last zero-chunk in Transfer-encoding: chunked response can be missing when Undertow write-timeout is reached

Solution Verified - Updated

Environment

  • Red Hat JBoss Enterprise Application Platform (EAP)
    • 7.x

Issue

  • HTTP Long polling is implemented with asynchronous servlet API, the last chunk 0\r\n\r\n will be missing when the polling interval is longer than Undertow write-timeout.
  • Getting a net::ERR_INCOMPLETE_CHUNKED_ENCODING error in the browser console if the browser is chrome.

Resolution

This is a known issue as reported This content is not included.JBEAP-23722, fixed in JBoss EAP 7.4.12+. As a workaround, there are two options:

  • Set write-timeout longer than long-polling interval, or unset write-timeout in http-listener. write-timeout is not set by default.
  • Comment out calling flush() from the servlet. If response type is Content-length: <byte>, this issue does not occur.

Root Cause

In the current Undertow implementation of write-timeout, when requests that re-use a keep-alive connection, write-timeout set during the previous request processing is taken over to the next request. As a result, the last zero chunk truncated response is returned if meet the following conditions are true:

  • The request re-use a keep-alive connection.
  • The request takes longer than write-timeout like long-polling processing by AsyncServlet.
  • Transfer-Encoding: chunked is applied to the response by calling flush() in the servlet.

Diagnostic Steps

Attach the following Byteman rule:

RULE trace createLastChunk
CLASS io.undertow.conduits.ChunkedStreamSinkConduit
METHOD createLastChunk(boolean)
AT ENTRY
IF true
DO traceStack("### Hit BYTEMAN - createLastChunk $1 = " + $1 + " ");
ENDRULE

RULE trace closing channel
CLASS sun.nio.ch.SocketDispatcher
METHOD close(java.io.FileDescriptor)
AT ENTRY
IF true
DO traceStack("### SocketChannel is closing now ");
ENDRULE

RULE trace updating expireTime in handleWriteTimeout
CLASS io.undertow.conduits.WriteTimeoutStreamSinkConduit
METHOD handleWriteTimeout(long)
AFTER WRITE expireTime
IF true
DO traceStack("### Hit BYTEMAN updated expireTime = " + $0.expireTime + " ");
ENDRULE

RULE trace updating expireTime in handleResumeTimeout
CLASS io.undertow.conduits.WriteTimeoutStreamSinkConduit
METHOD handleResumeTimeout()
AFTER WRITE expireTime
IF true
DO traceStack("### Hit BYTEMAN updated expireTime = " + $0.expireTime + " ");
ENDRULE

Add the following java options in JBOSS_HOME/bin/standalone.conf to attach byteman:

BYTEMAN_HOME=/<path-to-byteman>/byteman-download-4.0.16    <<<===
if [ "x$JAVA_OPTS" = "x" ]; then
   JAVA_OPTS="-Xms1303m -Xmx1303m -XX:MetaspaceSize=96M -XX:MaxMetaspaceSize=256m -Djava.net.preferIPv4Stack=true"
   JAVA_OPTS="$JAVA_OPTS -Djboss.modules.system.pkgs=$JBOSS_MODULES_SYSTEM_PKGS -Djava.awt.headless=true"
   JAVA_OPTS="$JAVA_OPTS -javaagent:${BYTEMAN_HOME}/lib/byteman.jar=script:${BYTEMAN_HOME}/scripts/TraceLastChunk.btm,boot:${BYTEMAN_HOME}/lib/byteman.jar"    <<<===
else
   echo "JAVA_OPTS already set in environment; overriding default settings with values: $JAVA_OPTS"
fi

The following log is an example of JBoss EAP 7.4.5 with OpenJDK8 if it corresponds to this issue. If the socket is closed on the stack above from WriteTimeoutStreamSinkConduit and createLastChunk is called afterward, the last zero chunk is missing due to write-timeout:

18:54:06,753 INFO  [stdout] (default task-1) ### SocketChannel is closing now sun.nio.ch.SocketDispatcher.close(SocketDispatcher.java:-1)
18:54:06,753 INFO  [stdout] (default task-1) sun.nio.ch.SocketChannelImpl.kill(SocketChannelImpl.java:878)
18:54:06,753 INFO  [stdout] (default task-1) sun.nio.ch.SocketChannelImpl.implCloseSelectableChannel(SocketChannelImpl.java:860)
18:54:06,754 INFO  [stdout] (default task-1) java.nio.channels.spi.AbstractSelectableChannel.implCloseChannel(AbstractSelectableChannel.java:241)
18:54:06,754 INFO  [stdout] (default task-1) java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:115)
18:54:06,754 INFO  [stdout] (default task-1) org.xnio.nio.NioSocketStreamConnection.closeAction(NioSocketStreamConnection.java:135)
18:54:06,754 INFO  [stdout] (default task-1) org.xnio.Connection.close(Connection.java:132)
18:54:06,754 INFO  [stdout] (default task-1) org.xnio.IoUtils.safeClose(IoUtils.java:152)
18:54:06,754 INFO  [stdout] (default task-1) io.undertow.conduits.WriteTimeoutStreamSinkConduit.handleWriteTimeout(WriteTimeoutStreamSinkConduit.java:101)
18:54:06,754 INFO  [stdout] (default task-1) io.undertow.conduits.WriteTimeoutStreamSinkConduit.write(WriteTimeoutStreamSinkConduit.java:117)
...
18:54:06,755 INFO  [stdout] (default task-1) io.undertow.servlet.spec.ServletPrintWriterDelegate.flush(ServletPrintWriterDelegate.java:76)
18:54:06,755 INFO  [stdout] (default task-1) test.LongPollingServlet$MyListener.onTimeout(LongPollingServlet.java:27)
...
18:54:06,758 INFO  [stdout] (default task-1) ### Hit BYTEMAN - createLastChunk $1 = false io.undertow.conduits.ChunkedStreamSinkConduit.createLastChunk(ChunkedStreamSinkConduit.java:-1)
18:54:06,758 INFO  [stdout] (default task-1) io.undertow.conduits.ChunkedStreamSinkConduit.terminateWrites(ChunkedStreamSinkConduit.java:318)
18:54:06,758 INFO  [stdout] (default task-1) org.xnio.conduits.ConduitStreamSinkChannel.shutdownWrites(ConduitStreamSinkChannel.java:178)
18:54:06,758 INFO  [stdout] (default task-1) org.xnio.StreamConnection.notifyWriteClosed(StreamConnection.java:95)
18:54:06,758 INFO  [stdout] (default task-1) org.xnio.nio.NioSocketStreamConnection.notifyWriteClosed(NioSocketStreamConnection.java:145)
18:54:06,758 INFO  [stdout] (default task-1) org.xnio.Connection.close(Connection.java:135)
18:54:06,758 INFO  [stdout] (default task-1) org.xnio.IoUtils.safeClose(IoUtils.java:152)
18:54:06,758 INFO  [stdout] (default task-1) io.undertow.conduits.WriteTimeoutStreamSinkConduit.handleWriteTimeout(WriteTimeoutStreamSinkConduit.java:101)
18:54:06,758 INFO  [stdout] (default task-1) io.undertow.conduits.WriteTimeoutStreamSinkConduit.write(WriteTimeoutStreamSinkConduit.java:117)
...
SBR
Product(s)
Components
Category
Tags

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.