From a0efc2c861d3e26a725a48d55beda62b66c9d064 Mon Sep 17 00:00:00 2001
From: dschom <dschomburg@mozilla.com>
Date: Fri, 14 Oct 2022 11:58:52 -0700
Subject: [PATCH] task(auth): Prevent possibility of double emitting logs

Because:
- When two loggers with the same name are created, logs end up being emitted twice.

This Commit:
- Prevents creating loggers with the same name.
- Automatically adjust logger name and warns about it.

Ideally we would just fail in this condition, but there are too many
tests that violate the notion that loggers have unique names. The
only pragmatic thing to do at this point is work around the problem
and attempt to correct the logger name.
---
 packages/fxa-auth-server/lib/log.js        | 24 +++++++++++++++-
 packages/fxa-auth-server/test/local/log.js | 32 ++++++++++++++++++++++
 2 files changed, 55 insertions(+), 1 deletion(-)

diff --git a/packages/fxa-auth-server/lib/log.js b/packages/fxa-auth-server/lib/log.js
index 35aeac35fd..4ce89be12b 100644
--- a/packages/fxa-auth-server/lib/log.js
+++ b/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);
 
diff --git a/packages/fxa-auth-server/test/local/log.js b/packages/fxa-auth-server/test/local/log.js
index f17867c3e5..128604591d 100644
--- a/packages/fxa-auth-server/test/local/log.js
+++ b/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',