diff --git a/src/common/wrap/wrap-logger.js b/src/common/wrap/wrap-logger.js new file mode 100644 index 000000000..f27027bed --- /dev/null +++ b/src/common/wrap/wrap-logger.js @@ -0,0 +1,38 @@ +/* + * Copyright 2020 New Relic Corporation. All rights reserved. + * SPDX-License-Identifier: Apache-2.0 + */ +/** + * @file Wraps native timeout and interval methods for instrumentation. + * This module is used by: jserrors, spa. + */ + +import { ee as baseEE } from '../event-emitter/contextual-ee' +import { createWrapperWithEmitter as wfn } from './wrap-function' + +/** + * Wraps a supplied function and adds emitter events under the `-wrap-logger-` prefix + * @param {Object} sharedEE - The shared event emitter on which a new scoped event emitter will be based. + * @param {Object} parent - The parent object housing the logger function + * @param {string} loggerFn - The name of the function in the parent object to wrap + * @returns {Object} Scoped event emitter with a debug ID of `logger`. + */ +// eslint-disable-next-line +export function wrapLogger(sharedEE, parent, loggerFn) { + const ee = scopedEE(sharedEE) + var wrapFn = wfn(ee) + + wrapFn.inPlace(parent, [loggerFn], `${loggerFn}-wrap-logger-`) + return ee +} + +/** + * Returns an event emitter scoped specifically for the `logger` context. This scoping is a remnant from when all the + * features shared the same group in the event, to isolate events between features. It will likely be revisited. + * @param {Object} sharedEE - Optional event emitter on which to base the scoped emitter. + * Uses `ee` on the global scope if undefined). + * @returns {Object} Scoped event emitter with a debug ID of 'logger'. + */ +export function scopedEE (sharedEE) { + return (sharedEE || baseEE).get('logger') +} diff --git a/src/loaders/api/api-methods.js b/src/loaders/api/api-methods.js index adca6bfef..54f9d42b3 100644 --- a/src/loaders/api/api-methods.js +++ b/src/loaders/api/api-methods.js @@ -1,5 +1,6 @@ import { SR_EVENT_EMITTER_TYPES } from '../../features/session_replay/constants' +/** These will get moved to feature constants once the feature exists */ export const logApiMethods = [ 'logError', 'logWarn', 'logInfo', 'logDebug', 'logTrace' ] @@ -8,7 +9,7 @@ export const apiMethods = [ 'setErrorHandler', 'finished', 'addToTrace', 'addRelease', 'addPageAction', 'setCurrentRouteName', 'setPageViewName', 'setCustomAttribute', 'interaction', 'noticeError', 'setUserId', 'setApplicationVersion', 'start', - SR_EVENT_EMITTER_TYPES.RECORD, SR_EVENT_EMITTER_TYPES.PAUSE, ...logApiMethods + SR_EVENT_EMITTER_TYPES.RECORD, SR_EVENT_EMITTER_TYPES.PAUSE, ...logApiMethods, 'wrapLogger' ] export const asyncApiMethods = [ diff --git a/src/loaders/api/api.js b/src/loaders/api/api.js index b990bd26e..ed6aab155 100644 --- a/src/loaders/api/api.js +++ b/src/loaders/api/api.js @@ -16,6 +16,8 @@ import { apiMethods, asyncApiMethods, logApiMethods } from './api-methods' import { SR_EVENT_EMITTER_TYPES } from '../../features/session_replay/constants' import { now } from '../../common/timing/now' import { MODE } from '../../common/session/constants' +import { wrapLogger } from '../../common/wrap/wrap-logger' +import { stringify } from '../../common/util/stringify' export function setTopLevelCallers () { const nr = gosCDN() @@ -35,6 +37,7 @@ export function setTopLevelCallers () { } const replayRunning = {} +const wrappedLoggers = new Set() export function setAPI (agentIdentifier, forceDrain, runSoftNavOverSpa = false) { if (!forceDrain) registerDrain(agentIdentifier, 'api') @@ -57,17 +60,31 @@ export function setAPI (agentIdentifier, forceDrain, runSoftNavOverSpa = false) * @param {{[key: string]: *}} context * @param {string} level */ - function log (message, context, level = 'info') { - handle(SUPPORTABILITY_METRIC_CHANNEL, [`API/log${level}/called`], undefined, FEATURE_NAMES.metrics, instanceEE) - handle('log', [now(), message, context, level], undefined, FEATURE_NAMES.logging, instanceEE) + function log (message, customAttributes, level = 'info') { + handle(SUPPORTABILITY_METRIC_CHANNEL, [`API/logging/${level}/called`], undefined, FEATURE_NAMES.metrics, instanceEE) + handle('log', [now(), message, customAttributes, level], undefined, FEATURE_NAMES.logging, instanceEE) } logApiMethods.forEach((method) => { - apiInterface[method] = function (message, context) { - log(message, context, method.toLowerCase().replace('log', '')) + apiInterface[method] = function (message, customAttributes = {}) { + log(message, customAttributes, method.toLowerCase().replace('log', '')) } }) + apiInterface.wrapLogger = (parent, functionName, level = 'info', customAttributes = {}) => { + if (!(typeof parent === 'object' && typeof functionName === 'string')) return + wrapLogger(instanceEE, parent, functionName) + if (!wrappedLoggers.has(parent[functionName])) { + wrappedLoggers.add(parent[functionName]) + instanceEE.on(`${functionName}-wrap-logger-end`, ([message, ...args]) => { + log(message, { + ...(!!args.length && { 'wrappedFn.args': stringify(args) }), + ...customAttributes + }, level) + }) + } + } + // Setup stub functions that queue calls for later processing. asyncApiMethods.forEach(fnName => { apiInterface[fnName] = apiCall(prefix, fnName, true, 'api') }) diff --git a/tests/components/api.test.js b/tests/components/api.test.js index 2ce38a89b..6d0f947e7 100644 --- a/tests/components/api.test.js +++ b/tests/components/api.test.js @@ -41,7 +41,7 @@ describe('setAPI', () => { test('should add expected api methods returned object', () => { const apiInterface = setAPI(agentId, true) - expect(Object.keys(apiInterface).length).toEqual(20) + expect(Object.keys(apiInterface).length).toEqual(21) expect(typeof apiInterface.setErrorHandler).toEqual('function') expect(typeof apiInterface.finished).toEqual('function') expect(typeof apiInterface.addToTrace).toEqual('function') @@ -62,6 +62,7 @@ describe('setAPI', () => { expect(typeof apiInterface.logWarn).toEqual('function') expect(typeof apiInterface.logDebug).toEqual('function') expect(typeof apiInterface.logTrace).toEqual('function') + expect(typeof apiInterface.wrapLogger).toEqual('function') }) test('should register api drain when not forced', () => { @@ -563,15 +564,134 @@ describe('setAPI', () => { }) describe('logging', () => { - logApiMethods.forEach(logMethod => { - describe(logMethod, () => { - let apiInterface + let apiInterface + beforeEach(async () => { + apiInterface = setAPI(agentId, true) + await new Promise(process.nextTick) + }) + describe('wrapLogger', () => { + test('should emit events for calls by wrapped function - defaults', () => { + const myLoggerPackage = { + myObservedLogger: jest.fn(), + myUnobservedLogger: jest.fn() + } + apiInterface.wrapLogger(myLoggerPackage, 'myObservedLogger') - beforeEach(async () => { - apiInterface = setAPI(agentId, true) - await new Promise(process.nextTick) - }) + /** emits data for observed fn */ + myLoggerPackage.myObservedLogger('test1') + + expect(myLoggerPackage.myObservedLogger).toHaveBeenCalled() + expect(handleModule.handle).toHaveBeenCalledTimes(2) + + const firstEmit = handleModule.handle.mock.calls[0] + expect(firstEmit[0]).toEqual(SUPPORTABILITY_METRIC_CHANNEL) + expect(firstEmit[1]).toEqual(['API/logging/info/called']) // defaults to info + expect(firstEmit[2]).toBeUndefined() + expect(firstEmit[3]).toEqual(FEATURE_NAMES.metrics) + expect(firstEmit[4]).toEqual(instanceEE) + + const secondEmit = handleModule.handle.mock.calls[1] + expect(secondEmit[0]).toEqual('log') + expect(secondEmit[1]).toEqual([expect.any(Number), 'test1', {}, 'info']) // defaults to {} + expect(secondEmit[2]).toBeUndefined() + expect(secondEmit[3]).toEqual(FEATURE_NAMES.logging) + expect(secondEmit[4]).toEqual(instanceEE) + + /** does NOT emit data for observed fn */ + myLoggerPackage.myUnobservedLogger('test1') + + expect(myLoggerPackage.myUnobservedLogger).toHaveBeenCalled() + expect(handleModule.handle).toHaveBeenCalledTimes(2) // still at 2 from last call + }) + + test('should emit events for calls by wrapped function - specified', () => { + const randomMethodName = faker.string.uuid() + const myLoggerPackage = { + [randomMethodName]: jest.fn() + } + apiInterface.wrapLogger(myLoggerPackage, randomMethodName, 'warn', { myCustomAttr: 1 }) + + /** emits data for observed fn */ + myLoggerPackage[randomMethodName]('test1') + + expect(myLoggerPackage[randomMethodName]).toHaveBeenCalled() + expect(handleModule.handle).toHaveBeenCalledTimes(2) + + const firstEmit = handleModule.handle.mock.calls[0] + expect(firstEmit[0]).toEqual(SUPPORTABILITY_METRIC_CHANNEL) + expect(firstEmit[1]).toEqual(['API/logging/warn/called']) // specified + expect(firstEmit[2]).toBeUndefined() + expect(firstEmit[3]).toEqual(FEATURE_NAMES.metrics) + expect(firstEmit[4]).toEqual(instanceEE) + + const secondEmit = handleModule.handle.mock.calls[1] + expect(secondEmit[0]).toEqual('log') + expect(secondEmit[1]).toEqual([expect.any(Number), 'test1', { myCustomAttr: 1 }, 'warn']) // specified + expect(secondEmit[2]).toBeUndefined() + expect(secondEmit[3]).toEqual(FEATURE_NAMES.logging) + expect(secondEmit[4]).toEqual(instanceEE) + }) + + test('should emit events with concat string for multiple args', () => { + const randomMethodName = faker.string.uuid() + const myLoggerPackage = { + [randomMethodName]: jest.fn() + } + apiInterface.wrapLogger(myLoggerPackage, randomMethodName) + + /** emits data for observed fn */ + myLoggerPackage[randomMethodName]('test1', { test2: 2 }, ['test3'], true, 1) + + expect(myLoggerPackage[randomMethodName]).toHaveBeenCalled() + expect(handleModule.handle).toHaveBeenCalledTimes(2) + + const firstEmit = handleModule.handle.mock.calls[0] + expect(firstEmit[0]).toEqual(SUPPORTABILITY_METRIC_CHANNEL) + expect(firstEmit[1]).toEqual(['API/logging/info/called']) // specified + expect(firstEmit[2]).toBeUndefined() + expect(firstEmit[3]).toEqual(FEATURE_NAMES.metrics) + expect(firstEmit[4]).toEqual(instanceEE) + + const secondEmit = handleModule.handle.mock.calls[1] + expect(secondEmit[0]).toEqual('log') + expect(secondEmit[1]).toEqual([expect.any(Number), 'test1', { 'wrappedFn.args': '[{"test2":2},["test3"],true,1]' }, 'info']) // specified + expect(secondEmit[2]).toBeUndefined() + expect(secondEmit[3]).toEqual(FEATURE_NAMES.logging) + expect(secondEmit[4]).toEqual(instanceEE) + }) + + test('wrapped function should still behave as intended', () => { + const randomMethodName = faker.string.uuid() + const myLoggerPackage = { + [randomMethodName]: jest.fn((arg) => arg + ' returned') + } + apiInterface.wrapLogger(myLoggerPackage, randomMethodName) + + /** emits data for observed fn */ + const output = myLoggerPackage[randomMethodName]('test1') + + expect(myLoggerPackage[randomMethodName]).toHaveBeenCalled() + expect(output).toEqual('test1 returned') + }) + test('should not emit events for same method twice', () => { + const distinctMethodName = 'distinctMethodName' + const myLoggerPackage = { + [distinctMethodName]: jest.fn() + } + apiInterface.wrapLogger(myLoggerPackage, distinctMethodName) + + myLoggerPackage[distinctMethodName]('test1') + expect(myLoggerPackage[distinctMethodName]).toHaveBeenCalledTimes(1) + + /** Wrap again... BUT it should only emit an event once still */ + apiInterface.wrapLogger(myLoggerPackage, distinctMethodName) + expect(myLoggerPackage[distinctMethodName]).toHaveBeenCalledTimes(1) + }) + }) + + logApiMethods.forEach(logMethod => { + describe(logMethod, () => { test('should create event emitter event for calls to API', () => { const args = [faker.string.uuid(), { [faker.string.uuid()]: faker.string.uuid() }] apiInterface[logMethod](...args) @@ -580,7 +700,7 @@ describe('setAPI', () => { const firstEmit = handleModule.handle.mock.calls[0] expect(firstEmit[0]).toEqual(SUPPORTABILITY_METRIC_CHANNEL) - expect(firstEmit[1]).toEqual([`API/${logMethod.toLowerCase()}/called`]) + expect(firstEmit[1]).toEqual([`API/logging/${logMethod.toLowerCase().replace('log', '')}/called`]) expect(firstEmit[2]).toBeUndefined() expect(firstEmit[3]).toEqual(FEATURE_NAMES.metrics) expect(firstEmit[4]).toEqual(instanceEE) diff --git a/tests/specs/api.e2e.js b/tests/specs/api.e2e.js index a79768fe1..ee9d89c2c 100644 --- a/tests/specs/api.e2e.js +++ b/tests/specs/api.e2e.js @@ -25,7 +25,7 @@ describe('newrelic api', () => { } return Array.from(result) } - return getAllPropertyNames(Object.values(newrelic.initializedAgents)[0]) + return getAllPropertyNames(Object.values(newrelic.initializedAgents)[0].api) }) expect(globalApiMethods).toEqual(expect.arrayContaining([ diff --git a/tests/specs/npm/index.e2e.js b/tests/specs/npm/index.e2e.js index ce2228a70..7ee5d7ade 100644 --- a/tests/specs/npm/index.e2e.js +++ b/tests/specs/npm/index.e2e.js @@ -54,38 +54,21 @@ describe.withBrowsersMatching(es2022Support)('basic npm agent', () => { }) if (testBuild !== 'worker-agent') { - it(`dist/${testBuild} exposes the correct API methods`, async () => { - await browser.url(await browser.testHandle.assetURL(`test-builds/browser-agent-wrapper/${testBuild}.html`)) - - const agentProps = await getAgentProps('window.agent') - const agentApiProps = await getAgentProps('window.agent.api') - - expect(agentProps).toEqual(expect.arrayContaining([ - ...apiMethods, - ...asyncApiMethods - ])) - - expect(agentApiProps).toEqual(expect.arrayContaining([ - ...apiMethods, - ...asyncApiMethods - ])) - }) - - it(`src/${testBuild} exposes the correct API methods`, async () => { - await browser.url(await browser.testHandle.assetURL(`test-builds/raw-src-wrapper/${testBuild}.html`)) - - const agentProps = await getAgentProps('window.agent') - const agentApiProps = await getAgentProps('window.agent.api') - - expect(agentProps).toEqual(expect.arrayContaining([ - ...apiMethods, - ...asyncApiMethods - ])) - - expect(agentApiProps).toEqual(expect.arrayContaining([ - ...apiMethods, - ...asyncApiMethods - ])) + ;[['dist', 'browser-agent-wrapper'], ['src', 'raw-src-wrapper']].forEach(([type, wrapper]) => { + it(`${type}/${testBuild} exposes the correct API methods`, async () => { + await browser.url(await browser.testHandle.assetURL(`test-builds/${wrapper}/${testBuild}.html`)) + + const NREUMProps = await getAgentProps('NREUM') + const newrelicProps = await getAgentProps('newrelic') + const agentApiProps = await getAgentProps('window.agent.api') + + ;[NREUMProps, newrelicProps, agentApiProps].forEach(keys => { + expect(keys).toEqual(expect.arrayContaining([ + ...apiMethods, + ...asyncApiMethods + ])) + }) + }) }) } }) diff --git a/tests/unit/loaders/api/api.test.js b/tests/unit/loaders/api/api.test.js index e61f97567..37a1707cb 100644 --- a/tests/unit/loaders/api/api.test.js +++ b/tests/unit/loaders/api/api.test.js @@ -11,7 +11,7 @@ describe('setTopLevelCallers', () => { setTopLevelCallers() const nreum = gosCDN() - expect(Object.keys(nreum).length).toEqual(20) + expect(Object.keys(nreum).length).toEqual(21) expect(typeof nreum.setErrorHandler).toEqual('function') expect(typeof nreum.finished).toEqual('function') expect(typeof nreum.addToTrace).toEqual('function') @@ -32,6 +32,7 @@ describe('setTopLevelCallers', () => { expect(typeof nreum.logDebug).toEqual('function') expect(typeof nreum.logWarn).toEqual('function') expect(typeof nreum.logTrace).toEqual('function') + expect(typeof nreum.wrapLogger).toEqual('function') }) test('should forward calls to initialized and exposed agents', () => {