MVI: Eager Observable like Observable.just() are subscribed to late in MviBasePresenter

[sockeqwe]

Seems like an internal bug with eager Observables when establishing the MVI chain.

http://stackoverflow.com/questions/43680876/losing-events-during-rxjava-subscribeon

[Rackles]

Hi,

this fixed it.

Thank you for your help.

[sockeqwe]

Thanks for your feedback! Glad it works now for you.

[Rackles]

I have to apologize. I made a mistake when testing the bug. I left my temporary fix in the application while testing the updated version of mosby. (I was to eager to test the new version....)

I'm terribly sorry but this didn't fix my problem.

[sockeqwe]

Are you sure you are using the latest snapshot?

Please try to redownload latest 3.0.4-SNAPSHOT with

./gradlew build --refresh-dependencies

[Rackles]

I redownloaded the snapshot. My problem still persists.

[sockeqwe]

Hm, could you please take a look here: https://github.com/sockeqwe/mosby/blob/master/mvi-common/src/test/java/com/hannesdorfmann/mosby3/mvi/EagerObservableTest.java

Isn't it more or less the observable chain you have in your app? This test pass now with latest 3.0.4-SNAPSHOT (didn't pass before).

Is your code somewhere available online so that I could take a close look and debug it?

[Rackles]

I'm sorry but I can't make the whole code available.

Essentially the code in stackoverflow shows the components that are causing my problem. Specifically in 3 out of 4 times the render()-function does noto get called with CardViewState.CardBackState.

I hope this helps.

[sockeqwe]

Really strange. I think this unit test covers your code on stackoverflow and passes the tests (100 % not just 3 of 4 times).

Could add a log to your merge operator (or whatever observable you use before subscribeViewState() to verify that this is really a mosby bug.

Observable observable = Observable.merge(...)

observable loggingObservable = observable.doOnNext ( newState -> System.out.println("new state "+newState);

subscribeViewState(loggingObservable, renderFunc);

If this logs are correct, then it might be a mosby bug. But having 3/4 times the wrong observable sounds pretty strange and I'm not sure if it is still a mosby bug.

[Rackles]

This log is not correct. Every time the render() function doesn't get triggered, the state also does not get logged.

So if I understand you correct this is not a mosby bug.

[sockeqwe]

Yes, then this is not a Mosby bug since your observable doesn't emit your desired output (otherwise it would be logged properly).

You have an error (or error in reasoning) somewhere in your rxjava code.

The easiest way to debug it is to add logs like observable.doOnNext( doSomeLogging ) to all your observables to track down the real issue.

Thanks for your help.

[jhowens89]

Did you ever encounter this issue again? I may be experiencing it as well. I'm a bit new to rxjava so I'll let you be the judge.

In DualTeamScoringFragment

override fun connectDataIntent(): Observable<Boolean> { return Observable.just(true).doOnNext({ Timber.d("connectDataIntent doOnNext") }) }

In DualTeamScoringPresenter

override fun bindIntents() {
        Timber.e("bindIntents id=${id}")
        Timber.e("interactor_id: ${dualTeamScoringInteractor.id}")
        val connectDataIntent = intent(DualTeamScoringView::connectDataIntent).doOnNext { Timber.d("preenter connectDataIntent doOnNext") }
                .switchMap {
                    Timber.d("connectDataIntent switchMap ${id}")
                    dualTeamScoringInteractor.dataSourceObservable()
                }.doOnError { Timber.e(it,"Fatal error occurred") }
                .onErrorReturnItem(DualTeamScoringViewAction.DataLoadingFailed() as DualTeamScoringViewAction)
                .subscribeOn(Schedulers.io())
                .observeOn(AndroidSchedulers.mainThread())

    val initialState = dualTeamScoringInteractor.getInitialState()

    subscribeViewState(connectDataIntent.scan(initialState, this::viewStateReducer)
            .doOnNext { Timber.e("subscribeViewState doOnNext viewState: ${it.toString()}") }
            .distinctUntilChanged(), DualTeamScoringView::render)

}

From my perspective, it certainly sounds like a race condition similar to what Rackles described. I always see "connectDataIntent doOnNext" in my logs, but it's uncertain if I'll see "preenter connectDataIntent doOnNext". Matter of fact, I would say most times I won't see "preenter connectDataIntent doOnNext" the first time -- when I first start my app and get past the splash screen. I usually see it after I switch to another fragment and reload this same fragment. Nothing is retained and those id-related logs you see is me tearing apart my dagger scoped implementations to make sure I was getting new instances. It was hard, but not super uncommon to reproduce when I commented things out. Despite many efforts, I could never reproduce in debug mode (I was trying to log "intentRelaysBinders.size" and calls to "reset()". A last attempt band-aid for the day:

Observable.just(true).delay(200, TimeUnit.MILLISECONDS)

seemed to stop the problems. Any insight?

[sockeqwe]

I'm sorry for the inconvenience Mosby may cause. I haven't seen this issue. Is your code somewhere available on github so I can take a look at it to debug it? If not, can you provide a full log where I can see all the order of the logging events ( .doOnNext() ) Do you emit a new intent from view.render() method or is it really like described in your code snippets above:

override fun connectDataIntent(): Observable<Boolean> { 
       return Observable.just(true).doOnNext({ Timber.d("connectDataIntent doOnNext") }) 
}

So you have a .startWith() at some point in your interactor? If yes, can you show me that piece of code too?

[jhowens89]

Ha, definitely don't have to apologize for creating such a convenient library. I'll try to post relevant code but at the interactor level everything is injected via dagger so I'll try to post what's relevant and you can ask for particulars.

I'm not currently setup with a device but I'll get you those logs within the day. Here are files I see as relevant. Let me know if you need more. debug_mosby.zip

[sockeqwe]

I have looked at your code but couldn't spot any particular issue with your code.

However, I'm not sure if this is an Mosby issue. Actually, there is a unit test that makes me wonder if your described error comes from your Interactor or DefaultLoader.

Do you still run into the error if you cut out your interactor and replace it with a simple observable like this:

override fun bindIntents() {
     val connectDataIntent = intent(DualTeamScoringView::connectDataIntent).doOnNext { Timber.d(" preenter connectDataIntent doOnNext") }
                .switchMap {
                    Timber.d("connectDataIntent switchMap ${id}")

                    // Changed
                    Observable.just(DualTeamScoringViewAction.DataCurrentlyLoading ) // <-- Do this instead of interactor

                }.doOnError { Timber.e(it,"Fatal error occurred") }
                .onErrorReturnItem(DualTeamScoringViewAction.DataLoadingFailed() as DualTeamScoringViewAction)
                .subscribeOn(Schedulers.io())
                .observeOn(AndroidSchedulers.mainThread())

        val initialState = dualTeamScoringInteractor.getInitialState()

        subscribeViewState(connectDataIntent.scan(initialState, this::viewStateReducer)
              .distinctUntilChanged(), DualTeamScoringView::render)
    }

Is it working if you cut out the Interactor?

[jhowens89]

So I think I solved the problem, but I say think because I'm still not sure why it would be a solution.

Replacing dualTeamScoringInteractor.dataSourceObservable()

with

Observable.just(DualTeamScoringViewAction.DataCurrentlyLoading)

didn't change anything. In fact, the mere existence of DualTeamScoringInteractor in the constructor would be enough to cause this behavior. Here is an example of what I'm talking about:

class DualTeamScoringPresenter @Inject constructor(val dualTeamScoringInteractor: DualTeamScoringInteractor) : MviBasePresenter<DualTeamScoringView,DualTeamScoringViewState>() {

    override fun bindIntents() {
        val connectDataIntent = intent(DualTeamScoringView::connectDataIntent).doOnNext { Timber.d(" preenter connectDataIntent doOnNext") }
                .switchMap {
                    Observable.just(DualTeamScoringViewAction.DataCurrentlyLoading() as DualTeamScoringViewAction)
                }.observeOn(AndroidSchedulers.mainThread())
                .subscribeOn(Schedulers.io())

        val initialState = DualTeamScoringViewState.BLOCKED.BLOCKING_REFRESH();

        subscribeViewState(connectDataIntent.scan(initialState, this::viewStateReducer)
                .doOnNext { Timber.e("subscribeViewState doOnNext viewState: ${it.toString()}") }
                .distinctUntilChanged(), DualTeamScoringView::render)

    }

    fun viewStateReducer(viewState: DualTeamScoringViewState, viewStateAction: DualTeamScoringViewAction): DualTeamScoringViewState {
        Timber.e("viewState: ${viewState.toString()} viewStateAction: ${viewStateAction.toString()}")

        return when (viewStateAction) {
            is DualTeamScoringViewAction.DataAvailable -> return DualTeamScoringViewState.NOT_BLOCKED(primaryScoringBannerModel = viewStateAction.primaryScoringBannerModel, announcementBannerModel = viewStateAction.announcementBannerData, sponsorLogoUrl = viewStateAction.sponsorLogoUrl)
            is DualTeamScoringViewAction.DataNotYetAvailable -> return DualTeamScoringViewState.BLOCKED.NO_DATA_TO_SHOW()
            is DualTeamScoringViewAction.DataLoadingFailed -> return when(viewState) {

                is DualTeamScoringViewState.NOT_BLOCKED, is DualTeamScoringViewState.BLOCKED.NO_DATA_TO_SHOW, is DualTeamScoringViewState.BLOCKED.BLOCKING_ERROR -> return viewState
                is DualTeamScoringViewState.BLOCKED.BLOCKING_REFRESH -> return DualTeamScoringViewState.BLOCKED.BLOCKING_ERROR()
            }
            is DualTeamScoringViewAction.DataCurrentlyLoading -> return when(viewState){

                is DualTeamScoringViewState.NOT_BLOCKED -> return viewState
                is DualTeamScoringViewState.BLOCKED -> return DualTeamScoringViewState.BLOCKED.BLOCKING_REFRESH()
            }
        }
    }
}

So what fixed it? It was the solution you suggested here: https://stackoverflow.com/a/43717278/8121863

I sorta fumbled into that solution and after I saw it working I revisited the stackoverflow thread to see if Rackles had been doing the same thing as me. It makes no sense to me. Sure my DualTeamScoringInteractor injects an item that will cause DefaultLoader to be created. And on creating of default loader you see that the init() method will kick off a subscription of a loader. But when I stubbed in your suggested test, how are these streams even connected? Also these subscriptions are preceded by .subscribeOn(Schedulers.io()) in DefaultLoader.

I tried hard to reproduce some version of this with your EagerView, EagerPresenter, and an EagerFragment -- butchering it even to the point where I started trying to mirror my DualTeamScoring setup rather than your test (using my dagger supplied interactor and such), but even then I had no luck reproducing.

Any clue what might have been happening?

[sockeqwe]

Finally, I was able to reproduce this issue. I try to isolate it and to fix this as soon as possible.

[jhowens89]

That's great to hear. I'll keep an eye out for an update.

[sockeqwe]

This is fixed in latest 3.1.1-Snapshot . @jhowens89 could you please try the latest snapshot in you project to verify that this fixes that issue?

I'm not sure if this is an internal RxJava bug, I will investigate / debug it even more...

[MFlisar]

I faced this problem as well in the last days and was wondering why I don't get my inital state emitted every now and then...

First tests on my side show, that the snapshot is working now. I've a very simple example (can offer this if it helps) that did not work but I can't reproduce it reliably, only every 5-10th time I lost a state. But simply trying to start my activity over and over again I constantly saw this error...

After updating to the snapshot I could not reproduce this issue again - after trying it about 50 times...

[skykelsey]

Thanks so much for fixing this. I was having the same issue, and it appeared that when I added some logging it started to work. Must have been some sort of race condition?

I've verified the issue is present in 3.1.0 and fixed in 3.1.1-SNAPSHOT