Skip to content
Open
Show file tree
Hide file tree
Changes from 5 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions src/common/session/session-entity.js
Original file line number Diff line number Diff line change
Expand Up @@ -30,6 +30,7 @@ const model = {
sessionTraceMode: MODE.OFF,
traceHarvestStarted: false,
loggingMode: LOGGING_MODE.OFF,
logApiMode: LOGGING_MODE.OFF,
serverTimeDiff: null, // set by TimeKeeper; "undefined" value will not be stringified and stored but "null" will
custom: {},
numOfResets: 0
Expand Down
4 changes: 3 additions & 1 deletion src/common/wrap/wrap-logger.js
Original file line number Diff line number Diff line change
Expand Up @@ -20,10 +20,11 @@ const contextMap = new Map()
* @param {Object} sharedEE - The shared event emitter on which a new scoped event emitter will be based.
* @param {Object} parent - The parent object housing the logger function
* @param {string} loggerFn - The name of the function in the parent object to wrap
* @param {boolean} [autoCaptured=true] - True if log was captured from auto wrapping. False if it was captured from the API manual usage.
* @returns {Object} Scoped event emitter with a debug ID of `logger`.
*/
// eslint-disable-next-line
export function wrapLogger(sharedEE, parent, loggerFn, context) {
export function wrapLogger(sharedEE, parent, loggerFn, context, autoCaptured = true) {
if (!(typeof parent === 'object' && !!parent && typeof loggerFn === 'string' && !!loggerFn && typeof parent[loggerFn] === 'function')) return warn(29)
const ee = scopedEE(sharedEE)
const wrapFn = wfn(ee)
Expand All @@ -35,6 +36,7 @@ export function wrapLogger(sharedEE, parent, loggerFn, context) {
const ctx = new EventContext(contextId)
ctx.level = context.level
ctx.customAttributes = context.customAttributes
ctx.autoCaptured = autoCaptured

const contextLookupKey = parent[loggerFn]?.[flag] || parent[loggerFn]
contextMap.set(contextLookupKey, ctx)
Expand Down
61 changes: 34 additions & 27 deletions src/features/logging/aggregate/index.js
Original file line number Diff line number Diff line change
Expand Up @@ -19,34 +19,40 @@ export class Aggregate extends AggregateBase {
static featureName = FEATURE_NAME
constructor (agentRef) {
super(agentRef, FEATURE_NAME)
this.isSessionTrackingEnabled = canEnableSessionTracking(agentRef.init) && agentRef.runtime.session
const updateLocalLoggingMode = (auto, api) => {
this.loggingMode = { auto, api }
// In agent v1.290.0 & under, the logApiMode prop did not yet exist, so need to account for old session state being in-use.
if (api === undefined) this.loggingMode.api = auto
}

super.customAttributesAreSeparate = true

// 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.loggingMode !== LOGGING_MODE.OFF && data.loggingMode === LOGGING_MODE.OFF) this.abort(ABORT_REASONS.CROSS_TAB)
else this.loggingMode = data.loggingMode
// In agent v1.290.0 & under, the logApiMode prop did not yet exist, so need to account for old session state being in-use with just loggingMode off == feature off.
if (data.loggingMode === LOGGING_MODE.OFF && (!data.logApiMode || data.logApiMode === LOGGING_MODE.OFF)) this.abort(ABORT_REASONS.CROSS_TAB)
else updateLocalLoggingMode(data.loggingMode, data.logApiMode)
})

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.waitForFlags(['log', 'logapi']).then(([auto, api]) => {
if (this.blocked) return // means abort already happened before this, likely from session reset or update; abort would've set mode off + deregistered drain

this.loggingMode ??= { auto, api } // likewise, don't want to overwrite the mode if it was set already
const session = this.agentRef.runtime.session
if (canEnableSessionTracking(agentRef.init) && session) {
if (session.isNew) this.#syncWithSessionManager()
else updateLocalLoggingMode(session.state.loggingMode, session.state.logApiMode)
}
if (this.loggingMode.auto === LOGGING_MODE.OFF && this.loggingMode.api === LOGGING_MODE.OFF) {
this.blocked = true
this.deregisterDrain()
return
}
if (session.isNew || !this.isSessionTrackingEnabled) {
this.updateLoggingMode(loggingMode)
} else {
this.loggingMode = session.state.loggingMode
}

/** emitted by instrument class (wrapped loggers) or the api methods directly */
registerHandler(LOGGING_EVENT_EMITTER_CHANNEL, this.handleLog.bind(this), this.featureName, this.ee)
Expand All @@ -56,21 +62,17 @@ export class Aggregate extends AggregateBase {
})
}

updateLoggingMode (loggingMode) {
this.loggingMode = loggingMode
this.syncWithSessionManager({
loggingMode: this.loggingMode
})
}

handleLog (timestamp, message, attributes = {}, level = LOG_LEVELS.INFO, targetEntityGuid) {
handleLog (timestamp, message, attributes = {}, level = LOG_LEVELS.INFO, autoCaptured, targetEntityGuid) {
if (!this.agentRef.runtime.entityManager.get(targetEntityGuid)) return warn(56, this.featureName)
if (this.blocked || !this.loggingMode) return
if (this.blocked) return
// Check respective logging mode depending on whether this log is from auto wrapped instrumentation or manual API that it's not turned off.
const modeForThisLog = autoCaptured ? this.loggingMode.auto : this.loggingMode.api
if (!modeForThisLog) 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)) {
if (modeForThisLog < (LOGGING_MODE[level] || Infinity)) {
this.reportSupportabilityMetric('Logging/Event/Dropped/Sampling')
return
}
Expand Down Expand Up @@ -149,13 +151,18 @@ export class Aggregate extends AggregateBase {
this.events.clear()
this.events.clearSave()
}
this.updateLoggingMode(LOGGING_MODE.OFF)
this.loggingMode = {
auto: LOGGING_MODE.OFF,
api: LOGGING_MODE.OFF
}
this.#syncWithSessionManager()
this.deregisterDrain()
}

syncWithSessionManager (state = {}) {
if (this.isSessionTrackingEnabled) {
this.agentRef.runtime.session.write(state)
}
#syncWithSessionManager () {
this.agentRef.runtime.session?.write({
loggingMode: this.loggingMode.auto,
logApiMode: this.loggingMode.api
})
}
}
4 changes: 2 additions & 2 deletions src/features/logging/instrument/index.js
Original file line number Diff line number Diff line change
Expand Up @@ -32,8 +32,8 @@ export class Instrument extends InstrumentBase {

/** emitted by wrap-logger function */
this.ee.on('wrap-logger-end', function handleLog ([message]) {
const { level, customAttributes } = this
bufferLog(instanceEE, message, customAttributes, level)
const { level, customAttributes, autoCaptured } = this
bufferLog(instanceEE, message, customAttributes, level, autoCaptured)
})
this.importAggregator(agentRef, () => import(/* webpackChunkName: "logging-aggregate" */ '../aggregate'))
}
Expand Down
5 changes: 3 additions & 2 deletions src/features/logging/shared/utils.js
Original file line number Diff line number Diff line change
Expand Up @@ -13,11 +13,12 @@ import { LOGGING_EVENT_EMITTER_CHANNEL, LOG_LEVELS } from '../constants'
* @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
* @param {boolean} [autoCaptured=true] - True if log was captured from auto wrapping. False if it was captured from the API manual usage.
* @param {object=} targetEntityGuid - the optional target entity guid provided by an api call
*/
export function bufferLog (ee, message, customAttributes = {}, level = LOG_LEVELS.INFO, targetEntityGuid, timestamp = now()) {
export function bufferLog (ee, message, customAttributes = {}, level = LOG_LEVELS.INFO, autoCaptured = true, targetEntityGuid, timestamp = now()) {
handle(SUPPORTABILITY_METRIC_CHANNEL, [`API/logging/${level.toLowerCase()}/called`], undefined, FEATURE_NAMES.metrics, ee)
handle(LOGGING_EVENT_EMITTER_CHANNEL, [timestamp, message, customAttributes, level, targetEntityGuid], undefined, FEATURE_NAMES.logging, ee)
handle(LOGGING_EVENT_EMITTER_CHANNEL, [timestamp, message, customAttributes, level, autoCaptured, targetEntityGuid], undefined, FEATURE_NAMES.logging, ee)
}

/**
Expand Down
2 changes: 1 addition & 1 deletion src/loaders/api/log.js
Original file line number Diff line number Diff line change
Expand Up @@ -14,5 +14,5 @@ export function setupLogAPI (agent) {
}

export function log (message, { customAttributes = {}, level = LOG_LEVELS.INFO } = {}, agentRef, targetEntityGuid, timestamp = now()) {
bufferLog(agentRef.ee, message, customAttributes, level, targetEntityGuid, timestamp)
bufferLog(agentRef.ee, message, customAttributes, level, false, targetEntityGuid, timestamp)
}
2 changes: 1 addition & 1 deletion src/loaders/api/wrapLogger.js
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,6 @@ import { setupAPI } from './sharedHandlers'

export function setupWrapLoggerAPI (agent) {
setupAPI(WRAP_LOGGER, (parent, functionName, { customAttributes = {}, level = LOG_LEVELS.INFO } = {}) => {
wrapLogger(agent.ee, parent, functionName, { customAttributes, level })
wrapLogger(agent.ee, parent, functionName, { customAttributes, level }, false)
}, agent)
}
6 changes: 3 additions & 3 deletions tests/components/api.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -812,7 +812,7 @@ describe('API tests', () => {
})])

expectHandled(SUPPORTABILITY_METRIC_CHANNEL, ['API/logging/info/called'])
expectHandled('log', [expect.any(Number), 'test1', {}, 'INFO', undefined])
expectHandled('log', [expect.any(Number), 'test1', {}, 'INFO', false, undefined])

const callCount = agent.ee.emit.mock.calls.length
/** does NOT emit data for observed fn */
Expand Down Expand Up @@ -845,7 +845,7 @@ describe('API tests', () => {
})])

expectHandled(SUPPORTABILITY_METRIC_CHANNEL, ['API/logging/warn/called'])
expectHandled('log', [expect.any(Number), 'test1', {}, 'warn', undefined])
expectHandled('log', [expect.any(Number), 'test1', {}, 'warn', false, undefined])
})

test('should emit events with concat string for multiple args', () => {
Expand Down Expand Up @@ -909,7 +909,7 @@ describe('API tests', () => {

expectHandled(SUPPORTABILITY_METRIC_CHANNEL, ['API/log/called'])
expectHandled(SUPPORTABILITY_METRIC_CHANNEL, [`API/logging/${logMethod.toLowerCase().replace('log', '')}/called`])
expectHandled('log', [expect.any(Number), args[0], args[1].customAttributes, logMethod.replace('log', '')])
expectHandled('log', [expect.any(Number), args[0], args[1].customAttributes, logMethod.replace('log', ''), false])
})
})
})
Expand Down
30 changes: 23 additions & 7 deletions tests/components/logging/aggregate.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -35,9 +35,10 @@ afterEach(() => {
jest.clearAllMocks()
})

const mockLoggingRumResponse = async (mode) => {
const mockLoggingRumResponse = async (mode, apiMode) => {
loggingAggregate.ee.emit('rumresp', [{
log: mode
log: mode,
logapi: apiMode
}])
return await new Promise(process.nextTick)
}
Expand All @@ -64,22 +65,37 @@ describe('class setup', () => {

test('should wait for flags - 0 = OFF', async () => {
expect(loggingAggregate.drained).toBeUndefined()
await mockLoggingRumResponse(LOGGING_MODE.OFF)
await mockLoggingRumResponse(LOGGING_MODE.OFF, 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)
await mockLoggingRumResponse(LOGGING_MODE.ERROR, LOGGING_MODE.OFF)

expect(loggingAggregate.drained).toEqual(true)
})

test('is not blocked if just logapi is on while log is flagged off', async () => {
expect(loggingAggregate.drained).toBeUndefined()
await mockLoggingRumResponse(LOGGING_MODE.OFF, LOGGING_MODE.INFO)

expect(loggingAggregate.drained).toEqual(true)
})

test('does not overwrite logging modes if set prior to rum response', async () => {
loggingAggregate.loggingMode = { auto: LOGGING_MODE.WARN, api: LOGGING_MODE.TRACE }
await mockLoggingRumResponse(LOGGING_MODE.OFF, LOGGING_MODE.OFF)

expect(loggingAggregate.loggingMode).toEqual({ auto: LOGGING_MODE.WARN, api: LOGGING_MODE.TRACE })
expect(loggingAggregate.blocked).toEqual(false)
})
})

describe('payloads', () => {
beforeEach(() => {
mockLoggingRumResponse(LOGGING_MODE.INFO)
mockLoggingRumResponse(LOGGING_MODE.INFO, LOGGING_MODE.INFO)
})

test('fills buffered logs with event emitter messages and prepares matching payload', async () => {
Expand Down Expand Up @@ -224,7 +240,7 @@ 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])
await mockLoggingRumResponse(LOGGING_MODE[logLevel], 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])
Expand All @@ -236,7 +252,7 @@ test.each(Object.keys(LOGGING_MODE))('payloads - log events are emitted (or not)
})

test('can harvest early', async () => {
await mockLoggingRumResponse(LOGGING_MODE.INFO)
await mockLoggingRumResponse(LOGGING_MODE.INFO, LOGGING_MODE.INFO)

jest.spyOn(mainAgent.runtime.harvester, 'triggerHarvestFor')

Expand Down
6 changes: 3 additions & 3 deletions tests/components/logging/instrument.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -32,7 +32,7 @@ test('should subscribe to wrap-logger events and buffer them', async () => {

const message = faker.string.uuid()
myLoggerSuite.myTestLogger(message)
expect(loggingUtilsModule.bufferLog).toHaveBeenCalledWith(loggingInstrument.ee, message, customAttributes, 'error')
expect(loggingUtilsModule.bufferLog).toHaveBeenCalledWith(loggingInstrument.ee, message, customAttributes, 'error', true)
})

test('wrapLogger should not re-wrap or overwrite context if called more than once', async () => {
Expand All @@ -44,12 +44,12 @@ test('wrapLogger should not re-wrap or overwrite context if called more than onc

let message = faker.string.uuid()
myLoggerSuite.myTestLogger(message)
expect(loggingUtilsModule.bufferLog).toHaveBeenCalledWith(loggingInstrument.ee, message, customAttributes, 'error') // ignores args: 2
expect(loggingUtilsModule.bufferLog).toHaveBeenCalledWith(loggingInstrument.ee, message, customAttributes, 'error', true) // ignores args: 2

const newCustomAttributes = { args: faker.string.uuid() }
/** re-wrap the logger with a NEW context, new events should NOT get that context because the wrapper should early-exit */
wrapLogger(loggingInstrument.ee, myLoggerSuite, 'myTestLogger', { customAttributes: newCustomAttributes, level: 'info' })
message = faker.string.uuid()
myLoggerSuite.myTestLogger(message)
expect(loggingUtilsModule.bufferLog).toHaveBeenCalledWith(loggingInstrument.ee, message, newCustomAttributes, 'info')
expect(loggingUtilsModule.bufferLog).toHaveBeenCalledWith(loggingInstrument.ee, message, newCustomAttributes, 'info', true)
})
8 changes: 4 additions & 4 deletions tests/components/logging/utils.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,7 @@ describe('bufferLog', () => {
expect(handleModule.handle.mock.calls[0][0]).toEqual('storeSupportabilityMetrics')
expect(handleModule.handle.mock.calls[0][1]).toEqual(['API/logging/info/called'])
expect(handleModule.handle.mock.calls[1][0]).toEqual('log')
expect(handleModule.handle.mock.calls[1][1]).toEqual([expect.any(Number), message, {}, 'INFO'])
expect(handleModule.handle.mock.calls[1][1]).toEqual([expect.any(Number), message, {}, 'INFO', true])

// method should not cast to '' or '{}'
expect(handleModule.handle.mock.calls[1][1][1]).not.toEqual('')
Expand All @@ -37,7 +37,7 @@ describe('bufferLog', () => {
expect(handleModule.handle.mock.calls[0][0]).toEqual('storeSupportabilityMetrics')
expect(handleModule.handle.mock.calls[0][1]).toEqual(['API/logging/info/called'])
expect(handleModule.handle.mock.calls[1][0]).toEqual('log')
expect(handleModule.handle.mock.calls[1][1]).toEqual([expect.any(Number), message, {}, 'INFO'])
expect(handleModule.handle.mock.calls[1][1]).toEqual([expect.any(Number), message, {}, 'INFO', true])
})

test('should buffer logs with message and custom attributes', () => {
Expand All @@ -48,7 +48,7 @@ describe('bufferLog', () => {
expect(handleModule.handle.mock.calls[0][0]).toEqual('storeSupportabilityMetrics')
expect(handleModule.handle.mock.calls[0][1]).toEqual(['API/logging/info/called'])
expect(handleModule.handle.mock.calls[1][0]).toEqual('log')
expect(handleModule.handle.mock.calls[1][1]).toEqual([expect.any(Number), message, customAttributes, 'INFO'])
expect(handleModule.handle.mock.calls[1][1]).toEqual([expect.any(Number), message, customAttributes, 'INFO', true])
})

test('should buffer logs with message, custom attributes, and custom level', () => {
Expand All @@ -59,7 +59,7 @@ describe('bufferLog', () => {
expect(handleModule.handle.mock.calls[0][0]).toEqual('storeSupportabilityMetrics')
expect(handleModule.handle.mock.calls[0][1]).toEqual(['API/logging/error/called'])
expect(handleModule.handle.mock.calls[1][0]).toEqual('log')
expect(handleModule.handle.mock.calls[1][1]).toEqual([expect.any(Number), message, customAttributes, 'ERROR'])
expect(handleModule.handle.mock.calls[1][1]).toEqual([expect.any(Number), message, customAttributes, 'ERROR', true])
})
})

Expand Down
1 change: 1 addition & 0 deletions tests/components/session-helpers.js
Original file line number Diff line number Diff line change
Expand Up @@ -39,6 +39,7 @@ export const model = {
sessionTraceMode: 0,
traceHarvestStarted: false,
loggingMode: 0,
logApiMode: 0,
serverTimeDiff: null,
custom: {},
numOfResets: 0
Expand Down
2 changes: 1 addition & 1 deletion tests/specs/harvesting/disable-harvesting.e2e.js
Original file line number Diff line number Diff line change
Expand Up @@ -68,7 +68,7 @@ describe('disable harvesting', () => {
const logsCapture = await browser.testHandle.createNetworkCaptures('bamServer', { test: testLogsRequest })
await browser.testHandle.scheduleReply('bamServer', {
test: testRumRequest,
body: JSON.stringify(rumFlags({ log: LOGGING_MODE.OFF }))
body: JSON.stringify(rumFlags({ log: LOGGING_MODE.OFF, logapi: LOGGING_MODE.OFF }))
})

const [logsHarvests] = await Promise.all([
Expand Down
2 changes: 1 addition & 1 deletion tests/specs/logging/harvesting.e2e.js
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,7 @@ describe('logging harvesting', () => {
const mockRumResponse = async (logLevel) => {
await browser.testHandle.scheduleReply('bamServer', {
test: testRumRequest,
body: JSON.stringify(rumFlags({ log: logLevel }))
body: JSON.stringify(rumFlags({ log: logLevel, logapi: logLevel }))
})
}

Expand Down
Loading
Loading