@advinans/plack

fluentd-gcp compatible Stackdriver logging for node

Logs from applications running in a Kubernetes cluster are automatically picked up a fluentd daemon set if Stackdriver logging is enabled. By formatting these logs as JSON objects, proper Stackdriver LogEntry objects are created, including HttpRequest properties and severity levels.

This is a small library to log JSON log entries in this format, based on pino. Pino uses the Bunyan log format, but with some small tweaks we can make it talk Stackdriver. It maps pino log levels to Stackdriver severity levels, and adds notice, alert and emergency severities.

The fluentd instance (as of 2018-01-18) does not convert all fields in the JSON payload to LogEntry fields. See below for information about what gets picked up. This project defines an interface for log entries with these fields.

Also included is a pretty printer for local development called plack. You can pipe log output through this utility. It doesn't have a lot of configuration.

$ node my-program.js | plack
[2018-02-28T13:43:23+01:00] INFO server up and listening on port 8080
[2018-02-28T13:43:23+01:00] INFO Updated user account
    userAccountId: "6fba0a63-f544-4cd8-becd-08e30dc47831"
[2018-02-28T13:43:23+01:00] INFO
    GET http://example.com/some/info?color=red
      requestSize: "3000"
      status: 200
      responseSize: "1000"
      userAgent: "Mozilla/4.0 (compatible; MSIE 6.0; Windows 98; Q312461; .NET CLR 1.0.3705)"
      remoteIp: "192.168.1.1"
      referer: "http://example.com/refererr"
      latency: "3.5s"

    field: "value"
[2018-02-28T13:43:23+01:00] ERROR
    MyError: Custom error
        at Object.<anonymous> (/Users/victor/code/advinans/@advinans--plack/examples/sample.ts:45:11)
        at Module._compile (module.js:660:30)
        at Object.Module._extensions..js (module.js:671:10)
        at Module.load (module.js:573:32)
        at tryModuleLoad (module.js:513:12)
        at Function.Module._load (module.js:505:3)
        at Function.Module.runMain (module.js:701:10)
        at startup (bootstrap_node.js:194:16)
        at bootstrap_node.js:618:3

    serviceContext: {
      "service": "plack-use",
      "version": "1.0.1"
    }
    name: "MyError"

Usage

Unless you provide a level to the plack constructor, it will respect process.env.LOG_LEVEL. This allows you to configure the log level through the environment, by default.

Basic usage

import plack from '@advinans/plack';

// Accepts standard pino configuration, but you shouldn't have to configure
// it at all
const log = plack();

log.info('hello world');
log.alert('red alert!');

Errors

import { VError } from 'verror';

// You can pass an explicit service context, but a default one is inferred
// based on your package.json (`.name`) and environment if not provided.
// We read `process.env.VERSION` from the environment, because we don't bump
// package.json versions (for Docker layering purposes)
const log = plack();

// The stack trace gets logged so that the error gets picked up by Stackdriver
// error reporting. It uses `VError.fullstack` to report a 'full" stack trace.
log.error(new Error('an error'));

// To provide additional context about an error that you wish to be reported
// as an error in Stackdriver, send an additional object. Enumerable error
// properties are also reported.
log.error(
  { context: { httpRequest: { method: 'GET', responseStatusCode: 500 } } },
  new Error('another error'),
);

// You *should* create custom error classes to improve error grouping in
// Stackdriver. You *must* set `this.name = this.constructor.name` in order
// for the stack trace to include the name of your custom error class.
class MyError extends Error {
  constructor(message?: string) {
    super(message);

    this.name = this.constructor.name;
  }
}

log.error(new MyError('My little error'));
log.error(
  new VError({ cause: new MyError('root cause'), name: 'RequestError' }),
  'The request failed',
);

Operations

Stackdriver supports logging long-running operations (LogEntryOperation). You can explicitly log such objects under the LOGGING_OPERATION key, or you can create a child logger:

const log = plack();

const op1 = log.operation({
  // An arbitrary producer identifier. The combination of id and
  // producer must be globally unique.
  producer: 'advinans/service-company/my-producer',

  // An arbitrary operation identifier. Log entries with the same
  // identifier are assumed to be part of the same operation.
  id: 'jobs-processor-8eb41c3d-3998-4360-9ea7-0132642e2d38',
});

op1.info({ first: true }, 'Operation starts');
op1.info('Operation runs');
op1.info({ last: true }, 'Operation ends');

Note: This uses pino's child bindings to create the initial operation key. Such bindings cannot be removed, so when logging first or last the logging key is repeated in the JSON output. This may cause problems for some JSON parsers but Stackdriver handles it gracefully (last value wins).

What gets picked up

The fluentd daemon set translates JSON payloads to StackDriver entries using a plugin called fluentd-plugin-google-cloud. Which fields get picked up can be figured out from the source code for this plugin (github.com/GoogleCloudPlatform/fluent-plugin-google). time is stripped from the payload, but it seems like Stackdriver ignores any timestamp set.

Here's some sample code illustrating sending rich log entries:

import plack from '@advinans/plack';

const log = plack.plack();
log.info(
  {
    httpRequest: {
      requestMethod: 'GET',
      requestUrl: 'https://localhost:8080',
      requestSize: '2048',
      status: 400,
      responseSize: '1024',
      userAgent:
        'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2704.103 Safari/537.36',
      remoteIp: '128.23.12.1',
      referer: 'https://google.com',
      cacheHit: false,
      cacheValidatedWithOriginServer: false,
      latency: '3s',
    },
    'logging.googleapis.com/sourceLocation': {
      file: 'index.js',
      function: 'main',
      line: '12',
    },
  },
  'access',
);

log.info(
  {
    'logging.googleapis.com/operation': {
      id: '9bf48d24-cd65-4699-9d2f-2c42bcc08437',
      producer: 'main-producer',
      first: true,
    },
  },
  'start of operation',
);

log.info(
  {
    'logging.googleapis.com/operation': {
      id: '9bf48d24-cd65-4699-9d2f-2c42bcc08437',
      producer: 'main-producer',
    },
  },
  'middle of operation',
);

log.info(
  {
    'logging.googleapis.com/operation': {
      id: '9bf48d24-cd65-4699-9d2f-2c42bcc08437',
      producer: 'main-producer',
      last: true,
    },
  },
  'end of operation',
);