From 4e6bf73859d31640be14bc1090b530db273d58d4 Mon Sep 17 00:00:00 2001 From: Johannes Millan Date: Wed, 25 Mar 2026 15:50:18 +0100 Subject: [PATCH] fix(sync): prevent false IN_SYNC status when sync errors occur (#6571) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Multiple error paths in the sync pipeline silently swallowed errors, allowing sync to report IN_SYNC while clients had diverged state. This caused permanent data loss — tasks missing on one device but present on another, with no indication anything was wrong. Fixes: 1. Propagate download failure: when OperationLogDownloadService returns success=false, throw instead of treating as "no new ops". Prevents lastServerSeq from advancing past failed downloads. 2. Throw on LWW conflict apply failure: autoResolveConflictsLWW now throws when applyOperations fails, matching the behavior of applyNonConflictingOps. Prevents lastServerSeq from advancing past failed conflict resolutions. 3. Propagate rejected ops handler errors: rethrow instead of swallowing in the uploadPendingOps catch block, so the sync-wrapper can set ERROR status. 4. Surface validation failure: validateAfterSync now checks the return value from validateAndRepairCurrentState and shows an error snackbar when validation fails. 5. Set ERROR status in sync-wrapper catch-all: the generic error handler now calls setSyncStatus('ERROR') so the sync icon shows the red error state. Fixes #6571 --- .../supersync-divergence-bug-6571.spec.ts | 198 ++++++++++++++++++ src/app/imex/sync/sync-wrapper.service.ts | 1 + .../sync/conflict-resolution.service.spec.ts | 62 ++++++ .../sync/conflict-resolution.service.ts | 5 + .../sync/operation-log-sync.service.spec.ts | 170 +++++++++++++++ .../op-log/sync/operation-log-sync.service.ts | 14 ++ .../remote-ops-processing.service.spec.ts | 16 ++ .../sync/remote-ops-processing.service.ts | 17 +- src/app/t.const.ts | 1 + src/assets/i18n/en.json | 1 + 10 files changed, 482 insertions(+), 3 deletions(-) create mode 100644 e2e/tests/sync/supersync-divergence-bug-6571.spec.ts diff --git a/e2e/tests/sync/supersync-divergence-bug-6571.spec.ts b/e2e/tests/sync/supersync-divergence-bug-6571.spec.ts new file mode 100644 index 0000000000..5910be8616 --- /dev/null +++ b/e2e/tests/sync/supersync-divergence-bug-6571.spec.ts @@ -0,0 +1,198 @@ +import { test, expect } from '../../fixtures/supersync.fixture'; +import { + createTestUser, + getSuperSyncConfig, + createSimulatedClient, + closeClient, + waitForTask, + getTaskCount, + type SimulatedE2EClient, +} from '../../utils/supersync-helpers'; +import { expectTaskOnAllClients } from '../../utils/supersync-assertions'; + +/** + * Bug #6571 Reproduction: Sync Divergence While Reporting IN_SYNC + * + * Root cause: Multiple error paths in the sync pipeline silently swallow + * errors, allowing sync to complete and report success even when operations + * were lost during processing. Confirmed bugs (unit-tested): + * 1. DownloadResult.success=false treated as "no new ops" + * 2. LWW conflict apply failure does not throw (swallowed) + * 3. handleRejectedOps error is swallowed + * 4. validateAfterSync result is discarded + * + * This e2e test uses Playwright route interception to drop ops from the + * download response (simulating what happens when any of the 4 bugs fires), + * then verifies the divergence persists while both clients show IN_SYNC. + */ + +test.describe('@supersync Bug #6571: Sync divergence reproduction', () => { + test('ops lost during download cause permanent divergence while showing IN_SYNC', async ({ + browser, + baseURL, + testRunId, + }) => { + let clientA: SimulatedE2EClient | null = null; + let clientB: SimulatedE2EClient | null = null; + + try { + const user = await createTestUser(testRunId); + const syncConfig = getSuperSyncConfig(user); + + // ─── Step 1: Set up both clients on empty server ─── + clientA = await createSimulatedClient(browser, baseURL!, 'A', testRunId); + await clientA.sync.setupSuperSync(syncConfig); + + clientB = await createSimulatedClient(browser, baseURL!, 'B', testRunId); + await clientB.sync.setupSuperSync(syncConfig); + + // ─── Step 2: Client A creates 3 tasks and syncs ─── + const task1 = `Task1-${testRunId}`; + const task2 = `Task2-${testRunId}`; + const task3 = `Task3-${testRunId}`; + + await clientA.workView.addTask(task1); + await clientA.workView.addTask(task2); + await clientA.workView.addTask(task3); + + await clientA.sync.syncAndWait(); + + // Verify A has all 3 + await waitForTask(clientA.page, task1); + await waitForTask(clientA.page, task2); + await waitForTask(clientA.page, task3); + const countA = await getTaskCount(clientA); + expect(countA).toBe(3); + + // ─── Step 3: Install route interception on Client B ─── + // Drop TASK Create ops from the download response. + // entityType and opType are NOT encrypted — only payload is. + // This simulates ops being lost during processing (as caused by bugs 1-4). + let intercepted = false; + let droppedOpCount = 0; + + // Intercept download API to drop one TASK Create op. + // entityType/opType are NOT encrypted (only payload is). + // On the wire, opType uses abbreviations: CRT, UPD, DEL. + await clientB.page.route('**/api/sync/ops**', async (route) => { + if (route.request().method() !== 'GET') { + await route.continue(); + return; + } + if (intercepted) { + await route.continue(); + return; + } + + const response = await route.fetch(); + const body = await response.json(); + + if (body.ops && Array.isArray(body.ops) && body.ops.length > 0) { + let droppedOne = false; + body.ops = body.ops.filter((serverOp: any) => { + if (droppedOne) return true; + const op = serverOp.op; + if (op && op.entityType === 'TASK' && op.opType === 'CRT') { + droppedOne = true; + droppedOpCount++; + return false; + } + return true; + }); + if (droppedOpCount > 0) { + intercepted = true; + } + } + + await route.fulfill({ + status: response.status(), + headers: response.headers(), + body: JSON.stringify(body), + }); + }); + + // ─── Step 4: Client B syncs — downloads ops with one dropped ─── + await clientB.sync.syncAndWait(); + + // Verify interception triggered + expect(intercepted).toBe(true); + expect(droppedOpCount).toBe(1); + + // ─── Step 5: Verify the divergence ─── + // Client B should have only 2 tasks (one Create op was dropped) + const countB = await getTaskCount(clientB); + expect(countB).toBe(2); // Missing one task + + // THE BUG: Both clients show sync success despite different state + const syncStateA = await clientA.sync.getSyncState(); + const syncStateB = await clientB.sync.getSyncState(); + expect(syncStateA).toBe('success'); + expect(syncStateB).toBe('success'); + + // ─── Step 6: Verify divergence is PERMANENT ─── + // Sync again — the dropped op will NOT reappear because + // lastServerSeq has advanced past it + await clientB.sync.syncAndWait(); + const countBAfterResync = await getTaskCount(clientB); + expect(countBAfterResync).toBe(2); // Still missing + + const syncStateBAfter = await clientB.sync.getSyncState(); + expect(syncStateBAfter).toBe('success'); + + console.log( + `[Bug6571] CONFIRMED: A=${countA} tasks, B=${countBAfterResync} tasks. ` + + `Sync state: A=${syncStateA}, B=${syncStateBAfter}. Permanent divergence.`, + ); + } finally { + if (clientA) await closeClient(clientA); + if (clientB) await closeClient(clientB); + } + }); + + test('convergence check: without interception both clients have identical state', async ({ + browser, + baseURL, + testRunId, + }) => { + let clientA: SimulatedE2EClient | null = null; + let clientB: SimulatedE2EClient | null = null; + + try { + const user = await createTestUser(testRunId); + const syncConfig = getSuperSyncConfig(user); + + // Set up both clients + clientA = await createSimulatedClient(browser, baseURL!, 'A', testRunId); + await clientA.sync.setupSuperSync(syncConfig); + + clientB = await createSimulatedClient(browser, baseURL!, 'B', testRunId); + await clientB.sync.setupSuperSync(syncConfig); + + // Client A creates tasks and syncs + const task1 = `Task1-${testRunId}`; + const task2 = `Task2-${testRunId}`; + const task3 = `Task3-${testRunId}`; + + await clientA.workView.addTask(task1); + await clientA.workView.addTask(task2); + await clientA.workView.addTask(task3); + await clientA.sync.syncAndWait(); + + // Client B syncs (no interception — happy path) + await clientB.sync.syncAndWait(); + + // Both should have all 3 tasks + await expectTaskOnAllClients([clientA, clientB], task1); + await expectTaskOnAllClients([clientA, clientB], task2); + await expectTaskOnAllClients([clientA, clientB], task3); + + const countA = await getTaskCount(clientA); + const countB = await getTaskCount(clientB); + expect(countA).toBe(3); + expect(countB).toBe(3); + } finally { + if (clientA) await closeClient(clientA); + if (clientB) await closeClient(clientB); + } + }); +}); diff --git a/src/app/imex/sync/sync-wrapper.service.ts b/src/app/imex/sync/sync-wrapper.service.ts index 21aceb44f2..338354dddf 100644 --- a/src/app/imex/sync/sync-wrapper.service.ts +++ b/src/app/imex/sync/sync-wrapper.service.ts @@ -547,6 +547,7 @@ export class SyncWrapperService { }); return 'HANDLED_ERROR'; } else { + this._providerManager.setSyncStatus('ERROR'); const errStr = getSyncErrorStr(error); this._snackService.open({ // msg: T.F.SYNC.S.UNKNOWN_ERROR, diff --git a/src/app/op-log/sync/conflict-resolution.service.spec.ts b/src/app/op-log/sync/conflict-resolution.service.spec.ts index ac7438d476..670f29ad97 100644 --- a/src/app/op-log/sync/conflict-resolution.service.spec.ts +++ b/src/app/op-log/sync/conflict-resolution.service.spec.ts @@ -3452,4 +3452,66 @@ describe('ConflictResolutionService', () => { }); }); }); + + // ═══════════════════════════════════════════════════════════════════════════ + // BUG CONFIRMATION TEST (Issue #6571) + // ═══════════════════════════════════════════════════════════════════════════ + + describe('Bug #6571: LWW apply failure does not throw', () => { + const now = Date.now(); + + const createOpForBug = ( + id: string, + clientId: string, + timestamp: number, + ): Operation => ({ + id, + clientId, + actionType: 'test' as ActionType, + opType: OpType.Update, + entityType: 'TASK', + entityId: 'task-1', + payload: { source: clientId }, + vectorClock: { [clientId]: 1 }, + timestamp, + schemaVersion: 1, + }); + + beforeEach(() => { + mockOpLogStore.hasOp.and.resolveTo(false); + mockOpLogStore.append.and.callFake(() => Promise.resolve(1)); + mockOpLogStore.appendWithVectorClockUpdate.and.callFake(() => Promise.resolve(1)); + mockOpLogStore.markApplied.and.resolveTo(undefined); + mockOpLogStore.markRejected.and.resolveTo(undefined); + mockOpLogStore.markFailed.and.resolveTo(undefined); + }); + + it('should throw when applyOperations has a failedOp', async () => { + const localOp = createOpForBug('local-1', 'client-a', now - 1000); + const remoteOp = createOpForBug('remote-1', 'client-b', now); + + const conflicts: EntityConflict[] = [ + { + entityType: 'TASK', + entityId: 'task-1', + localOps: [localOp], + remoteOps: [remoteOp], + suggestedResolution: 'manual', + }, + ]; + + mockOperationApplier.applyOperations.and.resolveTo({ + appliedOps: [], + failedOp: { op: remoteOp, error: new Error('Apply failed for task-1') }, + }); + + // FIXED: Should throw on apply failure (parity with applyNonConflictingOps) + await expectAsync(service.autoResolveConflictsLWW(conflicts)).toBeRejectedWithError( + 'Apply failed for task-1', + ); + + expect(mockOpLogStore.markFailed).toHaveBeenCalled(); + expect(mockSnackService.open).toHaveBeenCalled(); + }); + }); }); diff --git a/src/app/op-log/sync/conflict-resolution.service.ts b/src/app/op-log/sync/conflict-resolution.service.ts index 177feca3a3..26bcc70654 100644 --- a/src/app/op-log/sync/conflict-resolution.service.ts +++ b/src/app/op-log/sync/conflict-resolution.service.ts @@ -534,6 +534,11 @@ export class ConflictResolutionService { window.location.reload(); }, }); + + // FIX #6571: Throw on apply failure (parity with applyNonConflictingOps). + // Previously, apply failures during LWW resolution were logged but not + // thrown, causing sync to report IN_SYNC despite lost operations. + throw applyResult.failedOp.error; } } diff --git a/src/app/op-log/sync/operation-log-sync.service.spec.ts b/src/app/op-log/sync/operation-log-sync.service.spec.ts index 8d40745f04..46df1e827f 100644 --- a/src/app/op-log/sync/operation-log-sync.service.spec.ts +++ b/src/app/op-log/sync/operation-log-sync.service.spec.ts @@ -2126,4 +2126,174 @@ describe('OperationLogSyncService', () => { expect(forceDownloadSpy).toHaveBeenCalledWith(mockProvider); }); }); + + // ═══════════════════════════════════════════════════════════════════════════ + // BUG CONFIRMATION TESTS (Issue #6571) + // These tests confirm bugs where sync reports success despite errors. + // Each test documents current (buggy) behavior and expected (fixed) behavior. + // ═══════════════════════════════════════════════════════════════════════════ + + describe('Bug #6571: sync reports IN_SYNC despite errors', () => { + let uploadServiceSpy: jasmine.SpyObj; + let downloadServiceSpy: jasmine.SpyObj; + + beforeEach(() => { + uploadServiceSpy = TestBed.inject( + OperationLogUploadService, + ) as jasmine.SpyObj; + downloadServiceSpy = TestBed.inject( + OperationLogDownloadService, + ) as jasmine.SpyObj; + + // Default: not a fresh client + (opLogStoreSpy as any).loadStateCache = jasmine + .createSpy('loadStateCache') + .and.returnValue(Promise.resolve({ state: {} })); + (opLogStoreSpy as any).getLastSeq = jasmine + .createSpy('getLastSeq') + .and.returnValue(Promise.resolve(1)); + }); + + describe('Bug 1: download failure (success=false) treated as no_new_ops', () => { + it('should NOT return no_new_ops when download failed (success=false)', async () => { + downloadServiceSpy.downloadRemoteOps.and.returnValue( + Promise.resolve({ + newOps: [], + success: false, + failedFileCount: 0, + }), + ); + + const mockProvider = { + isReady: () => Promise.resolve(true), + setLastServerSeq: jasmine.createSpy('setLastServerSeq').and.resolveTo(), + } as any; + + // FIXED: Should throw when download failed, not silently return no_new_ops + await expectAsync(service.downloadRemoteOps(mockProvider)).toBeRejectedWithError( + /Download failed/, + ); + }); + }); + + describe('Bug 3: handleRejectedOps error is swallowed', () => { + it('should propagate errors from handleRejectedOps', async () => { + opLogStoreSpy.getUnsynced.and.returnValue(Promise.resolve([])); + + uploadServiceSpy.uploadPendingOps.and.returnValue( + Promise.resolve({ + uploadedCount: 1, + piggybackedOps: [], + rejectedCount: 1, + rejectedOps: [{ opId: 'op-1', error: 'conflict' }], + }), + ); + + rejectedOpsHandlerServiceSpy.handleRejectedOps.and.rejectWith( + new Error('Rejection handling failed'), + ); + + const mockProvider = { + isReady: () => Promise.resolve(true), + } as any; + + // FIXED: Should reject when rejection handler throws + await expectAsync(service.uploadPendingOps(mockProvider)).toBeRejectedWithError( + 'Rejection handling failed', + ); + }); + }); + + describe('lastServerSeq preservation on error (prevents permanent divergence)', () => { + it('should NOT persist lastServerSeq when download fails (success=false)', async () => { + downloadServiceSpy.downloadRemoteOps.and.returnValue( + Promise.resolve({ + newOps: [], + success: false, + failedFileCount: 0, + latestServerSeq: 42, + }), + ); + + const setLastServerSeqSpy = jasmine.createSpy('setLastServerSeq').and.resolveTo(); + + const mockProvider = { + isReady: () => Promise.resolve(true), + setLastServerSeq: setLastServerSeqSpy, + } as any; + + // Download fails — error thrown + await expectAsync(service.downloadRemoteOps(mockProvider)).toBeRejected(); + + // CRITICAL: lastServerSeq must NOT be persisted. + // If it were, the client would never re-download the failed ops. + expect(setLastServerSeqSpy).not.toHaveBeenCalled(); + }); + + it('should NOT persist lastServerSeq when processRemoteOps throws', async () => { + const remoteOp: Operation = { + id: 'remote-1', + clientId: 'client-B', + actionType: 'test' as ActionType, + opType: OpType.Update, + entityType: 'TASK' as const, + entityId: 'task-1', + payload: {}, + vectorClock: { clientB: 1 }, + timestamp: Date.now(), + schemaVersion: 1, + }; + + downloadServiceSpy.downloadRemoteOps.and.returnValue( + Promise.resolve({ + newOps: [remoteOp], + success: true, + failedFileCount: 0, + latestServerSeq: 42, + }), + ); + + // processRemoteOps throws (e.g., LWW apply failure after Bug 2 fix) + remoteOpsProcessingServiceSpy.processRemoteOps.and.rejectWith( + new Error('Apply failed during conflict resolution'), + ); + + const setLastServerSeqSpy = jasmine.createSpy('setLastServerSeq').and.resolveTo(); + + const mockProvider = { + isReady: () => Promise.resolve(true), + setLastServerSeq: setLastServerSeqSpy, + } as any; + + await expectAsync(service.downloadRemoteOps(mockProvider)).toBeRejected(); + + // CRITICAL: lastServerSeq must NOT be persisted. + // Client will re-download from the old seq on next sync. + expect(setLastServerSeqSpy).not.toHaveBeenCalled(); + }); + + it('should persist lastServerSeq on successful download (control test)', async () => { + downloadServiceSpy.downloadRemoteOps.and.returnValue( + Promise.resolve({ + newOps: [], + success: true, + failedFileCount: 0, + latestServerSeq: 42, + }), + ); + + const setLastServerSeqSpy = jasmine.createSpy('setLastServerSeq').and.resolveTo(); + + const mockProvider = { + isReady: () => Promise.resolve(true), + setLastServerSeq: setLastServerSeqSpy, + } as any; + + await service.downloadRemoteOps(mockProvider); + + // On success, lastServerSeq IS persisted + expect(setLastServerSeqSpy).toHaveBeenCalledWith(42); + }); + }); + }); }); diff --git a/src/app/op-log/sync/operation-log-sync.service.ts b/src/app/op-log/sync/operation-log-sync.service.ts index 8ac24d05df..af2c166b2e 100644 --- a/src/app/op-log/sync/operation-log-sync.service.ts +++ b/src/app/op-log/sync/operation-log-sync.service.ts @@ -387,7 +387,11 @@ export class OperationLogSyncService { ); localWinOpsCreated += rejectionResult.mergedOpsCreated; } catch (rejectionError) { + // FIX #6571: Propagate rejection handler errors instead of swallowing them. + // Previously, errors here were logged but not rethrown, causing uploadPendingOps + // to return kind='completed' with permanentRejectionCount=0, masking the failure. OpLog.err('OperationLogSyncService: Error handling rejected ops', rejectionError); + throw rejectionError; } // Update pending ops status for UI indicator @@ -430,6 +434,16 @@ export class OperationLogSyncService { ): Promise { const result = await this.downloadService.downloadRemoteOps(syncProvider, options); + // FIX #6571: Check download success before processing results. + // Previously, success=false was ignored and treated as "no new ops", + // causing sync to report IN_SYNC despite a failed download. + if (!result.success) { + throw new Error( + 'Download failed - partial or no data received. ' + + `failedFileCount=${result.failedFileCount}`, + ); + } + // Server migration detected: gap on empty server // Create a SYNC_IMPORT operation with full local state to seed the new server if (result.needsFullStateUpload) { diff --git a/src/app/op-log/sync/remote-ops-processing.service.spec.ts b/src/app/op-log/sync/remote-ops-processing.service.spec.ts index a2d29f751b..407280df58 100644 --- a/src/app/op-log/sync/remote-ops-processing.service.spec.ts +++ b/src/app/op-log/sync/remote-ops-processing.service.spec.ts @@ -1170,5 +1170,21 @@ describe('RemoteOpsProcessingService', () => { { callerHoldsLock: true }, ); }); + + // ═══════════════════════════════════════════════════════════════════════ + // BUG CONFIRMATION TEST (Issue #6571) + // ═══════════════════════════════════════════════════════════════════════ + + it('Bug #6571: should surface validation failure via snackbar', async () => { + validateStateServiceSpy.validateAndRepairCurrentState.and.resolveTo(false); + + // FIXED: Should show warning snackbar when validation fails + await service.validateAfterSync(); + + expect(validateStateServiceSpy.validateAndRepairCurrentState).toHaveBeenCalled(); + expect(snackServiceSpy.open).toHaveBeenCalledWith( + jasmine.objectContaining({ type: 'ERROR' }), + ); + }); }); }); diff --git a/src/app/op-log/sync/remote-ops-processing.service.ts b/src/app/op-log/sync/remote-ops-processing.service.ts index b3212ee6a8..2bf0d88bce 100644 --- a/src/app/op-log/sync/remote-ops-processing.service.ts +++ b/src/app/op-log/sync/remote-ops-processing.service.ts @@ -599,8 +599,19 @@ export class RemoteOpsProcessingService { * Pass true when calling from within the sp_op_log lock. */ async validateAfterSync(callerHoldsLock: boolean = false): Promise { - await this.validateStateService.validateAndRepairCurrentState('sync', { - callerHoldsLock, - }); + // FIX #6571: Check and surface validation result. + // Previously, the boolean return was discarded — validation failures + // were invisible and sync reported IN_SYNC despite invalid state. + const isValid = await this.validateStateService.validateAndRepairCurrentState( + 'sync', + { callerHoldsLock }, + ); + if (!isValid) { + OpLog.err('RemoteOpsProcessingService: State validation failed after sync'); + this.snackService.open({ + type: 'ERROR', + msg: T.F.SYNC.S.SYNC_VALIDATION_FAILED, + }); + } } } diff --git a/src/app/t.const.ts b/src/app/t.const.ts index 9111c1cc20..3e71e6f3a9 100644 --- a/src/app/t.const.ts +++ b/src/app/t.const.ts @@ -1386,6 +1386,7 @@ const T = { STORAGE_RECOVERED_AFTER_COMPACTION: 'F.SYNC.S.STORAGE_RECOVERED_AFTER_COMPACTION', SUCCESS_DOWNLOAD: 'F.SYNC.S.SUCCESS_DOWNLOAD', SUCCESS_VIA_BUTTON: 'F.SYNC.S.SUCCESS_VIA_BUTTON', + SYNC_VALIDATION_FAILED: 'F.SYNC.S.SYNC_VALIDATION_FAILED', TIMEOUT_ERROR: 'F.SYNC.S.TIMEOUT_ERROR', TOO_MANY_OPS_TO_DOWNLOAD: 'F.SYNC.S.TOO_MANY_OPS_TO_DOWNLOAD', UNKNOWN_ERROR: 'F.SYNC.S.UNKNOWN_ERROR', diff --git a/src/assets/i18n/en.json b/src/assets/i18n/en.json index e34b036736..47da6e2920 100644 --- a/src/assets/i18n/en.json +++ b/src/assets/i18n/en.json @@ -1346,6 +1346,7 @@ "STORAGE_RECOVERED_AFTER_COMPACTION": "Storage was running low. Old data cleaned up successfully.", "SUCCESS_DOWNLOAD": "Synced data from remote", "SUCCESS_VIA_BUTTON": "Data successfully synced", + "SYNC_VALIDATION_FAILED": "State validation failed after sync. Some data may be inconsistent.", "TIMEOUT_ERROR": "Sync operation timed out. {{suggestion}}", "TOO_MANY_OPS_TO_DOWNLOAD": "Too many sync operations to download. Some changes may be missing.", "UNKNOWN_ERROR": "Unknown Sync Error: {{err}}",