Distributed logging with Express.Js, Request, and Winston

Which do you think is easier to debug, a standalone application or a distributed system? Even ignoring problems like dropped messages or crashing servers, distributed systems are much harder to debug. Why? Because it’s much harder to see what’s going on inside the system.

With a standalone application you can look at the logs and trace a request coming in to the response going out.

distributed tracing user application

But in a distributed system each request from an external user may require work by multiple processes. Each process inside the distributed system will generate its own logs. Instead of reading a single source of logs you need to read the logs from multiple sources.

distributed tracing microservices

Distributed Tracing to the Rescue

How can you make reading the logs from a distributed system as easy as in a standalone application?

First, you need to make the aggregate logs available in a single place. Second, you need to ensure that all the logs for a single request are connected into a single trace.

Step 1: aggregating the logs

Let’s say you have a couple of Node microservices written using Express.js, using the Winston logging library. When frontend.js receives a request it sends a request over to backend.js:

var express = require('express');
var request = require('request');
var winston = require('winston');

var app = express();

app.get('/frontend-api', function(req, res) {
    winston.info('Sending internal request to backend...');
    request("http://backend/internal-api", function(error, response, body) {
        var rendered = renderBackendData(body);
        res.send(rendered);
    });
});

// etc.

The backend.js server has some logic of its own, and its own logging:

// ...

app.get('/internal-api', function(req, res) {
   winston.info("Got internal request, processing...");
   res.send(myBusinessLogic());
});

How do you get those logs into a central location? Using Datawire’s Microservices Development Kit you can easily route the logs to Datawire’s SaaS server, by adding just a few lines of code to each server. For example, we updatebackend.js like so:

// ... existing code ...

var mdk_express = require('datawire_mdk_express');
var mdk_winston = require('datawire_mdk_winston');
// Route Winston logging to the MDK:
winston.add(mdk_winston.MDKTransport, {mdk: mdk_express.mdk,
                                       name: 'backend-myapp'});

app = express()
// Add MDK middleware to Express:
app.use(mdk_express.mdkSessionStart);

// ... rest of the code is unchanged ...

With just these 5 lines of code added to frontend.js and backend.js all the logs will be routed to Datawire’s Mission Control servers:

distributed tracing microservices 2

So far we can still only view logs on a per-service basis. Next we’ll combine the logs from different processes so we can trace a request as it crosses multiple servers.

Step 2: tracing across processes

In order to trace an external request within the distributed system you need to include a trace identifier that will be passed to all processes handling the same request. You can do this, for example, by including an extra HTTP header with each request within your distributed system.

The MDK includes a wrapper for the request.js HTTP client that does this automatically. Just userequire('datawire_mdk_express').request instead of require('request') in your code. Here’s what the updatedfrontend.js server looks like:

var express = require('express');
var winston = require('winston');
var mdk_express = require('datawire_mdk_express');
// Use MDK's request.js wrapper:
var request = mdk_express.request;
var mdk_winston = require('datawire_mdk_winston');


winston.add(mdk_winston.MDKTransport, {mdk: mdk_express.mdk,
                                       name: 'myapp-frontend'});
var app = express();
app.use(mdk_express.mdkSessionStart);

// ... remaining code is unchanged ...

Now, when we send a request to the frontend server we can see the logs from both the frontend request and the backend request in one single trace within the MDK :

datawire tracing screenshot

We can do this because we’re storing the logs not per-service, but per external user request:

datawire tracing microservices 3

Polyglot distributed sessions

You can find existing tracing systems for JavaScript, of course, but they suffer from two limitations: they’re language-specific and logging-specific. While the MDK can work just fine as a JavaScript tracing system, it also provides more power and flexibility if and when you need it.

  • One of the benefits of a distributed system is the ability to use different languages for different components. While all the examples above were in JavaScript, the MDK also supports Java, Python and Ruby, with more languages coming in the future.
  • The MDK’s logging functionality is built on a more general-purpose abstraction: distributed sessions. A distributed session allows you to set an overall deadline for all of the processing of an external request, share authentication credentials, etc..

Give it a try!

Here’s how you can try this out with your code.

First, install the requirements: npm install datawire_mdk datawire_mdk_express datawire_mdk_request datawire_mdk_winston

Next, modify your code:

  1. Initialize the MDK support for express.js:
    var mdk_express = require('datawire_mdk_express');
    
    app = express();
    app.use(mdk_express.mdkSessionStart);
  2. Initialize MDK support for winston: javascript var mdk_winston = require('datawire_mdk_winston'); winston.add(mdk_winston.MDKTransport, {mdk: mdk_express.mdk, name: 'your-process-name'});
  3. Switch to the MDK request.js wrapper for communication within your application. Instead of var request = require('request'); you should do var request = mdk_express.request;.

Then, you’ll need an access token:

  1. Sign up for an account at app.datawire.io.
  2. Once you’ve got an account, click the “Organization” drop-down in the top-left and choose Token.
  3. Click the first “Copy to Clipboard” button.
  4. You know have your access token in your clipboard; set it for a terminal session by doing export DATAWIRE_TOKEN=<value in clipboard>.

You can now run your servers and see trace logging in the app.datawire.io UI.

Interested in getting notified as we support more frameworks, or add new features? We’d love to hear from you.