diff --git a/migration/1785530000000-MergeFinancialLogIndexes.js b/migration/1785530000000-MergeFinancialLogIndexes.js new file mode 100644 index 0000000000..654af3f584 --- /dev/null +++ b/migration/1785530000000-MergeFinancialLogIndexes.js @@ -0,0 +1,130 @@ +/** + * @typedef {import('typeorm').MigrationInterface} MigrationInterface + * @typedef {import('typeorm').QueryRunner} QueryRunner + */ + +/** + * Replace the two near-identical `log` indexes with a single combined index that serves both + * access paths. + * + * Starting point, measured in production: + * - `IDX_log_financial_query` on (system, subsystem, severity, valid, created, id) — 46 MB, + * 16687 idx_scan. Created by AddFinancialLogQueryIndex1785400000000. + * - `IDX_b7eda1156aca7b2a1302cdf88f` on (system, subsystem, severity, valid, created) + * INCLUDE ("totalBalanceChf", "btcPriceChf") — 42 MB, 25 idx_scan. Created by + * AddFinancialLogChartColumns1785520000000. + * + * The second index exists so the Overview chart query would be served by an Index Only Scan. It + * does not achieve that. The query selects `created, id, "totalBalanceChf", "btcPriceChf"` (see + * `LogRepository.getFinancialLogSummariesChartOnly`), and `id` is neither a key column nor an + * INCLUDE column of that index — so an Index Only Scan is impossible and the planner falls back to + * `IDX_log_financial_query`. What is left is a strictly narrower key prefix of the older index plus + * two payload columns that no plan can reach without a heap visit anyway: practically redundant + * rather than complementary, which the 25 scans against 16687 confirm. + * + * Production `EXPLAIN (ANALYZE, BUFFERS)`, both over the full 33136-row result (the query carries + * no LIMIT: its only caller passes `to`, `limit` and `after` as undefined throughout): + * - The real query, with `id` in the select list: Index Scan using `IDX_log_financial_query`, + * Buffers hit=2806 read=9222, 163.2 ms. + * - The same query with `id` removed from the select list: Index Only Scan using + * `IDX_b7eda1156aca7b2a1302cdf88f`, Heap Fetches 91, Buffers hit=2272 read=623, 12.8 ms. + * The conclusion this migration draws from those two numbers: the chart index was not worthless, + * it was cut wrong. The index-only plan it was meant to enable is roughly 13x faster and reads an + * order of magnitude fewer blocks from disk; the single column `id` is all that separates the two + * plans. + * + * The combined index fixes exactly that and nothing else. Its key columns + * (system, subsystem, severity, valid, created, id) are identical to those of + * `IDX_log_financial_query`, so every access path that index serves today — all 16687 scans, + * including the per-minute LedgerMarkService query it was built for — is served unchanged by the + * replacement, with the same ordering and the same selectivity. On top of that it carries + * "totalBalanceChf" and "btcPriceChf" as INCLUDE columns: payload only, not part of the key, so + * they change neither the ordering nor the search behaviour, but the chart query now finds all + * four of its selected columns inside the index and becomes Index-Only-Scan-capable. One index + * does both jobs, so both old ones are dropped. + * + * Index name `IDX_5e9ca4be25d4b828fe02a2dddf`: not a chosen name — custom index names are + * disallowed by CONTRIBUTING.md — but the deterministic name TypeORM's DefaultNamingStrategy + * produces for an index on `log` keyed by (system, subsystem, severity, valid, created, id): + * `IDX_` followed by the first 26 hex characters of + * sha1('log_created_id_severity_subsystem_system_valid') (table name, `_`, then the key column + * names sorted alphabetically and joined with `_`). INCLUDE columns are not part of that + * derivation. The formula was cross-checked by reproducing the existing name + * `IDX_b7eda1156aca7b2a1302cdf88f` from sha1('log_created_severity_subsystem_system_valid'). + * The physical key order stays (system, subsystem, severity, valid, created, id) as the access + * paths require; only the name derivation sorts the column names. + * + * CREATE INDEX CONCURRENTLY is not used: migrations in this codebase run transactionally and + * boot-blockingly (see `src/config/config.ts`, `migrationsRun` gated by the `SQL_MIGRATE` env var). + * CREATE INDEX CONCURRENTLY is not allowed inside a transaction and would crash the migration — + * the same reasoning as in the two predecessor migrations named above. + * + * Lock behaviour, stated precisely and without gloss: all pending migrations run inside a single + * database transaction (TypeORM default `migrationsTransactionMode: "all"`; see + * `node_modules/typeorm/data-source/DataSource.js`, `migrationExecutor.transaction = + * options?.transaction || this.options?.migrationsTransactionMode || "all"`, and + * `src/config/config.ts`, which sets only `migrationsRun` and never overrides that mode), and + * PostgreSQL releases locks at COMMIT, not at the end of each statement. + * - The `CREATE INDEX` holds a SHARE lock for the ENTIRE build, not briefly. Reads on `log` + * continue throughout; writes to `log` block for as long as the build runs. + * - Each `DROP INDEX` takes ACCESS EXCLUSIVE, which conflicts with every other lock mode including + * the AccessShareLock of a plain SELECT. Held until the migration transaction commits, it blocks + * reads on `log` as well as writes for that entire remaining window. + * The statement order in `up()` follows from this: build first, drop last, so the ACCESS EXCLUSIVE + * window starts as late as possible instead of also spanning the index build. It cannot be avoided, + * only kept short. For the same reason this migration is best deployed on its own: any other + * pending migration in the same batch stretches the window in which `log` is unreadable out to the + * shared COMMIT. + * `SET LOCAL lock_timeout` bounds only how long we WAIT to acquire a lock, never how long we hold + * it once acquired, and it is scoped to the whole transaction — hence set once at the top of `up()` + * and once at the top of `down()`, not per statement. + * `log` is 688 MB over 528920 rows. The build duration has not been measured against production + * data, so no upper bound is claimed here. + * + * No `IF EXISTS` / `IF NOT EXISTS` anywhere, deliberately: if one of the two expected indexes is + * already gone, the premise of this migration no longer holds, and it must fail loudly instead of + * quietly doing half the work and leaving the table in a state nobody described. + * + * The columns "totalBalanceChf" and "btcPriceChf" themselves are not touched. They are owned by + * AddFinancialLogChartColumns1785520000000; this migration only reshapes indexes. + * + * @class + * @implements {MigrationInterface} + */ +module.exports = class MergeFinancialLogIndexes1785530000000 { + name = 'MergeFinancialLogIndexes1785530000000'; + + /** + * @param {QueryRunner} queryRunner + */ + async up(queryRunner) { + // SET LOCAL is scoped to the whole transaction. Bounds WAIT time to acquire a lock, not how + // long a lock is held. Set once for all statements below. + await queryRunner.query(`SET LOCAL lock_timeout = '5s'`); + // Build first, drop last: keeps the ACCESS EXCLUSIVE window of the two DROPs as short as the + // single migration transaction allows. + await queryRunner.query( + `CREATE INDEX "IDX_5e9ca4be25d4b828fe02a2dddf" ON "log" ("system", "subsystem", "severity", "valid", "created", "id") INCLUDE ("totalBalanceChf", "btcPriceChf")`, + ); + await queryRunner.query(`DROP INDEX "public"."IDX_b7eda1156aca7b2a1302cdf88f"`); + await queryRunner.query(`DROP INDEX "public"."IDX_log_financial_query"`); + } + + /** + * @param {QueryRunner} queryRunner + */ + async down(queryRunner) { + // SET LOCAL is scoped to the whole transaction. Bounds WAIT time to acquire a lock, not how + // long a lock is held. Set once for all statements below. + await queryRunner.query(`SET LOCAL lock_timeout = '5s'`); + // Exact inverse of up(): both predecessor indexes are recreated verbatim as their originating + // migrations wrote them, and only then is the combined index dropped. + await queryRunner.query( + `CREATE INDEX "IDX_b7eda1156aca7b2a1302cdf88f" ON "log" ("system", "subsystem", "severity", "valid", "created") INCLUDE ("totalBalanceChf", "btcPriceChf")`, + ); + await queryRunner.query( + `CREATE INDEX "IDX_log_financial_query" ON "log" ("system", "subsystem", "severity", "valid", "created", "id")`, + ); + await queryRunner.query(`DROP INDEX "public"."IDX_5e9ca4be25d4b828fe02a2dddf"`); + } +}; diff --git a/src/integration/blockchain/bitcoin/services/__tests__/bitcoin-fee.service.spec.ts b/src/integration/blockchain/bitcoin/services/__tests__/bitcoin-fee.service.spec.ts index 0809ee1479..6f518f03fc 100644 --- a/src/integration/blockchain/bitcoin/services/__tests__/bitcoin-fee.service.spec.ts +++ b/src/integration/blockchain/bitcoin/services/__tests__/bitcoin-fee.service.spec.ts @@ -41,17 +41,12 @@ describe('BitcoinFeeService', () => { }); it('should throw when fee estimation fails and no cache available', async () => { - // The AsyncCache with fallbackToCache=true will try to use cached value first - // On first call with null, it should throw if there's no cached value + // fallbackToCache=true only substitutes a cached value when one exists. On the first call + // nothing is cached, so the error has to surface rather than being swallowed into undefined. mockClient.estimateSmartFee.mockResolvedValueOnce(null); - // Since AsyncCache catches the error and may return undefined when fallbackToCache fails, - // we test that null estimation is handled - await service.getRecommendedFeeRate(); + await expect(service.getRecommendedFeeRate()).rejects.toThrow('Failed to estimate fee rate from node'); - // With fallbackToCache=true and no cache, it may return undefined or throw - // The actual behavior depends on AsyncCache implementation - // For this test, we just verify the estimateSmartFee was called expect(mockClient.estimateSmartFee).toHaveBeenCalledWith(1); }); diff --git a/src/shared/utils/__tests__/async-cache.spec.ts b/src/shared/utils/__tests__/async-cache.spec.ts new file mode 100644 index 0000000000..c3af233501 --- /dev/null +++ b/src/shared/utils/__tests__/async-cache.spec.ts @@ -0,0 +1,273 @@ +import { AsyncCache, CacheItemResetPeriod } from '../async-cache'; + +describe('AsyncCache', () => { + let mockUpdate: jest.Mock; + let mockValue: string; + + beforeEach(() => { + mockValue = 'test-value'; + mockUpdate = jest.fn().mockResolvedValue(mockValue); + }); + + describe('get', () => { + it('should throw when the id is missing', async () => { + const cache = new AsyncCache(); + + await expect(cache.get('', mockUpdate)).rejects.toThrow('Error in AsyncCache: id is null'); + expect(mockUpdate).not.toHaveBeenCalled(); + }); + + it('should return the fetched data', async () => { + const cache = new AsyncCache(); + + const result = await cache.get('id', mockUpdate); + + expect(result).toBe(mockValue); + expect(mockUpdate).toHaveBeenCalledTimes(1); + }); + + it('should serve a second call from the cache when there is no validity period', async () => { + const cache = new AsyncCache(); + + const first = await cache.get('id', mockUpdate); + const second = await cache.get('id', mockUpdate); + + expect(first).toBe(mockValue); + expect(second).toBe(mockValue); + expect(mockUpdate).toHaveBeenCalledTimes(1); + }); + + it('should keep separate entries per id', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.EVERY_HOUR); + const update = jest.fn().mockResolvedValueOnce('value-a').mockResolvedValueOnce('value-b'); + + const resultA = await cache.get('a', update); + const resultB = await cache.get('b', update); + + expect(resultA).toBe('value-a'); + expect(resultB).toBe('value-b'); + expect(update).toHaveBeenCalledTimes(2); + }); + + it('should re-fetch when forceUpdate returns true', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.EVERY_HOUR); + const update = jest.fn().mockResolvedValueOnce('first').mockResolvedValue('second'); + + await cache.get('id', update); + const result = await cache.get('id', update, (entry) => entry === 'first'); + + expect(result).toBe('second'); + expect(update).toHaveBeenCalledTimes(2); + }); + }); + + describe('expiration', () => { + it('should not re-fetch a fresh entry', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.EVERY_HOUR); + + await cache.get('id', mockUpdate); + await cache.get('id', mockUpdate); + + expect(mockUpdate).toHaveBeenCalledTimes(1); + }); + + it('should re-fetch an expired entry', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.ALWAYS); + const update = jest.fn().mockResolvedValueOnce('first').mockResolvedValue('second'); + + const first = await cache.get('id', update); + const second = await cache.get('id', update); + + expect(first).toBe('first'); + expect(second).toBe('second'); + expect(update).toHaveBeenCalledTimes(2); + }); + }); + + describe('deduplication', () => { + it('should trigger only one update for parallel calls on the same id', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.EVERY_HOUR); + const update = jest + .fn() + .mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('shared'), 20))); + + const results = await Promise.all([cache.get('id', update), cache.get('id', update)]); + + expect(results).toEqual(['shared', 'shared']); + expect(update).toHaveBeenCalledTimes(1); + }); + + it('should trigger one update per id for parallel calls on different ids', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.EVERY_HOUR); + const update = jest + .fn() + .mockImplementationOnce(() => new Promise((resolve) => setTimeout(() => resolve('value-a'), 20))) + .mockImplementationOnce(() => new Promise((resolve) => setTimeout(() => resolve('value-b'), 20))); + + const results = await Promise.all([cache.get('a', update), cache.get('b', update)]); + + expect(results).toEqual(['value-a', 'value-b']); + expect(update).toHaveBeenCalledTimes(2); + }); + + it('should propagate a failing shared update to all waiting callers', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.EVERY_HOUR); + const update = jest.fn().mockRejectedValue(new Error('update failed')); + + // both calls are issued before the event loop is yielded to, so the second one joins the + // update of the first instead of starting its own + const first = cache.get('id', update).then( + (v) => v, + (e) => e.message, + ); + const second = cache.get('id', update).then( + (v) => v, + (e) => e.message, + ); + + const results = await Promise.all([first, second]); + + expect(results).toEqual(['update failed', 'update failed']); + expect(update).toHaveBeenCalledTimes(1); + }); + }); + + describe('invalidate', () => { + it('should drop only the given id when called with an id', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.EVERY_HOUR); + const updateA = jest.fn().mockResolvedValue('value-a'); + const updateB = jest.fn().mockResolvedValue('value-b'); + + await cache.get('a', updateA); + await cache.get('b', updateB); + + cache.invalidate('a'); + + await cache.get('a', updateA); + await cache.get('b', updateB); + + expect(updateA).toHaveBeenCalledTimes(2); + expect(updateB).toHaveBeenCalledTimes(1); + }); + + it('should drop all entries when called without an id', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.EVERY_HOUR); + const updateA = jest.fn().mockResolvedValue('value-a'); + const updateB = jest.fn().mockResolvedValue('value-b'); + + await cache.get('a', updateA); + await cache.get('b', updateB); + + cache.invalidate(); + + await cache.get('a', updateA); + await cache.get('b', updateB); + + expect(updateA).toHaveBeenCalledTimes(2); + expect(updateB).toHaveBeenCalledTimes(2); + }); + }); + + describe('invalidation during an in-flight update', () => { + it('should not write back data that was fetched before the invalidation', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.EVERY_HOUR); + const update = jest + .fn() + .mockImplementationOnce(() => new Promise((resolve) => setTimeout(() => resolve('stale'), 20))) + .mockResolvedValue('fresh'); + + const pending = cache.get('id', update); + await new Promise((resolve) => setTimeout(resolve, 0)); + + cache.invalidate('id'); + await pending; + + const result = await cache.get('id', update); + + expect(result).toBe('fresh'); + expect(update).toHaveBeenCalledTimes(2); + }); + + it('should still return the fetched data to the caller of the discarded update', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.EVERY_HOUR); + const update = jest + .fn() + .mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('stale'), 20))); + + const pending = cache.get('id', update); + await new Promise((resolve) => setTimeout(resolve, 0)); + + cache.invalidate('id'); + + await expect(pending).resolves.toBe('stale'); + }); + + it('should also discard an in-flight update for another id', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.EVERY_HOUR); + const update = jest + .fn() + .mockImplementationOnce(() => new Promise((resolve) => setTimeout(() => resolve('stale'), 20))) + .mockResolvedValue('fresh'); + + const pending = cache.get('b', update); + await new Promise((resolve) => setTimeout(resolve, 0)); + + cache.invalidate('a'); + + await expect(pending).resolves.toBe('stale'); + expect(await cache.get('b', update)).toBe('fresh'); + expect(update).toHaveBeenCalledTimes(2); + }); + + it('should not leave a partial entry behind when the write-back is discarded', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.EVERY_HOUR); + const update = jest + .fn() + .mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('stale'), 20))); + + const pending = cache.get('id', update); + await new Promise((resolve) => setTimeout(resolve, 0)); + + cache.invalidate('id'); + await pending; + + // there is no entry left, so there is nothing to fall back to and the error must surface + const failingUpdate = jest.fn().mockRejectedValue(new Error('update failed')); + + await expect(cache.get('id', failingUpdate, undefined, true)).rejects.toThrow('update failed'); + }); + }); + + describe('fallbackToCache', () => { + it('should return the cached value when the update fails', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.ALWAYS); + const update = jest.fn().mockResolvedValueOnce('cached').mockRejectedValue(new Error('update failed')); + + const first = await cache.get('id', update, undefined, true); + const second = await cache.get('id', update, undefined, true); + + expect(first).toBe('cached'); + expect(second).toBe('cached'); + expect(update).toHaveBeenCalledTimes(2); + }); + + it('should throw when the update fails and nothing is cached', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.EVERY_HOUR); + const update = jest.fn().mockRejectedValue(new Error('update failed')); + + await expect(cache.get('id', update, undefined, true)).rejects.toThrow('update failed'); + await expect(cache.get('id', update, undefined, true)).rejects.toThrow('update failed'); + expect(update).toHaveBeenCalledTimes(2); + }); + + it('should throw when the update fails and fallbackToCache is not set', async () => { + const cache = new AsyncCache(CacheItemResetPeriod.ALWAYS); + const update = jest.fn().mockResolvedValueOnce('cached').mockRejectedValue(new Error('update failed')); + + await cache.get('id', update); + + await expect(cache.get('id', update)).rejects.toThrow('update failed'); + expect(update).toHaveBeenCalledTimes(2); + }); + }); +}); diff --git a/src/shared/utils/async-cache.ts b/src/shared/utils/async-cache.ts index 0e9baa3001..455652b26b 100644 --- a/src/shared/utils/async-cache.ts +++ b/src/shared/utils/async-cache.ts @@ -13,7 +13,25 @@ export enum CacheItemResetPeriod { } export class AsyncCache { - private readonly cache = new Map }>(); + // holds complete entries only: an item without data/updated can never exist, so neither an + // in-flight nor a discarded update can leave a half-written entry behind + private readonly cache = new Map(); + + // updates currently in flight, kept separate from the data so that parallel get() calls for the + // same id share a single update() call; the promise resolves with the fetched data + private readonly updateCalls = new Map>(); + + // Monotonically increasing invalidation counter. A refresh captures it when it starts and writes + // its result back only if it is still unchanged. Without this guard, a refresh started before an + // invalidate() would repopulate the cache after it - with a fresh timestamp - and thereby undo + // the invalidation for up to a full item validity period. Callers rely on an invalidation taking + // effect immediately (e.g. FiatService.updatePrice() writing a price and then invalidating the + // repository cache), so the stale write-back must be dropped instead. + // The counter is deliberately instance-wide and not per key: invalidate('a') therefore also + // discards an in-flight refresh for key 'b'. That is intentionally conservative and harmless - + // the caller still receives its data, only the cache entry is missing and is re-fetched on the + // next access. + private generation = 0; constructor(private readonly itemValiditySeconds?: CacheItemResetPeriod) {} @@ -27,35 +45,56 @@ export class AsyncCache { const entry = this.cache.get(id); if (entry?.data == null || forceUpdate?.(entry.data) || entry.updated <= this.expiration) { - await this.updateInternal(id, update, fallbackToCache); + // the fetched data is handed through instead of being read back from the cache: a concurrent + // invalidate() may have discarded the write-back, but the caller must still get its data + return this.updateInternal(id, update, fallbackToCache); } - return this.cache.get(id).data; + return entry.data; } invalidate(id?: string): void { - if (!id) return this.cache.clear(); + // bumped by both forms, so every refresh that is currently in flight loses its write-back + this.generation++; + + if (!id) { + this.cache.clear(); + this.updateCalls.clear(); + return; + } this.cache.delete(id); + this.updateCalls.delete(id); } - private async updateInternal(id: string, update: () => Promise, fallbackToCache: boolean) { + private async updateInternal(id: string, update: () => Promise, fallbackToCache: boolean): Promise { try { // wait for an existing update - const entry = this.cache.get(id); - if (entry?.update != null) return await entry.update; + const pendingCall = this.updateCalls.get(id); + if (pendingCall != null) return await pendingCall; - const updateCall = update() + const generation = this.generation; + + // the type is annotated because the finally handler refers to the promise it belongs to + const updateCall: Promise = update() .then((data) => { - this.cache.set(id, { updated: new Date(), data }); + if (generation === this.generation) this.cache.set(id, { updated: new Date(), data }); + + return data; }) - .finally(() => this.cache.set(id, { ...this.cache.get(id), update: undefined })); + .finally(() => { + // only clear our own in-flight marker, a newer update may have replaced it in the meantime + if (this.updateCalls.get(id) === updateCall) this.updateCalls.delete(id); + }); - this.cache.set(id, { ...entry, update: updateCall }); + this.updateCalls.set(id, updateCall); - await updateCall; + return await updateCall; } catch (e) { - if (!fallbackToCache || !this.cache.has(id)) throw e; + const cachedEntry = this.cache.get(id); + if (!fallbackToCache || cachedEntry == null) throw e; + + return cachedEntry.data; } } diff --git a/src/subdomains/core/accounting/services/__tests__/integration/crypto-input-cutover.integration.spec.ts b/src/subdomains/core/accounting/services/__tests__/integration/crypto-input-cutover.integration.spec.ts index 28d02659b9..276ce762b0 100644 --- a/src/subdomains/core/accounting/services/__tests__/integration/crypto-input-cutover.integration.spec.ts +++ b/src/subdomains/core/accounting/services/__tests__/integration/crypto-input-cutover.integration.spec.ts @@ -85,6 +85,10 @@ describe('Ledger crypto_input-funded cutover double-book (§10.2, MAJOR — G-a ); }); + afterEach(() => { + Config.ledger.enabled = false; + }); + // --- FIXTURES --- // function snapshotLog(): Log { diff --git a/src/subdomains/core/accounting/services/__tests__/ledger-master-switch.spec.ts b/src/subdomains/core/accounting/services/__tests__/ledger-master-switch.spec.ts index b0a52521bd..c9aa63f1d2 100644 --- a/src/subdomains/core/accounting/services/__tests__/ledger-master-switch.spec.ts +++ b/src/subdomains/core/accounting/services/__tests__/ledger-master-switch.spec.ts @@ -1,5 +1,6 @@ import { createMock } from '@golevelup/ts-jest'; import { MODULE_METADATA } from '@nestjs/common/constants'; +import { MetadataScanner } from '@nestjs/core'; import { Test, TestingModule } from '@nestjs/testing'; import { Config } from 'src/config/config'; import { Process } from 'src/shared/services/process.service'; @@ -17,31 +18,60 @@ import { AccountingModule } from '../../accounting.module'; // exactly as it would already be invisible to the existing per-process `DISABLED_PROCESSES` kill-switches, // which depend on the very same `process` flag. Not this test's job to fix; CONTRIBUTING requires every // cron to carry its own Process flag regardless. +// +// Two blind spots that used to belong on that list are covered now: a cron method INHERITED from a base class +// (discovery walks the whole prototype chain, exactly as the production scheduler does), and a ledger method +// scheduled with Nest's native `@Cron` instead of `@DfxCron` (its own test below fails on it instead of +// silently not discovering it). const LEDGER_PROCESSES = new Set( (Object.keys(Process) as (keyof typeof Process)[]) .filter((key) => key.startsWith('LEDGER')) .map((key) => Process[key]), ); +// Metadata key that Nest's NATIVE `@Cron` (from `@nestjs/schedule`) writes onto the decorated method. Held as +// a string literal on purpose: the exported constant lives in `@nestjs/schedule/dist/schedule.constants` and +// is NOT re-exported from the package root, so importing it would mean reaching into the package's dist +// internals — a far more brittle coupling than the key's value, which is what the decorator writes at runtime. +const SCHEDULE_CRON_OPTIONS = 'SCHEDULE_CRON_OPTIONS'; + +// The very scanner the production scheduler uses (`DfxCronService.onModuleInit`). Using anything narrower — +// e.g. a single `Object.getOwnPropertyNames(prototype)` level — would give this test a SMALLER view than the +// one that actually schedules jobs: a cron sitting on a base class is registered in production but would go +// unexamined here. +const metadataScanner = new MetadataScanner(); + interface LedgerCronEntry { ProviderClass: new (...args: any[]) => any; methodName: string; process: Process; } -// Discover every ledger cron entry point from AccountingModule's OWN declared `providers` array (module -// metadata, not a hand-maintained list). A future ledger cron job only runs in production if its service -// class is registered there too — so scanning this array picks up a future job automatically, without any -// edit to this test file. -function discoverLedgerCronEntries(): LedgerCronEntry[] { +// Every class in AccountingModule's OWN declared `providers` array (module metadata, not a hand-maintained +// list) paired with the methods the production scanner would see on it. A future ledger cron job only runs in +// production if its service class is registered there too — so scanning this array picks up a future job +// automatically, without any edit to this test file. Both checks below share this one list so they can never +// disagree about WHICH methods are in scope. +function scanProviderMethods(): { ProviderClass: new (...args: any[]) => any; methodNames: string[] }[] { const providers: any[] = Reflect.getMetadata(MODULE_METADATA.PROVIDERS, AccountingModule) ?? []; - const entries: LedgerCronEntry[] = []; - for (const ProviderClass of providers) { - if (typeof ProviderClass !== 'function' || !ProviderClass.prototype) continue; + return providers + .filter((ProviderClass) => typeof ProviderClass === 'function' && ProviderClass.prototype) + .map((ProviderClass) => ({ + ProviderClass, + // getAllMethodNames() takes the prototype itself (no instance needed), walks the chain up to — but not + // including — Object.prototype, and already drops `constructor` and accessors. + methodNames: metadataScanner.getAllMethodNames(ProviderClass.prototype), + })); +} + +// Discover every ledger cron entry point: a scanned method carrying `@DfxCron` metadata with a +// `Process.LEDGER_*` value. +function discoverLedgerCronEntries(): LedgerCronEntry[] { + const entries: LedgerCronEntry[] = []; - for (const methodName of Object.getOwnPropertyNames(ProviderClass.prototype)) { - if (methodName === 'constructor') continue; + for (const { ProviderClass, methodNames } of scanProviderMethods()) { + for (const methodName of methodNames) { const methodRef = (ProviderClass.prototype as Record)[methodName]; if (typeof methodRef !== 'function') continue; @@ -89,6 +119,36 @@ describe('Ledger master switch (Config.ledger.enabled) — sustainability guard' expect(entries.length).toBeGreaterThanOrEqual(13); }); + // The discovery above — and with it every per-entry proof below — keys on `@DfxCron` metadata. A method + // scheduled with Nest's NATIVE `@Cron` is started by `@nestjs/schedule` itself and never passes through + // `DfxCronService`, so it would be silently absent from `entries`: scheduled in production, yet never shown + // to consult the master switch (and out of reach of its `Process` kill-switch too). The native decorator is + // legitimate elsewhere in the codebase, so this guards the ledger providers specifically rather than the + // import as such. + it('schedules no accounting cron via Nest-native @Cron, which the master switch cannot reach', () => { + const nativeCronMethods = scanProviderMethods().flatMap(({ ProviderClass, methodNames }) => + methodNames + .filter((methodName) => { + const methodRef = (ProviderClass.prototype as Record)[methodName]; + if (typeof methodRef !== 'function') return false; + + return Reflect.getMetadata(SCHEDULE_CRON_OPTIONS, methodRef) != null; + }) + .map((methodName) => `${ProviderClass.name}.${methodName}`), + ); + + // Asserted as a message rather than as an empty array so the failure states the CONSEQUENCE, not just the + // offending method name. + const violation = + nativeCronMethods.length > 0 + ? `Scheduled with Nest-native @Cron: ${nativeCronMethods.join(', ')} — @nestjs/schedule starts these ` + + `directly, so they bypass DfxCronService entirely and nothing subjects them to the ` + + `Config.ledger.enabled master switch (or to their Process kill-switch). Use @DfxCron instead.` + : ''; + + expect(violation).toBe(''); + }); + describe.each( entries.map((e): [string, LedgerCronEntry] => [`${e.ProviderClass.name}.${e.methodName} (${e.process})`, e]), )('%s', (_label, entry) => { diff --git a/src/subdomains/supporting/dashboard/__tests__/dashboard-financial.service.spec.ts b/src/subdomains/supporting/dashboard/__tests__/dashboard-financial.service.spec.ts index 02b280f7b7..f12d92ca7b 100644 --- a/src/subdomains/supporting/dashboard/__tests__/dashboard-financial.service.spec.ts +++ b/src/subdomains/supporting/dashboard/__tests__/dashboard-financial.service.spec.ts @@ -478,8 +478,149 @@ describe('DashboardFinancialService', () => { ], }; + const errorSpy = jest.spyOn(service['logger'], 'error'); + service.setLatestBalance(timestamp, assetLog, balancesByFinancialType, assets); + expect(latestBalanceStore.set).toHaveBeenCalledWith(expected); + // priceChf: null is the known, harmless normal case (144 of 430 production assets), not a defect: + // it must stay out of the log, otherwise the non-finite-price error line below is drowned out. + expect(errorSpy).not.toHaveBeenCalled(); + }); + + it('reports a NaN priceChf exactly once and leaves the poisoned aggregate uncorrected (no silent 0 normalisation)', () => { + // Before the JSON round-trip was removed, JSON.stringify collapsed NaN to null on the way into + // this aggregation; now it reaches the arithmetic directly and NaN-propagates through the whole + // blockchain total. The fix is to say so loudly, NOT to invent a value -- booking a broken price + // as 0 would silently understate the book. This test therefore asserts the UNTOUCHED arithmetic: + // + // BROKEN (NaN): 5 * NaN = NaN -> Ethereum plus = NaN (poisons the whole group) + // GOOD: 2 * 4000 = 8000 -> survives as its own asset key (8000 >= 5000 THRESHOLD) + // + // Ethereum rounded = Math.round(NaN) = NaN: `rounded <= 0` is false and `rounded < THRESHOLD` + // is false (every comparison with NaN is false), so the group is kept with plusBalanceChf NaN. + // BROKEN's own NaN entry falls into the local assetOther sum, which stays NaN and therefore + // never passes `assetOther > 0` -- so no synthetic 'Other' key is added. + // + // A later "fix" that normalises the price to 0 or null would turn plusBalanceChf into 8000 and + // break this test on purpose. + const timestamp = new Date('2026-07-14T12:00:00Z'); + const balancesByFinancialType: BalancesByFinancialType = {}; + const assetLog: AssetLog = { + '201': { priceChf: NaN, plusBalance: { total: 5 }, minusBalance: { total: 0 } }, + '202': { priceChf: 4000, plusBalance: { total: 2 }, minusBalance: { total: 0 } }, + }; + const assets = [ + { id: 201, name: 'BROKEN', blockchain: Blockchain.ETHEREUM }, + { id: 202, name: 'GOOD', blockchain: Blockchain.ETHEREUM }, + ] as Asset[]; + + const expected: LatestBalanceResponseDto = { + timestamp, + byType: [], + byBlockchain: [ + { + name: 'Ethereum', + plusBalanceChf: NaN, + minusBalanceChf: 0, + netBalanceChf: NaN, + assets: { GOOD: 8000 }, + }, + ], + }; + + const errorSpy = jest.spyOn(service['logger'], 'error'); + + service.setLatestBalance(timestamp, assetLog, balancesByFinancialType, assets); + + // one line per affected asset entry, emitted before the Scrypt/else split, carrying asset id, + // name and the actual value so the broken asset can be found from the log alone + expect(errorSpy).toHaveBeenCalledTimes(1); + expect(errorSpy).toHaveBeenCalledWith(expect.stringContaining('201')); + expect(errorSpy).toHaveBeenCalledWith(expect.stringContaining('BROKEN')); + expect(errorSpy).toHaveBeenCalledWith(expect.stringContaining('NaN')); + + expect(latestBalanceStore.set).toHaveBeenCalledWith(expected); + // explicit: the value was reported, not repaired + const written = (latestBalanceStore.set as jest.Mock).mock.calls[0][0] as LatestBalanceResponseDto; + expect(Number.isNaN(written.byBlockchain[0].plusBalanceChf)).toBe(true); + expect(Number.isNaN(written.byBlockchain[0].netBalanceChf)).toBe(true); + }); + + it('reports an Infinity priceChf exactly once and keeps the resulting Infinity totals uncorrected', () => { + // Infinity survives Math.round and every threshold comparison (Infinity >= 5000), so unlike NaN it + // stays visible as its own asset key -- still a corrupt number that must be reported, not replaced. + const timestamp = new Date('2026-07-14T12:00:00Z'); + const balancesByFinancialType: BalancesByFinancialType = {}; + const assetLog: AssetLog = { + '301': { priceChf: Infinity, plusBalance: { total: 5 }, minusBalance: { total: 0 } }, + }; + const assets = [{ id: 301, name: 'BROKEN_INF', blockchain: Blockchain.BITCOIN }] as Asset[]; + + const expected: LatestBalanceResponseDto = { + timestamp, + byType: [], + byBlockchain: [ + { + name: 'Bitcoin', + plusBalanceChf: Infinity, + minusBalanceChf: 0, + netBalanceChf: Infinity, + assets: { BROKEN_INF: Infinity }, + }, + ], + }; + + const errorSpy = jest.spyOn(service['logger'], 'error'); + + service.setLatestBalance(timestamp, assetLog, balancesByFinancialType, assets); + + expect(errorSpy).toHaveBeenCalledTimes(1); + expect(errorSpy).toHaveBeenCalledWith(expect.stringContaining('301')); + expect(errorSpy).toHaveBeenCalledWith(expect.stringContaining('Infinity')); + + expect(latestBalanceStore.set).toHaveBeenCalledWith(expected); + const written = (latestBalanceStore.set as jest.Mock).mock.calls[0][0] as LatestBalanceResponseDto; + expect(written.byBlockchain[0].plusBalanceChf).toBe(Infinity); + }); + + it('reports an undefined priceChf too (it produces NaN, so it must not share the null exemption)', () => { + // Guard for the strict `!== null` comparison: a loose `!= null` would also cover undefined and + // silently swallow this case, even though `total * undefined === NaN` corrupts the aggregate + // exactly like NaN does (5 * undefined = NaN -> Polygon plus = NaN, asset breakdown empty because + // neither the NaN asset value nor the NaN assetOther sum passes its comparison). + const timestamp = new Date('2026-07-14T12:00:00Z'); + const balancesByFinancialType: BalancesByFinancialType = {}; + const assetLog: AssetLog = { + '401': { + priceChf: undefined as unknown as number, + plusBalance: { total: 5 }, + minusBalance: { total: 0 }, + }, + }; + const assets = [{ id: 401, name: 'GHOST_UNDEF', blockchain: Blockchain.POLYGON }] as Asset[]; + + const expected: LatestBalanceResponseDto = { + timestamp, + byType: [], + byBlockchain: [ + { + name: 'Polygon', + plusBalanceChf: NaN, + minusBalanceChf: 0, + netBalanceChf: NaN, + assets: {}, + }, + ], + }; + + const errorSpy = jest.spyOn(service['logger'], 'error'); + + service.setLatestBalance(timestamp, assetLog, balancesByFinancialType, assets); + + expect(errorSpy).toHaveBeenCalledTimes(1); + expect(errorSpy).toHaveBeenCalledWith(expect.stringContaining('undefined')); + expect(latestBalanceStore.set).toHaveBeenCalledWith(expected); }); }); diff --git a/src/subdomains/supporting/dashboard/dashboard-financial.service.ts b/src/subdomains/supporting/dashboard/dashboard-financial.service.ts index 8a71b34f5c..9c6b1bbe08 100644 --- a/src/subdomains/supporting/dashboard/dashboard-financial.service.ts +++ b/src/subdomains/supporting/dashboard/dashboard-financial.service.ts @@ -1,6 +1,7 @@ import { Injectable } from '@nestjs/common'; import { Asset } from 'src/shared/models/asset/asset.entity'; import { AssetService } from 'src/shared/models/asset/asset.service'; +import { DfxLogger } from 'src/shared/services/dfx-logger'; import { RefRewardService } from '../../core/referral/reward/services/ref-reward.service'; import { AssetLog, BalancesByFinancialType } from '../log/dto/log.dto'; import { Log } from '../log/log.entity'; @@ -19,6 +20,8 @@ import { LatestBalanceStore } from './latest-balance.store'; @Injectable() export class DashboardFinancialService { + private readonly logger = new DfxLogger(DashboardFinancialService); + constructor( private readonly logService: LogService, private readonly assetService: AssetService, @@ -177,6 +180,22 @@ export class DashboardFinancialService { const blockchain = asset?.blockchain ?? 'Unknown'; const assetName = asset?.name ?? 'Unknown'; + // Report a broken price loudly, once per asset entry (before the Scrypt/else split, which + // multiplies priceChf in either branch), but do NOT repair it: this aggregation used to read a + // JSON.parse'd message, where JSON.stringify had already collapsed NaN/Infinity/-Infinity to + // null on the way in; without that round-trip such a value now reaches the arithmetic below and + // poisons the entire blockchain total via NaN propagation. Substituting 0 or null here would + // book a broken price as "no balance" and hide exactly the defect that needs fixing upstream, + // so the arithmetic stays untouched and only the log is added. `null` is deliberately NOT + // reported: asset.approxPriceChf is nullable and null-priced assets are the known, harmless + // normal case (`total * null === 0`, same as before the round-trip was removed) — logging them + // would drown the real signal. The comparison is strictly `!== null` on purpose: `undefined` + // must NOT fall under that exemption, because `total * undefined === NaN`. + if (assetData.priceChf !== null && !Number.isFinite(assetData.priceChf)) + this.logger.error( + `Non-finite priceChf (${assetData.priceChf}) for asset ${idStr} (${assetName}) in latest balance aggregation; value left uncorrected, ${blockchain} totals are corrupted`, + ); + if ((blockchain as string) === 'Scrypt') { const spotTotal = (assetData.plusBalance?.liquidity?.total ?? 0) + (assetData.plusBalance?.custom?.total ?? 0);