Repository: pinojs/pino
Pull request #254 (2017-06-07 06:48:18)

Fix crash in request serializer when behind proxy
When used behind a proxy the `req.connection` is not always set which throws an error in the serializer. So this change makes sure we're not trying to log properties on an undefined object.

mcollina: Can you please add a unit test for this?
joakimbeng: There you go! :)

Patch:
diff --git a/docs/API.md b/docs/API.md
index bd4c6b9..41a371b 100644
--- a/docs/API.md
+++ b/docs/API.md
@@ -27,6 +27,7 @@
     + [.epochTime](#epochTimeFunction)
     + [.slowTime](#slowTimeFunction)
     + [.nullTime](#nullTimeFunction)
++ [Metadata Support](#metadata)
 
 # module.exports
 
@@ -76,7 +77,8 @@
   * `enabled` (boolean): enables logging. Default: `true`
   * `browser` (Object): browser only, may have `asObject` and `write` keys, see [Pino in the Browser](../readme.md#browser)
 + `stream` (Writable): a writable stream where the logs will be written.
-  Default: `process.stdout`
+  It can also receive some log-line [metadata](#metadata), if the
+  relative protocol is enabled. Default: `process.stdout`
 
 ### Example:
 ```js
@@ -576,3 +578,31 @@ performance penalty.
 
 Returns an empty string. This function is used when the `timestamp` option
 is set to `false`.
+
+<a id="metadata"></a>
+# Metadata
+
+A destination stream can have a property `stream[Symbol.for('needsMetadata')] = true`
+to indicate that for every log line written, the following properties of the stream
+should be set:
+
+* the last logging level as `stream.lastLevel`
+* the last logging message as `stream.lastMsg`
+* the last logging object as `stream.lastObj`
+* the last logger instance as `stream.lastLogger` (to support child
+  loggers)
+
+## Example
+
+```js
+var instance = pino({}, {
+  [Symbol.for('needsMetadata')]: true,
+  write: function (chunk) {
+    console.log('lastLevel', this.lastLevel)
+    console.log('lastMsg', this.lastMsg)
+    console.log('lastObj', this.lastObj)
+    console.log('lastLogger', this.lastLogger)
+    console.log('line', chunk)
+  }
+})
+```
diff --git a/lib/serializers.js b/lib/serializers.js
index 57708eb..f65ad1a 100644
--- a/lib/serializers.js
+++ b/lib/serializers.js
@@ -5,8 +5,8 @@ function asReqValue (req) {
     method: req.method,
     url: req.url,
     headers: req.headers,
-    remoteAddress: req.connection.remoteAddress,
-    remotePort: req.connection.remotePort
+    remoteAddress: req.connection && req.connection.remoteAddress,
+    remotePort: req.connection && req.connection.remotePort
   }
 }
 
diff --git a/pino.js b/pino.js
index 87491a5..2621869 100644
--- a/pino.js
+++ b/pino.js
@@ -11,6 +11,7 @@ var levels = require('./lib/levels')
 var tools = require('./lib/tools')
 var serializers = require('./lib/serializers')
 var time = require('./lib/time')
+var needsMetadata = Symbol.for('needsMetadata')
 
 var LOG_VERSION = 1
 
@@ -199,14 +200,21 @@ Object.defineProperty(pinoPrototype, 'child', {
 
 function pinoWrite (obj, msg, num) {
   var s = this.asJson(obj, msg, num)
+  var stream = this.stream
   if (!this.cache) {
-    this.stream.write(flatstr(s))
+    if (stream[needsMetadata]) {
+      stream.lastLevel = num
+      stream.lastMsg = msg
+      stream.lastObj = obj
+      stream.lastLogger = this // for child loggers
+    }
+    stream.write(flatstr(s))
     return
   }
 
   this.cache.buf += s
   if (this.cache.buf.length > this.cache.size) {
-    this.stream.write(flatstr(this.cache.buf))
+    stream.write(flatstr(this.cache.buf))
     this.cache.buf = ''
   }
 }


Test patch:
diff --git a/test/http.test.js b/test/http.test.js
index d4463b4..61862e0 100644
--- a/test/http.test.js
+++ b/test/http.test.js
@@ -90,6 +90,47 @@ test('http request support via serializer', function (t) {
   })
 })
 
+test('http request support via serializer without request connection', function (t) {
+  t.plan(3)
+
+  var originalReq
+  var instance = pino({
+    serializers: {
+      req: pino.stdSerializers.req
+    }
+  }, sink(function (chunk, enc, cb) {
+    t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
+    delete chunk.time
+    t.deepEqual(chunk, {
+      pid: pid,
+      hostname: hostname,
+      level: 30,
+      msg: 'my request',
+      v: 1,
+      req: {
+        method: originalReq.method,
+        url: originalReq.url,
+        headers: originalReq.headers
+      }
+    })
+    cb()
+  }))
+
+  var server = http.createServer(function (req, res) {
+    originalReq = req
+    delete req.connection
+    instance.info({ req: req }, 'my request')
+    res.end('hello')
+  }).listen(function (err) {
+    t.error(err)
+    t.teardown(server.close.bind(server))
+
+    http.get('http://localhost:' + server.address().port, function (res) {
+      res.resume()
+    })
+  })
+})
+
 test('http response support', function (t) {
   t.plan(3)
 
diff --git a/test/metadata.test.js b/test/metadata.test.js
new file mode 100644
index 0000000..fe46333
--- /dev/null
+++ b/test/metadata.test.js
@@ -0,0 +1,121 @@
+'use strict'
+
+var test = require('tap').test
+var os = require('os')
+var pino = require('../')
+var sink = require('./helper').sink
+
+var pid = process.pid
+var hostname = os.hostname()
+
+test('metadata works', function (t) {
+  t.plan(6)
+  var dest = sink(function (chunk, enc, cb) {
+    t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
+    delete chunk.time
+    t.deepEqual(chunk, {
+      pid: pid,
+      hostname: hostname,
+      level: 30,
+      hello: 'world',
+      msg: 'a msg',
+      v: 1
+    })
+  })
+  var instance = pino({}, {
+    [Symbol.for('needsMetadata')]: true,
+    write: function (chunk) {
+      t.equal(instance, this.lastLogger)
+      t.equal(30, this.lastLevel)
+      t.equal('a msg', this.lastMsg)
+      t.deepEqual({ hello: 'world' }, this.lastObj)
+      dest.write(chunk)
+    }
+  })
+
+  instance.info({ hello: 'world' }, 'a msg')
+})
+
+test('child loggers works', function (t) {
+  t.plan(6)
+  var dest = sink(function (chunk, enc, cb) {
+    t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
+    delete chunk.time
+    t.deepEqual(chunk, {
+      pid: pid,
+      hostname: hostname,
+      level: 30,
+      hello: 'world',
+      from: 'child',
+      msg: 'a msg',
+      v: 1
+    })
+  })
+  var instance = pino({}, {
+    [Symbol.for('needsMetadata')]: true,
+    write: function (chunk) {
+      t.equal(child, this.lastLogger)
+      t.equal(30, this.lastLevel)
+      t.equal('a msg', this.lastMsg)
+      t.deepEqual({ from: 'child' }, this.lastObj)
+      dest.write(chunk)
+    }
+  })
+
+  var child = instance.child({ hello: 'world' })
+  child.info({ from: 'child' }, 'a msg')
+})
+
+test('without object', function (t) {
+  t.plan(6)
+  var dest = sink(function (chunk, enc, cb) {
+    t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
+    delete chunk.time
+    t.deepEqual(chunk, {
+      pid: pid,
+      hostname: hostname,
+      level: 30,
+      msg: 'a msg',
+      v: 1
+    })
+  })
+  var instance = pino({}, {
+    [Symbol.for('needsMetadata')]: true,
+    write: function (chunk) {
+      t.equal(instance, this.lastLogger)
+      t.equal(30, this.lastLevel)
+      t.equal('a msg', this.lastMsg)
+      t.equal(null, this.lastObj)
+      dest.write(chunk)
+    }
+  })
+
+  instance.info('a msg')
+})
+
+test('without msg', function (t) {
+  t.plan(6)
+  var dest = sink(function (chunk, enc, cb) {
+    t.ok(new Date(chunk.time) <= new Date(), 'time is greater than Date.now()')
+    delete chunk.time
+    t.deepEqual(chunk, {
+      pid: pid,
+      hostname: hostname,
+      level: 30,
+      hello: 'world',
+      v: 1
+    })
+  })
+  var instance = pino({}, {
+    [Symbol.for('needsMetadata')]: true,
+    write: function (chunk) {
+      t.equal(instance, this.lastLogger)
+      t.equal(30, this.lastLevel)
+      t.equal(undefined, this.lastMsg)
+      t.deepEqual({ hello: 'world' }, this.lastObj)
+      dest.write(chunk)
+    }
+  })
+
+  instance.info({ hello: 'world' })
+})