Log and test RxJS observables with 1log
Tags: rxjs, logging, testing, showdev
Published: 2021-02-01 15:49:27

**ATTENTION: this article is now outdated, please see [GitHub readme](https://github.com/ivan7237d/1log/tree/master/packages/rxjs) 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

```ts
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 &mdash; 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](https://github.com/ivan7237d/1log-rxjs). Let's jump straight to a basic code snippet and take a look at the log messages that it produces:

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

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

![Screenshot](https://dev-to-uploads.s3.amazonaws.com/i/qpqj0nd00cwltxmwfo2l.png)

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](https://developer.mozilla.org/en-US/docs/Web/API/DOMHighResTimeStamp#The_time_origin) 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](https://stackoverflow.com/questions/48233498/why-do-my-rxjs-state-changes-show-up-out-of-order).

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`](https://github.com/ivan7237d/1log-rxjs), while the library core is in package  [`1log`](https://github.com/ivan7237d/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 &mdash; 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 &mdash; 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](https://github.com/ivan7237d/1log): 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:

```ts
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:

![Screenshot](https://dev-to-uploads.s3.amazonaws.com/i/5y2diik6noc483k75ch6.png)

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

![Screenshot](https://dev-to-uploads.s3.amazonaws.com/i/7bfo9g3zq19m6nxdasfv.png)

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` &mdash; 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:

![Screenshot](https://dev-to-uploads.s3.amazonaws.com/i/gvj81o2voahg4ff293nm.png)

# 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:

```ts
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:

```ts
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](https://github.com/ivan7237d/antiutils), and which is 1log's only dependency. Check it out if you're curious.