fix: audit timers of same name should accumulate (#1435) (#1443)

lib/plugins/audit.js

@@ -86,7 +86,7 @@ function auditLogger(opts) {
                 (req.timers || []).forEach(function (time) {
                     var t = time.time;
                     var _t = Math.floor((1000000 * t[0]) + (t[1] / 1000));
-                    timers[time.name] = _t;
+                    timers[time.name] = (timers[time.name] || 0) + _t;
                 });
                 return ({
                     // account for native and queryParser plugin usage

test/plugins/audit.test.js

@@ -277,6 +277,61 @@ describe('audit logger', function () {
     });
 
 
+    it('restify-GH-1435 should accumulate log handler timers', function (done) {
+        // Dirty hack to capture the log record using a ring buffer.
+        var ringbuffer = new bunyan.RingBuffer({ limit: 1 });
+
+        SERVER.once('after', restify.plugins.auditLogger({
+            log: bunyan.createLogger({
+                name: 'audit',
+                streams:[ {
+                    level: 'info',
+                    type: 'raw',
+                    stream: ringbuffer
+                }]
+            }),
+            event: 'after'
+        }));
+
+        SERVER.get('/audit', function aTestHandler(req, res, next) {
+            req.startHandlerTimer('audit-acc');
+
+            setTimeout(function () {
+                req.endHandlerTimer('audit-acc');
+                // Very brief timing for same name
+                req.startHandlerTimer('audit-acc');
+                req.endHandlerTimer('audit-acc');
+                res.send('');
+                return (next());
+            }, 1100);
+            // this really should be 1000 but make it 1100 so that the tests
+            // don't sporadically fail due to timing issues.
+        });
+
+        CLIENT.get('/audit', function (err, req, res) {
+            assert.ifError(err);
+
+            var record = ringbuffer.records && ringbuffer.records[0];
+
+            // check timers
+            assert.ok(record, 'no log records');
+            assert.equal(
+                ringbuffer.records.length, 1,
+                'should only have 1 log record'
+            );
+            assert.ok(
+                record.req.timers.aTestHandler > 1000000,
+                'atestHandler should be > 1000000'
+            );
+            assert.ok(
+                record.req.timers['aTestHandler-audit-acc'] > 1000000,
+                'aTestHandler-audit-acc should be > 1000000'
+            );
+            done();
+        });
+    });
+
+
     it('restify-GH-812 audit logger has query params string', function (done) {
 
         // Dirty hack to capture the log record using a ring buffer.