text: 'use strict';
  /* eslint-disable func-names */
  
  // runtime modules
  var PassThrough = require('stream').PassThrough;
  
  // external requires
  var assert = require('chai').assert;
  var bunyan = require('bunyan');
  var lodash = require('lodash');
  var restify = require('../../lib/index.js');
  var restifyClients = require('restify-clients');
  
  // local files
  var helper = require('../lib/helper');
  var vasync = require('vasync');
  
  // local globals
  var MILLISECOND_IN_MICROSECONDS = 1000;
  var TOLERATED_MICROSECONDS = MILLISECOND_IN_MICROSECONDS;
  var SERVER;
  var CLIENT;
  var PORT;
  
  function assertIsAtLeastWithTolerate(num1, num2, tolerate, msg) {
      assert.isAtLeast(num1, num2 - tolerate, msg + 'should be >= ' + num2);
  }
  
  describe('audit logger', function() {
      beforeEach(function(done) {
          SERVER = restify.createServer({
              dtrace: helper.dtrace,
              log: helper.getLog('server')
          });
  
          SERVER.listen(0, '127.0.0.1', function() {
              PORT = SERVER.address().port;
              CLIENT = restifyClients.createJsonClient({
                  url: 'http://127.0.0.1:' + PORT,
                  dtrace: helper.dtrace,
                  retry: false
              });
  
              done();
          });
      });
  
      afterEach(function(done) {
          CLIENT.close();
          SERVER.close(done);
      });
  
      it('audit logger should print log by default', function(done) {
          var logBuffer = new bunyan.RingBuffer({
              limit: 1000
          });
          var collectLog;
          SERVER.on(
              'after',
              restify.plugins.auditLogger({
                  log: bunyan.createLogger({
                      name: 'audit',
                      streams: [
                          {
                              level: 'info',
                              stream: process.stdout
                          }
                      ]
                  }),
                  server: SERVER,
                  event: 'after'
              })
          );
  
          SERVER.get('/foo', function(req, res, next) {
              res.send(200, { testdata: 'foo' });
              next();
          });
  
          SERVER.get('/bar', function(req, res, next) {
              res.send(200, { testdata: 'bar' });
              next();
          });
  
          SERVER.get('/auditrecords', function(req, res, next) {
              // strip log records of req/res as they will cause
              // serialization issues.
              var data = logBuffer.records.map(function(record) {
                  return lodash.omit(record, 'req', 'res');
              }, []);
              res.send(200, data);
              next();
          });
  
          collectLog = function() {
              CLIENT.get('/auditrecords', function(err, req, res) {
                  assert.ifError(err);
                  var data = JSON.parse(res.body);
                  assert.ok(data);
                  data.forEach(function(d) {
                      assert.isNumber(d.latency);
                  });
                  done();
              });
          };
  
          vasync.forEachParallel(
              {
                  func: function clientRequest(urlPath, callback) {
                      CLIENT.get(urlPath, function(err, req, res) {
                          assert.ifError(err);
                          assert.ok(JSON.parse(res.body));
                          return callback(err, JSON.parse(res.body));
                      });
                  },
                  inputs: ['/foo', '/bar']
              },
              function(err, results) {
                  assert.ifError(err);
                  collectLog();
              }
          );
      });
  
      it('test audit logger emit', function(done) {
          SERVER.once(
              'after',
              restify.plugins.auditLogger({
                  log: bunyan.createLogger({
                      name: 'audit',
                      streams: [
                          {
                              level: 'info',
                              stream: process.stdout
                          }
                      ]
                  }),
                  server: SERVER,
                  event: 'after'
              })
          );
  
          SERVER.once('audit', function(data) {
              assert.ok(data);
              assert.ok(data.req_id);
              assert.equal(
                  data.req.url,
                  '/audit',
                  'request url should be /audit'
              );
              assert.isNumber(data.latency);
              done();
          });
  
          SERVER.get('/audit', [
              restify.plugins.queryParser(),
              function(req, res, next) {
                  res.send();
                  next();
              }
          ]);
  
          CLIENT.get('/audit', function(err, req, res) {
              assert.ifError(err);
          });
      });
  
      it('test custom serializers', 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',
                  serializers: {
                      req: function(req) {
                          return { fooReq: 'barReq' };
                      },
                      res: function(res) {
                          return { fooRes: 'barRes' };
                      }
                  }
              })
          );
  
          SERVER.get('/audit', function aTestHandler(req, res, next) {
              res.send('');
              return next();
          });
  
          SERVER.on('after', function() {
              var record = ringbuffer.records && ringbuffer.records[0];
              assert.equal(record.req.fooReq, 'barReq');
              assert.equal(record.res.fooRes, 'barRes');
              done();
          });
  
          CLIENT.get('/audit', function(err, req, res) {
              assert.ifError(err);
          });
      });
  
      it('should log handler timers', function(done) {
          // Dirty hack to capture the log record using a ring buffer.
          var ringbuffer = new bunyan.RingBuffer({ limit: 1 });
          var WAIT_IN_MILLISECONDS = 1100;
  
          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-sub');
  
              setTimeout(function() {
                  req.endHandlerTimer('audit-sub');
                  res.send('');
                  return next();
              }, WAIT_IN_MILLISECONDS);
              // this really should be 1000 but make it 1100 so that the tests
              // don't sporadically fail due to timing issues.
          });
  
          SERVER.on('after', function() {
              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'
              );
              assertIsAtLeastWithTolerate(
                  record.req.timers.aTestHandler,
                  WAIT_IN_MILLISECONDS * MILLISECOND_IN_MICROSECONDS,
                  TOLERATED_MICROSECONDS,
                  'atestHandler'
              );
              assertIsAtLeastWithTolerate(
                  record.req.timers['aTestHandler-audit-sub'],
                  WAIT_IN_MILLISECONDS * MILLISECOND_IN_MICROSECONDS,
                  TOLERATED_MICROSECONDS,
                  'aTestHandler-audit-sub'
              );
  
              var handlers = Object.keys(record.req.timers);
              assert.equal(
                  handlers[handlers.length - 2],
                  'aTestHandler-audit-sub',
                  'sub handler timer not in order'
              );
              assert.equal(
                  handlers[handlers.length - 1],
                  'aTestHandler',
                  'aTestHandler not last'
              );
              done();
          });
  
          CLIENT.get('/audit', function(err, req, res) {
              assert.ifError(err);
          });
      });
  
      it('should log anonymous handler timers', function(done) {
          this.timeout(5000);
  
          // Dirty hack to capture the log record using a ring buffer.
          var ringbuffer = new bunyan.RingBuffer({ limit: 1 });
          var WAIT_IN_MILLISECONDS = 1000;
  
          SERVER.once(
              'after',
              restify.plugins.auditLogger({
                  log: bunyan.createLogger({
                      name: 'audit',
                      streams: [
                          {
                              level: 'info',
                              type: 'raw',
                              stream: ringbuffer
                          }
                      ]
                  }),
                  event: 'after'
              })
          );
  
          SERVER.pre(function(req, res, next) {
              next();
          });
          SERVER.pre(function(req, res, next) {
              next();
          });
  
          SERVER.use(function(req, res, next) {
              next();
          });
          SERVER.use(function(req, res, next) {
              next();
          });
  
          SERVER.get(
              '/audit',
              function(req, res, next) {
                  setTimeout(function() {
                      return next();
                  }, WAIT_IN_MILLISECONDS);
              },
              function(req, res, next) {
                  req.startHandlerTimer('audit-sub');
  
                  setTimeout(function() {
                      req.endHandlerTimer('audit-sub');
                      res.send('');
                      return next();
                  }, WAIT_IN_MILLISECONDS);
              }
          );
  
          SERVER.on('after', function() {
              // check timers
              var record = ringbuffer.records && ringbuffer.records[0];
              assert.ok(record, 'no log records');
              assert.equal(
                  ringbuffer.records.length,
                  1,
                  'should only have 1 log record'
              );
              assertIsAtLeastWithTolerate(
                  record.req.timers['pre-0'],
                  0,
                  TOLERATED_MICROSECONDS,
                  'pre-0'
              );
              assertIsAtLeastWithTolerate(
                  record.req.timers['pre-1'],
                  0,
                  TOLERATED_MICROSECONDS,
                  'pre-1'
              );
              assertIsAtLeastWithTolerate(
                  record.req.timers['use-0'],
                  0,
                  TOLERATED_MICROSECONDS,
                  'use-0'
              );
              assertIsAtLeastWithTolerate(
                  record.req.timers['use-1'],
                  0,
                  TOLERATED_MICROSECONDS,
                  'use-1'
              );
              assertIsAtLeastWithTolerate(
                  record.req.timers['handler-0'],
                  WAIT_IN_MILLISECONDS * MILLISECOND_IN_MICROSECONDS,
                  TOLERATED_MICROSECONDS,
                  'handler-0'
              );
              assertIsAtLeastWithTolerate(
                  record.req.timers['handler-1'],
                  WAIT_IN_MILLISECONDS * MILLISECOND_IN_MICROSECONDS,
                  TOLERATED_MICROSECONDS,
                  'handler-1'
              );
              assertIsAtLeastWithTolerate(
                  record.req.timers['handler-1-audit-sub'],
                  WAIT_IN_MILLISECONDS * MILLISECOND_IN_MICROSECONDS,
                  TOLERATED_MICROSECONDS,
                  'handler-0-audit-sub'
              );
  
              var handlers = Object.keys(record.req.timers);
              assert.equal(
                  handlers[handlers.length - 2],
                  'handler-1-audit-sub',
                  'sub handler timer not in order'
              );
              assert.equal(
                  handlers[handlers.length - 1],
                  'handler-1',
                  'handler-1 not last'
              );
              done();
          });
  
          CLIENT.get('/audit', function(err, req, res) {
              assert.ifError(err);
          });
      });
  
      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 });
          var WAIT_IN_MILLISECONDS = 1100;
  
          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();
              }, WAIT_IN_MILLISECONDS);
              // this really should be 1000 but make it 1100 so that the tests
              // don't sporadically fail due to timing issues.
          });
  
          SERVER.on('after', function() {
              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'
              );
              assertIsAtLeastWithTolerate(
                  record.req.timers.aTestHandler,
                  WAIT_IN_MILLISECONDS * MILLISECOND_IN_MICROSECONDS,
                  TOLERATED_MICROSECONDS,
                  'atestHandler'
              );
              assertIsAtLeastWithTolerate(
                  record.req.timers['aTestHandler-audit-acc'],
                  WAIT_IN_MILLISECONDS * MILLISECOND_IN_MICROSECONDS,
                  TOLERATED_MICROSECONDS,
                  'aTestHandler-audit-acc'
              );
              done();
          });
  
          CLIENT.get('/audit', function(err, req, res) {
              assert.ifError(err);
          });
      });
  
      it('restify-GH-812 audit logger has query params string', 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(req, res, next) {
              res.send();
              next();
          });
  
          SERVER.on('after', function() {
              // check timers
              assert.ok(ringbuffer.records[0], 'no log records');
              assert.equal(
                  ringbuffer.records.length,
                  1,
                  'should only have 1 log record'
              );
              assert.ok(ringbuffer.records[0].req.query, 'a=1&b=2');
              done();
          });
  
          CLIENT.get('/audit?a=1&b=2', function(err, req, res) {
              assert.ifError(err);
          });
      });
  
      it('restify-GH-812 audit logger has query params obj', 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', [
              restify.plugins.queryParser(),
              function(req, res, next) {
                  res.send();
                  next();
              }
          ]);
  
          SERVER.on('after', function() {
              // check timers
              assert.ok(ringbuffer.records[0], 'no log records');
              assert.equal(
                  ringbuffer.records.length,
                  1,
                  'should only have 1 log record'
              );
              assert.deepEqual(ringbuffer.records[0].req.query, {
                  a: '1',
                  b: '2'
              });
              done();
          });
  
          CLIENT.get('/audit?a=1&b=2', function(err, req, res) {
              assert.ifError(err);
          });
      });
  
      it('should work with pre events', function(done) {
          var ptStream = new PassThrough();
  
          SERVER.once(
              'pre',
              restify.plugins.auditLogger({
                  log: bunyan.createLogger({
                      name: 'audit',
                      streams: [
                          {
                              level: 'info',
                              stream: ptStream
                          }
                      ]
                  }),
                  event: 'pre'
              })
          );
  
          SERVER.get('/audit', [
              restify.plugins.queryParser(),
              function(req, res, next) {
                  res.send();
                  next();
              }
          ]);
  
          ptStream.on('data', function(data) {
              var log = JSON.parse(data);
              assert.equal('pre', log.component);
              assert.ok(log.req_id);
              assert.ok(log.req);
              assert.ok(log.res);
          });
  
          CLIENT.get('/audit?a=1&b=2', function(err, req, res) {
              assert.ifError(err);
              done();
          });
      });
  
      it('should work with routed events', function(done) {
          var ptStream = new PassThrough();
  
          SERVER.once(
              'routed',
              restify.plugins.auditLogger({
                  log: bunyan.createLogger({
                      name: 'audit',
                      streams: [
                          {
                              level: 'info',
                              stream: ptStream
                          }
                      ]
                  }),
                  event: 'routed'
              })
          );
  
          SERVER.get('/audit', [
              restify.plugins.queryParser(),
              function(req, res, next) {
                  res.send();
                  next();
              }
          ]);
  
          ptStream.on('data', function(data) {
              var log = JSON.parse(data);
              assert.equal('routed', log.component);
              assert.ok(log.req_id);
              assert.ok(log.req);
              assert.ok(log.res);
          });
  
          CLIENT.get('/audit?a=1&b=2', function(err, req, res) {
              assert.ifError(err);
              done();
          });
      });
  
      it('should work with custom context functions', function(done) {
          SERVER.once(
              'after',
              restify.plugins.auditLogger({
                  log: bunyan.createLogger({
                      name: 'audit',
                      streams: [
                          {
                              level: 'info',
                              stream: process.stdout
                          }
                      ]
                  }),
                  context: function(req, res, route, err) {
                      return {
                          qs: req.getQuery()
                      };
                  },
                  server: SERVER,
                  event: 'after'
              })
          );
  
          SERVER.once('audit', function(data) {
              assert.ok(data);
              assert.ok(data.req_id);
              assert.isNumber(data.latency);
              assert.ok(data.context);
              assert.equal(data.context.qs, 'foo=bar');
              done();
          });
  
          SERVER.get('/audit', [
              restify.plugins.queryParser(),
              function(req, res, next) {
                  res.send();
                  next();
              }
          ]);
  
          CLIENT.get('/audit?foo=bar', function(err, req, res) {
              assert.ifError(err);
          });
      });
  
      it('should log 444 for closed request', function(done) {
          SERVER.once(
              'after',
              restify.plugins.auditLogger({
                  log: bunyan.createLogger({
                      name: 'audit',
                      streams: [
                          {
                              level: 'info',
                              stream: process.stdout
                          }
                      ]
                  }),
                  server: SERVER,
                  event: 'after'
              })
          );
  
          SERVER.once('audit', function(data) {
              assert.ok(data);
              assert.ok(data.req_id);
              assert.isNumber(data.latency);
              assert.equal(data.res.statusCode, 444);
              done();
          });
  
          SERVER.get('/audit', function(req, res, next) {
              setTimeout(function() {
                  res.send();
                  next();
              }, 100);
          });
  
          CLIENT.get(
              {
                  path: '/audit',
                  requestTimeout: 50
              },
              function(err, req, res) {}
          );
      });
  });
  