Centralized logging for Contrast agent services
npm install @contrast/logger@contrast/logger- Usage
- Structured Logging
- Filtering
- Best Practices
- Errors
- Objects
``ts
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.
Pino logs as JSON, so it is particularly good at logging JavaScript objects.
Given:
`ts`
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:
`json`
{"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:
`sh`
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
}
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:
`sh`
node example.js | jq "select(.level == 50)"
Output (click to expand)
`json`
{
"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:
`sh`
node example.js | jq "select(.obj)"
Output (click to expand)
`json`
{
"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!
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):
`ts`
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.
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.
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.
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
}
`
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:
`ts`
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
"main": "lib/index.js",
"types": "lib/index.d.ts",
"engines": {
"npm": ">=6.13.7 <7 || >= 8.3.1",
"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
`
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:
`ts``
const logger = core.logger.child({ name: 'contrast:rewriter' });