Repository: pinojs/pino-http
Pull request #34 (2017-07-21 12:46:38)

Respect startTime if already defined
Sometimes it's not possible to attach logger in the very beginning of the request, unfortunately `pino-http` overwrites what's there for, what seems to me, no good reason.

mcollina: I think we move to a Symbol, something like `Symbol('startTime')`, so we won't get any overwrite. If it's already there it might not be a UNIX epoch, skewing the measurements.
Rauno56: Yes, that's even better.
mcollina: can you also add a quick unit test for this?
Rauno56: Added a test.
mcollina: It's not linting properly: https://travis-ci.org/pinojs/pino-http/jobs/256062011
Rauno56: Yep, saw that... So used to semicolons.
davidmarkclements: @Rauno56 can you please add a benchmark comparison to this convo - since we're now access a closured var just want to make sure there's no slow-down
Rauno56: Sure... Where's the docs?
mcollina: Run `node benchmarks/pino-server.js > /dev/null`, and then benchmark with `autocannon -c 100 -d 5 -p 10 localhost:3000`. Launch it two times and take the second run. Before and after the change :).

Yes, it might be nice to have this in the README or in a md file in the benchmarks folder.
Rauno56: ```
### Benchmarking http-ndjson-equivalent-server.js

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg    Stdev  Max    
Latency (ms) 30.59  92.62  538    
Req/Sec      3171   311.84 3407   
Bytes/Sec    356 kB 35 kB  393 kB 

16k requests in 5s, 1.76 MB read

### Benchmarking http-ndjson-minimal-server.js

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg    Stdev   Max    
Latency (ms) 27.08  82.01   507    
Req/Sec      3589   147.15  3729   
Bytes/Sec    401 kB 17.9 kB 426 kB 

18k requests in 5s, 1.99 MB read

### Benchmarking no-log-server.js

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg      Stdev   Max     
Latency (ms) 4.82     12.62   176     
Req/Sec      20286.41 505.52  20751   
Bytes/Sec    2.27 MB  52.4 kB 2.36 MB 

101k requests in 5s, 11.3 MB read

### Benchmarking pino-extreme-server.js

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev   Max     
Latency (ms) 8.38    25.37   191     
Req/Sec      11712.8 714.48  12247   
Bytes/Sec    1.29 MB 76.4 kB 1.38 MB 

59k requests in 5s, 6.5 MB read

### Benchmarking pino-server.js

Running 5s test @ http://localhost:3000
100 connections with 10 pipelining factor

Stat         Avg     Stdev   Max     
Latency (ms) 9.27    28.14   242     
Req/Sec      10589.6 920.77  11151   
Bytes/Sec    1.16 MB 98.3 kB 1.25 MB 

53k requests in 5s, 5.88 MB read
```

Patch:
diff --git a/logger.js b/logger.js
index a4f7245..a10f3e3 100644
--- a/logger.js
+++ b/logger.js
@@ -2,6 +2,8 @@
 
 var pino = require('pino')
 
+var startTime = Symbol('startTime')
+
 function pinoLogger (opts, stream) {
   if (opts && opts._writableState) {
     stream = opts
@@ -30,7 +32,7 @@ function pinoLogger (opts, stream) {
     this.removeListener('error', onResFinished)
 
     var log = this.log
-    var responseTime = Date.now() - this.startTime
+    var responseTime = Date.now() - this[startTime]
 
     if (err) {
       log.error({
@@ -50,7 +52,7 @@ function pinoLogger (opts, stream) {
   function loggingMiddleware (req, res, next) {
     req.id = genReqId(req)
     req.log = res.log = logger.child({req: req})
-    res.startTime = Date.now()
+    res[startTime] = res[startTime] || Date.now()
     if (!req.res) { req.res = res }
 
     res.on('finish', onResFinished)
@@ -105,3 +107,4 @@ module.exports.stdSerializers = {
   req: asReqValue,
   res: pino.stdSerializers.res
 }
+module.exports.startTime = startTime


Test patch:
diff --git a/test.js b/test.js
index d844734..4c7ed4a 100644
--- a/test.js
+++ b/test.js
@@ -164,6 +164,30 @@ test('reuses existing req.id if present', function (t) {
   })
 })
 
+test('startTime', function (t) {
+  var dest = split(JSON.parse)
+  var logger = pinoHttp(dest)
+  var someStartTime = 56
+
+  t.equal(typeof pinoHttp.startTime, 'symbol')
+
+  function loggerWithStartTime (req, res) {
+    res[pinoHttp.startTime] = someStartTime
+    logger(req, res)
+    t.equal(res[pinoHttp.startTime], someStartTime)
+  }
+
+  setup(t, loggerWithStartTime, function (err, server) {
+    t.error(err)
+    doGet(server)
+  })
+
+  dest.on('data', function (line) {
+    t.equal(typeof line.responseTime, 'number')
+    t.end()
+  })
+})
+
 test('responseTime', function (t) {
   var dest = split(JSON.parse)
   var logger = pinoHttp(dest)