Timeout handling fails for non-idempotent strategy

[krutsko]

Recetly we tried to migrate from Hystrix 1.3.9 to the later one 1.3.16 and faced with issue that our custom Hystrix Strategy is not working properly after Hystrix Command throw a Timeout Exception.

I did some modification on this #212 (comment) to show up issue. (In the our real strategy, we use a Guice to propagate http request scope instances ServletScopes.scopeRequest(actual, seedMap) which throw IllegalStateException if called twice)

I'm not sure to consider this a real issue, so reject if needed.

package com.netflix.hystrix;

import com.netflix.hystrix.Hystrix;
import com.netflix.hystrix.HystrixCommand;
import com.netflix.hystrix.HystrixCommandGroupKey;
import com.netflix.hystrix.strategy.HystrixPlugins;
import com.netflix.hystrix.strategy.concurrency.HystrixConcurrencyStrategy;
import com.netflix.hystrix.strategy.concurrency.HystrixRequestContext;
import rx.functions.Action1;

import java.util.concurrent.Callable;

public class TestOrig {

    private static final ThreadLocal<String> requestIdThreadLocal = new ThreadLocal<String>();

    public static class DummyCommand extends HystrixCommand<Void> {

        public DummyCommand() {
            super(HystrixCommandGroupKey.Factory.asKey("Dummy"));
        }

        @Override
        protected Void run() throws Exception {
            System.out.println("requestId (run) = " + requestIdThreadLocal.get());
            Thread.sleep(2000);
            return null;
        }
    }

    public static void main(String[] args) {
        HystrixPlugins.getInstance().registerConcurrencyStrategy(new HystrixConcurrencyStrategy() {
            @Override
            public <T> Callable<T> wrapCallable(final Callable<T> callable) {
                return new RequestIdCallable<T>(callable);
            }
        });

        HystrixRequestContext context = HystrixRequestContext.initializeContext();

        requestIdThreadLocal.set("foobar");
        try {
            new DummyCommand().execute();
        } catch (Exception e) {
            System.out.println("initialized = " + HystrixRequestContext.isCurrentThreadInitialized());
            System.out.println("requestId (timeout) = " + requestIdThreadLocal.get());
            e.getCause().printStackTrace();
        }

        // works fine using toObservable
//        new DummyCommand().toObservable()
//                .doOnError(new Action1<Throwable>() {
//                    @Override
//                    public void call(Throwable throwable) {
//                        System.out.println("initialized = " + HystrixRequestContext.isCurrentThreadInitialized());
//                        System.out.println("requestId (timeout) = " + requestIdThreadLocal.get());
//                        throwable.getCause().printStackTrace();
//                    }
//                })
//                .materialize()
//                .toBlocking().single();


        context.shutdown();
        Hystrix.reset();
    }

    private static class RequestIdCallable<T> implements Callable<T> {
        private final Callable<T> callable;
        private final String requestId;

        public RequestIdCallable(Callable<T> callable) {
            this.callable = callable;
            this.requestId = requestIdThreadLocal.get();
        }

        @Override
        public T call() throws Exception {
            String original = requestIdThreadLocal.get();
            if (original != null) {
                throw new IllegalStateException("threadlocal already initialized");
            }
            requestIdThreadLocal.set(requestId);
            try {
                return callable.call();
            } finally {
                requestIdThreadLocal.set(original);
            }
        }
    }
}

Exptected: timeout exception.
Actual: IllegalStateException

[mattrjacobs]

Here's what's happening:

In the case where you're calling observe() on the command, the RequestIdCallable.call() method gets invoked twice.

1. The actual execution of the DummyCommand on thread: hystrix-Dummy-1. This thread has no context, so initialization is safe.
2. The execution of the non-blocking timeout mechanism (HystrixObservableTimeoutOperator). This executes on thread: Hystrix-Timer-1. It has no previous context, so initialization is fine.

In the case where you're calling execute() on the command, the RequestCallable.call() method gets invoked twice as well, in the same places.

1. The actual execution of the DummyCommand on thread: hystrix-Dummy-1. This thread has no context, so initialization is safe.
2. The execution of the blocking timeout mechanism (HystrixObservableTimeoutOperator). This executes back on the main thread. Since the unit tests sets the context already, this ThreadLocal has already had been initialized, so the second initialization fails.

Generalizing, working with ThreadLocals is going to be fairly sensitive to Hystrix internals. If possible, you should prefer HystrixRequestVariables, as they work much better with the HystrixCommand lifecycle, and are able to hop threads transparently.

I don't think that's there's a reasonable change to make within Hystrix, just the recommendation to prefer HystrixRequestVariable over ThreadLocal.

[krutsko]

Thank you for explanation, I got the message about avoid to use ThreadLocal, but unfortunately we're stick to Guice DI, which is rely on ThreadLocal internally. Calling Hystrix Concurrency Strategy twice over main thread, makes Guice throw IllegalStateException. I wonder how to prevent this case, please advice. We just moved up to patched version (from 1.3.9 to 1.3.16) and broke up our concept.

[mattrjacobs]

@krutsko I wanted to let you know I saw this. I don't have a great answer for you off the top of my head. I will think about it and get back to you

[mattrjacobs]

@krutsko I believe the only solution is to have an idempotent HystrixConcurrencyStrategy. On your example, instead of failing if you found a ThreadLocal already set, you could clear it. I'll add a comment to the HystrixConcurrencyStrategy Javadoc around this point.

[krutsko]

yeah, I'm using this workaround in my strategy now. thanks @mattrjacobs

[mattrjacobs]

Added comment in #665 with a pointer back here.

[tatini1]

hi,my use case is to run 5 threads doing separate network calls ,which ever thread get data first ,it should display the data ,i am using HystrixObservableCommand ,but i am getting synchronous execution ,can anyone help me how to achieve asynchronous execution using hystrics

[mattrjacobs]

@tatini1 This issue sounds completely different than the issue you commented on. Can you please open a new issue with details on what you're trying to achieve and what you're observing?