From c4477905fe1afa1d16f569461ce09596fcde3e73 Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Tue, 11 May 2021 18:16:10 +0300 Subject: [PATCH 01/11] feat: debug log global registrations and logger overwrites --- src/api/diag.ts | 14 +++++++++----- src/internal/global-utils.ts | 12 +++++++++--- 2 files changed, 18 insertions(+), 8 deletions(-) diff --git a/src/api/diag.ts b/src/api/diag.ts index 768ad74c..1b09c34d 100644 --- a/src/api/diag.ts +++ b/src/api/diag.ts @@ -85,11 +85,15 @@ 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) { + oldLogger.warn('Current logger will be overwritten'); + newLogger.warn('Current logger will overwrite one already registered'); + } + + return registerGlobal('diag', newLogger, true); }; self.disable = () => { diff --git a/src/internal/global-utils.ts b/src/internal/global-utils.ts index 5115c762..1272bc6d 100644 --- a/src/internal/global-utils.ts +++ b/src/internal/global-utils.ts @@ -35,13 +35,16 @@ export function registerGlobal( instance: OTelGlobalAPI[Type], allowOverride = false ): boolean { - _global[GLOBAL_OPENTELEMETRY_API_KEY] = _global[ + diag.debug( + `@opentelemetry/api: Registering a global for ${type} v${VERSION}.` + ); + + 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( @@ -75,6 +78,9 @@ export function getGlobal( } 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) { From f2d722b56d8d9122a45de9cfce0abe501792d344 Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Wed, 19 May 2021 10:33:53 +0300 Subject: [PATCH 02/11] refactor: extract `restore` as fn --- test/diag/logLevel.test.ts | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/test/diag/logLevel.test.ts b/test/diag/logLevel.test.ts index 3786fba9..1aa00bc9 100644 --- a/test/diag/logLevel.test.ts +++ b/test/diag/logLevel.test.ts @@ -45,6 +45,12 @@ describe('LogLevelFilter DiagLogger', () => { /** Simulated Legacy logger */ let incompleteLogger: DiagLogger; + const restore = () => { + 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; - }); + restore(); }); const levelMap: Array<{ From f18dbadcb6f5109bd04e12676435d51190046e37 Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Wed, 19 May 2021 10:41:42 +0300 Subject: [PATCH 03/11] refactor: remove an excessive level of describe nesting --- test/diag/logLevel.test.ts | 39 +++++++++++++++++--------------------- 1 file changed, 17 insertions(+), 22 deletions(-) diff --git a/test/diag/logLevel.test.ts b/test/diag/logLevel.test.ts index 1aa00bc9..1c2d1bd4 100644 --- a/test/diag/logLevel.test.ts +++ b/test/diag/logLevel.test.ts @@ -165,28 +165,23 @@ describe('LogLevelFilter DiagLogger', () => { }); levelMap.forEach(masterLevelMap => { - describe(`when diag logger is set to ${masterLevelMap.message}`, () => { - it('diag.setLogger level is ignored when using a specific logger', () => { - diag.setLogger(dummyLogger, masterLevelMap.level); - - const testLogger = createLogLevelDiagLogger( - map.level, - dummyLogger - ); - testLogger[fName](`${fName} called %s`, 'param1'); - diagLoggerFunctions.forEach(lName => { - if ( - fName === lName && - map.ignoreFuncs.indexOf(lName) === -1 - ) { - assert.deepStrictEqual(calledArgs[lName], [ - `${fName} called %s`, - 'param1', - ]); - } else { - assert.strictEqual(calledArgs[lName], null); - } - }); + it(`diag.setLogger level is ignored when diag logger is set to ${masterLevelMap.message}`, () => { + diag.setLogger(dummyLogger, masterLevelMap.level); + + const testLogger = createLogLevelDiagLogger( + map.level, + dummyLogger + ); + testLogger[fName](`${fName} called %s`, 'param1'); + diagLoggerFunctions.forEach(lName => { + if (fName === lName && map.ignoreFuncs.indexOf(lName) === -1) { + assert.deepStrictEqual(calledArgs[lName], [ + `${fName} called %s`, + 'param1', + ]); + } else { + assert.strictEqual(calledArgs[lName], null); + } }); }); }); From 50c0f8439dca2947a7125cad37e4467f4a6d6fdb Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Wed, 19 May 2021 10:56:24 +0300 Subject: [PATCH 04/11] refactor: assert multiple times instead of separating logger tests --- test/diag/logLevel.test.ts | 20 +++++++++++++------- 1 file changed, 13 insertions(+), 7 deletions(-) diff --git a/test/diag/logLevel.test.ts b/test/diag/logLevel.test.ts index 1c2d1bd4..117098fd 100644 --- a/test/diag/logLevel.test.ts +++ b/test/diag/logLevel.test.ts @@ -164,8 +164,9 @@ describe('LogLevelFilter DiagLogger', () => { }); }); - levelMap.forEach(masterLevelMap => { - it(`diag.setLogger level is ignored when diag logger is set to ${masterLevelMap.message}`, () => { + it('diag.setLogger level is ignored when appropriate', () => { + levelMap.forEach(masterLevelMap => { + restore(); diag.setLogger(dummyLogger, masterLevelMap.level); const testLogger = createLogLevelDiagLogger( @@ -175,12 +176,17 @@ describe('LogLevelFilter DiagLogger', () => { testLogger[fName](`${fName} called %s`, 'param1'); diagLoggerFunctions.forEach(lName => { if (fName === lName && map.ignoreFuncs.indexOf(lName) === -1) { - assert.deepStrictEqual(calledArgs[lName], [ - `${fName} called %s`, - 'param1', - ]); + assert.deepStrictEqual( + calledArgs[lName], + [`${fName} called %s`, 'param1'], + `expected to see messages when diag logger is set to ${masterLevelMap.message}` + ); } else { - assert.strictEqual(calledArgs[lName], null); + assert.strictEqual( + calledArgs[lName], + null, + `did not expect to see messages when diag logger is set to ${masterLevelMap.message}` + ); } }); }); From 4c3e0568ab979d534f178fd959ddf1c5e2d0366b Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Wed, 19 May 2021 11:03:10 +0300 Subject: [PATCH 05/11] refactor: rename restore better --- test/diag/logLevel.test.ts | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/test/diag/logLevel.test.ts b/test/diag/logLevel.test.ts index 117098fd..7b78f15a 100644 --- a/test/diag/logLevel.test.ts +++ b/test/diag/logLevel.test.ts @@ -45,7 +45,7 @@ describe('LogLevelFilter DiagLogger', () => { /** Simulated Legacy logger */ let incompleteLogger: DiagLogger; - const restore = () => { + const restoreCallHistory = () => { diagLoggerFunctions.forEach(fName => { calledArgs[fName] = null; }); @@ -72,7 +72,7 @@ describe('LogLevelFilter DiagLogger', () => { }); afterEach(() => { - restore(); + restoreCallHistory(); }); const levelMap: Array<{ @@ -166,7 +166,7 @@ describe('LogLevelFilter DiagLogger', () => { it('diag.setLogger level is ignored when appropriate', () => { levelMap.forEach(masterLevelMap => { - restore(); + restoreCallHistory(); diag.setLogger(dummyLogger, masterLevelMap.level); const testLogger = createLogLevelDiagLogger( From 6a9aa8113c125edbfbf13188aaebd1998ef7648b Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Wed, 19 May 2021 11:03:45 +0300 Subject: [PATCH 06/11] test: fix tests by ignoring alerts about the logger being set --- test/diag/logLevel.test.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/test/diag/logLevel.test.ts b/test/diag/logLevel.test.ts index 7b78f15a..d8df13d0 100644 --- a/test/diag/logLevel.test.ts +++ b/test/diag/logLevel.test.ts @@ -166,13 +166,13 @@ describe('LogLevelFilter DiagLogger', () => { it('diag.setLogger level is ignored when appropriate', () => { levelMap.forEach(masterLevelMap => { - restoreCallHistory(); diag.setLogger(dummyLogger, masterLevelMap.level); const testLogger = createLogLevelDiagLogger( map.level, dummyLogger ); + restoreCallHistory(); testLogger[fName](`${fName} called %s`, 'param1'); diagLoggerFunctions.forEach(lName => { if (fName === lName && map.ignoreFuncs.indexOf(lName) === -1) { @@ -221,6 +221,7 @@ describe('LogLevelFilter DiagLogger', () => { map.level, invalidLogger as any ); + restoreCallHistory(); testLogger[fName](`${fName} called %s`, 'param1'); diagLoggerFunctions.forEach(lName => { From 2d71eaec33082d3d6b45cd29a3976f23817cfd7d Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Wed, 19 May 2021 12:15:24 +0300 Subject: [PATCH 07/11] 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. --- src/internal/global-utils.ts | 8 ++--- test/internal/global.test.ts | 70 ++++++++++++++++++++---------------- 2 files changed, 43 insertions(+), 35 deletions(-) diff --git a/src/internal/global-utils.ts b/src/internal/global-utils.ts index 1272bc6d..ec26adc7 100644 --- a/src/internal/global-utils.ts +++ b/src/internal/global-utils.ts @@ -35,10 +35,6 @@ export function registerGlobal( instance: OTelGlobalAPI[Type], allowOverride = false ): boolean { - diag.debug( - `@opentelemetry/api: Registering a global for ${type} v${VERSION}.` - ); - const api = (_global[GLOBAL_OPENTELEMETRY_API_KEY] = _global[ GLOBAL_OPENTELEMETRY_API_KEY ] ?? { @@ -64,6 +60,10 @@ export function registerGlobal( } api[type] = instance; + diag.debug( + `@opentelemetry/api: Registered a global for ${type} v${VERSION}.` + ); + return true; } diff --git a/test/internal/global.test.ts b/test/internal/global.test.ts index 3932722b..74d1d4e9 100644 --- a/test/internal/global.test.ts +++ b/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.1'; +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); @@ -91,48 +100,47 @@ describe('Global Utils', () => { assert.strictEqual(api1.context['_getContextManager'](), original); }); + 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); + + sinon.assert.notCalled(logger1.error); + 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)); }); }); From 15f4a0806020471e9b644ac959dbf5a24fbb7d8a Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Wed, 19 May 2021 12:21:29 +0300 Subject: [PATCH 08/11] test: fix tests to ignore the messages created in setup --- test/diag/ComponentLogger.test.ts | 6 ++---- test/diag/logLevel.test.ts | 1 + test/diag/logger.test.ts | 12 ++++++++---- 3 files changed, 11 insertions(+), 8 deletions(-) diff --git a/test/diag/ComponentLogger.test.ts b/test/diag/ComponentLogger.test.ts index bbc25b1e..b9648c21 100644 --- a/test/diag/ComponentLogger.test.ts +++ b/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(() => { diff --git a/test/diag/logLevel.test.ts b/test/diag/logLevel.test.ts index d8df13d0..cfe86ce8 100644 --- a/test/diag/logLevel.test.ts +++ b/test/diag/logLevel.test.ts @@ -194,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) { diff --git a/test/diag/logger.test.ts b/test/diag/logger.test.ts index 308c2603..c0efdcb6 100644 --- a/test/diag/logger.test.ts +++ b/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) { From 3cfa8216fd1a26baedbbc4c735287a768bd3af83 Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Fri, 21 May 2021 13:23:38 +0300 Subject: [PATCH 09/11] feat: add stack trace to DiagLogger overwrite warnings --- src/api/diag.ts | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/src/api/diag.ts b/src/api/diag.ts index 1b09c34d..6119040b 100644 --- a/src/api/diag.ts +++ b/src/api/diag.ts @@ -89,8 +89,11 @@ export class DiagAPI implements DiagLogger { const newLogger = createLogLevelDiagLogger(logLevel, logger); // There already is an logger registered. We'll let it know before overwriting it. if (oldLogger) { - oldLogger.warn('Current logger will be overwritten'); - newLogger.warn('Current logger will overwrite one already registered'); + const stack = new Error().stack ?? ''; + 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); From 479286e911494a0da55aa5da7288cd36065e7a02 Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Fri, 21 May 2021 22:44:43 +0300 Subject: [PATCH 10/11] test: make sure only the second global logger logs after reregistration --- test/internal/global.test.ts | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/test/internal/global.test.ts b/test/internal/global.test.ts index c6b32405..05aca17f 100644 --- a/test/internal/global.test.ts +++ b/test/internal/global.test.ts @@ -135,12 +135,18 @@ describe('Global Utils', () => { 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); }); }); From dd33bc30e71736fd65eb6390958ac40adfdb4165 Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Mon, 31 May 2021 12:26:31 +0300 Subject: [PATCH 11/11] feat: revert changes to test structure --- test/diag/logLevel.test.ts | 48 +++++++++++++++++++------------------- 1 file changed, 24 insertions(+), 24 deletions(-) diff --git a/test/diag/logLevel.test.ts b/test/diag/logLevel.test.ts index cfe86ce8..1825db31 100644 --- a/test/diag/logLevel.test.ts +++ b/test/diag/logLevel.test.ts @@ -164,30 +164,30 @@ describe('LogLevelFilter DiagLogger', () => { }); }); - it('diag.setLogger level is ignored when appropriate', () => { - levelMap.forEach(masterLevelMap => { - diag.setLogger(dummyLogger, masterLevelMap.level); - - const testLogger = createLogLevelDiagLogger( - map.level, - dummyLogger - ); - restoreCallHistory(); - testLogger[fName](`${fName} called %s`, 'param1'); - diagLoggerFunctions.forEach(lName => { - if (fName === lName && map.ignoreFuncs.indexOf(lName) === -1) { - assert.deepStrictEqual( - calledArgs[lName], - [`${fName} called %s`, 'param1'], - `expected to see messages when diag logger is set to ${masterLevelMap.message}` - ); - } else { - assert.strictEqual( - calledArgs[lName], - null, - `did not expect to see messages when diag logger is set to ${masterLevelMap.message}` - ); - } + levelMap.forEach(masterLevelMap => { + describe(`when diag logger is set to ${masterLevelMap.message}`, () => { + it('diag.setLogger level is ignored when using a specific logger', () => { + diag.setLogger(dummyLogger, masterLevelMap.level); + + const testLogger = createLogLevelDiagLogger( + map.level, + dummyLogger + ); + restoreCallHistory(); + testLogger[fName](`${fName} called %s`, 'param1'); + diagLoggerFunctions.forEach(lName => { + if ( + fName === lName && + map.ignoreFuncs.indexOf(lName) === -1 + ) { + assert.deepStrictEqual(calledArgs[lName], [ + `${fName} called %s`, + 'param1', + ]); + } else { + assert.strictEqual(calledArgs[lName], null); + } + }); }); }); });