Node.JS and Observability

Javascript is a pretty prolific programming language, used daily by people visiting any number of websites and web applications. NodeJS, it’s server-side version, is also used all over the place. You’ll find it deployed as full application stacks to functions in things like AWS Lambda, or even as IoT processes with things like Johnny Five.

So when we think about Observability in the context of a nodejs stack, how do we set it up and get the information flowing? Well, we’ll need to get Node.js logs, metric data, and tracing data between our different components. In the next few hundred words we shall set theses up and have meaningful observability of our codebase.

ELK Stack Calculator
How much are you spending on managing your own ELK Stack?

Node.js Logs

In general, developers using Javascript are used to putting console.log everywhere to see what’s going on whilst they’re coding and then upgrading to something more structured for logging when the application is more fleshed out. So let’s follow that.

Personally, once I’ve progressed from simple debugging statements and I want to gather information in a more meaningful way, I move to Pino or Winston. As Winston is the most common, we’ll use that for the examples. It’s pretty easy getting started.

We add the dependency npm i -S winston and then create the logger. The simplest and minimum version of the logger is:

const logger = winston.createLogger({
  transports: [
    new winston.transports.Console(),
  ]
});

Then to actually add messages to logger, we simply use the following to add at the appropriate loglevel:

logger.info("127.0.0.1 - just a little information about home");
logger.warn("127.0.0.1 - a warning about home");
logger.error("127.0.0.1 - home is throwing an error");
logger.debug("127.0.0.1 - helps find bugs at home");

Winston & Transporters

Now in the above example, we’re outputting to console, just like console.log which is great when building the app or tailing the log off a container. If you are using Docker or Kubernetes to deploy your application, you can follow our simple guides here https://docs.logz.io/shipping/log-sources/docker.html and https://docs.logz.io/shipping/log-sources/kubernetes.html to move those tailed Node.js logs to Logz.io.

But what if you want more control of which logs go where, or you can’t tail what’s been sent to stdout?

Winston uses the concept of transporters to give you greater control, or even just redundancy, by sending the information to different sources. So what if we wanted to save it to a file, we can do:

const logger = winston.createLogger({
  transports: [
    new winston.transports.Console({ level: 'error' }),
    new winston.transports.File({
      filename: 'combined.log',
      level: 'info'
    })
  ]
});

In this example, the console will receive just the errors, and all the information levels are sent to the combined.log. If we then want to send your Node.js app logs to Logz.io to take advantage of Kibana and all its goodness we can simply add the Logz.io transporter.

To add it, just npm i -S winston-logzio and then the logger would look like

const LogzioWinstonTransport = require('winston-logzio');
const logzioWinstonTransport = new LogzioWinstonTransport({
  name: 'winston_logzio',
  token: process.env.SHIPPING_TOKEN,
  host: `${process.env.LISTENER_URI}:5015`,
});
const logger = winston.createLogger({
  transports: [
    new winston.transports.Console({ level: 'error' }),
    new winston.transports.File({
      filename: 'combined.log',
      level: 'info'
    })
    logzioWinstonTransport,
  ]
});

In this example, we’re still returning the errors to the console, all the info to the log file, but now we’re sending all Node.js logs defined in the application to Logz.io via the Winston Transporter. We’re simply defining the name so that we know what to look for within Kibana as where the logs came from, the Logz.io Token used to ship to the correct account, and the listener endpoint that we want processing Node.js application logs.

Node.js Metrics

Metric data is super important to know how your application/services are behaving at a given point, telling you if they’re choking for resources or simply if they’re even alive. Luckily when it comes to configuring and capturing metric data you don’t have to go digging within your source code to capture a lot of the pertinent information.

Withing the ELK stack we’ve got two candidates for capturing our metric data, as the example application I created is using Docker with Docker Compose the simplest way is to use our docker container. We’ve got a full guide at <insert link here> which walks through all the different configuration options for the docker container, but for me it was simply `docker pull logzio/docker-collector-metrics` which fetches the docker image for use on my laptop, and then the following to add it to my docker-compose.yml:

  metricsmonitor:
    image: logzio/docker-collector-metrics
    environment:
     - LOGZIO_MODULES=docker
     - LOGZIO_TOKEN=${LOGZIO_METRICS_TOKEN}
    volumes:
     - /var/run/docker.sock:/var/run/docker.sock:ro

Here I’m assigning this to metricsmonitor for it’s name, then I’m configuring the image to use the `docker` module for capturing data, giving it the metrics token from an `.env` file, and finally mounting the hosts `docker.sock` so it can sampe the data from the host for all the individual docker clients.

Metricbeat & Docker

Now if we want specific metric data for the processes within the docker container rather than the general resources it’s using of the host machine, we need to get a bit more creative.

Here I’m assigning this to metricsmonitor for its name, then I’m configuring the image to use the `docker` module for capturing data from the containers and `system` to get the host usage, giving it the metrics token from an .env file, and finally mounting the hosts `docker.sock` so it can sample the data from the host for all the individual docker containers.

If you are running just on a server, and you want to know the state of the processes on said server (including your application) you could use Metricbeat. Metricbeat is part of the suite of Beat tools to handle sending data to the ELK stack, and in this case we have a handy metrics guide on how to install and configure Metricbeat on the machine in question.

Node.js & Tracing

If you haven’t heard of tracing before, this quote describes it well:

Distributed tracing, also called distributed request tracing, is a method used to profile and monitor applications, especially those built using a microservices architecture. Distributed tracing helps pinpoint where failures occur and what causes poor performance.

What is tracing?

What this means is you can see the flow of your application and the impacts that different components or services have on each other.

Here at Logz.io we’re currently preparing Jaeger for our users to consume, as well as dog food internally, so it’s what I’ll be using for this example. Jaeger itself is a distributed tracing tool started at Uber and now governed by the Cloud Native Compute Foundation (CNCF).

So how easy is it to implement tracing? In reality, it’s not too hard to start capturing the spans that make up a trace. In this case, we’ll be adding Jaeger to a simple express app that will use middleware to capture all the inbound requests. Firstly we’ll need Jaeger & the OpenTracing client, as Jaeger is OpenTracing compliant and it’s the recommended configuration when being used over HTTP. To install the two libraries simply npm i -S opentracing jaeger-client, once you’ve got these we’ll want to configure the tracer as such:

const opentracing = require('opentracing');
const initTracer = require('jaeger-client').initTracer;
const config = {
  serviceName: 'Node.js-image-save',
  reporter: {
    collectorEndpoint: 'http://jaegercollector:14268/api/traces',
  },
  sampler: {
    type: 'const',
    param: 1
  }
};
const options = {
  tags: {
    'Node.js-image-save.version': '0.0.0',
  },
};
const tracer = initTracer(config, options);
opentracing.initGlobalTracer(tracer);

Here we’ve initiated the tracer and applied the settings globally for the application, and in those settings, we’ve set the name of the service for use within Jaeger Queries as well as point our client at the locally hosted Jaeger collector, and just for good measure we’ve set the sampler to 1 during this dev setup to force the sampling of every span sent.

In the middleware itself ,we’re doing something a little special:

// Tracing middleware
app.use((req, res, next) => {
  const tracer = opentracing.globalTracer();
  const wireCtx = tracer.extract(opentracing.FORMAT_HTTP_HEADERS, req.headers)
  // Creating our span with context from incoming request
  const span = tracer.startSpan(req.path, { childOf: wireCtx })
  // Use the log api to capture a log
  span.log({ event: 'request_received' })
  // Use the setTag api to capture standard span tags for http traces
  span.setTag(opentracing.Tags.HTTP_METHOD, req.method)
  span.setTag(opentracing.Tags.SPAN_KIND, opentracing.Tags.SPAN_KIND_RPC_SERVER)
  span.setTag(opentracing.Tags.HTTP_URL, req.path)
  // include trace ID in headers so that we can debug slow requests we see in
  // the browser by looking up the trace ID found in response headers
  const responseHeaders = {}
  tracer.inject(span, opentracing.FORMAT_HTTP_HEADERS, responseHeaders)
  res.set(responseHeaders)
  // add the span to the request object for any other handler to use the span
  Object.assign(req, { span })
  // finalize the span when the response is completed
  res.on('finish', () => {
    if (res.statusCode >= 500) {
      // Force the span to be collected for http errors
      span.setTag(opentracing.Tags.SAMPLING_PRIORITY, 1)
      // If error then set the span to error
      span.setTag(opentracing.Tags.ERROR, true)
      // Response should have meaning info to further troubleshooting
      span.log({ event: 'error', message: res.statusMessage })
    }
    // Capture the status code
      span.setTag(opentracing.Tags.HTTP_STATUS_CODE, res.statusCode)
      span.log({ event: 'request_end' })
      span.finish()
    });
  next();
});

Tracing: Linking the Spans

Firstly, instead of resetting the tracer for each route, we’re using the globally configured tracer.

After that, to make all the spans link together within the same trace we use the headers to create a context const wireCtx = tracer.extract(opentracing.FORMAT_HTTP_HEADERS, req.headers) and apply that to the span beneath. Next we’re setting the request header information as tags for use within Jaeger.

And finally, once the request is complete with res.on(‘finish’, () => {…}); we’re checking if the request has errored, and if it has we’re capturing it and it’s state so we can tell in Jaeger which requests are failing within the Jaeger queries.

As our code is set up to send to a Jaeger Collector we need one to capture and sample the information to be then sent to storage for use to run Jaeger queries against. To run this locally and see what’s happening with your application you can use the Jaeger All-in-one container:

  jaegercollector:
    image: jaegertracing/all-in-one:latest
    ports:
      - "5775:5775/udp"
      - "6831:6831/udp"
      - "6832:6832/udp"
      - "5778:5778"
      - "16686:16686"
      - "14268:14268"
      - "9411:9411"

This is an all in one container with the Jaeger Collector and Jaeger UI all in one place for your convenience. Now if you’d like to send the data to Logz.io to take advantage of all the data being in one place you’ll need to use our convenient Jaeger Collector:

  jaegercollector:
    image: logzio/jaeger-logzio-collector
    environment:
      - ACCOUNT_TOKEN=${LOGZIO_TRACING_TOKEN}
    ports:
      - "14268:14268"
      - "9411:9411"
      - "14269:14269"
      - "14250:14250"

Once again, we’re taking advantage of the .env to handle passing the correct Account Token to the container, and then the container handles the authentication with the Logz.io infrastructure for you in. Making it quite simple fire-and-forget.

If you’d like to look at the complete demo, you can head to https://github.com/ukmadlz/Node.js-observability for an example. And you can easily replicate part or all of this in your own application.

What about the data?

That’s an entire series of posts on how to interpret the data within the different tools we at Logz.io provide for you. But if you’re excited to crack on and learn how to do it, might I suggest these guides to get started with:

ELK Stack Calculator
Python. Go. Node. Java. Ship Your Logs Straight from Code with Logz.io!

Stay updated with us!

By submitting this form, you are accepting our Terms of Use and our Privacy Policy

Thank you for subscribing!

Internal