From a2d34aaa461cabf47147990a1c2910ea9a53b2d8 Mon Sep 17 00:00:00 2001
From: Laurence Rowe <l@lrowe.co.uk>
Date: Tue, 15 Aug 2017 14:45:57 -0700
Subject: [PATCH] fix: audit timers of same name should accumulate (#1435)
 (#1443)

---
 lib/plugins/audit.js       |  2 +-
 test/plugins/audit.test.js | 55 ++++++++++++++++++++++++++++++++++++++
 2 files changed, 56 insertions(+), 1 deletion(-)

diff --git a/lib/plugins/audit.js b/lib/plugins/audit.js
index 5f347ccfb..c861e155c 100644
--- a/lib/plugins/audit.js
+++ b/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
diff --git a/test/plugins/audit.test.js b/test/plugins/audit.test.js
index 478ad3e9b..1975deb97 100644
--- a/test/plugins/audit.test.js
+++ b/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.