Repository: pinojs/pino (js)

Issue:
Logging request id
Hello,

I’m using Pino with Fastify and I like to have a request id property in all logs that occur during the request lifecycle.

I’ve set the genReqId option like:
```js
logger.genReqId = function(request) {
    const requestId = request.headers['x-request-id'] || uuid();
    return requestId;
  };
```

And when I’m using req.log.info everything seems to work!

But I don’t want to pass the req.log as an argument to all the functions in the system that needs to log.  I want to write my logs in the form of logger.info, So I’m looking for a different solution. 

One thing I had in mind is when creating a new instance of the logger to do something like this:

```js
const logger = pino({
  base: { 
    request_id: () => uuid()
  }
});
```

And when I log a message, the request_id function will be evaluated at log time.

Currently the behaviour is that the base properties are evaluated once at the construction time.

Any ideas?

Pull request description:
[Closes #601] Add cls-proxify to ecosystem.md

Patch:
diff --git a/browser.js b/browser.js
index a6384c6..22ed05a 100644
--- a/browser.js
+++ b/browser.js
@@ -6,6 +6,10 @@ module.exports = pino
 
 var _console = global.console || {}
 var stdSerializers = {
+  mapHttpRequest: mock,
+  mapHttpResponse: mock,
+  wrapRequestSerializer: passthrough,
+  wrapResponseSerializer: passthrough,
   req: mock,
   res: mock,
   err: asErrValue
@@ -157,6 +161,7 @@ pino.levels = {
 }
 
 pino.stdSerializers = stdSerializers
+pino.symbols = require('./lib/symbols')
 
 function set (opts, logger, level, fallback) {
   var proto = Object.getPrototypeOf(logger)
@@ -296,4 +301,5 @@ function asErrValue (err) {
 }
 
 function mock () { return {} }
+function passthrough (a) { return a }
 function noop () {}
diff --git a/docs/ecosystem.md b/docs/ecosystem.md
index b12324b..780dd79 100644
--- a/docs/ecosystem.md
+++ b/docs/ecosystem.md
@@ -67,4 +67,5 @@ the logger for the [Rill framework](https://rill.site/).
 MongoDB and many [others](https://www.fluentd.org/dataoutputs) via Fluentd.
 + [`pino-pretty-min`](https://github.com/unjello/pino-pretty-min): a minimal
 prettifier inspired by the [logrus](https://github.com/sirupsen/logrus) logger.
++ [`cls-proxify`](https://github.com/keenondrums/cls-proxify): integration of pino and [CLS](https://github.com/jeff-lewis/cls-hooked). Useful for creating dynamically configured child loggers (e.g. with added trace ID) for each request. 
 
diff --git a/lib/redaction.js b/lib/redaction.js
index 6c075e8..5e7fd92 100644
--- a/lib/redaction.js
+++ b/lib/redaction.js
@@ -72,8 +72,10 @@ function redaction (opts, serialize) {
   const result = {
     [redactFmtSym]: fastRedact({ paths, censor, serialize, strict })
   }
-  const serializedCensor = serialize(censor)
-  const topCensor = () => serializedCensor
+
+  const topCensor = (...args) =>
+    typeof censor === 'function' ? serialize(censor(...args)) : serialize(censor)
+
   return [...Object.keys(shape), ...Object.getOwnPropertySymbols(shape)].reduce((o, k) => {
     // top level key:
     if (shape[k] === null) o[k] = topCensor
diff --git a/lib/tools.js b/lib/tools.js
index 92d44bc..41427eb 100644
--- a/lib/tools.js
+++ b/lib/tools.js
@@ -79,12 +79,11 @@ function asJson (obj, msg, num, time) {
   const chindings = this[chindingsSym]
   const serializers = this[serializersSym]
   var data = this[lsCacheSym][num] + time
-  if (msg !== undefined) {
-    data += messageKeyString + asString('' + msg)
-  }
+
   // we need the child bindings added to the output first so instance logged
   // objects can take precedence when JSON.parse-ing the resulting log line
   data = data + chindings
+
   var value
   if (hasObj === true) {
     var notHasOwnProperty = obj.hasOwnProperty === undefined
@@ -131,6 +130,11 @@ function asJson (obj, msg, num, time) {
       }
     }
   }
+
+  if (msg !== undefined) {
+    data += messageKeyString + asString('' + msg)
+  }
+
   return data + end
 }
 
diff --git a/package.json b/package.json
index 5f4674c..a04b442 100644
--- a/package.json
+++ b/package.json
@@ -1,6 +1,6 @@
 {
   "name": "pino",
-  "version": "5.11.1",
+  "version": "5.11.3",
   "description": "super fast, all natural json logger",
   "main": "pino.js",
   "browser": "./browser.js",
@@ -18,9 +18,9 @@
   "scripts": {
     "docs": "docsify serve",
     "browser-test": "airtap --local 8080 test/browser*test.js",
-    "test": "standard | snazzy && NODE_OPTIONS='--no-warnings -r qodaa' tap -j 4 --no-cov test/*test.js",
-    "ci": "standard | snazzy && TAP_TIMEOUT=480000 NODE_OPTIONS='--no-warnings -r qodaa' tap -j 4 --100 test/*test.js",
-    "cov-ui": "NODE_OPTIONS='--no-warnings -r qodaa' tap -j 4 --coverage-report=html test/*test.js",
+    "test": "standard | snazzy && NODE_OPTIONS='--no-warnings -r qodaa' tap --no-esm -j 4 --no-cov test/*test.js",
+    "ci": "standard | snazzy && TAP_TIMEOUT=480000 NODE_OPTIONS='--no-warnings -r qodaa' tap --no-esm -j 4 --100 test/*test.js",
+    "cov-ui": "NODE_OPTIONS='--no-warnings -r qodaa' tap --no-esm -j 4 --coverage-report=html test/*test.js",
     "bench": "node benchmarks/utils/runbench all",
     "bench-basic": "node benchmarks/utils/runbench basic",
     "bench-object": "node benchmarks/utils/runbench object",
@@ -58,37 +58,37 @@
   },
   "homepage": "http://getpino.io",
   "devDependencies": {
-    "airtap": "0.1.0",
+    "airtap": "2.0.2",
     "benchmark": "^2.1.4",
     "bole": "^3.0.2",
     "bunyan": "^1.8.12",
     "docsify-cli": "^4.2.1",
     "execa": "^1.0.0",
     "fastbench": "^1.0.1",
-    "flush-write-stream": "^1.0.3",
+    "flush-write-stream": "^2.0.0",
     "fresh-require": "^1.0.3",
-    "log": "^3.0.0",
+    "log": "^5.0.0",
     "loglevel": "^1.6.1",
     "pino-pretty": "^2.4.0",
     "pre-commit": "^1.2.2",
     "proxyquire": "^2.1.0",
+    "pump": "^3.0.0",
     "qodaa": "^1.0.1",
     "snazzy": "^8.0.0",
-    "split2": "^3.0.0",
+    "split2": "^3.1.1",
     "standard": "^12.0.1",
     "steed": "^1.1.3",
-    "tap": "^12.1.0",
-    "tape": "^4.9.0",
-    "through2": "^3.0.0",
-    "winston": "^3.1.0",
-    "pump": "^3.0.0"
+    "tap": "^12.6.0",
+    "tape": "^4.10.1",
+    "through2": "^3.0.1",
+    "winston": "^3.2.1"
   },
   "dependencies": {
-    "fast-redact": "^1.4.2",
+    "fast-redact": "^1.4.4",
     "fast-safe-stringify": "^2.0.6",
     "flatstr": "^1.0.9",
     "pino-std-serializers": "^2.3.0",
-    "quick-format-unescaped": "^3.0.0",
-    "sonic-boom": "^0.7.1"
+    "quick-format-unescaped": "^3.0.2",
+    "sonic-boom": "^0.7.3"
   }
 }


Test patch:
diff --git a/test/basic.test.js b/test/basic.test.js
index f164f21..483b0cf 100644
--- a/test/basic.test.js
+++ b/test/basic.test.js
@@ -76,6 +76,24 @@ function levelTest (name, level) {
     })
   })
 
+  test(`overriding object key by string at level ${name}`, async ({ is, same }) => {
+    const stream = sink()
+    const instance = pino(stream)
+    instance.level = name
+    instance[name]({ hello: 'world', msg: 'object' }, 'string')
+    const result = await once(stream, 'data')
+    is(new Date(result.time) <= new Date(), true, 'time is greater than Date.now()')
+    delete result.time
+    same(result, {
+      pid: pid,
+      hostname: hostname,
+      level: level,
+      msg: 'string',
+      hello: 'world',
+      v: 1
+    })
+  })
+
   test(`formatting logs as ${name}`, async ({ is }) => {
     const stream = sink()
     const instance = pino(stream)
diff --git a/test/browser.test.js b/test/browser.test.js
index 0218448..cdbfff9 100644
--- a/test/browser.test.js
+++ b/test/browser.test.js
@@ -1,6 +1,8 @@
 'use strict'
 const test = require('tape')
 const fresh = require('fresh-require')
+const pinoStdSerializers = require('pino-std-serializers')
+const pinoSymbols = require('../lib/symbols')
 const pino = require('../browser')
 
 levelTest('fatal')
@@ -101,22 +103,36 @@ test('exposes LOG_VERSION', ({ end, is }) => {
 
 test('exposes faux stdSerializers', ({ end, ok, same }) => {
   ok(pino.stdSerializers)
-  ok(pino.stdSerializers.req)
-  ok(pino.stdSerializers.res)
-  ok(pino.stdSerializers.err)
+  // make sure faux stdSerializers match pino-std-serializers
+  for (let serializer in pinoStdSerializers) {
+    ok(pino.stdSerializers[serializer], `pino.stdSerializers.${serializer}`)
+  }
+  // confirm faux methods return empty objects
   same(pino.stdSerializers.req(), {})
+  same(pino.stdSerializers.mapHttpRequest(), {})
+  same(pino.stdSerializers.mapHttpResponse(), {})
   same(pino.stdSerializers.res(), {})
-
+  // confirm wrapping function is a passthrough
+  const noChange = { foo: 'bar', fuz: 42 }
+  same(pino.stdSerializers.wrapRequestSerializer(noChange), noChange)
+  same(pino.stdSerializers.wrapResponseSerializer(noChange), noChange)
   end()
 })
 
 test('exposes err stdSerializer', ({ end, ok }) => {
-  ok(pino.stdSerializers)
-  ok(pino.stdSerializers.req)
-  ok(pino.stdSerializers.res)
   ok(pino.stdSerializers.err)
   ok(pino.stdSerializers.err(Error()))
+  end()
+})
 
+test('exposes real symbols', ({ end, ok, same }) => {
+  ok(pino.symbols)
+  // confirm every symbol is present
+  for (let symbol in pinoSymbols) {
+    ok(pino.symbols[symbol], `pino.symbols.${symbol}`)
+  }
+  // confirm real symbols are used
+  same(pino.symbols, pinoSymbols)
   end()
 })
 
diff --git a/test/redact.test.js b/test/redact.test.js
index 8856dcf..26db3ac 100644
--- a/test/redact.test.js
+++ b/test/redact.test.js
@@ -481,6 +481,32 @@ test('redact – supports top level wildcard', async ({ is }) => {
   is(req, '[Redacted]')
 })
 
+test('redact – supports top level wildcard with a censor function', async ({ is }) => {
+  const stream = sink()
+  const instance = pino({
+    redact: {
+      paths: ['*'],
+      censor: () => '[Redacted]'
+    }
+  }, stream)
+  instance.info({
+    req: {
+      id: 7915,
+      method: 'GET',
+      url: '/',
+      headers: {
+        host: 'localhost:3000',
+        connection: 'keep-alive',
+        cookie: 'SESSID=298zf09hf012fh2; csrftoken=u32t4o3tb3gg43; _gat=1;'
+      },
+      remoteAddress: '::ffff:127.0.0.1',
+      remotePort: 58022
+    }
+  })
+  const { req } = await once(stream, 'data')
+  is(req, '[Redacted]')
+})
+
 test('redact – supports top level wildcard and leading wildcard', async ({ is }) => {
   const stream = sink()
   const instance = pino({ redact: ['*', '*.req'] }, stream)