feat: debug log global registrations and logger overwrites (#63)

* feat: debug log global registrations and logger overwrites

* refactor: extract `restore` as fn

* refactor: remove an excessive level of describe nesting

* refactor: assert multiple times instead of separating logger tests

* refactor: rename restore better

* test: fix tests by ignoring alerts about the logger being set

* feat: move debuglogging global to the end of the registration

... that's to assure we really did register it, not only attempted.
Any short-circuits will be logged as well, so the debug would be
unneccessary in those cases.

* test: fix tests to ignore the messages created in setup

* feat: add stack trace to DiagLogger overwrite warnings

* test: make sure only the second global logger logs after reregistration

* feat: revert changes to test structure

Author: rauno56

src/api/diag.ts

@@ -85,11 +85,18 @@ export class DiagAPI implements DiagLogger {
         return false;
       }
 
-      return registerGlobal(
-        'diag',
-        createLogLevelDiagLogger(logLevel, logger),
-        true
-      );
+      const oldLogger = getGlobal('diag');
+      const newLogger = createLogLevelDiagLogger(logLevel, logger);
+      // There already is an logger registered. We'll let it know before overwriting it.
+      if (oldLogger) {
+        const stack = new Error().stack ?? '<failed to generate stacktrace>';
+        oldLogger.warn(`Current logger will be overwritten from ${stack}`);
+        newLogger.warn(
+          `Current logger will overwrite one already registered from ${stack}`
+        );
+      }
+
+      return registerGlobal('diag', newLogger, true);
     };
 
     self.disable = () => {

src/internal/global-utils.ts

@@ -35,13 +35,12 @@ export function registerGlobal<Type extends keyof OTelGlobalAPI>(
   instance: OTelGlobalAPI[Type],
   allowOverride = false
 ): boolean {
-  _global[GLOBAL_OPENTELEMETRY_API_KEY] = _global[
+  const api = (_global[GLOBAL_OPENTELEMETRY_API_KEY] = _global[
     GLOBAL_OPENTELEMETRY_API_KEY
   ] ?? {
     version: VERSION,
-  };
+  });
 
-  const api = _global[GLOBAL_OPENTELEMETRY_API_KEY]!;
   if (!allowOverride && api[type]) {
     // already registered an API of this type
     const err = new Error(
@@ -61,6 +60,10 @@ export function registerGlobal<Type extends keyof OTelGlobalAPI>(
   }
 
   api[type] = instance;
+  diag.debug(
+    `@opentelemetry/api: Registered a global for ${type} v${VERSION}.`
+  );
+
   return true;
 }
 
@@ -75,6 +78,9 @@ export function getGlobal<Type extends keyof OTelGlobalAPI>(
 }
 
 export function unregisterGlobal(type: keyof OTelGlobalAPI) {
+  diag.debug(
+    `@opentelemetry/api: Unregistering a global for ${type} v${VERSION}.`
+  );
   const api = _global[GLOBAL_OPENTELEMETRY_API_KEY];
 
   if (api) {

test/diag/ComponentLogger.test.ts

@@ -20,13 +20,9 @@ import { diag, DiagLogger, DiagLogLevel } from '../../src';
 
 class SpyLogger implements DiagLogger {
   debug() {}
-
   error() {}
-
   info() {}
-
   warn() {}
-
   verbose() {}
 }
 
@@ -41,6 +37,8 @@ describe('ComponentLogger', () => {
     logger = new SpyLogger();
     sandbox.spy(logger);
     diag.setLogger(logger, DiagLogLevel.ALL);
+    // clean any messages up that might be there from the registration
+    sandbox.reset();
   });
 
   afterEach(() => {

test/diag/logLevel.test.ts

@@ -45,6 +45,12 @@ describe('LogLevelFilter DiagLogger', () => {
   /** Simulated Legacy logger */
   let incompleteLogger: DiagLogger;
 
+  const restoreCallHistory = () => {
+    diagLoggerFunctions.forEach(fName => {
+      calledArgs[fName] = null;
+    });
+  };
+
   beforeEach(() => {
     // Set no logger so that sinon doesn't complain about TypeError: Attempted to wrap xxxx which is already wrapped
     diag.disable();
@@ -66,10 +72,7 @@ describe('LogLevelFilter DiagLogger', () => {
   });
 
   afterEach(() => {
-    // restore
-    diagLoggerFunctions.forEach(fName => {
-      calledArgs[fName] = null;
-    });
+    restoreCallHistory();
   });
 
   const levelMap: Array<{
@@ -170,6 +173,7 @@ describe('LogLevelFilter DiagLogger', () => {
                   map.level,
                   dummyLogger
                 );
+                restoreCallHistory();
                 testLogger[fName](`${fName} called %s`, 'param1');
                 diagLoggerFunctions.forEach(lName => {
                   if (
@@ -190,6 +194,7 @@ describe('LogLevelFilter DiagLogger', () => {
 
           it('diag.setLogger level and logger should log', () => {
             diag.setLogger(dummyLogger, map.level);
+            restoreCallHistory();
             diag[fName](`${fName} called %s`, 'param1');
             diagLoggerFunctions.forEach(lName => {
               if (fName === lName && map.ignoreFuncs.indexOf(lName) === -1) {
@@ -217,6 +222,7 @@ describe('LogLevelFilter DiagLogger', () => {
               map.level,
               invalidLogger as any
             );
+            restoreCallHistory();
 
             testLogger[fName](`${fName} called %s`, 'param1');
             diagLoggerFunctions.forEach(lName => {

test/diag/logger.test.ts

@@ -38,6 +38,12 @@ describe('DiagLogger functions', () => {
 
   let dummyLogger: DiagLogger;
 
+  const restoreCallHistory = () => {
+    diagLoggerFunctions.forEach(fName => {
+      calledArgs[fName] = null;
+    });
+  };
+
   beforeEach(() => {
     // mock
     dummyLogger = {} as DiagLogger;
@@ -49,10 +55,7 @@ describe('DiagLogger functions', () => {
   });
 
   afterEach(() => {
-    // restore
-    diagLoggerFunctions.forEach(fName => {
-      calledArgs[fName] = null;
-    });
+    restoreCallHistory();
     diag.disable();
   });
 
@@ -75,6 +78,7 @@ describe('DiagLogger functions', () => {
 
       it(`diag should log with ${fName} message`, () => {
         diag.setLogger(dummyLogger, DiagLogLevel.ALL);
+        restoreCallHistory();
         diag[fName](`${fName} called %s`, 'param1');
         diagLoggerFunctions.forEach(lName => {
           if (fName === lName) {

test/internal/global.test.ts

@@ -18,6 +18,7 @@ import * as assert from 'assert';
 import { getGlobal } from '../../src/internal/global-utils';
 import { _globalThis } from '../../src/platform';
 import { NoopContextManager } from '../../src/context/NoopContextManager';
+import { DiagLogLevel } from '../../src/diag/types';
 import sinon = require('sinon');
 
 const api1 = require('../../src') as typeof import('../../src');
@@ -32,6 +33,14 @@ const api2 = require('../../src') as typeof import('../../src');
 // It is intentionally not autogenerated to ensure the author of the change is aware of what they are doing.
 const GLOBAL_API_SYMBOL_KEY = 'io.opentelemetry.js.api.0';
 
+const getMockLogger = () => ({
+  verbose: sinon.spy(),
+  debug: sinon.spy(),
+  info: sinon.spy(),
+  warn: sinon.spy(),
+  error: sinon.spy(),
+});
+
 describe('Global Utils', () => {
   // prove they are separate instances
   assert.notEqual(api1, api2);
@@ -94,48 +103,53 @@ describe('Global Utils', () => {
     );
   });
 
+  it('should debug log registrations', () => {
+    const logger = getMockLogger();
+    api1.diag.setLogger(logger, DiagLogLevel.DEBUG);
+
+    const newContextManager = new NoopContextManager();
+    api1.context.setGlobalContextManager(newContextManager);
+
+    sinon.assert.calledWith(logger.debug, sinon.match(/global for context/));
+    sinon.assert.calledWith(logger.debug, sinon.match(/global for diag/));
+    sinon.assert.calledTwice(logger.debug);
+  });
+
   it('should log an error if there is a duplicate registration', () => {
-    const error = sinon.stub();
-    api1.diag.setLogger({
-      verbose: () => {},
-      debug: () => {},
-      info: () => {},
-      warn: () => {},
-      error,
-    });
+    const logger = getMockLogger();
+    api1.diag.setLogger(logger);
 
     api1.context.setGlobalContextManager(new NoopContextManager());
     api1.context.setGlobalContextManager(new NoopContextManager());
 
-    sinon.assert.calledOnce(error);
-    assert.strictEqual(error.firstCall.args.length, 1);
+    sinon.assert.calledOnce(logger.error);
+    assert.strictEqual(logger.error.firstCall.args.length, 1);
     assert.ok(
-      error.firstCall.args[0].startsWith(
+      logger.error.firstCall.args[0].startsWith(
         'Error: @opentelemetry/api: Attempted duplicate registration of API: context'
       )
     );
   });
 
   it('should allow duplicate registration of the diag logger', () => {
-    const error1 = sinon.stub();
-    const error2 = sinon.stub();
-    api1.diag.setLogger({
-      verbose: () => {},
-      debug: () => {},
-      info: () => {},
-      warn: () => {},
-      error: error1,
-    });
-
-    api1.diag.setLogger({
-      verbose: () => {},
-      debug: () => {},
-      info: () => {},
-      warn: () => {},
-      error: error2,
-    });
-
-    sinon.assert.notCalled(error1);
-    sinon.assert.notCalled(error2);
+    const logger1 = getMockLogger();
+    const logger2 = getMockLogger();
+
+    api1.diag.setLogger(logger1);
+    api1.diag.setLogger(logger2);
+
+    const MSG = '__log message__';
+    api1.diag.info(MSG);
+
+    sinon.assert.notCalled(logger1.error);
+    sinon.assert.notCalled(logger1.info);
+    sinon.assert.calledOnce(logger1.warn);
+    sinon.assert.calledWith(logger1.warn, sinon.match(/will be overwritten/i));
+
+    sinon.assert.notCalled(logger2.error);
+    sinon.assert.calledOnce(logger2.warn);
+    sinon.assert.calledWith(logger2.warn, sinon.match(/will overwrite/i));
+    sinon.assert.calledOnce(logger2.info);
+    sinon.assert.calledWith(logger2.info, MSG);
   });
 });