From ccad1f9baea16ea6bf8bf027425ec55f44586837 Mon Sep 17 00:00:00 2001 From: Harbinger Date: Thu, 18 Jun 2026 19:35:43 +0800 Subject: [PATCH] fix(op-log): lock snapshot save to prevent lost-update window (#8308) (#8439) * fix(op-log): lock snapshot save to prevent lost-update window saveCurrentStateAsSnapshot() read NgRx state then lastSeq without holding OPERATION_LOG lock. An op appended between the two reads would get seq <= lastAppliedOpSeq but its effect would be absent from the snapshot. On next hydration the tail replay would start after that seq, silently skipping the op forever. Fix: wrap in lockService.request(LOCK_NAMES.OPERATION_LOG, ...) and read lastSeq BEFORE state snapshot so the worst interleaving degrades to harmless re-replay (idempotent) rather than a missed op. Fixes #8308 * fix(op-log): address review feedback on snapshot lock PR - Amend JSDoc idempotency claim: syncTimeSpent is additive on re-replay - Add inline note about compaction's opposite read order and worse failure mode - Add lock regression tests (#8308): lock acquired, read order, error handling Co-Authored-By: Claude * docs(op-log): expand re-replay note to full op set + link #8469 * docs(op-log): generalize re-replay note, point to #8469 --------- Co-authored-by: Claude Co-authored-by: Johannes Millan --- .../operation-log-snapshot.service.spec.ts | 75 ++++++++++++++ .../operation-log-snapshot.service.ts | 98 ++++++++++++------- 2 files changed, 135 insertions(+), 38 deletions(-) diff --git a/src/app/op-log/persistence/operation-log-snapshot.service.spec.ts b/src/app/op-log/persistence/operation-log-snapshot.service.spec.ts index 58514f53ed..521b6fe2cc 100644 --- a/src/app/op-log/persistence/operation-log-snapshot.service.spec.ts +++ b/src/app/op-log/persistence/operation-log-snapshot.service.spec.ts @@ -10,6 +10,8 @@ import { VectorClockService } from '../sync/vector-clock.service'; import { StateSnapshotService } from '../backup/state-snapshot.service'; import { CLIENT_ID_PROVIDER, ClientIdProvider } from '../util/client-id.provider'; import { ValidateStateService } from '../validation/validate-state.service'; +import { LockService } from '../sync/lock.service'; +import { LOCK_NAMES } from '../core/operation-log.const'; import { MAX_VECTOR_CLOCK_SIZE } from '@sp/sync-core'; // Meaningful state (contains a task) so saveCurrentStateAsSnapshot proceeds past @@ -28,6 +30,7 @@ describe('OperationLogSnapshotService', () => { let mockSchemaMigrationService: jasmine.SpyObj; let mockClientIdProvider: jasmine.SpyObj; let mockValidateStateService: jasmine.SpyObj; + let mockLockService: jasmine.SpyObj; beforeEach(() => { mockOpLogStore = jasmine.createSpyObj('OperationLogStoreService', [ @@ -55,6 +58,11 @@ describe('OperationLogSnapshotService', () => { isValid: true, typiaErrors: [], }); + mockLockService = jasmine.createSpyObj('LockService', ['request']); + // Default: execute the callback inline (mirrors real Web Locks behavior in Chrome) + mockLockService.request.and.callFake(async (_name: string, fn: () => Promise) => + fn(), + ); TestBed.configureTestingModule({ providers: [ @@ -65,6 +73,7 @@ describe('OperationLogSnapshotService', () => { { provide: SchemaMigrationService, useValue: mockSchemaMigrationService }, { provide: CLIENT_ID_PROVIDER, useValue: mockClientIdProvider }, { provide: ValidateStateService, useValue: mockValidateStateService }, + { provide: LockService, useValue: mockLockService }, ], }); service = TestBed.inject(OperationLogSnapshotService); @@ -318,6 +327,72 @@ describe('OperationLogSnapshotService', () => { }); }); + describe('saveCurrentStateAsSnapshot — lock regression', () => { + it('should acquire OPERATION_LOG lock before saving (#8308)', async () => { + mockStateSnapshotService.getStateSnapshot.and.returnValue( + MEANINGFUL_SNAPSHOT_STATE as any, + ); + mockVectorClockService.getCurrentVectorClock.and.resolveTo({}); + mockOpLogStore.getLastSeq.and.resolveTo(1); + mockOpLogStore.saveStateCache.and.resolveTo(undefined); + + await service.saveCurrentStateAsSnapshot(); + + expect(mockLockService.request).toHaveBeenCalledWith( + LOCK_NAMES.OPERATION_LOG, + jasmine.any(Function), + ); + }); + + it('should read lastSeq BEFORE getStateSnapshot inside the lock', async () => { + const callOrder: string[] = []; + + mockLockService.request.and.callFake( + async (_name: string, fn: () => Promise) => { + callOrder.push('lock-start'); + const r = await fn(); + callOrder.push('lock-end'); + return r; + }, + ); + + mockOpLogStore.getLastSeq.and.callFake(async () => { + callOrder.push('getLastSeq'); + return 1; + }); + + mockStateSnapshotService.getStateSnapshot.and.callFake((() => { + callOrder.push('getStateSnapshot'); + return MEANINGFUL_SNAPSHOT_STATE; + }) as any); + + mockVectorClockService.getCurrentVectorClock.and.resolveTo({}); + mockOpLogStore.saveStateCache.and.resolveTo(undefined); + + await service.saveCurrentStateAsSnapshot(); + + // All operations should happen between lock-start and lock-end + const lockStartIndex = callOrder.indexOf('lock-start'); + const lockEndIndex = callOrder.indexOf('lock-end'); + expect(callOrder.indexOf('getLastSeq')).toBeGreaterThan(lockStartIndex); + expect(callOrder.indexOf('getLastSeq')).toBeLessThan(lockEndIndex); + expect(callOrder.indexOf('getStateSnapshot')).toBeGreaterThan(lockStartIndex); + expect(callOrder.indexOf('getStateSnapshot')).toBeLessThan(lockEndIndex); + + // Key invariant: lastSeq is read BEFORE state snapshot + expect(callOrder.indexOf('getLastSeq')).toBeLessThan( + callOrder.indexOf('getStateSnapshot'), + ); + }); + + it('should catch lock errors without throwing (hydration must not fail)', async () => { + mockLockService.request.and.rejectWith(new Error('Lock timeout')); + + // Should not throw — errors are caught internally + await expectAsync(service.saveCurrentStateAsSnapshot()).toBeResolved(); + }); + }); + describe('migrateSnapshotWithBackup', () => { const createSnapshot = (): MigratableStateCache => ({ state: { task: {}, project: {}, globalConfig: {} }, diff --git a/src/app/op-log/persistence/operation-log-snapshot.service.ts b/src/app/op-log/persistence/operation-log-snapshot.service.ts index a192c9cb16..63a074a0bc 100644 --- a/src/app/op-log/persistence/operation-log-snapshot.service.ts +++ b/src/app/op-log/persistence/operation-log-snapshot.service.ts @@ -13,6 +13,8 @@ import { CLIENT_ID_PROVIDER, ClientIdProvider } from '../util/client-id.provider import { limitVectorClockSize } from '../../core/util/vector-clock'; import { ValidateStateService } from '../validation/validate-state.service'; import { hasMeaningfulStateData } from '../validation/has-meaningful-state-data.util'; +import { LockService } from '../sync/lock.service'; +import { LOCK_NAMES } from '../core/operation-log.const'; type StateCache = MigratableStateCache; @@ -35,6 +37,7 @@ export class OperationLogSnapshotService { private schemaMigrationService = inject(SchemaMigrationService); private validateStateService = inject(ValidateStateService); private clientIdProvider: ClientIdProvider = inject(CLIENT_ID_PROVIDER); + private lockService = inject(LockService); /** * Validates that a snapshot has the expected structure and data. @@ -78,53 +81,72 @@ export class OperationLogSnapshotService { /** * Saves the current NgRx state as a snapshot for faster future loads. * Called after replaying many operations to optimize next startup. + * + * Wrapped in OPERATION_LOG lock to prevent a lost-update window: without + * the lock, an op appended between reading NgRx state and reading lastSeq + * would get a seq <= lastAppliedOpSeq but its effect would be absent from + * the snapshot. On next hydration the tail replay would start after that + * seq, silently skipping the op forever. + * + * Additionally, lastSeq is read BEFORE the state snapshot so the worst + * interleaving degrades to re-replay rather than a missed op. Most op types + * are idempotent on re-replay (entity-adapter CRUD/move/reorder), but some + * persistent ops accumulate onto current state and double-apply on re-replay + * (e.g. time-tracking/counter deltas and the plain-append branches of project + * task moves). This edge is unlikely (the save runs only during hydration) and + * strictly better than op-loss. The audited op list and a truly-lossless + * capture (quiesce the op-write queue before reading) are tracked in #8469. */ async saveCurrentStateAsSnapshot(): Promise { try { - // Get current state from NgRx - const currentState = this.stateSnapshotService.getStateSnapshot(); + await this.lockService.request(LOCK_NAMES.OPERATION_LOG, async () => { + // Read lastSeq BEFORE state snapshot — see JSDoc above. + // NOTE: compaction reads in the opposite order (state, then lastSeq); + // its failure mode if the lock is bypassed is missed-op data loss. + const lastSeq = await this.opLogStore.getLastSeq(); + const currentState = this.stateSnapshotService.getStateSnapshot(); - // GUARD (#7892): never cache an empty/degraded state over a good one. - // The snapshot is only a load-time cache — the op-log is the source of - // truth. If the live NgRx state has no user data (e.g. a transient - // hydration glitch left the store in its initial empty state), caching it - // would make the next boot trust empty data. Skipping the save is always - // safe for correctness: replaying the op-log reconstructs the true state - // (including legitimate full-wipe deletes), at most costing a slower boot. - if (!hasMeaningfulStateData(currentState)) { - OpLog.warn( - 'OperationLogSnapshotService: Skipping snapshot save — current state has no ' + - 'meaningful data (refusing to overwrite cache with empty state)', - ); - return; - } + // GUARD (#7892): never cache an empty/degraded state over a good one. + // The snapshot is only a load-time cache — the op-log is the source of + // truth. If the live NgRx state has no user data (e.g. a transient + // hydration glitch left the store in its initial empty state), caching it + // would make the next boot trust empty data. Skipping the save is always + // safe for correctness: replaying the op-log reconstructs the true state + // (including legitimate full-wipe deletes), at most costing a slower boot. + if (!hasMeaningfulStateData(currentState)) { + OpLog.warn( + 'OperationLogSnapshotService: Skipping snapshot save — current state has no ' + + 'meaningful data (refusing to overwrite cache with empty state)', + ); + return; + } - // Get current vector clock and last seq - const vectorClock = await this.vectorClockService.getCurrentVectorClock(); - const lastSeq = await this.opLogStore.getLastSeq(); + // Get current vector clock + const vectorClock = await this.vectorClockService.getCurrentVectorClock(); - // Prune vector clock before persisting to prevent bloat (max 20 entries). - // Without this, clocks can grow unbounded across sync cycles and cause - // repeated conflict dialogs on every sync. - const clientId = await this.clientIdProvider.loadClientId(); - const prunedClock = clientId - ? limitVectorClockSize(vectorClock, clientId) - : vectorClock; + // Prune vector clock before persisting to prevent bloat (max 20 entries). + // Without this, clocks can grow unbounded across sync cycles and cause + // repeated conflict dialogs on every sync. + const clientId = await this.clientIdProvider.loadClientId(); + const prunedClock = clientId + ? limitVectorClockSize(vectorClock, clientId) + : vectorClock; - // Extract entity keys for conflict detection after compaction - const snapshotEntityKeys = extractEntityKeysFromState(currentState); + // Extract entity keys for conflict detection after compaction + const snapshotEntityKeys = extractEntityKeysFromState(currentState); - // Save snapshot - await this.opLogStore.saveStateCache({ - state: currentState, - lastAppliedOpSeq: lastSeq, - vectorClock: prunedClock, - compactedAt: Date.now(), - schemaVersion: CURRENT_SCHEMA_VERSION, - snapshotEntityKeys, + // Save snapshot + await this.opLogStore.saveStateCache({ + state: currentState, + lastAppliedOpSeq: lastSeq, + vectorClock: prunedClock, + compactedAt: Date.now(), + schemaVersion: CURRENT_SCHEMA_VERSION, + snapshotEntityKeys, + }); + + OpLog.normal('OperationLogSnapshotService: Saved new snapshot'); }); - - OpLog.normal('OperationLogSnapshotService: Saved new snapshot'); } catch (e) { // Don't fail hydration if snapshot save fails OpLog.warn('OperationLogSnapshotService: Failed to save snapshot', e);