Skip to content
This repository has been archived by the owner on Nov 10, 2022. It is now read-only.

Commit

Permalink
feat: debug log global registrations and logger overwrites (#63)
Browse files Browse the repository at this point in the history 
* 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
  • Loading branch information
@rauno56
rauno56 committed May 31, 2021
1 parent 950433f commit ef02843
Show file tree
Hide file tree
Showing 6 changed files with 86 additions and 51 deletions.
17 changes: 12 additions & 5 deletions src/api/diag.ts
View file
Expand Up @@ -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 = () => {
Expand Down
12 changes: 9 additions & 3 deletions src/internal/global-utils.ts
View file
Expand Up @@ -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(
Expand All @@ -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;
}

Expand All @@ -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) {
Expand Down
6 changes: 2 additions & 4 deletions test/diag/ComponentLogger.test.ts
View file
Expand Up @@ -20,13 +20,9 @@ import { diag, DiagLogger, DiagLogLevel } from '../../src';

class SpyLogger implements DiagLogger {
debug() {}

error() {}

info() {}

warn() {}

verbose() {}
}

Expand All @@ -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(() => {
Expand Down
14 changes: 10 additions & 4 deletions test/diag/logLevel.test.ts
View file
Expand Up @@ -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();
Expand All @@ -66,10 +72,7 @@ describe('LogLevelFilter DiagLogger', () => {
});

afterEach(() => {
// restore
diagLoggerFunctions.forEach(fName => {
calledArgs[fName] = null;
});
restoreCallHistory();
});

const levelMap: Array<{
Expand Down Expand Up @@ -170,6 +173,7 @@ describe('LogLevelFilter DiagLogger', () => {
map.level,
dummyLogger
);
restoreCallHistory();
testLogger[fName](`${fName} called %s`, 'param1');
diagLoggerFunctions.forEach(lName => {
if (
Expand All @@ -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) {
Expand Down Expand Up @@ -217,6 +222,7 @@ describe('LogLevelFilter DiagLogger', () => {
map.level,
invalidLogger as any
);
restoreCallHistory();

testLogger[fName](`${fName} called %s`, 'param1');
diagLoggerFunctions.forEach(lName => {
Expand Down
12 changes: 8 additions & 4 deletions test/diag/logger.test.ts
View file
Expand Up @@ -38,6 +38,12 @@ describe('DiagLogger functions', () => {

let dummyLogger: DiagLogger;

const restoreCallHistory = () => {
diagLoggerFunctions.forEach(fName => {
calledArgs[fName] = null;
});
};

beforeEach(() => {
// mock
dummyLogger = {} as DiagLogger;
Expand All @@ -49,10 +55,7 @@ describe('DiagLogger functions', () => {
});

afterEach(() => {
// restore
diagLoggerFunctions.forEach(fName => {
calledArgs[fName] = null;
});
restoreCallHistory();
diag.disable();
});

Expand All @@ -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) {
Expand Down
76 changes: 45 additions & 31 deletions test/internal/global.test.ts
View file
Expand Up @@ -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');
Expand All @@ -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);
Expand Down Expand Up @@ -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);
});
});

0 comments on commit ef02843

Please sign in to comment.