Tracing

Star us on GitHub!

Overview

@bcheidemann/tracing is a framework for collecting event based tracing, logging, and diagnostic information from JavaScript applications at runtime.

Table of Contents

• Overview
• Installation
  • Deno
  • Node
  • Bun
• Motivation
• Prior Art
• Core Concepts
  • Spans
  • Events
  • Subscribers
  • Levels
• Usage
  • Examples
  • Recording Spans
  • Recording Events
  • Instrumenting Methods and Functions
  • Subscribers
• Usage Considerations
  • Usage in Asynchronous Code
  • Performance
  • Minifiers
  • Bundler Support
    • Vite
    • ESBuild
    • SWC
  • Runtime Support
  • ES Decorators vs Legacy Decorators
• ESLint Plugin
• Contributing

Installation

Deno

deno add @bcheidemann/tracing

Node

The package is published to JSR, a new package registry for TypeScript. To install JSR packages for Node, you need to use the jsr CLI. After installing it, it will behave just like any other Node module.

# npm
npx jsr add @bcheidemann/tracing

# yarn
yarn dlx jsr add @bcheidemann/tracing

# pnpm
pnpm dlx jsr add @bcheidemann/tracing

Bun

bunx jsr add @bcheidemann/tracing

Motivation

Implementing good logging is hard - especially in asynchronous applications! To get a view of what happened during a particular asynchronous task (e.g. an API request) we often need to pass around contextual information, such as request IDs, so that we can reconcile all of the logs for that task after the fact. Doing this properly is a lot of work, and can add excessive boilerplate to your application.

Prior Art

This package was heavily inspired by the tracing crate in the Rust ecosystem.

Core Concepts

Spans

Spans represent a discrete unit of work. For example, in a web server, they may be used to represent the lifetime of a request. Spans can be entered and exited. When an event is logged, the context of any entered spans will be included with the event automatically.

Events

Unlike spans, which represent a period of time during the execution of the program, events represent a single point of time. When an event is logged, any subscribers will be notified of the event, and all spans which are entered at that point it time.

Subscribers

Subscribers are responsible for handling events. Typically, these are used for logging.

Levels

Spans and events both have levels. Levels are used by subscribers to decide whether or not they are interested in a particular span or event. Note that spans and events are discrete from one another, meaning even if an entered span is below the minimum level for a subscriber, the subscriber is still notified of events which happen during that span if they are above the minimum level.

Usage

Examples

You can find usage examples here.

Recording Spans

Spans can be created and entered like this:

const guard = span(Level.INFO, "an example span").enter();

Note the guard being returned. This allows us to exit the span, either implicitly or explicitly.

To explicitly exit the span, you can simply call guard.exit(). However, if you are using TypeScript, with a bundler which supports TC39 using declarations, then you can automatically exit the span at the end of the scope.

{
  using guard = span(Level.INFO, "an example span").enter();
  // Do stuff
} // <-- span automatically exits here

The following shorthands are available:

traceSpan("a trace span");
debugSpan("a debug span");
infoSpan("an info span");
warnSpan("a warn span");
errorSpan("an error span");
criticalSpan("a critical span");

Additional context can be recorded against a span using span fields. These fields will be made available to subscribers when an event is emitted, along with the spans message and level.

span(Level.INFO, "info span with fields", {
  key: "value",
});

This can be used to capture arbitrary context about the span, for example, a web server may use this to capture the request ID.

Recording Events

Events can be emitted like this:

event(Level.INFO, "an example event");

The following shorthands are available:

trace("a trace event");
debug("a debug event");
info("an info event");
warn("a warn event");
error("an error event");
critical("a critical event");

Additional context can be recorded against an event using event fields. These fields will be made available to subscribers when the event is emitted, along with the events message and level.

event(Level.INFO, "info event with fields", {
  key: "value",
});

Instrumenting Methods and Functions

When using classes, you can instument methods as follows:

class Application {
  @instrument()
  async example() {
    // Do stuff
  }
}

A span is automatically entered when the function is called, and exited when the function ends. Note you must be using TypeScript with a bundler that supports TC39 decorators.

Similarly, functions can be instrumented like this:

const example = instumentCallback(
  function example() {
    // Do stuff
  },
);

By default, the span message will be the fully qualified name of the method (<ClassName>.<methodName>) or function (<functionName>). The span will also include an args field, which will include the runtime values of each argument passed to the method.

You can customise the instrumentation of the function or method using various attributes. For example, arguments can be omitted from the automatically created span as follows:

class AuthService {
  @instrument(skip("password"))
  login(username: string, password: string) {
    // Do stuff
  }
}

Or for instrumented functions:

const example = instumentCallback(
  [skip("password")]
  function login(username: string, password: string) {
    // Do stuff
  }
);

The following attributes can be applied:

Attribute	Example	Description
message	message("new message")	Changes the instrumented spans message.
target	target("functionName")	Changes the instrumented spans target field to the provided function name.
	target("ClassName", "methodName")	Changes the instrumented spans target field to the provided method name.
level	level(Level.TRACE)	Changes the instrumented spans level.
skip	skip("paramName")	Omits the named parameter from the instrumented spans args field.
	skip(0)	Omits the indexed parameter from the instrumented spans args field.
	skip(true, false)	Applies a positional mask to the parameters to omit from the instrumented spans args field.
redact	redact("paramName")	Replaces the named parameter with "[REDACTED]" in the instrumented spans args field.
	redact(0)	Replaces the indexed parameter with "[REDACTED]" in the instrumented spans args field.
	redact("param", param => param.field)	Replaces a field on the named parameter with "[REDACTED]" in the instrumented spans args field.
	redact(0, param => param.field)	Replaces a field on the indexed parameter with "[REDACTED]" in the instrumented spans args field.
	redact("param", param => [param.a, param.b])	Replaces multiple fields on the named parameter with "[REDACTED]" in the instrumented spans args field.
	redact(0, param => [param.a, param.b])	Replaces multiple fields on the indexed parameter with "[REDACTED]" in the instrumented spans args field.
skipAll	skipAll	Omits all parameters from the instrumented spans args field.
field	field("key", "value")	Adds the specified key and value to the instrumented spans fields.
	field("key", func)	Adds the specified field to the instrumented spans fields. The provided func will map the arguments to the field value.
logEnter	logEnter()	Logs an event when the function or method is entered.
	logEnter("message")	Logs an event with the provided message when the function or method is entered.
	logEnter(args => args[0])	Logs an event with a message produced from args when the function or method is entered.
	logEnter(Level.TRACE)	Logs an event at the provided level when the function or method is entered.
	logEnter(Level.TRACE, "message")	Logs an event with the provided message at the provided level when the function or method is entered.
	logEnter(Level.TRACE, args => args[0])	Logs an event with a message produced from args at the provided level when the function or method is entered.
logExit	logExit()	Logs an event when the function or method returns. Does not log an event if the function throws an error.
	logExit("message")	Logs an event with the provided message when the function or method returns.
	logExit(args => args[0])	Logs an event with a message produced from args when the function or method returns.
	logExit(Level.TRACE)	Logs an event at the provided level when the function or method returns.
	logExit(Level.TRACE, "message")	Logs an event with the provided message at the provided level when the function or method returns.
	logExit(Level.TRACE, args => args[0])	Logs an event with a message produced from args at the provided level when the function or method returns.
logError	logError()	Logs an event when the function or method throws an error.
	logError("message")	Logs an event with the provided message when the function or method throws an error.
	logError(args => args[0])	Logs an event with a message produced from args when the function or method throws an error.
	logError(Level.TRACE)	Logs an event at the provided level when the function or method throws an error.
	logError(Level.TRACE, "message")	Logs an event with the provided message at the provided level when the function or method throws an error.
	logError(Level.TRACE, args => args[0])	Logs an event with a message produced from args at the provided level when the function or method throws an error.
log	log()	Shorthand for logEnter, logExit, and logError. Logs an event when the function or method is entered, exist or throws.
	log(Level.TRACE)	Logs an event at the provided level when the function or method is entered or exist. Logs at error level on throw.
logReturnValue	logReturnValue()	Requires logExit. Appends the returnValue field to the logged exit event.
	logReturnValue((val, args) => val.toString())	Appends the mapped returnValue field to the logged exit event.

Subscribers

A default global subscriber should be registered when your program starts. This can be done as follows:

import { FmtSubscriber } from "@bcheidemann/tracing";

FmtSubscriber.setGlobalDefault();

// Rest of program

Usage Considerations

Usage in Asynchronous Code

tracing-js is designed to be compatible with asynchronous code without requrining any additional configuration. However, there's a couple of pitfalls when working with asynchronous code. Consider the following code:

async function inner() {
  // -- await boundary --
  info("Log from inner");
}

async function outer() {
  using _ = span(Level.INFO, "outer");
  info("Log from outer");
  // Not awaited
  inner();
}

You might expect "Log from inner", to be logged within the "outer" span. However, because the call to inner is not awaited, the "outer" span is exited before "Log from inner" is logged. This can be avoided by instrumenting inner.

async function inner() {
  // -- await boundary --
  info("Log from inner");
}

async function outer() {
  using _ = span(Level.INFO, "outer");
  info("Log from outer");
  // Not awaited
  const instrumentedInner = instrumentCallback(inner);
  instrumentedInner();
}

When a function instrumented with instrumentCallback is entered, the current context and it's subscriber will be cloned, and the function will run in this cloned context. Because cloned subscribers maintain their own span stack, when the outer function exits, the "outer" span will not be popped from the span stack in the inner contexts.

When working with class methods, the @instrument decorator can also be used:

class {
  @instrument()
  async inner() {
    // -- await boundary --
    info("Log from inner");
  }

  async outer() {
    using _ = span(Level.INFO, "outer");
    info("Log from outer");
    // Not awaited
    this.inner();
  }
}

The above techniques can also be applied to prevent concurrent contexts from interfering with eachother. Consider the following:

async function first() {
  using _ = span(Level.INFO, "first");
  // -- await boundary --
  info("Log from first");
}

async function second() {
  using _ = span(Level.INFO, "second");
  // -- await boundary --
  info("Log from second");
}

async function outer() {
  await Promise.all([
    first(),
    second(),
  ]);
}

Because the first and second function share the same context, "Log from first" may be logged in the "second" span, and visa versa. As before, this problem can be avoided by using instrumentCallback or @instrument (if working with class methods).

Performance

If performance is critical to your application, it may be worth avoiding instrumenting functions where it is not neccessary for any of the reasons listed in Usage in Asynchronous Code. This is because an instrumented function or method will always clone the context on entry, even if it is not necessary. Particularly in methods which are called often, this will create a significant amount of garbage which needs to be collected.

Minifiers

When using the skip attribute when instrumenting functions or methods, be aware that skipping attributes by name is not supported when using a minifier. Instead, skip function parameters by index, using the skip by mask (skip(true, false)), or skip by index (skip(0)) syntax.

Bundler Support

Some features @bcheidemann/tracing make use of TypeScript features which are not universally supported. The below table outlines bundler support by feature.

Last updated: 15th June 2024

Feature	JS (no bundler)	TSC	Vite	ESBuild	SWC
spans	✅	✅	✅	✅	✅
events	✅	✅	✅	✅	✅
subscribers	✅	✅	✅	✅	✅
function instrumentation	✅	✅	✅	✅	✅
method instrumentation	❌	✅	✅	✅	✅
using spans	❌	✅	✅	✅	✅

Vite

Since method instrumentation requires decorator support, you must ensure that Vite is configured to enable decorators if you wish to use the @instrument decorator. This can be done by adding the following lines to your Vite config.

import { defineConfig } from 'vite'

export default defineConfig({
+  esbuild: {
+    target: "es2022"
+  }
})

ESBuild

Since method instrumentation requires decorator support, you must ensure that ESBuild is configured to enable decorators if you wish to use the @instrument decorator. This can be done by setting the --target=es2022 flag.

NOTE: If you're using an older version of ESBuild (before 0.21.3) which doesn't support TC39 decorators, or your project is already using legacy decorators, you can use the @instrument decorator by enabling the experimentalDecorators option in your TypeScript config.

SWC

Since method instrumentation requires decorator support, you must ensure that SWC is configured to enable decorators if you wish to use the @instrument decorator. Please refer to the SWC documentation for configuration options.

Runtime Support

@bcheidemann/tracing works out of the box with Node, Deno and Bun. It also has full support for CloudFlare workers, but requires the use of the nodejs_compat flag.

Runtime	Supported	Comment
Node	✅
Deno	✅
Bun	✅
CloudFlare Workers	✅	Requires nodejs_compat flag.
Browser	❌	Requires AsyncLocalStorage API

ES Decorators vs Legacy Decorators

As of TypeScript v5, support has been added for the stage 3 decorators proposal, while still maintaining support for the legacy experimental decorators behind the experimentalDecorators option. The instrument decorator is agnostic of the type of decorator your project uses.

ESLint Plugin

@bcheidemann/tracing comes with an ESLint plugin, which helps catch common issues. See @bcheidemann/tracing-eslint.

Contributing

See CONTRIBUTING.md