strong-tie/inbound-calls
0
1# Help2 3* [Log rotation](#rotate)4* [Reopening log files](#reopening)5* [Saving to multiple files](#multiple)6* [Log filtering](#filter-logs)7* [Transports and systemd](#transport-systemd)8* [Log to different streams](#multi-stream)9* [Duplicate keys](#dupe-keys)10* [Log levels as labels instead of numbers](#level-string)11* [Pino with `debug`](#debug)12* [Unicode and Windows terminal](#windows)13* [Mapping Pino Log Levels to Google Cloud Logging (Stackdriver) Severity Levels](#stackdriver)14* [Using Grafana Loki to evaluate pino logs in a kubernetes cluster](#grafana-loki)15* [Avoid Message Conflict](#avoid-message-conflict)16* [Best performance for logging to `stdout`](#best-performance-for-stdout)17* [Testing](#testing)18 19<a id="rotate"></a>20## Log rotation21 22Use a separate tool for log rotation:23We recommend [logrotate](https://github.com/logrotate/logrotate).24Consider we output our logs to `/var/log/myapp.log` like so:25 26```27$ node server.js > /var/log/myapp.log28```29 30We would rotate our log files with logrotate, by adding the following to `/etc/logrotate.d/myapp`:31 32```33/var/log/myapp.log {34 su root35 daily36 rotate 737 delaycompress38 compress39 notifempty40 missingok41 copytruncate42}43```44 45The `copytruncate` configuration has a very slight possibility of lost log lines due46to a gap between copying and truncating - the truncate may occur after additional lines47have been written. To perform log rotation without `copytruncate`, see the [Reopening log files](#reopening)48help.49 50<a id="reopening"></a>51## Reopening log files52 53In cases where a log rotation tool doesn't offer copy-truncate capabilities,54or where using them is deemed inappropriate, `pino.destination`55can reopen file paths after a file has been moved away.56 57One way to use this is to set up a `SIGUSR2` or `SIGHUP` signal handler that58reopens the log file destination, making sure to write the process PID out59somewhere so the log rotation tool knows where to send the signal.60 61```js62// write the process pid to a well known location for later63const fs = require('node:fs')64fs.writeFileSync('/var/run/myapp.pid', process.pid)65 66const dest = pino.destination('/log/file')67const logger = require('pino')(dest)68process.on('SIGHUP', () => dest.reopen())69```70 71The log rotation tool can then be configured to send this signal to the process72after a log rotation event has occurred.73 74Given a similar scenario as in the [Log rotation](#rotate) section a basic75`logrotate` config that aligns with this strategy would look similar to the following:76 77```78/var/log/myapp.log {79 su root80 daily81 rotate 782 delaycompress83 compress84 notifempty85 missingok86 postrotate87 kill -HUP `cat /var/run/myapp.pid`88 endscript89}90```91 92<a id="multiple"></a>93## Saving to multiple files94 95See [`pino.multistream`](/docs/api.md#pino-multistream).96 97<a id="filter-logs"></a>98## Log Filtering99The Pino philosophy advocates common, preexisting, system utilities.100 101Some recommendations in line with this philosophy are:102 1031. Use [`grep`](https://linux.die.net/man/1/grep):104 ```sh105 $ # View all "INFO" level logs106 $ node app.js | grep '"level":30'107 ```1081. Use [`jq`](https://stedolan.github.io/jq/):109 ```sh110 $ # View all "ERROR" level logs111 $ node app.js | jq 'select(.level == 50)'112 ```113 114<a id="transport-systemd"></a>115## Transports and systemd116`systemd` makes it complicated to use pipes in services. One method for overcoming117this challenge is to use a subshell:118 119```120ExecStart=/bin/sh -c '/path/to/node app.js | pino-transport'121```122 123<a id="multi-stream"></a>124## Log to different streams125 126Pino's default log destination is the singular destination of `stdout`. While127not recommended for performance reasons, multiple destinations can be targeted128by using [`pino.multistream`](/docs/api.md#pino-multistream).129 130In this example, we use `stderr` for `error` level logs and `stdout` as default131for all other levels (e.g. `debug`, `info`, and `warn`).132 133```js134const pino = require('pino')135var streams = [136 {level: 'debug', stream: process.stdout},137 {level: 'error', stream: process.stderr},138 {level: 'fatal', stream: process.stderr}139]140 141const logger = pino({142 name: 'my-app',143 level: 'debug', // must be the lowest level of all streams144}, pino.multistream(streams))145```146 147<a id="dupe-keys"></a>148## How Pino handles duplicate keys149 150Duplicate keys are possibly when a child logger logs an object with a key that151collides with a key in the child loggers bindings.152 153See the [child logger duplicate keys caveat](/docs/child-loggers.md#duplicate-keys-caveat)154for information on this is handled.155 156<a id="level-string"></a>157## Log levels as labels instead of numbers158Pino log lines are meant to be parsable. Thus, Pino's default mode of operation159is to print the level value instead of the string name. 160However, you can use the [`formatters`](/docs/api.md#formatters-object) option 161with a [`level`](/docs/api.md#level) function to print the string name instead of the level value :162 163```js164const pino = require('pino')165 166const log = pino({167 formatters: {168 level: (label) => {169 return {170 level: label171 }172 }173 }174})175 176log.info('message')177 178// {"level":"info","time":1661632832200,"pid":18188,"hostname":"foo","msg":"message"}179```180 181Although it works, we recommend using one of these options instead if you are able:182 1831. If the only change desired is the name then a transport can be used. One such184transport is [`pino-text-level-transport`](https://npm.im/pino-text-level-transport).1851. Use a prettifier like [`pino-pretty`](https://npm.im/pino-pretty) to make186the logs human friendly.187 188<a id="debug"></a>189## Pino with `debug`190 191The popular [`debug`](https://npm.im/debug) is used in many modules across the ecosystem.192 193The [`pino-debug`](https://github.com/pinojs/pino-debug) module194can capture calls to `debug` loggers and run them195through `pino` instead. This results in a 10x (20x in asynchronous mode)196performance improvement - even though `pino-debug` is logging additional197data and wrapping it in JSON.198 199To quickly enable this install [`pino-debug`](https://github.com/pinojs/pino-debug)200and preload it with the `-r` flag, enabling any `debug` logs with the201`DEBUG` environment variable:202 203```sh204$ npm i pino-debug205$ DEBUG=* node -r pino-debug app.js206```207 208[`pino-debug`](https://github.com/pinojs/pino-debug) also offers fine-grain control to map specific `debug`209namespaces to `pino` log levels. See [`pino-debug`](https://github.com/pinojs/pino-debug)210for more.211 212<a id="windows"></a>213## Unicode and Windows terminal214 215Pino uses [sonic-boom](https://github.com/mcollina/sonic-boom) to speed216up logging. Internally, it uses [`fs.write`](https://nodejs.org/dist/latest-v10.x/docs/api/fs.html#fs_fs_write_fd_string_position_encoding_callback) to write log lines directly to a file217descriptor. On Windows, Unicode output is not handled properly in the218terminal (both `cmd.exe` and PowerShell), and as such the output could219be visualized incorrectly if the log lines include utf8 characters. It220is possible to configure the terminal to visualize those characters221correctly with the use of [`chcp`](https://ss64.com/nt/chcp.html) by222executing in the terminal `chcp 65001`. This is a known limitation of223Node.js.224 225<a id="stackdriver"></a>226## Mapping Pino Log Levels to Google Cloud Logging (Stackdriver) Severity Levels227 228Google Cloud Logging uses `severity` levels instead of log levels. As a result, all logs may show as INFO229level logs while completely ignoring the level set in the pino log. Google Cloud Logging also prefers that230log data is present inside a `message` key instead of the default `msg` key that Pino uses. Use a technique231similar to the one below to retain log levels in Google Cloud Logging232 233```js234const pino = require('pino')235 236// https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#logseverity237const PinoLevelToSeverityLookup = {238 trace: 'DEBUG',239 debug: 'DEBUG',240 info: 'INFO',241 warn: 'WARNING',242 error: 'ERROR',243 fatal: 'CRITICAL',244};245 246const defaultPinoConf = {247 messageKey: 'message',248 formatters: {249 level(label, number) {250 return {251 severity: PinoLevelToSeverityLookup[label] || PinoLevelToSeverityLookup['info'],252 level: number,253 }254 }255 },256}257 258module.exports = function createLogger(options) {259 return pino(Object.assign({}, options, defaultPinoConf))260}261```262 263A library that configures Pino for264[Google Cloud Structured Logging](https://cloud.google.com/logging/docs/structured-logging)265is available at:266[@google-cloud/pino-logging-gcp-config](https://www.npmjs.com/package/@google-cloud/pino-logging-gcp-config)267 268This library has the following features:269 270+ Converts Pino log levels to Google Cloud Logging log levels, as above271+ Uses `message` instead of `msg` for the message key, as above272+ Adds a millisecond-granularity timestamp in the 273 [structure](https://cloud.google.com/logging/docs/agent/logging/configuration#timestamp-processing)274 recognised by Google Cloud Logging eg: \275 `"timestamp":{"seconds":1445470140,"nanos":123000000}`276+ Adds a sequential277 [`insertId`](https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#FIELDS.insert_id)278 to ensure log messages with identical timestamps are ordered correctly.279+ Logs including an `Error` object have the280 [`stack_trace`](https://cloud.google.com/error-reporting/docs/formatting-error-messages#log-error)281 property set so that the error is forwarded to Google Cloud Error Reporting.282+ Includes a283 [`ServiceContext`](https://cloud.google.com/error-reporting/reference/rest/v1beta1/ServiceContext)284 object in the logs for Google Cloud Error Reporting, auto detected from the285 environment if not specified286+ Maps the OpenTelemetry properties `span_id`, `trace_id`, and `trace_flags`287 to the equivalent Google Cloud Logging fields.288 289<a id="grafana-loki"></a>290## Using Grafana Loki to evaluate pino logs in a kubernetes cluster291 292To get pino logs into Grafana Loki there are two options:293 2941. **Push:** Use [pino-loki](https://github.com/Julien-R44/pino-loki) to send logs directly to Loki.2951. **Pull:** Configure Grafana Promtail to read and properly parse the logs before sending them to Loki. 296 Similar to Google Cloud logging, this involves remapping the log levels. See this [article](https://medium.com/@janpaepke/structured-logging-in-the-grafana-monitoring-stack-8aff0a5af2f5) for details.297 298<a id="avoid-message-conflict"></a>299## Avoid Message Conflict300 301As described in the [`message` documentation](/docs/api.md#message), when a log302is written like `log.info({ msg: 'a message' }, 'another message')` then the303final output JSON will have `"msg":"another message"` and the `'a message'`304string will be lost. To overcome this, the [`logMethod` hook](/docs/api.md#logmethod)305can be used:306 307```js308'use strict'309 310const log = require('pino')({311 level: 'debug',312 hooks: {313 logMethod (inputArgs, method) {314 if (inputArgs.length === 2 && inputArgs[0].msg) {315 inputArgs[0].originalMsg = inputArgs[0].msg316 }317 return method.apply(this, inputArgs)318 }319 }320})321 322log.info('no original message')323log.info({ msg: 'mapped to originalMsg' }, 'a message')324 325// {"level":30,"time":1596313323106,"pid":63739,"hostname":"foo","msg":"no original message"}326// {"level":30,"time":1596313323107,"pid":63739,"hostname":"foo","msg":"a message","originalMsg":"mapped to originalMsg"}327```328 329<a id="best-performance-for-stdout"></a>330## Best performance for logging to `stdout`331 332The best performance for logging directly to stdout is _usually_ achieved by using the333default configuration:334 335```js336const log = require('pino')();337```338 339You should only have to configure custom transports or other settings340if you have broader logging requirements.341 342<a id="testing"></a>343## Testing344 345See [`pino-test`](https://github.com/pinojs/pino-test).346