stop basing the ignore mechanism on a fixed time frame

Author: s-h-a-d-o-w

README.md

@@ -42,8 +42,8 @@ Logs to console instead of files.
 - Tray icon DPI nonsense: I tried to attach a [manifest](https://learn.microsoft.com/en-us/windows/win32/hidpi/setting-the-default-dpi-awareness-for-a-process) to both `pkg` and `node:sea` .exes using both `mt` and `rcedit`. The `pkg` exe shrinks by 4 MB and doesn't work any more. With the `node:sea` exe, `rcedit` freezes. `mt` works but would require a environment variable override: "Node.js is only supported on Windows 8.1, Windows Server 2012 R2, or higher. Setting the NODE_SKIP_PLATFORM_CHECK environment variable to 1 skips this check, ...". Since it's not possible to bake environment variables into the .exe with `node:sea`, this is obviously not acceptable either. The only thing I can think of to resolve this would be to create a non-node wrapper that runs the .exe. Or maybe `bun` or `deno` become a viable alternative at some point (As of October 2024, I don't consider either of them anywhere near production ready. `bun` can't handle windows paths, at least in with projects like this one. `deno` still [doesn't clean up unneeded npm packages](https://github.com/denoland/deno/issues/21261).)
 - Multiple strategies are needed to prevent infinite loops:
 1. Whenever we do something on S3, it triggers SNS and we would repeat the same thing locally that we just did on S3, which would result in: Syncing to S3 => getting SNS => Syncing to S3 => infinite loop. To avoid this, the last modified date is synced after uploading/downloading and checked before uploading/downloading.
-2. Syncing timestamps triggers chokidar. For that, there is `ignoreFiles` in global state.
-3. Allowing frequent operations on the same file (which Cryptomator does), is done using the following: All local operations are debounced. If even with debouncing, the same file keeps changing without regularly changing in size, the client exits at some point because then it's probably a bug.
+2. Whenever a file is manipulated locally, it is added to `ignoreMaps`. Which makes it so that when the file watcher triggers because of what the client does rather than what the user does, that trigger is ignored.
+3. Allowing frequent operations on the same file (which Cryptomator does), is achieved using the following: All local operations are debounced. If even with debouncing, the same file keeps changing without regularly changing in size, the client exits at some point because then it's probably a bug.
 
 - `tsimp` fails without providing an error message, `tsx` works. 🤷‍♀️
 

client/package.json

@@ -14,10 +14,10 @@
     "dev": "tsx . debug",
     "dev:cli": "tsx . cli",
     "silenceexe": "create-nodew-exe s3-smart-sync.exe s3-smart-sync.exe",
-    "playground": "tsx ./playground.ts"
+    "playground": "tsx ./playground.cts"
   },
   "dependencies": {
-    "@aws-sdk/client-s3": "^3.701.0",
+    "@aws-sdk/client-s3": "^3.758.0",
     "@aws-sdk/lib-storage": "^3.758.0",
     "@s3-smart-sync/shared": "workspace:*",
     "auto-launch": "^5.0.6",

client/playground.ts client/playground.cts

@@ -12,7 +12,7 @@ export enum FileOperationType {
 
 export const UNIGNORE_DURATION = 200; // short because it only has to cover: end of operation -> file watcher trigger -> ignore that call
 export const WATCHER_DEBOUNCE_DURATION = 500;
-export const IGNORE_CLEANUP_DURATION = WATCHER_DEBOUNCE_DURATION * 2;
+export const IGNORE_CLEANUP_DURATION = 12 * 60 * 60 * 1000; // presumably, not even a large file transfer lasts longer than this. And this is only an emergency measure anyway.
 
 let watcher: FSWatcher | undefined;
 const ignoreMaps = {
@@ -26,25 +26,46 @@ export function ignore(fileOperationType: FileOperationType, filePath: string) {
     filePath.endsWith(path.sep)
       ? filePath.slice(0, -path.sep.length)
       : filePath,
-    Date.now(),
+    Date.now() + 1000000,
   );
 }
 
+export function resetIgnoreMaps() {
+  logger.debug("Resetting ignore maps due to connection loss");
+  ignoreMaps[FileOperationType.Remove].clear();
+  ignoreMaps[FileOperationType.Sync].clear();
+}
+
 export function unignore(
   fileOperationType: FileOperationType,
   filePath: string,
 ) {
+  // logger.debug(
+  //   `unignore: ${fileOperationType} ${filePath} ${JSON.stringify(
+  //     Array.from(ignoreMaps[fileOperationType].entries()),
+  //   )}`,
+  // );
   setTimeout(() => {
     ignoreMaps[fileOperationType].delete(filePath);
   }, UNIGNORE_DURATION);
 }
 
 function shouldIgnore(fileOperationType: FileOperationType, filePath: string) {
+  // logger.debug(
+  //   `shouldIgnore: ${fileOperationType} ${filePath} ${JSON.stringify(
+  //     Array.from(ignoreMaps[fileOperationType].entries()),
+  //   )}`,
+  // );
   const timestamp = ignoreMaps[fileOperationType].get(filePath);
   if (!timestamp) return false;
 
   // If the ignore entry is older than IGNORE_CLEANUP_DURATION, it is probably fair to assume that although we handle errors and call unignore(), something unexpected must have happened and this is a stale entry.
   if (Date.now() - timestamp > IGNORE_CLEANUP_DURATION) {
+    logger.error(
+      `Had to clean up ignore for a ${
+        fileOperationType === FileOperationType.Sync ? "sync" : "remove"
+      } operation for ${filePath}.`,
+    );
     ignoreMaps[fileOperationType].delete(filePath);
     return false;
   }

client/src/fileWatcher.ts

@@ -104,7 +104,8 @@ async function main() {
   async function removeFile(localPath: string) {
     const preliminaryKey = await convertAbsolutePathToKey(localPath);
 
-    // because the file was already deleted locally, we don't know whether it was a directory
+    // Because the file was already deleted locally, we don't know whether it was a directory
+    // (We could pass through the info from chokidar but that would be messy architecturally)
     let isDirectory: boolean | undefined;
     try {
       await getLastModified(preliminaryKey + "/");

client/src/index.ts

@@ -176,14 +176,12 @@ export async function upload(localPath: string, key: string) {
       Bucket: S3_BUCKET,
       Key: key,
       Body: key.endsWith("/") ? "" : createReadStream(localPath),
-      // Hopefully will be optional in the future: https://github.com/aws/aws-sdk-js-v3/issues/6922
-      ChecksumAlgorithm: "CRC32",
     },
   }).done();
+  logger.info(`Uploaded: ${key}`);
 
   // We have to sync timestamps to avoid redundant, potentially infinite, operations.
   await syncLastModified(localPath, await getLastModified(key));
-  logger.info(`Uploaded: ${key}`);
 }
 
 export async function upToDate(key: string) {

client/src/s3Operations.ts

@@ -4,7 +4,11 @@ import { getErrorMessage } from "@s3-smart-sync/shared/getErrorMessage.js";
 import { logger } from "@s3-smart-sync/shared/logger.js";
 import { biDirectionalSync } from "./biDirectionalSync.js";
 import { RECONNECT_DELAY, WEBSOCKET_URL } from "./consts.js";
-import { resumeFileWatcher, suspendFileWatcher } from "./fileWatcher.js";
+import {
+  resetIgnoreMaps,
+  resumeFileWatcher,
+  suspendFileWatcher,
+} from "./fileWatcher.js";
 import { changeTrayIconState, TrayIconState } from "./trayIcon.js";
 import { updateTrayTooltip } from "./trayWrapper.js";
 import { getHeartbeatInterval } from "@s3-smart-sync/shared/getHeartbeatInterval.js";
@@ -137,6 +141,7 @@ export function setUpWebsocket(
       logger.error("Disconnected from WebSocket server");
       changeTrayIconState(TrayIconState.Disconnected);
       updateTrayTooltip("S3 Smart Sync (Disconnected)");
+      resetIgnoreMaps();
       setTimeout(
         setUpWebsocket,
         RECONNECT_DELAY,

client/src/setUpWebsocket.ts

@@ -2,12 +2,13 @@ import { fileExists } from "@s3-smart-sync/shared/fileExists.js";
 import { mkdir, readFile, rm, stat } from "node:fs/promises";
 import { join } from "node:path";
 import {
-  IGNORE_CLEANUP_DURATION,
+  UNIGNORE_DURATION,
   WATCHER_DEBOUNCE_DURATION,
 } from "../src/fileWatcher.js";
 import {
   cleanupLocalDirectories,
   cleanupS3,
+  clientLogs,
   createClientDirectories,
   createFile,
   list,
@@ -28,21 +29,20 @@ let clientDirectories: Record<number, string>;
 describe("E2E Tests", () => {
   beforeAll(async () => {
     await startServer();
-    startClients(clientIds);
-    await pause(500);
   });
 
   afterAll(async () => {
-    const results = [
-      ...(await Promise.allSettled([
-        withTimeout(stopClients()),
-        withTimeout(stopServer()),
-      ])),
+    const results = await Promise.allSettled([
+      withTimeout(stopClients()),
+      withTimeout(stopServer()),
+    ]);
+
+    results.push(
       ...(await Promise.allSettled([
         withTimeout(cleanupS3()),
-        withTimeout(cleanupLocalDirectories()),
+        waitUntil(() => cleanupLocalDirectories()),
       ])),
-    ];
+    );
 
     const errors = results.filter((result) => result.status === "rejected");
     if (errors.length > 0) {
@@ -53,9 +53,17 @@ describe("E2E Tests", () => {
   });
 
   beforeEach(async () => {
-    await cleanupS3();
-    await cleanupLocalDirectories();
     clientDirectories = await createClientDirectories(clientIds);
+    await startClients(clientIds);
+  });
+
+  afterEach(async () => {
+    await stopClients();
+    await Promise.all([
+      cleanupS3(),
+      // Due to windows potentially aggressively locking down the directories, we retry until it works
+      waitUntil(() => cleanupLocalDirectories()),
+    ]);
   });
 
   it("should sync correctly on startup", async () => {
@@ -92,13 +100,13 @@ describe("E2E Tests", () => {
       }
     }
 
-    await stopClients([0]);
+    await stopClients([1]);
     await Promise.all(
       Object.entries(TEST_FILES).map(([key, content]) =>
-        createFile(1, key, content),
+        createFile(0, key, content),
       ),
     );
-    startClients([0]);
+    await startClients([1]);
 
     await waitUntil(async () => {
       await verifyFiles(clientDirectories[0]!);
@@ -119,6 +127,12 @@ describe("E2E Tests", () => {
         ).toBe(largeContent),
       { timeout: 10000 },
     );
+
+    // Client 1 shouldn't do anything after the download has finished. (Which means that the ignore mechanism works with large files.)
+    await pause(WATCHER_DEBOUNCE_DURATION * 2);
+    expect(clientLogs[1]!.trim().split("\n").at(-1)?.trim()).toMatch(
+      /Downloaded: large-file\.txt$/,
+    );
   }, 20000);
 
   it("should sync file changes between clients", async () => {
@@ -128,8 +142,7 @@ describe("E2E Tests", () => {
         await readFile(join(clientDirectories[1]!, "new-file.txt"), "utf-8"),
       ).toBe("New content"),
     );
-
-    await pause(IGNORE_CLEANUP_DURATION + 10);
+    await pause(UNIGNORE_DURATION + 10);
 
     await createFile(1, "new-file.txt", "Changed content");
     await waitUntil(async () =>
@@ -146,9 +159,8 @@ describe("E2E Tests", () => {
     );
 
     await rm(join(clientDirectories[0]!, "file-then-directory"));
-    await pause(WATCHER_DEBOUNCE_DURATION + 10);
+    await pause(WATCHER_DEBOUNCE_DURATION + 300);
     await sendSnsMessage("file-then-directory", "delete");
-    await pause(IGNORE_CLEANUP_DURATION + 10);
 
     await mkdir(join(clientDirectories[0]!, "file-then-directory"));
     // First, the debounced upload. Then we have to wait for the upload to actually have finished
@@ -182,7 +194,6 @@ describe("E2E Tests", () => {
       return Contents === undefined;
     });
     await sendSnsMessage("directory-then-file/", "delete");
-    await pause(IGNORE_CLEANUP_DURATION + 10);
 
     await createFile(0, "directory-then-file", "now it's a file");
     await waitUntil(async () => {
@@ -195,14 +206,14 @@ describe("E2E Tests", () => {
     });
   });
 
-  it("handles duplicate file/directory on S3", async () => {
+  it("handles duplicate file/directory on S3 by deleting the older", async () => {
     await stopClients();
     await upload("duplicate-file/", "");
     await upload("duplicate-file/nested/", "");
     await upload("duplicate-file/nested/file.txt", "...");
     await upload("duplicate-file", "");
 
-    startClients(clientIds);
+    await startClients(clientIds);
     await waitUntil(() =>
       readFile(join(clientDirectories[0]!, "duplicate-file"), "utf-8"),
     );