feat: Add auto-logging feature

.github/actions/build-ab/templates/postamble.js

@@ -59,13 +59,6 @@ if (!!newrelic && !!newrelic.log) {
   newrelic.log('NRBA postamble executed', {level: 'info'})
   newrelic.log(new Error('NRBA test error'), {level: 'error'})
 }
-if (!!newrelic && !!newrelic.wrapLogger) {
-  newrelic.wrapLogger(console, 'log', {customAttributes: {wrappedFn: 'console.log'}, level: 'info'})
-  newrelic.wrapLogger(console, 'error', {customAttributes: {wrappedFn: 'console.error'}, level: 'error'})
-  newrelic.wrapLogger(console, 'trace', {customAttributes: {wrappedFn: 'console.trace'}, level: 'trace'})
-  newrelic.wrapLogger(console, 'warn', {customAttributes: {wrappedFn: 'console.warn'}, level: 'warn'})
-  newrelic.wrapLogger(console, 'info', {customAttributes: {wrappedFn: 'console.info'}, level: 'info'})
-  newrelic.wrapLogger(console, 'debug', {customAttributes: {wrappedFn: 'console.debug'}, level: 'debug'})
-}
+
 if (!!newrelic && !!newrelic.setApplicationVersion) newrelic.setApplicationVersion( '' + Math.floor(Math.random() * 10) + '.' + Math.floor(Math.random() * 10) + '.' + Math.floor(Math.random() * 10) )
 {{/if}}

src/common/session/session-entity.js

@@ -16,6 +16,7 @@ import { handle } from '../event-emitter/handle'
 import { SUPPORTABILITY_METRIC_CHANNEL } from '../../features/metrics/constants'
 import { FEATURE_NAMES } from '../../loaders/features/features'
 import { windowAddEventListener } from '../event-listener/event-listener-opts'
+import { LOGGING_MODE } from '../../features/logging/constants'
 
 // this is what can be stored in local storage (not enforced but probably should be)
 // these values should sync between local storage and the parent class props
@@ -28,6 +29,7 @@ const model = {
   sessionReplaySentFirstChunk: false,
   sessionTraceMode: MODE.OFF,
   traceHarvestStarted: false,
+  loggingMode: LOGGING_MODE.OFF,
   serverTimeDiff: null, // set by TimeKeeper; "undefined" value will not be stringified and stored but "null" will
   custom: {}
 }

src/features/logging/aggregate/index.js

@@ -8,19 +8,47 @@
 import { stringify } from '../../../common/util/stringify'
 import { SUPPORTABILITY_METRIC_CHANNEL } from '../../metrics/constants'
 import { AggregateBase } from '../../utils/aggregate-base'
-import { FEATURE_NAME, LOGGING_EVENT_EMITTER_CHANNEL, LOG_LEVELS } from '../constants'
+import { FEATURE_NAME, LOGGING_EVENT_EMITTER_CHANNEL, LOG_LEVELS, LOGGING_MODE } from '../constants'
 import { Log } from '../shared/log'
 import { isValidLogLevel } from '../shared/utils'
 import { applyFnToProps } from '../../../common/util/traverse'
 import { MAX_PAYLOAD_SIZE } from '../../../common/constants/agent-constants'
+import { FEATURE_NAMES } from '../../../loaders/features/features'
+import { SESSION_EVENT_TYPES, SESSION_EVENTS } from '../../../common/session/constants'
+import { ABORT_REASONS } from '../../session_replay/constants'
+import { canEnableSessionTracking } from '../../utils/feature-gates'
 
 export class Aggregate extends AggregateBase {
   static featureName = FEATURE_NAME
   constructor (agentRef) {
     super(agentRef, FEATURE_NAME)
+    this.isSessionTrackingEnabled = canEnableSessionTracking(this.agentIdentifier) && this.agentRef.runtime.session
+
+    // The SessionEntity class can emit a message indicating the session was cleared and reset (expiry, inactivity). This feature must abort and never resume if that occurs.
+    this.ee.on(SESSION_EVENTS.RESET, () => {
+      this.abort(ABORT_REASONS.RESET)
+    })
+
+    this.ee.on(SESSION_EVENTS.UPDATE, (type, data) => {
+      if (this.blocked || type !== SESSION_EVENT_TYPES.CROSS_TAB) return
+      if (this.mode !== LOGGING_MODE.OFF && data.loggingMode === LOGGING_MODE.OFF) this.abort(ABORT_REASONS.CROSS_TAB)
+      else this.mode = data.loggingMode
+    })
+
     this.harvestOpts.raw = true
+    this.waitForFlags(['log']).then(([loggingMode]) => {
+      const session = this.agentRef.runtime.session ?? {}
+      if (this.loggingMode === LOGGING_MODE.OFF || (session.isNew && loggingMode === LOGGING_MODE.OFF)) {
+        this.blocked = true
+        this.deregisterDrain()
+        return
+      }
+      if (session.isNew || !this.isSessionTrackingEnabled) {
+        this.updateLoggingMode(loggingMode)
+      } else {
+        this.loggingMode = session.state.loggingMode
+      }
 
-    this.waitForFlags([]).then(() => {
       /** emitted by instrument class (wrapped loggers) or the api methods directly */
       registerHandler(LOGGING_EVENT_EMITTER_CHANNEL, this.handleLog.bind(this), this.featureName, this.ee)
       this.drain()
@@ -29,12 +57,20 @@
     })
   }
 
+  updateLoggingMode (loggingMode) {
+    this.loggingMode = loggingMode
+    this.syncWithSessionManager({
+      loggingMode: this.loggingMode
+    })
+  }
+
   handleLog (timestamp, message, attributes = {}, level = LOG_LEVELS.INFO) {
-    if (this.blocked) return
+    if (this.blocked || !this.loggingMode) return
 
     if (!attributes || typeof attributes !== 'object') attributes = {}
     if (typeof level === 'string') level = level.toUpperCase()
     if (!isValidLogLevel(level)) return warn(30, level)
+    if (this.loggingMode < (LOGGING_MODE[level] || Infinity)) return
 
     try {
       if (typeof message !== 'string') {
@@ -112,4 +148,19 @@
   queryStringsBuilder () {
     return { browser_monitoring_key: this.agentRef.info.licenseKey }
   }
+
+  /** Abort the feature, once aborted it will not resume */
+  abort (reason = {}) {
+    handle(SUPPORTABILITY_METRIC_CHANNEL, [`Logging/Abort/${reason.sm}`], undefined, FEATURE_NAMES.logging, this.ee)
+    this.blocked = true
+    this.updateLoggingMode(LOGGING_MODE.OFF)
+    this.events.clear()
+    this.deregisterDrain()
+  }
+
+  syncWithSessionManager (state = {}) {
+    if (this.isSessionTrackingEnabled) {
+      this.agentRef.runtime.session.write(state)
+    }
+  }
 }

src/features/logging/constants.js

@@ -12,6 +12,15 @@ export const LOG_LEVELS = {
   TRACE: 'TRACE'
 }
 
+export const LOGGING_MODE = {
+  OFF: 0,
+  ERROR: 1,
+  WARN: 2,
+  INFO: 3,
+  DEBUG: 4,
+  TRACE: 5
+}
+
 export const LOGGING_EVENT_EMITTER_CHANNEL = 'log'
 
 export const FEATURE_NAME = FEATURE_NAMES.logging

src/features/logging/instrument/index.js

@@ -5,13 +5,21 @@
 import { InstrumentBase } from '../../utils/instrument-base'
 import { FEATURE_NAME } from '../constants'
 import { bufferLog } from '../shared/utils'
+import { wrapLogger } from '../../../common/wrap/wrap-logger'
+import { globalScope } from '../../../common/constants/runtime'
 
 export class Instrument extends InstrumentBase {
   static featureName = FEATURE_NAME
   constructor (agentRef, auto = true) {
     super(agentRef, FEATURE_NAME, auto)
 
     const instanceEE = this.ee
+    wrapLogger(instanceEE, globalScope.console, 'log', { level: 'info' })
+    wrapLogger(instanceEE, globalScope.console, 'error', { level: 'error' })
+    wrapLogger(instanceEE, globalScope.console, 'warn', { level: 'warn' })
+    wrapLogger(instanceEE, globalScope.console, 'info', { level: 'info' })
+    wrapLogger(instanceEE, globalScope.console, 'debug', { level: 'debug' })
+    wrapLogger(instanceEE, globalScope.console, 'trace', { level: 'trace' })
     /** emitted by wrap-logger function */
     this.ee.on('wrap-logger-end', function handleLog ([message]) {
       const { level, customAttributes } = this

src/features/session_replay/aggregate/index.js

@@ -24,6 +24,7 @@
 import { buildNRMetaNode } from '../shared/utils'
 import { MAX_PAYLOAD_SIZE } from '../../../common/constants/agent-constants'
 import { cleanURL } from '../../../common/url/clean-url'
+import { canEnableSessionTracking } from '../../utils/feature-gates'
 
 export class Aggregate extends AggregateBase {
   static featureName = FEATURE_NAME
@@ -50,6 +51,8 @@
     this.errorNoticed = args?.errorNoticed || false
     this.harvestOpts.raw = true
 
+    this.isSessionTrackingEnabled = canEnableSessionTracking(this.agentIdentifier) && this.agentRef.runtime.session
+
     handle(SUPPORTABILITY_METRIC_CHANNEL, ['Config/SessionReplay/Enabled'], undefined, FEATURE_NAMES.metrics, this.ee)
 
     // The SessionEntity class can emit a message indicating the session was cleared and reset (expiry, inactivity). This feature must abort and never resume if that occurs.
@@ -71,7 +74,7 @@
     this.ee.on(SESSION_EVENTS.UPDATE, (type, data) => {
       if (!this.recorder || !this.initialized || this.blocked || type !== SESSION_EVENT_TYPES.CROSS_TAB) return
       if (this.mode !== MODE.OFF && data.sessionReplayMode === MODE.OFF) this.abort(ABORT_REASONS.CROSS_TAB)
-      this.mode = data.sessionReplay
+      this.mode = data.sessionReplayMode
     })
 
     registerHandler(SR_EVENT_EMITTER_TYPES.PAUSE, () => {
@@ -142,7 +145,7 @@
 
   /**
    * Evaluate entitlements and sampling before starting feature mechanics, importing and configuring recording library, and setting storage state
-   * @param {boolean} entitlements - the true/false state of the "sr" flag from RUM response
+   * @param {boolean} srMode - the true/false state of the "sr" flag (aka. entitlements) from RUM response
    * @param {boolean} ignoreSession - whether to force the method to ignore the session state and use just the sample flags
    * @returns {void}
    */
@@ -373,6 +376,8 @@
   }
 
   syncWithSessionManager (state = {}) {
-    this.agentRef.runtime.session.write(state)
+    if (this.isSessionTrackingEnabled) {
+      this.agentRef.runtime.session.write(state)
+    }
   }
 }

tests/assets/logs-api-wrap-logger-rewrapped.html

@@ -11,7 +11,7 @@
       var loggers = {
         log: function(message, attr){}
       }
-      
+
       newrelic.wrapLogger(loggers, 'log', { level: "warn" })
       loggers.log('test1')
       // should capture event with `warn` level

tests/assets/logs-console-logger-harvest-early.html

@@ -0,0 +1,21 @@
+<!DOCTYPE html>
+<!--
+  Copyright 2024 New Relic Corporation.
+  PDX-License-Identifier: Apache-2.0
+-->
+<html>
+  <head>
+    <title>Logs - Console Logs - Harvest Early</title>
+    {init} {config} {loader}
+  </head>
+  <body>Logs - Console Logs - Harvest Early
+    <script>
+      const longMessage = 'x'.repeat(800*800)
+      /** the combination of the two large messages pushes it past the MAX_PAYLOAD_SIZE,
+       * causing the first valid one to get harvested before buffering the second one **/
+      console.info(longMessage)
+      console.info(longMessage)
+      // harvest should not have the '...xxxxx...' payload in it
+    </script>
+  </body>
+</html>

tests/assets/logs-console-logger-post-load.html

@@ -0,0 +1,21 @@
+<!DOCTYPE html>
+<!--
+  Copyright 2024 New Relic Corporation.
+  PDX-License-Identifier: Apache-2.0
+-->
+<html>
+  <head>
+    <title>Logs - Console Logs - Post Load</title>
+    {init} {config} {loader}
+  </head>
+  <body>Logs - Console Logs - Post Load
+    <script>
+      console.log('log')
+      console.info('info')
+      console.debug('debug')
+      console.trace('trace')
+      console.error('error')
+      console.warn('warn')
+    </script>
+  </body>
+</html>

tests/assets/logs-console-logger-pre-load.html

@@ -0,0 +1,21 @@
+<!DOCTYPE html>
+<!--
+  Copyright 2024 New Relic Corporation.
+  PDX-License-Identifier: Apache-2.0
+-->
+<html>
+  <head>
+    <title>Logs - Console Logs - Pre Load</title>
+    {init} {config} {loader}
+    <script>
+      console.log('log')
+      console.info('info')
+      console.debug('debug')
+      console.trace('trace')
+      console.error('error')
+      console.warn('warn')
+    </script>
+  </head>
+  <body>Logs - Console Logs - Pre Load
+  </body>
+</html>

tests/assets/logs-console-logger-too-large.html

@@ -0,0 +1,24 @@
+<!DOCTYPE html>
+<!--
+  Copyright 2024 New Relic Corporation.
+  PDX-License-Identifier: Apache-2.0
+-->
+<html>
+  <head>
+    <title>Logs - Console Logs - Payload Too Large</title>
+    {init} {config} {loader}
+  </head>
+  <body>Logs - Console Logs - Payload Too Large
+    <script>
+      console.log('x'.repeat(1024*1024)) // too big
+      console.log('log')
+      console.info('info')
+      console.debug('debug')
+      console.trace('trace')
+      console.error('error')
+      console.warn('warn')
+
+      // harvest should not have the '...xxxxx...' payload in it
+    </script>
+  </body>
+</html>

tests/components/logging/aggregate.test.js

@@ -1,6 +1,6 @@
 import { getRuntime } from '../../../src/common/config/runtime'
 import { initialLocation } from '../../../src/common/constants/runtime'
-import { LOGGING_EVENT_EMITTER_CHANNEL } from '../../../src/features/logging/constants'
+import { LOG_LEVELS, LOGGING_EVENT_EMITTER_CHANNEL, LOGGING_MODE } from '../../../src/features/logging/constants'
 import { Instrument as Logging } from '../../../src/features/logging/instrument'
 import { Log } from '../../../src/features/logging/shared/log'
 import * as consoleModule from '../../../src/common/util/console'
@@ -34,6 +34,13 @@ afterEach(() => {
   jest.clearAllMocks()
 })
 
+const mockLoggingRumResponse = async (mode) => {
+  loggingAggregate.ee.emit('rumresp', [{
+    log: mode
+  }])
+  return await new Promise(process.nextTick)
+}
+
 describe('class setup', () => {
   test('should have expected public properties', () => {
     expect(Object.keys(loggingAggregate)).toEqual(expect.arrayContaining([
@@ -45,18 +52,31 @@ describe('class setup', () => {
     ]))
   })
 
-  test('should wait for flags', async () => {
+  test('should wait for flags - log flag is missing', async () => {
     expect(loggingAggregate.drained).toBeUndefined()
-    loggingAggregate.ee.emit('rumresp', {})
+    loggingAggregate.ee.emit('rumresp', [{}])
     await new Promise(process.nextTick)
+    expect(loggingAggregate.blocked).toEqual(true)
+  })
+
+  test('should wait for flags - 0 = OFF', async () => {
+    expect(loggingAggregate.drained).toBeUndefined()
+    await mockLoggingRumResponse(LOGGING_MODE.OFF)
+
+    expect(loggingAggregate.blocked).toEqual(true)
+  })
+
+  test('should wait for flags - 1 = ERROR', async () => {
+    expect(loggingAggregate.drained).toBeUndefined()
+    await mockLoggingRumResponse(LOGGING_MODE.ERROR)
+
     expect(loggingAggregate.drained).toEqual(true)
   })
 })
 
 describe('payloads', () => {
-  beforeEach(async () => {
-    loggingAggregate.ee.emit('rumresp', {})
-    await new Promise(process.nextTick)
+  beforeEach(() => {
+    mockLoggingRumResponse(LOGGING_MODE.INFO)
   })
 
   test('fills buffered logs with event emitter messages and prepares matching payload', async () => {
@@ -203,9 +223,21 @@ describe('payloads', () => {
   })
 })
 
+test.each(Object.keys(LOGGING_MODE))('payloads - log events are emitted (or not) according to flag from rum response - %s', async (logLevel) => {
+  const SOME_TIMESTAMP = 1234
+  await mockLoggingRumResponse(LOGGING_MODE[logLevel])
+  loggingAggregate.ee.emit(LOGGING_EVENT_EMITTER_CHANNEL, [SOME_TIMESTAMP, LOG_LEVELS.ERROR, { myAttributes: 1 }, LOG_LEVELS.ERROR])
+  loggingAggregate.ee.emit(LOGGING_EVENT_EMITTER_CHANNEL, [SOME_TIMESTAMP, LOG_LEVELS.WARN, { myAttributes: 1 }, LOG_LEVELS.WARN])
+  loggingAggregate.ee.emit(LOGGING_EVENT_EMITTER_CHANNEL, [SOME_TIMESTAMP, LOG_LEVELS.INFO, { myAttributes: 1 }, LOG_LEVELS.INFO])
+  loggingAggregate.ee.emit(LOGGING_EVENT_EMITTER_CHANNEL, [SOME_TIMESTAMP, LOG_LEVELS.DEBUG, { myAttributes: 1 }, LOG_LEVELS.DEBUG])
+  loggingAggregate.ee.emit(LOGGING_EVENT_EMITTER_CHANNEL, [SOME_TIMESTAMP, LOG_LEVELS.TRACE, { myAttributes: 1 }, LOG_LEVELS.TRACE])
+
+  expect(loggingAggregate.events.get()[0].data.length).toEqual(LOGGING_MODE[logLevel])
+  loggingAggregate.events.clear()
+})
+
 test('can harvest early', async () => {
-  loggingAggregate.ee.emit('rumresp', {})
-  await new Promise(process.nextTick)
+  await mockLoggingRumResponse(LOGGING_MODE.INFO)
 
   jest.spyOn(mainAgent.runtime.harvester, 'triggerHarvestFor')