feat: Logging feature harvesting and optimizations (#1064)

src/common/config/state/init.js

@@ -43,7 +43,7 @@ const model = () => {
     feature_flags: [],
     harvest: { tooManyRequestsDelay: 60 },
     jserrors: { enabled: true, harvestTimeSeconds: 10, autoStart: true },
-    logging: { enabled: true, harvestTimeSeconds: 30, autoStart: true, level: LOG_LEVELS.INFO },
+    logging: { enabled: true, harvestTimeSeconds: 10, autoStart: true, level: LOG_LEVELS.INFO },
     metrics: { enabled: true, autoStart: true },
     obfuscate: undefined,
     page_action: { enabled: true, harvestTimeSeconds: 30, autoStart: true },

src/common/wrap/wrap-logger.js

@@ -19,13 +19,23 @@ import { createWrapperWithEmitter as wfn } from './wrap-function'
  * @returns {Object} Scoped event emitter with a debug ID of `logger`.
  */
 // eslint-disable-next-line
-export function wrapLogger(sharedEE, parent, loggerFn, level) {
+export function wrapLogger(sharedEE, parent, loggerFn, context) {
   const ee = scopedEE(sharedEE)
-  var wrapFn = wfn(ee)
+  const wrapFn = wfn(ee)
 
+  /**
+   * This section allows us to pass an over-writable context along through the event emitter
+   * so that subsequent calls to `newrelic.wrapLogger` `WILL NOT` re-wrap (emit twice), but `WILL` overwrite the
+   * context object which contains the custom attributes and log level
+  */
   const ctx = new EventContext(contextId)
-  ctx.level = level
-  wrapFn.inPlace(parent, [loggerFn], 'wrap-logger-', ctx)
+  ctx.level = context.level
+  ctx.customAttributes = context.customAttributes
+  parent[loggerFn].__nrContext = ctx
+
+  /** observe calls to <loggerFn> and emit events prefixed with `wrap-logger-` */
+  wrapFn.inPlace(parent, [loggerFn], 'wrap-logger-', () => parent[loggerFn].__nrContext)
+
   return ee
 }
 

src/features/logging/aggregate/index.js

@@ -1,7 +1,12 @@
-import { getInfo, getRuntime } from '../../../common/config/config'
+import { getConfigurationValue, getInfo, getRuntime } from '../../../common/config/config'
+import { handle } from '../../../common/event-emitter/handle'
 import { registerHandler } from '../../../common/event-emitter/register-handler'
+import { HarvestScheduler } from '../../../common/harvest/harvest-scheduler'
+import { warn } from '../../../common/util/console'
+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 } from '../constants'
+import { FEATURE_NAME, LOGGING_EVENT_EMITTER_CHANNEL, LOGGING_IGNORED, MAX_PAYLOAD_SIZE } from '../constants'
 import { Log } from '../shared/log'
 
 export class Aggregate extends AggregateBase {
@@ -15,49 +20,82 @@ export class Aggregate extends AggregateBase {
     this.bufferedLogs = []
     /** held logs during sending, for retries */
     this.outgoingLogs = []
+    /** the estimated bytes of log data waiting to be sent -- triggers a harvest if adding a new log will exceed limit  */
+    this.estimatedBytes = 0
 
     this.#agentRuntime = getRuntime(this.agentIdentifier)
     this.#agentInfo = getInfo(this.agentIdentifier)
 
+    this.harvestTimeSeconds = getConfigurationValue(this.agentIdentifier, 'logging.harvestTimeSeconds')
+
     this.waitForFlags([]).then(() => {
+      this.scheduler = new HarvestScheduler('browser/logs', {
+        onFinished: this.onHarvestFinished.bind(this),
+        retryDelay: this.harvestTimeSeconds,
+        getPayload: this.prepareHarvest.bind(this),
+        raw: true
+      }, this)
+      /** harvest immediately once started to purge pre-load logs collected */
+      this.scheduler.startTimer(this.harvestTimeSeconds, 0)
       /** 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()
     })
   }
 
   handleLog (timestamp, message, attributes, level) {
-    this.bufferedLogs.push(
-      new Log(
-        this.#agentRuntime.timeKeeper.convertRelativeTimestamp(timestamp),
-        message,
-        attributes,
-        level
-      )
+    if (this.blocked) return
+    const log = new Log(
+      this.#agentRuntime.timeKeeper.convertRelativeTimestamp(timestamp),
+      message,
+      attributes,
+      level
     )
+    const logBytes = log.message.length + stringify(log.attributes).length + log.logType.length + 10 // timestamp == 10 chars
+    if (logBytes > MAX_PAYLOAD_SIZE) {
+      handle(SUPPORTABILITY_METRIC_CHANNEL, ['Logging/Harvest/Failed/Seen', logBytes])
+      return warn(LOGGING_IGNORED + '> ' + MAX_PAYLOAD_SIZE + ' bytes', log.message.slice(0, 25) + '...')
+    }
+
+    if (this.estimatedBytes + logBytes >= MAX_PAYLOAD_SIZE) {
+      handle(SUPPORTABILITY_METRIC_CHANNEL, ['Logging/Harvest/Early/Seen', this.estimatedBytes + logBytes])
+      this.scheduler.runHarvest({})
+    }
+    this.estimatedBytes += logBytes
+    this.bufferedLogs.push(log)
   }
 
-  preparePayload () {
+  prepareHarvest () {
+    if (this.blocked || !(this.bufferedLogs.length || this.outgoingLogs.length)) return
+    /** populate outgoing array while also clearing main buffer */
     this.outgoingLogs.push(...this.bufferedLogs.splice(0))
+    this.estimatedBytes = 0
+    /** see https://source.datanerd.us/agents/rum-specs/blob/main/browser/Log for logging spec */
     return {
-      common: {
-        attributes: {
-          entityGuid: this.#agentRuntime.appMetadata?.agents?.[0]?.entityGuid,
-          session: {
-            id: this.#agentRuntime?.session?.state.value || '0', // The session ID that we generate and keep across page loads
+      qs: {
+        browser_monitoring_key: this.#agentInfo.licenseKey
+      },
+      body: {
+        common: {
+          /** Attributes in the `common` section are added to `all` logs generated in the payload */
+          attributes: {
+            entityGuid: this.#agentRuntime.appMetadata?.agents?.[0]?.entityGuid, // browser entity guid as provided from RUM response
+            session: this.#agentRuntime?.session?.state.value || '0', // The session ID that we generate and keep across page loads
             hasReplay: this.#agentRuntime?.session?.state.sessionReplayMode === 1, // True if a session replay recording is running
             hasTrace: this.#agentRuntime?.session?.state.sessionTraceMode === 1, // True if a session trace recording is running
-            pageTraceId: this.#agentRuntime.ptid // The page's trace ID (equiv to agent id)
-          },
-          agent: {
-            appId: this.#agentInfo.applicationID, // Application ID from info object
-            standalone: this.#agentInfo.sa, // Whether the app is C+P or APM injected
-            version: this.#agentRuntime.version, // the browser agent version
-            distribution: this.#agentRuntime.distMethod // How is the agent being loaded on the page
+            ptid: this.#agentRuntime.ptid, // page trace id
+            appId: this.#agentInfo.applicationID, // Application ID from info object,
+            standalone: Boolean(this.#agentInfo.sa), // copy paste (true) vs APM (false)
+            agentVersion: this.#agentRuntime.version // browser agent version
           }
-        }
-      },
-      logs: this.outgoingLogs
+        },
+        /** logs section contains individual unique log entries */
+        logs: this.outgoingLogs
+      }
     }
   }
+
+  onHarvestFinished (result) {
+    if (!result.retry) this.outgoingLogs = []
+  }
 }

src/features/logging/constants.js

@@ -11,3 +11,9 @@ export const LOG_LEVELS = {
 export const LOGGING_EVENT_EMITTER_CHANNEL = 'log'
 
 export const FEATURE_NAME = FEATURE_NAMES.logging
+
+export const MAX_PAYLOAD_SIZE = 1000000
+
+export const LOGGING_FAILURE_MESSAGE = 'failed to wrap logger: '
+export const LOGGING_LEVEL_FAILURE_MESSAGE = 'invalid log level: '
+export const LOGGING_IGNORED = 'ignored log: '

src/features/logging/instrument/index.js

@@ -1,4 +1,3 @@
-import { stringify } from '../../../common/util/stringify'
 import { InstrumentBase } from '../../utils/instrument-base'
 import { FEATURE_NAME } from '../constants'
 import { bufferLog } from '../shared/utils'
@@ -10,9 +9,9 @@ export class Instrument extends InstrumentBase {
 
     const instanceEE = this.ee
     /** emitted by wrap-logger function */
-    this.ee.on('wrap-logger-end', function handleLog ([message, ...args]) {
-      const { level } = this
-      bufferLog(instanceEE, message, { ...(!!args.length && { customAttributes: stringify(args) }) }, level)
+    this.ee.on('wrap-logger-end', function handleLog ([message]) {
+      const { level, customAttributes } = this
+      bufferLog(instanceEE, message, customAttributes, level)
     })
     this.importAggregator()
   }

src/features/logging/shared/log.js

@@ -6,27 +6,22 @@ export class Log {
   timestamp
   /** @type {string} the log message */
   message
-  /** @type {string} the stringified object of attributes (could be args[] from wrapped logger) */
+  /** @type {object} the object of attributes to be parsed by logging ingest into top-level properties */
   attributes
   /** @type {'error'|'trace'|'debug'|'info'|'warn'} the log type of the log */
   logType
-  /** @type {Object<{url: string}>} The session level attributes of the log event */
-  session
 
   /**
    * @param {number} timestamp - Unix timestamp
    * @param {string} message - message string
-   * @param {{[key: string]: *}} attributes - other attributes
+   * @param {object} attributes - other log event attributes
    * @param {enum} level - Log level
    */
   constructor (timestamp, message, attributes, level) {
     /** @type {long} */
     this.timestamp = timestamp
     this.message = message
-    this.attributes = attributes
+    this.attributes = { ...attributes, pageUrl: cleanURL('' + globalScope.location) }
     this.logType = level
-    this.session = {
-      url: cleanURL('' + globalScope.location)
-    }
   }
 }

src/features/logging/shared/utils.js

@@ -1,16 +1,28 @@
 import { handle } from '../../../common/event-emitter/handle'
 import { now } from '../../../common/timing/now'
+import { stringify } from '../../../common/util/stringify'
 import { FEATURE_NAMES } from '../../../loaders/features/features'
 import { SUPPORTABILITY_METRIC_CHANNEL } from '../../metrics/constants'
-import { LOGGING_EVENT_EMITTER_CHANNEL } from '../constants'
+import { LOGGING_EVENT_EMITTER_CHANNEL, LOG_LEVELS } from '../constants'
 
 /**
    * @param {ContextualEE} ee - The contextual ee tied to the instance
    * @param {string} message - the log message string
    * @param {{[key: string]: *}} customAttributes - The log's custom attributes if any
    * @param {enum} level - the log level enum
    */
-export function bufferLog (ee, message, customAttributes, level = 'info') {
+export function bufferLog (ee, message, customAttributes = {}, level = 'info') {
+  if (typeof message !== 'string') message = stringify(message)
   handle(SUPPORTABILITY_METRIC_CHANNEL, [`API/logging/${level}/called`], undefined, FEATURE_NAMES.metrics, ee)
   handle(LOGGING_EVENT_EMITTER_CHANNEL, [now(), message, customAttributes, level], undefined, FEATURE_NAMES.logging, ee)
 }
+
+/**
+ * Checks if a supplied log level is acceptable for use in generating a log event
+ * @param {string} level
+ * @returns {boolean}
+ */
+export function isValidLogLevel (level) {
+  if (typeof level !== 'string') return false
+  return Object.values(LOG_LEVELS).some(logLevel => logLevel.toLowerCase() === level.toLowerCase())
+}

src/features/session_trace/aggregate/index.js

@@ -109,7 +109,6 @@ export class Aggregate extends AggregateBase {
 
   /** This module does not auto harvest by default -- it needs to be kicked off.  Once this method is called, it will then harvest on an interval */
   startHarvesting () {
-    console.log('start harvesting')
     if (this.scheduler.started || this.blocked) return
     this.scheduler.runHarvest()
     this.scheduler.startTimer(this.harvestTimeSeconds)
@@ -203,7 +202,6 @@ export class Aggregate extends AggregateBase {
 
   /** Stop running for the remainder of the page lifecycle */
   abort (reason) {
-    console.log('abort', reason)
     this.blocked = true
     this.mode = MODE.OFF
     this.agentRuntime.session.write({ sessionTraceMode: this.mode })

src/loaders/agent-base.js

@@ -181,4 +181,27 @@ export class AgentBase {
   interaction () {
     return this.#callMethod('interaction')
   }
+
+  /**
+   * Capture a log message with an `info` logLevel.
+   * {@link https://docs.newrelic.com/docs/browser/new-relic-browser/browser-apis/loginfo/}
+   * @param {string} message String to be captured as log message
+   * @param {object=} customAttributes Object of custom attributes, defaults to `{}` if not assigned
+   * @param {'error'|'debug'|'info'|'trace'|'warn'=} level The logLevel to assign to the captured log. Defaults to 'info' if not assigned.
+  */
+  log (message, customAttributes, level) {
+    return this.#callMethod('logInfo', message, customAttributes, level)
+  }
+
+  /**
+   * Wrap a logger function to capture a log each time the function is invoked with the message and arguments passed
+   * {@link https://docs.newrelic.com/docs/browser/new-relic-browser/browser-apis/wraplogger/}
+   * @param {Object} parent The parent object containing the logger method
+   * @param {string} functionName The property name of the function in the parent object to be wrapped
+   * @param {object=} customAttributes Object of custom attributes, defaults to `{}` if not assigned
+   * @param {'error'|'debug'|'info'|'trace'|'warn'=} level The logLevel to assign to logs captured from the function. Defaults to 'info' if not assigned.
+  */
+  wrapLogger (parent, functionName, customAttributes, level) {
+    return this.#callMethod('wrapLogger', parent, functionName, customAttributes, level)
+  }
 }

src/loaders/api/api-methods.js

@@ -1,15 +1,10 @@
 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'
-]
-
 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, 'wrapLogger'
+  SR_EVENT_EMITTER_TYPES.RECORD, SR_EVENT_EMITTER_TYPES.PAUSE, 'log', 'wrapLogger'
 ]
 
 export const asyncApiMethods = [

src/loaders/api/api.js

@@ -12,12 +12,12 @@ import { isBrowserScope } from '../../common/constants/runtime'
 import { warn } from '../../common/util/console'
 import { SUPPORTABILITY_METRIC_CHANNEL } from '../../features/metrics/constants'
 import { gosCDN } from '../../common/window/nreum'
-import { apiMethods, asyncApiMethods, logApiMethods } from './api-methods'
+import { apiMethods, asyncApiMethods } 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 { LOG_LEVELS } from '../../features/logging/constants'
-import { bufferLog } from '../../features/logging/shared/utils'
+import { LOGGING_FAILURE_MESSAGE, LOGGING_IGNORED, LOGGING_LEVEL_FAILURE_MESSAGE, LOG_LEVELS, MAX_PAYLOAD_SIZE } from '../../features/logging/constants'
+import { bufferLog, isValidLogLevel } from '../../features/logging/shared/utils'
 import { wrapLogger } from '../../common/wrap/wrap-logger'
 
 export function setTopLevelCallers () {
@@ -38,7 +38,6 @@ export function setTopLevelCallers () {
 }
 
 const replayRunning = {}
-const LOGGING_FAILURE_MESSAGE = 'Failed to wrap: '
 
 export function setAPI (agentIdentifier, forceDrain, runSoftNavOverSpa = false) {
   if (!forceDrain) registerDrain(agentIdentifier, 'api')
@@ -55,16 +54,17 @@ export function setAPI (agentIdentifier, forceDrain, runSoftNavOverSpa = false)
   var prefix = 'api-'
   var spaPrefix = prefix + 'ixn-'
 
-  logApiMethods.forEach((method) => {
-    apiInterface[method] = function (message, customAttributes = {}) {
-      bufferLog(instanceEE, message, customAttributes, method.toLowerCase().replace('log', ''))
-    }
-  })
+  apiInterface.log = function (message, customAttributes = {}, level = LOG_LEVELS.INFO) {
+    if (typeof message !== 'string' || !message) return warn(LOGGING_IGNORED + 'invalid message')
+    if (!isValidLogLevel(level)) return warn(LOGGING_LEVEL_FAILURE_MESSAGE + level, LOG_LEVELS)
+    if (message.length > MAX_PAYLOAD_SIZE) return warn(LOGGING_IGNORED + '> ' + MAX_PAYLOAD_SIZE + ' bytes: ', message.slice(0, 25) + '...')
+    bufferLog(instanceEE, message, customAttributes, level.toLowerCase())
+  }
 
-  apiInterface.wrapLogger = (parent, functionName, level = LOG_LEVELS.INFO) => {
-    if (!(typeof parent === 'object' && !!parent && typeof functionName === 'string' && !!functionName)) return warn(LOGGING_FAILURE_MESSAGE + 'invalid parent or function')
-    if (!Object.values(LOG_LEVELS).includes(level)) return warn(LOGGING_FAILURE_MESSAGE + 'invalid log level', LOG_LEVELS)
-    wrapLogger(instanceEE, parent, functionName, level)
+  apiInterface.wrapLogger = (parent, functionName, customAttributes = {}, level = LOG_LEVELS.INFO) => {
+    if (!(typeof parent === 'object' && !!parent && typeof functionName === 'string' && !!functionName && typeof parent[functionName] === 'function' && typeof customAttributes === 'object')) return warn(LOGGING_FAILURE_MESSAGE + 'invalid argument(s)')
+    if (!isValidLogLevel(level)) return warn(LOGGING_FAILURE_MESSAGE + LOGGING_LEVEL_FAILURE_MESSAGE + level, LOG_LEVELS)
+    wrapLogger(instanceEE, parent, functionName, { customAttributes, level: level.toLowerCase() })
   }
 
   // Setup stub functions that queue calls for later processing.

tests/assets/logs-api-harvest-early.html

@@ -0,0 +1,20 @@
+<!DOCTYPE html>
+<!--
+  Copyright 2020 New Relic Corporation.
+  PDX-License-Identifier: Apache-2.0
+-->
+<html>
+  <head>
+    <title>Logs API Post Load</title>
+    {init} {config} {loader}
+  </head>
+  <body>Logs API Post Load
+    <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 **/
+      newrelic.log(longMessage, {test: 1}) 
+      newrelic.log(longMessage, {test: 1})
+    </script>
+  </body>
+</html>