Unit-of-Work Telemetry

Emit one rich, structured log entry per unit of work. Instead of scattering dozens of log calls throughout handler code, accumulate context as the work progresses and emit a single rich log entry when it completes. Also known as canonical log lines (Stripe), structured events (Honeycomb), wide events, request-scoped events.

Wrap functions with log.traced() to create a span — it accumulates structured context, records timestamped events, and emits one log entry when the function completes. Spans propagate via AsyncLocalStorage with automatic parent–child relationships, so no function ever threads context manually.

When to use

Use this pattern at any boundary where a unit of work starts and ends — HTTP requests, queue jobs, scheduled tasks, RPC calls — and you want full context in one place instead of scattered console.log calls. The structured output is searchable and queryable in any log aggregator (Cloud Logging, Datadog, ELK).

Use log.traced() on functions that represent meaningful operations: service-layer methods, external calls, business logic with branching outcomes. Don't trace utility functions, getters, or pure transforms — those can still contribute context to the parent span via log.currentSpan() without producing their own log entry.

The pattern

Accumulating context during a unit of work

Wrap a function with log.traced(). Inside, call span.set() to accumulate structured fields and span.event() to record timestamped events. When the function returns (or throws), the span emits everything as one log entry:

import createLogger from "./logger.js";

const log = createLogger({ service: "jobs" });

const processJob = log.traced(
  "processJob()",
  async (job) => {
    const span = log.currentSpan();
    span.set("job.type", job.type);
    span.set("job.id", job.id);
    
    const items = await fetchItems(job);
    span.set("items.count", items.length);
    span.event("Fetched items");
    
    const results = await transform(items);
    span.set("results.count", results.length);
    span.event("Transformed items");
    
    await store(results);
    span.event("Stored results");
  },
);

// Call it like any normal function
await processJob(job);

Error handling is automatic — traced() catches exceptions, sets status to "error" with error.type and error.message, then re-throws. The emitted log entry contains every field accumulated during processing, plus span metadata and timing:

{
  "span.name": "processJob()",
  "span.id": "a1b2c3",
  "trace.id": "x9y8z7",
  "job.type": "import",
  "job.id": "abc-123",
  "items.count": 42,
  "results.count": 42,
  "status": "ok",
  "duration_ms": 817,
  "events": [
    {
      "ms": 12,
      "time": "2025-06-15T14:30:00.012Z",
      "message": "Fetched items"
    },
    {
      "ms": 415,
      "time": "2025-06-15T14:30:00.415Z",
      "message": "Transformed items"
    },
    {
      "ms": 816,
      "time": "2025-06-15T14:30:00.816Z",
      "message": "Stored results"
    }
  ],
  "severity": "DEBUG"
}

Contributing context without tracing

Not every function needs its own span. Helpers and utilities can get a handle on whatever span is currently active and add context to it:

import createLogger from "./logger.js";

const log = createLogger({ module: "email" });

async function validateEmail(addr) {
  const span = log.currentSpan();
  const result = await checkMx(addr);
  span.set("email.mx_valid", result.valid);
  span.event("MX lookup complete");
  return result;
}

If validateEmail is called inside createUser, the email.mx_valid field appears in createUser's log entry.

If there's no active span, currentSpan() warns and returns a detached span — one with no parent that is not a root. The warning and the span both include an async stack trace (span.detached_stack) showing exactly where the missing traced() or startSpan() wrapper should be. The span still accumulates normally and emits when end() is called. If end() is never called, the span emits itself during garbage collection via a FinalizationRegistry. Data is never lost.

Automatic parent–child relationships

When traced functions call other traced functions, the parent–child relationship is captured automatically:

const sendWelcome = log.traced("sendWelcome()", async (user) => {
  const span = log.currentSpan();
  const template = await renderTemplate("welcome", user);
  span.set("template.size", template.length);
  
  await smtp.send({ to: user.email, body: template });
  span.set("email.sent", true);
});

const createUser = log.traced("createUser()", async (input) => {
  const span = log.currentSpan();
  const user = await db.insert(input);
  await sendWelcome(user);  // gets its own span, linked to parent
  return user;
});

Emits two entries that share a trace.id:

trace.id: "x9y8z7"  span.name: "createUser()"    parent.span.id: null
trace.id: "x9y8z7"  span.name: "sendWelcome()"  parent.span.id: "a1b2c3"

No function passes IDs to another. AsyncLocalStorage handles it.

Concurrent children (Promise.all)

Parenting works correctly with concurrent execution. Each traced() call captures its parent before entering its own AsyncLocalStorage context, so concurrent children all link to the right parent:

const createUser = log.traced("createUser()", async (input) => {
  const span = log.currentSpan();
  const user = await db.insert(input);
  
  await Promise.all([
    sendWelcome(user),      // parent.span.id → createUser()
    syncToAnalytics(user),  // parent.span.id → createUser()
  ]);
  
  return user;
});

If concurrent branches spawn their own traced children, the nesting continues correctly — each AsyncLocalStorage run creates an isolated context.

Untraced functions calling currentSpan() during concurrent execution share the parent span. Interleaved event() calls are fine — the timestamps make the ordering clear. Key collisions from concurrent set() calls are caught automatically: the span records the overwrite in its events with the old and new values, so no data is silently lost.

The best practice is to use namespaced keys — email.mx_valid, phone.valid — so concurrent branches don't collide. The overwrite warning is a safety net, not something you should see regularly.

Request-level spans

At the HTTP boundary, use log.startSpan() to create a root span. Unlike traced(), startSpan() runs its callback immediately and gives you the span directly — you manage the lifecycle by calling span.end() yourself:

import createLogger from "./logger.js";

const log = createLogger({ service: "api" });

app.use((req, res, next) => {
  const traceId = req.headers["x-trace-id"] ?? crypto.randomUUID();
  
  const name = `${req.method} ${req.route?.path ?? req.path}`;
  log.startSpan(name, { traceId }, (span) => {
    span.set("http.request.method", req.method);
    span.set("http.request.path", req.path);
    
    res.on("finish", () => {
      span.set("http.response.status_code", res.statusCode);
      span.end();
    });
    
    next();
  });
});

Every traced() function called during request handling automatically becomes a child of the request span. The request-level span works the same way — it accumulates context and emits one rich log entry at the end. See request logging middleware for the Express-specific implementation.

Implementation

Core: span creation and AsyncLocalStorage

import { AsyncLocalStorage } from "node:async_hooks";
import { performance } from "node:perf_hooks";
import crypto from "node:crypto";

const store = new AsyncLocalStorage();
const release = new FinalizationRegistry((span) => {
  if (!span.ended) {
    span.set("span.gc_emitted", true);
    span.end();
  }
});

function createSpan(name, options = {}) {
  const { logger, level = "debug" } = options;
  const parent = store.getStore();
  const id = crypto.randomUUID().slice(0, 8);
  const traceId =
    options.traceId ??
    parent?.traceId ??
    crypto.randomUUID().slice(0, 8);
  const startTime = new Date();
  const startPerf = performance.now();
  const context = new Map([
    ["span.name", name],
    ["span.id", id],
    ["trace.id", traceId],
  ]);
  const events = [];
  
  if (parent) {
    context.set("parent.span.id", parent.id);
  }
  
  function elapsed() {
    return Math.round(performance.now() - startPerf);
  }
  
  const span = {
    id,
    traceId,
    ended: false,
    
    set(key, value) {
      if (context.has(key)) {
        const prev = context.get(key);
        events.push({
          ms: elapsed(),
          time: new Date().toISOString(),
          message: `key "${key}" overwritten`,
          "overwrite.previous": prev,
          "overwrite.new": value,
        });
      }
      context.set(key, value);
    },
    
    event(message, attributes = {}) {
      events.push({
        ms: elapsed(),
        time: new Date().toISOString(),
        message,
        ...attributes,
      });
    },
    
    end() {
      if (span.ended) return;
      span.ended = true;
      const durationMs = elapsed();
      context.set("duration_ms", durationMs);
      context.set("end_time", new Date().toISOString());
      
      if (events.length) {
        context.set("events", events);
      }
      
      const entry = Object.fromEntries(context);
      const emitLevel =
        context.get("status") === "error" ?
          "error" : level;
      
      logger[emitLevel]({
        ...entry,
        time: startTime.getTime(),
      });
    },
  };
  
  release.register(span, span);
  return span;
}

Adding tracing to the logger

traced(), startSpan(), and currentSpan() are methods on the logger. Each creates spans that are bound to the logger that created them — span.end() emits via the right logger automatically:

function addTracing(logger) {
  logger.traced = function (name, fn, options = {}) {
    const { level = "debug" } = options;
    
    return async function (...args) {
      const span = createSpan(name, { logger, level });
      
      return store.run(span, async () => {
        try {
          const result = await fn.apply(this, args);
          span.set("status", "ok");
          return result;
        } catch (error) {
          span.set("status", "error");
          span.set("error.type", error.name);
          span.set("error.message", error.message);
          throw error;
        } finally {
          span.end();
        }
      });
    };
  };
  
  logger.startSpan = function (name, options, fn) {
    if (typeof options === "function") {
      fn = options;
      options = {};
    }
    
    const span = createSpan(name, {
      ...options,
      logger,
    });
    
    return store.run(span, () => fn(span));
  };
  
  return logger;
}

log.currentSpan()

Returns the active span from AsyncLocalStorage. This is a global lookup — any logger instance returns the same span. Add it inside addTracing():

logger.currentSpan = function () {
  const span = store.getStore();
  if (span) return span;
  
  const stack = new Error("detached span").stack;
  logger.warn("currentSpan() called with no active span", { stack });
  const detached = createSpan("(detached)", { logger });
  detached.set("span.detached", true);
  detached.set("span.detached_stack", stack);
  return detached;
};

Integrating with createLogger

Call addTracing() when building the logger. See custom logger for the full createLogger implementation:

export default function createLogger(options) {
  const logger = pino(options);
  return addTracing(logger);
}

Timestamp strategy

Set the log entry's timestamp to when the span started, not when it was emitted. Include end_time and duration_ms in the payload.

When reading a trace sorted by timestamp, you want entries in the order operations began. If a parent starts at T=0 and a child starts at T=50, the parent should appear first — even though the child finishes and emits before the parent does.

Events carry both a relative ms (for quick scanning within a span) and an absolute time (for correlating across spans).

With pino, override the time field at emit time:

logger[level]({ ...entry, time: startTime.getTime() });

Naming conventions

Span names

Name spans after what they trace. A developer who knows the codebase should instantly recognize what each span represents:

• Functions: "createUser()", "processJob()", "sendWelcome()"
• HTTP requests: "GET /users/:id", "POST /orders"
• Messaging: "publish order.created", "consume email.send"

Field names

Use OpenTelemetry semantic conventions for field names. This is free — it's just strings — and it means your logs are interoperable with tracing tools and queryable by anyone who knows the conventions:

Field	Example	Notes
span.name	"createUser()"	Reads like what it traces
span.id	"a1b2c3"	Unique per span
trace.id	"x9y8z7"	Shared across a full request
parent.span.id	"f4e5d6"	Null for root spans
http.request.method	"POST"	OTel convention
http.response.status_code	201	OTel convention
db.system	"postgresql"	OTel convention
error.type	"ValidationError"	OTel convention
error.message	"email is required"	Human-readable
duration_ms	247	Span duration
end_time	"2025-..."	ISO 8601
status	"ok" or "error"	Outcome
events	[{ ms, time, message }]	Timestamped events within the span

Use dotted names for application-specific fields too: user.id, job.type, items.count. Dots create natural grouping in log explorers.

Testing

Pass a capture stream to the logger to assert on emitted entries without touching stdout. See custom logger for the captureStream pattern:

import { Writable } from "node:stream";
import createLogger from "./logger.js";

function captureStream() {
  const lines = [];
  const stream = new Writable({
    write(chunk, encoding, cb) {
      lines.push(JSON.parse(chunk.toString()));
      cb();
    },
  });
  return { lines, stream };
}

const { lines, stream } = captureStream();
const log = createLogger({
  destination: stream,
  level: "trace",
});

const myFn = log.traced("myFn()", async () => {
  const span = log.currentSpan();
  span.set("key", "value");
  span.event("something happened", { detail: 42 });
});

await myFn();

assert.equal(lines.length, 1);
assert.equal(lines[0]["span.name"], "myFn()");
assert.equal(lines[0].key, "value");
assert.equal(lines[0].status, "ok");
assert.ok(lines[0].duration_ms >= 0);
assert.ok(lines[0]["trace.id"]);
assert.equal(lines[0].events.length, 1);
assert.equal(
  lines[0].events[0].message,
  "something happened",
);
assert.equal(lines[0].events[0].detail, 42);

Design principles

Use set(key, value), not positional args. A Map preserves insertion order and makes field names explicit. Positional APIs like context.$log("key", value) lose the structure when serialized.

Align field names with OpenTelemetry. Use dotted names like http.request.method, enduser.id, and error.type so logs are interoperable with tracing tools and aggregators.

Emit at the boundary, not inside. The log entry is emitted once when the unit of work completes. Intermediate event() calls only add timestamped events to the entry — they do not produce separate log output.

The logger creates the span. Since the logger already knows about severity, formatting, and destination, it's the natural factory for spans. log.traced() and log.startSpan() create spans that emit via the logger that created them — no wiring needed.

The span is one object. set(), event(), and end() are methods on the span. There are no free-floating helper functions — context and events belong to the span they're attached to.

log.traced() is a decorator, log.startSpan() is immediate. traced() returns a wrapped function — the span lifecycle is automatic. startSpan() runs a callback now and gives you the span — you call end() yourself. Different names because they do different things.

Any function can reach the current span. log.currentSpan() returns the active span from AsyncLocalStorage. If there is no active span, it warns and returns a detached span marked span.detached: true. Telemetry never throws.

Parent–child relationships are automatic. AsyncLocalStorage nesting handles it. No function passes span IDs to another.

Emit at completion, timestamp at start. Each span emits one log entry when the function returns or throws. The entry's timestamp is when the function was called, so traces read in chronological order.

Key overwrites are recorded, not silent. If set() is called with a key that already exists, the previous value is captured in an event before being overwritten. No data is lost.

Default to debug, promote selectively. Most function-level traces are too granular for info. Promote specific high-value operations:

const processPayment = log.traced("processPayment()", fn, { level: "info" });

Trade-offs

Benefits:

• One queryable line per unit of work — easy to search and filter
• Full context in a single entry — no correlating scattered log lines
• Structured data — machine-readable, dashboardable
• Errors include the full execution context that led to the failure
• Automatic trace and parent IDs without manual wiring
• Structured events with absolute timestamps — correlatable across spans, convertible to OTel events
• Start-time timestamps give correct chronological ordering
• OTel-compatible field names — interoperable with tracing tools
• Compatible with the custom logger pattern for severity mapping and pretty printing

Costs:

• Delayed visibility — nothing is logged until the work completes (or fails)
• Memory — context grows with events for the duration of the work
• Discipline — every code path must flow through the accumulator to be captured
• AsyncLocalStorage — minor per-run overhead (negligible for I/O-bound work, measurable in tight CPU loops)
• No automatic library instrumentation — you must explicitly trace or use log.currentSpan() for third-party calls (unlike OpenTelemetry's monkeypatching)

When to prefer scattered logs instead:

• Long-running operations where you need real-time visibility
• Streaming responses where the "end" boundary is ambiguous
• Development/debugging where immediate console output is more useful than structured entries

When to reach for OpenTelemetry instead:

• You need automatic instrumentation of database drivers, HTTP clients, and other libraries without wrapping them
• You have multiple services and need cross-service trace propagation with standard tooling
• You want a tracing UI with waterfall visualizations out of the box
• The OTel configuration overhead is acceptable for your team size

Migration path:

Your log entries already contain trace.id, span.id, parent.span.id, start time, duration, and structured events — everything a tracing backend needs. A simple adapter can convert these log entries into OTel spans for export to Cloud Trace, Jaeger, or similar tools. The application code doesn't change; it's a read-time transformation.