From 7c084c208164f1eb137ce902140e7710735709ef Mon Sep 17 00:00:00 2001 From: ptang-nr Date: Wed, 13 Nov 2024 13:43:19 -0800 Subject: [PATCH 1/7] feat: Wrap various console logging methods (#1249) --- src/features/logging/instrument/index.js | 8 +++ .../logs-api-wrap-logger-rewrapped.html | 5 +- .../logs-console-logger-harvest-early.html | 21 +++++++ .../assets/logs-console-logger-post-load.html | 21 +++++++ .../assets/logs-console-logger-pre-load.html | 21 +++++++ .../assets/logs-console-logger-too-large.html | 24 ++++++++ tests/specs/logging/harvesting.e2e.js | 58 +++++++++++++++---- 7 files changed, 146 insertions(+), 12 deletions(-) create mode 100644 tests/assets/logs-console-logger-harvest-early.html create mode 100644 tests/assets/logs-console-logger-post-load.html create mode 100644 tests/assets/logs-console-logger-pre-load.html create mode 100644 tests/assets/logs-console-logger-too-large.html diff --git a/src/features/logging/instrument/index.js b/src/features/logging/instrument/index.js index 596321a7e..7dd072ac2 100644 --- a/src/features/logging/instrument/index.js +++ b/src/features/logging/instrument/index.js @@ -1,6 +1,8 @@ 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 @@ -8,6 +10,12 @@ export class Instrument extends InstrumentBase { 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 diff --git a/tests/assets/logs-api-wrap-logger-rewrapped.html b/tests/assets/logs-api-wrap-logger-rewrapped.html index a9397a556..f832349df 100644 --- a/tests/assets/logs-api-wrap-logger-rewrapped.html +++ b/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 @@ -22,7 +22,8 @@ // should NOT duplicate the log events (ie, capture 2 logs for this one call) var orig = loggers.log - loggers.log = (...args) => {console.log('wrapped again by 3rd party'); orig(...args)} + // simulate wrapping by 3rd party + loggers.log = (...args) => { orig(...args)} loggers.log('test3') // should capture another event, and still have the `warn` level even though the parent context was changed diff --git a/tests/assets/logs-console-logger-harvest-early.html b/tests/assets/logs-console-logger-harvest-early.html new file mode 100644 index 000000000..5bb65bb8f --- /dev/null +++ b/tests/assets/logs-console-logger-harvest-early.html @@ -0,0 +1,21 @@ + + + + + Logs - Console Logs - Harvest Early + {init} {config} {loader} + + Logs - Console Logs - Harvest Early + + + diff --git a/tests/assets/logs-console-logger-post-load.html b/tests/assets/logs-console-logger-post-load.html new file mode 100644 index 000000000..69369dc5b --- /dev/null +++ b/tests/assets/logs-console-logger-post-load.html @@ -0,0 +1,21 @@ + + + + + Logs - Console Logs - Post Load + {init} {config} {loader} + + Logs - Console Logs - Post Load + + + diff --git a/tests/assets/logs-console-logger-pre-load.html b/tests/assets/logs-console-logger-pre-load.html new file mode 100644 index 000000000..c099570d2 --- /dev/null +++ b/tests/assets/logs-console-logger-pre-load.html @@ -0,0 +1,21 @@ + + + + + Logs - Console Logs - Pre Load + {init} {config} {loader} + + + Logs - Console Logs - Pre Load + + diff --git a/tests/assets/logs-console-logger-too-large.html b/tests/assets/logs-console-logger-too-large.html new file mode 100644 index 000000000..a6912e215 --- /dev/null +++ b/tests/assets/logs-console-logger-too-large.html @@ -0,0 +1,24 @@ + + + + + Logs - Console Logs - Payload Too Large + {init} {config} {loader} + + Logs - Console Logs - Payload Too Large + + + diff --git a/tests/specs/logging/harvesting.e2e.js b/tests/specs/logging/harvesting.e2e.js index f1291e655..e2813490c 100644 --- a/tests/specs/logging/harvesting.e2e.js +++ b/tests/specs/logging/harvesting.e2e.js @@ -10,11 +10,7 @@ describe('logging harvesting', () => { describe('logging harvests', () => { const pageUrl = expect.any(String) const customAttributes = { test: 1 } - const attributes = { ...customAttributes, pageUrl } - const expectedLogs = ['INFO', 'DEBUG', 'TRACE', 'ERROR', 'WARN'].map(level => ({ - level, message: level.toLowerCase(), timestamp: expect.any(Number), attributes - })) - const expectedPayload = [{ + const commonAttributes = { common: { attributes: { appId: 42, @@ -29,16 +25,41 @@ describe('logging harvesting', () => { session: expect.any(String), ptid: expect.any(String) } - }, - logs: expectedLogs - }] - - ;['api', 'api-wrap-logger'].forEach(type => { + } + } + const expectedLogs = (type) => { + if (type === 'api' || type === 'api-wrap-logger') { + return ['INFO', 'DEBUG', 'TRACE', 'ERROR', 'WARN'].map(level => ({ + level, + message: level.toLowerCase(), + timestamp: expect.any(Number), + attributes: { + pageUrl, + ...customAttributes + } + })) + } else if (type === 'console-logger') { + return ['LOG', 'INFO', 'DEBUG', 'TRACE', 'ERROR', 'WARN'].map(level => ({ + level: level === 'LOG' ? 'INFO' : level, + message: level.toLowerCase(), + timestamp: expect.any(Number), + attributes: { + pageUrl + } + })) + } + } + + ;['api', 'api-wrap-logger', 'console-logger'].forEach(type => { it(`should harvest expected logs - ${type} pre load`, async () => { const [[{ request: { body } }]] = await Promise.all([ logsCapture.waitForResult({ totalCount: 1 }), browser.url(await browser.testHandle.assetURL(`logs-${type}-pre-load.html`)) ]) + const expectedPayload = [{ + ...commonAttributes, + logs: expectedLogs(type) + }] expect(JSON.parse(body)).toEqual(expectedPayload) }) @@ -48,6 +69,10 @@ describe('logging harvesting', () => { logsCapture.waitForResult({ totalCount: 1 }), browser.url(await browser.testHandle.assetURL(`logs-${type}-post-load.html`)) ]) + const expectedPayload = [{ + ...commonAttributes, + logs: expectedLogs(type) + }] expect(JSON.parse(body)).toEqual(expectedPayload) }) @@ -67,6 +92,19 @@ describe('logging harvesting', () => { logsCapture.waitForResult({ totalCount: 1 }), browser.url(await browser.testHandle.assetURL(`logs-${type}-too-large.html`)) ]) + + const logs = [...expectedLogs(type), { + level: 'DEBUG', + message: 'New Relic Warning: https://github.com/newrelic/newrelic-browser-agent/blob/main/docs/warning-codes.md#31', + timestamp: expect.any(Number), + attributes: { + pageUrl: expect.any(String) + } + }] + const expectedPayload = [{ + ...commonAttributes, + logs + }] expect(JSON.parse(body)).toEqual(expectedPayload) // should not contain the '...xxxxx...' payload in it }) }) From bb7ab4d8dc8cd94eafe1b46c47bed9b36eea5423 Mon Sep 17 00:00:00 2001 From: ptang-nr Date: Mon, 18 Nov 2024 15:06:06 -0800 Subject: [PATCH 2/7] feat: Aggregate log events based on rum flag (#1253) --- src/features/logging/aggregate/index.js | 13 ++- src/features/logging/constants.js | 9 ++ tests/components/logging/aggregate.test.js | 48 ++++++-- tests/specs/cleanup-on-halt.e2e.js | 3 +- .../harvesting/disable-harvesting.e2e.js | 18 ++- tests/specs/logging/harvesting.e2e.js | 108 +++++++++++------- tools/testing-server/constants.js | 1 + 7 files changed, 143 insertions(+), 57 deletions(-) diff --git a/src/features/logging/aggregate/index.js b/src/features/logging/aggregate/index.js index 09678149a..f878d015f 100644 --- a/src/features/logging/aggregate/index.js +++ b/src/features/logging/aggregate/index.js @@ -5,7 +5,7 @@ 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, 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' @@ -18,7 +18,13 @@ export class Aggregate extends AggregateBase { super(agentRef, FEATURE_NAME) this.harvestTimeSeconds = agentRef.init.logging.harvestTimeSeconds - this.waitForFlags([]).then(() => { + this.waitForFlags(['log']).then(([loggingMode]) => { + if (!loggingMode) { + this.blocked = true + this.deregisterDrain() + return + } + this.loggingMode = loggingMode this.scheduler = new HarvestScheduler(FEATURE_TO_ENDPOINT[this.featureName], { onFinished: (result) => this.postHarvestCleanup(result.sent && result.retry), retryDelay: this.harvestTimeSeconds, @@ -34,11 +40,12 @@ export class Aggregate extends AggregateBase { } 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') { diff --git a/src/features/logging/constants.js b/src/features/logging/constants.js index 0a5ceb708..e8b83be17 100644 --- a/src/features/logging/constants.js +++ b/src/features/logging/constants.js @@ -8,6 +8,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 diff --git a/tests/components/logging/aggregate.test.js b/tests/components/logging/aggregate.test.js index 5488afbac..f2beca86a 100644 --- a/tests/components/logging/aggregate.test.js +++ b/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([ @@ -46,18 +53,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 () => { @@ -204,9 +224,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().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(loggingAggregate.scheduler, 'runHarvest') diff --git a/tests/specs/cleanup-on-halt.e2e.js b/tests/specs/cleanup-on-halt.e2e.js index bc7ff08eb..6d12360fd 100644 --- a/tests/specs/cleanup-on-halt.e2e.js +++ b/tests/specs/cleanup-on-halt.e2e.js @@ -5,7 +5,7 @@ describe('Memory leaks', () => { it('does not occur on ee backlog when RUM flags are 0', async () => { await browser.testHandle.scheduleReply('bamServer', { test: testRumRequest, - body: JSON.stringify(rumFlags({ st: 0, sr: 0, err: 0, ins: 0, spa: 0, loaded: 1 })) + body: JSON.stringify(rumFlags({ st: 0, sr: 0, err: 0, ins: 0, spa: 0, log: 0, loaded: 1 })) }) // This test relies on features to call deregisterDrain when not enabled by flags which in turn should clear their backlogs. @@ -22,6 +22,7 @@ describe('Memory leaks', () => { expect(backlog).toEqual(expect.objectContaining({ ajax: 0, // ajax does not rely on any flags anyways so it's always drained jserrors: 0, + logging: 0, metrics: 0, generic_events: 0, page_view_event: 0, // no handler diff --git a/tests/specs/harvesting/disable-harvesting.e2e.js b/tests/specs/harvesting/disable-harvesting.e2e.js index b628548d0..cdf8c8667 100644 --- a/tests/specs/harvesting/disable-harvesting.e2e.js +++ b/tests/specs/harvesting/disable-harvesting.e2e.js @@ -1,4 +1,4 @@ -import { testBlobTraceRequest, testErrorsRequest, testEventsRequest, testInsRequest, testMetricsRequest, testRumRequest } from '../../../tools/testing-server/utils/expect-tests' +import { testBlobTraceRequest, testErrorsRequest, testEventsRequest, testInsRequest, testLogsRequest, testMetricsRequest, testRumRequest } from '../../../tools/testing-server/utils/expect-tests' import { rumFlags } from '../../../tools/testing-server/constants' describe('disable harvesting', () => { @@ -60,6 +60,22 @@ describe('disable harvesting', () => { expect(insightsHarvests).toEqual([]) }) + it('should disable harvesting console logs when log entitlement is 0', async () => { + const logsCapture = await browser.testHandle.createNetworkCaptures('bamServer', { test: testLogsRequest }) + await browser.testHandle.scheduleReply('bamServer', { + test: testRumRequest, + body: JSON.stringify(rumFlags({ log: 0 })) + }) + + const [logsHarvests] = await Promise.all([ + logsCapture.waitForResult({ timeout: 10000 }), + browser.url(await browser.testHandle.assetURL('obfuscate-pii.html')) + .then(() => browser.waitForAgentLoad()) + ]) + + expect(logsHarvests).toEqual([]) + }) + it('should disable harvesting session traces when stn entitlement is 0', async () => { const traceCapture = await browser.testHandle.createNetworkCaptures('bamServer', { test: testBlobTraceRequest }) await browser.testHandle.scheduleReply('bamServer', { diff --git a/tests/specs/logging/harvesting.e2e.js b/tests/specs/logging/harvesting.e2e.js index e2813490c..5e42fdc6b 100644 --- a/tests/specs/logging/harvesting.e2e.js +++ b/tests/specs/logging/harvesting.e2e.js @@ -1,12 +1,28 @@ -import { testLogsRequest } from '../../../tools/testing-server/utils/expect-tests' +import { testLogsRequest, testRumRequest } from '../../../tools/testing-server/utils/expect-tests' +import { rumFlags } from '../../../tools/testing-server/constants' +import { LOGGING_MODE } from '../../../src/features/logging/constants' describe('logging harvesting', () => { let logsCapture beforeEach(async () => { - logsCapture = await browser.testHandle.createNetworkCaptures('bamServer', { test: testLogsRequest }) + logsCapture = await browser.testHandle.createNetworkCaptures('bamServer', { + test: testLogsRequest + }) }) + const mockRumResponse = async (logLevel) => { + await browser.testHandle.scheduleReply('bamServer', { + test: testRumRequest, + body: JSON.stringify(rumFlags({ log: logLevel })) + }) + } + const checkPayload = (actualPayload, expectedPayload) => { + expect(actualPayload).toContainAllKeys(['common', 'logs']) + expect(actualPayload.common).toEqual(expectedPayload.common) + expect(actualPayload.logs).toIncludeSameMembers(expectedPayload.logs) + } + describe('logging harvests', () => { const pageUrl = expect.any(String) const customAttributes = { test: 1 } @@ -27,57 +43,54 @@ describe('logging harvesting', () => { } } } - const expectedLogs = (type) => { - if (type === 'api' || type === 'api-wrap-logger') { - return ['INFO', 'DEBUG', 'TRACE', 'ERROR', 'WARN'].map(level => ({ - level, - message: level.toLowerCase(), - timestamp: expect.any(Number), - attributes: { - pageUrl, - ...customAttributes - } - })) - } else if (type === 'console-logger') { - return ['LOG', 'INFO', 'DEBUG', 'TRACE', 'ERROR', 'WARN'].map(level => ({ - level: level === 'LOG' ? 'INFO' : level, - message: level.toLowerCase(), - timestamp: expect.any(Number), - attributes: { - pageUrl - } - })) - } + const expectedLogs = (type, logLevels = []) => { + return logLevels.map(level => ({ + level: type === 'console-logger' && level === 'LOG' ? 'INFO' : level, + message: level.toLowerCase(), + timestamp: expect.any(Number), + attributes: { + pageUrl, + ...(type === 'api' || type === 'api-wrap-logger' ? customAttributes : {}) + } + })) } ;['api', 'api-wrap-logger', 'console-logger'].forEach(type => { - it(`should harvest expected logs - ${type} pre load`, async () => { - const [[{ request: { body } }]] = await Promise.all([ - logsCapture.waitForResult({ totalCount: 1 }), - browser.url(await browser.testHandle.assetURL(`logs-${type}-pre-load.html`)) - ]) + Object.keys(LOGGING_MODE).filter(mode => mode !== 'OFF').forEach(mode => { + const logLevel = LOGGING_MODE[mode] + const loggingModes = Object.entries(LOGGING_MODE).filter(entry => entry[1] > LOGGING_MODE.OFF && entry[1] <= logLevel).map(entry => entry[0]) + if (type === 'console-logger' && logLevel >= LOGGING_MODE.INFO) { + loggingModes.push('LOG') + } const expectedPayload = [{ ...commonAttributes, - logs: expectedLogs(type) + logs: expectedLogs(type, loggingModes) }] - expect(JSON.parse(body)).toEqual(expectedPayload) - }) + it(`should harvest expected logs - ${type} pre load - logging mode: ${mode}`, async () => { + await mockRumResponse(logLevel) + const [[{ request: { body } }]] = await Promise.all([ + logsCapture.waitForResult({ totalCount: 1 }), + browser.url(await browser.testHandle.assetURL(`logs-${type}-pre-load.html`)) + ]) - it(`should harvest expected logs - ${type} post load`, async () => { - const [[{ request: { body } }]] = await Promise.all([ - logsCapture.waitForResult({ totalCount: 1 }), - browser.url(await browser.testHandle.assetURL(`logs-${type}-post-load.html`)) - ]) - const expectedPayload = [{ - ...commonAttributes, - logs: expectedLogs(type) - }] + const actualPayload = JSON.parse(body) + checkPayload(actualPayload[0], expectedPayload[0]) + }) - expect(JSON.parse(body)).toEqual(expectedPayload) + it(`should harvest expected logs - ${type} post load - logging mode: ${mode}`, async () => { + await mockRumResponse(logLevel) + const [[{ request: { body } }]] = await Promise.all([ + logsCapture.waitForResult({ totalCount: 1 }), + browser.url(await browser.testHandle.assetURL(`logs-${type}-post-load.html`)) + ]) + const actualPayload = JSON.parse(body) + checkPayload(actualPayload[0], expectedPayload[0]) + }) }) it(`should harvest early if reaching limit - ${type}`, async () => { + await mockRumResponse(LOGGING_MODE.INFO) let now = Date.now(); let then await Promise.all([ logsCapture.waitForResult({ totalCount: 1 }).then(() => { then = Date.now() }), @@ -88,12 +101,16 @@ describe('logging harvesting', () => { }) it(`should ignore log if too large - ${type}`, async () => { + await mockRumResponse(LOGGING_MODE.TRACE) const [[{ request: { body } }]] = await Promise.all([ logsCapture.waitForResult({ totalCount: 1 }), browser.url(await browser.testHandle.assetURL(`logs-${type}-too-large.html`)) ]) - - const logs = [...expectedLogs(type), { + const loggingModes = Object.entries(LOGGING_MODE).filter(entry => entry[1] > LOGGING_MODE.OFF).map(entry => entry[0]) + if (type === 'console-logger') { + loggingModes.push('LOG') + } + const logs = [...expectedLogs(type, loggingModes), { level: 'DEBUG', message: 'New Relic Warning: https://github.com/newrelic/newrelic-browser-agent/blob/main/docs/warning-codes.md#31', timestamp: expect.any(Number), @@ -105,7 +122,7 @@ describe('logging harvesting', () => { ...commonAttributes, logs }] - expect(JSON.parse(body)).toEqual(expectedPayload) // should not contain the '...xxxxx...' payload in it + checkPayload(JSON.parse(body)[0], expectedPayload[0]) // should not contain the '...xxxxx...' payload in it }) }) @@ -119,6 +136,7 @@ describe('logging harvesting', () => { }) it('should not double harvest on navigation logs', async () => { + await mockRumResponse(LOGGING_MODE.INFO) const [logsRequests] = await Promise.all([ logsCapture.waitForResult({ timeout: 15000 }), browser.url(await browser.testHandle.assetURL('logs-redirect.html')) @@ -133,6 +151,7 @@ describe('logging harvesting', () => { }) it('should allow for re-wrapping and 3rd party wrapping', async () => { + await mockRumResponse(LOGGING_MODE.INFO) const [[{ request: { body } }]] = await Promise.all([ logsCapture.waitForResult({ totalCount: 1 }), browser.url(await browser.testHandle.assetURL('logs-api-wrap-logger-rewrapped.html')) @@ -157,6 +176,7 @@ describe('logging harvesting', () => { describe('logging retry harvests', () => { [429].forEach(statusCode => it(`should send the logs on the next harvest when the first harvest statusCode is ${statusCode}`, async () => { + await mockRumResponse(LOGGING_MODE.TRACE) await browser.testHandle.scheduleReply('bamServer', { test: testLogsRequest, permanent: true, diff --git a/tools/testing-server/constants.js b/tools/testing-server/constants.js index 923dfdabd..0a7c98357 100644 --- a/tools/testing-server/constants.js +++ b/tools/testing-server/constants.js @@ -42,6 +42,7 @@ module.exports.rumFlags = (flags = {}, app = {}) => ({ sr: defaultFlagValue(flags.sr), // session replay entitlements 0|1 sts: defaultFlagValue(flags.sts), // session trace sampling 0|1|2 - off full error srs: defaultFlagValue(flags.srs), // session replay sampling 0|1|2 - off full error + log: flags.log ?? 3, // logging sampling 0|1|2|3|4|5 - off error warn info debug trace app: { agents: app.agents || [ { entityGuid: defaultEntityGuid } From 6658bcaab731000d1ab2189a6bd21d8d16b2c241 Mon Sep 17 00:00:00 2001 From: ptang-nr Date: Tue, 3 Dec 2024 11:18:33 -0800 Subject: [PATCH 3/7] feat: Persist logging flag in session (#1264) --- src/common/session/session-entity.js | 2 + src/features/logging/aggregate/index.js | 40 ++++- .../session_replay/aggregate/index.js | 16 +- src/features/utils/aggregate-base.js | 8 + tests/components/session-entity.test.js | 59 +------ tests/components/session-helpers.js | 1 + .../harvesting/disable-harvesting.e2e.js | 6 +- tests/specs/harvesting/index.e2e.js | 30 +++- tests/specs/logging/harvesting.e2e.js | 12 +- tests/specs/logging/session-pages.e2e.js | 166 ++++++++++++++++++ tests/specs/npm/micro-agent.e2e.js | 6 +- tests/specs/session-manager.e2e.js | 10 +- tests/specs/util/helpers.js | 33 ++++ tools/wdio/plugins/custom-commands.mjs | 14 ++ 14 files changed, 321 insertions(+), 82 deletions(-) create mode 100644 tests/specs/logging/session-pages.e2e.js diff --git a/src/common/session/session-entity.js b/src/common/session/session-entity.js index db4e92540..75900a632 100644 --- a/src/common/session/session-entity.js +++ b/src/common/session/session-entity.js @@ -12,6 +12,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 @@ -24,6 +25,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: {} } diff --git a/src/features/logging/aggregate/index.js b/src/features/logging/aggregate/index.js index f878d015f..467fcc16b 100644 --- a/src/features/logging/aggregate/index.js +++ b/src/features/logging/aggregate/index.js @@ -10,7 +10,9 @@ 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_TO_ENDPOINT } from '../../../loaders/features/features' +import { FEATURE_NAMES, FEATURE_TO_ENDPOINT } from '../../../loaders/features/features' +import { SESSION_EVENT_TYPES, SESSION_EVENTS } from '../../../common/session/constants' +import { ABORT_REASONS } from '../../session_replay/constants' export class Aggregate extends AggregateBase { static featureName = FEATURE_NAME @@ -18,13 +20,35 @@ export class Aggregate extends AggregateBase { super(agentRef, FEATURE_NAME) this.harvestTimeSeconds = agentRef.init.logging.harvestTimeSeconds + // 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.waitForFlags(['log']).then(([loggingMode]) => { - if (!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 } - this.loggingMode = loggingMode + if (session.isNew || !this.isSessionTrackingEnabled) { + this.loggingMode = loggingMode + + if (this.isSessionTrackingEnabled) { + this.syncWithSessionManager({ + loggingMode: this.loggingMode + }) + } + } else { + this.loggingMode = session.state.loggingMode + } this.scheduler = new HarvestScheduler(FEATURE_TO_ENDPOINT[this.featureName], { onFinished: (result) => this.postHarvestCleanup(result.sent && result.retry), retryDelay: this.harvestTimeSeconds, @@ -123,4 +147,14 @@ export class Aggregate extends AggregateBase { 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.loggingMode = LOGGING_MODE.OFF + this.syncWithSessionManager({ loggingMode: this.loggingMode }) + this.events.clear() + this.deregisterDrain() + } } diff --git a/src/features/session_replay/aggregate/index.js b/src/features/session_replay/aggregate/index.js index c824a5390..6bd9b90d6 100644 --- a/src/features/session_replay/aggregate/index.js +++ b/src/features/session_replay/aggregate/index.js @@ -73,7 +73,7 @@ export class Aggregate extends AggregateBase { 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 }) // Bespoke logic for blobs endpoint. @@ -147,16 +147,14 @@ export class Aggregate extends AggregateBase { this.scheduler.startTimer(this.harvestTimeSeconds) this.syncWithSessionManager({ sessionReplayMode: this.mode }) } else { - this.initializeRecording(false, true, true) + this.initializeRecording(false, true) } } /** - * 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} errorSample - the true/false state of the error sampling decision - * @param {boolean} fullSample - the true/false state of the full sampling decision - * @param {boolean} ignoreSession - whether to force the method to ignore the session state and use just the sample flags + * Evaluate entitlements (which already accounts for sampling) before starting feature mechanics, importing and configuring recording library, and setting storage state + * @param {boolean} srMode - the true/false state of the "sr" flag from RUM response + * @param {boolean} ignoreSession - whether to force the method to ignore the session state and use just the "sr" flag * @returns {void} */ async initializeRecording (srMode, ignoreSession) { @@ -394,8 +392,4 @@ export class Aggregate extends AggregateBase { this.ee.emit('REPLAY_ABORTED') while (this.recorder?.getEvents().events.length) this.recorder?.clearBuffer?.() } - - syncWithSessionManager (state = {}) { - this.agentRef.runtime.session.write(state) - } } diff --git a/src/features/utils/aggregate-base.js b/src/features/utils/aggregate-base.js index 873b64b61..286bce283 100644 --- a/src/features/utils/aggregate-base.js +++ b/src/features/utils/aggregate-base.js @@ -7,6 +7,7 @@ import { activatedFeatures } from '../../common/util/feature-flags' import { Obfuscator } from '../../common/util/obfuscate' import { EventBuffer } from './event-buffer' import { FEATURE_NAMES } from '../../loaders/features/features' +import { canEnableSessionTracking } from './feature-gates' export class AggregateBase extends FeatureBase { constructor (agentRef, featureName) { @@ -18,6 +19,7 @@ export class AggregateBase extends FeatureBase { else if (![FEATURE_NAMES.pageViewEvent, FEATURE_NAMES.sessionTrace].includes(this.featureName)) this.events = new EventBuffer() this.checkConfiguration(agentRef) this.obfuscator = agentRef.runtime.obfuscator + this.isSessionTrackingEnabled = canEnableSessionTracking(this.agentIdentifier) && this.agentRef.runtime.session } /** @@ -117,4 +119,10 @@ export class AggregateBase extends FeatureBase { existingAgent.runtime.obfuscator = new Obfuscator(this.agentIdentifier) } } + + syncWithSessionManager (state = {}) { + if (this.isSessionTrackingEnabled) { + this.agentRef.runtime.session.write(state) + } + } } diff --git a/tests/components/session-entity.test.js b/tests/components/session-entity.test.js index 49a5bbdbc..0cf3728be 100644 --- a/tests/components/session-entity.test.js +++ b/tests/components/session-entity.test.js @@ -2,6 +2,7 @@ import { PREFIX } from '../../src/common/session/constants' import { SessionEntity } from '../../src/common/session/session-entity' import { LocalMemory, model } from './session-helpers' import * as runtimeModule from '../../src/common/constants/runtime' +import { buildExpectedSessionState } from '../specs/util/helpers' jest.useFakeTimers() @@ -33,28 +34,13 @@ describe('constructor', () => { inactiveTimer: expect.any(Object), isNew: expect.any(Boolean), storage: expect.any(Object), - state: expect.objectContaining({ - value: expect.any(String), - expiresAt: expect.any(Number), - inactiveAt: expect.any(Number), - sessionReplayMode: expect.any(Number), - sessionReplaySentFirstChunk: expect.any(Boolean), - sessionTraceMode: expect.any(Number) - }) + state: expect.objectContaining(buildExpectedSessionState()) }) }) test('can use sane defaults', () => { const session = new SessionEntity({ agentIdentifier, key, storage }) - expect(session.state).toEqual(expect.objectContaining({ - value: expect.any(String), - expiresAt: expect.any(Number), - inactiveAt: expect.any(Number), - updatedAt: expect.any(Number), - sessionReplayMode: expect.any(Number), - sessionReplaySentFirstChunk: expect.any(Boolean), - sessionTraceMode: expect.any(Number) - })) + expect(session.state).toEqual(expect.objectContaining(buildExpectedSessionState())) }) test('expiresAt is the correct future timestamp - new session', () => { @@ -110,15 +96,7 @@ describe('constructor', () => { // missing required fields const storage = new LocalMemory({ [`${PREFIX}_${key}`]: { invalid_fields: true } }) const session = new SessionEntity({ agentIdentifier, key, storage }) - expect(session.state).toEqual(expect.objectContaining({ - value: expect.any(String), - expiresAt: expect.any(Number), - inactiveAt: expect.any(Number), - updatedAt: expect.any(Number), - sessionReplayMode: expect.any(Number), - sessionReplaySentFirstChunk: expect.any(Boolean), - sessionTraceMode: expect.any(Number) - })) + expect(session.state).toEqual(expect.objectContaining(buildExpectedSessionState())) }) test('expired expiresAt value in storage sets new defaults', () => { @@ -126,15 +104,7 @@ describe('constructor', () => { jest.setSystemTime(now) const storage = new LocalMemory({ [`${PREFIX}_${key}`]: { value, expiresAt: now - 100, inactiveAt: Infinity } }) const session = new SessionEntity({ agentIdentifier, key, storage }) - expect(session.state).toEqual(expect.objectContaining({ - value: expect.any(String), - expiresAt: expect.any(Number), - inactiveAt: expect.any(Number), - updatedAt: expect.any(Number), - sessionReplayMode: expect.any(Number), - sessionReplaySentFirstChunk: expect.any(Boolean), - sessionTraceMode: expect.any(Number) - })) + expect(session.state).toEqual(expect.objectContaining(buildExpectedSessionState())) }) test('expired inactiveAt value in storage sets new defaults', () => { @@ -142,15 +112,7 @@ describe('constructor', () => { jest.setSystemTime(now) const storage = new LocalMemory({ [`${PREFIX}_${key}`]: { value, inactiveAt: now - 100, expiresAt: Infinity } }) const session = new SessionEntity({ agentIdentifier, key, storage }) - expect(session.state).toEqual(expect.objectContaining({ - value: expect.any(String), - expiresAt: expect.any(Number), - inactiveAt: expect.any(Number), - updatedAt: expect.any(Number), - sessionReplayMode: expect.any(Number), - sessionReplaySentFirstChunk: expect.any(Boolean), - sessionTraceMode: expect.any(Number) - })) + expect(session.state).toEqual(expect.objectContaining(buildExpectedSessionState())) }) }) @@ -212,14 +174,7 @@ describe('read()', () => { const newSession = new SessionEntity({ agentIdentifier, key, storage, expiresMs: 10 }) expect(newSession.isNew).toBeTruthy() - expect(newSession.read()).toEqual(expect.objectContaining({ - value: expect.any(String), - expiresAt: expect.any(Number), - inactiveAt: expect.any(Number), - sessionReplayMode: expect.any(Number), - sessionReplaySentFirstChunk: expect.any(Boolean), - sessionTraceMode: expect.any(Number) - })) + expect(newSession.read()).toEqual(expect.objectContaining(buildExpectedSessionState())) }) test('"pre-existing" sessions get data from read()', () => { diff --git a/tests/components/session-helpers.js b/tests/components/session-helpers.js index 8e90f6919..e85f81dc4 100644 --- a/tests/components/session-helpers.js +++ b/tests/components/session-helpers.js @@ -38,6 +38,7 @@ export const model = { sessionReplaySentFirstChunk: false, sessionTraceMode: 0, traceHarvestStarted: false, + loggingMode: 0, serverTimeDiff: null, custom: {} } diff --git a/tests/specs/harvesting/disable-harvesting.e2e.js b/tests/specs/harvesting/disable-harvesting.e2e.js index cdf8c8667..bb5a297fe 100644 --- a/tests/specs/harvesting/disable-harvesting.e2e.js +++ b/tests/specs/harvesting/disable-harvesting.e2e.js @@ -1,5 +1,6 @@ import { testBlobTraceRequest, testErrorsRequest, testEventsRequest, testInsRequest, testLogsRequest, testMetricsRequest, testRumRequest } from '../../../tools/testing-server/utils/expect-tests' import { rumFlags } from '../../../tools/testing-server/constants' +import { LOGGING_MODE } from '../../../src/features/logging/constants' describe('disable harvesting', () => { it('should disable harvesting metrics and errors when err entitlement is 0', async () => { @@ -61,10 +62,13 @@ describe('disable harvesting', () => { }) it('should disable harvesting console logs when log entitlement is 0', async () => { + // logging mode will only take effect on a fresh session + await browser.destroyAgentSession() + const logsCapture = await browser.testHandle.createNetworkCaptures('bamServer', { test: testLogsRequest }) await browser.testHandle.scheduleReply('bamServer', { test: testRumRequest, - body: JSON.stringify(rumFlags({ log: 0 })) + body: JSON.stringify(rumFlags({ log: LOGGING_MODE.OFF })) }) const [logsHarvests] = await Promise.all([ diff --git a/tests/specs/harvesting/index.e2e.js b/tests/specs/harvesting/index.e2e.js index 681e235d2..8aa461249 100644 --- a/tests/specs/harvesting/index.e2e.js +++ b/tests/specs/harvesting/index.e2e.js @@ -1,6 +1,6 @@ import { faker } from '@faker-js/faker' import { testExpectedTrace } from '../util/helpers' -import { testAjaxEventsRequest, testAjaxTimeSlicesRequest, testBlobTraceRequest, testErrorsRequest, testInsRequest, testInteractionEventsRequest, testRumRequest, testTimingEventsRequest } from '../../../tools/testing-server/utils/expect-tests' +import { testAjaxEventsRequest, testAjaxTimeSlicesRequest, testBlobTraceRequest, testErrorsRequest, testInsRequest, testInteractionEventsRequest, testLogsRequest, testRumRequest, testTimingEventsRequest } from '../../../tools/testing-server/utils/expect-tests' describe('harvesting', () => { let rumCapture @@ -11,9 +11,10 @@ describe('harvesting', () => { let insightsCapture let interactionEventsCapture let errorMetricsCapture + let loggingEventsCapture beforeEach(async () => { - [rumCapture, timingEventsCapture, ajaxEventsCapture, ajaxMetricsCapture, traceCapture, insightsCapture, interactionEventsCapture, errorMetricsCapture] = await browser.testHandle.createNetworkCaptures('bamServer', [ + [rumCapture, timingEventsCapture, ajaxEventsCapture, ajaxMetricsCapture, traceCapture, insightsCapture, interactionEventsCapture, errorMetricsCapture, loggingEventsCapture] = await browser.testHandle.createNetworkCaptures('bamServer', [ { test: testRumRequest }, { test: testTimingEventsRequest }, { test: testAjaxEventsRequest }, @@ -21,7 +22,8 @@ describe('harvesting', () => { { test: testBlobTraceRequest }, { test: testInsRequest }, { test: testInteractionEventsRequest }, - { test: testErrorsRequest } + { test: testErrorsRequest }, + { test: testLogsRequest } ]) }) @@ -315,6 +317,28 @@ describe('harvesting', () => { interactionEventsHarvests.forEach(harvest => expect(harvest.request.query.s).toEqual('0')) }) + it('should not contain session data in the logs request when cookies_enabled is false', async () => { + const testURL = await browser.testHandle.assetURL('obfuscate-pii.html', { + init: { + privacy: { + cookies_enabled: false + } + } + }) + + const [ + loggingEventsHarvests + ] = await Promise.all([ + loggingEventsCapture.waitForResult({ totalCount: 1 }), + browser.url(testURL) + .then(() => browser.waitForAgentLoad()) + ]) + + loggingEventsHarvests.forEach(harvest => { + expect(harvest.request.query.session).toBeUndefined() + }) + }) + it('should not harvest features when there is no data', async () => { const [ insightsHarvests, diff --git a/tests/specs/logging/harvesting.e2e.js b/tests/specs/logging/harvesting.e2e.js index 5e42fdc6b..73d5fbf5b 100644 --- a/tests/specs/logging/harvesting.e2e.js +++ b/tests/specs/logging/harvesting.e2e.js @@ -11,12 +11,18 @@ describe('logging harvesting', () => { }) }) + afterEach(async () => { + // logging mode is sticky to the session, so we need to reset before the next test + await browser.destroyAgentSession() + }) + const mockRumResponse = async (logLevel) => { await browser.testHandle.scheduleReply('bamServer', { test: testRumRequest, body: JSON.stringify(rumFlags({ log: logLevel })) }) } + const checkPayload = (actualPayload, expectedPayload) => { expect(actualPayload).toContainAllKeys(['common', 'logs']) expect(actualPayload.common).toEqual(expectedPayload.common) @@ -70,8 +76,8 @@ describe('logging harvesting', () => { it(`should harvest expected logs - ${type} pre load - logging mode: ${mode}`, async () => { await mockRumResponse(logLevel) const [[{ request: { body } }]] = await Promise.all([ - logsCapture.waitForResult({ totalCount: 1 }), - browser.url(await browser.testHandle.assetURL(`logs-${type}-pre-load.html`)) + logsCapture.waitForResult({ totalCount: 1, timeout: 15000 }), + await browser.url(await browser.testHandle.assetURL(`logs-${type}-pre-load.html`)) ]) const actualPayload = JSON.parse(body) @@ -81,7 +87,7 @@ describe('logging harvesting', () => { it(`should harvest expected logs - ${type} post load - logging mode: ${mode}`, async () => { await mockRumResponse(logLevel) const [[{ request: { body } }]] = await Promise.all([ - logsCapture.waitForResult({ totalCount: 1 }), + logsCapture.waitForResult({ totalCount: 1, timeout: 15000 }), browser.url(await browser.testHandle.assetURL(`logs-${type}-post-load.html`)) ]) const actualPayload = JSON.parse(body) diff --git a/tests/specs/logging/session-pages.e2e.js b/tests/specs/logging/session-pages.e2e.js new file mode 100644 index 000000000..f7996d437 --- /dev/null +++ b/tests/specs/logging/session-pages.e2e.js @@ -0,0 +1,166 @@ +import { testLogsRequest } from '../../../tools/testing-server/utils/expect-tests' +import { LOGGING_MODE } from '../../../src/features/logging/constants' +import { supportsMultiTabSessions } from '../../../tools/browser-matcher/common-matchers.mjs' +import { getLogs } from '../util/helpers' + +describe('Logging Across Pages', () => { + let logsCapture + const TIMEOUT = 10000 + + beforeEach(async () => { + logsCapture = await browser.testHandle.createNetworkCaptures('bamServer', { + test: testLogsRequest + }) + await browser.enableLogging() + }) + + afterEach(async () => { + await browser.destroyAgentSession() + }) + + it('should record across same-tab page refresh', async () => { + let [logsHarvests] = await Promise.all([ + logsCapture.waitForResult({ totalCount: 1 }), + browser.url(await browser.testHandle.assetURL('logs-console-logger-pre-load.html')) + ]) + + const { localStorage } = await browser.getAgentSessionInfo() + const sessionId = localStorage.value + const page1Payload = JSON.parse(logsHarvests[0].request.body) + expect(page1Payload[0].common.attributes.session).toEqual(sessionId) + // expect log entries for: error, warn, info, log + expect(page1Payload[0].logs.length).toBe(4) + + // simulate a second call to rum in same session, which should return log = 0 + await browser.enableLogging({ logMode: LOGGING_MODE.OFF }) + let [refreshHarvests] = await Promise.all([ + logsCapture.waitForResult({ timeout: TIMEOUT }), + browser.refresh() + ]) + + // confirm we are still sending logs because logging is already enabled in this session + // note: the network capture has not been cleared, so the previous harvest is still there + expect(refreshHarvests.length).toBe(2) + const page2Payload = JSON.parse(refreshHarvests[1].request.body) + expect(page2Payload[0].common.attributes.session).toEqual(sessionId) + expect(page2Payload[0].logs.length).toBe(4) + }) + + it('should record across same-tab page navigation', async () => { + let [logsHarvests] = await Promise.all([ + logsCapture.waitForResult({ totalCount: 1 }), + browser.url(await browser.testHandle.assetURL('logs-console-logger-pre-load.html')) + ]) + + const { localStorage } = await browser.getAgentSessionInfo() + const sessionId = localStorage.value + const page1Payload = JSON.parse(logsHarvests[0].request.body) + expect(page1Payload[0].common.attributes.session).toEqual(sessionId) + // expect log entries for: error, warn, info, log + expect(page1Payload[0].logs.length).toBe(4) + + // simulate a second call to rum in same session, which should return log = 0 + await browser.enableLogging({ logMode: LOGGING_MODE.OFF }) + let [navigationHarvests] = await Promise.all([ + logsCapture.waitForResult({ timeout: TIMEOUT }), + browser.url(await browser.testHandle.assetURL('logs-console-logger-post-load.html')) + ]) + + // confirm we are still sending logs because logging is already enabled in this session + // note: the network capture has not been cleared, so the previous harvest is still there + expect(navigationHarvests.length).toBe(2) + const page2Payload = JSON.parse(navigationHarvests[1].request.body) + expect(page2Payload[0].common.attributes.session).toEqual(sessionId) + expect(page2Payload[0].logs.length).toBe(4) + }) + + it.withBrowsersMatching(supportsMultiTabSessions)('should record across new-tab page navigation', async () => { + let [logsHarvests] = await Promise.all([ + logsCapture.waitForResult({ totalCount: 1 }), + browser.url(await browser.testHandle.assetURL('logs-console-logger-pre-load.html')) + ]) + + const { localStorage } = await browser.getAgentSessionInfo() + const sessionId = localStorage.value + const page1Payload = JSON.parse(logsHarvests[0].request.body) + expect(page1Payload[0].common.attributes.session).toEqual(sessionId) + // expect log entries for: error, warn, info, log + expect(page1Payload[0].logs.length).toBe(4) + + // simulate a second call to rum in same session, which should return log = 0 + await browser.enableLogging({ logMode: LOGGING_MODE.OFF }) + let [newTabHarvests] = await Promise.all([ + logsCapture.waitForResult({ timeout: TIMEOUT }), + browser.newWindow(await browser.testHandle.assetURL('logs-console-logger-post-load.html'), { type: 'tab' }), + browser.waitForAgentLoad() + ]) + + // confirm we are still sending logs because logging is already enabled in this session + // note: the network capture has not been cleared, so the previous harvest is still there + expect(newTabHarvests.length).toBe(2) + const page2Payload = JSON.parse(newTabHarvests[1].request.body) + expect(page2Payload[0].common.attributes.session).toEqual(sessionId) + expect(page2Payload[0].logs.length).toBe(4) + + // IMPORTANT! - Reset the browser for the next test or it will fail + await browser.closeWindow() + await browser.switchToWindow((await browser.getWindowHandles())[0]) + }) + + it.withBrowsersMatching(supportsMultiTabSessions)('should kill active tab if killed in backgrounded tab', async () => { + let [logsHarvests] = await Promise.all([ + logsCapture.waitForResult({ totalCount: 1 }), + browser.url(await browser.testHandle.assetURL('logs-console-logger-pre-load.html')) + ]) + + const { localStorage } = await browser.getAgentSessionInfo() + const sessionId = localStorage.value + const page1Payload = JSON.parse(logsHarvests[0].request.body) + expect(page1Payload[0].common.attributes.session).toEqual(sessionId) + // expect log entries for: error, warn, info, log + expect(page1Payload[0].logs.length).toBe(4) + + await Promise.all([ + logsCapture.waitForResult({ timeout: TIMEOUT }), + browser.newWindow(await browser.testHandle.assetURL('logs-console-logger-post-load.html'), { type: 'tab' }), + browser.waitForAgentLoad() + ]) + + const page2BlockedBeforeAbort = await browser.execute(function () { + try { + return Object.values(newrelic.initializedAgents)[0].features.logging.featAggregate.blocked + } catch (err) { + return false + } + }) + expect(page2BlockedBeforeAbort).toEqual(false) + + const page2Blocked = await browser.execute(function () { + try { + var agg = Object.values(newrelic.initializedAgents)[0].features.logging.featAggregate + agg.abort() + return agg.blocked + } catch (err) { + return false + } + }) + expect(page2Blocked).toEqual(true) + + await browser.pause(1000) // Give the agent time to update the session state + await expect(getLogs()).resolves.toEqual(expect.objectContaining({ + events: [], + blocked: true, + loggingMode: LOGGING_MODE.OFF + })) + + await browser.closeWindow() + await browser.switchToWindow((await browser.getWindowHandles())[0]) + + await browser.pause(1000) // Give the agent time to update the session state + await expect(getLogs()).resolves.toEqual(expect.objectContaining({ + events: [], + blocked: true, + loggingMode: LOGGING_MODE.OFF + })) + }) +}) diff --git a/tests/specs/npm/micro-agent.e2e.js b/tests/specs/npm/micro-agent.e2e.js index e3ee368d4..c10e59097 100644 --- a/tests/specs/npm/micro-agent.e2e.js +++ b/tests/specs/npm/micro-agent.e2e.js @@ -3,6 +3,10 @@ import { testErrorsRequest, testInsRequest, testLogsRequest, testRumRequest } from '../../../tools/testing-server/utils/expect-tests' describe('micro-agent', () => { + beforeEach(async () => { + await browser.enableLogging() + }) + it('Smoke Test - Can send distinct payloads of all relevant data types to 2 distinct app IDs', async () => { const [rumCapture, errorsCapture, insightsCapture, logsCapture] = await browser.testHandle.createNetworkCaptures('bamServer', [ { test: testRumRequest }, @@ -40,7 +44,7 @@ describe('micro-agent', () => { rumCapture.waitForResult({ totalCount: 2 }), errorsCapture.waitForResult({ totalCount: 2 }), insightsCapture.waitForResult({ totalCount: 2 }), - logsCapture.waitForResult({ totalCount: 2 }) + logsCapture.waitForResult({ totalCount: 2, timeout: 15000 }) ]) // these props will get set to true once a test has matched it diff --git a/tests/specs/session-manager.e2e.js b/tests/specs/session-manager.e2e.js index 7bb371c50..00654e655 100644 --- a/tests/specs/session-manager.e2e.js +++ b/tests/specs/session-manager.e2e.js @@ -1,5 +1,6 @@ import { supportsMultiTabSessions } from '../../tools/browser-matcher/common-matchers.mjs' import { testErrorsRequest } from '../../tools/testing-server/utils/expect-tests' +import { buildExpectedSessionState } from './util/helpers' const config = { init: { @@ -8,14 +9,7 @@ const config = { } describe('newrelic session ID', () => { - const anySession = () => ({ - value: expect.any(String), - expiresAt: expect.any(Number), - inactiveAt: expect.any(Number), - updatedAt: expect.any(Number), - sessionReplayMode: expect.any(Number), - sessionReplaySentFirstChunk: expect.any(Boolean), - sessionTraceMode: expect.any(Number), + const anySession = () => buildExpectedSessionState({ traceHarvestStarted: expect.any(Boolean), custom: expect.any(Object), serverTimeDiff: expect.any(Number) diff --git a/tests/specs/util/helpers.js b/tests/specs/util/helpers.js index 0a54bc20d..296ba0dfb 100644 --- a/tests/specs/util/helpers.js +++ b/tests/specs/util/helpers.js @@ -14,6 +14,19 @@ export const RRWEB_EVENT_TYPES = { Custom: 5 } +export function buildExpectedSessionState (additionalExpectations) { + return Object.assign({ + value: expect.any(String), + expiresAt: expect.any(Number), + inactiveAt: expect.any(Number), + updatedAt: expect.any(Number), + sessionReplayMode: expect.any(Number), + sessionReplaySentFirstChunk: expect.any(Boolean), + sessionTraceMode: expect.any(Number), + loggingMode: expect.any(Number) + }, additionalExpectations) +} + export function testExpectedReplay ({ data, session, hasMeta, hasSnapshot, hasError, isFirstChunk, contentEncoding, decompressedBytes, appId, entityGuid, harvestId, currentUrl }) { expect(data.query).toMatchObject({ browser_monitoring_key: expect.any(String), @@ -166,3 +179,23 @@ export async function getSR () { } }) } + +export async function getLogs () { + return browser.execute(function () { + try { + var logs = Object.values(newrelic.initializedAgents)[0].features.logging.featAggregate + return { + events: logs.events.get(), + blocked: logs.blocked, + loggingMode: logs.loggingMode + } + } catch (err) { + return { + events: [], + blocked: undefined, + loggingMode: undefined, + err: JSON.stringify(err) + } + } + }) +} diff --git a/tools/wdio/plugins/custom-commands.mjs b/tools/wdio/plugins/custom-commands.mjs index 148493415..1471e31a2 100644 --- a/tools/wdio/plugins/custom-commands.mjs +++ b/tools/wdio/plugins/custom-commands.mjs @@ -115,6 +115,20 @@ export default class CustomCommands { }) }) + /** + * Sets a permanent scheduled reply for the rum call to include the log flag with sampling rate. + * Defaults to 100% sampling rate and log mode = 3/INFO. + */ + browser.addCommand('enableLogging', async function ({ sampling_rate = 100, logMode = 3 } = {}) { + const loggingMode = Math.random() * 100 < sampling_rate ? logMode : 0 + await browser.testHandle.clearScheduledReply('bamServer', { test: testRumRequest }) + await browser.testHandle.scheduleReply('bamServer', { + test: testRumRequest, + permanent: true, + body: JSON.stringify(rumFlags({ log: loggingMode })) + }) + }) + /** * Sets a permanent scheduled reply for the rum call to define the Date header * to a specific value. Default is to set the header to one hour in the past. From 5de66afa93c6caa3aa1bd437e70a5e713e5e8455 Mon Sep 17 00:00:00 2001 From: Pik Tang Date: Mon, 9 Dec 2024 13:14:35 -0800 Subject: [PATCH 4/7] chore: Prep to publish log experiment to staging Removing existing wrapLogger calls in preamble to tell them apart. --- .github/actions/build-ab/templates/postamble.js | 9 +-------- 1 file changed, 1 insertion(+), 8 deletions(-) diff --git a/.github/actions/build-ab/templates/postamble.js b/.github/actions/build-ab/templates/postamble.js index 90e0986c4..7345f8b4c 100644 --- a/.github/actions/build-ab/templates/postamble.js +++ b/.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}} From ea5735df201352dc65e074f3117e3d2952a5e07f Mon Sep 17 00:00:00 2001 From: Pik Tang Date: Wed, 11 Dec 2024 14:04:21 -0800 Subject: [PATCH 5/7] fix: Logging mode of the re-wrap test --- tests/specs/logging/harvesting.e2e.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/specs/logging/harvesting.e2e.js b/tests/specs/logging/harvesting.e2e.js index 5f7b9c35d..32bfd085f 100644 --- a/tests/specs/logging/harvesting.e2e.js +++ b/tests/specs/logging/harvesting.e2e.js @@ -157,7 +157,7 @@ describe('logging harvesting', () => { }) it('should allow for re-wrapping and 3rd party wrapping', async () => { - await mockRumResponse(LOGGING_MODE.INFO) + await mockRumResponse(LOGGING_MODE.DEBUG) const [[{ request: { body } }]] = await Promise.all([ logsCapture.waitForResult({ totalCount: 1 }), browser.url(await browser.testHandle.assetURL('logs-api-wrap-logger-rewrapped.html')) From 6053f4281ebc96a354e8ec50714e2e8ab984e1fc Mon Sep 17 00:00:00 2001 From: Pik Tang Date: Wed, 11 Dec 2024 14:32:22 -0800 Subject: [PATCH 6/7] chore: Small refactor/cleanup --- src/features/logging/aggregate/index.js | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/src/features/logging/aggregate/index.js b/src/features/logging/aggregate/index.js index 467fcc16b..46e0949a4 100644 --- a/src/features/logging/aggregate/index.js +++ b/src/features/logging/aggregate/index.js @@ -39,13 +39,7 @@ export class Aggregate extends AggregateBase { return } if (session.isNew || !this.isSessionTrackingEnabled) { - this.loggingMode = loggingMode - - if (this.isSessionTrackingEnabled) { - this.syncWithSessionManager({ - loggingMode: this.loggingMode - }) - } + this.updateLoggingMode(loggingMode) } else { this.loggingMode = session.state.loggingMode } @@ -63,6 +57,13 @@ export class Aggregate extends AggregateBase { }) } + updateLoggingMode (loggingMode) { + this.loggingMode = loggingMode + this.syncWithSessionManager({ + loggingMode: this.loggingMode + }) + } + handleLog (timestamp, message, attributes = {}, level = LOG_LEVELS.INFO) { if (this.blocked || !this.loggingMode) return @@ -152,8 +153,7 @@ export class Aggregate extends AggregateBase { abort (reason = {}) { handle(SUPPORTABILITY_METRIC_CHANNEL, [`Logging/Abort/${reason.sm}`], undefined, FEATURE_NAMES.logging, this.ee) this.blocked = true - this.loggingMode = LOGGING_MODE.OFF - this.syncWithSessionManager({ loggingMode: this.loggingMode }) + this.updateLoggingMode(LOGGING_MODE.OFF) this.events.clear() this.deregisterDrain() } From c2755448aebe085fd351a376811ba0fc435c6e02 Mon Sep 17 00:00:00 2001 From: Pik Tang Date: Wed, 8 Jan 2025 10:32:48 -0800 Subject: [PATCH 7/7] chore: Move session logic out of aggregate-base --- src/features/logging/aggregate/index.js | 8 ++++++++ src/features/session_replay/aggregate/index.js | 9 +++++++++ src/features/utils/aggregate-base.js | 8 -------- 3 files changed, 17 insertions(+), 8 deletions(-) diff --git a/src/features/logging/aggregate/index.js b/src/features/logging/aggregate/index.js index 46e0949a4..512ffc4c3 100644 --- a/src/features/logging/aggregate/index.js +++ b/src/features/logging/aggregate/index.js @@ -13,12 +13,14 @@ import { MAX_PAYLOAD_SIZE } from '../../../common/constants/agent-constants' import { FEATURE_NAMES, FEATURE_TO_ENDPOINT } 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.harvestTimeSeconds = agentRef.init.logging.harvestTimeSeconds + 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, () => { @@ -157,4 +159,10 @@ export class Aggregate extends AggregateBase { this.events.clear() this.deregisterDrain() } + + syncWithSessionManager (state = {}) { + if (this.isSessionTrackingEnabled) { + this.agentRef.runtime.session.write(state) + } + } } diff --git a/src/features/session_replay/aggregate/index.js b/src/features/session_replay/aggregate/index.js index 6bd9b90d6..ca6d77361 100644 --- a/src/features/session_replay/aggregate/index.js +++ b/src/features/session_replay/aggregate/index.js @@ -25,6 +25,7 @@ import { now } from '../../../common/timing/now' 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 @@ -52,6 +53,8 @@ export class Aggregate extends AggregateBase { this.recorder = args?.recorder this.errorNoticed = args?.errorNoticed || false + 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. @@ -392,4 +395,10 @@ export class Aggregate extends AggregateBase { this.ee.emit('REPLAY_ABORTED') while (this.recorder?.getEvents().events.length) this.recorder?.clearBuffer?.() } + + syncWithSessionManager (state = {}) { + if (this.isSessionTrackingEnabled) { + this.agentRef.runtime.session.write(state) + } + } } diff --git a/src/features/utils/aggregate-base.js b/src/features/utils/aggregate-base.js index 286bce283..873b64b61 100644 --- a/src/features/utils/aggregate-base.js +++ b/src/features/utils/aggregate-base.js @@ -7,7 +7,6 @@ import { activatedFeatures } from '../../common/util/feature-flags' import { Obfuscator } from '../../common/util/obfuscate' import { EventBuffer } from './event-buffer' import { FEATURE_NAMES } from '../../loaders/features/features' -import { canEnableSessionTracking } from './feature-gates' export class AggregateBase extends FeatureBase { constructor (agentRef, featureName) { @@ -19,7 +18,6 @@ export class AggregateBase extends FeatureBase { else if (![FEATURE_NAMES.pageViewEvent, FEATURE_NAMES.sessionTrace].includes(this.featureName)) this.events = new EventBuffer() this.checkConfiguration(agentRef) this.obfuscator = agentRef.runtime.obfuscator - this.isSessionTrackingEnabled = canEnableSessionTracking(this.agentIdentifier) && this.agentRef.runtime.session } /** @@ -119,10 +117,4 @@ export class AggregateBase extends FeatureBase { existingAgent.runtime.obfuscator = new Obfuscator(this.agentIdentifier) } } - - syncWithSessionManager (state = {}) { - if (this.isSessionTrackingEnabled) { - this.agentRef.runtime.session.write(state) - } - } }