fix(showcase): add comprehensive logging to harness probe execution pipeline

Probe runs were a black box in Railway logs — results only visible via
PocketBase API. Add structured INFO-level logging at every lifecycle
boundary so operators can diagnose probe outcomes from logs alone.

probe-invoker.ts:
- tick-start: probe ID, kind, discovered target count, trigger source
- target-start/complete: key, state (green/red/error), duration
- tick-complete: passed/failed counts, total duration
- run-summary: single structured line with every service's outcome

e2e-deep.ts (D5 driver):
- service-start: slug, feature count, backend URL
- feature-complete: slug, feature type, pass/fail, error if failed, duration
- service-complete: slug, passed/failed/skipped counts, duration

browser-pool.ts:
- acquire/release: available/inUse counts after operation
- recycle: slot index, context count, recycle threshold

orchestrator.ts:
- Thread logger into BrowserPool constructor

Author: jpr5

showcase/harness/src/orchestrator.ts

@@ -272,7 +272,7 @@ export async function boot(opts: BootOptions = {}): Promise<{
   const poolSize = process.env.BROWSER_POOL_SIZE
     ? parseInt(process.env.BROWSER_POOL_SIZE, 10) || 4
     : 4;
-  const browserPool = new BrowserPool(poolSize);
+  const browserPool = new BrowserPool(poolSize, undefined, logger);
   let browserPoolReady = false;
   try {
     await browserPool.init();

showcase/harness/src/probes/drivers/e2e-deep.ts

@@ -636,6 +636,13 @@ export function createE2eDeepDriver(
         });
       }
 
+      const serviceStart = Date.now();
+      ctx.logger.info("probe.e2e-deep.service-start", {
+        slug,
+        featureCount: requestedFeatures.length,
+        backendUrl,
+      });
+
       // Partition features into "registered" (script available) vs
       // "skipped" (no script). The skipped set short-circuits before
       // chromium so we don't pay for a launch per slug when Wave 2b
@@ -799,6 +806,7 @@ export function createE2eDeepDriver(
           const url = `${backendUrl}${route}`;
 
           await sem.acquire();
+          const featureStart = Date.now();
           try {
             if (abort.signal.aborted) {
               await sideEmit(ctx, {
@@ -817,6 +825,15 @@ export function createE2eDeepDriver(
                 },
                 observedAt: ctx.now().toISOString(),
               });
+              ctx.logger.info("probe.e2e-deep.feature-complete", {
+                slug,
+                featureType: ft,
+                pass: false,
+                errorDesc: timedOut
+                  ? `timeout after ${timeoutMs}ms`
+                  : "aborted",
+                durationMs: Date.now() - featureStart,
+              });
               return {
                 ft,
                 ok: false as const,
@@ -856,6 +873,12 @@ export function createE2eDeepDriver(
                 },
                 observedAt: ctx.now().toISOString(),
               });
+              ctx.logger.info("probe.e2e-deep.feature-complete", {
+                slug,
+                featureType: ft,
+                pass: true,
+                durationMs: Date.now() - featureStart,
+              });
               return { ft, ok: true as const };
             } else {
               await sideEmit(ctx, {
@@ -878,6 +901,13 @@ export function createE2eDeepDriver(
                 },
                 observedAt: ctx.now().toISOString(),
               });
+              ctx.logger.info("probe.e2e-deep.feature-complete", {
+                slug,
+                featureType: ft,
+                pass: false,
+                errorDesc: featureResult.errorDesc,
+                durationMs: Date.now() - featureStart,
+              });
               return {
                 ft,
                 ok: false as const,
@@ -944,6 +974,15 @@ export function createE2eDeepDriver(
         }
 
         const aggregateGreen = failed.length === 0;
+        ctx.logger.info("probe.e2e-deep.service-complete", {
+          slug,
+          passed,
+          failed: failed.length,
+          skipped: skipped.length,
+          total: requestedFeatures.length,
+          state: aggregateGreen ? "green" : "red",
+          durationMs: Date.now() - serviceStart,
+        });
         return {
           key: input.key,
           state: aggregateGreen ? "green" : "red",

showcase/harness/src/probes/helpers/browser-pool.ts

@@ -17,6 +17,15 @@ export interface BrowserPoolStats {
   totalRecycles: number;
 }
 
+/**
+ * Minimal logger surface the pool uses for lifecycle events. Matches the
+ * harness-wide `Logger` interface but only the `info` method is required.
+ * Optional so existing callers (tests, legacy boot paths) don't break.
+ */
+interface PoolLogger {
+  info(msg: string, meta?: Record<string, unknown>): void;
+}
+
 export class BrowserPool {
   private readonly poolSize: number;
   private readonly recycleAfter: number;
@@ -26,13 +35,19 @@ export class BrowserPool {
   private totalRecycles = 0;
   private inFlightRecycles = new Set<Promise<void>>();
   private isShutdown = false;
+  private readonly logger?: PoolLogger;
 
   // Tracks which Browser instance maps to which Slot, so release() can find
   // the slot in O(1) even after the slot was removed from `available`.
   private browserToSlot = new Map<Browser, Slot>();
 
-  constructor(size = 4, recycleAfter?: number) {
+  constructor(
+    size = 4,
+    recycleAfter?: number,
+    logger?: PoolLogger,
+  ) {
     this.poolSize = size;
+    this.logger = logger;
     const envRecycle = process.env.BROWSER_POOL_RECYCLE_AFTER
       ? parseInt(process.env.BROWSER_POOL_RECYCLE_AFTER, 10)
       : undefined;
@@ -71,6 +86,10 @@ export class BrowserPool {
 
     const slot = this.available.shift();
     if (slot) {
+      this.logger?.info("browser-pool.acquire", {
+        available: this.available.length,
+        inUse: this.slots.length - this.available.length,
+      });
       return slot.browser;
     }
 
@@ -119,6 +138,11 @@ export class BrowserPool {
     } else {
       this.available.push(slot);
     }
+    const s = this.stats();
+    this.logger?.info("browser-pool.release", {
+      available: s.available,
+      inUse: s.inUse,
+    });
   }
 
   async shutdown(): Promise<void> {
@@ -158,6 +182,13 @@ export class BrowserPool {
 
   private recycleSlot(slot: Slot): void {
     this.totalRecycles++;
+    const slotIdx = this.slots.indexOf(slot);
+    this.logger?.info("browser-pool.recycle", {
+      slotIndex: slotIdx,
+      contextCount: slot.contextCount,
+      recycleAfter: this.recycleAfter,
+      totalRecycles: this.totalRecycles,
+    });
 
     // Remove the old browser from the lookup map immediately so a
     // double-release of the stale reference is a no-op.

showcase/harness/src/probes/loader/probe-invoker.ts

@@ -208,6 +208,7 @@ export function buildProbeInvoker(
     // produce zero workers and drop every input on the floor.
     const concurrency = Math.max(cfg.max_concurrency, 1);
     const timeoutMs = "timeout_ms" in cfg ? cfg.timeout_ms : undefined;
+    const tickStart = Date.now();
 
     // B7: tracker registration. Read the slot's `triggeredRun` flag — set
     // by scheduler.trigger() before the handler runs — so the snapshot the
@@ -290,6 +291,14 @@ export function buildProbeInvoker(
     // fan out across.
     const allInputs: ResolvedInput[] = resolved.ok ? resolved.inputs : [];
 
+    logger.info("probe.tick-start", {
+      probeId: cfg.id,
+      kind: cfg.kind,
+      discoveredTargets: allInputs.length,
+      discoveryOk: resolved.ok,
+      triggered,
+    });
+
     // CR-A1.1: thread the trigger's slug filter end-to-end. Discover the
     // FULL roster (so logs/diagnostics still see what the source returned)
     // but only enqueue + run the slugs the operator asked for. Empty
@@ -516,6 +525,8 @@ export function buildProbeInvoker(
         // a dead defensive guard.
         const idx = cursor++;
         const { input, key, preError } = inputs[idx]!;
+        const targetStart = Date.now();
+        logger.info("probe.target-start", { probeId: cfg.id, key });
         // B7: mark running just before handing the input to the driver.
         tracker.start(key);
         // CR-A1.2: short-circuit on inputs the resolver pre-flagged as
@@ -562,6 +573,12 @@ export function buildProbeInvoker(
           tracker.complete(key, "red");
           failed++;
         }
+        logger.info("probe.target-complete", {
+          probeId: cfg.id,
+          key,
+          state: result.state,
+          durationMs: Date.now() - targetStart,
+        });
         try {
           await writer.write(result);
         } catch (err) {
@@ -689,6 +706,35 @@ export function buildProbeInvoker(
           });
         }
       }
+      logger.info("probe.tick-complete", {
+        probeId: cfg.id,
+        kind: cfg.kind,
+        total: summary.total,
+        passed: summary.passed,
+        failed: summary.failed,
+        durationMs: Date.now() - tickStart,
+        discoveryFailed: summary.discoveryFailed ?? false,
+      });
+      // Structured per-service run summary — a single log line carrying
+      // every target's outcome so Railway logs give a complete picture
+      // without needing PocketBase.
+      const summarySnap = tracker.snapshot();
+      if (summarySnap.services.length > 0) {
+        logger.info("probe.run-summary", {
+          probeId: cfg.id,
+          kind: cfg.kind,
+          total: summary.total,
+          passed: summary.passed,
+          failed: summary.failed,
+          durationMs: Date.now() - tickStart,
+          services: summarySnap.services.map((s) => ({
+            slug: s.slug,
+            state: s.state,
+            result: s.result,
+            ...(s.error ? { error: s.error } : {}),
+          })),
+        });
+      }
       // B7: clear the tracker so the next snapshot reports no inflight run.
       // Done in `finally` so even an unexpected throw still leaves the
       // scheduler's view clean. R3-A.2: same prefixed id as registration.