feat: Add wrapLogger API method for wrapping 3rd party loggers (#1054)

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')
+}

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 = [

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') })
 

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)

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([

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
+            ]))
+          })
+        })
       })
     }
   })

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', () => {