@contrast/logger

@contrast/logger

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

Usage

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

const logger = install(core);

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

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)"

Output (click to expand)

{
  "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)"

Output (click to expand)

{
  "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);
}

Output (click to expand)

[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 manifest = require('./package.json');
logger.info({ manifest }, 'package.json contents');
// instead of
logger.info('package.json contents: %o', manifest);

Output (Click to expand)

[1649265443612] INFO (12345 on foo): package.json contents
  manifest: {
    "name": "@contrast/logger",
    "version": "1.0.0",
    "description": "Centralized logging for Contrast agent services",
    "license": "UNLICENSED",
    "author": "Contrast Security <[e-mail]> (https://www.contrastsecurity.com)",
    "main": "lib/index.js",
    "types": "lib/index.d.ts",
    "engines": {
      "npm": ">=6.13.7 <7 || >= 8.4.0",
      "node": ">= 14.15.0"
    },
    "scripts": {
      "build": "tsc --build src/",
      "test": "nyc mocha src/",
      "test:only": "mocha --no-parallel lib/",
      "posttest": "echo \"file://$PWD/coverage/lcov-report/index.html\""
    },
    "dependencies": {
      "pino": "^7.9.1"
    }
  }

[1649265443613] INFO (12345 on foo): package.json contents: {"name":"@contrast/logger","version":"1.0.0","description":"Centralized logging for Contrast agent services","license":"UNLICENSED","author":"Contrast Security <[e-mail]> (https://www.contrastsecurity.com)","main":"lib/index.js","types":"lib/index.d.ts","engines":{"npm":">= 8.4.0","node":">= 14.15.0"},"scripts":{"build":"tsc --build src/","test":"nyc mocha src/","test:only":"npm test -- --no-parallel","posttest":"echo \"file://$PWD/coverage/lcov-report/index.html\""},"dependencies":{"pino":"^7.9.1"}}

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' });