Bug: Premature Unsubscribe

[vadims]

Updated: This is a pre-mature unsubscribe issue. It happens even with RxJava 0.18.2 and is an issue with Hystrix use of RxJava, not RxJava itself.

---

Is Hystrix 1.3.16 compatible with RxJava 0.20.0? If not, please close :)

We were using toObservable() and noticed that it would work in simple cases, but would hang if we composed additional operators. Could not reproduce when using observe().

Here's a short snippet that reproduces this:

public class Test {

  public static class DummyCommand extends HystrixCommand<String> {

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

    @Override
    protected String run() throws Exception {
      return "foo";
    }
  }

  public static void main(String[] args) {

    // simple case works
    {
      Observable<String> result = new DummyCommand().toObservable();
      System.out.println("result (simple) = " + result.toBlocking().single());
    }

    // flat map works if using observe()
    {
      Observable<String> result = new DummyCommand().observe()
          .flatMap(s -> new DummyCommand().observe());
      System.out.println("result (observe) = " + result.toBlocking().single());
    }

    // flat map hangs if using toObservable()
    {
      Observable<String> result = new DummyCommand().toObservable()
          .flatMap(s -> new DummyCommand().toObservable());
      System.out.println("result (toObservable) = " + result.toBlocking().single());
    }

    Hystrix.reset();
  }

}

[benjchristensen]

I don't experience a hang when I run this code. Are you saying you don't see 3 lines print?

result (simple) = foo
result (observe) = foo
result (toObservable) = foo

[vadims]

I only see 2 lines print and the JVM is still running

result (simple) = foo
result (observe) = foo

[vadims]

I see 3 lines when using Hystrix 1.3.9 and RxJava 0.16.1

[benjchristensen]

I haven't tested with 1.3.9. I'm using the latest which is 1.3.16: https://github.com/Netflix/Hystrix/releases/tag/1.3.16

[vadims]

When I tried with 1.3.16 it hanged and only outputted 2 lines. I reproduced this on Oracle JDK 1.8u5 on OS X and Oracle JDK 1.8u20 on Ubuntu 12.04.

[vadims]

I created a test project and ran it on Travis CI with the same results

https://github.com/vadims/hystrix-test

https://travis-ci.org/vadims/hystrix-test/builds/33650465

[benjchristensen]

Weird. I’ll hunt down what’s going on. I don’t understand how this is not happening for me or the Netflix prod environment.

Thanks for providing environment details and a test environment.

[vadims]

In case it helps.. I couldn't reproduce it later today until I added a Thread.sleep in the DummyCommand.

  public static class DummyCommand extends HystrixCommand<String> {

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

    @Override
    protected String run() throws Exception {
      Thread.sleep(100);
      return "foo";
    }
  }

[vadims]

Seems like toObservable() unsubscribes the entire chain somehow.

    System.out.println(LocalDateTime.now() + " Starting");
    new DummyCommand().toObservable()
        .doOnEach(n -> System.out.println(LocalDateTime.now() + " Before " + n))
        .flatMap(s -> Observable.timer(1, TimeUnit.SECONDS).map(v -> s))
        .doOnEach(n -> System.out.println(LocalDateTime.now() + " After " + n))
        .doOnUnsubscribe(() -> System.out.println(LocalDateTime.now() + " OnUnsubscribe"))
        .subscribe();

    Thread.sleep(5000);

outputs

2014-08-27T09:24:37.222 Starting
2014-08-27T09:24:37.326 Before [rx.Notification@8c079605 OnNext foo]
2014-08-27T09:24:37.327 Before [rx.Notification@2dd1bf1a OnCompleted]
2014-08-27T09:24:37.327 OnUnsubscribe

where

    System.out.println(LocalDateTime.now() + " Starting");
    new DummyCommand().observe()
        .doOnEach(n -> System.out.println(LocalDateTime.now() + " Before " + n))
        .flatMap(s -> Observable.timer(1, TimeUnit.SECONDS).map(v -> s))
        .doOnEach(n -> System.out.println(LocalDateTime.now() + " After " + n))
        .doOnUnsubscribe(() -> System.out.println(LocalDateTime.now() + " OnUnsubscribe"))
        .subscribe();

    Thread.sleep(5000);

outputs

2014-08-27T09:24:31.984 Starting
2014-08-27T09:24:32.104 Before [rx.Notification@8c079605 OnNext foo]
2014-08-27T09:24:32.106 Before [rx.Notification@2dd1bf1a OnCompleted]
2014-08-27T09:24:33.106 After [rx.Notification@8c079605 OnNext foo]
2014-08-27T09:24:33.107 After [rx.Notification@2dd1bf1a OnCompleted]
2014-08-27T09:24:33.107 OnUnsubscribe

[vadims]

Also, this is not reproducible in 1.4.0-RC4.

[benjchristensen]

Alright ... I can replicate now. Hystrix 1.3.16 with RxJava 0.20.x

[benjchristensen]

This appears to happen in Hystrix 1.3.16 and RxJava 0.18.2 as well, so it's a latent bug that has been there all along.

[vadims]

Thanks for the quick fix! I confirmed that it addressed the issue in our actual codebase.

[benjchristensen]

Thanks for the confirmation.