Sync says what it is doing, file by file

The counters said how MUCH and never which file, so a run that was working normally and one that had
wedged produced the same screen: `done` stops moving either way. A photograph is around thirty encodes
and a video is three plus a poster ladder, and none of that was visible from outside.

So the run keeps a transcript and the button opens it.

Every rung reports itself by CONSTRUCTION. Ten `variants.push` call sites became one `add`, which is
the point — a rung added later is described without anybody remembering to describe it. The slow
stages that produce nothing until they finish say so BEFORE they start instead: the HEIC decode, each
video rung, the poster frame. Those are the pauses that read as a hang.

`?since=<n>` is what keeps it cheap. The transcript is thousands of lines and polls once a second, so
sending all of it every tick would be the same megabyte over and over; the client keeps what it has
and asks for the rest. No `since` means everything, which is what a modal opened mid-run wants.

The transcript lives in the shared slot, not the modal, so closing it does not throw away the run —
somebody who looks, closes, and looks again is watching one run rather than two. `startedAt` is what
identifies a run, because `n` restarts at 1 and appending across a boundary would interleave two.

Polling, not a socket. Each line transfers once and the events are seconds apart, so a second
transport to open, authenticate and reconnect would buy nothing.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

api/derive.ts

@@ -538,12 +538,25 @@ async function topUp(dir: string, manifest: Manifest, email: string): Promise<Ma
  * finished, because the manifest is what everything else trusts. Half a ladder with a manifest is
  * worse than no ladder at all.
  */
+/** Told what just happened, rung by rung. See `onStep` — a no-op unless somebody is watching. */
+export type Step = (message: string) => void;
+
 export async function deriveOne(
   sourcePath: string,
   targetDir: string,
   email: string,
-  options: { force?: boolean } = {},
+  options: { force?: boolean; onStep?: Step } = {},
 ): Promise<{ built: boolean; manifest: Manifest }> {
+  /*
+    Say what is happening, if anybody asked.
+
+    A no-op by default, so nothing here depends on being watched — the sync passes one through to fill
+    its transcript; the watcher and the tests pass nothing. One photograph is around thirty encodes and
+    a video is three plus a poster ladder, so without this a run that is working normally and a run
+    that is wedged look identical from outside.
+  */
+  const step = options.onStep ?? (() => {});
+
   const name = sourcePath.slice(sourcePath.lastIndexOf('/') + 1);
   const kind = kindOf(name);
   if (!kind) throw new Error(`${name} is neither an image nor a video this understands.`);
@@ -563,8 +576,8 @@ export async function deriveOne(
   try {
     const manifest =
       kind === 'image'
-        ? await buildImage(sourcePath, staging, name, source, email)
-        : await buildVideo(sourcePath, staging, name, source, email);
+        ? await buildImage(sourcePath, staging, name, source, email, step)
+        : await buildVideo(sourcePath, staging, name, source, email, step);
 
     await writeFile(join(staging, MANIFEST), `${JSON.stringify(manifest, null, 2)}\n`, 'utf8');
 
@@ -596,6 +609,7 @@ async function buildImage(
   name: string,
   source: { bytes: number; mtimeMs: number },
   email: string,
+  step: Step,
 ): Promise<Manifest> {
   const meta = await avClub<{ width: number | null; height: number | null; needsConversion: boolean }>(
     `/v1/image?path=${encodeURIComponent(sourcePath)}`,
@@ -624,6 +638,9 @@ async function buildImage(
   */
   const master = meta.needsConversion ? join(staging, MASTER) : sourcePath;
   if (meta.needsConversion) {
+    // Announced BEFORE it happens, unlike a rung. This is the 8.5-second one, it produces nothing
+    // anybody sees, and a transcript that went quiet here is the exact case this exists to explain.
+    step(`decoding ${name} once (${width}x${height})`);
     await post('/v1/sharp', email, {
       inputPath: sourcePath,
       outputPath: master,
@@ -639,7 +656,17 @@ async function buildImage(
   */
   const lossless = await prefersLossless(master, staging, email, width);
 
+  /*
+    Collect and announce, so a rung cannot be added without being described.
+
+    Ten `variants.push` call sites became one `add`, which is the point: a rung added later reports
+    itself by construction rather than because somebody remembered to.
+  */
   const variants: Variant[] = [];
+  const add = (variant: Variant): void => {
+    variants.push(variant);
+    step(`${variant.file} · ${(variant.bytes / 1024).toFixed(0)} KB`);
+  };
 
   /*
     `full.webp` first, and always.
@@ -648,7 +675,7 @@ async function buildImage(
     exists at all — the original renders nowhere. A lightbox, a zoom, or handing the client their own
     photograph back all need it.
   */
-  variants.push(await encodeWebp(master, join(staging, 'full.webp'), null, email, width, height, lossless));
+  add(await encodeWebp(master, join(staging, 'full.webp'), null, email, width, height, lossless));
 
   /*
     AVIF beside every rung — except for a picture that wanted the lossless path.
@@ -660,13 +687,13 @@ async function buildImage(
   */
   const buildAvif = !lossless;
 
-  if (buildAvif) variants.push(await encodeAvif(master, join(staging, 'full.avif'), null, email, width, height));
+  if (buildAvif) add(await encodeAvif(master, join(staging, 'full.avif'), null, email, width, height));
 
   // Strictly less than the original: a rung at or above it would duplicate `full.webp` byte for byte.
   for (const rung of LADDER) {
     if (rung >= width) continue;
-    variants.push(await encodeWebp(master, join(staging, `${rung}.webp`), rung, email, width, height, lossless));
-    if (buildAvif) variants.push(await encodeAvif(master, join(staging, `${rung}.avif`), rung, email, width, height));
+    add(await encodeWebp(master, join(staging, `${rung}.webp`), rung, email, width, height, lossless));
+    if (buildAvif) add(await encodeAvif(master, join(staging, `${rung}.avif`), rung, email, width, height));
   }
 
   /*
@@ -686,8 +713,8 @@ async function buildImage(
   if (!squareEnough) {
     for (const rung of SQUARE_LADDER) {
       if (rung > Math.min(width, height)) continue;
-      variants.push(await encodeSquare(master, join(staging, `${rung}sq.webp`), rung, email, lossless));
-      if (buildAvif) variants.push(await encodeSquareAvif(master, join(staging, `${rung}sq.avif`), rung, email));
+      add(await encodeSquare(master, join(staging, `${rung}sq.webp`), rung, email, lossless));
+      if (buildAvif) add(await encodeSquareAvif(master, join(staging, `${rung}sq.avif`), rung, email));
     }
   }
 
@@ -870,6 +897,7 @@ async function buildVideo(
   name: string,
   source: { bytes: number; mtimeMs: number },
   email: string,
+  step: Step,
 ): Promise<Manifest> {
   const probe = await avClub<{ streams?: Array<{ codec_type?: string; width?: number; height?: number }> }>(
     `/v1/probe?path=${encodeURIComponent(sourcePath)}`,
@@ -879,7 +907,17 @@ async function buildVideo(
   const height = video?.height ?? 0;
   const width = video?.width ?? 0;
 
+  /*
+    Collect and announce, so a rung cannot be added without being described.
+
+    Ten `variants.push` call sites became one `add`, which is the point: a rung added later reports
+    itself by construction rather than because somebody remembered to.
+  */
   const variants: Variant[] = [];
+  const add = (variant: Variant): void => {
+    variants.push(variant);
+    step(`${variant.file} · ${(variant.bytes / 1024).toFixed(0)} KB`);
+  };
 
   /*
     Every rung the source is actually tall enough for, and the floor when it is tall enough for none.
@@ -892,6 +930,8 @@ async function buildVideo(
   const rungs = wanted.length ? wanted : [VIDEO_FLOOR];
 
   for (const rung of rungs) {
+    // Before, because this is minutes and the line after it is the only other one this loop prints.
+    step(`encoding ${rung.file}`);
     const result = await post<{ path: string; bytes: number }>('/v1/ffmpeg', email, {
       inputPath: sourcePath,
       outputPath: join(staging, rung.file),
@@ -900,7 +940,7 @@ async function buildVideo(
       // see sidecar/ffmpeg/run.ts. Used only to lighten the audio on the 480 rung.
       ...(rung.options ? { options: rung.options } : {}),
     });
-    variants.push({ file: rung.file, width: null, height: null, bytes: result.bytes });
+    add({ file: rung.file, width: null, height: null, bytes: result.bytes });
   }
 
   /*
@@ -911,6 +951,7 @@ async function buildVideo(
     is dropped. Two calls per video, once, at build time.
   */
   const stillJpg = join(staging, 'poster.jpg');
+  step('extracting the poster frame');
   await post('/v1/ffmpeg', email, {
     inputPath: sourcePath,
     outputPath: stillJpg,
@@ -933,7 +974,7 @@ async function buildVideo(
     order rather than the other one.
   */
   const placeholder = await encodePlaceholder(stillJpg, join(staging, 'placeholder.webp'), email);
-  variants.push({ file: 'poster.webp', width: width || null, height: height || null, bytes: poster.bytes });
+  add({ file: 'poster.webp', width: width || null, height: height || null, bytes: poster.bytes });
 
   /*
     The poster's own ladder, cut from the same still.
@@ -954,7 +995,7 @@ async function buildVideo(
       pipeline: [{ resize: { width: rung, fit: 'inside', withoutEnlargement: true } }],
       output: { format: 'webp', options: { quality: WEBP_QUALITY_POSTER } },
     });
-    variants.push({
+    add({
       file: `poster-${rung}.webp`,
       width: rung,
       height: height ? Math.round((rung / width) * height) : null,
@@ -969,7 +1010,7 @@ async function buildVideo(
       pipeline: [{ resize: { width: rung, fit: 'inside', withoutEnlargement: true } }],
       output: { format: 'avif', options: { quality: avifQualityFor(rung) } },
     });
-    variants.push({
+    add({
       file: `poster-${rung}.avif`,
       width: rung,
       height: height ? Math.round((rung / width) * height) : null,

api/router.ts

@@ -395,9 +395,25 @@ router.post('/_config/media/sync', async (ctx) => {
   }
 });
 
+/*
+  The sync's state, and the part of its transcript the caller does not have yet.
+
+  `?since=<n>` is what keeps a modal open on a long run cheap: the transcript is thousands of lines by
+  the end and polls once a second, so sending all of it every tick would be the same megabyte over and
+  over. The caller keeps what it has been given and asks for what came after.
+
+  Absent `since` means "everything", which is what a modal opening mid-run wants — a watcher that
+  arrived late should see what already happened rather than start from the next line.
+*/
 router.get('/_config/media/sync', async (ctx) => {
   const user = ctx.get('user');
-  return ctx.json(readSync(user.email));
+  const state = readSync(user.email);
+
+  const raw = ctx.req.query('since');
+  const since = raw === undefined ? null : Number(raw);
+  if (since === null || !Number.isFinite(since)) return ctx.json(state);
+
+  return ctx.json({ ...state, log: state.log.filter((line) => line.n > since) });
 });
 
 /**

api/sync.ts

@@ -76,8 +76,45 @@ export type SyncState = {
    */
   scope: string;
   trigger: RunTrigger;
+  /**
+   * A running transcript — what happened, to which file, when.
+   *
+   * The counters say how MUCH; this says what. They answer different questions and a run that stalls
+   * on one photograph is invisible in the counters: `done` simply stops moving, and there is nothing
+   * to tell "av-club is chewing on a 40-megapixel HEIC" apart from "the process is wedged".
+   *
+   * Kept on the state rather than written to a file, because the run already lives in memory and a log
+   * file would be a second thing to find, rotate and clean up for output whose whole value is that
+   * somebody is watching it right now. The ledger is what survives; this is what is happening.
+   */
+  log: LogLine[];
 };
 
+/** One line of the transcript. */
+export type LogLine = {
+  /**
+   * Monotonic, and the reason the client can poll cheaply.
+   *
+   * A watcher asks for everything after the last number it holds, so a modal open for a long run
+   * transfers each line once instead of re-sending the whole transcript every second.
+   */
+  n: number;
+  at: string;
+  level: 'info' | 'step' | 'done' | 'warn' | 'error';
+  /** The file this is about, when it is about one. Blank for the run's own lines. */
+  file: string;
+  text: string;
+};
+
+/**
+ * How many lines to keep.
+ *
+ * A photograph produces about thirty of them, so this is a few hundred files of detail. Past it the
+ * OLDEST go: the interesting end of a long run is the end, and a transcript that stopped recording at
+ * the top would drop the failure somebody opened it to read.
+ */
+const LOG_LIMIT = 4000;
+
 /** One. See the note above — this is a memory limit, not a politeness. */
 const CONCURRENCY = 1;
 
@@ -96,6 +133,7 @@ const idle = (): SyncState => ({
   fatal: null,
   scope: '',
   trigger: 'manual',
+  log: [],
 });
 
 const states = new Map<string, SyncState>();
@@ -131,14 +169,39 @@ export function startSync(
   return { started: true, state };
 }
 
+/**
+ * Add a line, and keep the buffer bounded.
+ *
+ * `seq` is per-run and starts where the last one left off only in the sense that a new run resets it —
+ * a watcher that reconnects across runs sees the numbers go backwards, which is why the client drops
+ * what it holds when `startedAt` changes rather than trusting the numbers alone.
+ */
+const say = (state: SyncState, level: LogLine['level'], file: string, text: string): void => {
+  const n = (state.log.at(-1)?.n ?? 0) + 1;
+  state.log.push({ n, at: new Date().toISOString(), level, file, text });
+  // Oldest first. See LOG_LIMIT — the end of a long run is the part worth keeping.
+  if (state.log.length > LOG_LIMIT) state.log.splice(0, state.log.length - LOG_LIMIT);
+};
+
+/** `1.4s`, `320ms`. Short enough to sit at the end of a line without becoming the line. */
+const since = (from: number): string => {
+  const ms = Date.now() - from;
+  return ms < 1000 ? `${ms}ms` : `${(ms / 1000).toFixed(1)}s`;
+};
+
 async function run(email: string, state: SyncState): Promise<void> {
+  const began = Date.now();
   try {
     const from = await originalsDir(email);
     const to = await derivedDir(email);
 
+    say(state, 'info', '', `Reading ${state.scope || 'originals/'}`);
+
     const files = await listOriginals(from, state.scope);
     state.total = files.length;
 
+    say(state, 'info', '', `${files.length} file${files.length === 1 ? '' : 's'} to check`);
+
     /*
       What is already built, indexed by what it was built FROM.
 
@@ -149,6 +212,10 @@ async function run(email: string, state: SyncState): Promise<void> {
     */
     const derivedIndex = await indexDerived(to);
 
+    // Worth a line: on a big library this is the pause before anything appears to happen, and without
+    // it the transcript opens with a gap somebody reads as a hang.
+    say(state, 'info', '', `Indexed ${derivedIndex.size} existing ladder${derivedIndex.size === 1 ? '' : 's'}`);
+
     let next = 0;
     const worker = async (): Promise<void> => {
       for (;;) {
@@ -157,6 +224,8 @@ async function run(email: string, state: SyncState): Promise<void> {
         if (file === undefined) return;
 
         state.current.push(file);
+        const startedFile = Date.now();
+        say(state, 'step', file, 'checking');
         try {
           const target = targetFor(to, file);
           await mkdir(dirname(target), { recursive: true });
@@ -175,10 +244,28 @@ async function run(email: string, state: SyncState): Promise<void> {
             ? await relocateDerived(derivedIndex, to, file, { bytes: info.size, mtimeMs: Math.round(info.mtimeMs) })
             : false;
 
-          const { built } = await deriveOne(`${from}/${file}`, target, email);
-          if (relocated && !built) state.moved++;
-          else if (built) state.built++;
-          else state.skipped++;
+          if (relocated) say(state, 'info', file, 'moved — renaming its ladder instead of rebuilding');
+
+          /*
+            Every rung, as it lands. This is the "what is it doing right now" the counters cannot say:
+            one photograph is thirty encodes and a video is three of them plus a poster ladder, and a
+            run that looks stopped is usually most of the way through one of those.
+          */
+          const { built } = await deriveOne(`${from}/${file}`, target, email, {
+            onStep: (message) => say(state, 'step', file, message),
+          });
+
+          if (relocated && !built) {
+            state.moved++;
+            say(state, 'done', file, `moved · ${since(startedFile)}`);
+          } else if (built) {
+            state.built++;
+            say(state, 'done', file, `built · ${since(startedFile)}`);
+          } else {
+            state.skipped++;
+            // `current` and not `skipped`: nothing was skipped over, the ladder was already right.
+            say(state, 'done', file, `already current · ${since(startedFile)}`);
+          }
         } catch (error) {
           const message = (error as Error).message;
           /*
@@ -188,9 +275,11 @@ async function run(email: string, state: SyncState): Promise<void> {
           */
           if (message.includes('av-club is not running')) {
             state.fatal = message;
+            say(state, 'error', '', message);
             return;
           }
           state.errors.push({ file, message });
+          say(state, 'error', file, message);
         } finally {
           state.current = state.current.filter((name) => name !== file);
           state.done++;
@@ -211,15 +300,37 @@ async function run(email: string, state: SyncState): Promise<void> {
       what the name has meant since these two folders stopped being called `user` and `treated`.
     */
     if (!state.scope && !state.fatal) {
-      state.pruned = (await pruneDerived(from, to)).length;
+      const orphans = await pruneDerived(from, to);
+      state.pruned = orphans.length;
+      // Named, not counted. A removal nobody can see the target of is the one thing here somebody
+      // might want to argue with afterwards.
+      for (const orphan of orphans) say(state, 'warn', orphan, 'removed — its original is gone');
     }
   } catch (error) {
     state.fatal = (error as Error).message;
+    say(state, 'error', '', (error as Error).message);
   } finally {
     state.running = false;
     state.current = [];
     state.finishedAt = new Date().toISOString();
 
+    // The last line, and the one still on screen when the modal stops moving.
+    say(
+      state,
+      state.fatal || state.errors.length ? 'warn' : 'done',
+      '',
+      [
+        `${state.built} built`,
+        state.skipped ? `${state.skipped} already current` : '',
+        state.moved ? `${state.moved} moved` : '',
+        state.pruned ? `${state.pruned} removed` : '',
+        state.errors.length ? `${state.errors.length} failed` : '',
+        `in ${since(began)}`,
+      ]
+        .filter(Boolean)
+        .join(' · '),
+    );
+
     /*
       The one durable record this leaves.