Step-by-step guide to add request ID to all SQL logs with Async Local Storage
Tags: node, log, fastify, devops
Published: 2021-05-19 01:59:34


 ---
title: Step-by-step guide to add request ID to all SQL logs with Async Local Storage
published: true
description: 
tags: nodejs, log, fastify, devops
cover_image: https://dev-to-uploads.s3.amazonaws.com/uploads/articles/d48ddbrmbptzvfx2mqp2.png
---

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](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/d48ddbrmbptzvfx2mqp2.png)

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.

```shell
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.

```typescript
// 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).

```typescript
// 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.

```typescript
// 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:

```typescript
// 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!

```typescript
// 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:

```typescript
// 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](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/do6yeo44updkgks7ctfj.png)
 
Next, let's confirm the `reqId` will appear in SQL query logs:

```typescript
// 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](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/8wkeu6h90v3n2cm0z6ej.png)
 

# Conclusion

Request ID tracking is really important to investigate bugs.

If you have any feedback, please leave a comment!