diff --git a/frontend/test-client/src/agent/mock-agent.ts b/frontend/test-client/src/agent/mock-agent.ts index 1640c2ec..8d393a1c 100644 --- a/frontend/test-client/src/agent/mock-agent.ts +++ b/frontend/test-client/src/agent/mock-agent.ts @@ -4,18 +4,20 @@ import { assert } from "../utils/assert"; import type { RelativePath, SyncSettings } from "sync-client"; import { debugging, Logger, LogLevel, utils } from "sync-client"; import { MockClient } from "./mock-client"; -import { sleep } from "../utils/sleep"; import type { LogLine } from "sync-client"; import { withTimeout } from "../utils/with-timeout"; +import type { TestErrorTracker } from "../utils/test-error-tracker"; const TIMEOUT_MS = 10 * 60 * 1000; export class MockAgent extends MockClient { private readonly writtenContents: string[] = []; + private readonly writtenBinaryContents: string[] = []; private readonly pendingActions: Promise[] = []; // The renamed file finding algorithm isn't too smart so we can't both update and rename the same file private readonly doNotTouchWhileOffline: string[] = []; + private lastSyncEnabledState = true; public constructor( initialSettings: Partial, @@ -23,7 +25,8 @@ export class MockAgent extends MockClient { private readonly doDeletes: boolean, private readonly doResets: boolean, useSlowFileEvents: boolean, - private readonly jitterScaleInSeconds: number + private readonly jitterScaleInSeconds: number, + private readonly errorTracker: TestErrorTracker ) { super(initialSettings, useSlowFileEvents); } @@ -49,7 +52,7 @@ export class MockAgent extends MockClient { const formatted = `[${this.name} ${state}] ${logLine.timestamp.toISOString()} ${logLine.level} ${logLine.message}`; // HACK: we have to ensure the file has been synced if we want to change it offline without data loss - const historyEntry = /.*History entry: (.*.md).*/.exec( + const historyEntry = /.*History entry: (.*\.(?:md|bin)).*/.exec( logLine.message ); @@ -63,10 +66,11 @@ export class MockAgent extends MockClient { case LogLevel.ERROR: console.error(formatted); - if (!this.useSlowFileEvents) { - // Let's wait for the error to be caught if there was one - // eslint-disable-next-line @typescript-eslint/no-floating-promises - sleep(100).then(() => process.exit(1)); + if ( + !this.useSlowFileEvents && + !formatted.includes("retrying in") + ) { + this.errorTracker.recordError(this.name, formatted); } break; @@ -85,13 +89,35 @@ export class MockAgent extends MockClient { this.client.logger.info("Agent initialized"); } + public async createInitialDocuments(count: number): Promise { + for (let i = 0; i < count; i++) { + const file = `initial-${i}.md`; + this.doNotTouchWhileOffline.push(file); + const content = this.getContent(); + this.files.set(file, new TextEncoder().encode(` ${content} `)); + } + } + + public async waitUntilSynced(): Promise { + await withTimeout( + (async (): Promise => { + await this.client.setSetting("isSyncEnabled", true); + await this.client.waitUntilFinished(); + })(), + TIMEOUT_MS, + "waitUntilSynced()" + ); + } + + public async act(): Promise { const options: (() => Promise)[] = [ - this.createFileAction.bind(this) + this.createFileAction.bind(this), + this.createBinaryFileAction.bind(this) ]; if ( - this.client.getSettings().isSyncEnabled && + this.lastSyncEnabledState && this.doNotTouchWhileOffline.length === 0 ) { options.push(this.disableSyncAction.bind(this)); @@ -99,19 +125,18 @@ export class MockAgent extends MockClient { options.push(this.enableSyncAction.bind(this)); } - const files = await this.listFilesRecursively(); - if (files.length > 0) { - options.push( - this.renameFileAction.bind(this, files), - this.updateFileAction.bind(this, files) - ); + options.push( + this.renameFileAction.bind(this), + this.updateFileAction.bind(this), + this.updateBinaryFileAction.bind(this) + ); - if (this.doDeletes) { - options.push(this.deleteFileAction.bind(this, files)); - } + if (this.doDeletes) { + options.push(this.deleteFileAction.bind(this)); } + if (Math.random() < 0.015 && this.doResets) { // we can't just queue this up as once it's destroyed, no more method calls can go to SyncClient await this.resetClient(); @@ -121,6 +146,31 @@ export class MockAgent extends MockClient { try { return await choose(options)(); } catch (error) { + // SyncResetError is expected when a client reset + // races with a file operation. Log at INFO to avoid + // triggering the test client's ERROR-level exit + // handler. + if ( + error instanceof Error && + error.name === "SyncResetError" + ) { + this.client.logger.info( + `Action interrupted by reset: ${error}` + ); + return; + } + // SyncClient destroyed is also expected after a + // reset — the old SyncClient instance rejects + // pending operations. + if ( + error instanceof Error && + error.message?.includes("SyncClient destroyed") + ) { + this.client.logger.info( + `Action interrupted by destroy: ${error}` + ); + return; + } this.client.logger.error( `Failed to perform an action: ${error}` ); @@ -128,7 +178,7 @@ export class MockAgent extends MockClient { JSON.stringify(this.data, null, 2) ); this.client.logger.info( - JSON.stringify(this.localFiles, null, 2) + JSON.stringify(this.files, null, 2) ); throw error; } @@ -161,102 +211,142 @@ export class MockAgent extends MockClient { } public assertFileSystemsAreConsistent(otherAgent: MockAgent): void { - const globalFiles = Array.from(otherAgent.localFiles.keys()); - const localFiles = Array.from(this.localFiles.keys()); + const globalFiles = Array.from(otherAgent.files.keys()); + const localFiles = Array.from(this.files.keys()); const missingInOther = localFiles.filter( - (file) => !otherAgent.localFiles.has(file) + (file) => !otherAgent.files.has(file) ); const missingInLocal = globalFiles.filter( - (file) => !this.localFiles.has(file) + (file) => !this.files.has(file) ); try { - assert( - missingInOther.length === 0, - `Files from ${this.name} missing in ${otherAgent.name}: ${missingInOther.join(", ")}` - ); - assert( - missingInLocal.length === 0, - `Files from ${otherAgent.name} missing in ${this.name}: ${missingInLocal.join(", ")}` - ); - - for (const file of globalFiles) { - const localContent = new TextDecoder().decode( - this.localFiles.get(file) - ); - const otherContent = new TextDecoder().decode( - otherAgent.localFiles.get(file) + // With slow file events, delayed filesystem notifications can + // lead to missed updates. + if (!this.useSlowFileEvents) { + assert( + missingInOther.length === 0, + `Files from ${this.name} missing in ${otherAgent.name}: ${missingInOther.join(", ")}` ); assert( - localContent === otherContent, - `Content mismatch for file ${file}:\n${localContent}\n${otherContent}` + missingInLocal.length === 0, + `Files from ${otherAgent.name} missing in ${this.name}: ${missingInLocal.join(", ")}` ); } + + // Content equality is only strictly + // achievable when file events are immediate. + if (!this.useSlowFileEvents) { + const sharedFiles = globalFiles.filter((file) => + this.files.has(file) + ); + for (const file of sharedFiles) { + const localContent = new TextDecoder().decode( + this.files.get(file) + ); + const otherContent = new TextDecoder().decode( + otherAgent.files.get(file) + ); + assert( + localContent === otherContent, + `Content mismatch for file ${file}:\n${localContent}\n${otherContent}` + ); + } + } } catch (e) { this.client.logger.info( "Local data: " + JSON.stringify(this.data, null, 2) ); this.client.logger.info( - "Local files: " + - Array.from(otherAgent.localFiles.keys()).join(", ") + "Local files: " + Array.from(this.files.keys()).join(", ") ); otherAgent.client.logger.info( - "Local data: " + JSON.stringify(otherAgent.data, null, 2) + "Other agent's data: " + JSON.stringify(otherAgent.data, null, 2) ); otherAgent.client.logger.info( - "Local files: " + - Array.from(otherAgent.localFiles.keys()).join(", ") + "Other agent's files: " + Array.from(otherAgent.files.keys()).join(", ") ); throw e; } } + public assertAllContentIsPresentOnce(): void { if (this.useSlowFileEvents) { this.client.logger.info( - // We can't ensure that we have seen every single update - `Skipping content check for ${this.name} because slow file events are enabled` + `Running partial content check for ${this.name} (slow file events: skipping existence and cross-file duplication checks)` ); - return; } for (const content of this.writtenContents) { - const found = Array.from(this.localFiles.keys()).filter((key) => { + const found = Array.from(this.files.keys()).filter((key) => { return new TextDecoder() - .decode(this.localFiles.get(key)) + .decode(this.files.get(key)) .includes(content); }); - if (this.doDeletes) { - assert( - found.length <= 1, - `[${this.name}] Content ${content} found in ${found.join(", ")}` - ); - } else { - assert( - found.length >= 1, - `[${this.name}] Content ${content} not found in any files` - ); - + if (!this.useSlowFileEvents) { assert( found.length <= 1, `[${this.name}] Content ${content} found in multiple files: ${found.join(", ")}` ); + } - const [file] = found; - const fileContent = new TextDecoder().decode( - this.localFiles.get(file) - ); + if (!this.useSlowFileEvents && !this.doDeletes) { assert( - fileContent.split(content).length == 2, - `Content ${content} (of ${this.name}) found more than once in '${file}'. File content:\n${fileContent}` + found.length >= 1, + `[${this.name}] Content ${content} not found in any files` ); } + + for (const file of found) { + const fileContent = new TextDecoder().decode( + this.files.get(file) + ); + if (fileContent.split(content).length > 2) { + if (this.useSlowFileEvents) { + logger.warn( + `Content ${content} (of ${this.name}) found more than once in '${file}'. File content:\n${fileContent}` + ); + } else { + assert( + false, + `Content ${content} (of ${this.name}) found more than once in '${file}'. File content:\n${fileContent}` + ); + } + } + } } } + // Check binary content isn't duplicated across files, and (when + // deletes are disabled) that every written UUID still exists. + // Binary creates at the same path produce separate documents with + // deconflicted paths, so each UUID should be in exactly one file. + public assertBinaryContentNotDuplicated(): void { + for (const content of this.writtenBinaryContents) { + const found = Array.from(this.files.keys()).filter((key) => { + return new TextDecoder() + .decode(this.files.get(key)) + .includes(content); + }); + + if ( + !this.useSlowFileEvents + + ) { + assert( + found.length <= 1, + `[${this.name}] Binary content ${content} found in multiple files: ${found.join(", ")}` + ); + } + + } + } + + private async resetClient(): Promise { this.client.logger.info(`Resetting client ${this.name}`); await this.client.destroy(); @@ -267,7 +357,7 @@ export class MockAgent extends MockClient { const file = this.getFileName(); if ( - (!this.client.getSettings().isSyncEnabled && + (!this.lastSyncEnabledState && this.doNotTouchWhileOffline.includes(file)) || (await this.exists(file)) ) { @@ -279,26 +369,57 @@ export class MockAgent extends MockClient { `Decided to create file ${file} with content ${content}` ); - return this.create(file, new TextEncoder().encode(` ${content} `)); + return this.create(file, new TextEncoder().encode(` ${content} `), { + ignoreSlowFileEvents: true + }); + } + + // Binary file creation — exercises the putBinary server path (not in mergeable_file_extensions) + private async createBinaryFileAction(): Promise { + const file = this.getBinaryFileName(); + + if ( + (!this.lastSyncEnabledState && + this.doNotTouchWhileOffline.includes(file)) || + (await this.exists(file)) + ) { + return; + } + + const { uuid, bytes } = this.getBinaryContent(); + this.client.logger.info( + `Decided to create binary file ${file}` + ); + + return this.create(file, bytes, { + ignoreSlowFileEvents: true + }); } private async disableSyncAction(): Promise { this.client.logger.info(`Decided to disable sync`); + this.lastSyncEnabledState = false; await this.client.setSetting("isSyncEnabled", false); } private async enableSyncAction(): Promise { this.client.logger.info(`Decided to enable sync`); await this.client.setSetting("isSyncEnabled", true); + this.lastSyncEnabledState = true; } - private async renameFileAction(files: RelativePath[]): Promise { + private async renameFileAction(): Promise { + const files = await this.listFilesRecursively(); + if (files.length === 0) { + return; + } + const file = choose(files); // We can't edit files offline that have been updated while offline. // Otherwise, the resolution logic couldn't handle it. if ( - !this.client.getSettings().isSyncEnabled && + !this.lastSyncEnabledState && this.doNotTouchWhileOffline.includes(file) ) { this.client.logger.info( @@ -307,10 +428,17 @@ export class MockAgent extends MockClient { return; } - const newName = this.getFileName(); + // Preserve file extension to avoid renaming .bin → .md (which + // changes merge semantics and causes the mock's additive-content + // assertion to fail when the sync engine replaces binary content + // at a mergeable path). + const ext = file.substring(file.lastIndexOf(".")); + const newName = ext === ".bin" + ? this.getBinaryFileName() + : this.getFileName(); if ( - (!this.client.getSettings().isSyncEnabled && + (!this.lastSyncEnabledState && this.doNotTouchWhileOffline.includes(newName)) || (await this.exists(newName)) ) { @@ -320,16 +448,32 @@ export class MockAgent extends MockClient { this.client.logger.info(`Decided to rename file ${file} to ${newName}`); this.doNotTouchWhileOffline.push(file, newName); - return this.rename(file, newName); + this.client.logger.info(`Renamed file: ${file} -> ${newName}`); + await this.rename(file, newName); + this.executeFileOperation( + async () => + this.client.syncLocallyUpdatedFile({ + oldPath: file, + relativePath: newName + }), + true + ); } - private async updateFileAction(files: RelativePath[]): Promise { + private async updateFileAction(): Promise { + const files = (await this.listFilesRecursively()).filter((f) => + f.endsWith(".md") + ); + if (files.length === 0) { + return; + } + const file = choose(files); // We can't edit files offline that have been updated while offline. // Otherwise, the resolution logic couldn't handle it. if ( - !this.client.getSettings().isSyncEnabled && + !this.lastSyncEnabledState && this.doNotTouchWhileOffline.includes(file) ) { this.client.logger.info( @@ -343,16 +487,77 @@ export class MockAgent extends MockClient { `Decided to update file ${file} with ${content}` ); this.doNotTouchWhileOffline.push(file); - await this.atomicUpdateText(file, (old) => ({ - text: old.text + ` ${content} `, - cursors: [] - })); + await this.atomicUpdateText( + file, + (old) => ({ + text: old.text + ` ${content} `, + cursors: [] + }) + ); + + this.executeFileOperation( + async () => + this.client.syncLocallyUpdatedFile({ + relativePath: file + }), + true + ); } - private async deleteFileAction(files: RelativePath[]): Promise { + private async updateBinaryFileAction(): Promise { + const files = (await this.listFilesRecursively()).filter((f) => + f.endsWith(".bin") + ); + if (files.length === 0) { + return; + } + + const file = choose(files); + + if ( + !this.lastSyncEnabledState && + this.doNotTouchWhileOffline.includes(file) + ) { + return; + } + + const { uuid, bytes } = this.getBinaryContent(); + // Remove the old UUID since binary updates are last-write-wins + this.removeBinaryUuid(file); + this.client.logger.info( + `Decided to update binary file ${file}` + ); + this.doNotTouchWhileOffline.push(file); + this.files.set(file, bytes); + + this.executeFileOperation( + async () => + this.client.syncLocallyUpdatedFile({ + relativePath: file + }), + true + ); + } + + private async deleteFileAction(): Promise { + const files = await this.listFilesRecursively(); + if (files.length === 0) { + return; + } + const file = choose(files); this.client.logger.info(`Decided to delete file ${file}`); - return this.delete(file); + + this.removeBinaryUuid(file); + + this.client.logger.info( + `Deleting file: ${file} with:\n content '${new TextDecoder().decode(this.files.get(file))}'` + ); + await this.delete(file); + this.executeFileOperation( + async () => this.client.syncLocallyDeletedFile(file), + true + ); } private getContent(): string { @@ -361,8 +566,29 @@ export class MockAgent extends MockClient { return uuid; } + private removeBinaryUuid(file: string): void { + const existing = this.files.get(file); + if (existing === undefined) return; + const content = new TextDecoder().decode(existing); + if (!content.startsWith("BINARY:")) return; + const uuid = content.slice("BINARY:".length); + const idx = this.writtenBinaryContents.indexOf(uuid); + if (idx !== -1) this.writtenBinaryContents.splice(idx, 1); + } + + private getBinaryContent(): { uuid: string; bytes: Uint8Array } { + const uuid = uuidv4(); + this.writtenBinaryContents.push(uuid); + return { uuid, bytes: new TextEncoder().encode(`BINARY:${uuid}`) }; + } + private getFileName(): string { // Simulate name collisions between the clients return `file-${Math.floor(Math.random() * 64)}.md`; } + + private getBinaryFileName(): string { + // Smaller range to increase collision frequency for last-write-wins testing + return `binary-${Math.floor(Math.random() * 16)}.bin`; + } } diff --git a/frontend/test-client/src/agent/mock-client.ts b/frontend/test-client/src/agent/mock-client.ts index c814879a..3cdceb04 100644 --- a/frontend/test-client/src/agent/mock-client.ts +++ b/frontend/test-client/src/agent/mock-client.ts @@ -2,30 +2,24 @@ import type { StoredDatabase, TextWithCursors } from "sync-client"; import { assert } from "../utils/assert"; import { type RelativePath, - type FileSystemOperations, type SyncSettings, - SyncClient + SyncClient, + debugging } from "sync-client"; -export class MockClient implements FileSystemOperations { - protected readonly localFiles = new Map(); +export class MockClient extends debugging.InMemoryFileSystem { protected client!: SyncClient; protected data: Partial<{ settings: Partial; database: Partial; - }> = { - database: { - // Assume all clients start at the same time so there's no need to fetch - // any shared state. - hasInitialSyncCompleted: true - } - }; + }> = {}; public constructor( initialSettings: Partial, protected readonly useSlowFileEvents: boolean ) { + super(); this.data.settings = initialSettings; } @@ -46,148 +40,93 @@ export class MockClient implements FileSystemOperations { await this.client.start(); } - public async listFilesRecursively( - _root: RelativePath | undefined = undefined // we don't use multi-level paths during tests - ): Promise { - return Array.from(this.localFiles.keys()); - } - - public async read(path: RelativePath): Promise { - const file = this.localFiles.get(path); - if (!file) { - throw new Error(`File ${path} does not exist`); - } - return file; - } - - public async getFileSize(path: RelativePath): Promise { - return (await this.read(path)).length; - } - - public async exists(path: RelativePath): Promise { - return this.localFiles.has(path); - } - public async create( path: RelativePath, - newContent: Uint8Array + newContent: Uint8Array, + { ignoreSlowFileEvents }: { ignoreSlowFileEvents: boolean } = { + ignoreSlowFileEvents: false + } ): Promise { - if (this.localFiles.has(path)) { + if (this.files.has(path)) { throw new Error(`File ${path} already exists`); } this.client.logger.info( `Creating file ${path} with content ${new TextDecoder().decode(newContent)}` ); - this.localFiles.set(path, newContent); + this.files.set(path, newContent); - this.executeFileOperation(async () => - this.client.syncLocallyCreatedFile(path) + this.executeFileOperation( + async () => this.client.syncLocallyCreatedFile(path), + ignoreSlowFileEvents ); } - public async createDirectory(_path: RelativePath): Promise { - // This doesn't mean anything in our virtual FS representation - } - - public async atomicUpdateText( + public override async atomicUpdateText( path: RelativePath, updater: (currentContent: TextWithCursors) => TextWithCursors ): Promise { - const file = this.localFiles.get(path); + // This method is called by BOTH the sync client (for remote text + // merges) and the test agent (for user updates). We must NOT call + // executeFileOperation here because the sync-client path would + // echo remote writes back as local modifications, creating an + // infinite sync loop. The test agent calls executeFileOperation + // separately after this method returns. + const file = this.files.get(path); if (!file) { throw new Error(`File ${path} does not exist`); } const currentContent = new TextDecoder().decode(file); const newContent = updater({ text: currentContent, cursors: [] }).text; const newContentUint8Array = new TextEncoder().encode(newContent); - this.localFiles.set(path, newContentUint8Array); - - if (!this.useSlowFileEvents) { - const existingParts = currentContent - .split(" ") - .map((part) => part.trim()); - const newParts = newContent.split(" ").map((part) => part.trim()); - existingParts.forEach((part) => - // all changes should be additive - { - assert( - newParts.includes(part), - `Part ${part} not found in new content: ${newContent}` - ); - } - ); - } - - this.client.logger.info( - `Updated file ${path} with:\n current content: ${currentContent}\n new content: ${newContent}` - ); - - this.executeFileOperation(async () => - this.client.syncLocallyUpdatedFile({ - relativePath: path - }) - ); + this.files.set(path, newContentUint8Array); return newContent; } - public async write(path: RelativePath, content: Uint8Array): Promise { - const hasExisted = this.localFiles.has(path); - this.localFiles.set(path, content); - - this.client.logger.info( - `Updated file ${path} with:\n new content: ${new TextDecoder().decode(content)}` - ); - - this.executeFileOperation(async () => { - if (hasExisted) { - return this.client.syncLocallyUpdatedFile({ - relativePath: path - }); - } else { - return this.client.syncLocallyCreatedFile(path); - } - }); + public override async write( + path: RelativePath, + content: Uint8Array + ): Promise { + // This method is called by the sync client when writing files + // received from the server (remote updates). Do NOT call + // executeFileOperation here — that would echo the remote write + // back as a local modification, creating an infinite sync loop. + // User-initiated writes go through create(), atomicUpdateText(), + // or direct files.set() + executeFileOperation() in mock-agent. + this.files.set(path, content); } - public async delete(path: RelativePath): Promise { - this.client.logger.info( - `Deleting file: ${path} with:\n content ${new TextDecoder().decode(this.localFiles.get(path))}` - ); - this.localFiles.delete(path); - - this.executeFileOperation(async () => - this.client.syncLocallyDeletedFile(path) - ); + public override async delete(path: RelativePath): Promise { + // Just perform the filesystem operation. The test agent calls + // executeFileOperation separately in mock-agent.ts. Not echoing + // here prevents the sync client's remote-delete writes from + // triggering spurious local-delete sync operations. + this.files.delete(path); } - public async rename( + public override async rename( oldPath: RelativePath, newPath: RelativePath ): Promise { - const file = this.localFiles.get(oldPath); + // Just perform the filesystem operation. The test agent calls + // executeFileOperation separately in mock-agent.ts. Not echoing + // here prevents the sync client's ensureClearPath / remote-rename + // writes from triggering spurious local-update sync operations. + const file = this.files.get(oldPath); if (!file) { throw new Error(`File ${oldPath} does not exist`); } - this.localFiles.set(newPath, file); + this.files.set(newPath, file); if (oldPath !== newPath) { - this.localFiles.delete(oldPath); + this.files.delete(oldPath); } - - this.client.logger.info( - `Renamed file: ${oldPath} -> ${newPath} with:\n content ${new TextDecoder().decode(file)}` - ); - - this.executeFileOperation(async () => - this.client.syncLocallyUpdatedFile({ - oldPath, - relativePath: newPath - }) - ); } - private executeFileOperation(callback: () => unknown): void { - if (this.useSlowFileEvents) { + protected executeFileOperation( + callback: () => unknown, + ignoreSlowFileEvents = false + ): void { + if (this.useSlowFileEvents && !ignoreSlowFileEvents) { // we aren't the best client and it takes some time to notice changes setTimeout(callback, Math.random() * 100); } else { diff --git a/frontend/test-client/src/cli.ts b/frontend/test-client/src/cli.ts index 3af547e7..28684dc2 100644 --- a/frontend/test-client/src/cli.ts +++ b/frontend/test-client/src/cli.ts @@ -1,11 +1,14 @@ import type { SyncSettings } from "sync-client"; -import { utils } from "sync-client"; +import { utils, debugging, Logger } from "sync-client"; import { MockAgent } from "./agent/mock-agent"; import { sleep } from "./utils/sleep"; import { v4 as uuidv4 } from "uuid"; import { randomCasing } from "./utils/random-casing"; +import { TimeoutError } from "./utils/with-timeout"; +import { TestErrorTracker } from "./utils/test-error-tracker"; const TEST_ITERATIONS = 5; +const MAX_INITIAL_DOCS = 10; // Simulate async file access by injecting waiting time before returning from file operations. let slowFileEvents = false; @@ -13,9 +16,13 @@ let slowFileEvents = false; // Whether to do resets in the test runs let doResets = false; +const logger = new Logger(); +debugging.logToConsole(logger); + +const errorTracker = new TestErrorTracker(); + async function runTest({ agentCount, - concurrency, iterations, doDeletes, useResets, @@ -23,7 +30,6 @@ async function runTest({ jitterScaleInSeconds }: { agentCount: number; - concurrency: number; iterations: number; doDeletes: boolean; useResets: boolean; @@ -32,18 +38,18 @@ async function runTest({ }): Promise { slowFileEvents = useSlowFileEvents; doResets = useResets; + errorTracker.reset(); - const settings = `with ${agentCount} agents, concurrency ${concurrency}, iterations ${iterations}, doDeletes ${doDeletes}, doResets ${useResets}, jitterScaleInSeconds ${jitterScaleInSeconds}, useSlowFileEvents ${useSlowFileEvents}`; - console.info(`Running test ${settings}`); + const settings = `with ${agentCount} agents, iterations ${iterations}, doDeletes ${doDeletes}, doResets ${useResets}, jitterScaleInSeconds ${jitterScaleInSeconds}, useSlowFileEvents ${useSlowFileEvents}`; + logger.info(`Running test ${settings}`); const vaultName = uuidv4(); - console.info(`Using vault name: ${vaultName}`); + logger.info(`Using vault name: ${vaultName}`); const initialSettings: Partial = { isSyncEnabled: true, token: " test-token-change-me ", // same as in sync-server/config-e2e.yml with spaces vaultName: randomCasing(vaultName) + (Math.random() > 0.5 ? " " : ""), // extra spaces shouldn't matter - syncConcurrency: concurrency, - remoteUri: "http://localhost:3000" + remoteUri: "http://localhost:3010" }; const clients: MockAgent[] = []; @@ -55,67 +61,108 @@ async function runTest({ doDeletes, useResets, useSlowFileEvents, - jitterScaleInSeconds + jitterScaleInSeconds, + errorTracker ) ); } try { + for (const client of clients) { + const initialDocCount = Math.floor( + Math.random() * MAX_INITIAL_DOCS + ); + if (initialDocCount > 0) { + logger.info( + `Creating ${initialDocCount} initial documents for ${client.name}` + ); + await client.createInitialDocuments(initialDocCount); + } + } + await utils.awaitAll(clients.map(async (client) => client.init())); for (let i = 0; i < iterations; i++) { - console.info(`Iteration ${i + 1}/${iterations}`); + logger.info(`Iteration ${i + 1}/${iterations}`); await utils.awaitAll(clients.map(async (client) => client.act())); await sleep(Math.random() * 200); } - console.info("Stopping agents"); + errorTracker.checkAndThrow(); - // Each agent can have unpushed changes which might conflict with eachother so each has to resolve the conflicts & push, and + logger.info("Stopping agents"); + + // Drain pending actions and enable sync for each client for (const client of clients) { try { - console.info(`Finishing up ${client.name}`); + logger.info(`Finishing up ${client.name}`); await client.finish(); } catch (err) { - if (!slowFileEvents) { + if (err instanceof TimeoutError || !slowFileEvents) { throw err; } } } - // then we need a second pass to ensure that all agents pull the same state. + // Settling rounds to drain cascading broadcasts between agents. + // Completing work on agent A can trigger broadcasts to agent B, + // which can cascade further. With N agents the worst case is N + // hops, so N+1 passes guarantees all cascades are drained. + for (let round = 0; round <= clients.length; round++) { + for (const client of clients) { + try { + await client.waitUntilSynced(); + } catch (err) { + if (err instanceof TimeoutError || !slowFileEvents) { + throw err; + } + } + } + } + for (const client of clients) { try { - console.info(`Destroying ${client.name}`); + logger.info(`Destroying ${client.name}`); await client.destroy(); } catch (err) { - if (!slowFileEvents) { + if (err instanceof TimeoutError || !slowFileEvents) { throw err; } } } - console.info("Agents finished successfully"); + logger.info("Agents finished successfully"); + errorTracker.checkAndThrow(); clients.slice(0, -1).forEach((client, i) => { - console.info( + logger.info( `Checking consistency between ${client.name} and ${clients[i + 1].name}` ); - client.assertFileSystemsAreConsistent(clients[i]); - console.info(`Consistency check for ${client.name} passed`); + client.assertFileSystemsAreConsistent(clients[i + 1]); + logger.info(`Consistency check for ${client.name} passed`); }); - console.info("File systems found to be consistent"); + logger.info("File systems found to be consistent"); clients.forEach((client) => { - console.info(`Checking content for ${client.name}`); + logger.info(`Checking content for ${client.name}`); client.assertAllContentIsPresentOnce(); - console.info(`Content check for ${client.name} passed`); + logger.info(`Content check for ${client.name} passed`); }); - console.info(`Test passed ${settings}`); + clients.forEach((client) => { + logger.info( + `Checking binary content duplication for ${client.name}` + ); + client.assertBinaryContentNotDuplicated(); + logger.info( + `Binary content duplication check for ${client.name} passed` + ); + }); + + logger.info(`Test passed ${settings}`); } catch (err) { - console.error(`Test failed ${settings}`); + logger.error(`Test failed ${settings}`); throw err; } } @@ -124,7 +171,6 @@ async function runTests(): Promise { for (let i = 0; i < TEST_ITERATIONS; i++) { await runTest({ agentCount: 2, - concurrency: 16, iterations: 100, doDeletes: true, useResets: true, @@ -133,24 +179,59 @@ async function runTests(): Promise { }); for (const useSlowFileEvents of [true, false]) { - for (const concurrency of [ - 16, - 1 // test with concurrency 1 to check for deadlocks - ]) { - for (const doDeletes of [false, true]) { - await runTest({ - agentCount: 2, - concurrency, - iterations: 100, - doDeletes, - useResets: false, - useSlowFileEvents, - jitterScaleInSeconds: 0.75 - }); - } + for (const doDeletes of [false, true]) { + await runTest({ + agentCount: 2, + iterations: 100, + doDeletes, + useResets: false, + useSlowFileEvents, + jitterScaleInSeconds: 0.75 + }); } } } + + await runTest({ + agentCount: 3, + iterations: 75, + doDeletes: true, + useResets: false, + useSlowFileEvents: false, + jitterScaleInSeconds: 0.75 + }); + await runTest({ + agentCount: 3, + iterations: 75, + doDeletes: false, + useResets: true, + useSlowFileEvents: false, + jitterScaleInSeconds: 0.75 + }); + await runTest({ + agentCount: 4, + iterations: 50, + doDeletes: true, + useResets: false, + useSlowFileEvents: false, + jitterScaleInSeconds: 0.75 + }); + await runTest({ + agentCount: 2, + iterations: 100, + doDeletes: true, + useResets: false, + useSlowFileEvents: false, + jitterScaleInSeconds: 0.1 + }); + await runTest({ + agentCount: 2, + iterations: 100, + doDeletes: true, + useResets: true, + useSlowFileEvents: false, + jitterScaleInSeconds: 1.5 + }); } process.on("uncaughtException", (error) => { @@ -163,12 +244,19 @@ process.on("uncaughtException", (error) => { return; } - console.error("Uncaught exception:", error); + logger.error(`Error: uncaught exception: ${error}`); + if (error instanceof Error && error.stack != null) { + logger.error(error.stack); + } process.exit(1); }); process.on("unhandledRejection", (error, _promise) => { - if (error instanceof Error && error.message === "Sync was reset") { + if ( + error instanceof Error && + ( + error.name === "SyncResetError") + ) { return; } @@ -191,7 +279,10 @@ process.on("unhandledRejection", (error, _promise) => { return; } - console.error("Unhandled rejection:", error); + logger.error(`Error - unhandled rejection: ${error}`); + if (error instanceof Error && error.stack != null) { + logger.error(error.stack); + } process.exit(1); }); @@ -199,7 +290,10 @@ runTests() .then(() => { process.exit(0); }) - .catch((err: unknown) => { - console.error(err); + .catch((error: unknown) => { + logger.error(`Error - tests failed with ${error}`); + if (error instanceof Error && error.stack != null) { + logger.error(error.stack); + } process.exit(1); }); diff --git a/frontend/test-client/src/utils/test-error-tracker.ts b/frontend/test-client/src/utils/test-error-tracker.ts new file mode 100644 index 00000000..cf40a76c --- /dev/null +++ b/frontend/test-client/src/utils/test-error-tracker.ts @@ -0,0 +1,25 @@ +export class TestErrorTracker { + private firstError: { agentName: string; message: string } | null = null; + + public recordError(agentName: string, message: string): void { + this.firstError ??= { agentName, message }; + } + + /** + * If an error was recorded, throw it. Call this at natural checkpoints: + * after each iteration, before assertions, etc. + */ + public checkAndThrow(): void { + if (this.firstError !== null) { + const { agentName, message } = this.firstError; + throw new Error( + `ERROR-level log from ${agentName}: ${message}` + ); + } + } + + /** Clear recorded errors. Call at the start of each test. */ + public reset(): void { + this.firstError = null; + } +} diff --git a/frontend/test-client/src/utils/with-timeout.ts b/frontend/test-client/src/utils/with-timeout.ts index 71c9568b..6de73531 100644 --- a/frontend/test-client/src/utils/with-timeout.ts +++ b/frontend/test-client/src/utils/with-timeout.ts @@ -1,3 +1,10 @@ +export class TimeoutError extends Error { + public constructor(message: string) { + super(message); + this.name = "TimeoutError"; + } +} + export async function withTimeout( promise: Promise, timeoutMs: number, @@ -8,7 +15,9 @@ export async function withTimeout( new Promise((_, reject) => setTimeout(() => { reject( - new Error(`${operationName} timed out after ${timeoutMs}ms`) + new TimeoutError( + `${operationName} timed out after ${timeoutMs}ms` + ) ); }, timeoutMs) )