@contrast/logger

• Usage
• Structured Logging
  • Filtering
• Best Practices
  • Errors
  • Objects
• Namespacing

Usage

Centralized, structured logging for Contrast agent services, built on Pino. @contrast/agentify composes the logger onto core, so components use core.logger:

core.logger.info({ foo, bar }, 'message with %s, %d', 'string', 123);

Outside the agent, install it onto your own core object:

const { default: install } = require('@contrast/logger');

const logger = install(core); // also sets core.logger

See Pino documentation for the logger's API.

Structured Logging

Pino logs as JSON, so it is particularly good at logging JavaScript objects.

Given:

logger.info('hello world');
logger.error('this is at error level');
logger.info('the answer is %d', 42);
logger.info({ obj: 42 }, 'hello world');
logger.info({ obj: 42, b: 2 }, 'hello world');
logger.info({ nested: { obj: 42 } }, 'nested');

Log output looks like the following:

{"level":30,"time":1649266923912,"pid":12345,"hostname":"foo","msg":"hello world"}
{"level":50,"time":1649266923913,"pid":12345,"hostname":"foo","msg":"this is at error level"}
{"level":30,"time":1649266923913,"pid":12345,"hostname":"foo","msg":"the answer is 42"}
{"level":30,"time":1649266923913,"pid":12345,"hostname":"foo","obj":42,"msg":"hello world"}
{"level":30,"time":1649266923913,"pid":12345,"hostname":"foo","obj":42,"b":2,"msg":"hello world"}
{"level":30,"time":1649266923913,"pid":12345,"hostname":"foo","nested":{"obj":42},"msg":"nested"}

You can use pino-pretty to format logs during development. The previous lines, when passed to pino-pretty, will format to the following:

node example.js | npx pino-pretty

[1649266998216] INFO (12345 on foo): hello world
[1649266998216] ERROR (12345 on foo): this is at error level
[1649266998216] INFO (12345 on foo): the answer is 42
[1649266998216] INFO (12345 on foo): hello world
    obj: 42
[1649266998216] INFO (12345 on foo): hello world
    obj: 42
    b: 2
[1649266998216] INFO (12345 on foo): nested
    nested: {
      "obj": 42
    }

Filtering

In addition to being easier to read when pretty-printed, JSON logging also allows us to filter with utilities like jq.

For example, we can filter only error messages:

node example.js | jq "select(.level == 50)"

{
  "level": 50,
  "time": 1649268122322,
  "pid": 12345,
  "hostname": "foo",
  "msg": "this is at error level"
}

Or, we can look up only log entries with the obj property:

node example.js | jq "select(.obj)"

{
  "level": 30,
  "time": 1649268235040,
  "pid": 12345,
  "hostname": "foo",
  "obj": 42,
  "msg": "hello world"
}
{
  "level": 30,
  "time": 1649268235040,
  "pid": 12345,
  "hostname": "foo",
  "obj": 42,
  "b": 2,
  "msg": "hello world"
}

See jq's tutorial and manual for examples on just how powerful JSON processing can be!

Best Practices

Errors

Pino handles errors specially when they are passed as err or when passed as the first argument. See: https://github.com/pinojs/pino/blob/master/docs/api.md#serializers-object

For example, when handling an error we should use the following pattern(s):

try {
  // ...something that throws
} catch (err) {
  logger.warn(err);
  // if we want to customize the message:
  logger.warn(err, 'something bad happened');
  // or if we need to provide additional data:
  logger.warn({ err, data }, 'something broke when handling %s', filename);
}

[1649264653814] WARN (12345 on foo): yikes!
  err: {
    "type": "Error",
    "message": "yikes!",
    "stack":
        Error: yikes!
            at Object.<anonymous> (/path/to/file.js:5:13)
            at Module._compile (internal/modules/cjs/loader.js:1085:14)
            at Object.Module._extensions..js (internal/modules/cjs/loader.js:1114:10)
            at Module.load (internal/modules/cjs/loader.js:950:32)
            at Function.Module._load (internal/modules/cjs/loader.js:790:12)
            at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:75:12)
            at internal/main/run_main_module.js:17:47
  }

[1649264653814] WARN (12345 on foo): something bad happened
  err: {
    "type": "Error",
    "message": "yikes!",
    "stack":
        Error: yikes!
            at Object.<anonymous> (/path/to/file.js:5:13)
            at Module._compile (internal/modules/cjs/loader.js:1085:14)
            at Object.Module._extensions..js (internal/modules/cjs/loader.js:1114:10)
            at Module.load (internal/modules/cjs/loader.js:950:32)
            at Function.Module._load (internal/modules/cjs/loader.js:790:12)
            at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:75:12)
            at internal/main/run_main_module.js:17:47
  }

[1649264653814] WARN (12345 on foo): something broke when handling foo.js
  data: {
    "foo": "bar"
  }
  err: {
    "type": "Error",
    "message": "yikes!",
    "stack":
        Error: yikes!
            at Object.<anonymous> (/path/to/file.js:5:13)
            at Module._compile (internal/modules/cjs/loader.js:1085:14)
            at Object.Module._extensions..js (internal/modules/cjs/loader.js:1114:10)
            at Module.load (internal/modules/cjs/loader.js:950:32)
            at Function.Module._load (internal/modules/cjs/loader.js:790:12)
            at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:75:12)
            at internal/main/run_main_module.js:17:47
  }

Objects

Rather than including information in the log message itself, it is more helpful to include data in the first argument.

For example, if we want to log the contents of an object:

const route = { method: 'GET', path: '/users/:id', handler: 'getUser' };
logger.info({ route }, 'route registered');
// instead of
logger.info('route registered: %o', route);

[1649265443612] INFO (12345 on foo): route registered
  route: {
    "method": "GET",
    "path": "/users/:id",
    "handler": "getUser"
  }

[1649265443613] INFO (12345 on foo): route registered: {"method":"GET","path":"/users/:id","handler":"getUser"}

Namespacing

When using the logger in another module, you could instantiate a namespace using the child method.

For example, in the @contrast/rewriter module, we could namespace the logger as follows:

const logger = core.logger.child({ name: 'contrast:rewriter' });