@contrast/logger
v1.16.0
Published
Centralized logging for Contrast agent services
Downloads
72,847
Maintainers
Keywords
Readme
@contrast/logger
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)"
{
"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 manifest = require('./package.json');
logger.info({ manifest }, 'package.json contents');
// instead of
logger.info('package.json contents: %o', manifest);
[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 <[email protected]> (https://www.contrastsecurity.com)",
"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 <[email protected]> (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' });