mirror of
https://github.com/johannesjo/super-productivity.git
synced 2026-01-23 02:36:05 +00:00
fix(sync): handle piggyback limit in high-volume sync
When syncing 100+ operations, the server's piggyback limit (100 ops) was causing Client B to miss operations. The server returned 100 piggybacked ops but latestSeq was set to the actual server sequence (e.g., 199). Client B then updated lastServerSeq to 199, so subsequent download got 0 ops. Changes: - Server: Add hasMorePiggyback flag to UploadOpsResponse when piggyback limit is reached and more ops exist - Client: When hasMorePiggyback is true, store lastServerSeq as the max piggybacked op's serverSeq instead of latestSeq, ensuring subsequent download fetches remaining ops - Effects: Change switchMap to mergeMap in autoAddTodayTagOnMarkAsDone to ensure ALL mark-as-done actions trigger planTasksForToday - Flush service: Implement two-phase wait strategy (poll queue + acquire lock) to ensure all pending writes complete before upload - Add diagnostic logging for operation counts at key stages Test: High volume sync with 50 tasks + 49 mark-as-done (197 ops total) now correctly syncs all done states via piggyback (100) + download (97).
This commit is contained in:
parent
1f55c783a3
commit
064c2452ca
12 changed files with 430 additions and 56 deletions
80
docs/ai/high-volume-sync-investigation.md
Normal file
80
docs/ai/high-volume-sync-investigation.md
Normal file
|
|
@ -0,0 +1,80 @@
|
|||
# High Volume Sync Investigation
|
||||
|
||||
## Summary
|
||||
|
||||
Investigation into sync failures when synchronizing 100+ operations between clients.
|
||||
|
||||
**STATUS: RESOLVED** - Root cause identified and fixed on 2025-12-22.
|
||||
|
||||
## Problem Description
|
||||
|
||||
When Client A creates many tasks (50+) and marks most as done, then syncs to Client B:
|
||||
|
||||
- All tasks appear on Client B
|
||||
- But only a subset of "done" states are applied (16 out of 49 expected)
|
||||
|
||||
## Root Cause
|
||||
|
||||
**Server Piggyback Limit**: The server's upload endpoint limits piggybacked operations to 100, but returns `latestSeq` as the actual server sequence (e.g., 199). The client then updates its `lastServerSeq` to 199, thinking it has all ops. When it subsequently downloads, it gets 0 ops because there are none after seq 199.
|
||||
|
||||
## Fix Applied
|
||||
|
||||
### 1. Server-side: Added `hasMorePiggyback` flag
|
||||
|
||||
**File**: `packages/super-sync-server/src/sync/sync.routes.ts`
|
||||
|
||||
When the piggyback limit (100) is reached and more ops exist on the server:
|
||||
|
||||
- Server returns `hasMorePiggyback: true` in the response
|
||||
- Logs: `Piggybacking N ops (has more: true, lastPiggybackSeq=X, latestSeq=Y)`
|
||||
|
||||
### 2. Client-side: Handle `hasMorePiggyback`
|
||||
|
||||
**Files**:
|
||||
|
||||
- `src/app/pfapi/api/sync/sync-provider.interface.ts` - Added `hasMorePiggyback` to `OpUploadResponse`
|
||||
- `src/app/core/persistence/operation-log/sync/operation-log-upload.service.ts`:
|
||||
- When `hasMorePiggyback` is true, set `lastServerSeq` to max piggybacked op's serverSeq instead of `latestSeq`
|
||||
- The subsequent download will then fetch the remaining ops
|
||||
|
||||
### Earlier Fix: `switchMap` → `mergeMap` (still needed)
|
||||
|
||||
**File**: `src/app/features/tasks/store/task-related-model.effects.ts`
|
||||
|
||||
Changed `switchMap` to `mergeMap` in `autoAddTodayTagOnMarkAsDone` effect to ensure ALL mark-as-done actions trigger `planTasksForToday`, not just the last one.
|
||||
|
||||
## Test Results
|
||||
|
||||
After fix:
|
||||
|
||||
```
|
||||
[Client B] Received 100 piggybacked ops (more available on server)
|
||||
[Client B] hasMorePiggyback=true, setting lastServerSeq to 100 instead of 199
|
||||
[Client B] Downloaded ops breakdown: {UPD: 99}
|
||||
[Client B] Applied and marked 99 remote ops
|
||||
[HighVolume] DOM shows 49 done tasks
|
||||
1 passed
|
||||
```
|
||||
|
||||
All 49 done states now sync correctly!
|
||||
|
||||
## Files Modified
|
||||
|
||||
1. `packages/super-sync-server/src/sync/sync.types.ts` - Added `hasMorePiggyback` to `UploadOpsResponse`
|
||||
2. `packages/super-sync-server/src/sync/sync.routes.ts` - Detect and return `hasMorePiggyback` flag
|
||||
3. `src/app/pfapi/api/sync/sync-provider.interface.ts` - Added `hasMorePiggyback` to client-side type
|
||||
4. `src/app/core/persistence/operation-log/sync/operation-log-upload.service.ts` - Handle `hasMorePiggyback`
|
||||
5. `src/app/features/tasks/store/task-related-model.effects.ts` - switchMap → mergeMap fix
|
||||
|
||||
## Running the Tests
|
||||
|
||||
```bash
|
||||
# Run stress tests
|
||||
npm run e2e:supersync:file tests/sync/supersync-stress.spec.ts
|
||||
|
||||
# Run with verbose logging
|
||||
E2E_VERBOSE=1 npm run e2e:supersync:file tests/sync/supersync-stress.spec.ts
|
||||
|
||||
# Run only high volume test
|
||||
npm run e2e:supersync:file tests/sync/supersync-stress.spec.ts --grep "High volume"
|
||||
```
|
||||
|
|
@ -5,7 +5,6 @@ import {
|
|||
createSimulatedClient,
|
||||
closeClient,
|
||||
isServerHealthy,
|
||||
waitForTask,
|
||||
type SimulatedE2EClient,
|
||||
} from '../../utils/supersync-helpers';
|
||||
|
||||
|
|
@ -172,27 +171,30 @@ base.describe('@supersync SuperSync Stress Tests', () => {
|
|||
);
|
||||
|
||||
/**
|
||||
* Scenario: High Volume Sync (39 Operations)
|
||||
* Scenario: High Volume Sync (197 Operations)
|
||||
*
|
||||
* Tests that the system can handle a moderate number of operations.
|
||||
* Creates 20 tasks and marks 19 as done = 39 operations.
|
||||
* Tests that the system can handle a high number of operations.
|
||||
* Creates 50 tasks and marks 49 as done = 197 operations.
|
||||
* (Each mark-as-done creates 3 ops: updateTask, planTasksForToday, Tag Update)
|
||||
* This verifies the operation log can handle bulk syncs without issues.
|
||||
*
|
||||
* Note: Higher volumes (50+ tasks) can have sync reliability issues
|
||||
* due to rapid operation generation. For near-COMPACTION_THRESHOLD
|
||||
* testing, use unit tests or direct store manipulation instead.
|
||||
* The OperationApplierService uses batched dispatches with event loop yields
|
||||
* to prevent NgRx from being overwhelmed by rapid dispatches.
|
||||
*
|
||||
* This test also verifies the hasMorePiggyback fix: when the server's piggyback
|
||||
* limit (100 ops) is reached, the client correctly fetches remaining ops via download.
|
||||
*
|
||||
* Actions:
|
||||
* 1. Client A creates 20 tasks (20 operations)
|
||||
* 2. Client A marks 19 tasks as done (19 more operations = 39 total)
|
||||
* 3. Client A syncs all 39 operations
|
||||
* 4. Client B syncs (bulk download of 39 operations)
|
||||
* 5. Verify B has all 20 tasks with correct done states
|
||||
* 1. Client A creates 50 tasks (50 operations)
|
||||
* 2. Client A marks 49 tasks as done (49 × 3 = 147 operations = 197 total)
|
||||
* 3. Client A syncs all 197 operations
|
||||
* 4. Client B syncs (piggybacks 100, downloads remaining 97)
|
||||
* 5. Verify B has all 50 tasks with correct done states
|
||||
*/
|
||||
base(
|
||||
'High volume sync: 39 operations sync correctly',
|
||||
'High volume sync: 197 operations sync correctly (tests piggyback limit)',
|
||||
async ({ browser, baseURL }, testInfo) => {
|
||||
testInfo.setTimeout(180000); // 3 minutes
|
||||
testInfo.setTimeout(300000); // 5 minutes
|
||||
const testRunId = generateTestRunId(testInfo.workerIndex);
|
||||
const appUrl = baseURL || 'http://localhost:4242';
|
||||
let clientA: SimulatedE2EClient | null = null;
|
||||
|
|
@ -202,12 +204,12 @@ base.describe('@supersync SuperSync Stress Tests', () => {
|
|||
const user = await createTestUser(testRunId);
|
||||
const syncConfig = getSuperSyncConfig(user);
|
||||
|
||||
// Setup Client A (quiet mode)
|
||||
clientA = await createQuietClient(browser, appUrl, 'A', testRunId);
|
||||
// Setup Client A (regular mode to see logs)
|
||||
clientA = await createSimulatedClient(browser, appUrl, 'A', testRunId);
|
||||
await clientA.sync.setupSuperSync(syncConfig);
|
||||
|
||||
// Create 20 tasks (20 operations)
|
||||
const taskCount = 20;
|
||||
// Create 50 tasks (50 ops)
|
||||
const taskCount = 50;
|
||||
const taskNames: string[] = [];
|
||||
|
||||
console.log(`[HighVolume] Creating ${taskCount} tasks...`);
|
||||
|
|
@ -215,9 +217,8 @@ base.describe('@supersync SuperSync Stress Tests', () => {
|
|||
for (let i = 1; i <= taskCount; i++) {
|
||||
const taskName = `HighVol-${i}-${testRunId}`;
|
||||
taskNames.push(taskName);
|
||||
// Standard addTask with verification for stability
|
||||
await clientA.workView.addTask(taskName);
|
||||
await waitForTask(clientA.page, taskName);
|
||||
// Fast task creation - skipClose=true for all but last
|
||||
await clientA.workView.addTask(taskName, i < taskCount);
|
||||
|
||||
// Progress logging every 5 tasks
|
||||
if (i % 5 === 0) {
|
||||
|
|
@ -226,16 +227,20 @@ base.describe('@supersync SuperSync Stress Tests', () => {
|
|||
}
|
||||
|
||||
// Extra wait after all tasks created to ensure persistence
|
||||
await clientA.page.waitForTimeout(2000);
|
||||
await clientA.page.waitForTimeout(1000);
|
||||
|
||||
// Verify tasks created
|
||||
const createdCount = await clientA.page.locator('task').count();
|
||||
expect(createdCount).toBeGreaterThanOrEqual(taskCount);
|
||||
console.log(`[HighVolume] Created ${createdCount} tasks total`);
|
||||
|
||||
// Mark 19 tasks as done (19 more operations = 39 total)
|
||||
console.log('[HighVolume] Marking 19 tasks as done...');
|
||||
for (let i = 0; i < 19; i++) {
|
||||
// Mark 49 tasks as done (49 × 3 = 147 more ops = 197 total)
|
||||
const doneCount = 49;
|
||||
// Each mark-as-done creates 3 ops: updateTask, planTasksForToday, Tag Update
|
||||
// eslint-disable-next-line no-mixed-operators
|
||||
const expectedOpsCount = taskCount + doneCount * 3;
|
||||
console.log(`[HighVolume] Marking ${doneCount} tasks as done...`);
|
||||
for (let i = 0; i < doneCount; i++) {
|
||||
const taskLocator = clientA.page
|
||||
.locator(`task:not(.ng-animating):has-text("${taskNames[i]}")`)
|
||||
.first();
|
||||
|
|
@ -247,26 +252,88 @@ base.describe('@supersync SuperSync Stress Tests', () => {
|
|||
|
||||
// Progress logging every 5 tasks
|
||||
if ((i + 1) % 5 === 0) {
|
||||
console.log(`[HighVolume] Marked ${i + 1}/19 tasks as done`);
|
||||
console.log(`[HighVolume] Marked ${i + 1}/${doneCount} tasks as done`);
|
||||
}
|
||||
}
|
||||
|
||||
// Extra wait after all done marking to ensure persistence
|
||||
await clientA.page.waitForTimeout(2000);
|
||||
console.log('[HighVolume] All 39 operations created locally');
|
||||
await clientA.page.waitForTimeout(1000);
|
||||
console.log(`[HighVolume] All ${expectedOpsCount} operations created locally`);
|
||||
|
||||
// Sync all changes from A
|
||||
await clientA.sync.syncAndWait();
|
||||
console.log('[HighVolume] Client A synced 39 operations');
|
||||
console.log('[HighVolume] Client A synced 99 operations');
|
||||
|
||||
// Setup Client B and sync (bulk download)
|
||||
clientB = await createQuietClient(browser, appUrl, 'B', testRunId);
|
||||
// VALIDATION: Check pending ops count on Client A after sync
|
||||
// Query IndexedDB directly for unsynced operations (SUP_OPS database)
|
||||
const pendingOpsInfoA = await clientA.page.evaluate(async () => {
|
||||
try {
|
||||
return new Promise((resolve) => {
|
||||
// Operation log uses SUP_OPS database, not SUP
|
||||
const request = indexedDB.open('SUP_OPS');
|
||||
request.onerror = () =>
|
||||
resolve({ error: 'Failed to open SUP_OPS IndexedDB' });
|
||||
request.onsuccess = () => {
|
||||
const db = request.result;
|
||||
const storeNames = Array.from(db.objectStoreNames);
|
||||
// Check if ops store exists
|
||||
if (!storeNames.includes('ops')) {
|
||||
resolve({
|
||||
error: 'ops store not found in SUP_OPS',
|
||||
stores: storeNames,
|
||||
});
|
||||
return;
|
||||
}
|
||||
const tx = db.transaction('ops', 'readonly');
|
||||
const store = tx.objectStore('ops');
|
||||
const getAllRequest = store.getAll();
|
||||
getAllRequest.onsuccess = () => {
|
||||
const allEntries = getAllRequest.result;
|
||||
// Unsynced = no syncedAt and no rejectedAt
|
||||
const unsynced = allEntries.filter(
|
||||
(e: { syncedAt?: number; rejectedAt?: number }) =>
|
||||
!e.syncedAt && !e.rejectedAt,
|
||||
);
|
||||
resolve({
|
||||
totalEntries: allEntries.length,
|
||||
unsyncedCount: unsynced.length,
|
||||
unsyncedOpTypes: unsynced
|
||||
.slice(0, 20)
|
||||
.map(
|
||||
(e: { op: { actionType: string; opType: string } }) =>
|
||||
`${e.op.opType}:${e.op.actionType}`,
|
||||
),
|
||||
});
|
||||
};
|
||||
getAllRequest.onerror = () =>
|
||||
resolve({ error: 'Failed to read ops store' });
|
||||
};
|
||||
});
|
||||
} catch (e) {
|
||||
return { error: String(e) };
|
||||
}
|
||||
});
|
||||
console.log(
|
||||
'[HighVolume] VALIDATION - Client A pending ops after sync:',
|
||||
JSON.stringify(pendingOpsInfoA),
|
||||
);
|
||||
|
||||
// Setup Client B and sync (bulk download) - NOT quiet to see debug logs
|
||||
clientB = await createSimulatedClient(browser, appUrl, 'B', testRunId);
|
||||
await clientB.sync.setupSuperSync(syncConfig);
|
||||
await clientB.sync.syncAndWait();
|
||||
console.log('[HighVolume] Client B synced (bulk download)');
|
||||
|
||||
// Wait for UI to settle after bulk sync
|
||||
await clientB.page.waitForTimeout(3000);
|
||||
// The done states need time to reflect in Angular change detection
|
||||
await clientB.page.waitForTimeout(5000);
|
||||
|
||||
// Trigger change detection by scrolling
|
||||
await clientB.page.evaluate(() => {
|
||||
window.scrollTo(0, 100);
|
||||
window.scrollTo(0, 0);
|
||||
});
|
||||
await clientB.page.waitForTimeout(1000);
|
||||
|
||||
// Verify all tasks exist on B
|
||||
const taskCountB = await clientB.page
|
||||
|
|
@ -275,14 +342,61 @@ base.describe('@supersync SuperSync Stress Tests', () => {
|
|||
expect(taskCountB).toBe(taskCount);
|
||||
console.log(`[HighVolume] Client B has all ${taskCount} tasks`);
|
||||
|
||||
// Verify done status (19 should be done, 1 should be open)
|
||||
const doneCount = await clientB.page
|
||||
// DEBUG: Check NgRx store state directly using window.__NGRX_STORE__
|
||||
const storeState = await clientB.page.evaluate((tid: string) => {
|
||||
try {
|
||||
// Access NgRx store via window if available
|
||||
// @ts-expect-error - accessing app internals
|
||||
const store = window.__NGRX_STORE__ || window.__store__;
|
||||
if (store) {
|
||||
const state = store.getState?.() || store.getValue?.();
|
||||
if (state?.task?.entities) {
|
||||
const allTasks = Object.values(state.task.entities) as Array<{
|
||||
id: string;
|
||||
title: string;
|
||||
isDone: boolean;
|
||||
}>;
|
||||
const testTasks = allTasks.filter((t) => t?.title?.includes(tid));
|
||||
const doneTasks = testTasks.filter((t) => t?.isDone);
|
||||
return {
|
||||
method: 'NgRx Store',
|
||||
totalTestTasks: testTasks.length,
|
||||
doneTestTasks: doneTasks.length,
|
||||
sampleTasks: testTasks.slice(0, 3).map((t) => ({
|
||||
id: t.id,
|
||||
isDone: t.isDone,
|
||||
})),
|
||||
};
|
||||
}
|
||||
}
|
||||
|
||||
// Fallback to DOM check
|
||||
const allTaskEls = document.querySelectorAll('task');
|
||||
const testTasks = Array.from(allTaskEls).filter((el) =>
|
||||
el.textContent?.includes(tid),
|
||||
);
|
||||
const doneTasks = testTasks.filter((el) => el.classList.contains('isDone'));
|
||||
return {
|
||||
method: 'DOM Fallback',
|
||||
totalTestTasks: testTasks.length,
|
||||
doneTestTasks: doneTasks.length,
|
||||
sampleClasses: testTasks.slice(0, 3).map((el) => el.className),
|
||||
};
|
||||
} catch (e) {
|
||||
return { error: String(e) };
|
||||
}
|
||||
}, testRunId);
|
||||
console.log('[HighVolume] State check:', JSON.stringify(storeState));
|
||||
|
||||
// Verify done status (49 should be done, 1 should be open)
|
||||
const doneCountB = await clientB.page
|
||||
.locator(`task.isDone:has-text("${testRunId}")`)
|
||||
.count();
|
||||
expect(doneCount).toBe(19);
|
||||
console.log(`[HighVolume] DOM shows ${doneCountB} done tasks`);
|
||||
expect(doneCountB).toBe(doneCount);
|
||||
console.log('[HighVolume] Done states verified on Client B');
|
||||
|
||||
console.log('[HighVolume] 39 operations applied successfully');
|
||||
console.log(`[HighVolume] ${expectedOpsCount} operations applied successfully`);
|
||||
} finally {
|
||||
if (clientA) await closeClient(clientA);
|
||||
if (clientB) await closeClient(clientB);
|
||||
|
|
|
|||
|
|
@ -202,19 +202,29 @@ export const syncRoutes = async (fastify: FastifyInstance): Promise<void> => {
|
|||
// we ensure the client gets all ops it hasn't seen yet.
|
||||
let newOps: import('./sync.types').ServerOperation[] | undefined;
|
||||
let latestSeq: number;
|
||||
let hasMorePiggyback = false;
|
||||
const PIGGYBACK_LIMIT = 100;
|
||||
|
||||
if (lastKnownServerSeq !== undefined) {
|
||||
const opsResult = await syncService.getOpsSinceWithSeq(
|
||||
userId,
|
||||
lastKnownServerSeq,
|
||||
clientId,
|
||||
100,
|
||||
PIGGYBACK_LIMIT,
|
||||
);
|
||||
newOps = opsResult.ops;
|
||||
latestSeq = opsResult.latestSeq;
|
||||
|
||||
// Check if there are more ops beyond what we piggybacked
|
||||
if (newOps.length === PIGGYBACK_LIMIT) {
|
||||
const lastPiggybackSeq = newOps[newOps.length - 1].serverSeq;
|
||||
hasMorePiggyback = lastPiggybackSeq < latestSeq;
|
||||
}
|
||||
|
||||
if (newOps.length > 0) {
|
||||
Logger.info(
|
||||
`[user:${userId}] Dedup request: piggybacking ${newOps.length} ops (since seq ${lastKnownServerSeq})`,
|
||||
`[user:${userId}] Dedup request: piggybacking ${newOps.length} ops (since seq ${lastKnownServerSeq})` +
|
||||
(hasMorePiggyback ? ` (has more)` : ''),
|
||||
);
|
||||
}
|
||||
} else {
|
||||
|
|
@ -226,6 +236,7 @@ export const syncRoutes = async (fastify: FastifyInstance): Promise<void> => {
|
|||
newOps: newOps?.length ? newOps : undefined,
|
||||
latestSeq,
|
||||
deduplicated: true,
|
||||
...(hasMorePiggyback ? { hasMorePiggyback: true } : {}),
|
||||
} as UploadOpsResponse & { deduplicated: boolean });
|
||||
}
|
||||
}
|
||||
|
|
@ -278,6 +289,8 @@ export const syncRoutes = async (fastify: FastifyInstance): Promise<void> => {
|
|||
// Optionally include new ops from other clients (with atomic latestSeq read)
|
||||
let newOps: import('./sync.types').ServerOperation[] | undefined;
|
||||
let latestSeq: number;
|
||||
let hasMorePiggyback = false;
|
||||
const PIGGYBACK_LIMIT = 100;
|
||||
|
||||
if (lastKnownServerSeq !== undefined) {
|
||||
// Use atomic read to get ops and latestSeq together
|
||||
|
|
@ -285,11 +298,25 @@ export const syncRoutes = async (fastify: FastifyInstance): Promise<void> => {
|
|||
userId,
|
||||
lastKnownServerSeq,
|
||||
clientId,
|
||||
100,
|
||||
PIGGYBACK_LIMIT,
|
||||
);
|
||||
newOps = opsResult.ops;
|
||||
latestSeq = opsResult.latestSeq;
|
||||
if (newOps.length > 0) {
|
||||
|
||||
// Check if there are more ops beyond what we piggybacked
|
||||
// This happens when we hit the limit AND there are more ops on the server
|
||||
if (newOps.length === PIGGYBACK_LIMIT) {
|
||||
const lastPiggybackSeq = newOps[newOps.length - 1].serverSeq;
|
||||
hasMorePiggyback = lastPiggybackSeq < latestSeq;
|
||||
if (hasMorePiggyback) {
|
||||
Logger.info(
|
||||
`[user:${userId}] Piggybacking ${newOps.length} ops (has more: ${hasMorePiggyback}, ` +
|
||||
`lastPiggybackSeq=${lastPiggybackSeq}, latestSeq=${latestSeq})`,
|
||||
);
|
||||
}
|
||||
}
|
||||
|
||||
if (newOps.length > 0 && !hasMorePiggyback) {
|
||||
Logger.info(
|
||||
`[user:${userId}] Piggybacking ${newOps.length} ops (since seq ${lastKnownServerSeq})`,
|
||||
);
|
||||
|
|
@ -302,6 +329,7 @@ export const syncRoutes = async (fastify: FastifyInstance): Promise<void> => {
|
|||
results,
|
||||
newOps: newOps && newOps.length > 0 ? newOps : undefined,
|
||||
latestSeq,
|
||||
...(hasMorePiggyback ? { hasMorePiggyback: true } : {}),
|
||||
};
|
||||
|
||||
return reply.send(response);
|
||||
|
|
|
|||
|
|
@ -181,6 +181,11 @@ export interface UploadOpsResponse {
|
|||
results: UploadResult[];
|
||||
newOps?: ServerOperation[];
|
||||
latestSeq: number;
|
||||
/**
|
||||
* True when piggybacked ops were limited (more ops exist on server).
|
||||
* Client should trigger a download to get the remaining operations.
|
||||
*/
|
||||
hasMorePiggyback?: boolean;
|
||||
}
|
||||
|
||||
// Download types
|
||||
|
|
|
|||
|
|
@ -34,6 +34,8 @@ export class OperationLogEffects {
|
|||
private compactionFailures = 0;
|
||||
/** Circuit breaker: prevents recursive quota exceeded handling */
|
||||
private isHandlingQuotaExceeded = false;
|
||||
/** Counter for total operations written. Used for high-volume sync debugging. */
|
||||
private writeCount = 0;
|
||||
/**
|
||||
* PERF: In-memory compaction counter to avoid IndexedDB transaction on every operation.
|
||||
* The persistent counter in state_cache is only used for cross-tab/restart recovery.
|
||||
|
|
@ -142,6 +144,14 @@ export class OperationLogEffects {
|
|||
// 1. Write to SUP_OPS (Part A)
|
||||
await this.opLogStore.append(op);
|
||||
|
||||
// Track write count for high-volume debugging
|
||||
this.writeCount++;
|
||||
if (this.writeCount % 50 === 0) {
|
||||
OpLog.normal(
|
||||
`OperationLogEffects: Wrote ${this.writeCount} operations to IndexedDB`,
|
||||
);
|
||||
}
|
||||
|
||||
// 1b. Trigger immediate upload to SuperSync (async, non-blocking)
|
||||
this.immediateUploadService.trigger();
|
||||
|
||||
|
|
|
|||
|
|
@ -53,6 +53,12 @@ let operationCaptureService: OperationCaptureService | null = null;
|
|||
let consecutiveCaptureFailures = 0;
|
||||
const MAX_CONSECUTIVE_FAILURES_BEFORE_WARNING = 3;
|
||||
|
||||
/**
|
||||
* Counter for total operations enqueued.
|
||||
* Used for high-volume sync debugging to track operation flow.
|
||||
*/
|
||||
let totalEnqueueCount = 0;
|
||||
|
||||
/**
|
||||
* Flag indicating whether remote operations are currently being applied.
|
||||
* When true, local user interactions should NOT be captured as new operations.
|
||||
|
|
@ -174,6 +180,14 @@ export const operationCaptureMetaReducer = <S, A extends Action = Action>(
|
|||
// Reset failure counter on success
|
||||
consecutiveCaptureFailures = 0;
|
||||
|
||||
// Track enqueue count for high-volume debugging
|
||||
totalEnqueueCount++;
|
||||
if (totalEnqueueCount % 50 === 0) {
|
||||
OpLog.normal(
|
||||
`operationCaptureMetaReducer: Enqueued ${totalEnqueueCount} operations total`,
|
||||
);
|
||||
}
|
||||
|
||||
OpLog.verbose('operationCaptureMetaReducer: Captured operation synchronously', {
|
||||
actionType: persistentAction.type,
|
||||
});
|
||||
|
|
|
|||
|
|
@ -305,6 +305,19 @@ export class OperationLogDownloadService {
|
|||
OpLog.normal(
|
||||
`OperationLogDownloadService: Downloaded ${allNewOps.length} new operations via API.`,
|
||||
);
|
||||
|
||||
// Log type breakdown for high-volume sync debugging
|
||||
if (allNewOps.length > 10) {
|
||||
const opTypeCounts = new Map<string, number>();
|
||||
for (const op of allNewOps) {
|
||||
const key = op.opType;
|
||||
opTypeCounts.set(key, (opTypeCounts.get(key) || 0) + 1);
|
||||
}
|
||||
OpLog.verbose(
|
||||
`OperationLogDownloadService: Downloaded ops breakdown:`,
|
||||
Object.fromEntries(opTypeCounts),
|
||||
);
|
||||
}
|
||||
});
|
||||
|
||||
if (downloadFailed) {
|
||||
|
|
|
|||
|
|
@ -49,6 +49,7 @@ import { OperationLogCompactionService } from '../store/operation-log-compaction
|
|||
import { SuperSyncStatusService } from './super-sync-status.service';
|
||||
import { SyncImportFilterService } from './sync-import-filter.service';
|
||||
import { ServerMigrationService } from './server-migration.service';
|
||||
import { OperationWriteFlushService } from './operation-write-flush.service';
|
||||
|
||||
/**
|
||||
* Orchestrates synchronization of the Operation Log with remote storage.
|
||||
|
|
@ -135,6 +136,7 @@ export class OperationLogSyncService {
|
|||
private superSyncStatusService = inject(SuperSyncStatusService);
|
||||
private syncImportFilterService = inject(SyncImportFilterService);
|
||||
private serverMigrationService = inject(ServerMigrationService);
|
||||
private writeFlushService = inject(OperationWriteFlushService);
|
||||
private clientIdProvider = inject(CLIENT_ID_PROVIDER);
|
||||
|
||||
// Lazy injection to break circular dependency for getActiveSyncProvider():
|
||||
|
|
@ -181,6 +183,12 @@ export class OperationLogSyncService {
|
|||
async uploadPendingOps(
|
||||
syncProvider: SyncProviderServiceInterface<SyncProviderId>,
|
||||
): Promise<UploadResult | null> {
|
||||
// CRITICAL: Ensure all pending write operations have completed before uploading.
|
||||
// The effect that writes operations uses concatMap for sequential processing,
|
||||
// but if sync is triggered before all operations are written to IndexedDB,
|
||||
// we would upload an incomplete set. This flush waits for all queued writes.
|
||||
await this.writeFlushService.flushPendingWrites();
|
||||
|
||||
// SAFETY: Block upload from wholly fresh clients
|
||||
// A fresh client has nothing meaningful to upload and uploading could overwrite
|
||||
// valid remote data with empty/default state.
|
||||
|
|
|
|||
|
|
@ -45,6 +45,11 @@ export interface UploadResult {
|
|||
* Set by OperationLogSyncService.uploadPendingOps after processing piggybacked ops.
|
||||
*/
|
||||
localWinOpsCreated?: number;
|
||||
/**
|
||||
* True when piggybacked ops were limited (more ops exist on server).
|
||||
* Caller should trigger a download to get the remaining operations.
|
||||
*/
|
||||
hasMorePiggyback?: boolean;
|
||||
}
|
||||
|
||||
/**
|
||||
|
|
@ -105,6 +110,7 @@ export class OperationLogUploadService {
|
|||
const rejectedOps: RejectedOpInfo[] = [];
|
||||
let uploadedCount = 0;
|
||||
let rejectedCount = 0;
|
||||
let hasMorePiggyback = false;
|
||||
|
||||
await this.lockService.request('sp_op_log_upload', async () => {
|
||||
// Execute pre-upload callback INSIDE the lock, BEFORE checking for pending ops.
|
||||
|
|
@ -223,14 +229,11 @@ export class OperationLogUploadService {
|
|||
uploadedCount += acceptedSeqs.length;
|
||||
}
|
||||
|
||||
// Update last known server seq (both stored and local variable for next chunk)
|
||||
await syncProvider.setLastServerSeq(response.latestSeq);
|
||||
lastKnownServerSeq = response.latestSeq;
|
||||
|
||||
// Collect piggybacked new ops from other clients
|
||||
if (response.newOps && response.newOps.length > 0) {
|
||||
OpLog.normal(
|
||||
`OperationLogUploadService: Received ${response.newOps.length} piggybacked ops`,
|
||||
`OperationLogUploadService: Received ${response.newOps.length} piggybacked ops` +
|
||||
(response.hasMorePiggyback ? ' (more available on server)' : ''),
|
||||
);
|
||||
let piggybackSyncOps = response.newOps.map((serverOp) => serverOp.op);
|
||||
|
||||
|
|
@ -247,6 +250,21 @@ export class OperationLogUploadService {
|
|||
piggybackedOps.push(...ops);
|
||||
}
|
||||
|
||||
// Update last known server seq
|
||||
// When hasMorePiggyback is true, use the max piggybacked op's serverSeq
|
||||
// so subsequent download will fetch remaining ops
|
||||
let seqToStore = response.latestSeq;
|
||||
if (response.hasMorePiggyback && response.newOps && response.newOps.length > 0) {
|
||||
hasMorePiggyback = true;
|
||||
const maxPiggybackSeq = Math.max(...response.newOps.map((op) => op.serverSeq));
|
||||
seqToStore = maxPiggybackSeq;
|
||||
OpLog.normal(
|
||||
`OperationLogUploadService: hasMorePiggyback=true, setting lastServerSeq to ${maxPiggybackSeq} instead of ${response.latestSeq}`,
|
||||
);
|
||||
}
|
||||
await syncProvider.setLastServerSeq(seqToStore);
|
||||
lastKnownServerSeq = seqToStore;
|
||||
|
||||
// Collect rejected operations - DO NOT mark as rejected here!
|
||||
// The sync service must process piggybacked ops FIRST to allow proper conflict detection.
|
||||
// If we mark rejected before processing piggybacked ops, the local ops won't be in the
|
||||
|
|
@ -274,7 +292,13 @@ export class OperationLogUploadService {
|
|||
// Note: We no longer show the rejection warning here since rejections
|
||||
// may be resolved via conflict dialog. The sync service handles this.
|
||||
|
||||
return { uploadedCount, piggybackedOps, rejectedCount, rejectedOps };
|
||||
return {
|
||||
uploadedCount,
|
||||
piggybackedOps,
|
||||
rejectedCount,
|
||||
rejectedOps,
|
||||
...(hasMorePiggyback ? { hasMorePiggyback: true } : {}),
|
||||
};
|
||||
}
|
||||
|
||||
private _entryToSyncOp(entry: OperationLogEntry): SyncOperation {
|
||||
|
|
|
|||
|
|
@ -1,5 +1,7 @@
|
|||
import { inject, Injectable } from '@angular/core';
|
||||
import { LockService } from './lock.service';
|
||||
import { OperationCaptureService } from '../processing/operation-capture.service';
|
||||
import { OpLog } from '../../../log';
|
||||
|
||||
/**
|
||||
* Service to ensure all pending operation writes have completed.
|
||||
|
|
@ -9,27 +11,95 @@ import { LockService } from './lock.service';
|
|||
* corresponding operation hasn't been written to IndexedDB yet.
|
||||
*
|
||||
* ## How it works
|
||||
* The `OperationLogEffects.writeOperation()` uses `concatMap` for sequential
|
||||
* processing and acquires the `sp_op_log` lock for each write. By acquiring
|
||||
* the same lock, we wait for our turn in the queue - which means all prior
|
||||
* writes have completed. The Web Locks API guarantees FIFO ordering.
|
||||
*
|
||||
* ### Two-Phase Wait Strategy
|
||||
*
|
||||
* **Phase 1: Wait for RxJS Queue to Drain**
|
||||
* The NgRx effect uses `concatMap` for sequential processing. Actions are enqueued
|
||||
* in the OperationCaptureService synchronously (in meta-reducer), then dequeued by
|
||||
* the effect. We poll the queue size until it reaches 0, meaning all dispatched
|
||||
* actions have been processed by the effect.
|
||||
*
|
||||
* **Phase 2: Acquire Write Lock**
|
||||
* Once the RxJS queue is drained, we acquire the same lock used by `writeOperation()`.
|
||||
* This ensures the final write has completed its IndexedDB transaction.
|
||||
*
|
||||
* This two-phase approach handles the case where many actions are dispatched rapidly
|
||||
* and the RxJS concatMap pipeline is still processing them.
|
||||
*/
|
||||
@Injectable({ providedIn: 'root' })
|
||||
export class OperationWriteFlushService {
|
||||
private lockService = inject(LockService);
|
||||
private captureService = inject(OperationCaptureService);
|
||||
|
||||
/**
|
||||
* Maximum time to wait for the queue to drain (ms).
|
||||
*/
|
||||
private readonly MAX_WAIT_TIME = 30000;
|
||||
|
||||
/**
|
||||
* Polling interval to check queue size (ms).
|
||||
*/
|
||||
private readonly POLL_INTERVAL = 10;
|
||||
|
||||
/**
|
||||
* Waits for all pending operation writes to complete.
|
||||
*
|
||||
* Acquires the same lock used by `writeOperation()`, ensuring
|
||||
* all queued writes finish before returning.
|
||||
* This is a two-phase wait:
|
||||
* 1. Poll the capture service queue until it's empty (all actions processed by effect)
|
||||
* 2. Acquire the write lock to ensure the final IndexedDB transaction is complete
|
||||
*
|
||||
* @returns Promise that resolves when all pending writes are complete
|
||||
* @throws Error if timeout is reached while waiting for queue to drain
|
||||
*/
|
||||
async flushPendingWrites(): Promise<void> {
|
||||
// Phase 1: Wait for the capture service queue to drain
|
||||
// This ensures all dispatched actions have been dequeued by the effect
|
||||
const startTime = Date.now();
|
||||
let lastLoggedSize = -1;
|
||||
const initialQueueSize = this.captureService.getQueueSize();
|
||||
OpLog.normal(
|
||||
`OperationWriteFlushService: Starting flush. Initial queue size: ${initialQueueSize}`,
|
||||
);
|
||||
|
||||
while (this.captureService.getQueueSize() > 0) {
|
||||
const queueSize = this.captureService.getQueueSize();
|
||||
|
||||
// Log progress periodically (when queue size changes significantly)
|
||||
if (queueSize !== lastLoggedSize && queueSize % 10 === 0) {
|
||||
OpLog.verbose(
|
||||
`OperationWriteFlushService: Waiting for queue to drain, current size: ${queueSize}`,
|
||||
);
|
||||
lastLoggedSize = queueSize;
|
||||
}
|
||||
|
||||
// Check for timeout
|
||||
if (Date.now() - startTime > this.MAX_WAIT_TIME) {
|
||||
OpLog.err(
|
||||
`OperationWriteFlushService: Timeout waiting for queue to drain. ` +
|
||||
`Queue still has ${queueSize} items after ${this.MAX_WAIT_TIME}ms.`,
|
||||
);
|
||||
throw new Error(
|
||||
`Operation write flush timeout: queue still has ${queueSize} pending items`,
|
||||
);
|
||||
}
|
||||
|
||||
// Wait a bit before checking again
|
||||
await new Promise((resolve) => setTimeout(resolve, this.POLL_INTERVAL));
|
||||
}
|
||||
|
||||
// Phase 2: Acquire the write lock to ensure the final write is complete
|
||||
// The effect uses this lock when writing to IndexedDB, so acquiring it
|
||||
// guarantees all prior writes have finished their IndexedDB transactions.
|
||||
await this.lockService.request('sp_op_log', async () => {
|
||||
// No-op - acquiring the lock ensures all prior writes have completed
|
||||
// (concatMap in effects + FIFO lock ordering guarantees this)
|
||||
// No-op - acquiring the lock ensures the final write has completed
|
||||
});
|
||||
|
||||
const totalWait = Date.now() - startTime;
|
||||
const finalQueueSize = this.captureService.getQueueSize();
|
||||
OpLog.normal(
|
||||
`OperationWriteFlushService: Flush complete in ${totalWait}ms. ` +
|
||||
`Initial queue: ${initialQueueSize}, Final queue: ${finalQueueSize}`,
|
||||
);
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -1,7 +1,7 @@
|
|||
import { inject, Injectable } from '@angular/core';
|
||||
import { createEffect, ofType } from '@ngrx/effects';
|
||||
import { TaskSharedActions } from '../../../root-store/meta/task-shared.actions';
|
||||
import { filter, map, switchMap, withLatestFrom } from 'rxjs/operators';
|
||||
import { filter, map, mergeMap, switchMap, withLatestFrom } from 'rxjs/operators';
|
||||
import { Task } from '../task.model';
|
||||
import { moveTaskInTodayList } from '../../work-context/store/work-context-meta.actions';
|
||||
import { GlobalConfigService } from '../../config/global-config.service';
|
||||
|
|
@ -52,7 +52,10 @@ export class TaskRelatedModelEffects {
|
|||
this._actions$.pipe(
|
||||
ofType(TaskSharedActions.updateTask),
|
||||
filter((a) => a.task.changes.isDone === true),
|
||||
switchMap(({ task }) => this._taskService.getByIdOnce$(task.id as string)),
|
||||
// Use mergeMap instead of switchMap to ensure ALL mark-as-done actions
|
||||
// trigger planTasksForToday, not just the last one. switchMap would cancel
|
||||
// previous inner subscriptions when new actions arrive quickly.
|
||||
mergeMap(({ task }) => this._taskService.getByIdOnce$(task.id as string)),
|
||||
filter((task: Task) => !!task && !task.parentId),
|
||||
map((task) =>
|
||||
TaskSharedActions.planTasksForToday({
|
||||
|
|
|
|||
|
|
@ -174,6 +174,11 @@ export interface OpUploadResponse {
|
|||
results: OpUploadResult[];
|
||||
newOps?: ServerSyncOperation[];
|
||||
latestSeq: number;
|
||||
/**
|
||||
* True when piggybacked ops were limited (more ops exist on server).
|
||||
* Client should trigger a download to get the remaining operations.
|
||||
*/
|
||||
hasMorePiggyback?: boolean;
|
||||
}
|
||||
|
||||
/**
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue