diff --git a/packages/destination-actions/src/destinations/ms-bing-ads-audiences/syncAudiences/__tests__/index.test.ts b/packages/destination-actions/src/destinations/ms-bing-ads-audiences/syncAudiences/__tests__/index.test.ts index 596193a2677..0260dad8dc3 100644 --- a/packages/destination-actions/src/destinations/ms-bing-ads-audiences/syncAudiences/__tests__/index.test.ts +++ b/packages/destination-actions/src/destinations/ms-bing-ads-audiences/syncAudiences/__tests__/index.test.ts @@ -264,6 +264,295 @@ describe('MS Bing Ads Audiences syncAudiences', () => { expect(payloadArg[0].email).toBe('add1@segment.com') }) + describe('debug logging (actions-ms-bing-ads-audiences-debug-logging flag)', () => { + const DEBUG_FLAG = 'actions-ms-bing-ads-audiences-debug-logging' + + const makeLogger = () => + ({ + info: jest.fn(), + error: jest.fn(), + warn: jest.fn(), + debug: jest.fn(), + crit: jest.fn(), + log: jest.fn(), + withTags: jest.fn(), + level: 'info', + name: 'test' + } as any) + + const addEvent = () => + createTestEvent({ + type: 'identify', + properties: { aud_key: true }, + context: { traits: { email: 'demo@segment.com' } } + }) + + it('does not log when the flag is off', async () => { + nock(BASE_URL).post('/CustomerListUserData/Apply').reply(200, {}) + const logger = makeLogger() + + await testDestination.testAction('syncAudiences', { + event: addEvent(), + mapping: baseMapping, + useDefaultMappings: true, + settings, + logger, + features: { [DEBUG_FLAG]: false } + }) + + expect(logger.info).not.toHaveBeenCalled() + expect(logger.error).not.toHaveBeenCalled() + }) + + it('logs response metadata when the flag is on, without leaking CustomerListItems', async () => { + nock(BASE_URL).post('/CustomerListUserData/Apply').reply(200, { PartialErrors: [] }) + const logger = makeLogger() + + await testDestination.testAction('syncAudiences', { + event: addEvent(), + mapping: baseMapping, + useDefaultMappings: true, + settings, + logger, + features: { [DEBUG_FLAG]: true } + }) + + expect(logger.info).toHaveBeenCalledTimes(1) + const logged = (logger.info as jest.Mock).mock.calls[0][0] as string + expect(logged).toContain('[ms-bing-ads-audiences][DEBUG]') + expect(logged).toContain('identifierType=Email') + expect(logged).toContain('itemCount=1') + expect(logged).toContain('partialErrors=[]') + // The hashed identifier must never be logged. + expect(logged).not.toContain('5a95f052958dac8ed1d66d74eb481b3ccdbbc953b583c5ff0325be6b091d6281') + }) + + it('logs the Microsoft tracking id from the response header', async () => { + nock(BASE_URL) + .post('/CustomerListUserData/Apply') + .reply(200, { PartialErrors: [] }, { TrackingId: 'abc-123-track' }) + const logger = makeLogger() + + await testDestination.testAction('syncAudiences', { + event: addEvent(), + mapping: baseMapping, + useDefaultMappings: true, + settings, + logger, + features: { [DEBUG_FLAG]: true } + }) + + const logged = (logger.info as jest.Mock).mock.calls[0][0] as string + expect(logged).toContain('trackingId=abc-123-track') + }) + + it('falls back to a body-level tracking id when no header is present', async () => { + nock(BASE_URL).post('/CustomerListUserData/Apply').reply(200, { TrackingId: 'body-track-789', PartialErrors: [] }) + const logger = makeLogger() + + await testDestination.testAction('syncAudiences', { + event: addEvent(), + mapping: baseMapping, + useDefaultMappings: true, + settings, + logger, + features: { [DEBUG_FLAG]: true } + }) + + const logged = (logger.info as jest.Mock).mock.calls[0][0] as string + expect(logged).toContain('trackingId=body-track-789') + }) + + it('logs the tracking id in full, never truncated', async () => { + // Even an unexpectedly long tracking id must be quotable to Microsoft support verbatim. + const longTrackingId = `T-${'9'.repeat(6000)}` + nock(BASE_URL) + .post('/CustomerListUserData/Apply') + .reply(200, { PartialErrors: [] }, { TrackingId: longTrackingId }) + const logger = makeLogger() + + await testDestination.testAction('syncAudiences', { + event: addEvent(), + mapping: baseMapping, + useDefaultMappings: true, + settings, + logger, + features: { [DEBUG_FLAG]: true } + }) + + const logged = (logger.info as jest.Mock).mock.calls[0][0] as string + expect(logged).toContain(`trackingId=${longTrackingId}`) + expect(logged).not.toContain('[truncated]') + }) + + it('redacts PartialError free-text fields that can echo identifiers', async () => { + // Bing can echo the offending identifier in Message/Details/FieldPath. Only codes/index + // should be logged, never the free-text fields. + nock(BASE_URL) + .post('/CustomerListUserData/Apply') + .reply(200, { + PartialErrors: [ + { + ErrorCode: 'InvalidCustomerListItem', + Code: 4001, + Index: 0, + Type: 'BatchError', + Message: 'Invalid value crm_secret_12345', + Details: 'crm_secret_12345', + FieldPath: 'CustomerListItems[0]=crm_secret_12345' + } + ] + }) + const logger = makeLogger() + + await testDestination.testBatchAction('syncAudiences', { + events: [addEvent()], + mapping: baseMapping, + useDefaultMappings: true, + settings, + logger, + features: { [DEBUG_FLAG]: true } + }) + + const logged = (logger.info as jest.Mock).mock.calls[0][0] as string + expect(logged).toContain('ErrorCode') + expect(logged).toContain('InvalidCustomerListItem') + // The free-text fields (and any identifier they echo) must not be logged. + expect(logged).not.toContain('crm_secret_12345') + expect(logged).not.toContain('Message') + expect(logged).not.toContain('FieldPath') + }) + + it('strips control characters from logged content to prevent log injection', async () => { + // A crafted response body with newlines must not be able to forge log lines. + nock(BASE_URL) + .post('/CustomerListUserData/Apply') + .reply(200, { + PartialErrors: [ + { ErrorCode: 'X\nInjected', Code: 1, Index: 0, Type: 'T', Message: null, Details: null, FieldPath: null } + ] + }) + const logger = makeLogger() + + await testDestination.testBatchAction('syncAudiences', { + events: [addEvent()], + mapping: baseMapping, + useDefaultMappings: true, + settings, + logger, + features: { [DEBUG_FLAG]: true } + }) + + const logged = (logger.info as jest.Mock).mock.calls[0][0] as string + expect(logged).not.toContain('\n') + }) + + it('sanitizes a crafted audience id to prevent log injection', async () => { + nock(BASE_URL).post('/CustomerListUserData/Apply').reply(200, { PartialErrors: [] }) + const logger = makeLogger() + + await testDestination.testAction('syncAudiences', { + event: addEvent(), + mapping: { ...baseMapping, audience_id: 'aud\n_injected' }, + useDefaultMappings: true, + settings, + logger, + features: { [DEBUG_FLAG]: true } + }) + + const logged = (logger.info as jest.Mock).mock.calls[0][0] as string + expect(logged).not.toContain('\n') + }) + + it('truncates oversized values without exceeding the cap', async () => { + // A long PartialError code forces truncation; the resulting log line's summary segment + // (including the suffix) must stay within the configured cap. + const longCode = 'C'.repeat(10000) + nock(BASE_URL) + .post('/CustomerListUserData/Apply') + .reply(200, { + PartialErrors: [ + { ErrorCode: longCode, Code: 1, Index: 0, Type: 'T', Message: null, Details: null, FieldPath: null } + ] + }) + const logger = makeLogger() + + await testDestination.testBatchAction('syncAudiences', { + events: [addEvent()], + mapping: baseMapping, + useDefaultMappings: true, + settings, + logger, + features: { [DEBUG_FLAG]: true } + }) + + const logged = (logger.info as jest.Mock).mock.calls[0][0] as string + const partialErrors = logged.split('partialErrors=')[1] + expect(partialErrors).toContain('[truncated]') + // The truncated segment (suffix included) must not exceed the 4096 cap. + expect(partialErrors.length).toBeLessThanOrEqual(4096) + }) + + it('does not let a throwing logger break the action', async () => { + nock(BASE_URL).post('/CustomerListUserData/Apply').reply(200, { PartialErrors: [] }) + const logger = makeLogger() + ;(logger.info as jest.Mock).mockImplementation(() => { + throw new Error('logger exploded') + }) + + // A throwing logger must be swallowed so the action still succeeds. + const response = await testDestination.testAction('syncAudiences', { + event: addEvent(), + mapping: baseMapping, + useDefaultMappings: true, + settings, + logger, + features: { [DEBUG_FLAG]: true } + }) + + expect(response[0].status).toBe(200) + }) + + it('does not crash when the response body is empty', async () => { + // Empty body => response.data is undefined; logging must still succeed. + nock(BASE_URL).post('/CustomerListUserData/Apply').reply(200) + const logger = makeLogger() + + const response = await testDestination.testAction('syncAudiences', { + event: addEvent(), + mapping: baseMapping, + useDefaultMappings: true, + settings, + logger, + features: { [DEBUG_FLAG]: true } + }) + + expect(logger.info).toHaveBeenCalledTimes(1) + expect(response[0].status).toBe(200) + }) + + it('does not log on the error path (only success responses are logged)', async () => { + nock(BASE_URL).post('/CustomerListUserData/Apply').reply(500, { message: 'boom' }) + const logger = makeLogger() + + const response = await testDestination.testBatchAction('syncAudiences', { + events: [addEvent()], + mapping: baseMapping, + useDefaultMappings: true, + settings, + logger, + features: { [DEBUG_FLAG]: true } + }) + + // We only log successful responses; the error path emits nothing. + expect(logger.info).not.toHaveBeenCalled() + expect(logger.error).not.toHaveBeenCalled() + // The HTTP error is still handled normally. + expect(utils.handleHttpError).toHaveBeenCalled() + expect(response[0].status).toBe(500) + }) + }) + it('should throw non-HTTP errors in batch mode', async () => { // Create a custom error that is NOT an HTTPError const customError = new Error('Custom non-HTTP error') diff --git a/packages/destination-actions/src/destinations/ms-bing-ads-audiences/syncAudiences/index.ts b/packages/destination-actions/src/destinations/ms-bing-ads-audiences/syncAudiences/index.ts index e93d5fe65d8..12ee3bce235 100644 --- a/packages/destination-actions/src/destinations/ms-bing-ads-audiences/syncAudiences/index.ts +++ b/packages/destination-actions/src/destinations/ms-bing-ads-audiences/syncAudiences/index.ts @@ -1,4 +1,4 @@ -import { ActionDefinition, RequestClient, HTTPError } from '@segment/actions-core' +import { ActionDefinition, RequestClient, HTTPError, Logger, ModifiedResponse } from '@segment/actions-core' import { MultiStatusResponse } from '@segment/actions-core' import type { Settings } from '../generated-types' import type { Payload } from './generated-types' @@ -20,7 +20,7 @@ import { handleHttpError, categorizePayloadByAction } from '../utils' -import { Identifier, SyncAudiencePayload } from '../types' +import { Identifier, SyncAudiencePayload, PartialError } from '../types' const action: ActionDefinition = { title: 'Sync Audiences', @@ -36,15 +36,132 @@ const action: ActionDefinition = { batch_size, computation_class }, - perform: async (request, { payload }) => { - return await syncUser(request, [payload], false) + perform: async (request, { payload, features, logger }) => { + return await syncUser(request, [payload], false, isDebugLoggingEnabled(features), logger) }, - performBatch: async (request, { payload }) => { - return await syncUser(request, payload, true) + performBatch: async (request, { payload, features, logger }) => { + return await syncUser(request, payload, true, isDebugLoggingEnabled(features), logger) } } +// TEMPORARY DEBUG LOGGING — gated behind the 'actions-ms-bing-ads-audiences-debug-logging' +// feature flag. Logs non-sensitive request metadata (identifier type + item count) plus a +// redacted summary of the Bing Ads API response/errors to the centralized logging pipeline. +// It intentionally does NOT log CustomerListItems (hashed emails / CRM IDs) and strips the +// PartialError free-text fields (Message/Details/FieldPath) that can echo back identifiers — +// CRM IDs in particular are unhashed. Remove once debugging is complete. +const DEBUG_LOGGING_FLAG = 'actions-ms-bing-ads-audiences-debug-logging' + +const isDebugLoggingEnabled = (features: Record | undefined): boolean => + Boolean(features && features[DEBUG_LOGGING_FLAG]) + +// Cap logged values so a large or malformed response can't produce oversized log entries. The +// cap is strict: the returned string (including the truncation suffix) never exceeds it. +const MAX_LOGGED_BODY_LENGTH = 4096 +const TRUNCATION_SUFFIX = '…[truncated]' + +// Strip control characters so logged content can't forge log lines or inject control +// sequences. Applied to every interpolated value; does NOT cap length. +const stripControlChars = (value: string): string => + // Stripping control chars is the intent here, so no-control-regex is expected. + // eslint-disable-next-line no-control-regex + value.replace(/[\u0000-\u001f\u007f]/g, ' ') + +// Strip control chars AND cap length (truncating without splitting a surrogate pair). Use for +// values that can be arbitrarily large (response/error bodies); prefer stripControlChars alone +// for short identifiers that must be logged in full. +const sanitizeForLog = (value: string): string => { + let out = value + if (out.length > MAX_LOGGED_BODY_LENGTH) { + // Reserve room for the suffix so the total stays within the cap. + let end = MAX_LOGGED_BODY_LENGTH - TRUNCATION_SUFFIX.length + const code = out.charCodeAt(end - 1) + // If the cut lands on the high half of a surrogate pair, drop it. + if (code >= 0xd800 && code <= 0xdbff) { + end -= 1 + } + out = `${out.slice(0, end)}${TRUNCATION_SUFFIX}` + } + return stripControlChars(out) +} + +// Build a PII-safe summary of the Bing Ads response. PartialErrors are reduced to their codes +// and index — the free-text Message/Details/FieldPath fields can echo back the offending +// identifier value, so they are dropped. +const summarizeErrors = (errors: PartialError[] | undefined): string => { + if (!errors || errors.length === 0) { + return '[]' + } + return JSON.stringify(errors.map((e) => ({ ErrorCode: e.ErrorCode, Code: e.Code, Index: e.Index, Type: e.Type }))) +} + +// Extract Microsoft's request/tracking identifier so it can be quoted to Bing Ads support. +// It is normally returned as a response header (TrackingId / x-ms-trackingid / RequestId) and +// is sometimes also echoed in the body as a top-level id field. It is a short opaque id, not +// PII, so it is logged in full (control chars stripped, never truncated). +const TRACKING_HEADER_NAMES = ['trackingid', 'x-ms-trackingid', 'requestid', 'x-ms-requestid'] +const TRACKING_BODY_KEYS = ['TrackingId', 'RequestId'] + +const extractTrackingId = (headers: Headers | undefined, body: unknown): string => { + for (const name of TRACKING_HEADER_NAMES) { + const value = headers?.get(name) + if (value) { + return value + } + } + if (body && typeof body === 'object') { + for (const key of TRACKING_BODY_KEYS) { + const value = (body as Record)[key] + if (typeof value === 'string' && value) { + return value + } + } + } + return 'none' +} + +// Run a logging side effect, swallowing any error: temporary debug logging must never alter +// the action's control flow (e.g. by masking the original error in the catch path). +const safeLog = (fn: () => void): void => { + try { + fn() + } catch { + // Intentionally ignored — debug logging is best-effort. + } +} + +// TEMPORARY: logs a redacted summary of the Bing Ads response, plus non-sensitive metadata about +// the request and Microsoft's tracking id (for support tickets). We intentionally do NOT log +// CustomerListItems (hashed emails / CRM IDs) or the PartialError free-text fields — only +// identifier type, item count, status, tracking id and error codes. +const logBingAdsResponse = ( + logger: Logger | undefined, + debugLogging: boolean, + action: string, + audienceId: string, + sentPayload: SyncAudiencePayload, + response: ModifiedResponse +): void => { + if (!debugLogging || !logger) { + return + } + const { CustomerListItemSubType, CustomerListItems } = sentPayload.CustomerListUserData + const partialErrors = (response.data as { PartialErrors?: PartialError[] } | undefined)?.PartialErrors + const trackingId = extractTrackingId(response.headers, response.data) + safeLog(() => + logger.info( + `[ms-bing-ads-audiences][DEBUG] ${action} audienceId=${stripControlChars(audienceId)} status=${ + response.status + } ` + + // trackingId is only control-char stripped, never truncated, so it can be quoted in full. + `trackingId=${stripControlChars(trackingId)} ` + + `identifierType=${CustomerListItemSubType} itemCount=${CustomerListItems.length} ` + + `partialErrors=${sanitizeForLog(summarizeErrors(partialErrors))}` + ) + ) +} + /** * Synchronizes user audience data with Microsoft Bing Ads. * @@ -58,7 +175,13 @@ const action: ActionDefinition = { * @returns A promise that resolves to a `MultiStatusResponse` object summarizing the results. * @throws Will throw an error if a non-batch operation fails, or rethrows non-HTTP errors in batch mode. */ -const syncUser = async (request: RequestClient, payload: Payload[], isBatch: boolean) => { +const syncUser = async ( + request: RequestClient, + payload: Payload[], + isBatch: boolean, + debugLogging = false, + logger?: Logger +) => { const msResponse = new MultiStatusResponse() if (!Array.isArray(payload) || payload.length === 0) { @@ -87,10 +210,12 @@ const syncUser = async (request: RequestClient, payload: Payload[], isBatch: boo // Send data to Microsoft Bing Ads for both Add and Remove actions if they have entries if (addMap.size > 0) { const response = await sendDataToMicrosoftBingAds(request, addPayload) + logBingAdsResponse(logger, debugLogging, 'Add', audienceId, addPayload, response) handleMultistatusResponse(msResponse, response, addItems, addMap, payload, isBatch) } if (removeMap.size > 0) { const response = await sendDataToMicrosoftBingAds(request, removePayload) + logBingAdsResponse(logger, debugLogging, 'Remove', audienceId, removePayload, response) handleMultistatusResponse(msResponse, response, removeItems, removeMap, payload, isBatch) } } catch (error) {