From b0f0fec3784832ca5bed66aba452688fc13c0d6f Mon Sep 17 00:00:00 2001 From: Danswar <48102227+Danswar@users.noreply.github.com> Date: Wed, 29 Jul 2026 10:03:34 -0300 Subject: [PATCH 1/4] fix(kyc): skip the Sumsub file sync for non-Sumsub ident steps (#4435) * fix(kyc): skip the Sumsub file sync for non-Sumsub ident steps reviewIdentSteps selects every ident step in internal review, regardless of its type, and syncs the ident files before persisting the new status. syncIdentFilesInternal throws for any step that is not a Sumsub one, so a manual ident lost its manual-review transition and stayed in internal review - where the every-minute review picked it up and failed it again, indefinitely. Only call the sync for Sumsub steps: a manual ident uploads its document in updateIdentManual and never has an IDENT_REPORT to sync. The ordering stays as it is, so a failing sync still keeps a Sumsub step in internal review to be retried. * fix(kyc): document the intentional sync-before-save ordering, tighten the tests - state in the comment that running the sync before the save is deliberate, so the guard is not mistaken for a workaround and the ordering is not "cleaned up" later - cover that ordering: a Sumsub step whose sync fails must stay unsaved for a retry - assert the status the repo actually receives; the entity is already mutated in memory before the sync, so the previous assertion held with the bug present - use the SumSubLevelName enum instead of a level name that cannot occur - name the spy after the method it replaces, add the dep-scope comment the other blocks in this file carry, and drop the unused Config bootstrap * fix(kyc): cover both Sumsub ident types and make the retry test self-validating - run the two Sumsub cases over SumsubAuto and SumsubVideo: a guard narrowed to one of them passed the previous tests, while the other type would have completed without any file and without an error - assert in the retry case that the sync was reached, so its two absence assertions cannot hold because the iteration never got there - type savedStatus as optional, since undefined is the "never saved" sentinel - state in the dep-scope comment which stubs the short dep list depends on * fix(kyc): pin the remaining legs of the ident file-sync condition Mutation-checking the previous tests showed four weakenings of the condition that no test noticed: replacing the type guard with !isManual, dropping the already-has-a-report check, matching a different file subType, and dropping the isCompleted leg. Each of them re-breaks a real path. - run the non-Sumsub case over Manual and both legacy IdNow types - cover a step that already carries its ident report, i.e. the normal case in which the webhook downloaded it before the review runs - cover a completing step, which needs its files even more than one in manual review: it leaves internal review for good and is never revisited * fix(kyc): pin the ident file-sync condition against its last three weakenings Three more mutations of the condition passed the previous cases: collapsing the report check to "the account has no files at all", and replacing the whole status clause with true or with !isFailed. The first would disable the review-time sync for nearly every account, the other two would pull documents for an ignored ident. - give the no-report cases an unrelated file, so an empty file list cannot stand in for a missing ident report - cover the ignored outcome, the third one the review can reach - separate the auto and video IdNow fixtures, which are told apart by companyid * fix(kyc): use a synthetic step id and an exhaustive fixture map - the fixture carried a real step id from the incident; fixtures stay synthetic - map every ident type without the optional modifier, so a sixth type fails to compile here instead of silently reaching the review without a result --- .../services/__tests__/kyc.service.spec.ts | 171 +++++++++++++++++- .../generic/kyc/services/kyc.service.ts | 7 + 2 files changed, 177 insertions(+), 1 deletion(-) diff --git a/src/subdomains/generic/kyc/services/__tests__/kyc.service.spec.ts b/src/subdomains/generic/kyc/services/__tests__/kyc.service.spec.ts index 34604aa837..17d53d8e9e 100644 --- a/src/subdomains/generic/kyc/services/__tests__/kyc.service.spec.ts +++ b/src/subdomains/generic/kyc/services/__tests__/kyc.service.spec.ts @@ -6,18 +6,23 @@ import { JwtPayload } from 'src/shared/auth/jwt-payload.interface'; import { UserRole } from 'src/shared/auth/user-role.enum'; import { createCustomCountry } from 'src/shared/models/country/__mocks__/country.entity.mock'; import { Country } from 'src/shared/models/country/country.entity'; +import { CountryService } from 'src/shared/models/country/country.service'; import { DfxLogger } from 'src/shared/services/dfx-logger'; +import * as processServiceModule from 'src/shared/services/process.service'; import { createCustomUserData } from '../../../user/models/user-data/__mocks__/user-data.entity.mock'; import { UserData } from '../../../user/models/user-data/user-data.entity'; import { RiskStatus, UserDataStatus } from '../../../user/models/user-data/user-data.enum'; import { UserDataService } from '../../../user/models/user-data/user-data.service'; import { UserStatus } from '../../../user/models/user/user.enum'; import { IdentDocument } from '../../dto/ident.dto'; -import { FileType, KycFileBlob } from '../../dto/kyc-file.dto'; +import { KycError } from '../../dto/kyc-error.enum'; +import { FileSubType, FileType, KycFileBlob } from '../../dto/kyc-file.dto'; +import { SumSubLevelName } from '../../dto/sum-sub.dto'; import { KycFile } from '../../entities/kyc-file.entity'; import { KycStep } from '../../entities/kyc-step.entity'; import { ContentType } from '../../enums/content-type.enum'; import { KycStepName } from '../../enums/kyc-step-name.enum'; +import { KycStepType } from '../../enums/kyc.enum'; import { ReviewStatus } from '../../enums/review-status.enum'; import { KycStepRepository } from '../../repositories/kyc-step.repository'; import { KycDocumentService } from '../integration/kyc-document.service'; @@ -574,3 +579,167 @@ describe('KycService checkDfxApproval duplicate-key recovery', () => { expect(kycStepRepo.update).not.toHaveBeenCalled(); }); }); + +// The ident file sync only works for Sumsub steps - it throws on any other ident type - and it runs +// BEFORE the status is persisted, so a failing sync keeps the step in INTERNAL_REVIEW for the next +// run. A manual ident therefore used to lose its MANUAL_REVIEW transition and stay in +// INTERNAL_REVIEW, where the every-minute review re-processed and re-failed it forever. +describe('KycService reviewIdentSteps file sync', () => { + let service: KycService; + let kycStepRepo: jest.Mocked; + let userDataService: jest.Mocked; + let syncIdentFilesInternalSpy: jest.SpyInstance; + // the status as seen by the repo, not as read after the run: manualReview() mutates the entity + // in memory before the sync, so asserting on the entity afterwards would pass either way - + // undefined means the step was never saved + let savedStatus: ReviewStatus | undefined; + + // resultData is read per ident type, so each type needs its own result shape + const sumsubResult = (levelName: SumSubLevelName) => ({ + data: { info: { idDocs: [{ firstNameEn: 'Max', lastNameEn: 'Muster', dob: '1990-01-01' }] } }, + webhook: { levelName }, + }); + + // companyid is what separates an auto from a video IdNow ident, see getIdentificationType + const idNowResult = (companyid: string) => ({ + userdata: { firstname: { value: 'Max' }, lastname: { value: 'Muster' }, birthday: { value: '1990-01-01' } }, + identificationprocess: { companyid, result: 'SUCCESS' }, + }); + + // fully mapped on purpose: a new ident type then fails to compile instead of silently arriving here + // without a result + const identResult: { [t in KycStepType]: object } = { + [KycStepType.MANUAL]: { firstName: 'Max', lastName: 'Muster', birthday: '1990-01-01' }, + [KycStepType.AUTO]: idNowResult('dfxauto'), + [KycStepType.VIDEO]: idNowResult('dfxvideo'), + [KycStepType.SUMSUB_AUTO]: sumsubResult(SumSubLevelName.CH_STANDARD), + [KycStepType.SUMSUB_VIDEO]: sumsubResult(SumSubLevelName.CH_STANDARD_VIDEO), + }; + + const identStep = (type: KycStepType, kycFiles: KycFile[] = []): KycStep => { + const userData = createCustomUserData({ id: 42, kycFiles, users: [] }); + // mirrors the finder's WHERE clause: the account has a completed nationality step + userData.getStepsWith = jest.fn().mockReturnValue([createMock({ isCompleted: true })]); + + return Object.assign(new KycStep(), { + id: 1, + name: KycStepName.IDENT, + type, + status: ReviewStatus.INTERNAL_REVIEW, + userData, + result: JSON.stringify(identResult[type]), + }); + }; + + beforeEach(() => { + savedStatus = undefined; + kycStepRepo = createMock(); + kycStepRepo.findBy.mockResolvedValue([]); + (kycStepRepo.save as jest.Mock).mockImplementation(async (step: KycStep) => { + savedStatus = step.status; + return step; + }); + userDataService = createMock(); + userDataService.getUserDataByBirthday.mockResolvedValue([]); + + // with getIdentCheckErrors, createStepLog and syncIdentFilesInternal stubbed below, the review + // path only touches these deps; avoid wiring all constructor deps + service = Object.create(KycService.prototype); + (service as any).kycStepRepo = kycStepRepo; + (service as any).userDataService = userDataService; + (service as any).countryService = createMock(); + (service as any).logger = createMock(); + + jest.spyOn(processServiceModule, 'DisabledProcess').mockReturnValue(false); + // the check itself is not under test here - a plain, non-ignoring error puts every step into + // manual review, so the cases differ only in the ident type + jest.spyOn(service as any, 'getIdentCheckErrors').mockReturnValue([KycError.FIRST_NAME_NOT_MATCHING]); + jest.spyOn(service as any, 'createStepLog').mockResolvedValue(undefined); + syncIdentFilesInternalSpy = jest.spyOn(service as any, 'syncIdentFilesInternal').mockResolvedValue(undefined); + }); + + // the sync throws for every type it does not know, so all of them have to stay out of it - the + // legacy IdNow types are dormant, but a guard narrowed to Manual would wedge them just the same + const nonSumsubTypes = [KycStepType.MANUAL, KycStepType.AUTO, KycStepType.VIDEO]; + // both Sumsub types can sync, so both have to be covered - a guard narrowed to one of them would + // otherwise leave the other completing without any file, silently + const sumsubTypes = [KycStepType.SUMSUB_AUTO, KycStepType.SUMSUB_VIDEO]; + + it.each(nonSumsubTypes)('persists a %s ident step without touching the Sumsub file sync', async (type) => { + const step = identStep(type); + kycStepRepo.find.mockResolvedValue([step]); + // mirror the real implementation: it rejects a non-Sumsub step, which would skip the save below + syncIdentFilesInternalSpy.mockRejectedValue(new Error(`Invalid ident step type ${type}`)); + + await service.reviewIdentSteps(); + + expect(syncIdentFilesInternalSpy).not.toHaveBeenCalled(); + expect(savedStatus).toBe(ReviewStatus.MANUAL_REVIEW); + }); + + it.each(sumsubTypes)('still syncs the files of a %s ident step that has no ident report yet', async (type) => { + // an unrelated file must not stand in for the report: only a missing IDENT_REPORT triggers the sync + const step = identStep(type, [createMock({ subType: FileSubType.IDENT_SELFIE })]); + kycStepRepo.find.mockResolvedValue([step]); + + await service.reviewIdentSteps(); + + expect(syncIdentFilesInternalSpy).toHaveBeenCalledWith(step); + expect(savedStatus).toBe(ReviewStatus.MANUAL_REVIEW); + }); + + // the normal case: the ident webhook already downloaded the report, so there is nothing to fetch + it.each(sumsubTypes)('skips the file sync of a %s ident step that already has its report', async (type) => { + const step = identStep(type, [createMock({ subType: FileSubType.IDENT_REPORT })]); + kycStepRepo.find.mockResolvedValue([step]); + + await service.reviewIdentSteps(); + + expect(syncIdentFilesInternalSpy).not.toHaveBeenCalled(); + expect(savedStatus).toBe(ReviewStatus.MANUAL_REVIEW); + }); + + // a completing step must sync too: it leaves INTERNAL_REVIEW for good, so a missed file is not + // retried by a later run but simply stays missing + it.each(sumsubTypes)('still syncs the files of a completing %s ident step', async (type) => { + const step = identStep(type); + kycStepRepo.find.mockResolvedValue([step]); + jest.spyOn(service as any, 'getIdentCheckErrors').mockReturnValue([]); + // both run after the save; stub them so an unwired dep cannot throw into the catch and mask this + jest.spyOn(service as any, 'completeIdent').mockResolvedValue(undefined); + jest.spyOn(service as any, 'checkDfxApproval').mockResolvedValue(undefined); + + await service.reviewIdentSteps(); + + expect(syncIdentFilesInternalSpy).toHaveBeenCalledWith(step); + expect(savedStatus).toBe(ReviewStatus.COMPLETED); + }); + + // a merged or blocked account is ignored instead of reviewed, and it is saved like any other + // outcome - so an unguarded sync would wedge it in internal review just the same + it.each(sumsubTypes)('skips the file sync of an ignored %s ident step', async (type) => { + const step = identStep(type); + kycStepRepo.find.mockResolvedValue([step]); + jest.spyOn(service as any, 'getIdentCheckErrors').mockReturnValue([KycError.USER_DATA_MERGED]); + + await service.reviewIdentSteps(); + + expect(syncIdentFilesInternalSpy).not.toHaveBeenCalled(); + expect(savedStatus).toBe(ReviewStatus.IGNORED); + }); + + // the sync deliberately runs before the save: a Sumsub step whose files could not be fetched has + // to keep its INTERNAL_REVIEW status so the next run retries it instead of advancing without files + it.each(sumsubTypes)('leaves a %s ident step unsaved when its file sync fails, for a retry', async (type) => { + const step = identStep(type); + kycStepRepo.find.mockResolvedValue([step]); + syncIdentFilesInternalSpy.mockRejectedValue(new Error('blob is immutable')); + + await service.reviewIdentSteps(); + + // the sync has to be reached, otherwise the two absence assertions below hold for the wrong reason + expect(syncIdentFilesInternalSpy).toHaveBeenCalledWith(step); + expect(kycStepRepo.save).not.toHaveBeenCalled(); + expect(savedStatus).toBeUndefined(); + }); +}); diff --git a/src/subdomains/generic/kyc/services/kyc.service.ts b/src/subdomains/generic/kyc/services/kyc.service.ts index 4fbe642f36..3717e2bfce 100644 --- a/src/subdomains/generic/kyc/services/kyc.service.ts +++ b/src/subdomains/generic/kyc/services/kyc.service.ts @@ -276,7 +276,14 @@ export class KycService { entity.manualReview(comment); } + // Running the sync before the save is intentional: a Sumsub step whose files could not be + // fetched must keep its INTERNAL_REVIEW status so the next run retries it, instead of + // advancing with an incomplete document set. That makes the type guard mandatory - only + // Sumsub idents have files to sync (and an IDENT_REPORT at all), a manual ident uploads its + // document in updateIdentManual, and syncIdentFilesInternal throws on every other type. An + // unguarded call therefore wedged manual idents in INTERNAL_REVIEW to be retried forever. if ( + entity.isSumsub && !entity.userData.kycFiles.some((f) => f.subType === FileSubType.IDENT_REPORT) && (entity.isCompleted || entity.status === ReviewStatus.MANUAL_REVIEW) ) From 3057a4db65ebb5b3fcc59d3c5cd4516256d204eb Mon Sep 17 00:00:00 2001 From: TaprootFreak <142087526+TaprootFreak@users.noreply.github.com> Date: Wed, 29 Jul 2026 15:37:00 +0200 Subject: [PATCH 2/4] a0b32b4e - Expose order timestamps in the Safe activity history (#4448) * feat(custody): expose order timestamps in the account history The order history DTO carried no timestamp at all, so a client had no way to date an entry. Pass both the creation date and the valuta timestamp separately rather than collapsing them: an order only gets completedAt once it completes, and the distinction between when an order was recorded and when it was valuated is exactly what a reader needs. * test(custody): pin the history mapper timestamps The valuta timestamp is only ever set once an order completes. A later refactoring that collapses it onto the creation date would claim a valuta that never happened, so assert the undefined case explicitly. --- .../dto/output/custody-order-history.dto.ts | 6 ++ .../custody-order-history-dto.mapper.spec.ts | 62 +++++++++++++++++++ .../custody-order-history-dto.mapper.ts | 2 + 3 files changed, 70 insertions(+) create mode 100644 src/subdomains/core/custody/mappers/__tests__/custody-order-history-dto.mapper.spec.ts diff --git a/src/subdomains/core/custody/dto/output/custody-order-history.dto.ts b/src/subdomains/core/custody/dto/output/custody-order-history.dto.ts index 4db68a4966..eeb930702f 100644 --- a/src/subdomains/core/custody/dto/output/custody-order-history.dto.ts +++ b/src/subdomains/core/custody/dto/output/custody-order-history.dto.ts @@ -16,6 +16,12 @@ export class CustodyOrderHistoryDto { @ApiProperty({ enum: CustodyOrderHistoryStatus }) status: CustodyOrderHistoryStatus; + @ApiProperty() + created: Date; + + @ApiPropertyOptional({ description: 'Valuta timestamp, set once the order is completed' }) + completedAt?: Date; + @ApiPropertyOptional() inputAmount?: number; diff --git a/src/subdomains/core/custody/mappers/__tests__/custody-order-history-dto.mapper.spec.ts b/src/subdomains/core/custody/mappers/__tests__/custody-order-history-dto.mapper.spec.ts new file mode 100644 index 0000000000..937f722fce --- /dev/null +++ b/src/subdomains/core/custody/mappers/__tests__/custody-order-history-dto.mapper.spec.ts @@ -0,0 +1,62 @@ +import { CustodyOrder } from '../../entities/custody-order.entity'; +import { CustodyOrderStatus, CustodyOrderType } from '../../enums/custody'; +import { CustodyOrderHistoryStatus } from '../../dto/output/custody-order-history.dto'; +import { CustodyOrderHistoryDtoMapper } from '../custody-order-history-dto.mapper'; + +describe('CustodyOrderHistoryDtoMapper', () => { + describe('map', () => { + it('passes through both timestamps for a completed order', () => { + const created = new Date('2026-01-08T10:00:00Z'); + const completedAt = new Date('2026-01-28T12:00:00Z'); + const order = Object.assign(new CustodyOrder(), { + type: CustodyOrderType.DEPOSIT, + status: CustodyOrderStatus.COMPLETED, + created, + completedAt, + }); + + const result = CustodyOrderHistoryDtoMapper.map(order); + + expect(result.created).toEqual(created); + expect(result.completedAt).toEqual(completedAt); + expect(result.status).toBe(CustodyOrderHistoryStatus.COMPLETED); + }); + + it('leaves completedAt undefined for an order that never completed', () => { + const created = new Date('2026-01-08T10:00:00Z'); + const order = Object.assign(new CustodyOrder(), { + type: CustodyOrderType.DEPOSIT, + status: CustodyOrderStatus.CONFIRMED, + created, + }); + + const result = CustodyOrderHistoryDtoMapper.map(order); + + // A fallback onto created would claim a valuta the order never had. + expect(result.created).toEqual(created); + expect(result.completedAt).toBeUndefined(); + }); + + it('keeps the timestamps of each order in mapList', () => { + const created1 = new Date('2026-01-01T00:00:00Z'); + const created2 = new Date('2026-01-15T00:00:00Z'); + const order1 = Object.assign(new CustodyOrder(), { + type: CustodyOrderType.DEPOSIT, + status: CustodyOrderStatus.COMPLETED, + created: created1, + completedAt: new Date('2026-01-02T00:00:00Z'), + }); + const order2 = Object.assign(new CustodyOrder(), { + type: CustodyOrderType.DEPOSIT, + status: CustodyOrderStatus.CONFIRMED, + created: created2, + }); + + const result = CustodyOrderHistoryDtoMapper.mapList([order1, order2]); + + expect(result).toHaveLength(2); + expect(result[0].created).toEqual(created1); + expect(result[1].created).toEqual(created2); + }); + }); +}); diff --git a/src/subdomains/core/custody/mappers/custody-order-history-dto.mapper.ts b/src/subdomains/core/custody/mappers/custody-order-history-dto.mapper.ts index 5795e0e1f0..29402026b6 100644 --- a/src/subdomains/core/custody/mappers/custody-order-history-dto.mapper.ts +++ b/src/subdomains/core/custody/mappers/custody-order-history-dto.mapper.ts @@ -14,6 +14,8 @@ export class CustodyOrderHistoryDtoMapper { return { type: order.type, status: this.mapStatus(order), + created: order.created, + completedAt: order.completedAt, inputAmount: isIncoming || isSwap ? (order.inputAmount ?? order.transactionRequest?.estimatedAmount) : order.inputAmount, inputAsset: order.inputAsset?.name, From 564ece02afab8b41166f589bf35add63553c53a1 Mon Sep 17 00:00:00 2001 From: Danswar <48102227+Danswar@users.noreply.github.com> Date: Wed, 29 Jul 2026 10:41:54 -0300 Subject: [PATCH 3/4] fix(scrypt): back off quarantined-order venue lookups (#4438) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * fix(scrypt): back off quarantined-order venue lookups and release the never-sent order 127664 A quarantined order whose reference the venue does not know pays a full 30-day execution-report fetch on every reconciliation pass — several per 10-second tick via the pipeline loop, measured at ~300 heavy fetches per hour against the same connection whose failure usually caused the quarantine in the first place. - resolveUncertainOrders: per-order cooldown, a tenth of the order's age clamped to [1 min, 30 min], stamped when the lookup FINISHES (success, inconclusive and thrown alike); a pending manual release bypasses it - getOrderStatus: optional 'since' lower bound for the fallback fetch; the uncertain-order path passes order.created minus one day, never wider than the previous fixed 30-day window - migration: release order 127664 — provably never sent (its stored failure is thrown before any bytes leave the process, the venue never knew the reference across 8 h of lookups, the EUR position never drained and was manually converted at the venue). Compare-and-set guards make it a no-op if the admin endpoint releases it first; correlationId + created window pin the exact production row. * fix(scrypt): drop the release migration and scope cooldown stamps to one quarantine episode Review follow-ups: - the data migration for order 127664 is removed: the order was released via the admin endpoint on 2026-07-28 (row is Failed), so the status compare-and-set makes the migration a guaranteed no-op — and the only state it could ever match again is a blockConfirmedOrder re-quarantine, which must never be flipped to Failed - a cooldown stamp now lives for exactly one quarantine episode: it is cleared when the order's exit write lands (leaveQuarantine), so an order quarantined anew gets its first venue lookup immediately instead of inheriting up to 30 minutes of old wait - two mutation-killing tests: the cooldown measures from the END of a slow lookup (a start-stamp mutant fails), and a re-quarantined order starts a fresh cooldown (removing the exit-write deletion fails) --- .../exchange/services/scrypt.service.ts | 9 +- .../actions/__tests__/scrypt.adapter.spec.ts | 26 ++++ .../adapters/actions/scrypt.adapter.ts | 7 +- ...uidity-management-pipeline.service.spec.ts | 132 ++++++++++++++++++ .../liquidity-management-pipeline.service.ts | 60 +++++++- 5 files changed, 230 insertions(+), 4 deletions(-) diff --git a/src/integration/exchange/services/scrypt.service.ts b/src/integration/exchange/services/scrypt.service.ts index b6b2f96394..97d16daace 100644 --- a/src/integration/exchange/services/scrypt.service.ts +++ b/src/integration/exchange/services/scrypt.service.ts @@ -580,13 +580,18 @@ export class ScryptService extends PricingProvider { return found; } - async getOrderStatus(clOrdId: string): Promise { + /** + * @param since lower bound for the fallback history fetch. A caller that knows when its reference can + * earliest have existed passes it here, so a lookup for an absent order does not pull a full 30 days of + * execution reports over the connection. Defaults to the full 30-day window. + */ + async getOrderStatus(clOrdId: string, since?: Date): Promise { // Try in-memory cache first let report = this.executionReports.get(clOrdId); // Fallback: fetch from Scrypt API (e.g. after restart or WS reconnect) if (!report) { - const reports = await this.fetchExecutionReports(Util.daysBefore(30)); + const reports = await this.fetchExecutionReports(since ?? Util.daysBefore(30)); const fetched = reports.find((r) => r.ClOrdID === clOrdId); if (fetched) { diff --git a/src/subdomains/core/liquidity-management/adapters/actions/__tests__/scrypt.adapter.spec.ts b/src/subdomains/core/liquidity-management/adapters/actions/__tests__/scrypt.adapter.spec.ts index 387976f068..03f2765ea9 100644 --- a/src/subdomains/core/liquidity-management/adapters/actions/__tests__/scrypt.adapter.spec.ts +++ b/src/subdomains/core/liquidity-management/adapters/actions/__tests__/scrypt.adapter.spec.ts @@ -16,6 +16,7 @@ import { } from 'src/integration/exchange/services/scrypt-websocket-connection'; import { ScryptService } from 'src/integration/exchange/services/scrypt.service'; import { AssetService } from 'src/shared/models/asset/asset.service'; +import { Util } from 'src/shared/utils/util'; import { DexService } from 'src/subdomains/supporting/dex/services/dex.service'; import { PricingService } from 'src/subdomains/supporting/pricing/services/pricing.service'; import { LiquidityManagementAction } from '../../../entities/liquidity-management-action.entity'; @@ -582,5 +583,30 @@ describe('ScryptAdapter', () => { await expect(adapter.resolveUncertainOrder(order)).resolves.toBe(UncertainOrderResolution.SENT); expect(order.correlationId).toBe('dfx-lm-4711-1'); }); + + it("bounds the fallback fetch by the order's creation date, with one day of margin", async () => { + // a reference cannot be published before the order that reserved it existed, so the venue lookup for + // a recent order has no business pulling a month of history + const getOrderStatus = jest.spyOn(scryptService, 'getOrderStatus').mockResolvedValue(venueOrder('dfx-lm-4711')); + const order = createUncertainSellOrder(); + + await adapter.resolveUncertainOrder(order); + + expect(getOrderStatus).toHaveBeenCalledWith('dfx-lm-4711', Util.daysBefore(1, order.created)); + }); + + it('never widens the fetch window past the previous fixed 30 days, however old the order', async () => { + const getOrderStatus = jest.spyOn(scryptService, 'getOrderStatus').mockResolvedValue(venueOrder('dfx-lm-4711')); + const order = createUncertainSellOrder({ created: new Date(Date.now() - 40 * 24 * 60 * 60 * 1000) }); + + // the 30-day bound is derived from "now", so pin it from both sides instead of comparing exact dates + const earliest = Util.daysBefore(30); + await adapter.resolveUncertainOrder(order); + const latest = Util.daysBefore(30); + + const [, since] = getOrderStatus.mock.calls[0]; + expect(since?.getTime()).toBeGreaterThanOrEqual(earliest.getTime()); + expect(since?.getTime()).toBeLessThanOrEqual(latest.getTime()); + }); }); }); diff --git a/src/subdomains/core/liquidity-management/adapters/actions/scrypt.adapter.ts b/src/subdomains/core/liquidity-management/adapters/actions/scrypt.adapter.ts index a248b471ce..2d4f2c155d 100644 --- a/src/subdomains/core/liquidity-management/adapters/actions/scrypt.adapter.ts +++ b/src/subdomains/core/liquidity-management/adapters/actions/scrypt.adapter.ts @@ -614,8 +614,13 @@ export class ScryptAdapter extends LiquidityActionAdapter { const candidates = this.attemptedReferencesNewestFirst(order); let rejectedCount = 0; + // A reference cannot be published before the order that reserved it existed; one day of margin + // covers venue-side clock skew and late re-publication. Never widen past the previous fixed + // 30-day window for very old orders. + const since = new Date(Math.max(Util.daysBefore(30).getTime(), Util.daysBefore(1, order.created).getTime())); + for (const candidate of candidates) { - const info = await this.scryptService.getOrderStatus(candidate); + const info = await this.scryptService.getOrderStatus(candidate, since); // Absent, newest first: an accepted replacement may simply not be visible yet, while the order it // replaced still is. Falling through to that predecessor would report SENT on a reference the venue diff --git a/src/subdomains/core/liquidity-management/services/liquidity-management-pipeline.service.spec.ts b/src/subdomains/core/liquidity-management/services/liquidity-management-pipeline.service.spec.ts index 8eb67c322d..d56e44de6d 100644 --- a/src/subdomains/core/liquidity-management/services/liquidity-management-pipeline.service.spec.ts +++ b/src/subdomains/core/liquidity-management/services/liquidity-management-pipeline.service.spec.ts @@ -158,12 +158,17 @@ describe('LiquidityManagementPipelineService', () => { }); describe('resolveUncertainOrders', () => { + /** Fixed and weeks old: the resolve cooldown derives its interval from the order's age, so a moving + * `created` would make these tests depend on when they run. */ + const ORDER_CREATED = new Date('2026-07-01T00:00:00Z'); + function uncertainOrder(overrides: Partial = {}): LiquidityManagementOrder { return Object.assign(new LiquidityManagementOrder(), { id: 9, status: LiquidityManagementOrderStatus.UNCERTAIN, correlationId: 'dfx-lm-9', errorMessage: 'Scrypt did not answer', + created: ORDER_CREATED, action: { id: 233, system: 'Scrypt', command: 'sell' }, ...overrides, }); @@ -477,6 +482,133 @@ describe('LiquidityManagementPipelineService', () => { expect(order.status).toBe(LiquidityManagementOrderStatus.UNCERTAIN); }); + + describe('venue-lookup cooldown', () => { + // The cooldown is a pure function of Date.now(), so these tests drive the clock instead of waiting. + // Scoped here rather than suite-wide: nothing else in this file cares about time. + beforeEach(() => jest.useFakeTimers()); + afterEach(() => jest.useRealTimers()); + + /** Like `stubIntegration`, but hands the lookup mock back so a test can count venue asks. UNAVAILABLE + * keeps the order quarantined without touching any other state, so every pass sees the same picture + * and only the cooldown decides whether the venue is asked. */ + function stubResolver(): jest.Mock { + const resolveUncertainOrder = jest.fn().mockResolvedValue(UncertainOrderResolution.UNAVAILABLE); + jest.spyOn(actionIntegrationFactory, 'getIntegration').mockReturnValue({ + supportedCommands: ['sell'], + executeOrder: jest.fn(), + checkCompletion: jest.fn(), + validateParams: jest.fn(), + resolveUncertainOrder, + }); + return resolveUncertainOrder; + } + + it('asks the venue immediately on the first pass for a fresh quarantined order', async () => { + const resolveUncertainOrder = stubResolver(); + jest.spyOn(orderRepo, 'findBy').mockResolvedValue([uncertainOrder({ created: new Date() })]); + + await service['resolveUncertainOrders'](); + + expect(resolveUncertainOrder).toHaveBeenCalledTimes(1); + }); + + it('does not ask again while the cooldown is running', async () => { + const resolveUncertainOrder = stubResolver(); + jest.spyOn(orderRepo, 'findBy').mockResolvedValue([uncertainOrder({ created: new Date() })]); + + await service['resolveUncertainOrders'](); + // the next cron tick, well inside the one-minute floor a fresh order gets + jest.advanceTimersByTime(10_000); + await service['resolveUncertainOrders'](); + + expect(resolveUncertainOrder).toHaveBeenCalledTimes(1); + }); + + it('asks again once the cooldown has elapsed', async () => { + const resolveUncertainOrder = stubResolver(); + jest.spyOn(orderRepo, 'findBy').mockResolvedValue([uncertainOrder({ created: new Date() })]); + + await service['resolveUncertainOrders'](); + jest.advanceTimersByTime(61_000); + await service['resolveUncertainOrders'](); + + expect(resolveUncertainOrder).toHaveBeenCalledTimes(2); + }); + + it('measures the cooldown from the end of the lookup, not its start', async () => { + // a lookup can be slow — a stamp taken at its start would already be half-expired by the time it + // finishes, letting the next pass re-enter immediately + const resolveUncertainOrder = stubResolver(); + resolveUncertainOrder.mockImplementation(async () => { + jest.advanceTimersByTime(120_000); // a lookup that outlives the one-minute floor + return UncertainOrderResolution.UNAVAILABLE; + }); + jest.spyOn(orderRepo, 'findBy').mockResolvedValue([uncertainOrder({ created: new Date() })]); + + await service['resolveUncertainOrders'](); + await service['resolveUncertainOrders'](); + + expect(resolveUncertainOrder).toHaveBeenCalledTimes(1); + }); + + it('starts the cooldown even when the venue lookup throws', async () => { + // a dead connection is exactly the regime the cooldown exists for — stamping only successful + // lookups would re-ask a venue that cannot answer on every pass, at full fetch cost each time + const resolveUncertainOrder = stubResolver(); + resolveUncertainOrder.mockRejectedValue(new Error('Connection closed')); + jest.spyOn(orderRepo, 'findBy').mockResolvedValue([uncertainOrder({ created: new Date() })]); + + await service['resolveUncertainOrders'](); + await service['resolveUncertainOrders'](); + + expect(resolveUncertainOrder).toHaveBeenCalledTimes(1); + }); + + it('resolves an order with a pending release on every pass', async () => { + // a manual release must complete on the next tick, and its own venue-wait runs on its own clock — + // the cooldown has no say here + const resolveUncertainOrder = stubResolver(); + jest.spyOn(orderRepo, 'findBy').mockResolvedValue([releasePendingOrder()]); + + await service['resolveUncertainOrders'](); + await service['resolveUncertainOrders'](); + + expect(resolveUncertainOrder).toHaveBeenCalledTimes(2); + }); + + it('starts a fresh cooldown when an order re-enters quarantine after leaving it', async () => { + // the stamp's lifetime is one quarantine episode: a venue verdict releases the order, and when the + // completion check quarantines it anew moments later, the NEW episode's first lookup must not + // inherit the previous episode's wait + const resolveUncertainOrder = stubResolver(); + resolveUncertainOrder.mockResolvedValueOnce(UncertainOrderResolution.NOT_SENT); + jest.spyOn(orderRepo, 'update').mockResolvedValue({ affected: 1, raw: [], generatedMaps: [] }); + const findBy = jest.spyOn(orderRepo, 'findBy'); + + findBy.mockResolvedValueOnce([uncertainOrder({ created: new Date() })]); + await service['resolveUncertainOrders'](); + + findBy.mockResolvedValueOnce([uncertainOrder({ created: new Date() })]); + await service['resolveUncertainOrders'](); + + expect(resolveUncertainOrder).toHaveBeenCalledTimes(2); + }); + + it('prunes the cooldown entry once an order has left quarantine', async () => { + stubResolver(); + const findBy = jest.spyOn(orderRepo, 'findBy'); + + findBy.mockResolvedValueOnce([uncertainOrder({ created: new Date() })]); + await service['resolveUncertainOrders'](); + expect(service['uncertainResolveAttempts'].size).toBe(1); + + // resolved elsewhere: the quarantine set no longer holds the order, so its entry must not linger + findBy.mockResolvedValueOnce([]); + await service['resolveUncertainOrders'](); + expect(service['uncertainResolveAttempts'].size).toBe(0); + }); + }); }); describe('resolveUncertainOrderManually', () => { diff --git a/src/subdomains/core/liquidity-management/services/liquidity-management-pipeline.service.ts b/src/subdomains/core/liquidity-management/services/liquidity-management-pipeline.service.ts index 3dbd887d94..a25617b6ba 100644 --- a/src/subdomains/core/liquidity-management/services/liquidity-management-pipeline.service.ts +++ b/src/subdomains/core/liquidity-management/services/liquidity-management-pipeline.service.ts @@ -22,6 +22,20 @@ import { LiquidityManagementPipelineRepository } from '../repositories/liquidity import { LiquidityManagementRuleRepository } from '../repositories/liquidity-management-rule.repository'; import { LiquidityManagementService } from './liquidity-management.service'; +/** + * How long reconciliation waits before asking the venue about the same quarantined order again, + * proportional to the order's age (a tenth of it, within these bounds). + * + * A venue lookup is not free: for an order the venue does not know it is a full history fetch, carried over + * the very connection whose failure usually caused the quarantine in the first place. Asking on every pass + * is what turned one permanently-absent reference into hundreds of heavy fetches per hour. The interval is + * age-proportional because the value of asking decays with age: a freshly quarantined order's answer can + * still change — the venue may simply not have published the reference yet, and fast auto-heal matters — + * while an order that has been absent for eight hours is not going to answer differently within a minute. + */ +const UNCERTAIN_RESOLVE_MIN_INTERVAL_MS = 60_000; // 1 minute +const UNCERTAIN_RESOLVE_MAX_INTERVAL_MS = 30 * 60_000; // 30 minutes + @Injectable() export class LiquidityManagementPipelineService { private readonly logger = new DfxLogger(LiquidityManagementPipelineService); @@ -39,6 +53,18 @@ export class LiquidityManagementPipelineService { */ private readonly unappliedObservations = new Map(); + /** + * When the venue lookup for each quarantined order last FINISHED — the clock behind the resolve cooldown. + * + * The end of the attempt, not its start: a slow lookup that finishes just before the next pass must not + * permit immediate re-entry. In memory like `unappliedObservations`, and safe there for the same reason — + * losing it on a restart only means one extra lookup per order, never a wrong conclusion. A stamp lives + * for one quarantine episode: it is cleared when the order's exit write lands, so a re-quarantined order + * starts fresh, with the per-pass prune against the loaded quarantine set as the safety net for orders + * that leave any other way. + */ + private readonly uncertainResolveAttempts = new Map(); // orderId -> last attempt END + constructor( private readonly ruleRepo: LiquidityManagementRuleRepository, private readonly orderRepo: LiquidityManagementOrderRepository, @@ -308,10 +334,30 @@ export class LiquidityManagementPipelineService { const orders = await this.orderRepo.findBy({ status: LiquidityManagementOrderStatus.UNCERTAIN }); let anyChanged = false; + // an order that has left quarantine has no cooldown to keep + const quarantinedIds = new Set(orders.map((order) => order.id)); + for (const id of this.uncertainResolveAttempts.keys()) + if (!quarantinedIds.has(id)) this.uncertainResolveAttempts.delete(id); + for (const order of orders) { // Somebody has already judged this one never sent; the venue's answer is what puts that into effect. const releasePending = Boolean(order.notSentRecheckDue); + // Not re-asked on every pass: the interval grows with the order's age, because the value of asking + // decays with it — a fresh order's venue answer can still change, an eight-hour-old one's cannot. A + // pending release bypasses the wait entirely: a manual release must complete on the next tick, and + // its own venue-wait runs on its own clock. + if (!releasePending) { + const ageMs = Date.now() - order.created.getTime(); + const intervalMs = Math.min( + Math.max(ageMs / 10, UNCERTAIN_RESOLVE_MIN_INTERVAL_MS), + UNCERTAIN_RESOLVE_MAX_INTERVAL_MS, + ); + + const lastAttemptEnd = this.uncertainResolveAttempts.get(order.id); + if (lastAttemptEnd && Date.now() - lastAttemptEnd.getTime() < intervalMs) continue; + } + try { // Null when the action's system or command is no longer registered at all — an order can outlive the // adapter that made it, and dereferencing that would throw here on every pass, forever. @@ -326,7 +372,15 @@ export class LiquidityManagementPipelineService { continue; } - const resolution = await actionIntegration.resolveUncertainOrder(order); + let resolution: UncertainOrderResolution; + try { + resolution = await actionIntegration.resolveUncertainOrder(order); + } finally { + // Stamped when the lookup finishes, whatever it returned or threw. A dead connection is exactly + // the regime the cooldown exists for — stamping only successes would re-ask a venue that cannot + // answer on every pass, at full fetch cost each time. + this.uncertainResolveAttempts.set(order.id, new Date()); + } if (resolution === UncertainOrderResolution.SENT) { if (await this.applyConfirmedObservation(order)) { @@ -541,6 +595,10 @@ export class LiquidityManagementPipelineService { return false; } + // A landed write ends the quarantine episode, and the cooldown stamp's lifetime is exactly one episode: + // an order quarantined anew must get its first lookup immediately, not inherit an old wait. + this.uncertainResolveAttempts.delete(order.id); + return true; } From 3542bca909148a74d13cf907981c6ad81ac8b845 Mon Sep 17 00:00:00 2001 From: TaprootFreak <142087526+TaprootFreak@users.noreply.github.com> Date: Wed, 29 Jul 2026 16:10:02 +0200 Subject: [PATCH 4/4] 7392bb63 - Bound financial-log reads in SQL instead of after loading (#4446) * fix(ledger): bound financial-log reads in SQL instead of after loading LedgerMarkService paginated financial-log snapshots through windows, but getFinancialLogs had no upper bound and no limit in SQL. Every window re-read all rows from its start date to today - including the message column at ~5.8 KB per row - and discarded the excess in JavaScript. In production that filter matches 32'757 rows carrying 311 MB of JSON, while the filter scan itself costs only 134 ms. Push `to` and `limit` into the query and replace the window loop with a keyset cursor. The cursor is the id of the last row of the previous page; its `created` value is resolved in a correlated subquery instead of round-tripping through a JS Date. log.created is timestamp(6) and 4999 of 5000 sampled production rows carry a microsecond remainder that a Date truncates - comparing against the truncated value would re-include the cursor row on every page and, at markPreloadMaxRows = 1, never terminate. A missing cursor row fails loud rather than yielding an empty page that callers would misread as end-of-data. On overflow the probe read is reused as the first page instead of being discarded and read again. The returned row set is unchanged for identical parameters. * fix(ledger): validate the preload row cap and detect a stale cursor reliably Review follow-ups on the bounded financial-log reads. markPreloadMaxRows comes from an env var and was never validated. At 0 the probe read sliced to an empty first page and LIMIT 0 returned nothing, so preload() silently built an empty mark cache while rows existed. It is now required to be a positive integer and fails loud otherwise. The cursor existence check ran before the main query, which left a window in which cleanup() could delete the cursor row: the query then saw a NULL cursor, returned no rows, and pagination read that as end-of-data. The check now runs only after an empty result with a cursor set, which closes that window and drops the extra round-trip on every non-empty page. The pagination fake filtered on id alone while the query compares (created, id) lexicographically, so a later row with a lower id would have been dropped in the test but returned in production. It now resolves the cursor row and compares the same way, with a test covering non-monotonic ids. Also bounds the cutover snapshot read at `to` in SQL rather than filtering in JavaScript afterwards, now that the parameter exists. * test(ledger): annotate the cutover snapshot mock return type --- .../__tests__/ledger-cutover.service.spec.ts | 12 +- .../__tests__/ledger-mark.service.spec.ts | 343 +++++++++++++++--- .../services/ledger-cutover.service.ts | 7 +- .../services/ledger-mark.service.ts | 55 +-- .../log/__tests__/log.repository.spec.ts | 114 +++++- .../supporting/log/log.repository.ts | 85 ++++- src/subdomains/supporting/log/log.service.ts | 10 +- 7 files changed, 532 insertions(+), 94 deletions(-) diff --git a/src/subdomains/core/accounting/services/__tests__/ledger-cutover.service.spec.ts b/src/subdomains/core/accounting/services/__tests__/ledger-cutover.service.spec.ts index 03d6a8f8d6..9d8a06a7c3 100644 --- a/src/subdomains/core/accounting/services/__tests__/ledger-cutover.service.spec.ts +++ b/src/subdomains/core/accounting/services/__tests__/ledger-cutover.service.spec.ts @@ -1434,10 +1434,16 @@ describe('LedgerCutoverService', () => { describe('snapshot selection + pinning (R3-1)', () => { it('throws when there is no valid FinancialDataLog snapshot ≤ cutoff date (flag stays unset)', async () => { jest.spyOn(settingService, 'get').mockResolvedValue(undefined); - // selectSnapshot reads getFinancialLogs and keeps only rows created ≤ now; a single FUTURE-dated row is filtered - // out → no snapshot → cutover throws → the throw propagates to @DfxCron → flag stays unset. + // selectSnapshot bounds the read at `to = now` in SQL; a single FUTURE-dated row therefore never comes back + // → no snapshot → cutover throws → the throw propagates to @DfxCron → flag stays unset. + // The mock honours `to` like the real query does — a mock ignoring it would hide a dropped upper bound. const future = Object.assign(new Log(), { id: 1, created: new Date(Date.now() + 86400000), valid: true }); - jest.spyOn(logService, 'getFinancialLogs').mockResolvedValue([future]); + jest + .spyOn(logService, 'getFinancialLogs') + .mockImplementation( + async (_from?: Date, _dailySample?: boolean, to?: Date): Promise => + [future].filter((r) => !to || r.created.getTime() <= to.getTime()), + ); const setSpy = jest.spyOn(settingService, 'set').mockResolvedValue(); await expect(service.run()).rejects.toThrow('No valid FinancialDataLog snapshot available for cutover'); diff --git a/src/subdomains/core/accounting/services/__tests__/ledger-mark.service.spec.ts b/src/subdomains/core/accounting/services/__tests__/ledger-mark.service.spec.ts index dfdcbc2df7..0b29127d25 100644 --- a/src/subdomains/core/accounting/services/__tests__/ledger-mark.service.spec.ts +++ b/src/subdomains/core/accounting/services/__tests__/ledger-mark.service.spec.ts @@ -1,5 +1,6 @@ import { createMock } from '@golevelup/ts-jest'; import { Test, TestingModule } from '@nestjs/testing'; +import { Config } from 'src/config/config'; import { TestUtil } from 'src/shared/utils/test.util'; import { Util } from 'src/shared/utils/util'; import { createCustomLog } from 'src/subdomains/supporting/log/__mocks__/log.entity.mock'; @@ -7,8 +8,11 @@ import { Log } from 'src/subdomains/supporting/log/log.entity'; import { LogService } from 'src/subdomains/supporting/log/log.service'; import { LedgerMarkService } from '../ledger-mark.service'; +let nextLogId = 1; + function financialLog(created: Date, assets: Record): Log { return createCustomLog({ + id: nextLogId++, system: 'LogService', subsystem: 'FinancialDataLog', created, @@ -16,6 +20,46 @@ function financialLog(created: Date, assets: Record Promise; + +/** + * Fake `getFinancialLogs` that honours from/to/limit/after like the repository keyset query. + * Pagination tests must use this — rigid mockResolvedValueOnce chains ignore limit and hide data-loss bugs. + * `after` is the id-only cursor (number); filter is the production row-value compare + * `(created, id) > (cursor.created, cursor.id)` after resolving the cursor row from `allRows` by id. + */ +function fakeGetFinancialLogs(allRows: Log[]): FakeGetFinancialLogs { + return async (from?: Date, _dailySample?: boolean, to?: Date, limit?: number, after?: number): Promise => { + let rows = [...allRows].sort((a, b) => { + const byCreated = a.created.getTime() - b.created.getTime(); + return byCreated !== 0 ? byCreated : a.id - b.id; + }); + + if (from) rows = rows.filter((r) => r.created.getTime() >= from.getTime()); + if (to) rows = rows.filter((r) => r.created.getTime() <= to.getTime()); + if (after != null) { + // Cursor row may sit outside the from/to window — resolve it from the full set, not the filtered page. + const cursor = allRows.find((r) => r.id === after); + if (!cursor) throw new Error(`Financial log cursor row ${after} no longer exists`); + rows = rows.filter( + (r) => + r.created.getTime() > cursor.created.getTime() || + (r.created.getTime() === cursor.created.getTime() && r.id > cursor.id), + ); + } + if (limit != null) rows = rows.slice(0, limit); + + return rows; + }; +} + describe('LedgerMarkService', () => { let service: LedgerMarkService; let logService: LogService; @@ -58,13 +102,20 @@ describe('LedgerMarkService', () => { expect(await service.getLatestMark(999)).toBeUndefined(); }); - it('ignores logs created after now (upper-bound ≤ now)', async () => { - jest.spyOn(logService, 'getFinancialLogs').mockResolvedValue([ - financialLog(daysAgo(1), { '7': { priceChf: 110 } }), - financialLog(new Date(Date.now() + 60_000), { '7': { priceChf: 999 } }), // future → excluded - ]); + it('requests financial logs with upper bound to = asOf (SQL-side ≤ now)', async () => { + const spy = jest + .spyOn(logService, 'getFinancialLogs') + .mockResolvedValue([financialLog(daysAgo(1), { '7': { priceChf: 110 } })]); - expect(await service.getLatestMark(7)).toBe(110); + await service.getLatestMark(7); + + expect(spy).toHaveBeenCalledTimes(1); + const [, dailySample, to] = spy.mock.calls[0]; + expect(dailySample).toBe(true); + expect(to).toBeInstanceOf(Date); + // asOf is captured at call time as new Date(Date.now()); within a few ms of "now" + expect((to as Date).getTime()).toBeLessThanOrEqual(Date.now()); + expect((to as Date).getTime()).toBeGreaterThan(Date.now() - 5_000); }); }); @@ -91,7 +142,7 @@ describe('LedgerMarkService', () => { await service.getMarkAtWidened(5, asOf, 90); - expect(spy).toHaveBeenCalledWith(Util.daysBefore(90, asOf), true); // 90d span > threshold → dailySample + expect(spy).toHaveBeenCalledWith(Util.daysBefore(90, asOf), true, asOf, Config.ledger.markPreloadMaxRows + 1); }); it('never returns a mark created after asOf', async () => { @@ -216,7 +267,12 @@ describe('LedgerMarkService', () => { await service.preload(new Date('2026-06-01'), new Date('2026-06-10')); // 9 days > threshold 2 - expect(spy).toHaveBeenCalledWith(new Date('2026-06-01'), true); // dailySample = true + expect(spy).toHaveBeenCalledWith( + new Date('2026-06-01'), + true, + new Date('2026-06-10'), + Config.ledger.markPreloadMaxRows + 1, + ); }); it('uses the full minute-tick for fresh windows within the threshold', async () => { @@ -226,22 +282,29 @@ describe('LedgerMarkService', () => { await service.preload(new Date('2026-06-01'), new Date('2026-06-01T06:00:00Z')); // < 2 days - expect(spy).toHaveBeenCalledWith(new Date('2026-06-01'), false); // full tick + expect(spy).toHaveBeenCalledWith( + new Date('2026-06-01'), + false, + new Date('2026-06-01T06:00:00Z'), + Config.ledger.markPreloadMaxRows + 1, + ); }); - it('trims log rows whose created is strictly after `to` (upper-bound filter before pagination)', async () => { - jest.spyOn(logService, 'getFinancialLogs').mockResolvedValue([ - financialLog(new Date('2026-06-01'), { '5': { priceChf: 50000 } }), - financialLog(new Date('2026-06-03'), { '5': { priceChf: 52000 } }), // beyond `to` → must be dropped - ]); + it('passes to and limit (maxRows + 1) on the preload trigger read', async () => { + const to = new Date('2026-06-02'); + const spy = jest + .spyOn(logService, 'getFinancialLogs') + .mockResolvedValue([financialLog(new Date('2026-06-01'), { '5': { priceChf: 50000 } })]); - const cache = await service.preload(new Date('2026-06-01'), new Date('2026-06-02')); + await service.preload(new Date('2026-06-01'), to); - expect(cache.getMarkAt(5, new Date('2026-06-02'))).toBe(50000); // only the in-window row survives, NOT 52000 + // Upper bound and row cap are enforced in SQL (no post-load JS filter); +1 keeps overflow detectable. + expect(spy).toHaveBeenCalledWith(new Date('2026-06-01'), false, to, Config.ledger.markPreloadMaxRows + 1); }); // §5.2 step 3 pagination backstop: when the first bounded read returns more than markPreloadMaxRows rows the service - // re-loads in created-continuation windows. With markPreloadMaxRows=1 the first read (2 rows) trips the backstop. + // continues via keyset pages over id (created resolved in-DB). With markPreloadMaxRows=1 the first read (2 rows) + // trips the backstop; the probe's first maxRows rows are reused as page 1. describe('pagination backstop (rows > markPreloadMaxRows)', () => { let pagedService: LedgerMarkService; @@ -250,7 +313,7 @@ describe('LedgerMarkService', () => { providers: [ // override BOTH ledger fields (Object.assign is shallow → a partial ledger would drop the threshold) TestUtil.provideConfig({ - ledger: { markPreloadMaxRows: 1, markPreloadDailySampleThresholdDays: 2 } as any, + ledger: { markPreloadMaxRows: 1, markPreloadDailySampleThresholdDays: 2 }, }), LedgerMarkService, { provide: LogService, useValue: logService }, @@ -259,19 +322,12 @@ describe('LedgerMarkService', () => { pagedService = module.get(LedgerMarkService); }); - it('re-loads via created-continuation windows and walks the cache across windows', async () => { + it('re-loads via keyset pages and walks the cache across windows', async () => { const w1a = financialLog(new Date('2026-06-01T00:00:00Z'), { '5': { priceChf: 50000 } }); const w1b = financialLog(new Date('2026-06-01T01:00:00Z'), { '5': { priceChf: 51000 } }); const w2 = financialLog(new Date('2026-06-01T02:00:00Z'), { '5': { priceChf: 52000 } }); - const spy = jest.spyOn(logService, 'getFinancialLogs'); - // first call (the trigger read) returns 2 rows > maxRows(1) → backstop kicks in; - // paginate then re-queries from the windowStart cursor. - spy - .mockResolvedValueOnce([w1a, w1b]) // trigger read: > maxRows → paginate - .mockResolvedValueOnce([w1a, w1b]) // window 1: 2 rows, lastCreated advances the cursor - .mockResolvedValueOnce([w2]) // window 2: 1 row < maxRows → loop stops after this window - .mockResolvedValue([]); + const spy = jest.spyOn(logService, 'getFinancialLogs').mockImplementation(fakeGetFinancialLogs([w1a, w1b, w2])); const cache = await pagedService.preload(new Date('2026-06-01T00:00:00Z'), new Date('2026-06-01T03:00:00Z')); @@ -283,40 +339,227 @@ describe('LedgerMarkService', () => { expect(cache.getMarkAt(5, new Date('2026-06-01T02:30:00Z'))).toBe(52000); }); - it('stops the pagination loop on the first empty window (no infinite loop)', async () => { - const trigger = [ - financialLog(new Date('2026-06-01T00:00:00Z'), { '5': { priceChf: 50000 } }), - financialLog(new Date('2026-06-01T01:00:00Z'), { '5': { priceChf: 51000 } }), - ]; + // Regression B: created-only continuation with maxRows=1 re-fetched page-1's sole row forever and dropped the rest. + it('keeps every row when markPreloadMaxRows is 1 (no silent drop of the second created)', async () => { + const r1 = financialLog(new Date('2026-06-01T00:00:00Z'), { '5': { priceChf: 50000 } }); + const r2 = financialLog(new Date('2026-06-01T01:00:00Z'), { '5': { priceChf: 51000 } }); + + jest.spyOn(logService, 'getFinancialLogs').mockImplementation(fakeGetFinancialLogs([r1, r2])); + + const cache = await pagedService.preload(new Date('2026-06-01T00:00:00Z'), new Date('2026-06-01T03:00:00Z')); + + expect(cache.getMarkAt(5, new Date('2026-06-01T00:30:00Z'))).toBe(50000); + expect(cache.getMarkAt(5, new Date('2026-06-01T01:30:00Z'))).toBe(51000); + }); + + // Non-monotone ids: a later `created` can carry a smaller id than the cursor. Production compares + // `(created, id)` lexicographically; an id-only `id > after` filter would drop the second row. + it('keeps rows with non-monotone ids via lexicographic (created, id) keyset cursor', async () => { + const t0 = new Date('2026-06-01T00:00:00Z'); + const t1 = new Date('2026-06-01T01:00:00Z'); + const rowA = createCustomLog({ + id: 200, + system: 'LogService', + subsystem: 'FinancialDataLog', + created: t0, + message: JSON.stringify({ assets: { '5': { priceChf: 50000 } } }), + }); + const rowB = createCustomLog({ + id: 50, + system: 'LogService', + subsystem: 'FinancialDataLog', + created: t1, + message: JSON.stringify({ assets: { '6': { priceChf: 51000 } } }), + }); + + jest.spyOn(logService, 'getFinancialLogs').mockImplementation(fakeGetFinancialLogs([rowA, rowB])); + + const cache = await pagedService.preload(t0, new Date('2026-06-01T03:00:00Z')); + + expect(cache.getMarkAt(5, t0)).toBe(50000); + expect(cache.getMarkAt(6, t1)).toBe(51000); + }); + + it('excludes rows with created after to from the cache (SQL upper bound is respected)', async () => { + const inRange = financialLog(new Date('2026-06-01T00:00:00Z'), { '5': { priceChf: 50000 } }); + const alsoInRange = financialLog(new Date('2026-06-01T01:00:00Z'), { '5': { priceChf: 51000 } }); + const afterTo = financialLog(new Date('2026-06-01T04:00:00Z'), { '5': { priceChf: 99999 } }); + const to = new Date('2026-06-01T03:00:00Z'); + const spy = jest .spyOn(logService, 'getFinancialLogs') - .mockResolvedValueOnce(trigger) // trigger read → paginate - .mockResolvedValueOnce([]); // first window already empty → break immediately + .mockImplementation(fakeGetFinancialLogs([inRange, alsoInRange, afterTo])); + + const cache = await pagedService.preload(new Date('2026-06-01T00:00:00Z'), to); + + expect(cache.getMarkAt(5, new Date('2026-06-01T00:30:00Z'))).toBe(50000); + expect(cache.getMarkAt(5, new Date('2026-06-01T01:30:00Z'))).toBe(51000); + // too-late row must not leak into the cache (lookup at/after its created still shows the last in-range mark) + expect(cache.getMarkAt(5, afterTo.created)).toBe(51000); + expect(cache.getMarkAt(5, afterTo.created)).not.toBe(99999); + // every call passes the same upper bound + for (const call of spy.mock.calls) { + expect(call[2]).toEqual(to); + } + }); + + it('returns an empty cache when no financial logs fall in the window', async () => { + const spy = jest.spyOn(logService, 'getFinancialLogs').mockImplementation(fakeGetFinancialLogs([])); const cache = await pagedService.preload(new Date('2026-06-01T00:00:00Z'), new Date('2026-06-01T03:00:00Z')); - expect(spy).toHaveBeenCalledTimes(2); // trigger + one empty window, then break - expect(cache.getMarkAt(5, new Date('2026-06-01T00:30:00Z'))).toBeUndefined(); // empty window → empty cache + expect(spy).toHaveBeenCalledTimes(1); // trigger only — empty, no pagination + expect(cache.getMarkAt(5, new Date('2026-06-01T00:30:00Z'))).toBeUndefined(); }); - it('breaks when a window does not advance the created cursor (lastCreated <= windowStart guard)', async () => { - // every paginated window returns the SAME single timestamp at/below windowStart → the lastCreated<=windowStart - // guard breaks the loop instead of re-querying the identical window forever. - const stuck = financialLog(new Date('2026-06-01T00:00:00Z'), { '5': { priceChf: 50000 } }); - const trigger = [ - stuck, - financialLog(new Date('2026-06-01T00:00:00Z'), { '6': { priceChf: 2 } }), // same created → 2 rows > maxRows - ]; + // §5.2 precision fix: log.created is timestamp(6) in Postgres (microsecond precision) but JS `Date` + // only carries milliseconds - reading a row truncates e.g. ...841802 -> ...841. A (created, id)-Date + // cursor sent back to the DB compares this truncated value against the SAME row's full-precision + // column, and ...841802 > ...841000 is true, so the row that WAS the cursor reappears (duplicate / + // infinite loop at markPreloadMaxRows=1). The id-only cursor removes the Date round-trip entirely: + // the DB resolves `created` for :afterId itself, at full precision - this failure mode becomes + // structurally impossible. + describe('microsecond-precision cursor (regression: a Date-based cursor duplicates the cursor row)', () => { + it('the new id-only cursor never re-includes the cursor row: rows sharing a millisecond are each emitted exactly once, pagination terminates', async () => { + // All three rows carry the SAME JS-representable millisecond. In Postgres they differ only in the + // microsecond remainder, which a JS Date cannot hold — so a Date-based cursor could not tell them + // apart and re-included the cursor row. The id-only cursor is immune by construction. + const sameMs = new Date('2026-07-29T11:51:46.841Z').getTime(); + const rows = [ + financialLog(new Date(sameMs), { '5': { priceChf: 1 } }), + financialLog(new Date(sameMs), { '6': { priceChf: 2 } }), + financialLog(new Date(sameMs), { '7': { priceChf: 3 } }), + ]; + + // pagedService here = the pagination-backstop describe-block's service instance with + // markPreloadMaxRows = 1 (see that block's beforeEach) - reuse it, do not rebuild a separate module. + const spy = jest.spyOn(logService, 'getFinancialLogs').mockImplementation(fakeGetFinancialLogs(rows)); + + const cache = await pagedService.preload(new Date(sameMs), new Date(sameMs)); + + expect(cache.getMarkAt(5, new Date(sameMs))).toBe(1); + expect(cache.getMarkAt(6, new Date(sameMs))).toBe(2); + expect(cache.getMarkAt(7, new Date(sameMs))).toBe(3); + expect(spy.mock.calls.length).toBeLessThan(10); // terminates - no infinite loop + + // structural guarantee: the cursor argument passed to getFinancialLogs is always a plain id + // (number), never a Date - so there is no JS-truncated timestamp for the DB to compare at all. + for (const call of spy.mock.calls) { + const afterArg = call[4]; + if (afterArg !== undefined) expect(typeof afterArg).toBe('number'); + } + }); + }); + }); + + // SQL limit can end a page mid-group of rows that share the same `created`; keyset after id + // must continue past the tie without re-emitting seen rows or dropping the rest of the group. + describe('pagination mid-group created tie (SQL limit cuts a same-created group)', () => { + let pagedService: LedgerMarkService; + + beforeEach(async () => { + const module: TestingModule = await Test.createTestingModule({ + providers: [ + TestUtil.provideConfig({ + ledger: { markPreloadMaxRows: 2, markPreloadDailySampleThresholdDays: 2 }, + }), + LedgerMarkService, + { provide: LogService, useValue: logService }, + ], + }).compile(); + pagedService = module.get(LedgerMarkService); + }); + + // Regression A: a same-created group larger than maxRows used to stall (newRows empty) and drop remaining rows. + it('does not lose rows when a same-created group is larger than maxRows', async () => { + const batchStart = new Date('2026-06-01T00:00:00Z'); + const to = new Date('2026-06-01T23:59:59Z'); + const sameCreated = new Date('2026-06-01T12:00:00Z'); + const r1 = financialLog(sameCreated, { '5': { priceChf: 1 } }); + const r2 = financialLog(sameCreated, { '6': { priceChf: 2 } }); + const r3 = financialLog(sameCreated, { '7': { priceChf: 3 } }); + const r4 = financialLog(new Date('2026-06-01T18:00:00Z'), { '8': { priceChf: 4 } }); + + const spy = jest.spyOn(logService, 'getFinancialLogs').mockImplementation(fakeGetFinancialLogs([r1, r2, r3, r4])); + + const cache = await pagedService.preload(batchStart, to); + + // all four rows land — three-way created tie + later distinct created + expect(cache.getMarkAt(5, to)).toBe(1); + expect(cache.getMarkAt(6, to)).toBe(2); + expect(cache.getMarkAt(7, to)).toBe(3); + expect(cache.getMarkAt(8, to)).toBe(4); + // finite number of calls — keyset advances; no infinite re-query of the tie-group + expect(spy.mock.calls.length).toBeLessThan(10); + }); + + // Overflow reuse: probe reads maxRows+1, reuses first maxRows as page 1, continues from that last id. + // Without reuse: 1 probe + 3 pages = 4 calls. With reuse: 1 probe + 2 continuation pages = 3. + it('reuses the overflow probe as page 1 (no double-read of the first maxRows rows)', async () => { + const batchStart = new Date('2026-06-01T00:00:00Z'); + const to = new Date('2026-06-01T23:59:59Z'); + const r1 = financialLog(new Date('2026-06-01T01:00:00Z'), { '5': { priceChf: 10 } }); + const r2 = financialLog(new Date('2026-06-01T02:00:00Z'), { '5': { priceChf: 20 } }); + const r3 = financialLog(new Date('2026-06-01T03:00:00Z'), { '5': { priceChf: 30 } }); + const r4 = financialLog(new Date('2026-06-01T04:00:00Z'), { '5': { priceChf: 40 } }); + const r5 = financialLog(new Date('2026-06-01T05:00:00Z'), { '5': { priceChf: 50 } }); + const spy = jest .spyOn(logService, 'getFinancialLogs') - .mockResolvedValueOnce(trigger) // trigger read → paginate - .mockResolvedValue(trigger); // every window returns the same created → cursor cannot advance → break + .mockImplementation(fakeGetFinancialLogs([r1, r2, r3, r4, r5])); + + const cache = await pagedService.preload(batchStart, to); + + // all five marks land at their respective timestamps + expect(cache.getMarkAt(5, new Date('2026-06-01T01:30:00Z'))).toBe(10); + expect(cache.getMarkAt(5, new Date('2026-06-01T02:30:00Z'))).toBe(20); + expect(cache.getMarkAt(5, new Date('2026-06-01T03:30:00Z'))).toBe(30); + expect(cache.getMarkAt(5, new Date('2026-06-01T04:30:00Z'))).toBe(40); + expect(cache.getMarkAt(5, new Date('2026-06-01T05:30:00Z'))).toBe(50); + // markPreloadMaxRows=2: probe (3) + page after r2 (r3,r4) + page after r4 (r5) = 3 calls + expect(spy.mock.calls.length).toBe(3); + }); + }); - const cache = await pagedService.preload(new Date('2026-06-01T00:00:00Z'), new Date('2026-06-01T03:00:00Z')); + // dailySample=true pagination path: span > threshold so both getFinancialLogs branches' cursor logic is exercised + // under overflow (maxRows small enough that multi-page keyset runs). + describe('pagination with dailySample=true (span > markPreloadDailySampleThresholdDays)', () => { + let pagedService: LedgerMarkService; + + beforeEach(async () => { + const module: TestingModule = await Test.createTestingModule({ + providers: [ + // BOTH ledger fields required (shallow merge); low threshold so a multi-day span forces dailySample + TestUtil.provideConfig({ + ledger: { markPreloadMaxRows: 1, markPreloadDailySampleThresholdDays: 2 }, + }), + LedgerMarkService, + { provide: LogService, useValue: logService }, + ], + }).compile(); + pagedService = module.get(LedgerMarkService); + }); - // it must NOT spin: the guard breaks after the first (non-advancing) window - expect(spy.mock.calls.length).toBeLessThan(5); - expect(cache.getMarkAt(5, new Date('2026-06-01T00:00:00Z'))).toBe(50000); + it('paginates with dailySample=true on overflow and keeps every mark', async () => { + // 9-day span > threshold 2 → dailySample true; 3 rows > maxRows 1 → multi-page keyset + const batchStart = new Date('2026-06-01T00:00:00Z'); + const to = new Date('2026-06-10T00:00:00Z'); + const r1 = financialLog(new Date('2026-06-01T00:00:00Z'), { '5': { priceChf: 100 } }); + const r2 = financialLog(new Date('2026-06-05T00:00:00Z'), { '5': { priceChf: 200 } }); + const r3 = financialLog(new Date('2026-06-09T00:00:00Z'), { '5': { priceChf: 300 } }); + + const spy = jest.spyOn(logService, 'getFinancialLogs').mockImplementation(fakeGetFinancialLogs([r1, r2, r3])); + + const cache = await pagedService.preload(batchStart, to); + + expect(cache.getMarkAt(5, new Date('2026-06-01T12:00:00Z'))).toBe(100); + expect(cache.getMarkAt(5, new Date('2026-06-05T12:00:00Z'))).toBe(200); + expect(cache.getMarkAt(5, new Date('2026-06-09T12:00:00Z'))).toBe(300); + // every call (probe + continuation pages) must request dailySample + expect(spy.mock.calls.length).toBeGreaterThan(1); + for (const call of spy.mock.calls) { + expect(call[1]).toBe(true); + } }); }); }); diff --git a/src/subdomains/core/accounting/services/ledger-cutover.service.ts b/src/subdomains/core/accounting/services/ledger-cutover.service.ts index ebaef83cfb..a2be82840d 100644 --- a/src/subdomains/core/accounting/services/ledger-cutover.service.ts +++ b/src/subdomains/core/accounting/services/ledger-cutover.service.ts @@ -179,13 +179,12 @@ export class LedgerCutoverService { return repinned != null && +repinned !== snapshot.id ? this.logService.getLog(+repinned) : snapshot; } - // §6.3: newest valid=true FinancialDataLog ≤ cutoff date. Bounded read (last 2 days) then pick latest ≤ now. + // §6.3: newest valid=true FinancialDataLog ≤ cutoff date. Bounded read (last 2 days, to=now in SQL) then pick latest. private async selectSnapshot(): Promise { const now = new Date(); - const candidates = await this.logService.getFinancialLogs(Util.daysBefore(2, now)); - const valid = candidates.filter((l) => l.created.getTime() <= now.getTime()); + const candidates = await this.logService.getFinancialLogs(Util.daysBefore(2, now), false, now); - return valid.length ? Util.maxObj(valid, 'created') : undefined; + return candidates.length ? Util.maxObj(candidates, 'created') : undefined; } private parseFinance(message: string): FinanceLog | undefined { diff --git a/src/subdomains/core/accounting/services/ledger-mark.service.ts b/src/subdomains/core/accounting/services/ledger-mark.service.ts index 9db293abc3..4aea62f446 100644 --- a/src/subdomains/core/accounting/services/ledger-mark.service.ts +++ b/src/subdomains/core/accounting/services/ledger-mark.service.ts @@ -85,9 +85,7 @@ export class LedgerMarkService { if (this.latestMarks && now - this.latestMarks.loadedAt < LATEST_MARK_TTL_MS) return this.latestMarks.map; const asOf = new Date(now); - const rows = ( - await this.logService.getFinancialLogs(Util.daysBefore(LATEST_MARK_LOOKBACK_DAYS, asOf), true) - ).filter((r) => r.created.getTime() <= asOf.getTime()); + const rows = await this.logService.getFinancialLogs(Util.daysBefore(LATEST_MARK_LOOKBACK_DAYS, asOf), true, asOf); const map = new Map(); for (const row of rows) { @@ -140,43 +138,58 @@ export class LedgerMarkService { /** * Bounded preload (§5.2, Hard Constraint #4): always limited by (batchStartDate, to) and maxRows. * Order is fixed — dailySample decision FIRST (avoids loading the full minute-tick), THEN upper-bound - * trimming, THEN the maxRows pagination backstop. + * trimming, THEN the maxRows pagination backstop (keyset over id; created resolved in-DB). */ async preload(batchStartDate: Date, to: Date): Promise { const spanDays = Util.daysDiff(batchStartDate, to); const dailySample = spanDays > Config.ledger.markPreloadDailySampleThresholdDays; + const maxRows = this.getMarkPreloadMaxRows(); - let rows = await this.logService.getFinancialLogs(batchStartDate, dailySample); - rows = rows.filter((r) => r.created.getTime() <= to.getTime()); + // +1 so probeRows.length > maxRows can still detect overflow when SQL already caps at maxRows + const probeRows = await this.logService.getFinancialLogs(batchStartDate, dailySample, to, maxRows + 1); - if (rows.length > Config.ledger.markPreloadMaxRows) { - rows = await this.paginate(batchStartDate, to, dailySample); - } + const rows = + probeRows.length > maxRows + ? await this.paginate(batchStartDate, to, dailySample, probeRows.slice(0, maxRows)) + : probeRows; return new LedgerMarkCache(this.buildMarkMap(rows)); } - // created-continuation windows; never load everything into one heap (§5.2 step 3) - private async paginate(batchStartDate: Date, to: Date, dailySample: boolean): Promise { - const result: Log[] = []; - let windowStart = batchStartDate; - - while (windowStart.getTime() <= to.getTime()) { - const window = (await this.logService.getFinancialLogs(windowStart, dailySample)).filter( - (r) => r.created.getTime() <= to.getTime(), - ); + // Keyset pages over id; never load everything into one heap (§5.2 step 3). + // `firstPage` reuses the rows preload() already read via the overflow probe (the same maxRows-sized + // first page a from-scratch pagination would produce, since both share the same filters/order/limit= + // maxRows and deterministic ORDER BY created ASC, id ASC) — so the probe read is not thrown away and + // re-fetched. Halves the data read on overflow, result set stays identical to full re-pagination. + private async paginate(batchStartDate: Date, to: Date, dailySample: boolean, firstPage: Log[]): Promise { + const maxRows = this.getMarkPreloadMaxRows(); + const result: Log[] = [...firstPage]; + let after: number | undefined = firstPage[firstPage.length - 1]?.id; + + // Keyset continuation: each page starts strictly after the last returned id. + while (true) { + const window = await this.logService.getFinancialLogs(batchStartDate, dailySample, to, maxRows, after); if (!window.length) break; result.push(...window); - const lastCreated = window[window.length - 1].created; - if (window.length < Config.ledger.markPreloadMaxRows || lastCreated.getTime() <= windowStart.getTime()) break; + if (window.length < maxRows) break; - windowStart = new Date(lastCreated.getTime() + 1); + after = window[window.length - 1].id; } return result; } + // Fail loud on a non-positive / non-integer markPreloadMaxRows (e.g. LEDGER_MARK_PRELOAD_MAX_ROWS=0 or + // a broken env parse): LIMIT 0 / empty first page would otherwise silently build an empty cache. + private getMarkPreloadMaxRows(): number { + const value = Config.ledger.markPreloadMaxRows; + if (!Number.isInteger(value) || value <= 0) { + throw new Error(`Invalid LEDGER_MARK_PRELOAD_MAX_ROWS: expected a positive integer, got ${String(value)}`); + } + return value; + } + private buildMarkMap(rows: Log[]): Map { const marks = new Map(); diff --git a/src/subdomains/supporting/log/__tests__/log.repository.spec.ts b/src/subdomains/supporting/log/__tests__/log.repository.spec.ts index a9a1ae3854..6da4f4bbe2 100644 --- a/src/subdomains/supporting/log/__tests__/log.repository.spec.ts +++ b/src/subdomains/supporting/log/__tests__/log.repository.spec.ts @@ -2,10 +2,34 @@ import { EntityManager, UpdateResult } from 'typeorm'; import { FINANCIAL_LOG_VALIDITY_AUDIT_SUBSYSTEM } from '../log.entity'; import { LogRepository } from '../log.repository'; +type UpdateQueryBuilderStub = { + update: jest.Mock; + set: jest.Mock; + where: jest.Mock; + andWhere: jest.Mock; + execute: jest.Mock; +}; + +type FinancialLogQueryBuilderStub = { + where: jest.Mock; + andWhere: jest.Mock; + orderBy: jest.Mock; + addOrderBy: jest.Mock; + groupBy: jest.Mock; + limit: jest.Mock; + take: jest.Mock; + select: jest.Mock; + setParameters: jest.Mock; + getQuery: jest.Mock; + getParameters: jest.Mock; + getExists: jest.Mock; + getMany: jest.Mock; +}; + // Minimal chainable stub for the update query builder: every condition call returns itself, and // execute() reports how many rows the batch touched. -function updateQueryBuilderStub(affected: number | null | undefined) { - const builder = { +function updateQueryBuilderStub(affected: number | null | undefined): UpdateQueryBuilderStub { + const builder: UpdateQueryBuilderStub = { update: jest.fn().mockReturnThis(), set: jest.fn().mockReturnThis(), where: jest.fn().mockReturnThis(), @@ -16,6 +40,28 @@ function updateQueryBuilderStub(affected: number | null | undefined) { return builder; } +// Chainable stub for the main getFinancialLogs query path (getMany) and the post-empty cursor guard (getExists). +// Same stub instance serves both createQueryBuilder calls; getExists is only consulted after an empty main result. +function financialLogQueryBuilderStub(exists: boolean): FinancialLogQueryBuilderStub { + const builder: FinancialLogQueryBuilderStub = { + where: jest.fn().mockReturnThis(), + andWhere: jest.fn().mockReturnThis(), + orderBy: jest.fn().mockReturnThis(), + addOrderBy: jest.fn().mockReturnThis(), + groupBy: jest.fn().mockReturnThis(), + limit: jest.fn().mockReturnThis(), + take: jest.fn().mockReturnThis(), + select: jest.fn().mockReturnThis(), + setParameters: jest.fn().mockReturnThis(), + getQuery: jest.fn().mockReturnValue(''), + getParameters: jest.fn().mockReturnValue({}), + getExists: jest.fn().mockResolvedValue(exists), + getMany: jest.fn().mockResolvedValue([]), + }; + + return builder; +} + describe('LogRepository', () => { it('constructs against the provided entity manager', () => { const repo = new LogRepository({} as EntityManager); @@ -77,4 +123,68 @@ describe('LogRepository', () => { ); }); }); + + describe('getFinancialLogs cursor guard', () => { + it('fails loud when the keyset cursor id no longer exists (no silent empty main query)', async () => { + const repo = new LogRepository({} as EntityManager); + const stub = financialLogQueryBuilderStub(false); + jest.spyOn(repo, 'createQueryBuilder').mockReturnValue(stub as never); + + await expect(repo.getFinancialLogs(undefined, false, undefined, undefined, 999)).rejects.toThrow( + 'Financial log cursor row 999 no longer exists', + ); + + // Main query runs first; guard only after empty result + set after. + expect(stub.getMany).toHaveBeenCalled(); + expect(stub.getExists).toHaveBeenCalled(); + }); + + it('returns empty when the cursor still exists (legitimate end-of-data)', async () => { + const repo = new LogRepository({} as EntityManager); + const stub = financialLogQueryBuilderStub(true); + jest.spyOn(repo, 'createQueryBuilder').mockReturnValue(stub as never); + + await expect(repo.getFinancialLogs(undefined, false, undefined, undefined, 999)).resolves.toEqual([]); + + expect(stub.getMany).toHaveBeenCalled(); + expect(stub.getExists).toHaveBeenCalled(); + }); + + it('skips the existence check when after is unset', async () => { + const repo = new LogRepository({} as EntityManager); + const stub = financialLogQueryBuilderStub(false); + jest.spyOn(repo, 'createQueryBuilder').mockReturnValue(stub as never); + + await expect(repo.getFinancialLogs(undefined, false)).resolves.toEqual([]); + + expect(stub.getMany).toHaveBeenCalled(); + expect(stub.getExists).not.toHaveBeenCalled(); + }); + + it('skips the existence check when the main query returns rows', async () => { + const repo = new LogRepository({} as EntityManager); + const stub = financialLogQueryBuilderStub(false); + const page = [{ id: 1 } as never]; + stub.getMany.mockResolvedValueOnce(page); + jest.spyOn(repo, 'createQueryBuilder').mockReturnValue(stub as never); + + await expect(repo.getFinancialLogs(undefined, false, undefined, undefined, 999)).resolves.toBe(page); + + expect(stub.getMany).toHaveBeenCalled(); + expect(stub.getExists).not.toHaveBeenCalled(); + }); + + it('fails loud on the dailySample path when the cursor id no longer exists', async () => { + const repo = new LogRepository({} as EntityManager); + const stub = financialLogQueryBuilderStub(false); + jest.spyOn(repo, 'createQueryBuilder').mockReturnValue(stub as never); + + await expect(repo.getFinancialLogs(undefined, true, undefined, undefined, 999)).rejects.toThrow( + 'Financial log cursor row 999 no longer exists', + ); + + expect(stub.getMany).toHaveBeenCalled(); + expect(stub.getExists).toHaveBeenCalled(); + }); + }); }); diff --git a/src/subdomains/supporting/log/log.repository.ts b/src/subdomains/supporting/log/log.repository.ts index e52c4ffe74..fc55654bb8 100644 --- a/src/subdomains/supporting/log/log.repository.ts +++ b/src/subdomains/supporting/log/log.repository.ts @@ -130,7 +130,20 @@ export class LogRepository extends BaseRepository { } // Filters valid = true so chart series skip spike/glitch snapshots; use getLatestFinancialLog for exact numeric values. - async getFinancialLogs(from?: Date, dailySample?: boolean): Promise { + // Optional `after` keyset cursor is the id of the last row of the previous page (never a Date / created value). + // Ordering remains (created ASC, id ASC); the cursor comparison is a Postgres row-value `(created, id) > (...)` + // where `created` for `:afterId` is resolved in a correlated subquery at full timestamp(6) microsecond precision. + // That avoids round-tripping `created` through JS `Date` (ms only), which would truncate and re-include the cursor row. + // Main query runs first. Only when it returns empty with a set `after` does assertEmptyResultIsEndOfData run: a + // deleted cursor id would make the subquery NULL and the WHERE exclude every row, which callers would misread as + // end-of-data. Non-empty pages skip the existence check (no extra round-trip). + async getFinancialLogs( + from?: Date, + dailySample?: boolean, + to?: Date, + limit?: number, + after?: number, // id of the last row of the previous page; NEVER a Date/created value + ): Promise { if (dailySample) { const subQuery = this.createQueryBuilder('subLog') .select('MAX(subLog.id)', 'max_id') @@ -143,27 +156,75 @@ export class LogRepository extends BaseRepository { let query = this.createQueryBuilder('log') .where(`log.id IN (${subQuery.getQuery()})`) .setParameters(subQuery.getParameters()) - .orderBy('log.created', 'ASC'); + .orderBy('log.created', 'ASC') + .addOrderBy('log.id', 'ASC'); if (from) { query = query.andWhere('log.created >= :from', { from }); } + if (to) { + query = query.andWhere('log.created <= :to', { to }); + } + if (after != null) { + // Row-value compare; subquery resolves created at full DB precision so JS Date truncation cannot re-include + // the cursor row. Empty results with a set after are checked via assertEmptyResultIsEndOfData below. + query = query.andWhere( + '(log.created, log.id) > ((SELECT c.created FROM log c WHERE c.id = :afterId), :afterId)', + { afterId: after }, + ); + } + if (limit != null) { + query = query.limit(limit); + } - return query.getMany(); + const rows = await query.getMany(); + if (!rows.length && after != null) await this.assertEmptyResultIsEndOfData(after); + return rows; } - const where: FindOptionsWhere = { - system: 'LogService', - subsystem: FINANCIAL_DATA_LOG_SUBSYSTEM, - severity: LogSeverity.INFO, - valid: true, - }; + // QueryBuilder (not find/FindOptionsWhere): the row-value keyset on (created, id) cannot be expressed cleanly otherwise. + let query = this.createQueryBuilder('log') + .where('log.system = :system', { system: 'LogService' }) + .andWhere('log.subsystem = :subsystem', { subsystem: FINANCIAL_DATA_LOG_SUBSYSTEM }) + .andWhere('log.severity = :severity', { severity: LogSeverity.INFO }) + .andWhere('log.valid = :valid', { valid: true }) + .orderBy('log.created', 'ASC') + .addOrderBy('log.id', 'ASC'); + + if (from && to) { + query = query.andWhere('log.created >= :from AND log.created <= :to', { from, to }); + } else if (from) { + query = query.andWhere('log.created >= :from', { from }); + } else if (to) { + query = query.andWhere('log.created <= :to', { to }); + } - if (from) { - where.created = MoreThanOrEqual(from); + if (after != null) { + // Row-value compare; subquery resolves created at full DB precision so JS Date truncation cannot re-include + // the cursor row. Empty results with a set after are checked via assertEmptyResultIsEndOfData below. + query = query.andWhere( + '(log.created, log.id) > ((SELECT c.created FROM log c WHERE c.id = :afterId), :afterId)', + { afterId: after }, + ); } - return this.find({ where, order: { created: 'ASC' } }); + if (limit != null) { + query = query.take(limit); + } + + const rows = await query.getMany(); + if (!rows.length && after != null) await this.assertEmptyResultIsEndOfData(after); + return rows; + } + + // After an empty main-query result with a keyset cursor, fail loud when the cursor id is gone: the row-value + // subquery would return NULL and `(created, id) > (NULL, :afterId)` is NULL in Postgres → WHERE excludes every + // row → silent empty result that callers misread as end-of-data. Only invoked when the main query already + // returned empty (and `after` is set), so non-empty pages pay no extra round-trip. Prefer an explicit error + // over that false EOF. + private async assertEmptyResultIsEndOfData(afterId: number): Promise { + const exists = await this.createQueryBuilder('log').where('log.id = :afterId', { afterId }).getExists(); + if (!exists) throw new Error(`Financial log cursor row ${afterId} no longer exists`); } // Resolves the rows the update would change, locking them until the surrounding transaction diff --git a/src/subdomains/supporting/log/log.service.ts b/src/subdomains/supporting/log/log.service.ts index 3338e82ad5..edc180269a 100644 --- a/src/subdomains/supporting/log/log.service.ts +++ b/src/subdomains/supporting/log/log.service.ts @@ -135,8 +135,14 @@ export class LogService { return this.logRepo.findOne({ where: { system, subsystem, severity, valid }, order: { id: 'DESC' } }); } - async getFinancialLogs(from?: Date, dailySample?: boolean): Promise { - return this.logRepo.getFinancialLogs(from, dailySample); + async getFinancialLogs( + from?: Date, + dailySample?: boolean, + to?: Date, + limit?: number, + after?: number, // id of the last row of the previous page; NEVER a Date/created value + ): Promise { + return this.logRepo.getFinancialLogs(from, dailySample, to, limit, after); } async getLatestFinancialLog(): Promise {