feat: structured logging across harness + engines + substrates (Wedge 1.9)

Every lifecycle step of every harness and every substrate now emits one
structured log line to stderr, configurable by env:

  COMPUTERAGENT_LOG=debug|info|warn|error|silent  (default: info)
  COMPUTERAGENT_LOG_FORMAT=pretty|json            (default: auto by TTY)

What you see at info:
  substrate.local.boot, harness.boot, harness.ready, session.create,
  session.start, engine.start, session.end, engine.turn.end,
  substrate.local.dispose

What you additionally see at debug:
  http.request (every REST hit), engine.tool_use, engine.tool_result,
  engine.assistant_text, engine.usage, fs.read/write/edit/delete, etc.

Architecture (per Wedge 1.9 in the plan):
 - Tiny ~80 LOC zero-dep `Logger` in @computeragent/protocol.
   Stable interface; pino can replace the implementation later.
 - Additive `logger?: Logger` on `EngineContext`, `ServerDeps`, and
   `CreateHarnessServerOptions`. `nopLogger` is the default.
 - Engines (claude-agent-sdk, gitagent, deepagents): one log call per
   tool_use, tool_result, assistant_text, usage_snapshot; plus start +
   turn.end + error.
 - Harness server: per-route http.request logs; create-session,
   run-session, permission_request, permission_decision, cancel,
   http.error.
 - Substrates (local, e2b, vzvm): boot, harness.ready, dispose, plus
   per-runtime steps (upload, install, vm.clone, port_forward).
 - SDK `new ComputerAgent({ debug: true })`: forces
   COMPUTERAGENT_LOG=debug in the spawned harness env AND emits a
   one-line client-side summary per HarnessEvent consumed.
 - LocalSubstrate (and E2B/VZVM) defaults onLog to relay child stderr
   to parent stderr verbatim, so harness-side structured logs surface
   in the parent terminal without extra wiring.

Bundle size: +20KB across all three substrate bundles (1.0M of which
is the engine code + 80 LOC logger). Acceptable.

Known limitation: on sub-second `agent.dispose()` flows, the very last
1-2 engine + session.end lines may be truncated by the stderr flush
race when the harness child is SIGTERM'd. A 250ms drain in
killProcess covers most cases; not all. Doesn't affect real-length
agent runs.

Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>

Author: kapaleshreyas

packages/engine-claude-agent-sdk/src/engine.ts

@@ -7,6 +7,7 @@ import type {
   EngineEvent,
   UserMessage,
 } from "@computeragent/protocol";
+import { nopLogger } from "@computeragent/protocol";
 import { buildCanUseTool } from "./permission-bridge.js";
 import { deriveEngineUuid } from "./derive-uuid.js";
 
@@ -39,6 +40,15 @@ export class ClaudeAgentEngine implements EngineDriver<ClaudeAgentOptions> {
   async *startSession(
     ctx: EngineContext<ClaudeAgentOptions>,
   ): AsyncIterable<EngineEvent> {
+    const log = ctx.logger ?? nopLogger;
+    const turnStartedAt = Date.now();
+    const model = (ctx.options as { model?: string }).model;
+    log.info("engine.start", {
+      engine: "claude-agent-sdk",
+      sessionId: ctx.sessionId,
+      model,
+      workdir: ctx.workdir,
+    });
     const prompt = adaptUserMessages(ctx.userMessageQueue, ctx.sessionId);
     const abortController = signalToController(ctx.abortSignal);
 
@@ -93,19 +103,70 @@ export class ClaudeAgentEngine implements EngineDriver<ClaudeAgentOptions> {
       ...storeOpts,
     };
 
-    for await (const message of query({ prompt, options })) {
-      if (ctx.abortSignal.aborted) break;
+    try {
+      for await (const message of query({ prompt, options })) {
+        if (ctx.abortSignal.aborted) break;
 
-      // Surface token/cost telemetry BEFORE the message itself. SDKResultMessage
-      // is the turn terminator — once the SDK consumer sees it, my issue #2
-      // fix synthesizes a `ca_session_ended` and stops reading. So usage has
-      // to land on the wire BEFORE the result, otherwise it's dropped. The
-      // consumer (SDK aggregator) uses costSemantic="cumulative" to take the
-      // max and sums the per-turn tokens. Never compute cost client-side — see #5.
-      const snapshot = toUsageSnapshot(message);
-      if (snapshot) yield snapshot;
+        logSdkMessage(log, ctx.sessionId, message);
 
-      yield { kind: "sdk_message", payload: message };
+        // Surface token/cost telemetry BEFORE the message itself. SDKResultMessage
+        // is the turn terminator — once the SDK consumer sees it, my issue #2
+        // fix synthesizes a `ca_session_ended` and stops reading. So usage has
+        // to land on the wire BEFORE the result, otherwise it's dropped. The
+        // consumer (SDK aggregator) uses costSemantic="cumulative" to take the
+        // max and sums the per-turn tokens. Never compute cost client-side — see #5.
+        const snapshot = toUsageSnapshot(message);
+        if (snapshot) {
+          log.debug("engine.usage", {
+            sessionId: ctx.sessionId,
+            inputTokens: snapshot.kind === "ca_usage_snapshot" ? snapshot.inputTokens : undefined,
+            outputTokens: snapshot.kind === "ca_usage_snapshot" ? snapshot.outputTokens : undefined,
+            costUsd: snapshot.kind === "ca_usage_snapshot" ? snapshot.costUsd : undefined,
+          });
+          yield snapshot;
+        }
+
+        yield { kind: "sdk_message", payload: message };
+      }
+      log.info("engine.turn.end", {
+        engine: "claude-agent-sdk",
+        sessionId: ctx.sessionId,
+        durationMs: Date.now() - turnStartedAt,
+      });
+    } catch (err) {
+      log.error("engine.error", {
+        engine: "claude-agent-sdk",
+        sessionId: ctx.sessionId,
+        error: err instanceof Error ? err.message : String(err),
+      });
+      throw err;
+    }
+  }
+}
+
+/**
+ * Extract tool_use, tool_result, and assistant_text events from each
+ * SDKMessage as it flows through. Pure log emission — no transformation.
+ */
+function logSdkMessage(log: { debug: (e: string, f?: Record<string, unknown>) => void }, sessionId: string, message: unknown): void {
+  const m = message as {
+    type?: string;
+    message?: { content?: Array<{ type: string; name?: string; id?: string; text?: string; tool_use_id?: string; is_error?: boolean; content?: unknown }> };
+  };
+  if (m?.type === "assistant" && Array.isArray(m.message?.content)) {
+    for (const block of m.message.content) {
+      if (block.type === "tool_use") {
+        log.debug("engine.tool_use", { sessionId, name: block.name, callId: block.id });
+      } else if (block.type === "text" && typeof block.text === "string") {
+        log.debug("engine.assistant_text", { sessionId, textLen: block.text.length });
+      }
+    }
+  } else if (m?.type === "user" && Array.isArray(m.message?.content)) {
+    for (const block of m.message.content) {
+      if (block.type === "tool_result") {
+        const bytes = typeof block.content === "string" ? block.content.length : JSON.stringify(block.content ?? "").length;
+        log.debug("engine.tool_result", { sessionId, callId: block.tool_use_id, isError: block.is_error, bytes });
+      }
     }
   }
 }

packages/engine-deepagents/src/engine.ts

@@ -3,8 +3,10 @@ import type {
   EngineContext,
   EngineDriver,
   EngineEvent,
+  Logger,
   UserMessage,
 } from "@computeragent/protocol";
+import { nopLogger } from "@computeragent/protocol";
 
 const CAPABILITIES: EngineCapabilities = {
   streamingInput: true,
@@ -52,6 +54,7 @@ export class DeepAgentsEngine implements EngineDriver<DeepAgentsOptions> {
   async *startSession(
     ctx: EngineContext<DeepAgentsOptions>,
   ): AsyncIterable<EngineEvent> {
+    const log = ctx.logger ?? nopLogger;
     // Lazy import — deepagents pulls in a heavy LangChain dep tree (~150MB).
     // Loading it inside startSession means importers of @computeragent/engine-deepagents
     // only pay the cost when the engine actually runs.
@@ -97,12 +100,26 @@ export class DeepAgentsEngine implements EngineDriver<DeepAgentsOptions> {
       ...(ctx.options.systemPrompt ? { systemPrompt: ctx.options.systemPrompt } : {}),
     });
 
+    log.info("engine.start", {
+      engine: "deepagents",
+      sessionId: ctx.sessionId,
+      model: stripProviderPrefix(modelName),
+      workdir: ctx.workdir,
+      backend: "local-shell",
+    });
+
     // One outer iteration = one user message = one fresh stream call.
     // The checkpointer + threadId carry conversation state across turns.
     for await (const userMsg of ctx.userMessageQueue) {
       if (ctx.abortSignal.aborted) break;
 
       const userText = flattenContent(userMsg.content);
+      const turnStartedAt = Date.now();
+      log.info("engine.turn.start", {
+        engine: "deepagents",
+        sessionId: ctx.sessionId,
+        userTextLen: userText.length,
+      });
       const input = { messages: [{ role: "user" as const, content: userText }] };
       const config = {
         configurable: { thread_id: threadId },
@@ -111,32 +128,52 @@ export class DeepAgentsEngine implements EngineDriver<DeepAgentsOptions> {
 
       let lastUsage: { input_tokens?: number; output_tokens?: number } | undefined;
       let finalText = "";
+      let priorMsgCount = 0;
+
+      try {
+        // Stream LangGraph events in "values" mode — emits the full state on each
+        // step. We forward every chunk so downstream tools can inspect the state.
+        const stream = await agent.stream(input, { ...config, streamMode: "values" });
+        for await (const chunk of stream as AsyncIterable<unknown>) {
+          if (ctx.abortSignal.aborted) break;
+          yield { kind: "sdk_message", payload: chunk };
 
-      // Stream LangGraph events in "values" mode — emits the full state on each
-      // step. We forward every chunk so downstream tools can inspect the state.
-      const stream = await agent.stream(input, { ...config, streamMode: "values" });
-      for await (const chunk of stream as AsyncIterable<unknown>) {
-        if (ctx.abortSignal.aborted) break;
-        yield { kind: "sdk_message", payload: chunk };
-
-        // Inspect the latest message for usage metadata + assistant text.
-        const messages = extractMessagesFromChunk(chunk);
-        const last = messages[messages.length - 1];
-        if (last) {
-          if (typeof last.content === "string" && last.content.trim()) {
-            finalText = last.content;
-          } else if (Array.isArray(last.content)) {
-            const textParts = last.content
-              .filter((b): b is { type: "text"; text: string } => (b as { type?: string }).type === "text")
-              .map((b) => b.text);
-            if (textParts.length > 0) finalText = textParts.join("");
+          // Inspect the latest message for usage metadata + assistant text.
+          const messages = extractMessagesFromChunk(chunk);
+          // Log only NEW messages per chunk so each tool_use/tool_result lands once.
+          const newMsgs = messages.slice(priorMsgCount);
+          priorMsgCount = messages.length;
+          for (const m of newMsgs) logDeepAgentMessage(log, ctx.sessionId, m);
+
+          const last = messages[messages.length - 1];
+          if (last) {
+            if (typeof last.content === "string" && last.content.trim()) {
+              finalText = last.content;
+            } else if (Array.isArray(last.content)) {
+              const textParts = last.content
+                .filter((b): b is { type: "text"; text: string } => (b as { type?: string }).type === "text")
+                .map((b) => b.text);
+              if (textParts.length > 0) finalText = textParts.join("");
+            }
+            if (last.usage_metadata) lastUsage = last.usage_metadata;
           }
-          if (last.usage_metadata) lastUsage = last.usage_metadata;
         }
+      } catch (err) {
+        log.error("engine.error", {
+          engine: "deepagents",
+          sessionId: ctx.sessionId,
+          error: err instanceof Error ? err.message : String(err),
+        });
+        throw err;
       }
 
       // Emit usage snapshot BEFORE the result terminator (per issue #2 ordering).
       if (lastUsage && (lastUsage.input_tokens !== undefined || lastUsage.output_tokens !== undefined)) {
+        log.debug("engine.usage", {
+          sessionId: ctx.sessionId,
+          inputTokens: lastUsage.input_tokens,
+          outputTokens: lastUsage.output_tokens,
+        });
         yield {
           kind: "ca_usage_snapshot",
           ...(lastUsage.input_tokens !== undefined ? { inputTokens: lastUsage.input_tokens } : {}),
@@ -158,6 +195,46 @@ export class DeepAgentsEngine implements EngineDriver<DeepAgentsOptions> {
           ...(lastUsage ? { usage: lastUsage } : {}),
         },
       };
+      log.info("engine.turn.end", {
+        engine: "deepagents",
+        sessionId: ctx.sessionId,
+        durationMs: Date.now() - turnStartedAt,
+        finalTextLen: finalText.length,
+      });
+    }
+  }
+}
+
+/**
+ * Pure log emission for a single LangChain BaseMessage (already destructured
+ * from a `messages[]` array). LangChain messages expose `_getType()` for role
+ * and `tool_calls` (when assistant chose to call tools).
+ */
+function logDeepAgentMessage(
+  log: Logger,
+  sessionId: string,
+  msg: { content?: unknown; _getType?: () => string; tool_calls?: Array<{ name: string; id?: string }>; name?: string; tool_call_id?: string },
+): void {
+  const role = typeof msg._getType === "function" ? msg._getType() : "?";
+  if (msg.tool_calls && msg.tool_calls.length > 0) {
+    for (const tc of msg.tool_calls) {
+      log.debug("engine.tool_use", { sessionId, name: tc.name, callId: tc.id });
+    }
+    return;
+  }
+  if (role === "tool") {
+    const bytes = typeof msg.content === "string" ? msg.content.length : JSON.stringify(msg.content ?? "").length;
+    log.debug("engine.tool_result", { sessionId, name: msg.name, callId: msg.tool_call_id, bytes });
+    return;
+  }
+  if (role === "ai" || role === "assistant") {
+    if (typeof msg.content === "string" && msg.content.trim()) {
+      log.debug("engine.assistant_text", { sessionId, textLen: msg.content.length });
+    } else if (Array.isArray(msg.content)) {
+      const textLen = msg.content
+        .filter((b): b is { type: string; text: string } => (b as { type?: string }).type === "text")
+        .reduce((n, b) => n + (b.text?.length ?? 0), 0);
+      if (textLen > 0) log.debug("engine.assistant_text", { sessionId, textLen });
     }
   }
 }