Actual exception is being hidden by OnErrorFailedException

[ktchernov]

Using RxJava 1.10 (and similar issue on 1.0.15), I stumbled upon a mysterious stack trace that made no sense in my app, after a lot of debugging, I found that RxJava will report the wrong exception in some scenarios. For example, if you run this sample code:

Observable.just(1).doOnNext(new Action1<Integer>() {
        @Override public void call(Integer val) {
            throw new IllegalStateException("doOnNextException");
        }
    }).retryWhen(new Func1<Observable<? extends Throwable>, Observable<?>>() {
        @Override public Observable<?> call(Observable<? extends Throwable> errorObservable) {
            return errorObservable.flatMap(new Func1<Throwable, Observable<?>>() {
                @Override public Observable<?> call(Throwable throwable) {
                    return Observable.just(3).delay(1, TimeUnit.SECONDS).doOnNext(
                            new Action1<Integer>() {
                                @Override public void call(Integer integer) {
                                    throw new UnsupportedOperationException("retry exception");
                                }
                            });
                }
            });
        }
    }).subscribe(new Subscriber<Integer>() {
        @Override public void onCompleted() {
            Log.v("EX", "onCompleted");
        }

        @Override public void onError(Throwable e) {
            Log.v("EX", "onError");
            throw new IllegalThreadStateException();
        }

        @Override public void onNext(Integer integer) {
            Log.v("EX", "onNext");
        }
    });

The expected behaviour should be that IllegalThreadStateException (thrown within the onError handler of the subscriber) is included as the cause. However, the actual stack trace contains UnsupportedOperationException as the cause - which is not the problem in the code snippet above. the UnsupportedOperationException is totally fine, but the problem arises when onError throws.

This leads to a stack trace that points to the wrong cause and does not include the actual cause (which would be the IllegalThreadStateException). If I removed the retryWhen() block - then the stack trace correctly includes IllegalThreadStateException as the exception from within onError.

The (incorrect) trace from the code snippet above:

Process: com.example.mydemoapp, PID: 14118
java.lang.IllegalStateException: Fatal Exception thrown on Scheduler.Worker thread.
    at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:62)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:422)
    at java.util.concurrent.FutureTask.run(FutureTask.java:237)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:152)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:265)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
    at java.lang.Thread.run(Thread.java:818)
 Caused by: rx.exceptions.OnErrorFailedException: Error occurred when trying to propagate error to Observer.onError
    at rx.observers.SafeSubscriber._onError(SafeSubscriber.java:194)
    at rx.observers.SafeSubscriber.onError(SafeSubscriber.java:120)
    at rx.internal.operators.OnSubscribeRedo$4$1.onError(OnSubscribeRedo.java:331)
    at rx.internal.operators.OperatorMerge$MergeSubscriber.reportError(OperatorMerge.java:240)
    at rx.internal.operators.OperatorMerge$MergeSubscriber.checkTerminate(OperatorMerge.java:776)
    at rx.internal.operators.OperatorMerge$MergeSubscriber.emitLoop(OperatorMerge.java:537)
    at rx.internal.operators.OperatorMerge$MergeSubscriber.emit(OperatorMerge.java:526)
    at rx.internal.operators.OperatorMerge$InnerSubscriber.onError(OperatorMerge.java:810)
    at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:71)
    at rx.exceptions.Exceptions.throwOrReport(Exceptions.java:187)
    at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:82)
    at rx.internal.operators.OperatorDelay$1$3.call(OperatorDelay.java:88)
    at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:422) 
    at java.util.concurrent.FutureTask.run(FutureTask.java:237) 
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:152) 
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:265) 
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112) 
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587) 
    at java.lang.Thread.run(Thread.java:818) 
 Caused by: rx.exceptions.CompositeException: 2 exceptions occurred. 
    at rx.observers.SafeSubscriber._onError(SafeSubscriber.java:194) 
    at rx.observers.SafeSubscriber.onError(SafeSubscriber.java:120) 
    at rx.internal.operators.OnSubscribeRedo$4$1.onError(OnSubscribeRedo.java:331) 
    at rx.internal.operators.OperatorMerge$MergeSubscriber.reportError(OperatorMerge.java:240) 
    at rx.internal.operators.OperatorMerge$MergeSubscriber.checkTerminate(OperatorMerge.java:776) 
    at rx.internal.operators.OperatorMerge$MergeSubscriber.emitLoop(OperatorMerge.java:537) 
    at rx.internal.operators.OperatorMerge$MergeSubscriber.emit(OperatorMerge.java:526) 
    at rx.internal.operators.OperatorMerge$InnerSubscriber.onError(OperatorMerge.java:810) 
    at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:71) 
    at rx.exceptions.Exceptions.throwOrReport(Exceptions.java:187) 
    at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:82) 
    at rx.internal.operators.OperatorDelay$1$3.call(OperatorDelay.java:88) 
    at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55) 
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:422) 
    at java.util.concurrent.FutureTask.run(FutureTask.java:237) 
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:152) 
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:265) 
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112) 
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587) 
    at java.lang.Thread.run(Thread.java:818) 
 Caused by: rx.exceptions.CompositeException$CompositeExceptionCausalChain: Chain of Causes for CompositeException In Order Received =>
    at android.util.Log.getStackTraceString(Log.java:504)
    at com.android.internal.os.RuntimeInit.Clog_e(RuntimeInit.java:59)
    at com.android.internal.os.RuntimeInit.access$200(RuntimeInit.java:43)
    at com.android.internal.os.RuntimeInit$UncaughtHandler.uncaughtException(RuntimeInit.java:91)
    at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:693)
    at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:690)
    at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:66)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:422) 
    at java.util.concurrent.FutureTask.run(FutureTask.java:237) 
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:152) 
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:265) 
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112) 
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587) 
    at java.lang.Thread.run(Thread.java:818) 
 Caused by: java.lang.UnsupportedOperationException: retry exception
    at com.example.mydemoapp.MainActivity$3$1$1.call(MainActivity.java:74)
    at com.example.mydemoapp.MainActivity$3$1$1.call(MainActivity.java:72)
    at rx.Observable$11.onNext(Observable.java:4445)
    at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:80)
    at rx.internal.operators.OperatorDelay$1$3.call(OperatorDelay.java:88)
    at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:422) 
    at java.util.concurrent.FutureTask.run(FutureTask.java:237) 
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:152) 
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:265) 
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112) 
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587) 
    at java.lang.Thread.run(Thread.java:818) 
 Caused by: rx.exceptions.OnErrorThrowable$OnNextValue: OnError while emitting onNext value: 3
    at rx.exceptions.Exceptions.throwOrReport(Exceptions.java:187)
    at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:82)
    at rx.internal.operators.OperatorDelay$1$3.call(OperatorDelay.java:88) 
    at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55) 
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:422) 
    at java.util.concurrent.FutureTask.run(FutureTask.java:237) 
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:152) 
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:265) 
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112) 
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587) 
    at java.lang.Thread.run(Thread.java:818) 

[akarnokd]

You shoudn't throw from Observer.onError or Subscriber.onError but there are safeguards which have to wrap exceptions and deliver it somewhere upstream.

[ktchernov]

You shoudn't throw from Observer.onError or Subscriber.onError but there are safeguards which have to wrap exceptions and deliver it somewhere upstream.

This is just an example to illustrate the problem, my point was not that there shouldn't be exception, my point is that the cause exception that OnErrorFailedException wraps is the wrong exception and not the cause.

Instead the log is of an exception which is already handled. This is confusing and can take a lot of time to understand and to find the actual cause.

For example, in my app there is a rare bug somewhere inside my onError handler, which causes an exception, but I don't know which line inside my handler throws or what exception it throws because I do not see the actual stack trace. Instead I see the error that caused the onError to be invoked.

If you run the same example above with the retryWhen removed, you get the correct exception (note IllegalStateException is at the bottom of the stack trace, while in the first stack trace above the already-handled UnsupportedOperationException is at the bottom of the stack trace):

rx.exceptions.OnErrorFailedException: Error occurred when trying to propagate error to Observer.onError
    at rx.observers.SafeSubscriber._onError(SafeSubscriber.java:194)
    at rx.observers.SafeSubscriber.onError(SafeSubscriber.java:120)
    at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:71)
    at rx.exceptions.Exceptions.throwOrReport(Exceptions.java:187)
    at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:82)
    at rx.internal.util.ScalarSynchronousObservable$1.call(ScalarSynchronousObservable.java:46)
    at rx.internal.util.ScalarSynchronousObservable$1.call(ScalarSynchronousObservable.java:35)
    at rx.Observable$2.call(Observable.java:162)
    at rx.Observable$2.call(Observable.java:154)
    at rx.Observable.subscribe(Observable.java:8191)
    at rx.Observable.subscribe(Observable.java:8158)
    at com.example.mydemoapp.MainActivity.testRetryError(MainActivity.java:65)
    at com.example.mydemoapp.MainActivity.onOptionsItemSelected(MainActivity.java:53)
    at android.app.Activity.onMenuItemSelected(Activity.java:2908)
    at android.support.v4.app.FragmentActivity.onMenuItemSelected(FragmentActivity.java:361)
    at android.support.v7.app.AppCompatActivity.onMenuItemSelected(AppCompatActivity.java:147)
    at android.support.v7.view.WindowCallbackWrapper.onMenuItemSelected(WindowCallbackWrapper.java:100)
    at android.support.v7.view.WindowCallbackWrapper.onMenuItemSelected(WindowCallbackWrapper.java:100)
    at android.support.v7.app.ToolbarActionBar$2.onMenuItemClick(ToolbarActionBar.java:68)
    at android.support.v7.widget.Toolbar$1.onMenuItemClick(Toolbar.java:172)
    at android.support.v7.widget.ActionMenuView$MenuBuilderCallback.onMenuItemSelected(ActionMenuView.java:760)
    at android.support.v7.view.menu.MenuBuilder.dispatchMenuItemSelected(MenuBuilder.java:811)
    at android.support.v7.view.menu.MenuItemImpl.invoke(MenuItemImpl.java:152)
    at android.support.v7.view.menu.MenuBuilder.performItemAction(MenuBuilder.java:958)
    at android.support.v7.view.menu.MenuBuilder.performItemAction(MenuBuilder.java:948)
    at android.support.v7.view.menu.MenuPopupHelper.onItemClick(MenuPopupHelper.java:191)
    at android.widget.AdapterView.performItemClick(AdapterView.java:310)
    at android.widget.AbsListView.performItemClick(AbsListView.java:1145)
    at android.widget.AbsListView$PerformClick.run(AbsListView.java:3042)
    at android.widget.AbsListView$3.run(AbsListView.java:3879)
    at android.os.Handler.handleCallback(Handler.java:739)
    at android.os.Handler.dispatchMessage(Handler.java:95)
    at android.os.Looper.loop(Looper.java:148)
    at android.app.ActivityThread.main(ActivityThread.java:5417)
    at java.lang.reflect.Method.invoke(Native Method)
    at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726)
    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)
 Caused by: rx.exceptions.CompositeException: 2 exceptions occurred. 
    at rx.observers.SafeSubscriber._onError(SafeSubscriber.java:194) 
    at rx.observers.SafeSubscriber.onError(SafeSubscriber.java:120) 
    at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:71) 
    at rx.exceptions.Exceptions.throwOrReport(Exceptions.java:187) 
    at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:82) 
    at rx.internal.util.ScalarSynchronousObservable$1.call(ScalarSynchronousObservable.java:46) 
    at rx.internal.util.ScalarSynchronousObservable$1.call(ScalarSynchronousObservable.java:35) 
    at rx.Observable$2.call(Observable.java:162) 
    at rx.Observable$2.call(Observable.java:154) 
    at rx.Observable.subscribe(Observable.java:8191) 
    at rx.Observable.subscribe(Observable.java:8158) 
    at com.example.mydemoapp.MainActivity.testRetryError(MainActivity.java:65) 
    at com.example.mydemoapp.MainActivity.onOptionsItemSelected(MainActivity.java:53) 
    at android.app.Activity.onMenuItemSelected(Activity.java:2908) 
    at android.support.v4.app.FragmentActivity.onMenuItemSelected(FragmentActivity.java:361) 
    at android.support.v7.app.AppCompatActivity.onMenuItemSelected(AppCompatActivity.java:147) 
    at android.support.v7.view.WindowCallbackWrapper.onMenuItemSelected(WindowCallbackWrapper.java:100) 
    at android.support.v7.view.WindowCallbackWrapper.onMenuItemSelected(WindowCallbackWrapper.java:100) 
    at android.support.v7.app.ToolbarActionBar$2.onMenuItemClick(ToolbarActionBar.java:68) 
    at android.support.v7.widget.Toolbar$1.onMenuItemClick(Toolbar.java:172) 
    at android.support.v7.widget.ActionMenuView$MenuBuilderCallback.onMenuItemSelected(ActionMenuView.java:760) 
    at android.support.v7.view.menu.MenuBuilder.dispatchMenuItemSelected(MenuBuilder.java:811) 
    at android.support.v7.view.menu.MenuItemImpl.invoke(MenuItemImpl.java:152) 
    at android.support.v7.view.menu.MenuBuilder.performItemAction(MenuBuilder.java:958) 
    at android.support.v7.view.menu.MenuBuilder.performItemAction(MenuBuilder.java:948) 
    at android.support.v7.view.menu.MenuPopupHelper.onItemClick(MenuPopupHelper.java:191) 
    at android.widget.AdapterView.performItemClick(AdapterView.java:310) 
    at android.widget.AbsListView.performItemClick(AbsListView.java:1145) 
    at android.widget.AbsListView$PerformClick.run(AbsListView.java:3042) 
    at android.widget.AbsListView$3.run(AbsListView.java:3879) 
    at android.os.Handler.handleCallback(Handler.java:739) 
    at android.os.Handler.dispatchMessage(Handler.java:95) 
    at android.os.Looper.loop(Looper.java:148) 
    at android.app.ActivityThread.main(ActivityThread.java:5417) 
    at java.lang.reflect.Method.invoke(Native Method) 
    at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726) 
    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616) 
 Caused by: rx.exceptions.CompositeException$CompositeExceptionCausalChain: Chain of Causes for CompositeException In Order Received =>
    at android.util.Log.getStackTraceString(Log.java:338)
    at com.android.internal.os.RuntimeInit.Clog_e(RuntimeInit.java:61)
    at com.android.internal.os.RuntimeInit.-wrap0(RuntimeInit.java)
    at com.android.internal.os.RuntimeInit$UncaughtHandler.uncaughtException(RuntimeInit.java:86)
    at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:693)
    at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:690)
 Caused by: java.lang.IllegalStateException: doOnNextException
    at com.example.mydemoapp.MainActivity$3.call(MainActivity.java:63)
    at com.example.mydemoapp.MainActivity$3.call(MainActivity.java:61)
    at rx.Observable$11.onNext(Observable.java:4445)
    at rx.internal.operators.OperatorDoOnEach$1.onNext(OperatorDoOnEach.java:80)
    at rx.internal.util.ScalarSynchronousObservable$1.call(ScalarSynchronousObservable.java:46)
    at rx.internal.util.ScalarSynchronousObservable$1.call(ScalarSynchronousObservable.java:35)
 at rx.Observable$2.call

[ktchernov]

Simpler way to reproduce is to just throw within a doOnError() - the exception that is thrown is swallowed and is not part of the causal chain.

    Observable.just(1).doOnNext(new Action1<Integer>() {
        @Override public void call(Integer val) {
            throw new IllegalStateException("doOnNextException");
        }
    }).doOnError(new Action1<Throwable>() {
                @Override public void call(Throwable throwable) {
                    throw new UnsupportedOperationException("onError exception");
                }
    }).subscribe(new Subscriber<Integer>() {
        @Override public void onCompleted() {
            Log.v("EX", "onCompleted");
        }

        @Override public void onError(Throwable e) {
            Log.v("EX", "onError");
            throw new IllegalThreadStateException();
        }

        @Override public void onNext(Integer integer) {
            Log.v("EX", "onNext");
        }
    });

[premnirmal]

I see this issue too. When I see logs via crashlytics the stacktrace just shows the composite exception but not the details of the actual crash in onError(). I see there's a bug in CompositeException.java. Fixing in a new PR

[zsxwing]

Closing via #3977