From ef028434d92ed5629c4fe18fa2c5bc2674aaa86a Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Mon, 31 May 2021 12:34:29 +0300 Subject: [PATCH 1/3] 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 --- src/api/diag.ts | 17 +++++-- src/internal/global-utils.ts | 12 +++-- test/diag/ComponentLogger.test.ts | 6 +-- test/diag/logLevel.test.ts | 14 ++++-- test/diag/logger.test.ts | 12 +++-- test/internal/global.test.ts | 76 ++++++++++++++++++------------- 6 files changed, 86 insertions(+), 51 deletions(-) diff --git a/src/api/diag.ts b/src/api/diag.ts index 768ad74c..6119040b 100644 --- a/src/api/diag.ts +++ b/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 ?? ''; + 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 = () => { diff --git a/src/internal/global-utils.ts b/src/internal/global-utils.ts index 5115c762..ec26adc7 100644 --- a/src/internal/global-utils.ts +++ b/src/internal/global-utils.ts @@ -35,13 +35,12 @@ export function registerGlobal( 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( } api[type] = instance; + diag.debug( + `@opentelemetry/api: Registered a global for ${type} v${VERSION}.` + ); + return true; } @@ -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) { 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 3786fba9..1825db31 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 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 => { 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) { diff --git a/test/internal/global.test.ts b/test/internal/global.test.ts index 99fadb95..016dafe3 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.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); }); }); From 1a35772046f6bba0b960dd246df6e37eba0d7f15 Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Tue, 1 Jun 2021 23:09:48 +0300 Subject: [PATCH 2/3] chore: add node:16 to the test matrix (#85) --- .github/workflows/test.yaml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/.github/workflows/test.yaml b/.github/workflows/test.yaml index 5c0f08f1..d261f2a7 100644 --- a/.github/workflows/test.yaml +++ b/.github/workflows/test.yaml @@ -10,7 +10,7 @@ jobs: strategy: fail-fast: false matrix: - container: ["node:8", "node:10", "node:12", "node:14"] + container: ["node:8", "node:10", "node:12", "node:14", "node:16"] runs-on: ubuntu-latest container: image: ${{ matrix.container }} @@ -29,7 +29,7 @@ jobs: - name: Report Coverage run: npm run codecov - if: ${{ matrix.container }} == 'node:12' + if: ${{ matrix.container }} == 'node:14' browser-tests: runs-on: ubuntu-latest From 35224c7e3442f8f965bd543f2d1c8a8c70b47351 Mon Sep 17 00:00:00 2001 From: Naseem Date: Tue, 1 Jun 2021 16:36:51 -0400 Subject: [PATCH 3/3] =?UTF-8?q?chore:=20function=20overloads=20implementat?= =?UTF-8?q?ion=20of=20startActiveSpan=20in=20noop=20t=E2=80=A6=20(#81)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Daniel Dyla Co-authored-by: Valentin Marchaud --- src/trace/NoopTracer.ts | 62 ++++++++++--------- test/noop-implementations/noop-tracer.test.ts | 14 ++--- 2 files changed, 41 insertions(+), 35 deletions(-) diff --git a/src/trace/NoopTracer.ts b/src/trace/NoopTracer.ts index b44dde20..238553e6 100644 --- a/src/trace/NoopTracer.ts +++ b/src/trace/NoopTracer.ts @@ -49,41 +49,47 @@ export class NoopTracer implements Tracer { startActiveSpan ReturnType>( name: string, - arg2: F | SpanOptions, + fn: F + ): ReturnType; + startActiveSpan ReturnType>( + name: string, + opts: SpanOptions | undefined, + fn: F + ): ReturnType; + startActiveSpan ReturnType>( + name: string, + opts: SpanOptions | undefined, + ctx: Context | undefined, + fn: F + ): ReturnType; + startActiveSpan ReturnType>( + name: string, + arg2?: F | SpanOptions, arg3?: F | Context, arg4?: F ): ReturnType | undefined { - let fn: F | undefined, - options: SpanOptions | undefined, - activeContext: Context | undefined; - if (arguments.length === 2 && typeof arg2 === 'function') { - fn = arg2; - } else if ( - arguments.length === 3 && - typeof arg2 === 'object' && - typeof arg3 === 'function' - ) { - options = arg2; - fn = arg3; - } else if ( - arguments.length === 4 && - typeof arg2 === 'object' && - typeof arg3 === 'object' && - typeof arg4 === 'function' - ) { - options = arg2; - activeContext = arg3; - fn = arg4; + let opts: SpanOptions | undefined; + let ctx: Context | undefined; + let fn: F; + + if (arguments.length < 2) { + return; + } else if (arguments.length === 2) { + fn = arg2 as F; + } else if (arguments.length === 3) { + opts = arg2 as SpanOptions | undefined; + fn = arg3 as F; + } else { + opts = arg2 as SpanOptions | undefined; + ctx = arg3 as Context | undefined; + fn = arg4 as F; } - const parentContext = activeContext ?? context.active(); - const span = this.startSpan(name, options, parentContext); + const parentContext = ctx ?? context.active(); + const span = this.startSpan(name, opts, parentContext); const contextWithSpanSet = setSpan(parentContext, span); - if (fn) { - return context.with(contextWithSpanSet, fn, undefined, span); - } - return; + return context.with(contextWithSpanSet, fn, undefined, span); } } diff --git a/test/noop-implementations/noop-tracer.test.ts b/test/noop-implementations/noop-tracer.test.ts index 7f23ff22..03701720 100644 --- a/test/noop-implementations/noop-tracer.test.ts +++ b/test/noop-implementations/noop-tracer.test.ts @@ -69,16 +69,16 @@ describe('NoopTracer', () => { } }; const opts = { attributes: { foo: 'bar' } }; - const ctx = context.active(); - const a = tracer.startActiveSpan(name, fn); - assert.strictEqual(a, 1); + assert.strictEqual((tracer as any).startActiveSpan(name), undefined); - const b = tracer.startActiveSpan(name, opts, fn); + assert.strictEqual(tracer.startActiveSpan(name, fn), 1); - assert.strictEqual(b, 1); + assert.strictEqual(tracer.startActiveSpan(name, opts, fn), 1); - const c = tracer.startActiveSpan(name, opts, ctx, fn); - assert.strictEqual(c, 1); + assert.strictEqual( + tracer.startActiveSpan(name, opts, context.active(), fn), + 1 + ); }); });