Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix Javanica unit tests for fallback commands #663

Closed
mattrjacobs opened this issue Feb 10, 2015 · 13 comments
Closed

Fix Javanica unit tests for fallback commands #663

mattrjacobs opened this issue Feb 10, 2015 · 13 comments
Milestone

Comments

@mattrjacobs
Copy link
Contributor

These starting failing in #647. Commented them out to make forward progress. I won't be able to release until these get resolved. /cc @dmgcodevil @sawano for any insights

@sawano
Copy link
Contributor

sawano commented Feb 10, 2015

I'll try to take a look at it and see what I can make out of it.

@mattrjacobs
Copy link
Contributor Author

Thanks @sawano!

On Mon, Feb 9, 2015 at 11:36 PM, Daniel Sawano notifications@github.com
wrote:

I'll try to take a look at it and see what I can make out of it.


Reply to this email directly or view it on GitHub
#663 (comment).

@dmgcodevil
Copy link
Contributor

Hi @mattrjacobs

I've looked into it, the first that I found is that the broken tests dedicated to check nested fallbacks calls.
I'm talking about this approach:
fallbacks

Test testGetUserSyncWithFallbackCommand covers the following scenario:

  1. Invoke main command: getUserSyncFallbackCommand
  2. If getUserSyncFallbackCommand has failed then invoke firstFallbackCommand (fallback)
  3. If firstFallbackCommandhas has failed then invoke secondFallbackCommand (fallback)
  4. if secondFallbackCommand has failed then just invoke method: staticFallback

ok, I decided that it would be better to create a test in order to check this approach (command-firstFallback-secondFallback-plainFallback) works fine without javanica. Thus I created test:

public class MultiFallbackTest {

    public static final String MAIN_COMMAND = MainCommand.class.getSimpleName();
    public static final String FIRST_FALLBACK = FirstFallback.class.getSimpleName();
    public static final String SECOND_FALLBACK = SecondFallback.class.getSimpleName();

    public static class MainCommand extends HystrixCommand<String> {
        protected MainCommand() {
            super(buildSetter(MAIN_COMMAND));
        }

        @Override
        protected String run() throws Exception {
            throw new RuntimeException();
        }

        @Override protected String getFallback() {
            try {
                return new FirstFallback().execute();
            } catch (Exception e) {
                throw Throwables.propagate(e);
            }
        }
    }

    public static class FirstFallback extends HystrixCommand<String> {
        protected FirstFallback() {
            super(buildSetter(FIRST_FALLBACK));
        }

        @Override
        protected String run() throws Exception {
            throw new RuntimeException();
        }

        @Override protected String getFallback() {
            try {
                return new SecondFallback().execute();
            } catch (Exception e) {
                throw Throwables.propagate(e);
            }
        }
    }

    public static class SecondFallback extends HystrixCommand<String> {
        protected SecondFallback() {
            super(buildSetter(SECOND_FALLBACK));
        }

        @Override protected String run() throws Exception {
            throw new RuntimeException();
        }

        @Override protected String getFallback() {
            return "result";
        }
    }

    private static HystrixCommand.Setter buildSetter(String commandKey) {
        return HystrixCommand.Setter
                .withGroupKey(HystrixCommandGroupKey.Factory.asKey(MultiFallbackTest.class.getSimpleName()))
                .andCommandKey(HystrixCommandKey.Factory.asKey(commandKey));
    }

    @Test
    public void test() throws Exception {
        HystrixRequestContext context = HystrixRequestContext.initializeContext();
        try {
            assertEquals("result", new MainCommand().execute());
            assertEquals(3, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size());
            HystrixInvokableInfo<?> mainCommand = getHystrixCommandByKey(MAIN_COMMAND);
            com.netflix.hystrix.HystrixInvokableInfo firstFallbackCommand = getHystrixCommandByKey(FIRST_FALLBACK);
            com.netflix.hystrix.HystrixInvokableInfo secondFallbackCommand = getHystrixCommandByKey(SECOND_FALLBACK);

            // confirm that command has failed
            assertTrue(mainCommand.getExecutionEvents().contains(HystrixEventType.FAILURE));
            // confirm that first fallback has failed
            assertTrue(firstFallbackCommand.getExecutionEvents().contains(HystrixEventType.FAILURE));
            // and that second fallback was successful
            assertTrue(secondFallbackCommand.getExecutionEvents().contains(HystrixEventType.FALLBACK_SUCCESS));
        } finally {
            context.shutdown();
        }
    }

}

This test fails with the following error (including stacktrace):

com.netflix.hystrix.exception.HystrixRuntimeException: MainCommand failed and failed retrieving fallback.
    at com.netflix.hystrix.AbstractCommand$20.call(AbstractCommand.java:829)
    at com.netflix.hystrix.AbstractCommand$20.call(AbstractCommand.java:797)
    at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$1.onError(OperatorOnErrorResumeNextViaFunction.java:77)
    at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:70)
    at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:70)
    at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:70)
    at rx.Observable$ThrowObservable$1.call(Observable.java:9101)
    at rx.Observable$ThrowObservable$1.call(Observable.java:9091)
    at rx.Observable.unsafeSubscribe(Observable.java:7326)
    at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$1.onError(OperatorOnErrorResumeNextViaFunction.java:78)
    at rx.internal.operators.OperatorMap$1.onError(OperatorMap.java:49)
    at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:314)
    at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:306)
    at rx.Observable$1.call(Observable.java:146)
    at rx.Observable$1.call(Observable.java:138)
    at rx.Observable$1.call(Observable.java:146)
    at rx.Observable$1.call(Observable.java:138)
    at rx.Observable$1.call(Observable.java:146)
    at rx.Observable$1.call(Observable.java:138)
    at rx.Observable$1.call(Observable.java:146)
    at rx.Observable$1.call(Observable.java:138)
    at rx.Observable$1.call(Observable.java:146)
    at rx.Observable$1.call(Observable.java:138)
    at rx.Observable$1.call(Observable.java:146)
    at rx.Observable$1.call(Observable.java:138)
    at rx.Observable$1.call(Observable.java:146)
    at rx.Observable$1.call(Observable.java:138)
    at rx.Observable$1.call(Observable.java:146)
    at rx.Observable$1.call(Observable.java:138)
    at rx.Observable.unsafeSubscribe(Observable.java:7326)
    at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$1.onError(OperatorOnErrorResumeNextViaFunction.java:78)
    at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:70)
    at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:70)
    at com.netflix.hystrix.AbstractCommand$HystrixObservableTimeoutOperator$3.onError(AbstractCommand.java:985)
    at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:70)
    at rx.internal.operators.OperatorSubscribeOn$1$1$1.onError(OperatorSubscribeOn.java:71)
    at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:70)
    at rx.Observable$ThrowObservable$1.call(Observable.java:9101)
    at rx.Observable$ThrowObservable$1.call(Observable.java:9091)
    at rx.Observable.unsafeSubscribe(Observable.java:7326)
    at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$1.onError(OperatorOnErrorResumeNextViaFunction.java:78)
    at rx.internal.operators.OperatorMap$1.onError(OperatorMap.java:49)
    at com.netflix.hystrix.HystrixCommand$1.call(HystrixCommand.java:297)
    at com.netflix.hystrix.HystrixCommand$1.call(HystrixCommand.java:289)
    at rx.Observable$1.call(Observable.java:146)
    at rx.Observable$1.call(Observable.java:138)
    at rx.Observable$1.call(Observable.java:146)
    at rx.Observable$1.call(Observable.java:138)
    at rx.Observable$1.call(Observable.java:146)
    at rx.Observable$1.call(Observable.java:138)
    at rx.Observable.unsafeSubscribe(Observable.java:7326)
    at com.netflix.hystrix.AbstractCommand$4.call(AbstractCommand.java:524)
    at com.netflix.hystrix.AbstractCommand$4.call(AbstractCommand.java:508)
    at rx.Observable.unsafeSubscribe(Observable.java:7326)
    at rx.internal.operators.OperatorSubscribeOn$1$1.call(OperatorSubscribeOn.java:62)
    at com.netflix.hystrix.strategy.concurrency.HystrixContexSchedulerAction$1.call(HystrixContexSchedulerAction.java:56)
    at com.netflix.hystrix.strategy.concurrency.HystrixContexSchedulerAction$1.call(HystrixContexSchedulerAction.java:47)
    at com.netflix.hystrix.strategy.concurrency.HystrixContexSchedulerAction.call(HystrixContexSchedulerAction.java:69)
    at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:47)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.RuntimeException
    at com.netflix.hystrix.contrib.javanica.test.spring.fallback.MultiFallbackTest$MainCommand.run(MultiFallbackTest.java:38)
    at com.netflix.hystrix.contrib.javanica.test.spring.fallback.MultiFallbackTest$MainCommand.run(MultiFallbackTest.java:30)
    at com.netflix.hystrix.HystrixCommand$1.call(HystrixCommand.java:294)
    ... 21 more

It looks like something changed in core that affects this behavior and root cause of the issue isn't because of javanica. @mattrjacobs could you say what major changes were made in core before the tests became broken, any information will be really helpful for me.

@mattrjacobs
Copy link
Contributor Author

Thanks for looking into it, @dmgcodevil. The change that triggered the unit test failure was a bugfix. In 1.3.x, setting the interruptOnTimeout property to true for a thread-isolated HystrixCommand caused an Thread.interrupt to occur against the Hystrix thread after the calling thread had walked away.

In the migration to 1.4, this logic got dropped for the nonblocking timeout case, and the thread interruption was never occurring. The #647 PR added this capability back. Since the Javanica unit tests were the only ones to fail, I assumed the issue was with Javanica.

Given your reproduction above, it looks like the issue could be in Hystrix-core. I'll add in your unit tests and see what I find. I really appreciate the help!

@dmgcodevil
Copy link
Contributor

Javanica is built over the core, it doesn't introduce some specific logic that decoupled from it, thus if the test case that I mentioned above will pass then the broken javanica test will returned back to normal state.

@dmgcodevil
Copy link
Contributor

Do you have any tests to check such behaviour, that is: a command with a fallback which is also a comnand and so on and so forth

@mattrjacobs
Copy link
Contributor Author

I'm adding a few right now. They are failing, as expected given your example above.

@mattrjacobs
Copy link
Contributor Author

Here are a few reproductions: #670. I'm working on a fix.

@dmgcodevil
Copy link
Contributor

I see you completely changed core code to use rx, or it was made from scratch (originally) ? I'm asking because I would like to have a facility to read core source code in order to find root cause of an issues if it take place, I think It can be useful if you create separate article where you will describe how the core organized, add some visual diagrams of core architecture, because when I'm looking into code I see callback hell and it's really not easy to find something because of lack of information about infrastructure. WDYT ?

@mattrjacobs
Copy link
Contributor Author

@dmgcodevil Yes, the major change from 1.3.x -> 1.4 was to base the command execution flow on RxJava. This allows for true non-blocking usage, as in HystrixObservableCommand. I completely agree with your point about the Wiki documentation not keeping up with the code. This is on my list of things to do before I call 1.4.0 done. When I make progress on that, I'll ping you and I'd love to hear if it answers your questions.

@dmgcodevil
Copy link
Contributor

@mattrjacobs it sounds good, thanks. Also, please keep me posted about progress with faiing tests.

@mattrjacobs
Copy link
Contributor Author

Root cause here was that thread interruption was happening on every unsubscribe(), not just on thread timeouts. The Javanica unit tests happened to be the only ones exercising this functionality, so I wrongly assigned the blame there. Now that the fix was made, the Javanica unit tests are uncommented again.

@dmgcodevil
Copy link
Contributor

Great! Thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants