19. MVI Debugging

Written by Aldo Olivares

In the previous chapter, you learned how to implement the MVI architecture pattern by rebuilding WeWatch. In this chapter, we’ll skip the usual unit testing with JUnit and Mockito and instead you’ll learn some helpful techniques for manually testing and debugging MVI and reactive code.

Along the way, you’ll:

• Verify the execution of your Intents.
• Verify the flow of your architecture.
• Use Timber to log statements in Android.
• Verify your Observables.
• Use RxJava’s startWith().

Getting started

Start by opening the starter project for this chapter.

Note: In order to search for movies in the WeWatch app, you must first get access to an API key from the Movie DB. To get your API own key, sign up for an account at www.themoviedb.org. Then, navigate to your account settings on the website, view your settings for the API, and register for a developer API key. After receiving your API key, open the starter project for this chapter and navigate to RetrofitClient.kt. There, you can replace the existing value for API_KEY with your own.

After Android Studio finishes building the project, run the app to see it in action.

Try adding a movie by pressing the + floating action button.

Enter a title and click the search button:

Select a movie and click OK on the Snackbar that appears:

So far, the app seems to be working fine, but you need to verify that the right Intents are getting sent and that the appropriate states are being returned.

Introducing Timber

Most developers use logs to debug their apps and test their code. To create a log statement, you typically use the Log class that comes with the Android SDK.

A typical log statement looks like this:

Log.d(TAG, "msg")

This code creates a log statement and displays it to the logcat console. TAG is typically a constant value that holds the class name that responsible for printing the statement. You can also set different priority levels like verbose, debug or error depending on your needs.

The problem with the traditional Log class is that when you release your app to the Play Store, you’ll need to remove these statements so that no sensitive information, such as passwords or authentication tokens, are visible as plain text. A possible solution is to use Control-F to find every line that starts with Log, and then delete what you find. However, if your app contains thousands of lines of code, this might be a difficult and timely task. Besides, you might actually need those statements for debugging purposes later.

To solve this problem, some developers from Square created a handy library for conditional based logging named Timber.

Timber lets you display log statements only when they meet certain conditions, for example, if your app’s current build is a DEBUG build. With Timber, you define the behavior of your logs by creating Tree instances, and use Timber.plant() to add them. You can use the default DebugTree that automatically determines which class is calling it and uses that classes name for the TAG.

To start using Timber, add the following line to your app-level build.gradle:

//Timber
def timberVersion = "4.7.1"
implementation "com.jakewharton.timber:timber:$timberVersion"

Keeping in line with the Timber documentation, you should create your Tree instances as soon as possible, preferably in the onCreate() of your Application class. You’ll do that now.

Open App.kt and add the following code inside onCreate():

if (BuildConfig.DEBUG) {
  Timber.plant(Timber.DebugTree())
}

That’s all you need to do to start using Timber’s enhanced log statements. So now, instead of doing something like this:

Log.d(TAG, "message")

You can use Timber to print statements — without having to worry about them showing up in production:

Timber.d("message")

Now that timber is set up, you’ll learn how to test your MVI architecture.

Note: If you want to keep using the traditional Log class for this chapter — or in your own projects for that matter — that’s up to you, but I highly recommend using this or another logging library of your choice. Log messages in production environments pose a significant security risk, and it’s easy to forget to delete one of your logs, especially if your app has thousands of lines of code.

Testing the MVI architecture

Having an MVI architecture means you have predictable states that are triggered based on Intents. In other words, you have a unidirectional and cyclical flow for your app’s data, and this makes it easier to detect errors because you’ll know the last Intent that triggered as well as the state rendered before an exception occurs. However, to detect errors with this type of architecture you first need to make sure your app’s states are flowing as expected.

To test your Intents, you’ll use RxJava’s doOnNext(), which modifies your Observable source to perform a certain action when it calls onNext().

doOnNext() is the perfect choice to debug your app and add a log each time an Intent is triggered.

Inside view/activity, open MainPresenter.kt and modify observeMovieDisplay() and observeMovieDelete(), like so:

private fun observeMovieDeleteIntent() = view.deleteMovieIntent()
    .doOnNext { Timber.d("Intent: delete movie") }//Add this line
    .subscribeOn(AndroidSchedulers.mainThread())
    .observeOn(Schedulers.io())
    .flatMap<Unit> { movieInteractor.deleteMovie(it) }
    .subscribe()

private fun observeMovieDisplay() = movieInteractor.getMovieList()
    .doOnNext { Timber.d("Intent: display movie") }//Add this line
    .observeOn(AndroidSchedulers.mainThread())
    .doOnSubscribe { view.render(MovieState.LoadingState) }
    .doOnNext { view.render(it) }
    .subscribe()

Whenever there’s an intent to display or delete a movie, MainPresenter will print a log message.

Now you need to know which states get displayed at any given point in your MainView. Open MainActivity.kt and modify render() so it matches this:

override fun render(state: MovieState) {
  Timber.d("State: ${state.javaClass.simpleName}")//Add this line
  when (state) {
    is MovieState.LoadingState -> renderLoadingState()
    is MovieState.DataState -> renderDataState(state)
    is MovieState.ErrorState -> renderErrorState(state)
  }
}

This code prints a log with the MovieState received from the MainPresenter.

Build and run the app. Look at the logcat console and you’ll see what’s happening under the hood:

D/MainActivity: State: LoadingState
D/MainPresenter$observeMovieDisplay: Intent: display movie
D/MainActivity: State: DataState

Notice something weird? The LoadingState is immediately displayed even before the display movies Intent gets triggered. Although this isn’t horrible — because you’re still achieving the desired behavior of displaying the loading state before the data state — the LoadingState should only be displayed after receiving the display movie’s Intent.

If this type of problem exists here, it might also exist elsewhere. To sort out why this is happening, you’ll add a log statement to the display intent.

Inside the presenter package, open SearchPresenter.kt and modify it, like so:

private fun observeMovieDisplayIntent() = view.displayMoviesIntent()
    .doOnNext { Timber.d("Intent: display movies") }//Add this line
    .flatMap<MovieState> { movieInteractor.searchMovies(it) }
    .subscribeOn(Schedulers.io())
    .observeOn(AndroidSchedulers.mainThread())
    .doOnSubscribe { view.render(MovieState.LoadingState) }
    .subscribe { view.render(it) }

Next, inside the view/activity package, open SearchMovieActivity.kt and add a log statement to render():

override fun render(state: MovieState) {
  Timber.d("State: ${state.javaClass.simpleName}")
  when (state) {
    is MovieState.LoadingState -> renderLoadingState()
    is MovieState.DataState -> renderDataState(state)
    is MovieState.ErrorState -> renderErrorState(state)
    is MovieState.ConfirmationState -> renderConfirmationState(state)
    is MovieState.FinishState -> renderFinishState()
  }
}

Every time render() is called, this code prints a log with the MovieState.

Build and run the app. Try searching for a movie.

D/SearchMovieActivity: State: LoadingState
D/SearchPresenter$observeMovieDisplayIntent: Intent: display movies
D/SearchMovieActivity: State: DataState

As suspected, the same thing is happening to SearchPresenter and SearchView: The LoadingState is immediately rendered before the Intent is sent.

It seems there’s a bug in the app that’s rendering the LoadingState before emitting Intents. This is why testing is so crucial.

Open MainPresenter.kt again and look at observeMovieDisplay():

private fun observeMovieDisplay() = movieInteractor.getMovieList()//1
    .doOnNext { Timber.d("Intent: display movie") }//2
    .observeOn(AndroidSchedulers.mainThread())//3
    .doOnSubscribe { view.render(MovieState.LoadingState) }//4
    .doOnNext { view.render(it) }//5
    .subscribe()//6

Take a moment to review this code:

1. getMovieList() retrieves the list of saved movies from the Room database and returns the result on your observable’s onNext().

2. doOnNext() adds a log message every time there’s a response from the previous statement.

3. observeOn() changes the thread of all operators further downstream. This means that doOnSubscribe(), doOnNext() and subscribe() will get called from the main thread.

4. doOnSubscribe() executes the action passed as a parameter as soon as you subscribe to the Observable even before items are emitted. Look at the diagram following this explanation to see how.

5. In this case, you tell the View that you want to render the loading State before emitting an item.

6. Finally, subscribe() makes your subscriber start observing your observable’s emissions.

Do you see the problem here? You’re using doOnSubscribe() to make your View render the LoadingState before an item is emitted.

The second issue is that you’re not observing any of the MainView Intents; you’re only observing getMovieList() in the MainInteractor.

This may not be a big deal right now, because you don’t need any information from the MainView, but in a traditional MVI architecture you want to react to your View’s Intents before executing any actions.

Because the second problem is the easiest to solve, you’ll start there. In the root, open MainView.kt and add the following method signature to your Interface:

fun displayMoviesIntent(): Observable<Unit>

You’ll implement this method in the MainView to send an Intent that you want to display a list of movies.

Open MainActivity.kt and press Control-I to implement the missing members and select displayMoviesIntent().

Now, add the following code to displayMoviesIntent():

return Observable.just(Unit)

There are several ways to create an Observable that does not emit any items; one of them is to call Observable.empty(). The problem with empty() is that it immediately terminates and calls onComplete() without calling onNext(); this is not what you want because you won’t be able to perform any additional actions.

On the other hand, just() is better in this case because it converts any item (including Unit) into an Observable and emits it on onNext().

Open MainPresenter.kt and modify observeMovieDisplay(), like so:

private fun observeMovieDisplay() = view.displayMoviesIntent()//1
    .doOnNext { Timber.d("Intent: display movie") }
    .flatMap<MovieState> { movieInteractor.getMovieList() }//2
    .observeOn(AndroidSchedulers.mainThread())
    .doOnSubscribe { view.render(MovieState.LoadingState) }
    .doOnNext { view.render(it) }
    .subscribe()

1. Instead of directly reacting to getMovieList() from the MovieInteractor, you’re going to react to displayMoviesIntent() of your MainView.
2. Since displayMoviesIntent() is immediately calling onNext(), you’re going to use the flatMap() operator to call getMovieList() of the MovieInteractor.

Build and run the app to verify everything is still working as expected.

Look at your logs to see if LoadingState is still getting rendered before displayMoviesIntent().

D/MainActivity: State: LoadingState
D/MainPresenter$observeMovieDisplay: Intent: display movie
D/MainActivity: State: DataState

Sure enough, the problem is still there. So, how can you solve it? Using startWith().

startWith() is a useful RxJava operator that lets you emit a specified sequence of items before emitting the items from the Observable source.

Because of this, startWith() is an excellent choice to solve the problem your app is currently facing.

Modify observeMovieDisplay(), like so:

private fun observeMovieDisplay() = view.displayMoviesIntent()
    .doOnNext { Timber.d("Intent: display movies intent") }
    .flatMap<MovieState> { movieInteractor.getMovieList() }
    .startWith(MovieState.LoadingState)
    .observeOn(AndroidSchedulers.mainThread())
    .subscribe { view.render(it) }

Instead of calling doOnSubscribe(), you’re using startWith() to emit the LoadingState before any other State is emitted from the MovieInteractor.

Build and run the app. Check the logs to see if startWith() is working as intended.

D/MainPresenter$observeMovieDisplay: Intent: display movies intent
D/MainActivity: State: LoadingState
D/MainActivity: State: DataState

Great! Your app’s LoadingState and DataState are displayed in the proper order. In other words, after receiving an Intent.

Now you need to fix SearchPresenter by replacing doOnNext() with startWith().

Open SearchPresenter.kt and modify observeMovieDisplayIntent() so it matches this:

private fun observeMovieDisplayIntent() = view.displayMoviesIntent()
    .doOnNext { Timber.d("Intent: display movies") }
    .flatMap<MovieState> { movieInteractor.searchMovies(it) }
    .startWith(MovieState.LoadingState)
    .subscribeOn(Schedulers.io())
    .observeOn(AndroidSchedulers.mainThread())
    .subscribe { view.render(it) }

Build and run the app. Navigate to the SearchMovieActivity by searching for a movie.

Check the logs to verify that the LoadingState is called after the Intent and before the DataState.

D/SearchPresenter$observeMovieDisplayIntent: Intent: display movies
D/SearchMovieActivity: State: LoadingState
D/SearchMovieActivity: State: DataState

Great!

Now that your MVI architecture is working as expected, you know precisely what the last Intent emitted was before a crash occurs, making it easier to trace and fix errors.

Key points

• Timber is a handy library for conditional based logging that lets you print log statements only when they meet certain conditions.
• doOnNext() modifies your Observable source to perform a certain action when it calls onNext().
• doOnSubscribe() executes the action passed as a parameter as soon as you subscribe to the Observable.
• startWith() makes an Observable emit a specific sequence of items before it begins emitting the items normally expected from it.

Where to go from here?

If you want to learn more about RxJava and MVI, look at the following resources:

• The official ReactiveX website contains an introduction to the most important RxJava concepts such as Observable, Operator, Subject and Scheduler: http://reactivex.io/
• The RxJava javadoc: http://reactivex.io/RxJava/2.x/javadoc/.
• This decision tree that can help you find the appropriate ReactiveX operator according to your needs: http://reactivex.io/documentation/operators.html#tree