DEV Community

Cover image for Step-by-step guide to add request ID to all SQL logs with Async Local Storage
Kay Gosho
Kay Gosho

Posted on • Updated on

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

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
Enter fullscreen mode Exit fullscreen mode

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>()
Enter fullscreen mode Exit fullscreen mode

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(),
    }
  },
})
Enter fullscreen mode Exit fullscreen mode

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')
})
Enter fullscreen mode Exit fullscreen mode

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())
  })
})

// ...
Enter fullscreen mode Exit fullscreen mode

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)
})

// ...
Enter fullscreen mode Exit fullscreen mode

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()
})

// ...
Enter fullscreen mode Exit fullscreen mode

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')
})

// ...
Enter fullscreen mode Exit fullscreen mode

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!

Top comments (1)

Collapse
 
acro5piano profile image
Kay Gosho

Thanks for your comment.