From a49e9562bd029c3c59c5fd604ae690a9e5113b56 Mon Sep 17 00:00:00 2001
From: Claude <noreply@anthropic.com>
Date: Sun, 10 May 2026 13:42:03 +0000
Subject: [PATCH] Workers: cover logging gaps so each one is visible at the
 default level

Three workers were silent at the default Logs-drawer level:

**attachment-expiry-worker** had no `createLogger` at all - the only
log path was the legacy `post({type:'log'})` channel inside the
worker entry, which only fires on setup-session failure and lease
loss. The cycle itself had zero logging, so an attachment-expiry
problem in production left no breadcrumb. Now the loop logs at
.info on lease acquisition, on each non-zero expire batch ("expired
N attachment row(s) older than D days"), and on errors; .debug on
polling and empty-queue ticks so an idle worker isn't noisy.

**samskara-worker** logged at .debug for events the other agent
workers log at .info ("picked up thread X" / "finished thread X"),
and used .trace for some routine state. With the drawer at the
default level, samskara was invisible - you saw every other worker
fire but not this one. Bumped four lifecycle lines to .info:

  - assimilate: claimed substrate <id> (thread <thread>)
  - assimilate: saved substrate <id>
  - pair-relate: selected pair <a> <> <b> (cosine X.XXX)
  - pair-relate: associated <a> <> <b> (<kind>: <label>)
  - compound-regen: synthesizing summary from N sample row(s)

Detail / error / null-result lines stay on .debug so the drawer
isn't flooded with samskara's higher per-cycle volume.

**wiki-librarian-worker** had logs on `too-small` / `reviewed` /
`error` but none on `acquired-lease` / `polling` / `too-soon` -
and `too-soon` is the most common state for the first 12 hours
after deploy, so the user couldn't tell whether the librarian was
firing at all. Now:

  - lease acquired: .info ("lease acquired - checking eligibility
    on the next cycle")
  - polling for lease (another device holds it): .debug, since
    polling fires every 60s while waiting
  - too-soon: .info, with the configured min-interval named
    explicitly so the user knows the next eligible run timing
    without doing the math. ~24 lines/day during cooldown - not
    noisy, and gives the "yes, alive and waiting" signal that was
    missing.
  - claim acquired - starting librarian run: .info
  - claim RPC / list / agent throws were on .debug, bumped to
    .info so a real failure isn't silent.

Embed-worker logging left as-is (the abbreviated `embed-` source
tag and existing log shape; no functional issues).

https://claude.ai/code/session_015XcR7xzLdij66ZbYERUdLH
---
 src/lib/agents/attachment_expiry/loop.ts | 30 ++++++++++++--
 src/lib/agents/samskara/loop.ts          | 51 +++++++++++++++---------
 src/lib/agents/wiki-librarian/loop.ts    | 40 ++++++++++++++-----
 3 files changed, 90 insertions(+), 31 deletions(-)

diff --git a/src/lib/agents/attachment_expiry/loop.ts b/src/lib/agents/attachment_expiry/loop.ts
index 0936e61..1d89a37 100644
--- a/src/lib/agents/attachment_expiry/loop.ts
+++ b/src/lib/agents/attachment_expiry/loop.ts
@@ -12,6 +12,9 @@
  */
 import type { SupabaseService } from '../../supabase';
 import type { LeaseCoordinator } from '../../embeddings/lease';
+import { createLogger } from '../../logger.svelte';
+
+const log = createLogger('attachment-expiry-worker');
 
 export type CycleResult =
   /** Just took the lease on this cycle — no work yet, caller should recurse immediately. */
@@ -42,21 +45,42 @@ export async function runOneCycle(ctx: CycleContext): Promise<CycleResult> {
 
   if (!ctx.coordinator.isHolding) {
     const acquired = await ctx.coordinator.acquire();
-    if (!acquired) return 'polling';
+    if (!acquired) {
+      // Polling fires every leasePollMs while another device holds
+      // the lease. Logged at .debug so an idle worker doesn't spam
+      // the drawer.
+      log.debug('polling for lease (another device holds it)');
+      return 'polling';
+    }
     ctx.coordinator.startHeartbeat(ctx.onLeaseLost);
+    log.info('lease acquired - starting expiry sweep');
     return 'acquired-lease';
   }
 
   let affected: number;
   try {
     affected = await ctx.supabase.expireOldAttachments(ctx.expiryDays);
-  } catch {
+  } catch (err) {
     // Transient failure — Supabase hiccup, network blip. Back off and
     // retry. The work isn't time-sensitive so we don't need tight
     // retries; the hourly idle poll will eventually catch up.
+    log.info(
+      `expire RPC failed: ${err instanceof Error ? err.message : String(err)}`
+    );
     return 'error';
   }
-  if (affected === 0) return 'empty-queue';
+  if (affected === 0) {
+    // Empty-queue is the steady state once the backlog drains.
+    // .debug rather than .info to avoid an hourly heartbeat line in
+    // the drawer; the user can flip log level to debug when actively
+    // checking that the worker is alive.
+    log.debug(`expire sweep found no rows older than ${ctx.expiryDays} days`);
+    return 'empty-queue';
+  }
+  log.info(
+    `expired ${affected} attachment row${affected === 1 ? '' : 's'} ` +
+      `older than ${ctx.expiryDays} days`
+  );
   return 'expired';
 }
 
diff --git a/src/lib/agents/samskara/loop.ts b/src/lib/agents/samskara/loop.ts
index 6e0b971..761cba7 100644
--- a/src/lib/agents/samskara/loop.ts
+++ b/src/lib/agents/samskara/loop.ts
@@ -202,12 +202,13 @@ async function runAssimilatePhase(ctx: CycleContext): Promise<CycleResult> {
     return 'error';
   }
   if (!claim) return 'empty-phase';
-  log.debug('assimilate: claimed substrate', {
-    substrateId: claim.id,
-    threadId: claim.threadId,
-    userMessageId: claim.userMessageId,
-    assistantMessageId: claim.assistantMessageId,
-  });
+  // Lifecycle headline parallel to "picked up thread X" in the
+  // other agent workers - logged at .info so the user can see
+  // samskara firing in the drawer at the default level.
+  log.info(
+    `assimilate: claimed substrate ${claim.id} ` +
+      `(thread ${claim.threadId})`
+  );
 
   // Fetch the two messages this substrate row anchors. assistantMessageId
   // can be null (a turn that errored before the assistant row landed); in
@@ -267,7 +268,14 @@ async function runAssimilatePhase(ctx: CycleContext): Promise<CycleResult> {
     log.debug('assimilate: save failed', err);
     return 'error';
   }
-  if (!saved) log.debug('assimilate: save rejected (claim expired?)', { substrateId: claim.id });
+  if (!saved) {
+    log.debug('assimilate: save rejected (claim expired?)', { substrateId: claim.id });
+  } else {
+    // Lifecycle "finished" line parallel to "finished thread X" in
+    // the other agent workers. Logged at .info; details about the
+    // assimilation result stay on the .debug line above.
+    log.info(`assimilate: saved substrate ${claim.id}`);
+  }
   return saved ? 'progress' : 'save-rejected';
 }
 
@@ -322,11 +330,12 @@ async function runPairRelatePhase(ctx: CycleContext): Promise<CycleResult> {
   }
 
   const partner = recent[bestIdx];
-  log.debug('pair-relate: selected pair', {
-    seedId: seed.id,
-    partnerId: partner.id,
-    cosine: bestSim,
-  });
+  // Lifecycle "picked up" line parallel to the other agents' "picked
+  // up X" - .info so it's visible at the default log level.
+  log.info(
+    `pair-relate: selected pair ${seed.id} <> ${partner.id} ` +
+      `(cosine ${bestSim.toFixed(3)})`
+  );
   const result = await ctx.agent.relate(
     { situation: seed.situation, outcome: seed.outcome },
     { situation: partner.situation, outcome: partner.outcome },
@@ -380,12 +389,11 @@ async function runPairRelatePhase(ctx: CycleContext): Promise<CycleResult> {
     log.debug('pair-relate: upsert threw', err);
     return 'error';
   }
-  log.debug('pair-relate: associated', {
-    aId,
-    bId,
-    kind: result.kind,
-    label: shorten(result.label),
-  });
+  // Lifecycle "finished" line - .info so the user sees the
+  // association land in the drawer at the default log level.
+  log.info(
+    `pair-relate: associated ${aId} <> ${bId} (${result.kind}: ${shorten(result.label)})`
+  );
   return 'progress';
 }
 
@@ -835,7 +843,12 @@ async function runCompoundRegenPhase(ctx: CycleContext): Promise<CycleResult> {
     return 'error';
   }
   if (rows.length === 0) return 'empty-phase';
-  log.debug('compound-regen: synthesizing', { rows: rows.length, cap });
+  // Lifecycle "starting work" line - .info so a compound-regen run
+  // is visible in the drawer.
+  log.info(
+    `compound-regen: synthesizing summary from ${rows.length} sample row(s) ` +
+      `(cap ${cap})`
+  );
 
   const summary = await ctx.agent.summarizeCompound(
     rows.map((r) => ({
diff --git a/src/lib/agents/wiki-librarian/loop.ts b/src/lib/agents/wiki-librarian/loop.ts
index 5063c26..5e28827 100644
--- a/src/lib/agents/wiki-librarian/loop.ts
+++ b/src/lib/agents/wiki-librarian/loop.ts
@@ -59,8 +59,16 @@ export async function runOneCycle(ctx: CycleContext): Promise<CycleResult> {
 
   if (!ctx.coordinator.isHolding) {
     const acquired = await ctx.coordinator.acquire();
-    if (!acquired) return 'polling';
+    if (!acquired) {
+      // Polling fires every leasePollMs; .debug rather than .info so
+      // an idle librarian doesn't spam the drawer with a "still
+      // polling" line every minute. The acquired-lease branch below
+      // does land at .info so the user sees the transition.
+      log.debug('polling for lease (another device holds it)');
+      return 'polling';
+    }
     ctx.coordinator.startHeartbeat(ctx.onLeaseLost);
+    log.info('lease acquired - checking eligibility on the next cycle');
     return 'acquired-lease';
   }
 
@@ -72,10 +80,26 @@ export async function runOneCycle(ctx: CycleContext): Promise<CycleResult> {
     claimed = await ctx.supabase.claimWikiLibrarianRun(
       ctx.minIntervalSeconds
     );
-  } catch {
+  } catch (err) {
+    log.info(
+      `claim RPC failed: ${err instanceof Error ? err.message : String(err)}`
+    );
     return 'error';
   }
-  if (!claimed) return 'too-soon';
+  if (!claimed) {
+    // Logged at .info so the user can see "yes, the librarian is
+    // alive and waiting" without enabling debug. Idle nap is 1h, so
+    // this lands ~24 lines/day during the 12h cooldown - not noisy.
+    // The interval is named explicitly so the user knows the next
+    // attempt timing without doing the math.
+    const hours = Math.round(ctx.minIntervalSeconds / 3600);
+    log.info(
+      `not yet eligible for a librarian run ` +
+        `(min interval ${hours}h since last successful run)`
+    );
+    return 'too-soon';
+  }
+  log.info('claim acquired - starting librarian run');
 
   // Snapshot of every article. Same listing the drawer uses, but
   // we cap at 500 (matching listWikiArticles' default) - a librarian
@@ -85,9 +109,8 @@ export async function runOneCycle(ctx: CycleContext): Promise<CycleResult> {
   try {
     articles = await ctx.supabase.listWikiArticles({ limit: 500 });
   } catch (err) {
-    log.debug(
-      'failed to list wiki articles for librarian',
-      err instanceof Error ? err.message : String(err)
+    log.info(
+      `failed to list wiki articles: ${err instanceof Error ? err.message : String(err)}`
     );
     return 'error';
   }
@@ -113,9 +136,8 @@ export async function runOneCycle(ctx: CycleContext): Promise<CycleResult> {
       signal: ctx.signal,
     });
   } catch (err) {
-    log.debug(
-      'librarian agent threw unexpectedly',
-      err instanceof Error ? err.message : String(err)
+    log.info(
+      `librarian agent threw unexpectedly: ${err instanceof Error ? err.message : String(err)}`
     );
     return 'error';
   }