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 caselog
will return a function just like itself, but with the plugin installed — or you can install a plugin globally by callinginstallPlugin(yourPlugin)
before anylog
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 fromObservable
will not be proxied — to log a subject, first convert it to an observable using methodasObservable
.
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.
Top comments (0)