Tracing NodeJS Services with Open Telemetry

In the first two articles in this series we took a crash course in instrumenting a small three service system using Zipkin. Today we’re going to take a look at using OpenTelemetry to do that same thing, and then we’ll export those same metrics to Zipkin.

This article assumes you’ve read those previous two articles, have NodeJS installed on your computer, and have a Zipkin service up and running at localhost:9411. If you’re not sure where to start part 1 of this series has everything you’ll need.

Also, the final version of the programs you’ll build in this articles are available on GitHub. We recommend working your way through the example in order to see how things are built, piece by piece, but if you need the final source it’s there for you.

The Service

We’ll start by creating a new project and installing express

$ mkdir new-project
$ cd new-project
$ npm init -y
$ npm install express

and then creating a small express service in a file named hello.js

// File: hello.js
const express = require('express')
const app = express()
const port = 3000

app.get('/hello', async function (req, res) {
  // send back hello message
  res.type('json')
  res.send(JSON.stringify({hello:"world"}))
})

app.listen(
  port,
  function() {
    console.log(`Example app listening at http://localhost:${port}`)
  }
)

If we run the above program

$ node hello.js
Example app listening at http://localhost:3000

we’ll be able to fetch the contents from its sole URL

$ curl http://localhost:3000/hello
{"hello":"world"}

We now have a simple service, ready for tracing.

The Tracer

An OpenTelemetry tracer works similarly to a Zipkin tracer. Outgoing HTTP requests have a trace ID added to them, and incoming HTTP requests look-for-or-generate a trace ID. However, how we accomplish this with OpenTelemetry looks a lot different than how we do this with Zipkin.

OpenTelemetry requires that end-user-programmers

1. Instantiate a trace provider

2. Configure that trace provider with an exporter

3. Install OpenTelemetry plugins to instrument specific node module(s)

A trace provider is the global “hey, we’re going to instrument stuff” object. An exporter is an object that will send telemetry data to another system where you can view it. An OpenTelemetry plugin will perform the act of instrumenting functions and methods from a NodeJS package.

These plugins are one of the biggest differences between OpenTelemetry and a system like Zipkin. Zipkin made us add a middleware to Express ourselves, and replace our fetch function with a wrapped version. With OpenTelemetry, the plugins will do this work for us.

Instrumenting the Service

We’ll start by creating our trace provider and configuring it with an exporter. To do this, we’ll need to install the OpenTelemetry auto instrumentation package for NodeJS

$ npm install @opentelemetry/node

Then, before we require any other modules, we’ll add the following code to the start of our program

// File: hello.js
const { NodeTracerProvider } = require('@opentelemetry/node');
const { ConsoleSpanExporter, SimpleSpanProcessor } = require('@opentelemetry/tracing');

const provider = new NodeTracerProvider();
const consoleExporter = new ConsoleSpanExporter();
const spanProcessor = new SimpleSpanProcessor(consoleExporter);
provider.addSpanProcessor(spanProcessor);
provider.register()

const express = require('express')

/* ... */

This code creates a trace provider and adds a span processor to it. The trace processor requires an exporter, so we instantiate that as well. Don’t worry too much about the difference between a span processor and an exporter right now — just know that they both are responsible for getting the telemetry data out of your service and into another system. In this case “the system” is your console window.

Instrumenting the Modules

With the above code in place, we technically have a traced program. However, without any plugins installed, there will be no spans generated.

All we need to do to add a plugin is npm install it into our project. The NodeTraceProvider object is smart enough to notice the presence of a plugin and load it.

So, let’s install the http plugin

$ npm install @opentelemetry/plugin-http

Then, we’ll start our service

$ node hello.js
PluginLoader#load: trying to load http@14.2.0
PluginLoader#load: trying to load express@4.17.1
PluginLoader#load: could not load plugin @opentelemetry/plugin-express of module express. Error: Cannot find module '@opentelemetry/plugin-express'
Require stack:
- /path/to/our/app/node_modules/@opentelemetry/node/build/src/instrumentation/PluginLoader.js
- /path/to/our/app/node_modules/@opentelemetry/node/build/src/NodeTracerProvider.js
- /path/to/our/app/node_modules/@opentelemetry/node/build/src/index.js
- /path/to/our/app/hello.js
Example app listening at http://localhost:3000

We’ll ignore those OpenTelemetry warnings for now, and instead make a request into our service

$ curl http://localhost:3000/hello
{"hello":"world"}

If we take a look at the terminal window where our service is running, we’ll see an exported span.

{
  traceId: 'edb9cefd1dfaf04bb866cfc559f06c16',
  parentId: undefined,
  name: 'GET /hello',
  id: '4b2e7586cc47abf4',
  kind: 1,
  timestamp: 1592157739675988,
  duration: 6413,
  attributes: {
    'http.url': 'http://localhost:3000/hello',
    'http.host': 'localhost:3000',
    'net.host.name': 'localhost',
    'http.method': 'GET',
    'http.route': '/hello',
    'http.target': '/hello',
    'http.user_agent': 'curl/7.54.0',
    'http.flavor': '1.1',
    'net.transport': 'IP.TCP',
    component: 'http',
    'net.host.ip': '::1',
    'net.host.port': 3000,
    'net.peer.ip': '::1',
    'net.peer.port': 51927,
    'http.status_code': 200,
    'http.status_text': 'OK'
  },
  status: { code: 0 },
  events: []
}

Congratulations — you just instrumented a service using OpenTelemetry.

Core Plugins and Contrib Plugins

The plugin we installed, @opentelemetry/plugin-http, instruments NodeJS’s http module. The http module is where APIs for NodeJS’s underlying HTTP handling (both sending requests, and handling requests) lives. Rather then attempt to instrument every new web framework, the OpenTelemetry project instruments this http module and its counterpart https module (for secure connections). By instrumenting these modules OpenTelemetry ends up with basic instrumentation for any web framework that uses these two packages. (express, restify, fastify, etc.)

The http and https plugins are distributed via the main OpenTelemetry repository, along with similar plugins for the two most popular GRPC libraries. There’s also an XmlHttpRequest plugin for browser based applications.

The core job all of these plugins have is to “bind” each individual request to a single trace. Defining what “binding” actually means is beyond the scope of this article, but in oversimplified terms it’s making sure that trace IDs are added to outgoing requests, and then read-or-created for incoming requests.

In addition to these core plugins, the OpenTelemetry project also has a contrib repository which contains additional instrumentation for popular frameworks. When we started our program earlier, we saw a warning from OpenTelemetry

PluginLoader#load: trying to load express@4.17.1
PluginLoader#load: could not load plugin @opentelemetry/plugin-express of module express. Error: Cannot find module '@opentelemetry/plugin-express'

This was OpenTelemetry telling us it had detected the express module, but couldn’t find the corresponding OpenTelemetry @opentelemetry/plugin-express plugin. Let’s install that plugin right now

$ npm install @opentelemetry/plugin-express

You can find the source for this plugin in the contrib repository.

If we run our program with this module installed, we’ll no longer see the warnings when we startup our service.

$ node hello.js
PluginLoader#load: trying to load http@14.2.0
PluginLoader#load: trying to load express@4.17.1
Example app listening at http://localhost:3000

Exporting to Zipkin

While it’s neat, spans in a terminal window are a poor way to have visibility into a service. In our code above, the following lines are what added a console exporter to our system

// File: hello.js

const consoleExporter = new ConsoleSpanExporter();
const spanProcessor = new SimpleSpanProcessor(consoleExporter);
provider.addSpanProcessor(spanProcessor);

We created an exporter, then used that exporter when creating a span processor, and then added that span processor to our trace provider. Let’s do the same for a Zipkin exporter. First, we’ll need to install the OpenTelemetry package that implements the Zipkin exporter

$ npm install @opentelemetry/exporter-zipkin

Then, we’ll add the following lines to the instrumentation code at the start of the program.

// File: hello.js

const { ZipkinExporter } = require('@opentelemetry/exporter-zipkin');
/* ... */
const zipkinExporter = new ZipkinExporter({
    url: 'http://localhost:9411/api/v2/spans',
    serviceName: 'service-hello'
});
const zipkinProcessor = new SimpleSpanProcessor(zipkinExporter)
provider.addSpanProcessor(zipkinProcessor)

const express = require('express')

Here we’re instantiating a Zipkin exporter, and then adding it to the trace provider. You can have as many different exporters configured as you like — we don’t need to remove our console exporter. With the above in place, and your Zipkin system up and running at localhost:9411, let’s start our application back up

$ node hello.js
PluginLoader#load: trying to load http@14.2.0
PluginLoader#load: trying to load express@4.17.1
Example app listening at http://localhost:3000

and request some URLs.

$ curl http://localhost:3000/hello
{"hello":"world"}

$ curl http://localhost:3000/hello
{"hello":"world"}

If we hop over to the Zipkin UI and search for recent traces, we’ll see we’ve recorded a single service trace.

However — if we click through to the trace details, we’ll see these traces do not look like the traces we’ve previously seen.

What’s going on?

A Span in not a Service

In our previous Zipkin examples — one span equaled one service. However — a “span” is just a span of time that’s related to other spans of time. We can use a span to measure any individual part of our service as well.

The express auto-instrumentation plugin creates spans that measure actions within the express framework. How long each middleware took to execute, how long your express handler took to execute, etc. It gives you insights not just into what’s going on with the service as a whole, but also individual parts of your express system. This is the role most of the contrib plugins play in the OpenTelemetry project. The core plugins are concerned with ensuring each request is bound to a single trace, but the contrib plugins will create spans (or metrics!) specific to the behavior of a particular framework.

Instrumenting HTTP

You can also use OpenTelemetry to instrument a distributed system. Let’s create a second service in a file named main.js.

// File: main.js

const { NodeTracerProvider } = require('@opentelemetry/node');
const { ConsoleSpanExporter, SimpleSpanProcessor } = require('@opentelemetry/tracing');
const { ZipkinExporter } = require('@opentelemetry/exporter-zipkin');

const provider = new NodeTracerProvider();
const consoleExporter = new ConsoleSpanExporter();
const spanProcessor = new SimpleSpanProcessor(consoleExporter);
provider.addSpanProcessor(spanProcessor);

const zipkinExporter = new ZipkinExporter({
  url: 'http://localhost:9411/api/v2/spans',
  serviceName: 'service-main'
});
const zipkinProcessor = new SimpleSpanProcessor(zipkinExporter)
provider.addSpanProcessor(zipkinProcessor)
provider.register()

const express = require('express')
const app = express()
const port = 3001

const getUrlContents = function(url, fetch) {
  return new Promise((resolve, reject)=>{
    fetch(url)
    .then(res => res.text())
    .then(body => resolve(body));
  })
}

app.get('/main', async function (req, res) {
  // fetch data from second service running on port 3001
  const results = await getUrlContents('http://localhost:3000/hello', require('node-fetch'))
  res.type('json')
  res.send(JSON.stringify({hello:results}))
})

app.listen(
  port,
  function() {
    console.log(`Example app listening at http://localhost:${port}`)
  }
)

This service users the node-fetch library to call our first service. We’ve also instrumented this service with almost identical code — the only thing that’s different is we’ve named this service service-main.

// File: main.js
const zipkinExporter = new ZipkinExporter({
  url: 'http://localhost:9411/api/v2/spans',
  serviceName: 'service-main'
});

So lets get node-fetch added to our project so our HTTP request works

$ npm install node-fetch

If we start each service in a separate terminal

$ node hello.js

/* ... */

$ node main.js

and call the new service, we can see the combined contents returned.

$ curl http://localhost:3001/main

Then, if we take a look at the trace in Zipkin

we can see each span from the services are linked together. The OpenTelemetry http plugin took care of this for us. The node-fetch plugin uses the underlying functionality of NodeJS’s http and https to make requests. Unlike Zipkin, we don’t need to manually wrap the fetch function.

Wrap Up

So that’s how to instrument an application using the current version of OpenTelemetry. We have, however, only scratched the surface of what’s going on with OpenTelemetry. In our next few articles we’ll take a look at the project as a whole, and examine the underlying objects that plugins use to instrument an application.