# `@contrast/logger`

- [Usage](#usage)
- [Structured Logging](#structured-logging)
  - [Filtering](#filtering)
- [Best Practices](#best-practices)
  - [Errors](#errors)
  - [Objects](#objects)

## Usage

```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](https://github.com/pinojs/pino/blob/master/docs/api.md#logger-instance)
documentation for the logger's API.

## Structured Logging

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`](https://github.com/pinojs/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
    }
```

### Filtering

In addition to being easier to read when pretty-printed, JSON logging also allows
us to filter with utilities like [`jq`](https://stedolan.github.io/jq/).

For example, we can filter only error messages:

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

<details>
<summary>Output (click to expand)</summary>

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

</details>

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

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

<details>
<summary>Output (click to expand)</summary>

```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"
}
```

</details>

See `jq`'s [tutorial](https://stedolan.github.io/jq/tutorial/) and
[manual](https://stedolan.github.io/jq/manual/v1.6/) 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):

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

<details>
<summary>Output (click to expand)</summary>

```
[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
  }
```

</details>

### 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:

```ts
const manifest = require('./package.json');
logger.info({ manifest }, 'package.json contents');
// instead of
logger.info('package.json contents: %o', manifest);
```

<details>
<summary>Output (Click to expand)</summary>

```
[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 <nodejs@contrastsecurity.com> (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 <nodejs@contrastsecurity.com> (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"}}
```

</details>

## Namespacing

When using the logger in another module, you could instantiate a namespace using
the [`child`](https://github.com/pinojs/pino/blob/master/docs/api.md#loggerchildbindings-options--logger) method.

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

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