From a1b312c1f1b9522bb725459455f64cf9f169c4d7 Mon Sep 17 00:00:00 2001 From: TaprootFreak <142087526+TaprootFreak@users.noreply.github.com> Date: Sat, 1 Aug 2026 14:03:20 +0200 Subject: [PATCH] feat(payout): log amount, asset and chain per escalated payout order (#4568) * feat(payout): log amount, asset and chain per escalated payout order `logFailedOrders` wrote a single collecting line for the whole batch, carrying only order id, context and correlation id. Two consequences: judging an escalation always required a DB lookup for what was actually at stake, and log-based monitoring could only ever extract one order per line - a batch of seven escalations (as happened on 2026-07-24) surfaced exactly one of them, because a regexp matches a line once. Write one line per escalated order in addition to the collecting line, carrying the payout amount, its asset and the chain the payout was going out on. The collecting line is unchanged: it is also the body of the escalation mail. The wording is a parsing contract - every field is fenced by a literal on both sides so a value containing a space or a comma cannot swallow the next one - and a new spec pins the shape, including the nullable asset relation degrading to a placeholder rather than to an unparsable line. * docs(payout): name the mail path precisely in the escalation log comment * fix(payout): quote the asset name in the escalation line and cover the fence cases Review follow-up on the parsing contract, two gaps: The asset name is the only free-form value in the line. Fenced only by ` of ` and ` on chain `, a name that happened to contain " on chain " would have ended the asset field early and handed the parser a wrong chain - with no parse error at all. A silently wrong value in a critical alert is worse than a loud failure, so the name is now quoted; the only name that can still break parsing is one containing an apostrophe, and that breaks visibly. `?? 'unknown'` also did not cover an empty name: it only catches null/undefined, so `name: ''` would have produced an unparsable line - exactly what the fallback exists to prevent. Now `||`. Two tests added for the cases that were missing: an empty asset name, and a name carrying the fence wording. * test(payout): pin the apostrophe case as the accepted limit of the quoting The service comment claims that an apostrophe in the asset name breaks the line visibly rather than mis-parsing it. That was prose only: nothing failed if a future change to the escaping turned it back into a partial match with a wrong chain. Now it is a test. * test(payout): give the batch case distinct chains and assets The multi-order test used the same asset and chain for both orders and only checked the id per line, so it could not have caught fields being mixed up between orders in a batch - which is the one place where that could happen. Now the two orders differ in amount, asset and chain, and every field is matched against the line of its own order. * fix(payout): read the asset name greedily - quoting alone can be forged Review follow-up. The claim that an apostrophe in the asset name always breaks parsing visibly was wrong. Read lazily, the field ends at the first quote INSIDE the name, so a name like `Foo' on chain Ethereum` closes its own field and then imitates the next fence: the pattern matches happily and yields a WRONG chain, with no error at all - precisely the silent failure the quoting was meant to prevent. The fix belongs on the reading side. The pinned contract now reads the name greedily, up to the LAST `' on chain ` before `, context`. That fence is always the one this service wrote, so no value inside the name can forge it. Two consequences for the tests: the apostrophe case is no longer an accepted casualty but parses correctly, and the adversarial name that imitates the fence is pinned as its own case. * fix(payout): JSON-encode the free-form fields instead of fencing them with a quote Third round on the same defect, so this time the approach goes rather than the symptom. A plain quote around a free-form value is forgeable in BOTH reading directions, and the two previous attempts each closed one and opened the other: - read up to the FIRST quote, a name like `Foo" on chain Ethereum` closes its own field and imitates the next fence -> wrong chain, no error; - read up to the LAST one, a later free-form field offers a competing fence. `correlationId` is a plain string column, so `129680" on chain FAKE, context FAKE, correlation "x` does exactly that -> wrong chain, no error, and this one is reachable through the admin manual-payout path, where the id is only `@IsString()`. Both were measured, not argued. Neither reading is safe, because the ambiguity is in the format, not in the quantifier: the closing quote is not identifiable as long as the value may contain one. The free-form values are now JSON-encoded and read as JSON strings, with `(?:[^"\\]|\\.)*` skipping escape pairs. A quote inside a value arrives escaped, so the closing quote is unambiguous whatever the value contains. Verified for: apostrophe, embedded quote plus a forged fence, a correlation id carrying a full forged tail, backslash, empty name. * style(payout): apply Prettier formatting to the escalation spec The Format check step in CI is stricter than eslint, which is what I had run locally. * test(payout): pin the backslash case and fix three comments left from the quote-fence version Two review follow-ups. The commit that introduced JSON encoding claimed the backslash case as verified, but nothing pinned it. A trailing backslash is exactly what lets a forged quote slip past a reader that does not track escape pairs, because `\"` then looks like an escaped quote when it is really an escaped backslash followed by the real closing one. Both free-form fields now carry one in the tests. Three explanatory comments still illustrated the forgery with an apostrophe. The fence is a double quote since the switch to JSON encoding, so the examples described an escape character that no longer plays any role. * test(payout): pin backslash parity, not just the presence of a backslash The single backslash case was not enough to hold the escape mechanism. An encoder that doubles only the FIRST backslash of a value - a `replace` without the global flag, an entirely ordinary mistake - passes all twelve existing tests while leaving the line forgeable: with two backslashes ahead of an embedded quote it emits an odd number of them, the quote then reads as unescaped, and the chain comes back as `Ethereum" on chain Tron` instead of `Tron`. Verified by mutation rather than by argument: with that encoder patched in, the new test is the only one of the thirteen that fails; the service file was restored afterwards and is unchanged. * test(payout): pin that a newline in a value cannot split the record The escaping has to cover control characters, not just quote and backslash - and this is where getting it wrong stops being a parsing problem. A newline inside a value splits the record into two physical lines, and because the payload can spell out a complete second escalation, the log would carry a fully invented order with a freely chosen chain and amount. That is a forged record, not a mis-read field. `JSON.stringify` already prevents it, but nothing pinned it: an encoder that escapes quote and backslash correctly and globally, yet leaves control characters alone, passed all thirteen tests. Verified by mutation - with that encoder patched in, the new test is the only one of fourteen that fails; the service file was restored afterwards and is unchanged. --- .../__tests__/payout-log.service.spec.ts | 276 ++++++++++++++++++ .../payout/services/payout-log.service.ts | 29 +- 2 files changed, 304 insertions(+), 1 deletion(-) create mode 100644 src/subdomains/supporting/payout/services/__tests__/payout-log.service.spec.ts diff --git a/src/subdomains/supporting/payout/services/__tests__/payout-log.service.spec.ts b/src/subdomains/supporting/payout/services/__tests__/payout-log.service.spec.ts new file mode 100644 index 0000000000..58e03861e8 --- /dev/null +++ b/src/subdomains/supporting/payout/services/__tests__/payout-log.service.spec.ts @@ -0,0 +1,276 @@ +import { Blockchain } from 'src/integration/blockchain/shared/enums/blockchain.enum'; +import { createCustomAsset } from 'src/shared/models/asset/__mocks__/asset.entity.mock'; +import { DfxLogger } from 'src/shared/services/dfx-logger'; +import { createCustomPayoutOrder } from '../../entities/__mocks__/payout-order.entity.mock'; +import { PayoutOrderContext } from '../../entities/payout-order.entity'; +import { PayoutLogService } from '../payout-log.service'; + +// The shape log-based monitoring extracts from the per-order escalation line. Pinned here so a reworded log line +// fails in CI instead of silently reducing the escalation alert to a bare order count. +// +// The free-form fields are read as JSON strings, with `(?:[^"\\]|\\.)*` skipping escape pairs. That is what makes the +// closing quote unambiguous: a plain-quote fence is forgeable whichever way it is read - up to the FIRST quote, a name +// like `Foo" on chain Ethereum` closes its own field and imitates the next fence; up to the LAST one, a later +// free-form field can offer a competing fence. Both yield a wrong chain with no parse error. The adversarial tests +// below pin exactly those two attempts. +const ESCALATION_PATTERN = + /Payout order (?[0-9]+) escalated to PayoutUncertain: amount (?[^ ]+) of "(?(?:[^"\\]|\\.)*)" on chain (?[^,]+), context (?[^,]+), correlation "(?(?:[^"\\]|\\.)*)"$/; + +// The values come back JSON-encoded; decode before comparing to the entity value. +const decode = (v: string): string => JSON.parse(`"${v}"`); + +describe('PayoutLogService', () => { + describe('#logFailedOrders(...)', () => { + let service: PayoutLogService; + let errorSpy: jest.SpyInstance; + + beforeEach(() => { + service = new PayoutLogService(); + errorSpy = jest.spyOn(DfxLogger.prototype, 'error').mockImplementation(); + }); + + afterEach(() => { + jest.restoreAllMocks(); + }); + + const escalationLines = (): string[] => + errorSpy.mock.calls.map((c) => c[0] as string).filter((m) => m.includes('escalated to PayoutUncertain')); + + it('logs nothing for an empty batch', () => { + const message = service.logFailedOrders([]); + + expect(errorSpy).not.toHaveBeenCalled(); + expect(message).toContain('0 payout order(s) failed and pending investigation'); + }); + + it('keeps the summary line and its return value unchanged', () => { + const order = createCustomPayoutOrder({ id: 113108, correlationId: '129680' }); + + const message = service.logFailedOrders([order]); + + expect(message).toBe( + '1 payout order(s) failed and pending investigation: [Order ID: 113108, Context: BuyCrypto, CorrelationID: 129680] ', + ); + expect(errorSpy).toHaveBeenCalledWith(message); + }); + + // Different chains and assets in one batch on purpose: a batch is exactly where fields could get mixed up + // between orders, and every value has to stay with the line of its own order. + it('logs one parsable escalation line per order in addition to the summary', () => { + const orders = [ + createCustomPayoutOrder({ + id: 113108, + correlationId: '129680', + amount: 0.31000703, + asset: createCustomAsset({ name: 'XMR' }), + chain: Blockchain.MONERO, + }), + createCustomPayoutOrder({ + id: 113109, + correlationId: '129672', + amount: 329.67763343, + asset: createCustomAsset({ name: 'USDT' }), + chain: Blockchain.TRON, + }), + ]; + + service.logFailedOrders(orders); + + const lines = escalationLines(); + expect(lines).toHaveLength(2); + expect(errorSpy).toHaveBeenCalledTimes(3); + expect(lines.map((l) => ESCALATION_PATTERN.exec(l)?.groups)).toMatchObject([ + { order: '113108', amount: '0.31000703', asset: 'XMR', chain: 'Monero', correlation: '129680' }, + { order: '113109', amount: '329.67763343', asset: 'USDT', chain: 'Tron', correlation: '129672' }, + ]); + }); + + it('exposes amount, asset and chain of the payout', () => { + const order = createCustomPayoutOrder({ + id: 113107, + amount: 1.53111317, + asset: createCustomAsset({ name: 'XMR', blockchain: Blockchain.MONERO }), + chain: Blockchain.MONERO, + context: PayoutOrderContext.BUY_CRYPTO, + correlationId: '129674', + }); + + service.logFailedOrders([order]); + + const groups = ESCALATION_PATTERN.exec(escalationLines()[0])?.groups; + expect(groups).toMatchObject({ + order: '113107', + amount: '1.53111317', + asset: 'XMR', + chain: 'Monero', + context: 'BuyCrypto', + correlation: '129674', + }); + }); + + // The asset relation is nullable on the entity, and a line that stops matching would drop the order out of the + // alert entirely - it has to degrade to a placeholder, not to an unparsable line. + it('stays parsable when the order carries no asset', () => { + const order = createCustomPayoutOrder({ id: 42, asset: null, chain: Blockchain.BITCOIN, amount: 0.5 }); + + service.logFailedOrders([order]); + + const groups = ESCALATION_PATTERN.exec(escalationLines()[0])?.groups; + expect(groups).toMatchObject({ order: '42', amount: '0.5', asset: 'unknown', chain: 'Bitcoin' }); + }); + + // An empty name has to reach the same placeholder as a missing relation: it would otherwise encode to "" and read + // back as an empty asset rather than as a name, so `??` would not be enough here. + it('falls back to the placeholder when the asset name is empty', () => { + const order = createCustomPayoutOrder({ id: 44, asset: createCustomAsset({ name: '' }) }); + + service.logFailedOrders([order]); + + expect(ESCALATION_PATTERN.exec(escalationLines()[0])?.groups).toMatchObject({ asset: 'unknown' }); + }); + + // A value carrying a space must not shift the following field. + it('keeps the fields separated when a value contains a space', () => { + const order = createCustomPayoutOrder({ + id: 43, + asset: createCustomAsset({ name: 'Wrapped BTC' }), + chain: Blockchain.ETHEREUM, + }); + + service.logFailedOrders([order]); + + const groups = ESCALATION_PATTERN.exec(escalationLines()[0])?.groups; + expect(groups).toMatchObject({ asset: 'Wrapped BTC', chain: 'Ethereum' }); + }); + + it('reads an asset name containing an apostrophe correctly', () => { + const order = createCustomPayoutOrder({ + id: 46, + asset: createCustomAsset({ name: "O'Brien Token" }), + chain: Blockchain.ETHEREUM, + }); + + service.logFailedOrders([order]); + + expect(ESCALATION_PATTERN.exec(escalationLines()[0])?.groups).toMatchObject({ + asset: "O'Brien Token", + chain: 'Ethereum', + }); + }); + + // First of the two forgery attempts a plain-quote fence cannot survive: the name closes its own field and then + // imitates the chain fence. Read up to the first quote, this yields chain=`Ethereum" on chain Tron` - wrong, and + // silently so. The chain must still come out as Tron. + it('cannot be tricked by an asset name that imitates the chain fence', () => { + const order = createCustomPayoutOrder({ + id: 47, + asset: createCustomAsset({ name: 'Foo" on chain Ethereum' }), + chain: Blockchain.TRON, + }); + + service.logFailedOrders([order]); + + const groups = ESCALATION_PATTERN.exec(escalationLines()[0])?.groups; + expect(decode(groups.asset)).toBe('Foo" on chain Ethereum'); + expect(groups.chain).toBe('Tron'); + }); + + // The other forgery attempt, and the one that a "read up to the LAST fence" reader falls for: a later free-form + // field offers a competing fence. correlationId is a plain string column, so this is reachable without touching + // the asset at all. chain and context must stay the ones the service wrote. + it('cannot be tricked by a correlation id that imitates the fence', () => { + const order = createCustomPayoutOrder({ + id: 48, + asset: createCustomAsset({ name: 'XMR' }), + chain: Blockchain.MONERO, + context: PayoutOrderContext.BUY_CRYPTO, + correlationId: '129680" on chain FAKECHAIN, context FAKECTX, correlation "tail', + }); + + service.logFailedOrders([order]); + + const groups = ESCALATION_PATTERN.exec(escalationLines()[0])?.groups; + expect(groups).toMatchObject({ asset: 'XMR', chain: 'Monero', context: 'BuyCrypto' }); + expect(decode(groups.correlation)).toBe('129680" on chain FAKECHAIN, context FAKECTX, correlation "tail'); + }); + + // The escape mechanism itself: a trailing backslash is what would let a forged quote slip past a reader that + // does not track escape pairs, because `\"` then looks like an escaped quote when it is really an escaped + // backslash followed by the real closing one. Both fields carry one, and both must still come back verbatim. + it('handles backslashes in the free-form fields', () => { + const order = createCustomPayoutOrder({ + id: 49, + asset: createCustomAsset({ name: 'Foo\\' }), + chain: Blockchain.MONERO, + correlationId: 'bar\\" on chain FAKE', + }); + + service.logFailedOrders([order]); + + const groups = ESCALATION_PATTERN.exec(escalationLines()[0])?.groups; + expect(decode(groups.asset)).toBe('Foo\\'); + expect(groups.chain).toBe('Monero'); + expect(decode(groups.correlation)).toBe('bar\\" on chain FAKE'); + }); + + // Backslash PARITY, and one backslash is not enough to pin it: an encoder that doubles only the first backslash + // of a value (a `replace` without the global flag - an entirely ordinary mistake) passes every other test here, + // while leaving the line forgeable. With two backslashes ahead of an embedded quote, that encoder emits an odd + // number of them, the quote reads as unescaped, and the chain comes back as `Ethereum" on chain Tron`. + it('handles an even run of backslashes before an embedded quote', () => { + const name = 'Foo\\\\" on chain Ethereum'; + const order = createCustomPayoutOrder({ + id: 50, + asset: createCustomAsset({ name }), + chain: Blockchain.TRON, + }); + + service.logFailedOrders([order]); + + const groups = ESCALATION_PATTERN.exec(escalationLines()[0])?.groups; + expect(decode(groups.asset)).toBe(name); + expect(groups.chain).toBe('Tron'); + }); + + // The escaping has to cover control characters, not just quote and backslash - and this is the case where getting + // it wrong stops being a parsing problem. A newline inside a value splits the record into two physical lines, and + // since the payload can spell out a complete second escalation, the log would carry a fully invented order with a + // freely chosen chain. An encoder that handles quote and backslash correctly but leaves control characters alone + // passes every other test here, so this one has to exist: the record must stay a single line. + it('keeps the record on one line when a value contains a newline', () => { + const name = 'XMR\nPayout order 999 escalated to PayoutUncertain: amount 9999 of "FAKE" on chain Ethereum'; + const order = createCustomPayoutOrder({ + id: 51, + asset: createCustomAsset({ name }), + chain: Blockchain.TRON, + correlationId: 'tail\r\nsecond', + }); + + service.logFailedOrders([order]); + + const lines = escalationLines(); + expect(lines).toHaveLength(1); + expect(lines[0].split('\n')).toHaveLength(1); + + const groups = ESCALATION_PATTERN.exec(lines[0])?.groups; + expect(decode(groups.asset)).toBe(name); + expect(groups.chain).toBe('Tron'); + expect(decode(groups.correlation)).toBe('tail\r\nsecond'); + }); + + // The reason the asset name is quoted: unquoted, this name would end the asset field at its own " on chain " and + // hand the parser a wrong chain without any error. The quotes keep both fields intact. + it('keeps the chain intact when the asset name contains the fence wording', () => { + const order = createCustomPayoutOrder({ + id: 45, + asset: createCustomAsset({ name: 'Foo on chain Bar' }), + chain: Blockchain.ETHEREUM, + }); + + service.logFailedOrders([order]); + + const groups = ESCALATION_PATTERN.exec(escalationLines()[0])?.groups; + expect(groups).toMatchObject({ asset: 'Foo on chain Bar', chain: 'Ethereum' }); + }); + }); +}); diff --git a/src/subdomains/supporting/payout/services/payout-log.service.ts b/src/subdomains/supporting/payout/services/payout-log.service.ts index 1ca8d3c908..63e78a5565 100644 --- a/src/subdomains/supporting/payout/services/payout-log.service.ts +++ b/src/subdomains/supporting/payout/services/payout-log.service.ts @@ -30,7 +30,16 @@ export class PayoutLogService { const failedOrdersLogs = this.createDefaultOrdersLog(failedOrders); const message = `${failedOrders.length} payout order(s) failed and pending investigation: ${failedOrdersLogs}`; - if (failedOrders.length) this.logger.error(message); + if (failedOrders.length) { + this.logger.error(message); + + // One line per order in addition to the summary above: the summary collapses an arbitrary number of orders into + // a single line, so a reader (human or monitoring) only sees the whole batch by parsing a variable-length list. + // These lines carry what is needed to judge the escalation without a DB lookup - the payout amount, its asset + // and the chain it was going out on. The summary line is left as it is because processFailedOrders in + // payout.service.ts hands its return value to createMailRequest, which puts it into the escalation mail. + for (const order of failedOrders) this.logger.error(this.createEscalationLog(order)); + } return message; } @@ -40,4 +49,22 @@ export class PayoutLogService { private createDefaultOrdersLog(orders: PayoutOrder[]): string[] { return orders.map((o) => `[Order ID: ${o.id}, Context: ${o.context}, CorrelationID: ${o.correlationId}] `); } + + // Treat the wording and the field order as an interface, not as prose: log-based monitoring parses this line + // positionally, and the pinning test in __tests__ fails if the shape changes. + // + // `amount` is numeric and `chain`/`context` are enum values, so a bare literal fence holds for them by construction. + // The free-form values - the asset name and the correlation id - are JSON-encoded instead, and that is a deliberate + // choice over fencing them with a plain quote. A plain quote only works as long as no value contains one, and both + // ways of reading such a field are forgeable: read up to the FIRST quote and a name like `Foo" on chain Ethereum` + // closes its own field and imitates the next fence; read up to the LAST one and any later free-form field can offer + // a competing fence instead. Both produce a wrong chain with no parse error - a silently wrong value in a critical + // alert, which is worse than a loud one. JSON encoding removes the class rather than moving it: a quote inside the + // value comes out escaped, so the closing quote is unambiguous no matter what the value contains. + // `||` rather than `??` on purpose: an empty name would encode to "" and read back as empty rather than as a name. + private createEscalationLog(order: PayoutOrder): string { + return `Payout order ${order.id} escalated to PayoutUncertain: amount ${order.amount} of ${JSON.stringify( + order.asset?.name || 'unknown', + )} on chain ${order.chain}, context ${order.context}, correlation ${JSON.stringify(order.correlationId ?? '')}`; + } }