Skip to main content

Request Id Tracing in Node.js Applications

 If you ever wrote back-end applications in Node.js, you know that tracing the same HTTP request through log entries is a problem. Usually your logs look something like this:

[07/Nov/2018:15:48:11 +0000] User sign-up: starting request validation

[07/Nov/2018:15:48:11 +0000] User sign-up: starting request validation

[07/Nov/2018:15:48:12 +0000] User sign-up: request validation success

[07/Nov/2018:15:48:13 +0000] User sign-up: request validation failed. Reason:

...

Here, log entries are mixed up and there is no way to determine which of them belong to the same request. While you would probably prefer to see something like this:

[07/Nov/2018:15:48:11 +0000] [request-id:550e8400-e29b-41d4-a716-446655440000] User sign-up: starting request validation

[07/Nov/2018:15:48:11 +0000] [request-id:340b4357-c11d-31d4-b439-329584783999] User sign-up: starting request validation

[07/Nov/2018:15:48:12 +0000] [request-id:550e8400-e29b-41d4-a716-446655440000] User sign-up: request validation success

[07/Nov/2018:15:48:13 +0000] [request-id:340b4357-c11d-31d4-b439-329584783999] User sign-up: request validation failed. Reason:

...

Notice the [request-id:*] part that contains request identifiers here. These identifiers will allow you to filter log entries that belong to the same request. Moreover, if your application is composed of microservices communicating with each other over HTTP, request identifiers may be sent in an HTTP header and used for tracing request chains across logs generated by all microservices on the chain. It’s difficult to overestimate how valuable this feature is for diagnostic and monitoring purposes.

As a developer, you would probably want to configure your web framework and/or logger library in a single place and get request ids generated and printed to logs automatically. But unfortunately, it may be a problem in Node.js world.

In this article we are going to discuss the problem and one of possible solutions.

OK, but is it Even a Problem?

In many other languages and platforms, like JVM and Java Servlet containers, where HTTP servers are built around a multi-threaded architecture and blocking I/O, it’s not a problem. If we put an identifier of the thread that processes HTTP request into logs, it already may serve as a natural filter parameter for tracing a particular request. This solution is far from being ideal, but it can be enhanced further with using Thread-local storage (TLS). TLS is basically a way to store and retrieve key-value pairs in a context associated with the current thread. In our case, it may be used to store ids (and any other diagnostic data) generated for each new request. Many logging libraries have features built around TLS. As an example, check out docs for SLF4J’s Mapped Diagnostic Context.

Due to the asynchronous nature of Node.js, which is based on the event loop, there is simply nothing like the thread-local storage, as your JS code is being processed on a single thread. Without this or similar API, you would have to drag a context object, containing the request id, all across your request handling calls.

/////////////////////

'use strict'


// a primitive logger object

const logger = {

  info: console.log

}


const express = require('express')

const uuidv4 = require('uuid/v4')


const app = express()


app.get('/', function (req, res) {

  req._id = uuidv4(); // generate and store a request id

  logger.info(`Started request handling, request id: ${req._id}`)

  

  // pass `req` object into the nested call

  fakeDbAccess(req)

    .then((result) => res.json(result))

})


async function fakeDbAccess (req) {

  return new Promise((resolve) => {

    setTimeout(() => {

      logger.info(`Logs from fakeDbAccess, request id: ${req._id}`)

      resolve({ message: 'Hello world' })

    }, 0)

  })

}


app.listen(3000, (err) => {

  if (err) {

    logger.err('The app could not start')

  }

  logger.info('The app is listening on 3000')

})

////////////////////
How About Out-of-the-box solutions for my Belowed Express/Koa/another-web-framework?
As you already know, if you want to have request ids in your Node.js app, you may use cls-hooked and integrate it with the web framework that you are using. But probably you would want to use a library that would be doing this stuff.
Recently I was in search of such library and failed to find a good match for the task. Yes, there are several libraries that integrate web frameworks, e.g. Express, with CLS. On the other hand, there are libraries that provide request id generation middlewares. But I did not find a library that would combine both CLS and request ids in order to solve the request id tracing problem.
So, ladies and gentlemen, please meet cls-rtracer, a small library that solves a not-so-small problem. It provides middlewares for Express and Koa that implement CLS-based request id generation and allows to obtain request ids anywhere on your call chain.
The integration with cls-rtracer basically requires two steps. The first one — attach the middleware in the appropriate place. The second — configure your logging library.
That’s how it might look like in case of an Express-based app:

////////////////////////////
'use strict'

const rTracer = require('cls-rtracer')

// that how you can configure winston logger

const { createLogger, format, transports } = require('winston')
const { combine, timestamp, printf } = format

// a custom format that outputs request id
const rTracerFormat = printf((info) => {
  const rid = rTracer.id()
  return rid
    ? `${info.timestamp} [request-id:${rid}]: ${info.message}`
    : `${info.timestamp}: ${info.message}`
})

const logger = createLogger({
  format: combine(
    timestamp(),
    rTracerFormat
  ),
  transports: [new transports.Console()]
})

// now let's configure and start the Express app

const express = require('express')

const app = express()
app.use(rTracer.expressMiddleware())

app.get('/', function (req, res) {
  logger.info('Starting request handling')
  fakeDbAccess()
    .then((result) => res.json(result))
})

async function fakeDbAccess () {
  return new Promise((resolve) => {
    setTimeout(() => {
      logger.info('Logs from fakeDbAccess')
      resolve({ message: 'Hello from cls-rtracer Express example' })
    }, 0)
  })
}

app.listen(3000, (err) => {
  if (err) {
    logger.err('The app could not start')
  }
  logger.info('The app is listening on 3000')
})










Comments

Post a Comment

Popular posts from this blog

Understand Angular’s forRoot and forChild

  forRoot   /   forChild   is a pattern for singleton services that most of us know from routing. Routing is actually the main use case for it and as it is not commonly used outside of it, I wouldn’t be surprised if most Angular developers haven’t given it a second thought. However, as the official Angular documentation puts it: “Understanding how  forRoot()  works to make sure a service is a singleton will inform your development at a deeper level.” So let’s go. Providers & Injectors Angular comes with a dependency injection (DI) mechanism. When a component depends on a service, you don’t manually create an instance of the service. You  inject  the service and the dependency injection system takes care of providing an instance. import { Component, OnInit } from '@angular/core'; import { TestService } from 'src/app/services/test.service'; @Component({ selector: 'app-test', templateUrl: './test.component.html', styleUrls: ['./test.compon...
Post a Comment
Read more

4 Ways to Communicate Across Browser Tabs in Realtime

1. Local Storage Events You might have already used LocalStorage, which is accessible across Tabs within the same application origin. But do you know that it also supports events? You can use this feature to communicate across Browser Tabs, where other Tabs will receive the event once the storage is updated. For example, let’s say in one Tab, we execute the following JavaScript code. window.localStorage.setItem("loggedIn", "true"); The other Tabs which listen to the event will receive it, as shown below. window.addEventListener('storage', (event) => { if (event.storageArea != localStorage) return; if (event.key === 'loggedIn') { // Do something with event.newValue } }); 2. Broadcast Channel API The Broadcast Channel API allows communication between Tabs, Windows, Frames, Iframes, and  Web Workers . One Tab can create and post to a channel as follows. const channel = new BroadcastChannel('app-data'); channel.postMessage(data); And oth...
Post a Comment
Read more

Working with Node.js streams

  Introduction Streams are one of the major features that most Node.js applications rely on, especially when handling HTTP requests, reading/writing files, and making socket communications. Streams are very predictable since we can always expect data, error, and end events when using streams. This article will teach Node developers how to use streams to efficiently handle large amounts of data. This is a typical real-world challenge faced by Node developers when they have to deal with a large data source, and it may not be feasible to process this data all at once. This article will cover the following topics: Types of streams When to adopt Node.js streams Batching Composing streams in Node.js Transforming data with transform streams Piping streams Error handling Node.js streams Types of streams The following are four main types of streams in Node.js: Readable streams: The readable stream is responsible for reading data from a source file Writable streams: The writable stream is re...
Post a Comment
Read more