fix(dictionary): stop large character dictionaries from timing out (#189)

src/main/runtime/character-dictionary-auto-sync.ts

@@ -1,13 +1,29 @@
 import * as fs from 'fs';
 import * as path from 'path';
 import { ensureDir } from '../../shared/fs-utils';
+import {
+  buildBuildingMessage,
+  buildCheckingMessage,
+  buildFailedMessage,
+  buildGeneratingMessage,
+  buildImportingMessage,
+  buildReadyMessage,
+  formatCharacterDictionaryProgressDetail,
+  joinGeneratingDetail,
+} from './character-dictionary-auto-sync-messages';
+import { readDictionaryZipRevision } from '../character-dictionary-runtime/zip';
 import type { AnilistCharacterDictionaryProfileScope } from '../../types';
 import type {
   CharacterDictionarySnapshotProgressCallbacks,
   CharacterDictionarySnapshotResult,
+  CharacterDictionarySnapshotStageProgress,
   MergedCharacterDictionaryBuildResult,
 } from '../character-dictionary-runtime';
 
+const DEFAULT_IMPORT_TIMEOUT_BASE_MS = 120_000;
+const IMPORT_TIMEOUT_MS_PER_MB = 6_000;
+const IMPORT_TIMEOUT_MAX_MS = 1_800_000;
+
 type AutoSyncMediaEntry = {
   mediaId: number;
   label: string;
@@ -72,7 +88,15 @@ export interface CharacterDictionaryAutoSyncRuntimeDeps {
   now: () => number;
   schedule?: (fn: () => void, delayMs: number) => ReturnType<typeof setTimeout>;
   clearSchedule?: (timer: ReturnType<typeof setTimeout>) => void;
+  /** Budget for the quick Yomitan queries (dictionary info, settings upsert). */
   operationTimeoutMs?: number;
+  /**
+   * Base budget for the slow Yomitan mutations (delete + import). The effective budget grows with
+   * the merged ZIP size, because importing a large dictionary can take several minutes.
+   */
+  dictionaryImportTimeoutBaseMs?: number;
+  heartbeatMs?: number;
+  progressThrottleMs?: number;
   logInfo?: (message: string) => void;
   logWarn?: (message: string) => void;
   onSyncStatus?: (event: CharacterDictionaryAutoSyncStatusEvent) => void;
@@ -345,37 +369,6 @@ function sameMembership(left: number[], right: number[]): boolean {
   return arraysEqual(leftSorted, rightSorted);
 }
 
-function buildSyncingMessage(mediaTitle: string): string {
-  return `Updating character dictionary for ${mediaTitle}...`;
-}
-
-function buildCheckingMessage(mediaTitle: string): string {
-  return `Checking character dictionary for ${mediaTitle}...`;
-}
-
-function buildGeneratingMessage(mediaTitle: string): string {
-  return `Generating character dictionary for ${mediaTitle}...`;
-}
-
-function buildImportingMessage(mediaTitle: string): string {
-  return `Importing character dictionary for ${mediaTitle}...`;
-}
-
-function buildBuildingMessage(mediaTitle: string): string {
-  return `Building character dictionary for ${mediaTitle}...`;
-}
-
-function buildReadyMessage(mediaTitle: string): string {
-  return `Character dictionary ready for ${mediaTitle}`;
-}
-
-function buildFailedMessage(mediaTitle: string | null, errorMessage: string): string {
-  if (mediaTitle) {
-    return `Character dictionary sync failed for ${mediaTitle}: ${errorMessage}`;
-  }
-  return `Character dictionary sync failed: ${errorMessage}`;
-}
-
 export function createCharacterDictionaryAutoSyncRuntimeService(
   deps: CharacterDictionaryAutoSyncRuntimeDeps,
 ): {
@@ -389,21 +382,31 @@ export function createCharacterDictionaryAutoSyncRuntimeService(
   const clearSchedule = deps.clearSchedule ?? ((timer) => clearTimeout(timer));
   const debounceMs = 800;
   const operationTimeoutMs = Math.max(1, Math.floor(deps.operationTimeoutMs ?? 7_000));
+  const dictionaryImportTimeoutBaseMs = Math.max(
+    1,
+    Math.floor(deps.dictionaryImportTimeoutBaseMs ?? DEFAULT_IMPORT_TIMEOUT_BASE_MS),
+  );
+  const heartbeatMs = Math.max(1, Math.floor(deps.heartbeatMs ?? 5_000));
+  const progressThrottleMs = Math.max(0, Math.floor(deps.progressThrottleMs ?? 1_000));
 
   let debounceTimer: ReturnType<typeof setTimeout> | null = null;
   let syncInFlight = false;
   let runQueued = false;
   let activeCurrentMediaId: number | null = null;
 
-  const withOperationTimeout = async <T>(label: string, promise: Promise<T>): Promise<T> => {
+  const withTimeout = async <T>(
+    label: string,
+    promise: Promise<T>,
+    timeoutMs: number,
+  ): Promise<T> => {
     let timer: ReturnType<typeof setTimeout> | null = null;
     try {
       return await Promise.race([
         promise,
         new Promise<never>((_resolve, reject) => {
           timer = setTimeout(() => {
-            reject(new Error(`${label} timed out after ${operationTimeoutMs}ms`));
-          }, operationTimeoutMs);
+            reject(new Error(`${label} timed out after ${timeoutMs}ms`));
+          }, timeoutMs);
         }),
       ]);
     } finally {
@@ -413,6 +416,57 @@ export function createCharacterDictionaryAutoSyncRuntimeService(
     }
   };
 
+  const withOperationTimeout = <T>(label: string, promise: Promise<T>): Promise<T> =>
+    withTimeout(label, promise, operationTimeoutMs);
+
+  /**
+   * Importing a merged dictionary means Yomitan writing every term and image into IndexedDB, which
+   * scales with the ZIP: a single-season dictionary lands in seconds, One Piece takes minutes. Size
+   * the budget off the archive instead of failing a healthy import on a flat deadline.
+   */
+  const resolveImportTimeoutMs = (zipPath: string | null): number => {
+    let bytes = 0;
+    if (zipPath) {
+      try {
+        bytes = fs.statSync(zipPath).size;
+      } catch {
+        bytes = 0;
+      }
+    }
+    const sizeAllowanceMs = (bytes / (1024 * 1024)) * IMPORT_TIMEOUT_MS_PER_MB;
+    return Math.min(
+      IMPORT_TIMEOUT_MAX_MS,
+      Math.max(
+        dictionaryImportTimeoutBaseMs,
+        Math.round(dictionaryImportTimeoutBaseMs + sizeAllowanceMs),
+      ),
+    );
+  };
+
+  /** Keeps the persistent notification ticking so a multi-minute import never looks hung. */
+  const withHeartbeat = async <T>(
+    run: () => Promise<T>,
+    onTick: (elapsedMs: number) => void,
+  ): Promise<T> => {
+    const startedAt = deps.now();
+    let stopped = false;
+    let timer: ReturnType<typeof setTimeout> | null = null;
+    const tick = (): void => {
+      if (stopped) return;
+      onTick(deps.now() - startedAt);
+      timer = schedule(tick, heartbeatMs);
+    };
+    timer = schedule(tick, heartbeatMs);
+    try {
+      return await run();
+    } finally {
+      stopped = true;
+      if (timer !== null) {
+        clearSchedule(timer);
+      }
+    }
+  };
+
   const runSyncOnce = async (): Promise<void> => {
     const config = deps.getConfig();
     if (!config.enabled) {
@@ -422,33 +476,112 @@ export function createCharacterDictionaryAutoSyncRuntimeService(
 
     let currentMediaId: number | undefined;
     let currentMediaTitle: string | null = null;
+    let lastProgressAt = Number.NEGATIVE_INFINITY;
+    let lastProgressStage: CharacterDictionarySnapshotStageProgress['stage'] | null = null;
+    let generating: {
+      mediaId: number;
+      mediaTitle: string;
+      startedAt: number;
+      detail: string | null;
+    } | null = null;
+    let imageRate: { startedAt: number; startCompleted: number } | null = null;
+
+    const emitGeneratingStatus = (): void => {
+      if (!generating) {
+        return;
+      }
+      deps.onSyncStatus?.({
+        phase: 'generating',
+        mediaId: generating.mediaId,
+        mediaTitle: generating.mediaTitle,
+        message: buildGeneratingMessage(
+          generating.mediaTitle,
+          joinGeneratingDetail(generating.detail, deps.now() - generating.startedAt),
+        ),
+      });
+    };
+
+    // Image downloads are serial and evenly paced, so the observed rate predicts the tail well.
+    const estimateRemainingImageMs = (
+      progress: CharacterDictionarySnapshotStageProgress,
+      nowMs: number,
+    ): number | null => {
+      if (progress.stage !== 'images' || progress.total === null || imageRate === null) {
+        return null;
+      }
+      const done = progress.completed - imageRate.startCompleted;
+      const elapsedMs = nowMs - imageRate.startedAt;
+      const remaining = progress.total - progress.completed;
+      if (done <= 0 || elapsedMs <= 0 || remaining <= 0) {
+        return null;
+      }
+      return Math.round((elapsedMs / done) * remaining);
+    };
 
     try {
       deps.logInfo?.('[dictionary:auto-sync] syncing current anime snapshot');
-      const snapshot = await deps.getOrCreateCurrentSnapshot(undefined, {
-        onChecking: ({ mediaId, mediaTitle }) => {
-          currentMediaId = mediaId;
-          currentMediaTitle = mediaTitle;
-          activeCurrentMediaId = mediaId;
-          deps.onSyncStatus?.({
-            phase: 'checking',
-            mediaId,
-            mediaTitle,
-            message: buildCheckingMessage(mediaTitle),
-          });
-        },
-        onGenerating: ({ mediaId, mediaTitle }) => {
-          currentMediaId = mediaId;
-          currentMediaTitle = mediaTitle;
-          activeCurrentMediaId = mediaId;
-          deps.onSyncStatus?.({
-            phase: 'generating',
-            mediaId,
-            mediaTitle,
-            message: buildGeneratingMessage(mediaTitle),
-          });
-        },
-      });
+      const snapshot = await withHeartbeat(
+        () =>
+          deps.getOrCreateCurrentSnapshot(undefined, {
+            onChecking: ({ mediaId, mediaTitle }) => {
+              currentMediaId = mediaId;
+              currentMediaTitle = mediaTitle;
+              activeCurrentMediaId = mediaId;
+              deps.onSyncStatus?.({
+                phase: 'checking',
+                mediaId,
+                mediaTitle,
+                message: buildCheckingMessage(mediaTitle),
+              });
+            },
+            onGenerating: ({ mediaId, mediaTitle }) => {
+              currentMediaId = mediaId;
+              currentMediaTitle = mediaTitle;
+              activeCurrentMediaId = mediaId;
+              lastProgressAt = Number.NEGATIVE_INFINITY;
+              lastProgressStage = null;
+              imageRate = null;
+              generating = { mediaId, mediaTitle, startedAt: deps.now(), detail: null };
+              emitGeneratingStatus();
+            },
+            // Long-running work (AniList character pages, then one image download per character
+            // and voice actor, then MeCab name splits) reports counts so the notification shows
+            // movement instead of a frozen "Generating..." for the minutes a large series takes.
+            onGenerateProgress: (progress) => {
+              const nowMs = deps.now();
+              if (!generating) {
+                generating = {
+                  mediaId: progress.mediaId,
+                  mediaTitle: progress.mediaTitle,
+                  startedAt: nowMs,
+                  detail: null,
+                };
+              }
+              if (progress.stage === 'images' && imageRate === null) {
+                imageRate = { startedAt: nowMs, startCompleted: progress.completed };
+              }
+              // Stage changes and the last item of a stage always report; the throttle only thins
+              // out the run of identical-looking updates in between.
+              const isFinal = progress.total !== null && progress.completed >= progress.total;
+              const isStageChange = progress.stage !== lastProgressStage;
+              if (!isFinal && !isStageChange && nowMs - lastProgressAt < progressThrottleMs) {
+                return;
+              }
+              lastProgressAt = nowMs;
+              lastProgressStage = progress.stage;
+              generating.mediaId = progress.mediaId;
+              generating.mediaTitle = progress.mediaTitle;
+              generating.detail = formatCharacterDictionaryProgressDetail(
+                progress,
+                estimateRemainingImageMs(progress, nowMs),
+              );
+              emitGeneratingStatus();
+            },
+          }),
+        // Ticks even when a step stalls, so the message keeps moving while the counts do not.
+        () => emitGeneratingStatus(),
+      );
+      generating = null;
       currentMediaId = snapshot.mediaId;
       currentMediaTitle = snapshot.mediaTitle;
       activeCurrentMediaId = snapshot.mediaId;
@@ -531,33 +664,61 @@ export function createCharacterDictionaryAutoSyncRuntimeService(
           mediaTitle: snapshot.mediaTitle,
           message: buildImportingMessage(snapshot.mediaTitle),
         });
-        if (existing !== null) {
-          await withOperationTimeout(
-            `deleteYomitanDictionary(${dictionaryTitle})`,
-            deps.deleteYomitanDictionary(dictionaryTitle),
-          );
-        }
-        if (merged === null) {
-          const existingMergedZipPath = path.join(dictionariesDir, 'merged.zip');
-          if (fs.existsSync(existingMergedZipPath)) {
-            merged = {
-              zipPath: existingMergedZipPath,
-              revision,
-              dictionaryTitle,
-              entryCount: snapshot.entryCount,
-            };
-          } else {
-            merged = await deps.buildMergedDictionary(nextActiveMediaIdValues);
-          }
-        }
-        deps.logInfo?.(`[dictionary:auto-sync] importing merged dictionary: ${merged.zipPath}`);
-        const imported = await withOperationTimeout(
-          `importYomitanDictionary(${path.basename(merged.zipPath)})`,
-          deps.importYomitanDictionary(merged.zipPath),
+        await withHeartbeat(
+          async () => {
+            const importTimeoutMs = resolveImportTimeoutMs(
+              merged?.zipPath ?? path.join(dictionariesDir, 'merged.zip'),
+            );
+            if (existing !== null) {
+              await withTimeout(
+                `deleteYomitanDictionary(${dictionaryTitle})`,
+                deps.deleteYomitanDictionary(dictionaryTitle),
+                importTimeoutMs,
+              );
+            }
+            if (merged === null) {
+              // The cached archive only stands in for the recorded state when its own index.json
+              // agrees. A stale or half-written ZIP would be imported under the wrong revision,
+              // and every later sync would then see a revision mismatch and re-import it.
+              const existingMergedZipPath = path.join(dictionariesDir, 'merged.zip');
+              const existingMergedRevision = readDictionaryZipRevision(existingMergedZipPath);
+              if (existingMergedRevision === revision) {
+                merged = {
+                  zipPath: existingMergedZipPath,
+                  revision,
+                  dictionaryTitle,
+                  entryCount: snapshot.entryCount,
+                };
+              } else {
+                deps.logInfo?.(
+                  `[dictionary:auto-sync] cached merged ZIP unusable (revision ${existingMergedRevision ?? 'unreadable'}, expected ${revision}); rebuilding`,
+                );
+                merged = await deps.buildMergedDictionary(nextActiveMediaIdValues);
+              }
+            }
+            const mergedZipPath = merged.zipPath;
+            const mergedImportTimeoutMs = resolveImportTimeoutMs(mergedZipPath);
+            deps.logInfo?.(
+              `[dictionary:auto-sync] importing merged dictionary: ${mergedZipPath} (timeout ${mergedImportTimeoutMs}ms)`,
+            );
+            const imported = await withTimeout(
+              `importYomitanDictionary(${path.basename(mergedZipPath)})`,
+              deps.importYomitanDictionary(mergedZipPath),
+              mergedImportTimeoutMs,
+            );
+            if (!imported) {
+              throw new Error(`Failed to import dictionary ZIP: ${merged.zipPath}`);
+            }
+          },
+          (elapsedMs) => {
+            deps.onSyncStatus?.({
+              phase: 'importing',
+              mediaId: snapshot.mediaId,
+              mediaTitle: snapshot.mediaTitle,
+              message: buildImportingMessage(snapshot.mediaTitle, elapsedMs),
+            });
+          },
         );
-        if (!imported) {
-          throw new Error(`Failed to import dictionary ZIP: ${merged.zipPath}`);
-        }
         changed = true;
       }