Request Tracing in Node.js

Theres a saying that software developers like us spend 90% of our time on debugging, and only 10% of our time actually writing code. This is a bit of an exaggeration! It is true that debugging is a significant part of our work, though, especially in this era of microservices architecture. Today, its not unusual for us to have hundredseven thousandsof microservices running simultaneously in our production servers.

Traditionally, we rely on logs when it comes to debugging software problems. However, not all logs are helpful. They can be unspecific, for example, indicating only the error status code or showing a generic error, such as Something went wrong. Even if the log records a more specific errorlike User request id is invalid with a 400 bad request errorit can still take us hours or days to figure out the root cause of the problem due to the high number of services involved. This is where request tracing comes into play.

By applying request tracing in our Node.js application, we can see the flow of the problematic error represented visually. This helps us to pinpoint which services may be involved in the error, and find the root cause of the problem quickly. In this article, well define request tracing, explore its importance, and look at how we can efficiently apply request tracing in our Node.js application.

What Is Request Tracing?

Request tracing refers to the technique of finding subrequests from the multiple services that are triggered when a single request is made. In a microservices architecture, especially in a distributed application, a service often needs to integrate with other services, databases, or third-party dependencies. As a result, when a request is executed, inner requests are triggered too.

Why We Need Request Tracing

In order to debug an error, we need to understand how the request that generated the error is created. Logs alone are not enough; they only tell us which error type has occurred, but do not tell us the context of the issue.

Traces, on the other hand, show us the requests executed inside a single parent request. We can also see the request that was made immediately before the parent's request. In short, request tracing provides us with an overview of the request process. By combining traces with logs, we can identify the root cause of the problem. Moreover, tracing reduces our debugging time since it helps to highlight the true origin of an issue in a simple and quick way by passing log error cascades.

An Amplication Request

Hey developer, while you're reading about request tracing, we have a request for you... We'd love to get a star from you on GitHub for Amplication. Think of it as a virtual high-five that makes our developer's hearts skip a beat. Plus, when we reach 10,000 stars, I've promised the team a pizza party. So, if you want to see some thrilled developers with tomato sauce on their faces, give us a on GitHub!

Please don't leave us hanging like a callback without a promise! So click that shiny star button and spread some Amplication love.

How Request Tracing Works

When a user performs an actionfor example, clicking the Confirm button to buy a shoe from an e-commerce storeseveral requests are executed. First, a new trace will be created after the user clicks Confirm. Then a parent span will be triggered. Inside the parent span, there could be an API request to check the authenticity of the user, and another API to confirm whether the user has permission to make the payment. Additional API requests could be executed, such as checking the number of shoes in stock is sufficient, or verifying that the user balance is high enough to make the payment.

These requests will all be captured and included in the parent span. As a result, we can see how these requests correlate to one another, and if a request fails, we can tell what happened immediately beforehand that may have acted as a trigger.
How to Implement Request Tracing for Node.js Applications.

To implement request tracing for the Node.js application, we need to assign a unique request ID for every request in the current service so that it will forward to other services. As a result, we can use this ID to trace and visualize requests across our system architecture and identify the root cause of the failure.

Common Tools that Support Request Tracing

There are a number of open source observability backend toolslike Jaeger, Zipkin, and Signozthat support storing and visualizing request traces. Previously, two popular standards existed for the traces format: OpenTracing and OpenCensus. Tools often only supported one or another, making it a challenge to integrate software applications with the tools they need. Fortunately, OpenTracing and OpenCensus unified into OpenTelemetry in 2019, allowing software developers to implement request tracing with relative ease.

OpenTelemetry is a vendor-agnostic collection of tools that can visualize traces, collect data on the time spent processing each request, and capture the requests as individual spans in traces. In order for different observability tools to visualize traces, applications need to follow OpenTelemetry formats.

Implement Request Tracing as a Middleware

Lets say we have an application that lets users create blog posts to review movies. The application will provide APIs for users to create an account, log in, and create new blog posts.
We will use OpenTelemetry to apply request tracing for the application. The traces then will be forwarded to Jaeger. Our application will use MongoDB as a database and Express as a web server. We need to install the following dependencies in order for OpenTelemetry to attach traces to the API request.

npm install --save @opentelemetry/apinpm install --save @opentelemetry/sdk-trace-nodenpm install --save opentelemetry-instrumentation-expressnpm install --save @opentelemetry/instrumentation-mongodbnpm install --save @opentelemetry/instrumentation-http

We also need to install the Jaeger dependency to forward OpenTelemetry traces to Jaeger so that we can view the traces via the Jaeger GUI page later.

npm install --save @opentelemetry/exporter-jaeger

To implement request tracing as a middleware, lets create a new file in the root directory of the project, named tracing.js. Copy the following code to the file:

const { Resource } = require("@opentelemetry/resources");const { SemanticResourceAttributes } = require("@opentelemetry/semantic-conventions");const { SimpleSpanProcessor } = require("@opentelemetry/sdk-trace-base");const { NodeTracerProvider } = require("@opentelemetry/sdk-trace-node");const { trace } = require("@opentelemetry/api");//exporterconst { JaegerExporter } = require("@opentelemetry/exporter-jaeger");//instrumentationsconst { ExpressInstrumentation } = require("opentelemetry-instrumentation-express");const { MongoDBInstrumentation } = require("@opentelemetry/instrumentation-mongodb");const { HttpInstrumentation } = require("@opentelemetry/instrumentation-http");const { registerInstrumentations } = require("@opentelemetry/instrumentation");//Exportermodule.exports = (serviceName) => {  const exporter = new JaegerExporter({    endpoint: "http://localhost:14268/api/traces",  });  const provider = new NodeTracerProvider({    resource: new Resource({      [SemanticResourceAttributes.SERVICE_NAME]: serviceName,    }),  });  provider.addSpanProcessor(new SimpleSpanProcessor(exporter));  provider.register();  registerInstrumentations({    instrumentations: [      new HttpInstrumentation(),      new ExpressInstrumentation(),      new MongoDBInstrumentation(),    ],    tracerProvider: provider,  });  return trace.getTracer(serviceName);};

In the code, well register instrumentation for the application to attach traces to MongoDB requests, Express server requests, and HTTP requests:

  instrumentations: [      new HttpInstrumentation(),      new ExpressInstrumentation(),      new MongoDBInstrumentation(),  ]

The traces will be sent to the Jaeger endpoint: http://localhost:14268/api/traces.
We also need to add one line of code to the entry file of the application in order to enable OpenTelemetry to send traces to the application:

const tracer = require("./tracing")("blog-movie-review-service");

Before we start our application to check for the request traces, we need to bring up the Jaeger service to store the traces. Run the following command to trigger the Jaeger service using Docker:

docker run -d --name jaeger \  -e COLLECTOR_ZIPKIN_HOST_PORT=:9411 \  -p 5775:5775/udp \  -p 6831:6831/udp \  -p 6832:6832/udp \  -p 5778:5778 \  -p 16686:16686 \  -p 14250:14250 \  -p 14268:14268 \  -p 14269:14269 \  -p 9411:9411 \  jaegertracing/all-in-one:1.32

Lets bring up the application, and then go to the Jaeger GUI page to see the captured traces.

Figure 1: Captured traces are shown in Jager GUI page

We can see that the traces have been captured by OpenTelemetry and are being stored in Jaeger. To check the trace related to the API request for creating a new blog post, click on the first trace (Figure 1) to bring up details (Figure 2).

Figure 2: Detail about the trace for success request to create a new post

Here, we can see inside the trace, there are spans for HTTP request (POST /v1/posts) and MongoDB request (mongodb.insert).
Lets see what a failed API request looks like when we provide an invalid authorId for the post:

Figure 3: Detail about the trace for failed request to create a new post

Here, we see that the API request failed to make an HTTP request because the application is verifying the validity of the authorId, and there is no request being sent to MongoDB to insert the blog post.
By applying request tracing to our application, we can easily debug the application and discover at which step in the API request the problem arises.

Best Practices for Request Tracing

As we have seen, applying request tracing for a Node.js application enables us to investigate software issues quickly and effectively. To achieve optimal request tracing results, we should follow three core best practices when applying request tracing for our application.

1. Follow OpenTelemetry Standard Formats

Following OpenTelemetry standard formats allows other tools that can integrate with OpenTelemetry (like Zipkin, Jaeger, or Prometheus) to store and visualize traces effectively. We can choose the tool that suits our specific needs, say, to achieve better visualization without applying a new trace format.

2. Choose a Unique String for Every Source

Choosing a unique string for every source allows us to trace the software issue quickly based on the unique string. Lets say we want to trace the failed API request for creating a new blog post in the demo application. From the application log, we obtained the unique trace ID used to make the API request. We can grab that unique trace ID and search Jaeger to obtain a full picture of what went wrong.

3. Choose an Appropriate Span Name

Choosing a span name that matches the name of the method invoked by the span allows us to figure out what was going on in the application when the problem occurred. We should also include a custom span tag to preserve the trace. This enables us to search for the custom tag directly, instead of having to locate the trace ID and then search for it.
For example, we can add a custom span tag for the trace related to creating a new blog post. When we need to investigate an issue related to creating blog posts, we can use the custom span tag, and all the traces for creating new movie review posts will be displayed instantly.

Conclusion

In the world of distributed software and microservice architecture, an application log alone is not enough to debug when a problem arises. To achieve observability so that we can debug software problems quickly, we need to implement request tracing in our Node.js application. OpenTelemetrys standard tracing format makes achieving traceability easy, since we can simply make use of one of the many tools readily available to aid in the request tracing process.