Step-by-step guide to add request ID to all SQL logs with Async Local Storage

Logging is important for all production-ready service. It will significantly affect our productivity when a issue happens.

With request ID, we can track a user's request without grepping every rows with our eyes. Just filtering with the unique request ID and things done. Almost all logging service has filtering feature, so it's a quite portable way.

Since Node.js typically runs on a single threaded environment, it requires a trick to add request ID for each logs. The trick was domain API for a long time, but now you can use AsyncLocalStorage to create thread-like context.

I'll show you how to do it.

NOTE: AsyncLocalStorage has performance impact, but I think easy logging is more important than performance.

The code

In this example I use Fastify and Knex and pino with TypeScript, but the idea should be used with every technologies.

https://github.com/acro5piano/knex-fastify-async-local-storage-example

Step 1 - Setup

Nothing special.

yarn add fastify knex nanoid pino pino-pretty sqlite3

# For easy development
yarn add -D esbuild-register @types/node @types/pino typescript

Step 2 - create an execution context

This is a key part. AsyncLocalStorage contains data which is unique for each request.

// src/executionContext.ts

import { AsyncLocalStorage } from 'async_hooks'

type ContextKey = 'reqId'

export const executionContext = new AsyncLocalStorage< string>()

Step 3 - create logger

This logger adds reqId to every records. You must log everything with this logger (not use console.log).

// src/logger.ts

import pino from 'pino'
import { executionContext } from './executionContext'

export const logger = pino({
  prettyPrint: true,
  mixin() {
    return {
      reqId: executionContext.getStore(),
    }
  },
})

Step 4 - create Knex

Use our logger for query logging. It automatically adds reqId.

Disclaimer: For simplicity, I don't add log reduction settings. If you use it on production service, don't forget to hide sensitive information from logs.

// src/db.ts

import createKnex from 'knex'
import { logger } from './logger'

export const db = createKnex({
  client: 'sqlite3',
  connection: ':memory:',
  useNullAsDefault: false,
})

// Log every query with our logger
db.on('query', ({ sql, bindings }) => {
  logger.info({ sql, bindings }, 'SQL')
})

Step 5 - create main HTTP server (Fastify)

Fastify has logging feature by specifying logger option. request.log.info automatically adds reqId which might be enough for small services. However, using our executionContext we can add reqId to every log records, including SQL log!

To do so, create Fastify instance first:

// src/app.ts

import Fastify from 'fastify'
import { nanoid } from 'nanoid'
import { logger } from './logger'
import { executionContext } from './executionContext'
import { db } from './db'

export const app = Fastify({
  logger,
  genReqId: () => nanoid(), // the default is increment, but nanoid is easier for tracing
  disableRequestLogging: true, // we do it on our own
})

// Create a database table for logging (just for example)
app.addHook('onReady', async () => {
  await db.schema.createTable('logs', (t) => {
    t.bigIncrements()
    t.string('message').notNullable()
    t.string('req_id').notNullable()
    t.timestamp('created_at').notNullable().defaultTo(db.fn.now())
  })
})

// ...

Then, register a hook which wraps request handling in the context. Without this, we cannot access the context!

// src/app.ts

// ...

// Add hook to run all operations on the request context
app.addHook('preHandler', (_, __, next) => {
  executionContext.run(request.id, next)
})

// ...

Okay, we set reqId to the context! Let's try the logging feature:

// src/app.ts

// ...

// Log request
app.addHook('preHandler', (request, _, next) => {
  const { method, url, ip } = request
  logger.info({ method, url, ip }, 'incoming request')
  next()
})

// ...

It adds reqId.

Next, let's confirm the reqId will appear in SQL query logs:

// src/app.ts

// ...

// Main routing
app.get('/', async (_, reply) => {
  await db('logs').insert({
    message: 'incoming request',
    req_id: executionContext.getStore()!.get('reqId'),
  })
  reply.send('ok')
})

// ...

It will emits the following log.

Conclusion

Request ID tracking is really important to investigate bugs.

If you have any feedback, please leave a comment!

Comments

[Kay Gosho]

Thanks for your comment.