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

How to use Ngx-Charts in Angular ?

Charts helps us to visualize large amount of data in an easy to understand and interactive way. This helps businesses to grow more by taking important decisions from the data. For example, e-commerce can have charts or reports for product sales, with various categories like product type, year, etc. In angular, we have various charting libraries to create charts.  Ngx-charts  is one of them. Check out the list of  best angular chart libraries .  In this article, we will see data visualization with ngx-charts and how to use ngx-charts in angular application ? We will see, How to install ngx-charts in angular ? Create a vertical bar chart Create a pie chart, advanced pie chart and pie chart grid Introduction ngx-charts  is an open-source and declarative charting framework for angular2+. It is maintained by  Swimlane . It is using Angular to render and animate the SVG elements with all of its binding and speed goodness and uses d3 for the excellent math functio...
Post a Comment
Read more

JavaScript new features in ES2019(ES10)

The 2019 edition of the ECMAScript specification has many new features. Among them, I will summarize the ones that seem most useful to me. First, you can run these examples in  node.js ≥12 . To Install Node.js 12 on Ubuntu-Debian-Mint you can do the following: $sudo apt update $sudo apt -y upgrade $sudo apt update $sudo apt -y install curl dirmngr apt-transport-https lsb-release ca-certificates $curl -sL https://deb.nodesource.com/setup_12.x | sudo -E bash - $sudo apt -y install nodejs Or, in  Chrome Version ≥72,  you can try those features in the developer console(Alt +j). Array.prototype.flat && Array.prototype. flatMap The  flat()  method creates a new array with all sub-array elements concatenated into it recursively up to the specified depth. let array1 = ['a','b', [1, 2, 3]]; let array2 = array1.flat(); //['a', 'b', 1, 2, 3] We should also note that the method excludes gaps or empty elements in the array: let array1 ...
Post a Comment
Read more

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