Timed operations

SerilogTimings for logit: an operation is a unit of work that ends in one event saying what it was, how it ended and how long it took.

const op = log.beginOperation('Sync {Tenant}', tenant.id);
try {
  await sync(tenant);
  op.complete();
} catch (err) {
  op.abandon(err);
  throw err;
}
// 08:12:03.123 INF Sync acme completed in 1203.4 ms
// 08:12:03.123 WRN Sync acme abandoned in 88.1 ms   (+ the error)

The message is the template plus {Outcome:l} in {Elapsed:0.0} ms, so the event carries Outcome (completed / abandoned) and Elapsed (milliseconds, from performance.now()) as properties. Completion logs at info, abandonment at warn.

timed#

For a function, the try / catch is done for you:

const user = await log.timed('Load user {UserId}', () => users.get(id), id);

Sync or async: a returned promise is awaited; a throw or rejection abandons the operation with the error and rethrows.

Enriching along the way#

await log.timed('Import {File}', async (op) => {
  const rows = await parse(file);
  op.enrich('Rows', rows.length);
  await insert(rows);
}, file.name);
// Import orders.csv completed in 412.0 ms Rows=8800

op.complete('Rows', n) is enrich plus complete in one. op.enrich(name, value, destructure) captures the value when the operation ends.

using#

With TypeScript 5.2+ an operation disposes itself — and an unfinished one is abandoned, which is what you want when an early return or a throw skipped complete():

function rebuildIndex() {
  using op = log.beginOperation('Rebuild index');
  if (!dirty) return;      // abandoned — the event says so
  rebuild();
  op.complete();
}

op.cancel() ends it without any event.

Levels and slow operations#

log.operation(options, template, ...args) takes the levels and a threshold:

const op = log.operation({ completeLevel: 'debug', abandonLevel: 'error', warnAfter: 500 }, 'Render {Page}', page);

op.elapsed is the running time, for your own thresholds.

Server actions and jobs#

Operations are the natural shape of a server action, a queue job, a cron tick:

export async function processJob(job: Job) {
  return log.forContext({ JobId: job.id }).timed('Job {Kind}', async (op) => {
    const result = await handlers[job.kind](job);
    op.enrich('Attempts', job.attempts);
    return result;
  }, job.kind);
}

Bind the id with forContext so every event inside the operation carries it, not only the final one — or open a LogContext scope.