Hystrix: Race condition in HystrixSampleSseServlet with response writes

Created on 17 Jan 2018  路  6Comments  路  Source: Netflix/Hystrix

Context

We run some services that use Hystrix and we also have a Turbine instance to monitor these services. We've been getting some intermittent ArrayIndexOutOfBoundsExceptions thrown from our Hystrix services' embedded Tomcat which I believe is due to HystrixSampleSseServlet's writes to the response not being thread-safe (since the write socket buffer is not thread-safe).

Suggested Fix

We can synchronize on the writes to the response during the lifetime of handleRequest to avoid concurrent writes of pings from the Tomcat thread and samples from the Observable thread.

I have opened a PR here: https://github.com/Netflix/Hystrix/pull/1757 (successfully merged).

Tracking the issue down

JDK Version: jdk1.8.0_144.jdk

Dependencies for Application Service with Hystrix and embedded tomcat:

com.netflix.hystrix:hystrix-javanica:1.5.12
com.netflix.hystrix:hystrix-metrics-event-stream:1.5.12
# also should occur in 1.5.13
org.apache.tomcat.embed:tomcat-embed-core:8.5.16

Dependencies: Turbine Instance

com.netflix.turbine:turbine-core:1.0.0

In production, we have seen intermittent occurrences of ArrayIndexOutOfBoundsException when Tomcat tries to end a request to the /hystrix.stream endpoint.

The server logs are as follows:

DEBUG [2017-11-03 19:09:46,157] [http-nio-51035-exec-10] [] [] o.a.coyote.http11.Http11InputBuffer: []/[] [] [] Received [GET /hystrix.stream HTTP/1.1
Host: 127.0.0.1:51035
Connection: Keep-Alive
User-Agent: Apache-HttpClient/4.5 (Java/1.8.0_92)

]
ERROR [2017-11-03 20:03:03,158] [http-nio-51035-exec-10] [] [] o.a.coyote.http11.Http11Processor: []/[] [] [] Error processing request
java.lang.ArrayIndexOutOfBoundsException: null
    at java.lang.System.arraycopy(Native Method)
    at java.nio.HeapByteBuffer.compact(HeapByteBuffer.java:228)
    at org.apache.tomcat.util.net.SocketBufferHandler.setWriteBufferConfiguredForWrite(SocketBufferHandler.java:109)
    at org.apache.tomcat.util.net.SocketBufferHandler.configureWriteBufferForWrite(SocketBufferHandler.java:91)
    at org.apache.tomcat.util.net.SocketWrapperBase.writeBlocking(SocketWrapperBase.java:447)
    at org.apache.tomcat.util.net.SocketWrapperBase.write(SocketWrapperBase.java:388)
    at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.doWrite(Http11OutputBuffer.java:644)
    at org.apache.coyote.http11.filters.ChunkedOutputFilter.doWrite(ChunkedOutputFilter.java:121)
    at org.apache.coyote.http11.Http11OutputBuffer.doWrite(Http11OutputBuffer.java:235)
    at org.apache.coyote.Response.doWrite(Response.java:541)
    at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:351)
    at org.apache.catalina.connector.OutputBuffer.flushByteBuffer(OutputBuffer.java:815)
    at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:310)
    at org.apache.catalina.connector.OutputBuffer.close(OutputBuffer.java:263)
    at org.apache.catalina.connector.Response.finishResponse(Response.java:484)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:373)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:799)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1455)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
ERROR [2017-11-03 20:03:03,158] [http-nio-51035-exec-10] [] [] o.a.coyote.http11.Http11Processor: []/[] [] [] Error finishing response
java.lang.ArrayIndexOutOfBoundsException: null
    at java.lang.System.arraycopy(Native Method)
    at java.nio.HeapByteBuffer.compact(HeapByteBuffer.java:228)
    at org.apache.tomcat.util.net.SocketBufferHandler.setWriteBufferConfiguredForWrite(SocketBufferHandler.java:109)
    at org.apache.tomcat.util.net.SocketBufferHandler.configureWriteBufferForWrite(SocketBufferHandler.java:91)
    at org.apache.tomcat.util.net.SocketWrapperBase.writeBlocking(SocketWrapperBase.java:447)
    at org.apache.tomcat.util.net.SocketWrapperBase.write(SocketWrapperBase.java:388)
    at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.doWrite(Http11OutputBuffer.java:644)
    at org.apache.coyote.http11.filters.ChunkedOutputFilter.end(ChunkedOutputFilter.java:184)
    at org.apache.coyote.http11.Http11OutputBuffer.finishResponse(Http11OutputBuffer.java:327)
    at org.apache.coyote.http11.Http11Processor.endRequest(Http11Processor.java:1475)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:839)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1455)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
DEBUG [2017-11-03 20:03:03,158] [http-nio-51035-exec-10] [] [] o.a.coyote.http11.Http11Processor: []/[] [] [] Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@46f9cc71:org.apache.tomcat.util.net.NioChannel@4169106c:java.nio.channels.SocketChannel[connected local=/127.0.0.1:51035 remote=/10.1.1.100:33224]], Status in: [OPEN_READ], State out: [CLOSED]

From our Turbine server's end, I recompiled the turbine-core JAR to include logging client failures
by changing InstanceMonitor.java:483:

// originally:
// logger.info("Got ioe for host: " + this.getName())
logger.info("Got ioe for host: " + this.getName(), ioe);

Over the course of about 18 hours, turbine's InstanceMonitor gets about 1000 IOExceptions. 93% of them are SocketTimeoutExceptions due to read timeouts. The remaining 7% of exceptions are as follows:

org.apache.http.ConnectionClosedException: Premature end of chunk coded message body: closing chunk expected
org.apache.http.MalformedChunkCodingException: Bad chunk header:
org.apache.http.MalformedChunkCodingException: Unexpected content at the end of chunk

The org.apache.http.MalformedChunkCodingException: Bad chunk header: occurs about 48 times, with the response containing partial pings and hystrix samples mixed together:

org.apache.http.MalformedChunkCodingException: Bad chunk header: esFromCache":0,"rollingCountSemaphoreRejected":0,"rollingCountShortCircuited":0,"rollingCountSuccess":0,"rollingCountThreadPoolRejected":0,"rollingCountTimeout":0,"currentConcurrentExecutionCount":0,"rollingMaxConcurrentExecutionCount":0,"latencyExecute_mean":0,"latencyExecute":{"0":0,"25":0,"50":0,"75":0,"90":0,"95":0,"99":0,"99.5":0,"100":0},"latencyTotal_mean":0,"latencyTotal":{"0":0,"25":0,"50":0,"75":0,"90":0,"95":0,"99":0,"99.5":0,"100":0},"propertyValue_circuitBreakerRequestVolumeThreshold":20,"propertyValue_circuitBreakerSleepWindowInMilliseconds":5000,"propertyValue_circuitBreakerErrorThresholdPercentage":50,"propertyValue_circuitBreakerForceOpen":false,"propertyValue_circuitBreakerForceClosed":false,"propertyValue_circuitBreakerEnabled":true,"propertyValue_executionIsolationStrategy":"THREAD","propertyValue_executionIsolationThreadTimeoutInMilliseconds":1000,"propertyValue_executionTimeoutInMilliseconds":1000,"propertyValue_executionIsolationThreadInterruptOnTimeout":true,"propertyValue_executionIsolationThreadPoolKeyOverride":null,"propertyValue_executionIsolationSemaphoreMaxConcurrentRequests":10,"propertyValue_fallbackIsolationSemaphoreMaxConcurrentRequests":10,"propertyValue_metricsRollingStatisticalWindowInMilliseconds":10000,"propertyValue_requestCacheEnabled":true,"propertyValue_requestLogEnabled":true,"reportingHosts":1,"threadPool":"IRestClient"}
org.apache.http.MalformedChunkCodingException: Bad chunk header: type":"H
org.apache.http.MalformedChunkCodingException: Bad chunk header: endata: {"type":"HystrixThreadPool","name":"LRestClient","currentTime":1515775497197,"curping:

Out of the 27 ConnectionClosedExceptions that occurred, 4 of them were correlated with an
ArrayIndexOutOfBoundsException on the Tomcat server.

Back on the Tomcat server, Http11Processor.endRequest() will only get called if HystrixSampleSseServlet.handleRequest()
has finished. This will occur when:
1) The client disconnects.
2) Server encounters issue writing to response, HystrixSampleSseServlet's moreDataWillBeSent is set to false.

Note that printWriter.write() eventually writes into the Tomcat socket's writeBuffer (SocketBufferHandler's writeBuffer, a HeapByteBuffer).

When concurrent writes occur, the internal fields of the Tomcat write socket buffer can get clobbered due to a race condition. The socket buffer is not thread safe, so when two concurrent writes to HeapByteBuffer's using put() occur, the internal position field can exceed the limit of the buffer and cause an ArrayIndexOutOfBoundsException.

If there's only 1 thread acting on the HeapByteBuffer, the put() and get() methods throw a BufferOverflowException and prevent the position field from accessing a memory location outside of the buffer's byte array bounds.

In the HystrixSampleSseServlet, any exceptions (including ArrayIndexOutOfBoundsExceptions from writing) are swallowed by the printWriter.write() and the method exits. However, the write socket buffer's internal state is still messed up and Tomcat's Response.finishResponse() ends up getting an ArrayIndexOutOfBoundsException when it eventually tries to write to the socket. The exception reoccurs when compact() is called in the first mentioned stack trace above.

I've attached a test case which, when run enough times or long enough, produces an ArrayIndexOutOfBoundsException on a HeapByteBuffer:

package com.test.turbine;

import org.junit.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.nio.ByteBuffer;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;

public class HeapByteBufferTest {

    private static final Logger logger = LoggerFactory.getLogger(HeapByteBufferTest.class);

    @Test
    public void whenThreadsSharing_thenThrowsAob() throws Exception {
        ByteBuffer hb = ByteBuffer.allocate(1);
        ExecutorService executorService = Executors.newFixedThreadPool(2);

        while (true) {
            CountDownLatch contest = new CountDownLatch(1);

            /*
                From java.nio.ByteBuffer

                final int nextPutIndex() {                          // package-private
                    if (position >= limit)
                        throw new BufferOverflowException();
                    // this is where the race condition occurs, if:
                    // t1 returns 0
                    // t2 also returns 0
                    // t1 increments position (position = 1)
                    // t2 increments position (position = 2)
                    // call to compact() will now fail
                    return position++;
                }
             */

            Waiter writer1 = new Waiter(contest) {
                @Override
                public void run() {
                    try {
                        this.latch.await();
                        hb.put((byte)0x1);
                    } catch (Exception e) {
                        if (e instanceof ArrayIndexOutOfBoundsException) {
                            logger.info("", e);
                        }
                        throw new RuntimeException("Writer 1 failed", e);
                    }
                }
            };

            Waiter writer2 = new Waiter(contest) {
                @Override
                public void run() {
                    try {
                        this.latch.await();
                        hb.put((byte)0x1);
                    } catch (Exception e) {
                        if (e instanceof ArrayIndexOutOfBoundsException) {
                            logger.info("", e);
                        }
                        throw new RuntimeException("Writer 2 failed", e);
                    }

                    if (hb.position() > hb.capacity()) {
                        logger.info("Position has exceeded capacity");
                        hb.compact();
                    }
                }
            };

            Future<?> result1 = executorService.submit(writer1);
            Future<?> result2 = executorService.submit(writer2);
            contest.countDown();
            try {
                result2.get();
            } catch (Exception e) {
                if (e instanceof ExecutionException) {
                    Throwable cause1 = e.getCause();
                    if (cause1 instanceof ArrayIndexOutOfBoundsException) {
                        logger.info("Compact " + cause1.toString());
                        throw (ArrayIndexOutOfBoundsException) cause1;
                    } else {
                        Throwable cause2 = cause1.getCause();
                        if (cause2 instanceof ArrayIndexOutOfBoundsException) {
                            logger.info("Array index but not from compact" + cause2.toString());
                        }
                    }
                }
            }

            try {
                result1.get();
            } catch (Exception e) {
                if (e instanceof ExecutionException) {
                    // runtime exception
                    Throwable cause1 = e.getCause();
                    Throwable cause2 = cause1.getCause();
                    if (cause2 instanceof ArrayIndexOutOfBoundsException) {
                        logger.info("[WRITER 1] ArrayIndexOutOfBoundsException" + cause2.toString(), cause2);
                    }
                }
            }

            hb.clear();
        }
    }

    private static abstract class Waiter implements Runnable {

        protected CountDownLatch latch;

        public Waiter(CountDownLatch latch) {
            this.latch = latch;
        }

        public abstract void run();
    }

}

Which, run enough times (haha, could use some help here) eventually outputs this:

Connected to the target VM, address: '127.0.0.1:54130', transport: 'socket'
16:00:09.509 [pool-1-thread-2] INFO com.test.turbine.HeapByteBufferTest - Position has exceeded capacity
16:00:09.511 [pool-1-thread-1] INFO com.test.turbine.HeapByteBufferTest - 
java.lang.ArrayIndexOutOfBoundsException: 1
    at java.nio.HeapByteBuffer.put(HeapByteBuffer.java:169)
    at com.test.turbine.HeapByteBufferTest$1.run(HeapByteBufferTest.java:47)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
16:00:09.513 [main] INFO com.test.turbine.HeapByteBufferTest - Compact java.lang.ArrayIndexOutOfBoundsException

java.lang.ArrayIndexOutOfBoundsException
    at java.lang.System.arraycopy(Native Method)
    at java.nio.HeapByteBuffer.compact(HeapByteBuffer.java:228)
    at com.test.turbine.HeapByteBufferTest$2.run(HeapByteBufferTest.java:72)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

Disconnected from the target VM, address: '127.0.0.1:54130', transport: 'socket'

Process finished with exit code 255

I'm trying to find an easier way to make this exception easier to reproduce without running the test
repeatedly, open to suggestions.

picture erichhsun
👍2

Most helpful comment

When will it be released?

picture MISS-COOKER on 12 Aug 2019
👍3

All 6 comments

@erichhsun Thank you for this! We're using it in production now, and all the ArrayIndexOutOfBoundsExceptions disappeared.

henrik242 picture henrik242 on 23 Feb 2018

@henrik242 Resolved by https://github.com/Netflix/Hystrix/pull/1757.

erichhsun picture erichhsun on 26 Apr 2018
👍1

1.5.18 is released, finally!

henrik242 picture henrik242 on 19 Nov 2018

Spoke too soon. 1.5.18 is just a re-release of 1.5.11 :(

henrik242 picture henrik242 on 19 Nov 2018

Seeing this as well, thanks for the hard work tracking it down!

jrlucier picture jrlucier on 5 Mar 2019

When will it be released?

MISS-COOKER picture MISS-COOKER on 12 Aug 2019
👍3
Was this page helpful?
0 / 5 - 0 ratings

Related issues

chrisgray picture chrisgray  路  4Comments
e-Masary picture e-Masary  路  7Comments
elandau picture elandau  路  3Comments
pranavtiwary picture pranavtiwary  路  6Comments
JasonMathison picture JasonMathison  路  4Comments