📑

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

5 min read

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

118744160-c252b880-b88e-11eb-9311-c6742bdbc33c

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<Map<ContextKey, 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()?.get('reqId'),
    }
  },
})

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(new Map(), next)
})

// ...

Then, set reqId to the context. It will be isolated in each request.

// src/app.ts

// ...

// Set request ID to the context
app.addHook('preHandler', (request, _, next) => {
  executionContext.getStore()?.set('reqId', request.id)
  next()
})

// ...

Okay, we set reqId to the context! Let's add 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.

image

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.

image

Conclusion

Request ID tracking is really important to investigate bugs.

If you have any feedback, please leave a comment!

Discussion

ログインするとコメントできます