Log and test RxJS observables with 1log

ATTENTION: this article is now outdated, please see GitHub readme for the current version of the API.

Logging

As soon as I started building an app that uses RxJS, I realized that I needed a logging utility. First I went with a common approach of creating a custom operator like

const log = <T>(label: string): MonoTypeOperatorFunction<T> =>
  tap(
    (value) => console.log(label, value),
    (error) => console.error(label, error),
    () => console.log(label, 'complete'),
  );

At some point though, I ran into debugging scenarios where I needed more information than nexts, errors, and completions — at a minimum,

• A way to tell when an observable is created, subscribed and unsubbed.

• When some observable is subscribed multiple times, a way to tell which subscription a next/error/complete/unsub originates from.

So I came up with 1log. Let's jump straight to a basic code snippet and take a look at the log messages that it produces:

import { log } from '1log';
import { timer } from 'rxjs';

timer(500).pipe(log).subscribe();

For the most part, the messages are self-explanatory, but there are a few things to note while we're at it.

Time deltas are muted if they are less than 10ms and bold if they are 1s or more. They are computed using performance.now (so the first delta is counted from the time the user started navigation that opened the page) and exclude the time spent on logging itself.

The indentation (as in the last line in the above screenshot) indicates synchronous stack level. One situation where this is handy is reentrancy-related bugs.

Colors and other styling is supported in all recent desktop browsers (where it's implemented using %c directive) and in Node/terminal (where it's implemented using ANSI escape codes).

Tip: In Chrome, you can right-click an observable or a subscriber from a "create" or "subscribe" log message and say "Store as global variable". The object will be stored with a name like temp1. It's sometimes useful to have access to this object in the console, for example to call next on a subscriber.

Library core

Now let's take a closer look at the library's API.

The logic specific to RxJS observables is in package 1log-rxjs, while the library core is in package 1log.

The core exports a function log which can be used like just like the regular console.log, but has two superpowers:

• When passed a single argument, it returns that argument or a proxy that mimics it. This means that log can be inserted into any expression without changing the behavior of your program, e.g. f(log(x)).

• It supports plugins. There are two ways to install a plugin: you can install a plugin locally by passing it as an argument to log, in which case log will return a function just like itself, but with the plugin installed — or you can install a plugin globally by calling installPlugin(yourPlugin) before any log calls.

The package 1log-rxjs exports a plugin called observablePlugin. It's installed globally with the default config, and affects how the log function behaves when you give it an RxJS observable, as in log(yourObservable) or equivalently yourObservable.pipe(log). Instead of passing yourObsevable through as is, log will return a proxy that's like the original, but logs everything that's happening to it.

Tip: Instances of classes like Subject that inherit from Observable will not be proxied — to log a subject, first convert it to an observable using method asObservable.

The core library has a bunch of features that you can read about in its GitHub readme: it provides plugins similar to observablePlugin, but for functions, promises and iterables; it also supports severity levels, optimized production builds and usage in libraries. What I'd like to do here though is talk about a plugin included in the core called badgePlugin, and at the same time give you another, slightly more complex example of using 1log.

As I mentioned, you can install a plugin locally by passing it to the log function. In particular, log(badgePlugin('your caption')) will return a function just like log, but which prefixes log messages with a badge. Let's see what messages are logged by the following code:

import { badgePlugin, log } from '1log';
import { fromEvent, timer } from 'rxjs';
import { switchMap } from 'rxjs/operators';

fromEvent(document, 'click')
  .pipe(
    log(badgePlugin('outer')),
    switchMap(() => timer(500).pipe(log(badgePlugin('inner')))),
  )
  .subscribe();

Two messages appear as soon as the page loads:

In this example, 2.35 seconds later I click somewhere in the page, and this immediately produces three more messages:

Notice that for the inner observable the badge says "create 1", not "create 2": that's because there are separate counters for inner and outer observables, or generally speaking, for each combination of preceding badges.

What happened so far is that my click started the 500ms timer inside switchMap — but in 157ms, before the timer has had the chance to fire, I click again, and switchMap switches to a new timer, which eventually fires:

Testing

In combination with Jest's snapshots feature, inspecting log messages is a great way to test observables.

You can configure the library in such a way that when running tests, log messages are placed in a buffer instead of writing them to the console. You can retrieve them from that buffer and clear it by calling getMessages().

Let's take a look at an example. I launch Jest in watch mode and create the following .test.ts / .test.js file:

import { getMessages, log } from '1log';
import { timer } from 'rxjs';

test('timer', () => {
  timer(500).pipe(log).subscribe();
  jest.runAllTimers();
  expect(getMessages()).toMatchInlineSnapshot();
});

Once I save this file, Jest fills in the snapshot and there you go, I have a comprehensive and easy-to-read test:

import { getMessages, log } from '1log';
import { timer } from 'rxjs';

test('timer', () => {
  timer(500).pipe(log).subscribe();
  jest.runAllTimers();
  expect(getMessages()).toMatchInlineSnapshot(`
    [create 1] +0ms [Observable]
    [create 1] [subscribe 1] +0ms [Subscriber]
    [create 1] [subscribe 1] [next] +500ms 0
    [create 1] [subscribe 1] [complete] +0ms
    · [create 1] [subscribe 1] [unsubscribe] +0ms
  `);
});

Since colors are not available in tests, badges like [create 1] are not shortened to [1] the way they are in the console.

---

P.S. Together with 1log I published a utilities library which I called Antiutils, and which is 1log's only dependency. Check it out if you're curious.