Debugging RxJS, Part 2: Logging

Translator: Ice Panpan; Validator: None at present

Logging is not exciting.

However, this is the most straightforward way to get enough information to reason about a problem without having to guess. It is usually the preferred way to debug RxJS code. This is the second article in a series that focuses on using logging to solve real-world problems. In the first part of debugging Rxjs (I) : Tools, I mainly introduced rxJS-Spy. In this article, I’ll show you how to use RxJS-Spy to get detailed and targeted information with minimal impact.

Let’s look at a simple example using RXJS and rxJS-Spy UMD bundles:

RxSpy.spy();
RxSpy.log(/user-.+/);
RxSpy.log('users');

const names = ['benlesh'.'kwonoj'.'staltz'];
constusers = Rx.Observable.forkJoin(... names.map(name= >
  Rx.Observable
    .ajax
    .getJSON(`https://api.github.com/users/${name}`)
    .tag(`user-${name}`)
))
.tag('users');

users.subscribe();
Copy the code

This example uses forkJoin to combine an Observable that emits an array of GitHub users.

Rxjs-spy marks Observables with the tag operator and annotates them with strings only. Before combining observables, this example first enables listening and configures which observables to log — regular expressions that match /user-.+/ or those with the Users tag.

The console output for this example is as follows:

In addition to Observable next and complete notifications, the recorded output includes subscribe and unsubscribe notifications. It shows everything that happened:

  1. The combination ofObservableThe subscription affects every user API requestObservableParallel subscription of;
  2. Requests are completed in any order;
  3. ObservableAll done;
  4. And unpair when all is doneObservableThe subscription.

Notifications for each record also include information about the subscriber receiving the notification — including the number of subscriptions the subscriber has and the stack trace of the SUBSCRIBE call:

The stack trace refers to the root of the SUBSCRIBE call — that is, the explicit call that affects the subscriber to the Observable subscription. Consequently, the stack trace of the requested Observable also references the subscribe call in media.js:

When I debug, I find it more useful to know the actual root of a subscribe call than to know the location of a subscribe in a combined Observable.

Now let’s look at a real, real problem.

When writing Redux-Observable EPics or NGRX Effects, I see several developers writing similar code:

import { Observable } from 'rxjs/Observable';
import { ajax } from 'rxjs/observable/dom/ajax';

const getRepos = action$= >
  action$.ofType('REPOS_REQUEST')
    .map(action= > action.payload.user)
    .switchMap(user= > ajax.getJSON(`https://api.notgithub.com/users/${user}/repos`))
    .map(repos= > { type: 'REPOS_RESPONSE'.payload: { repos } })
    .catch(error= > Observable.of({ type: 'REPOS_ERROR' }))
    .tag('getRepos');
Copy the code

At first glance, this looks good. Most of the time it works, it’s the kind of bug that can sneak past unit tests.

The problem is that it sometimes stops working, especially after a wrong action has occurred.

The record shows what is happening:

Observable that sees the Redux-Observalbe infrastructure unsubscribe from EPIC completes after the error action is emitted. The catch of the document explains why this is the case.

Whatever Observable is returned by the Selector is attached to the Observable chain.

In this epic, the Observable that returns after the catch completes also sees the epic completion.

The solution is to move the map and catch into the switchMap, as follows:

import { Observable } from 'rxjs/Observable';
import { ajax } from 'rxjs/observable/dom/ajax';

const getRepos = action$= >
  action$.ofType('REPOS_REQUEST')
    .map(action= > action.payload.user)
    .switchMap(user= > ajax
      .getJSON(`https://api.notgithub.com/users/${user}/repos`)
      .map(repos= > { type: 'REPOS_RESPONSE'.payload: { repos } })
      .catch(error= > Observable.of({ type: 'REPOS_ERROR' }))
    )
    .tag('getRepos');
Copy the code

This Epic will no longer complete and continue to send the error action:

In both cases, the only changes that need to be made to the code being debugged are the addition of some markup annotations.

Comments have little impact, and once added, I tend to leave them in the code. Tag operators can be used independently of diagnostic rxjS-spy — use rxjs-spy/add/operator/tag or import rxjs-Spy /operator/tag directly, so there is little overhead to retain tags.

Loggers can be configured using regular expressions, which can yield many possible tag methods. For example, using compound tags such as Github/Users and Github /repos allows you to enable logging for all Github Observables that are tagged and stored in the repository.

Recording is not exciting, but the information that can be gleaned from the output of the recording can often save a lot of time. A flexible markup approach can further reduce the time spent working with logging related code.