Merge pull request #14244 from mozilla/FXA-6031-prevent-double-log-scenario

task(auth): Prevent possibility of double emitting logs

packages/fxa-auth-server/lib/log.js

@@ -17,9 +17,24 @@ const Sentry = require('@sentry/node');
 const ISSUER = config.get('domain') || '';
 const CLIENT_ID_TO_SERVICE_NAMES = config.get('oauth.clientIds') || {};
 
+// Keeps track of how many times a logger name has been used.
+const _registered = {};
+
 function Lug(options) {
+  const name = options.name || 'fxa-auth-server';
   EventEmitter.call(this);
-  this.name = options.name || 'fxa-auth-server';
+
+  // Ensure that names are unique. If two loggers are created with the same
+  // name, a double log scenario occurs.
+  if (_registered[name] === undefined) {
+    this.name = name;
+  } else {
+    let i = 1;
+    while (_registered[`${name}-${i}`] !== undefined) {
+      i++;
+    }
+    this.name = `${name}-${i}`;
+  }
 
   this.logger = mozlog({
     app: this.name,
@@ -27,12 +42,19 @@ function Lug(options) {
     stream: options.stderr || process.stderr,
     fmt: options.fmt,
   })();
+  _registered[this.name] = 1;
 
   this.stdout = options.stdout || process.stdout;
 
   this.nodeTracer = options.nodeTracer;
 
   this.notifier = require('./notifier')(this, statsd);
+
+  // Encourage avoiding scenarios where loggers names have to be incremented.
+  if (this.name !== name) {
+    const msg = `Logger with name of ${name} already registered. Adjusting name to ${this.name} to prevent double log scenario.`;
+    this.logger.warn('init', { msg });
+  }
 }
 util.inherits(Lug, EventEmitter);
 

packages/fxa-auth-server/test/local/log.js

@@ -175,6 +175,38 @@ describe('log', () => {
     );
   });
 
+  it('warns and fixes duplicate logger names', () => {
+    const logModule = proxyquire('../../lib/log', mocks);
+
+    const opts = {
+      level: 'debug',
+      name: 'test-duplicates',
+      stdout: { on: sinon.spy() },
+    };
+    logModule(opts);
+    logModule(opts);
+    logModule(opts);
+
+    // Edge case, user passes in already incremented name for some reason...
+    logModule({ ...opts, name: 'test-duplicates-1' });
+
+    assert.equal(mocks.mozlog.callCount, 5, 'mozlog was called 5 times');
+    assert.calledWithMatch(mocks.mozlog, { app: 'test' });
+    assert.calledWithMatch(mocks.mozlog, { app: opts.name });
+    assert.calledWithMatch(mocks.mozlog, { app: opts.name + '-1' });
+    assert.calledWithMatch(mocks.mozlog, { app: opts.name + '-2' });
+    assert.calledWithMatch(mocks.mozlog, { app: opts.name + '-1-1' });
+    assert.calledWithMatch(logger.warn, 'init', {
+      msg: `Logger with name of ${opts.name} already registered. Adjusting name to ${opts.name}-1 to prevent double log scenario.`,
+    });
+    assert.calledWithMatch(logger.warn, 'init', {
+      msg: `Logger with name of ${opts.name} already registered. Adjusting name to ${opts.name}-2 to prevent double log scenario.`,
+    });
+    assert.calledWithMatch(logger.warn, 'init', {
+      msg: `Logger with name of ${opts.name}-1 already registered. Adjusting name to ${opts.name}-1-1 to prevent double log scenario.`,
+    });
+  });
+
   it('.activityEvent', () => {
     log.activityEvent({
       event: 'foo',