From 302291a15b91157740af2c21a3019b4c81268be9 Mon Sep 17 00:00:00 2001 From: Alexander Sapountzis Date: Fri, 28 Aug 2026 16:24:59 -0400 Subject: [PATCH 1/2] feat: add diagnostic logging for setter/selectPlacements timing Logs attribute/identity setter calls (setUserAttribute, removeUserAttribute, onUserIdentified, onLoginComplete, onLogoutComplete, onModifyComplete) and selectPlacements dispatches independently via LoggingService, so the delta between when attributes get set and when a placement call goes out can be computed downstream from the logged timestamps and page URL. Only attribute keys are logged, never values, to avoid shipping customer PII into the logging pipeline. Diagnostic logs use their own rate-limit bucket (still shipped at severity INFO) so they can't starve the operational INFO budget shared with page-view/quota logging. --- src/Rokt-Kit.ts | 31 +++++- src/diagnosticTiming.spec.ts | 34 +++++++ src/diagnosticTiming.ts | 26 +++++ test/src/tests.spec.ts | 191 +++++++++++++++++++++++++++++++++++ 4 files changed, 280 insertions(+), 2 deletions(-) create mode 100644 src/diagnosticTiming.spec.ts create mode 100644 src/diagnosticTiming.ts diff --git a/src/Rokt-Kit.ts b/src/Rokt-Kit.ts index 61fcf8e..44b6f42 100644 --- a/src/Rokt-Kit.ts +++ b/src/Rokt-Kit.ts @@ -39,6 +39,7 @@ import { import { isLocalStorageAvailable } from './storage'; import { isObject, isString, isEmpty, isFunction, sanitizeUrl } from './utils'; +import { buildSetterDiagnosticLogEntry, buildSelectPlacementsDiagnosticLogEntry } from './diagnosticTiming'; import { createLauncherAttachState, markLauncherAttached, @@ -607,8 +608,13 @@ class ReportingTransport { code?: string, stackTrace?: string, onError?: (error: DeliveryError) => void, + // Defaults to `severity` so existing callers are unaffected. Pass a + // distinct value to give a class of logs its own rate-limit budget + // (e.g. diagnostics that shouldn't compete with operational INFO logs) + // while still reporting the real `severity` on the wire. + rateLimitKey: string = severity, ): void { - if (!this._isEnabled || this._rateLimiter.incrementAndCheck(severity)) { + if (!this._isEnabled || this._rateLimiter.incrementAndCheck(rateLimitKey)) { return; } @@ -708,9 +714,22 @@ class LoggingService { log(entry: LogEntry | null | undefined): void { if (!entry) return; + this._send(entry, WSDKErrorSeverity.INFO); + } + + // Ships at INFO severity like log(), but under its own rate-limit bucket + // (see ReportingTransport.send's rateLimitKey) so a burst of diagnostic + // timing entries can't starve the operational INFO budget shared by + // page-view/quota logging. + logDiagnostic(entry: LogEntry | null | undefined): void { + if (!entry) return; + this._send(entry, WSDKErrorSeverity.INFO, 'DIAGNOSTIC_TIMING'); + } + + private _send(entry: LogEntry, severity: string, rateLimitKey?: string): void { this._transport.send( this._loggingUrl, - WSDKErrorSeverity.INFO, + severity, entry.message, entry.code, undefined, @@ -727,6 +746,7 @@ class LoggingService { }); } }, + rateLimitKey, ); } } @@ -1335,6 +1355,7 @@ class RoktKit implements KitInterface { } public setUserAttribute(key: string, value: unknown): string { + this.loggingService?.logDiagnostic(buildSetterDiagnosticLogEntry('setUserAttribute', [key])); if (!isSelectPlacementsAttributePersistenceDenied(key)) { this.userAttributes[key] = value; } @@ -1342,12 +1363,14 @@ class RoktKit implements KitInterface { } public removeUserAttribute(key: string): string { + this.loggingService?.logDiagnostic(buildSetterDiagnosticLogEntry('removeUserAttribute', [key])); delete this.userAttributes[key]; return 'Successfully removed user attribute for forwarder: ' + name; } private handleIdentityComplete(user: IMParticleUser, callbackName: string): string { this.userAttributes = removeSelectPlacementsAttributePersistenceDeniedAttributes(user.getAllUserAttributes()); + this.loggingService?.logDiagnostic(buildSetterDiagnosticLogEntry(callbackName, Object.keys(this.userAttributes))); return 'Successfully called ' + callbackName + ' for forwarder: ' + name; } @@ -1552,6 +1575,10 @@ class RoktKit implements KitInterface { const selectPlacementsOptions: Record = { ...options, attributes: selectPlacementsAttributes }; + this.loggingService?.logDiagnostic( + buildSelectPlacementsDiagnosticLogEntry(Object.keys(selectPlacementsAttributes)), + ); + const selection = this.launcher!.selectPlacements(selectPlacementsOptions); // After selection resolves, sync the Rokt session ID back to mParticle, then log diff --git a/src/diagnosticTiming.spec.ts b/src/diagnosticTiming.spec.ts new file mode 100644 index 0000000..cb06467 --- /dev/null +++ b/src/diagnosticTiming.spec.ts @@ -0,0 +1,34 @@ +import { describe, it, expect } from 'vitest'; +import { buildSetterDiagnosticLogEntry, buildSelectPlacementsDiagnosticLogEntry } from './diagnosticTiming'; + +describe('diagnosticTiming', () => { + describe('buildSetterDiagnosticLogEntry', () => { + it('reports the source and attribute keys', () => { + const entry = buildSetterDiagnosticLogEntry('setUserAttribute', ['favoriteColor']); + + expect(entry.code).toBe('ATTRIBUTE_SETTER_CALLED'); + expect(entry.message).toBe('Rokt Kit: setUserAttribute called [attributeKeys=favoriteColor]'); + }); + + it('joins multiple attribute keys', () => { + const entry = buildSetterDiagnosticLogEntry('onUserIdentified', ['email', 'firstName']); + + expect(entry.message).toContain('[attributeKeys=email,firstName]'); + }); + + it('never includes attribute values, only keys', () => { + const entry = buildSetterDiagnosticLogEntry('setUserAttribute', ['email']); + + expect(entry.message).not.toContain('test@example.com'); + }); + }); + + describe('buildSelectPlacementsDiagnosticLogEntry', () => { + it('reports the full set of placement attribute keys', () => { + const entry = buildSelectPlacementsDiagnosticLogEntry(['favoriteColor', 'mpid']); + + expect(entry.code).toBe('SELECT_PLACEMENTS_DISPATCHED'); + expect(entry.message).toBe('Rokt Kit: selectPlacements dispatched [placementAttributeKeys=favoriteColor,mpid]'); + }); + }); +}); diff --git a/src/diagnosticTiming.ts b/src/diagnosticTiming.ts new file mode 100644 index 0000000..702b484 --- /dev/null +++ b/src/diagnosticTiming.ts @@ -0,0 +1,26 @@ +// Builds diagnostic log entries for attribute/identity setter calls and +// selectPlacements dispatches. Each fires independently at the moment it +// happens; correlating the two (timing delta, which setters preceded a given +// placement call) is done downstream from the logged timestamps and page URL +// that ReportingTransport already attaches to every log request. Attribute +// names only — never values — since this ships over the network logging +// pipeline and setter payloads can carry customer PII. + +export interface DiagnosticLogEntry { + message: string; + code: string; +} + +export function buildSetterDiagnosticLogEntry(source: string, attributeKeys: string[]): DiagnosticLogEntry { + return { + message: `Rokt Kit: ${source} called [attributeKeys=${attributeKeys.join(',')}]`, + code: 'ATTRIBUTE_SETTER_CALLED', + }; +} + +export function buildSelectPlacementsDiagnosticLogEntry(placementAttributeKeys: string[]): DiagnosticLogEntry { + return { + message: `Rokt Kit: selectPlacements dispatched [placementAttributeKeys=${placementAttributeKeys.join(',')}]`, + code: 'SELECT_PLACEMENTS_DISPATCHED', + }; +} diff --git a/test/src/tests.spec.ts b/test/src/tests.spec.ts index aeaae16..84d37a2 100644 --- a/test/src/tests.spec.ts +++ b/test/src/tests.spec.ts @@ -943,6 +943,40 @@ describe('Rokt Forwarder', () => { }); }); + it('should log a diagnostic entry with the full set of placement attribute keys, independent of any setter log', async () => { + await (window as any).mParticle.forwarder.init( + { + accountId: '123456', + }, + reportService.cb, + true, + null, + {}, + ); + + const logDiagnosticSpy = vi.spyOn((window as any).mParticle.forwarder.loggingService, 'logDiagnostic'); + + (window as any).mParticle.forwarder.setUserAttribute('favoriteColor', 'blue'); + + await (window as any).mParticle.forwarder.selectPlacements({ + identifier: 'test-placement', + attributes: { test: 'test' }, + }); + + // One log for the setter call, one for the selectPlacements dispatch — no correlation between them. + expect(logDiagnosticSpy).toHaveBeenCalledTimes(2); + expect(logDiagnosticSpy).toHaveBeenCalledWith( + expect.objectContaining({ message: 'Rokt Kit: setUserAttribute called [attributeKeys=favoriteColor]' }), + ); + const dispatchEntry = logDiagnosticSpy.mock.calls.find( + (call) => call[0].code === 'SELECT_PLACEMENTS_DISPATCHED', + )?.[0]; + expect(dispatchEntry.message).toContain('placementAttributeKeys='); + expect(dispatchEntry.message).toContain('favoriteColor'); + expect(dispatchEntry.message).not.toContain('blue'); + logDiagnosticSpy.mockRestore(); + }); + it('should send the mParticle session id current at the time of each call', async () => { let currentSessionId = 'first-mp-session'; (window as any).mParticle.sessionManager = { @@ -3647,6 +3681,31 @@ describe('Rokt Forwarder', () => { 'test-attribute': 'test-value', }); }); + + it('should log a diagnostic entry with the attribute key but not its value', async () => { + const logDiagnosticSpy = vi.spyOn((window as any).mParticle.forwarder.loggingService, 'logDiagnostic'); + + (window as any).mParticle.forwarder.setUserAttribute('test-attribute', 'sensitive-value'); + + expect(logDiagnosticSpy).toHaveBeenCalledWith( + expect.objectContaining({ + code: 'ATTRIBUTE_SETTER_CALLED', + message: 'Rokt Kit: setUserAttribute called [attributeKeys=test-attribute]', + }), + ); + logDiagnosticSpy.mockRestore(); + }); + + it('should log a diagnostic entry even for a denylisted attribute key', async () => { + const logDiagnosticSpy = vi.spyOn((window as any).mParticle.forwarder.loggingService, 'logDiagnostic'); + + (window as any).mParticle.forwarder.setUserAttribute('confirmationRef', 'order-123'); + + expect(logDiagnosticSpy).toHaveBeenCalledWith( + expect.objectContaining({ message: 'Rokt Kit: setUserAttribute called [attributeKeys=confirmationRef]' }), + ); + logDiagnosticSpy.mockRestore(); + }); }); describe('#removeUserAttribute', () => { @@ -3657,6 +3716,20 @@ describe('Rokt Forwarder', () => { expect((window as any).mParticle.forwarder.userAttributes).toEqual({}); }); + + it('should log a diagnostic entry for the removed key', async () => { + const logDiagnosticSpy = vi.spyOn((window as any).mParticle.forwarder.loggingService, 'logDiagnostic'); + + (window as any).mParticle.forwarder.removeUserAttribute('test-attribute'); + + expect(logDiagnosticSpy).toHaveBeenCalledWith( + expect.objectContaining({ + code: 'ATTRIBUTE_SETTER_CALLED', + message: 'Rokt Kit: removeUserAttribute called [attributeKeys=test-attribute]', + }), + ); + logDiagnosticSpy.mockRestore(); + }); }); describe('#onUserIdentified', () => { @@ -3679,6 +3752,30 @@ describe('Rokt Forwarder', () => { expect((window as any).mParticle.forwarder.filters.filteredUser.getMPID()).toBe('123'); }); + it('should log a diagnostic entry with the resulting attribute keys but not their values', () => { + const logDiagnosticSpy = vi.spyOn((window as any).mParticle.forwarder.loggingService, 'logDiagnostic'); + + (window as any).mParticle.forwarder.onUserIdentified({ + getAllUserAttributes: function () { + return { email: 'test@example.com' }; + }, + getMPID: function () { + return '123'; + }, + getUserIdentities: function () { + return { userIdentities: {} }; + }, + }); + + expect(logDiagnosticSpy).toHaveBeenCalledWith( + expect.objectContaining({ + code: 'ATTRIBUTE_SETTER_CALLED', + message: 'Rokt Kit: onUserIdentified called [attributeKeys=email]', + }), + ); + logDiagnosticSpy.mockRestore(); + }); + it('should not cache denylisted commerce attributes from the filtered user', () => { (window as any).mParticle.forwarder.onUserIdentified({ getAllUserAttributes: function () { @@ -4357,6 +4454,24 @@ describe('Rokt Forwarder', () => { 'user-attr': 'user-value', }); }); + + it('should log a diagnostic entry sourced as onLoginComplete', () => { + const logDiagnosticSpy = vi.spyOn((window as any).mParticle.forwarder.loggingService, 'logDiagnostic'); + + (window as any).mParticle.forwarder.onLoginComplete({ + getAllUserAttributes: function () { + return { 'user-attr': 'user-value' }; + }, + getMPID: function () { + return '123'; + }, + }); + + expect(logDiagnosticSpy).toHaveBeenCalledWith( + expect.objectContaining({ message: 'Rokt Kit: onLoginComplete called [attributeKeys=user-attr]' }), + ); + logDiagnosticSpy.mockRestore(); + }); }); describe('#onLogoutComplete', () => { @@ -4374,6 +4489,24 @@ describe('Rokt Forwarder', () => { 'remaining-attr': 'some-value', }); }); + + it('should log a diagnostic entry sourced as onLogoutComplete', () => { + const logDiagnosticSpy = vi.spyOn((window as any).mParticle.forwarder.loggingService, 'logDiagnostic'); + + (window as any).mParticle.forwarder.onLogoutComplete({ + getAllUserAttributes: function () { + return { 'remaining-attr': 'some-value' }; + }, + getMPID: function () { + return '123'; + }, + }); + + expect(logDiagnosticSpy).toHaveBeenCalledWith( + expect.objectContaining({ message: 'Rokt Kit: onLogoutComplete called [attributeKeys=remaining-attr]' }), + ); + logDiagnosticSpy.mockRestore(); + }); }); describe('#onModifyComplete', () => { @@ -4394,6 +4527,27 @@ describe('Rokt Forwarder', () => { 'modified-attr': 'modified-value', }); }); + + it('should log a diagnostic entry sourced as onModifyComplete', () => { + const logDiagnosticSpy = vi.spyOn((window as any).mParticle.forwarder.loggingService, 'logDiagnostic'); + + (window as any).mParticle.forwarder.onModifyComplete({ + getAllUserAttributes: function () { + return { 'modified-attr': 'modified-value' }; + }, + getMPID: function () { + return '123'; + }, + getUserIdentities: function () { + return { userIdentities: {} }; + }, + }); + + expect(logDiagnosticSpy).toHaveBeenCalledWith( + expect.objectContaining({ message: 'Rokt Kit: onModifyComplete called [attributeKeys=modified-attr]' }), + ); + logDiagnosticSpy.mockRestore(); + }); }); describe('#fetchOptimizely', () => { @@ -7935,6 +8089,43 @@ describe('Rokt Forwarder', () => { service.log(null); expect(fetchCalls.length).toBe(0); }); + + it('logDiagnostic should send to the logging endpoint with severity INFO', () => { + const errorService = new ErrorReportingServiceClass({ isLoggingEnabled: true }, '1.0.0', 'test-guid'); + const service = new LoggingServiceClass( + { loggingUrl: 'test.com/v1/log', isLoggingEnabled: true }, + errorService, + '1.0.0', + 'test-guid', + ); + service.logDiagnostic({ message: 'diagnostic entry', code: 'SELECT_PLACEMENTS_SETTER_TIMING' }); + expect(fetchCalls.length).toBe(1); + const body = JSON.parse(fetchCalls[0].options.body); + expect(body.severity).toBe('INFO'); + expect(body.additionalInformation.message).toBe('diagnostic entry'); + }); + + it('logDiagnostic should not share its rate-limit budget with log()', () => { + const errorService = new ErrorReportingServiceClass({ isLoggingEnabled: true }, '1.0.0', 'test-guid'); + const service = new LoggingServiceClass( + { loggingUrl: 'test.com/v1/log', isLoggingEnabled: true }, + errorService, + '1.0.0', + 'test-guid', + ); + + // Exhaust log()'s INFO budget. + for (let i = 0; i < 10; i++) { + service.log({ message: 'operational log ' + i }); + } + expect(fetchCalls.length).toBe(10); + service.log({ message: 'rate limited operational log' }); + expect(fetchCalls.length).toBe(10); + + // logDiagnostic still gets through on its own budget. + service.logDiagnostic({ message: 'diagnostic entry', code: 'SELECT_PLACEMENTS_SETTER_TIMING' }); + expect(fetchCalls.length).toBe(11); + }); }); describe('RateLimiter', () => { From 02137ab7c81120ebefe362b6b50267fc418b70f1 Mon Sep 17 00:00:00 2001 From: Alexander Sapountzis Date: Fri, 28 Aug 2026 16:43:46 -0400 Subject: [PATCH 2/2] refactor: isolate diagnostic log rate limit via a second transport Reverts ReportingTransport.send() to its original signature and instead gives LoggingService a dedicated ReportingTransport (its own RateLimiter, reusing the existing optional constructor param) for logDiagnostic(), so the rate-limit isolation lives entirely where it's needed instead of on the shared send() method used by ErrorReportingService too. --- src/Rokt-Kit.ts | 29 +++++++++++++---------------- 1 file changed, 13 insertions(+), 16 deletions(-) diff --git a/src/Rokt-Kit.ts b/src/Rokt-Kit.ts index 44b6f42..9ebcc06 100644 --- a/src/Rokt-Kit.ts +++ b/src/Rokt-Kit.ts @@ -608,13 +608,8 @@ class ReportingTransport { code?: string, stackTrace?: string, onError?: (error: DeliveryError) => void, - // Defaults to `severity` so existing callers are unaffected. Pass a - // distinct value to give a class of logs its own rate-limit budget - // (e.g. diagnostics that shouldn't compete with operational INFO logs) - // while still reporting the real `severity` on the wire. - rateLimitKey: string = severity, ): void { - if (!this._isEnabled || this._rateLimiter.incrementAndCheck(rateLimitKey)) { + if (!this._isEnabled || this._rateLimiter.incrementAndCheck(severity)) { return; } @@ -696,6 +691,10 @@ class ErrorReportingService { class LoggingService { private _transport: ReportingTransport; + // Own ReportingTransport (and thus own RateLimiter) so a burst of + // diagnostic timing entries can't starve the operational INFO budget + // that _transport shares with page-view/quota logging via log(). + private _diagnosticTransport: ReportingTransport; private _loggingUrl: string; private _errorReportingService: { report: (e: ErrorReport) => void }; @@ -708,28 +707,27 @@ class LoggingService { rateLimiter?: RateLimiter, ) { this._transport = new ReportingTransport(config, integrationName, launcherInstanceGuid, accountId, rateLimiter); + this._diagnosticTransport = new ReportingTransport(config, integrationName, launcherInstanceGuid, accountId); this._loggingUrl = generateReportingUrl(config?.loggingUrl, config?.integrationDomain, LOGGING_ENDPOINT); this._errorReportingService = errorReportingService; } log(entry: LogEntry | null | undefined): void { if (!entry) return; - this._send(entry, WSDKErrorSeverity.INFO); + this._send(this._transport, entry); } - // Ships at INFO severity like log(), but under its own rate-limit bucket - // (see ReportingTransport.send's rateLimitKey) so a burst of diagnostic - // timing entries can't starve the operational INFO budget shared by - // page-view/quota logging. + // Ships at INFO severity like log(), but through a separate transport + // instance so it has its own rate-limit budget. logDiagnostic(entry: LogEntry | null | undefined): void { if (!entry) return; - this._send(entry, WSDKErrorSeverity.INFO, 'DIAGNOSTIC_TIMING'); + this._send(this._diagnosticTransport, entry); } - private _send(entry: LogEntry, severity: string, rateLimitKey?: string): void { - this._transport.send( + private _send(transport: ReportingTransport, entry: LogEntry): void { + transport.send( this._loggingUrl, - severity, + WSDKErrorSeverity.INFO, entry.message, entry.code, undefined, @@ -746,7 +744,6 @@ class LoggingService { }); } }, - rateLimitKey, ); } }