diff --git a/src/libs/DebugUtils.ts b/src/libs/DebugUtils.ts index 14014053ea79..d28e905d066a 100644 --- a/src/libs/DebugUtils.ts +++ b/src/libs/DebugUtils.ts @@ -827,6 +827,7 @@ function validateReportActionDraftProperty(key: keyof ReportAction, value: strin isTestReceipt: 'boolean', isTestDriveReceipt: 'boolean', thumbnail: 'string', + receiptTraceId: 'string', }); case 'childRecentReceiptTransactionIDs': return validateObject>(value, {}, 'string'); @@ -1188,6 +1189,7 @@ function validateTransactionDraftProperty(key: keyof Transaction, value: string) isTestReceipt: 'boolean', isTestDriveReceipt: 'boolean', thumbnail: 'string', + receiptTraceId: 'string', }); case 'taxRate': return validateObject>(value, { diff --git a/src/libs/Network/SequentialQueue.ts b/src/libs/Network/SequentialQueue.ts index 3a20f1883ea9..65c3caefc530 100644 --- a/src/libs/Network/SequentialQueue.ts +++ b/src/libs/Network/SequentialQueue.ts @@ -19,6 +19,7 @@ import Log from '@libs/Log'; import {getIsOffline as isOfflineNetwork} from '@libs/NetworkState'; import {processWithMiddleware} from '@libs/Request'; import RequestThrottle from '@libs/RequestThrottle'; +import {logReceiptEnqueued, RECEIPT_BEARING_COMMANDS} from '@libs/telemetry/ReceiptObservability'; import CONST from '@src/CONST'; import ONYXKEYS from '@src/ONYXKEYS'; @@ -555,6 +556,26 @@ async function push(newRequest: OnyxRequest): Promis isSequentialQueueRunning, }); + if (RECEIPT_BEARING_COMMANDS.has(newRequest.command)) { + const data = (newRequest.data ?? {}) as { + transactionID?: string; + receipt?: {receiptTraceId?: string}; + }; + // Only log when there is a receipt at data.receipt. SplitBill nests it in the splits JSON, and SendMoney and + // friends can run without one. A row without a trace id cannot be joined to the capture log, so it is just noise. + if (data.receipt) { + logReceiptEnqueued({ + receiptTraceId: data.receipt.receiptTraceId, + transactionID: data.transactionID, + command: newRequest.command, + persistedQueueLength: currentRequests.length, + }); + } + } + + // Save the request to the persisted queue. The in-memory update inside save() + // happens synchronously, so flush() below will see the new request immediately. + // The returned promise resolves when disk persistence completes. let persistencePromise: Promise; if (newRequest.checkAndFixConflictingRequest) { diff --git a/src/libs/actions/App.ts b/src/libs/actions/App.ts index c9dfa5a6b485..4a288c39bb2a 100644 --- a/src/libs/actions/App.ts +++ b/src/libs/actions/App.ts @@ -16,6 +16,7 @@ import {sanitizeUrlForLogging} from '@libs/sanitizeLogParams'; import {isLoggingInAsNewUser as isLoggingInAsNewUserSessionUtils} from '@libs/SessionUtils'; import {clearSoundAssetsCache} from '@libs/Sound'; import {cancelAllSpans, endSpan, getSpan, startSpan} from '@libs/telemetry/activeSpans'; +import {logReceiptQueueSnapshot} from '@libs/telemetry/ReceiptObservability'; import CONST from '@src/CONST'; import getPathFromState from '@src/libs/Navigation/helpers/getPathFromState'; @@ -289,12 +290,14 @@ AppState.addEventListener('change', (nextAppState) => { if (nextAppState.match(/inactive|background/) && appState === 'active') { Log.info('App going to background', false, {previousState: appState, nextState: nextAppState}); Log.info('Flushing logs as app is going inactive', true, {}, true); + logReceiptQueueSnapshot('background'); saveCurrentPathBeforeBackground(); } if (nextAppState === 'active' && appState?.match(/inactive|background/)) { Log.info('App coming to foreground', false, {previousState: appState, nextState: nextAppState}); Log.info('Cancelling telemetry spans as app is coming to foreground', false, {previousState: appState, nextState: nextAppState}); + logReceiptQueueSnapshot('foreground'); cancelAllSpans(); } appState = nextAppState; diff --git a/src/libs/actions/IOU/MoneyRequest.ts b/src/libs/actions/IOU/MoneyRequest.ts index 71e93f0f2ab5..70157875bc4d 100644 --- a/src/libs/actions/IOU/MoneyRequest.ts +++ b/src/libs/actions/IOU/MoneyRequest.ts @@ -1,5 +1,6 @@ import type {LocalizedTranslate} from '@components/LocaleContextProvider'; +import {WRITE_COMMANDS} from '@libs/API/types'; import DateUtils from '@libs/DateUtils'; import DistanceRequestUtils from '@libs/DistanceRequestUtils'; import {getGPSRoutes, getGPSWaypoints} from '@libs/GPSDraftDetailsUtils'; @@ -18,6 +19,7 @@ import { } from '@libs/ReportUtils'; import type {OptionData} from '@libs/ReportUtils'; import {startSpan} from '@libs/telemetry/activeSpans'; +import {logReceiptSubmitted} from '@libs/telemetry/ReceiptObservability'; import { getCategoryTaxDetails, getDefaultTaxCode, @@ -145,6 +147,14 @@ function createTransaction({ const taxCode = (transaction?.taxCode ? transaction.taxCode : defaultTaxCode) ?? ''; const taxAmount = transaction?.taxAmount ?? 0; const optimisticTransactionID = optimisticTransactionIDs.at(index); + const submittedCommand = iouType === CONST.IOU.TYPE.TRACK && report ? WRITE_COMMANDS.TRACK_EXPENSE : WRITE_COMMANDS.REQUEST_MONEY; + logReceiptSubmitted({ + receiptTraceId: receipt.receiptTraceId, + draftTransactionID: receiptFile.transactionID, + transactionID: optimisticTransactionID ?? receiptFile.transactionID, + command: submittedCommand, + iouType, + }); if (iouType === CONST.IOU.TYPE.TRACK && report) { trackExpense({ report, diff --git a/src/libs/actions/IOU/Receipt.ts b/src/libs/actions/IOU/Receipt.ts index d17d60665280..c20e32c83d30 100644 --- a/src/libs/actions/IOU/Receipt.ts +++ b/src/libs/actions/IOU/Receipt.ts @@ -8,6 +8,7 @@ import Navigation from '@libs/Navigation/Navigation'; import {hasDependentTags, isGroupPolicy} from '@libs/PolicyUtils'; import {buildOptimisticDetachReceipt, isInvoiceReport as isInvoiceReportReportUtils} from '@libs/ReportUtils'; import {getCurrentSearchQueryJSON} from '@libs/SearchQueryUtils'; +import {logReceiptCaptured, mintAndStampReceiptTraceId} from '@libs/telemetry/ReceiptObservability'; import ViolationsUtils from '@libs/Violations/ViolationsUtils'; import {resolveDetachReceiptConflicts} from '@userActions/RequestConflictUtils'; @@ -194,6 +195,9 @@ function replaceReceipt({ return; } + const receiptTraceId = mintAndStampReceiptTraceId(file); + logReceiptCaptured({file, captureSource: 'replace', receiptTraceId}); + const allTransactions = getAllTransactions(); const allReports = getAllReports(); @@ -205,6 +209,7 @@ function replaceReceipt({ localSource: null, state: state ?? CONST.IOU.RECEIPT_STATE.OPEN, filename: file.name, + receiptTraceId, }; const newTransaction = transaction && {...transaction, receipt: receiptOptimistic}; const retryParams: ReplaceReceipt = {transactionID, file: undefined, source, transactionPolicy, transactionPolicyCategories, transactionPolicyTagList, transactionViolations}; @@ -315,10 +320,11 @@ function setMoneyRequestReceipt( isTestReceipt = false, isTestDriveReceipt = false, thumbnail?: string, + receiptTraceId?: string, ) { Onyx.merge(`${isDraft ? ONYXKEYS.COLLECTION.TRANSACTION_DRAFT : ONYXKEYS.COLLECTION.TRANSACTION}${transactionID}`, { // isTestReceipt = false and isTestDriveReceipt = false are being converted to null because we don't really need to store it in Onyx in those cases - receipt: {source, filename, type: type ?? '', isTestReceipt: isTestReceipt ? true : null, isTestDriveReceipt: isTestDriveReceipt ? true : null, thumbnail}, + receipt: {source, filename, type: type ?? '', isTestReceipt: isTestReceipt ? true : null, isTestDriveReceipt: isTestDriveReceipt ? true : null, thumbnail, receiptTraceId}, }); } diff --git a/src/libs/actions/Session/index.ts b/src/libs/actions/Session/index.ts index eba84e1f68c0..c794e70981d5 100644 --- a/src/libs/actions/Session/index.ts +++ b/src/libs/actions/Session/index.ts @@ -39,6 +39,7 @@ import {getReportIDFromLink} from '@libs/ReportUtils'; import * as SessionUtils from '@libs/SessionUtils'; import {checkIfShouldUseNewPartnerName, resetDidUserLogInDuringSession} from '@libs/SessionUtils'; import {clearSoundAssetsCache} from '@libs/Sound'; +import {logReceiptQueueSnapshot} from '@libs/telemetry/ReceiptObservability'; import Timers from '@libs/Timers'; import {hideContextMenu} from '@pages/inbox/report/ContextMenu/ReportActionContextMenu'; @@ -258,6 +259,7 @@ function signInWithSupportAuthToken(authToken: string) { */ function signOut(params: {autoGeneratedLogin?: string; signedInWithSAML?: boolean; authToken?: string} = {}): Promise> { Log.info('Flushing logs before signing out', true, {}, true); + logReceiptQueueSnapshot('signOut'); const shouldUseNewPartnerName = checkIfShouldUseNewPartnerName(params.autoGeneratedLogin); const logOutParams: LogOutParams = { diff --git a/src/libs/telemetry/ReceiptObservability.ts b/src/libs/telemetry/ReceiptObservability.ts new file mode 100644 index 000000000000..d8e1dbfc22b9 --- /dev/null +++ b/src/libs/telemetry/ReceiptObservability.ts @@ -0,0 +1,208 @@ +import {getAll as getAllPersistedRequests, getOngoingRequest} from '@libs/actions/PersistedRequests'; +import {WRITE_COMMANDS} from '@libs/API/types'; +import getPlatform from '@libs/getPlatform'; +import Log from '@libs/Log'; +import {getIsOffline} from '@libs/NetworkState'; +import {rand64} from '@libs/NumberUtils'; + +import CONST from '@src/CONST'; +import type {FileObject} from '@src/types/utils/Attachment'; + +/** Prefix on every receipt log line so we can filter the logs without parsing free text. */ +const RECEIPT_LOG_PREFIX = '[Receipt]'; + +/** Points in the app lifecycle where we snapshot the receipts that are still pending. */ +type ReceiptSnapshotTrigger = 'signOut' | 'background' | 'foreground'; + +/** How a receipt entered the app. */ +type ReceiptCaptureSource = 'camera' | 'gallery' | 'file' | 'replace'; + +/** + * Maps the picker capture path to a source. On native the picker is the OS gallery. On web the same callback fires + * for both file browsing and drag and drop. Keeping it here means a new platform only has to change one place. + */ +function getPickerCaptureSource(): ReceiptCaptureSource { + return getPlatform() === CONST.PLATFORM.WEB ? 'file' : 'gallery'; +} + +/** Inputs for the enqueued milestone, taken when the receipt request reaches the write queue. */ +type ReceiptEnqueuedParams = { + receiptTraceId: string | undefined; + transactionID: string | undefined; + command: string; + persistedQueueLength: number; +}; + +/** + * Write commands whose params can carry a captured receipt. A pending request with one of these commands is a receipt + * that has not reached the server yet. Keep this in sync with the durability slice so the two features agree on which + * queued requests own a local receipt file. + */ +const RECEIPT_BEARING_COMMANDS = new Set([ + WRITE_COMMANDS.REQUEST_MONEY, + WRITE_COMMANDS.TRACK_EXPENSE, + WRITE_COMMANDS.SPLIT_BILL, + WRITE_COMMANDS.SPLIT_BILL_AND_OPEN_REPORT, + WRITE_COMMANDS.START_SPLIT_BILL, + WRITE_COMMANDS.COMPLETE_SPLIT_BILL, + WRITE_COMMANDS.REPLACE_RECEIPT, + WRITE_COMMANDS.SEND_MONEY_ELSEWHERE, + WRITE_COMMANDS.SEND_MONEY_WITH_WALLET, + WRITE_COMMANDS.CATEGORIZE_TRACKED_EXPENSE, + WRITE_COMMANDS.SHARE_TRACKED_EXPENSE, +]); + +/** When each receipt was enqueued, keyed by transaction id, so a snapshot can report how long it has waited. */ +const enqueuedAtByTransactionID = new Map(); + +/** + * Upper bound on the enqueue timing map. The snapshot path normally drains it, but a session that never backgrounds + * or signs out, like a long-lived web tab, would keep adding one entry per receipt. Once we pass this cap we drop the + * oldest entry. Losing it only makes a later snapshot miss the wait time for that receipt, so the data stays correct. + */ +const MAX_TRACKED_ENQUEUE_TIMESTAMPS = 100; + +/** + * Creates a unique correlation id for a captured receipt and stamps it on the in-memory file object. + * + * We add it as a normal property so it travels with the file through submit into the final request params, and + * survives JSON.stringify and Onyx storage into the persisted request. This still works for a web File, whose binary + * content never serializes. + */ +function mintAndStampReceiptTraceId(file: FileObject): string { + const receiptTraceId = rand64(); + // eslint-disable-next-line no-param-reassign + file.receiptTraceId = receiptTraceId; + return receiptTraceId; +} + +/** + * Records the capture milestone, the moment a receipt image enters the app. It carries the entry point, file format, + * and size, so we can later check whether lost receipts lean toward a format like HEIC or PDF, or toward large files. + * Sent right away so it survives a hard app kill. + */ +function logReceiptCaptured({file, captureSource, receiptTraceId}: {file: FileObject; captureSource: ReceiptCaptureSource; receiptTraceId: string}) { + Log.info(`${RECEIPT_LOG_PREFIX} captured`, true, { + event: 'captured', + receiptTraceId, + captureSource, + mimeType: file.type, + fileExtension: file.name?.includes('.') ? file.name.split('.').pop()?.toLowerCase() : undefined, + fileSizeBytes: file.size ?? undefined, + platform: getPlatform(), + }); +} + +/** + * Records the submit milestone and maps the draft transaction id to the final one. This is what joins the capture + * logs to everything downstream, because the id changes from the fixed draft id at submit. + */ +function logReceiptSubmitted({ + receiptTraceId, + draftTransactionID, + transactionID, + command, + iouType, +}: { + receiptTraceId: string | undefined; + draftTransactionID: string; + transactionID: string; + command: string; + iouType: string; +}) { + Log.info(`${RECEIPT_LOG_PREFIX} submitted`, true, { + event: 'submitted', + receiptTraceId, + draftTransactionID, + transactionID, + command, + iouType, + }); +} + +/** + * Records the enqueued milestone, when the receipt upload reaches the write queue. The gap between this and the + * existing network "sent" log is the window where the queue is blocked, which is what we want to see. It records the + * offline state and queue depth so we can tell a normal offline wait apart from a stuck queue. + */ +function logReceiptEnqueued({receiptTraceId, transactionID, command, persistedQueueLength}: ReceiptEnqueuedParams) { + if (transactionID) { + // Re-insert so this key becomes the newest, then drop the oldest entries past the cap. This keeps the map + // bounded even when no snapshot ever runs to drain it. + enqueuedAtByTransactionID.delete(transactionID); + enqueuedAtByTransactionID.set(transactionID, Date.now()); + while (enqueuedAtByTransactionID.size > MAX_TRACKED_ENQUEUE_TIMESTAMPS) { + const oldestTransactionID = enqueuedAtByTransactionID.keys().next().value; + if (oldestTransactionID === undefined) { + break; + } + enqueuedAtByTransactionID.delete(oldestTransactionID); + } + } + + Log.info(`${RECEIPT_LOG_PREFIX} enqueued`, true, { + event: 'enqueued', + receiptTraceId, + transactionID, + command, + isOffline: getIsOffline(), + persistedQueueLength, + }); +} + +/** + * Logs one line per receipt still pending in the write queue, tagged with what triggered the snapshot. Stays quiet + * when nothing is pending, so the normal case makes no noise. Sent right away so it survives a hard app kill from the + * background. + */ +function logReceiptQueueSnapshot(trigger: ReceiptSnapshotTrigger) { + const isOffline = getIsOffline(); + const now = Date.now(); + const pendingTransactionIDs = new Set(); + + // Include the ongoing request. Once processNextRequest moves a receipt into the ongoing slot it is the one + // actively uploading, but it no longer shows up in getAll. Without this we would skip it here and then drop it + // from the timing map in the cleanup below. + const ongoingRequest = getOngoingRequest(); + const requests = ongoingRequest ? [ongoingRequest, ...getAllPersistedRequests()] : getAllPersistedRequests(); + + for (const request of requests) { + if (!RECEIPT_BEARING_COMMANDS.has(request.command)) { + continue; + } + + const data = (request.data ?? {}) as {transactionID?: string; receipt?: {receiptTraceId?: string}}; + // Skip when there is no receipt at data.receipt. SplitBill nests it inside the splits JSON, and SendMoney with + // no attached receipt has no receipt field. A row without a trace id cannot be joined to the capture log, so + // it would only add noise to the snapshot. + if (!data.receipt) { + continue; + } + const transactionID = data.transactionID; + if (transactionID) { + pendingTransactionIDs.add(transactionID); + } + const enqueuedAt = transactionID ? enqueuedAtByTransactionID.get(transactionID) : undefined; + + Log.info(`${RECEIPT_LOG_PREFIX} queue snapshot`, true, { + event: 'snapshot', + trigger, + receiptTraceId: data.receipt.receiptTraceId, + transactionID, + command: request.command, + msSinceEnqueued: enqueuedAt !== undefined ? now - enqueuedAt : undefined, + isOffline, + }); + } + + // Drop timing entries for receipts that already left the queue, so the map only holds pending receipts. + for (const transactionID of enqueuedAtByTransactionID.keys()) { + if (pendingTransactionIDs.has(transactionID)) { + continue; + } + enqueuedAtByTransactionID.delete(transactionID); + } +} + +export {mintAndStampReceiptTraceId, logReceiptCaptured, logReceiptSubmitted, logReceiptEnqueued, logReceiptQueueSnapshot, getPickerCaptureSource, RECEIPT_BEARING_COMMANDS}; +export type {ReceiptCaptureSource}; diff --git a/src/libs/telemetry/forwardLogsToSentry.ts b/src/libs/telemetry/forwardLogsToSentry.ts index b392c518f4aa..b497fbed757e 100644 --- a/src/libs/telemetry/forwardLogsToSentry.ts +++ b/src/libs/telemetry/forwardLogsToSentry.ts @@ -1,7 +1,18 @@ +import type {SeverityLevel} from '@sentry/react-native'; +import type {TupleToUnion} from 'type-fest'; + import * as Sentry from '@sentry/react-native'; type SentryLogLevel = 'debug' | 'info' | 'warn' | 'error'; +/** Maps our log levels onto Sentry breadcrumb severity levels. */ +const SENTRY_BREADCRUMB_LEVEL: Record = { + debug: 'debug', + info: 'info', + warn: 'warning', + error: 'error', +}; + /** * Whitelist of parameter key patterns allowed to be forwarded to Sentry. * Exact strings match the key literally, regexes match against the flattened dot-notation key. @@ -21,7 +32,16 @@ const PARAMETERS_WHITELIST: ReadonlyArray = [ /** * Only log lines whose message contains one of these prefixes are forwarded to Sentry. */ -const FORWARDED_LOG_PREFIXES = ['[Reauthenticate]', '[MFA]', '[OnyxUpdateManagerError]'] as const; +const FORWARDED_LOG_PREFIXES = ['[Reauthenticate]', '[MFA]', '[OnyxUpdateManagerError]', '[Receipt]'] as const; + +type ForwardedLogPrefix = TupleToUnion; + +/** + * Extra parameter keys forwarded only for a given log prefix, on top of PARAMETERS_WHITELIST. A key here is not + * allowed for any other prefix, so a generic key like event cannot leak from an unrelated line. This keeps the + * receipt keys tied to the receipt logs instead of widening the global whitelist. + */ +const PREFIX_SCOPED_PARAMETERS_WHITELIST = new Map>([['[Receipt]', ['receiptTraceId', 'transactionID', 'event']]]); /** * Method deciding whether a log packet should be forwarded to Sentry. @@ -31,8 +51,8 @@ const FORWARDED_LOG_PREFIXES = ['[Reauthenticate]', '[MFA]', '[OnyxUpdateManager * There is no redaction / filtering of sensitive data implemented yet. When you implement any log forwarding logic, make sure that you do not leak any sensitive data. */ -function shouldForwardLog(log: {message?: string; parameters?: Record | undefined}) { - return FORWARDED_LOG_PREFIXES.some((prefix) => log.message?.includes(prefix)); +function getMatchedForwardPrefix(message: string): TupleToUnion | undefined { + return FORWARDED_LOG_PREFIXES.find((prefix) => message.includes(prefix)); } function mapLogMessageToSentryLevel(message: string): SentryLogLevel { @@ -52,12 +72,14 @@ function isPlainObject(value: unknown): value is Record { return typeof value === 'object' && value !== null && !Array.isArray(value); } -function isKeyWhitelisted(key: string): boolean { - return PARAMETERS_WHITELIST.some((pattern) => (typeof pattern === 'string' ? key === pattern : pattern.test(key))); +function isKeyWhitelisted(key: string, prefix: ForwardedLogPrefix): boolean { + const matchesPattern = (pattern: string | RegExp) => (typeof pattern === 'string' ? key === pattern : pattern.test(key)); + const prefixScopedPatterns = PREFIX_SCOPED_PARAMETERS_WHITELIST.get(prefix) ?? []; + return PARAMETERS_WHITELIST.some(matchesPattern) || prefixScopedPatterns.some(matchesPattern); } -function filterWhitelistedParameters(parameters: Record): Record { - return Object.fromEntries(Object.entries(parameters).filter(([key]) => isKeyWhitelisted(key))); +function filterWhitelistedParameters(parameters: Record, prefix: ForwardedLogPrefix): Record { + return Object.fromEntries(Object.entries(parameters).filter(([key]) => isKeyWhitelisted(key, prefix))); } function flattenNestedParameters(parameters: Record, prefix = ''): Record { @@ -75,12 +97,12 @@ function flattenNestedParameters(parameters: Record, prefix = ' return result; } -function prepareParametersForSentry(parameters: Record | undefined): Record | undefined { +function prepareParametersForSentry(parameters: Record | undefined, prefix: ForwardedLogPrefix): Record | undefined { if (!parameters) { return undefined; } - return filterWhitelistedParameters(flattenNestedParameters(parameters)); + return filterWhitelistedParameters(flattenNestedParameters(parameters), prefix); } function forwardLogsToSentry(logPacket: string | undefined) { @@ -88,11 +110,18 @@ function forwardLogsToSentry(logPacket: string | undefined) { return; } - let parsedPacket: Array<{message?: string; parameters?: Record | undefined}> | undefined; + let parsedPacket: + | Array<{ + message?: string; + parameters?: Record | undefined; + }> + | undefined; try { parsedPacket = JSON.parse(logPacket) as typeof parsedPacket; } catch { - Sentry.logger.warn('Failed to parse log packet for Sentry forwarding', {logPacket}); + Sentry.logger.warn('Failed to parse log packet for Sentry forwarding', { + logPacket, + }); return; } @@ -104,21 +133,33 @@ function forwardLogsToSentry(logPacket: string | undefined) { if (!logLine || typeof logLine.message !== 'string') { continue; } - if (!shouldForwardLog(logLine)) { + const prefix = getMatchedForwardPrefix(logLine.message); + if (!prefix) { continue; } + const params = prepareParametersForSentry(logLine.parameters, prefix); const level = mapLogMessageToSentryLevel(logLine.message); const logMethod = Sentry.logger[level]; - if (!logMethod) { - continue; + if (logMethod) { + if (params) { + logMethod(logLine.message, params); + } else { + logMethod(logLine.message); + } } - if (logLine.parameters) { - logMethod(logLine.message, prepareParametersForSentry(logLine.parameters)); - } else { - logMethod(logLine.message); - } + // Mirror the line as a breadcrumb so the trail shows up on any crash or error. The breadcrumb carries the same + // whitelisted keys as the forwarded log, so only opaque ids, never the receipt source, filename, or bytes. You + // can search the trace id by data.receiptTraceId. We avoid Sentry.setTag because tags are global, so the latest + // receipt would overwrite earlier ones and tag unrelated crashes with the wrong id. + Sentry.addBreadcrumb({ + category: prefix.replaceAll(/[[\]]/g, '').toLowerCase(), + type: 'info', + level: SENTRY_BREADCRUMB_LEVEL[level], + message: logLine.message, + data: params, + }); } } diff --git a/src/pages/iou/request/step/IOURequestStepScan/components/ScanFromReport.tsx b/src/pages/iou/request/step/IOURequestStepScan/components/ScanFromReport.tsx index 7ce68bc22297..8b23e8b949b7 100644 --- a/src/pages/iou/request/step/IOURequestStepScan/components/ScanFromReport.tsx +++ b/src/pages/iou/request/step/IOURequestStepScan/components/ScanFromReport.tsx @@ -8,6 +8,8 @@ import useOnyx from '@hooks/useOnyx'; import useOptimisticDraftTransactions from '@hooks/useOptimisticDraftTransactions'; import {navigateToConfirmationPage} from '@libs/IOUUtils'; +import type {ReceiptCaptureSource} from '@libs/telemetry/ReceiptObservability'; +import {getPickerCaptureSource} from '@libs/telemetry/ReceiptObservability'; import type {ReceiptFile} from '@pages/iou/request/step/IOURequestStepScan/types'; import buildReceiptFiles from '@pages/iou/request/step/IOURequestStepScan/utils/buildReceiptFiles'; @@ -61,7 +63,7 @@ function ScanFromReport({report, iouType, reportID, transactionID, transaction, ); }; - const processReceipts = (files: FileObject[]) => { + const processReceipts = (files: FileObject[], captureSource: ReceiptCaptureSource) => { const receiptFiles = buildReceiptFiles({ files, getFileSource, @@ -73,6 +75,7 @@ function ScanFromReport({report, iouType, reportID, transactionID, transaction, isMultiScanEnabled, transactions, draftTransactionIDsToCleanUp: draftTransactionIDs, + captureSource, }); if (receiptFiles.length === 0) { @@ -95,7 +98,7 @@ function ScanFromReport({report, iouType, reportID, transactionID, transaction, }; const {validateFiles, PDFValidationComponent, ErrorModal} = useFilesValidation((files: FileObject[]) => { - processReceipts(files); + processReceipts(files, getPickerCaptureSource()); }); return ( @@ -104,12 +107,12 @@ function ScanFromReport({report, iouType, reportID, transactionID, transaction, { if (isMultiScanEnabled) { - processReceipts([file]); + processReceipts([file], 'camera'); return; } // Pre-warm the thumbnail cache before navigating so the confirm page // doesn't flash an un-thumbnail receipt. - precacheReceiptImage(source).then(() => processReceipts([file])); + precacheReceiptImage(source).then(() => processReceipts([file], 'camera')); }} onPicked={validateFiles} onAttachmentPickerStatusChange={setIsLoaderVisible} diff --git a/src/pages/iou/request/step/IOURequestStepScan/components/ScanGlobalCreate.tsx b/src/pages/iou/request/step/IOURequestStepScan/components/ScanGlobalCreate.tsx index 5f824f6c3bac..cee4ed5dd559 100644 --- a/src/pages/iou/request/step/IOURequestStepScan/components/ScanGlobalCreate.tsx +++ b/src/pages/iou/request/step/IOURequestStepScan/components/ScanGlobalCreate.tsx @@ -7,6 +7,9 @@ import {precacheReceiptImage} from '@hooks/useLocalReceiptThumbnail'; import useOnyx from '@hooks/useOnyx'; import useOptimisticDraftTransactions from '@hooks/useOptimisticDraftTransactions'; +import type {ReceiptCaptureSource} from '@libs/telemetry/ReceiptObservability'; +import {getPickerCaptureSource} from '@libs/telemetry/ReceiptObservability'; + import type {ReceiptFile} from '@pages/iou/request/step/IOURequestStepScan/types'; import buildReceiptFiles from '@pages/iou/request/step/IOURequestStepScan/utils/buildReceiptFiles'; import getFileSource from '@pages/iou/request/step/IOURequestStepScan/utils/getFileSource'; @@ -67,7 +70,7 @@ function ScanGlobalCreateInner({reportID, transactionID, transaction, currentUse useScanFileReadabilityCheck(transactions, draftTransactionIDs ?? [], disableMultiScan); - const processReceipts = (files: FileObject[]) => { + const processReceipts = (files: FileObject[], captureSource: ReceiptCaptureSource) => { const receiptFiles = buildReceiptFiles({ files, getFileSource, @@ -79,6 +82,7 @@ function ScanGlobalCreateInner({reportID, transactionID, transaction, currentUse isMultiScanEnabled, transactions, draftTransactionIDsToCleanUp: draftTransactionIDs, + captureSource, }); if (receiptFiles.length === 0) { @@ -104,7 +108,7 @@ function ScanGlobalCreateInner({reportID, transactionID, transaction, currentUse }; const {validateFiles, PDFValidationComponent, ErrorModal} = useFilesValidation((files: FileObject[]) => { - processReceipts(files); + processReceipts(files, getPickerCaptureSource()); }); return ( @@ -113,12 +117,12 @@ function ScanGlobalCreateInner({reportID, transactionID, transaction, currentUse { if (isMultiScanEnabled) { - processReceipts([file]); + processReceipts([file], 'camera'); return; } // Pre-warm the thumbnail cache before navigating so the confirm page // doesn't flash an un-thumbnail receipt. - precacheReceiptImage(source).then(() => processReceipts([file])); + precacheReceiptImage(source).then(() => processReceipts([file], 'camera')); }} onPicked={validateFiles} onAttachmentPickerStatusChange={setIsLoaderVisible} diff --git a/src/pages/iou/request/step/IOURequestStepScan/components/ScanSkipConfirmation.tsx b/src/pages/iou/request/step/IOURequestStepScan/components/ScanSkipConfirmation.tsx index f6789b4c8f99..7a8594820951 100644 --- a/src/pages/iou/request/step/IOURequestStepScan/components/ScanSkipConfirmation.tsx +++ b/src/pages/iou/request/step/IOURequestStepScan/components/ScanSkipConfirmation.tsx @@ -26,6 +26,8 @@ import {submitWithDismissFirst} from '@libs/Navigation/helpers/submitWithDismiss import {rand64} from '@libs/NumberUtils'; import {isMoneyRequestReport} from '@libs/ReportUtils'; import {cancelSpan} from '@libs/telemetry/activeSpans'; +import type {ReceiptCaptureSource} from '@libs/telemetry/ReceiptObservability'; +import {getPickerCaptureSource} from '@libs/telemetry/ReceiptObservability'; import {getDefaultTaxCode, getIsFromGlobalCreate, getTaxValue} from '@libs/TransactionUtils'; import {getLocationPermission} from '@pages/iou/request/step/IOURequestStepScan/LocationPermission'; @@ -344,7 +346,7 @@ function ScanSkipConfirmation({report, action, iouType, reportID, transactionID, submitDirectly(files, false); }; - const processReceipts = (files: FileObject[]) => { + const processReceipts = (files: FileObject[], captureSource: ReceiptCaptureSource) => { const newReceiptFiles = buildReceiptFiles({ files, getFileSource, @@ -355,6 +357,7 @@ function ScanSkipConfirmation({report, action, iouType, reportID, transactionID, shouldAcceptMultipleFiles: true, isMultiScanEnabled, transactions, + captureSource, }); if (newReceiptFiles.length === 0) { @@ -380,7 +383,7 @@ function ScanSkipConfirmation({report, action, iouType, reportID, transactionID, }; const {validateFiles, PDFValidationComponent, ErrorModal} = useFilesValidation((files: FileObject[]) => { - processReceipts(files); + processReceipts(files, getPickerCaptureSource()); }); return ( @@ -388,7 +391,7 @@ function ScanSkipConfirmation({report, action, iouType, reportID, transactionID, {PDFValidationComponent} { - processReceipts([file]); + processReceipts([file], 'camera'); }} onPicked={validateFiles} onAttachmentPickerStatusChange={setIsLoaderVisible} diff --git a/src/pages/iou/request/step/IOURequestStepScan/utils/buildReceiptFiles.ts b/src/pages/iou/request/step/IOURequestStepScan/utils/buildReceiptFiles.ts index f256e1bff6f9..a9689a1fb4c2 100644 --- a/src/pages/iou/request/step/IOURequestStepScan/utils/buildReceiptFiles.ts +++ b/src/pages/iou/request/step/IOURequestStepScan/utils/buildReceiptFiles.ts @@ -1,3 +1,5 @@ +import type {ReceiptCaptureSource} from '@libs/telemetry/ReceiptObservability'; +import {logReceiptCaptured, mintAndStampReceiptTraceId} from '@libs/telemetry/ReceiptObservability'; import {shouldReuseInitialTransaction} from '@libs/TransactionUtils'; import type {ReceiptFile} from '@pages/iou/request/step/IOURequestStepScan/types'; @@ -26,6 +28,9 @@ type BuildReceiptFilesParams = { * IDs of stale draft transactions to wipe before building new ones. */ draftTransactionIDsToCleanUp?: string[]; + + /** How the receipt entered the app, recorded on the capture log. */ + captureSource?: ReceiptCaptureSource; }; /** @@ -44,6 +49,7 @@ function buildReceiptFiles({ isMultiScanEnabled, transactions, draftTransactionIDsToCleanUp, + captureSource = 'file', }: BuildReceiptFilesParams): ReceiptFile[] { if (files.length === 0) { return []; @@ -66,8 +72,10 @@ function buildReceiptFiles({ }); const transactionID = transaction?.transactionID ?? initialTransactionID; + const receiptTraceId = mintAndStampReceiptTraceId(file); + logReceiptCaptured({file, captureSource, receiptTraceId}); receiptFiles.push({file, source, transactionID}); - setMoneyRequestReceipt(transactionID, source, file.name ?? '', true, file.type); + setMoneyRequestReceipt(transactionID, source, file.name ?? '', true, file.type, false, false, undefined, receiptTraceId); } return receiptFiles; diff --git a/src/pages/iou/request/step/confirmation/ReceiptFileValidator.tsx b/src/pages/iou/request/step/confirmation/ReceiptFileValidator.tsx index f68b1e146d8b..d460236f024a 100644 --- a/src/pages/iou/request/step/confirmation/ReceiptFileValidator.tsx +++ b/src/pages/iou/request/step/confirmation/ReceiptFileValidator.tsx @@ -88,6 +88,9 @@ function ReceiptFileValidator({ const onSuccess = (file: File) => { const receipt: Receipt = file; + // Rebuilding the receipt from disk makes a fresh File without the trace id from capture, so copy it + // back from the saved draft. This keeps the capture, submit, and enqueue logs tied to one receipt. + receipt.receiptTraceId = item.receipt?.receiptTraceId; if (item?.receipt?.isTestReceipt) { receipt.isTestReceipt = true; receipt.state = CONST.IOU.RECEIPT_STATE.SCAN_COMPLETE; diff --git a/src/types/onyx/Transaction.ts b/src/types/onyx/Transaction.ts index 66a92ec097fb..997fe0c894a1 100644 --- a/src/types/onyx/Transaction.ts +++ b/src/types/onyx/Transaction.ts @@ -263,6 +263,9 @@ type Receipt = { /** Local thumbnail URI for fast preview on confirmation page */ thumbnail?: string; + + /** Correlation id created at capture, used to follow this receipt from capture to upload in the logs. */ + receiptTraceId?: string; }; /** Model of route */ diff --git a/src/types/utils/Attachment.ts b/src/types/utils/Attachment.ts index c67547ca21e2..7cc0955bb5c2 100644 --- a/src/types/utils/Attachment.ts +++ b/src/types/utils/Attachment.ts @@ -7,6 +7,6 @@ type ImagePickerResponse = { width?: number; }; -type FileObject = Partial & {getAsFile?: () => File | null; lastModified?: number}; +type FileObject = Partial & {getAsFile?: () => File | null; lastModified?: number; receiptTraceId?: string}; export type {FileObject, ImagePickerResponse}; diff --git a/tests/actions/IOU/RequestMoneyTest.ts b/tests/actions/IOU/RequestMoneyTest.ts index 778a980f4816..050ec1430bd1 100644 --- a/tests/actions/IOU/RequestMoneyTest.ts +++ b/tests/actions/IOU/RequestMoneyTest.ts @@ -8,10 +8,12 @@ import deleteReport from '@libs/actions/Report/DeleteReport'; import {subscribeToUserEvents} from '@libs/actions/User'; import type {ApiCommand} from '@libs/API/types'; import {WRITE_COMMANDS} from '@libs/API/types'; +import * as IsFileUploadable from '@libs/isFileUploadable'; import Navigation from '@libs/Navigation/Navigation'; import {rand64} from '@libs/NumberUtils'; import type * as PolicyUtils from '@libs/PolicyUtils'; import {getAllReportActions, getIOUActionForReportID, getOriginalMessage, isActionableTrackExpense, isMoneyRequestAction} from '@libs/ReportActionsUtils'; +import {mintAndStampReceiptTraceId} from '@libs/telemetry/ReceiptObservability'; import type {IOUAction} from '@src/CONST'; import CONST from '@src/CONST'; @@ -28,6 +30,7 @@ import type {Participant} from '@src/types/onyx/Report'; import type ReportAction from '@src/types/onyx/ReportAction'; import type {ReportActions} from '@src/types/onyx/ReportAction'; import type Transaction from '@src/types/onyx/Transaction'; +import type {Receipt} from '@src/types/onyx/Transaction'; import {isEmptyObject} from '@src/types/utils/EmptyObject'; import type {OnyxCollection, OnyxEntry} from 'react-native-onyx'; @@ -2437,6 +2440,60 @@ describe('actions/IOU', () => { } }); + it('propagates the capture-time receiptTraceId into the final request params', async () => { + // jsdom and the lib module disagree on the `Blob` constructor identity, so a real File is + // gated out by isFileUploadable in tests. Force it through to exercise the receipt pass-through. + const isFileUploadableSpy = jest.spyOn(IsFileUploadable, 'default').mockReturnValue(true); + + // Given a receipt file stamped with a trace id at capture time + const receipt: Receipt = new File(['receipt-bytes'], 'receipt.png', { + type: 'image/png', + }); + receipt.source = 'file://receipt.png'; + const traceId = mintAndStampReceiptTraceId(receipt); + + // When the expense is submitted + requestMoney({ + report: {reportID: ''}, + participantParams: { + payeeEmail: RORY_EMAIL, + payeeAccountID: RORY_ACCOUNT_ID, + participant: {login: CARLOS_EMAIL, accountID: CARLOS_ACCOUNT_ID}, + }, + transactionParams: { + amount: 10000, + attendees: [], + currency: CONST.CURRENCY.USD, + created: '', + merchant: 'KFC', + comment: '', + receipt, + }, + shouldGenerateTransactionThreadReport: true, + isASAPSubmitBetaEnabled: false, + currentUserAccountIDParam: RORY_ACCOUNT_ID, + currentUserEmailParam: RORY_EMAIL, + transactionViolations: {}, + policyRecentlyUsedCurrencies: [], + existingTransactionDraft: undefined, + draftTransactionIDs: [], + isSelfTourViewed: false, + quickAction: undefined, + betas: [CONST.BETAS.ALL], + personalDetails: {}, + }); + + await waitForBatchedUpdates(); + + // Then the trace id minted at capture reaches the final request receipt params + expect(writeSpy).toHaveBeenCalledTimes(1); + const [command, params] = writeSpy.mock.calls.at(0); + expect(command).toBe(WRITE_COMMANDS.REQUEST_MONEY); + expect(JSON.stringify(params)).toContain(traceId); + + isFileUploadableSpy.mockRestore(); + }); + it('adds grouped from snapshot optimistic data for grouped search queries', async () => { const currentSearchQueryJSON = { type: CONST.SEARCH.DATA_TYPES.EXPENSE, diff --git a/tests/unit/ReceiptObservabilityTest.ts b/tests/unit/ReceiptObservabilityTest.ts new file mode 100644 index 000000000000..c780829b879f --- /dev/null +++ b/tests/unit/ReceiptObservabilityTest.ts @@ -0,0 +1,178 @@ +import * as PersistedRequests from '@libs/actions/PersistedRequests'; +import {WRITE_COMMANDS} from '@libs/API/types'; +import Log from '@libs/Log'; +import {logReceiptCaptured, logReceiptQueueSnapshot, mintAndStampReceiptTraceId} from '@libs/telemetry/ReceiptObservability'; + +import type {FileObject} from '@src/types/utils/Attachment'; + +type CapturedLogLine = {message: string; sendNow?: boolean; params: Record}; + +const receiptRequest = (transactionID: string, receiptTraceId: string) => ({ + command: WRITE_COMMANDS.REQUEST_MONEY, + data: {transactionID, receipt: {source: `file://${transactionID}.png`, receiptTraceId}}, +}); + +const nonReceiptRequest = {command: WRITE_COMMANDS.OPEN_REPORT, data: {reportID: '99'}}; + +describe('ReceiptObservability', () => { + let logLines: CapturedLogLine[]; + let logInfoSpy: jest.SpyInstance>; + + beforeEach(() => { + logLines = []; + // Capture each emitted log line into a typed list so assertions never have to cast `mock.calls`. + logInfoSpy = jest.spyOn(Log, 'info').mockImplementation((message, sendNow, params) => { + if (!params || typeof params !== 'object' || Array.isArray(params) || params instanceof Error) { + return; + } + logLines.push({message, sendNow, params}); + }); + }); + + afterEach(() => { + logInfoSpy.mockRestore(); + }); + + describe('mintAndStampReceiptTraceId', () => { + it('stamps an id that survives JSON serialization without leaking the image bytes', () => { + // Given a captured receipt file carrying a large amount of image data + const file: FileObject = new File(['x'.repeat(100_000)], 'receipt.png', {type: 'image/png'}); + + // When we mint and stamp a trace id at capture time + const traceId = mintAndStampReceiptTraceId(file); + + // Then the id is a non-empty, opaque string stamped on the file object + expect(traceId).toBeTruthy(); + expect(file.receiptTraceId).toBe(traceId); + + // And it survives the JSON serialization used to persist the request (the correlation spine reaches the + // persisted request), while the raw image bytes never serialize into the payload (no base64 bloat). + const serialized = JSON.stringify(file); + expect(serialized).toContain(traceId); + expect(serialized.length).toBeLessThan(1_000); + }); + }); + + describe('logReceiptCaptured', () => { + it('logs a [Receipt] captured line carrying the entry point and file metadata', () => { + // Given a captured HEIC file from the camera + const file: FileObject = new File(['x'.repeat(2048)], 'photo.HEIC', {type: 'image/heic'}); + + // When we record the capture milestone + logReceiptCaptured({file, captureSource: 'camera', receiptTraceId: 'trace-X'}); + + // Then a [Receipt] captured line is emitted immediately, carrying the correlation id and file metadata + const captured = logLines.find((line) => line.params.event === 'captured'); + expect(captured?.message).toContain('[Receipt]'); + expect(captured?.sendNow).toBe(true); + expect(captured?.params).toMatchObject({ + event: 'captured', + receiptTraceId: 'trace-X', + captureSource: 'camera', + mimeType: 'image/heic', + fileExtension: 'heic', + fileSizeBytes: 2048, + }); + }); + }); + + describe('logReceiptQueueSnapshot', () => { + let getAllSpy: jest.SpyInstance; + let getOngoingRequestSpy: jest.SpyInstance; + + beforeEach(() => { + getAllSpy = jest.spyOn(PersistedRequests, 'getAll').mockReturnValue([]); + getOngoingRequestSpy = jest.spyOn(PersistedRequests, 'getOngoingRequest').mockReturnValue(null); + }); + + afterEach(() => { + getAllSpy.mockRestore(); + getOngoingRequestSpy.mockRestore(); + }); + + it('emits one [Receipt] snapshot line per pending receipt and skips non-receipt requests', () => { + // Given a queue holding two receipt-bearing requests and one unrelated request + getAllSpy.mockReturnValue([receiptRequest('100', 'trace-A'), nonReceiptRequest, receiptRequest('200', 'trace-B')]); + + // When we snapshot the queue at a lifecycle boundary + logReceiptQueueSnapshot('background'); + + // Then exactly one snapshot line is emitted per pending receipt, none for the unrelated request + const snapshots = logLines.filter((line) => line.params.event === 'snapshot'); + expect(snapshots).toHaveLength(2); + + // And each line carries the [Receipt] prefix, is sent immediately, and identifies the receipt + for (const snapshot of snapshots) { + expect(snapshot.message).toContain('[Receipt]'); + expect(snapshot.sendNow).toBe(true); + expect(snapshot.params.trigger).toBe('background'); + expect(snapshot.params.command).toBe(WRITE_COMMANDS.REQUEST_MONEY); + } + expect(snapshots.map((snapshot) => snapshot.params.receiptTraceId)).toEqual(expect.arrayContaining(['trace-A', 'trace-B'])); + expect(snapshots.map((snapshot) => snapshot.params.transactionID)).toEqual(expect.arrayContaining(['100', '200'])); + }); + + it('emits nothing when no receipt-bearing request is pending', () => { + // Given a queue with no receipt-bearing requests + getAllSpy.mockReturnValue([nonReceiptRequest]); + + // When we snapshot the queue + logReceiptQueueSnapshot('signOut'); + + // Then no snapshot line is emitted (zero noise in the common case) + expect(logLines.filter((line) => line.params.event === 'snapshot')).toHaveLength(0); + }); + + it.each([ + WRITE_COMMANDS.SPLIT_BILL, + WRITE_COMMANDS.SPLIT_BILL_AND_OPEN_REPORT, + WRITE_COMMANDS.COMPLETE_SPLIT_BILL, + WRITE_COMMANDS.SEND_MONEY_ELSEWHERE, + WRITE_COMMANDS.SEND_MONEY_WITH_WALLET, + WRITE_COMMANDS.CATEGORIZE_TRACKED_EXPENSE, + WRITE_COMMANDS.SHARE_TRACKED_EXPENSE, + ])('includes %s in the receipt-bearing set', (command) => { + // Given a queued request for a receipt-bearing command outside the original 4-command allow-list + getAllSpy.mockReturnValue([{command, data: {transactionID: '300', receipt: {source: 'file://300.png', receiptTraceId: 'trace-C'}}}]); + + // When we snapshot the queue + logReceiptQueueSnapshot('background'); + + // Then a snapshot line is emitted for it (without the expansion the receipt would be silently dropped) + const snapshots = logLines.filter((line) => line.params.event === 'snapshot'); + expect(snapshots).toHaveLength(1); + expect(snapshots.at(0)?.params).toMatchObject({command, transactionID: '300', receiptTraceId: 'trace-C'}); + }); + + it('skips receipt-bearing commands whose data.receipt is missing (e.g. SplitBill, SendMoney without receipt)', () => { + // Given a receipt-bearing command queued WITHOUT a top-level data.receipt — SplitBill nests it in the splits + // JSON; SendMoney can be issued with no receipt at all. A snapshot row with no trace id is not joinable to + // the capture log and would only add noise. + getAllSpy.mockReturnValue([ + {command: WRITE_COMMANDS.SPLIT_BILL, data: {transactionID: '500', splits: '[...]'}}, + {command: WRITE_COMMANDS.SEND_MONEY_WITH_WALLET, data: {transactionID: '501'}}, + ]); + + // When we snapshot the queue + logReceiptQueueSnapshot('background'); + + // Then no snapshot line is emitted — non-correlatable rows are filtered out + expect(logLines.filter((line) => line.params.event === 'snapshot')).toHaveLength(0); + }); + + it('includes the receipt promoted to the ongoing request slot', () => { + // Given one receipt uploading in the ongoing slot and another still waiting in the queue + getOngoingRequestSpy.mockReturnValue(receiptRequest('100', 'trace-A')); + getAllSpy.mockReturnValue([receiptRequest('200', 'trace-B')]); + + // When we snapshot the queue at sign-out + logReceiptQueueSnapshot('signOut'); + + // Then the uploading receipt is captured alongside the queued one + const snapshots = logLines.filter((line) => line.params.event === 'snapshot'); + expect(snapshots).toHaveLength(2); + expect(snapshots.map((snapshot) => snapshot.params.receiptTraceId)).toEqual(expect.arrayContaining(['trace-A', 'trace-B'])); + expect(snapshots.map((snapshot) => snapshot.params.transactionID)).toEqual(expect.arrayContaining(['100', '200'])); + }); + }); +}); diff --git a/tests/unit/forwardLogsToSentryTest.ts b/tests/unit/forwardLogsToSentryTest.ts new file mode 100644 index 000000000000..a132f5410252 --- /dev/null +++ b/tests/unit/forwardLogsToSentryTest.ts @@ -0,0 +1,74 @@ +import forwardLogsToSentry from '@libs/telemetry/forwardLogsToSentry'; + +import * as Sentry from '@sentry/react-native'; + +jest.mock('@sentry/react-native', () => ({ + logger: {debug: jest.fn(), info: jest.fn(), warn: jest.fn(), error: jest.fn()}, + addBreadcrumb: jest.fn(), +})); + +const packetWith = (message: string, parameters: Record) => JSON.stringify([{message, parameters}]); + +describe('forwardLogsToSentry', () => { + afterEach(() => { + jest.clearAllMocks(); + }); + + it('adds a breadcrumb carrying the receipt trail so a crash report shows it, with only whitelisted params', () => { + // Given a forwarded [Receipt] log line carrying opaque ids alongside non-whitelisted file metadata + const packet = packetWith('[info] [Receipt] enqueued', { + event: 'enqueued', + receiptTraceId: 'trace-Z', + transactionID: '42', + command: 'RequestMoney', + source: 'file://secret.png', + fileSizeBytes: 999, + }); + + // When the packet is mirrored to Sentry + forwardLogsToSentry(packet); + + // Then a receipt breadcrumb is recorded carrying the correlation ids... + expect(Sentry.addBreadcrumb).toHaveBeenCalledWith( + expect.objectContaining({ + category: 'receipt', + message: '[info] [Receipt] enqueued', + data: expect.objectContaining({event: 'enqueued', receiptTraceId: 'trace-Z', transactionID: '42', command: 'RequestMoney'}), + }), + ); + + // ...but never the receipt source or other non-whitelisted fields + const breadcrumb = jest.mocked(Sentry.addBreadcrumb).mock.calls.at(0)?.[0]; + expect(breadcrumb?.data).not.toHaveProperty('source'); + expect(breadcrumb?.data).not.toHaveProperty('fileSizeBytes'); + }); + + it('does not forward the receipt-scoped params (event/transactionID) for a different prefix', () => { + // Given a [Reauthenticate] line that happens to carry generic `event`/`transactionID` params + const packet = packetWith('[info] [Reauthenticate] refreshing token', { + event: 'something-unrelated', + transactionID: 'should-not-leak', + command: 'Reauthenticate', + }); + + // When the packet is mirrored to Sentry + forwardLogsToSentry(packet); + + // Then the globally whitelisted key is forwarded, but the receipt-scoped keys are not + const breadcrumb = jest.mocked(Sentry.addBreadcrumb).mock.calls.at(0)?.[0]; + expect(breadcrumb?.data).toEqual(expect.objectContaining({command: 'Reauthenticate'})); + expect(breadcrumb?.data).not.toHaveProperty('event'); + expect(breadcrumb?.data).not.toHaveProperty('transactionID'); + }); + + it('does not add a breadcrumb for log lines that are not forwarded', () => { + // Given a log line without a forwarded prefix + const packet = packetWith('[info] [SequentialQueue] push() called', {command: 'OpenReport'}); + + // When the packet is processed + forwardLogsToSentry(packet); + + // Then nothing is mirrored to Sentry + expect(Sentry.addBreadcrumb).not.toHaveBeenCalled(); + }); +});