summaryrefslogtreecommitdiffhomepage
diff options
context:
space:
mode:
authorAdam Malczewski <[email protected]>2026-06-06 22:52:48 +0900
committerAdam Malczewski <[email protected]>2026-06-06 22:52:48 +0900
commit3e95b26ee2928c40db581bed4c138d3fa842b753 (patch)
treef9500ab4d75934fb6c0a3863db4c63b29e1b4444
parent219cf053fad4e48b22590d3178438bf5d67d04e3 (diff)
downloaddispatch-3e95b26ee2928c40db581bed4c138d3fa842b753.tar.gz
dispatch-3e95b26ee2928c40db581bed4c138d3fa842b753.zip
feat(transport-http,transport-ws): structured edge logging (close coverage gap #2)
Both HTTP + WS transport edges now emit structured logs via the injected logger (D7-compliant: no per-AgentEvent/chat.delta frame logging). Verified live — the journal contains the edge records. - transport-ws: connection open/close (debug), chat.send accepted (info), surface-op + malformed-chat.send (warn), abort-on-close (debug). +4 bun tests. Correctly scoped extensionId=transport-ws (owns its Bun.serve). - transport-http: /chat accepted (info) / 400 (warn) / turn-failure (error), GET /conversations read (info), /models + store failure (error). +4 vitest. Known follow-up: transport-http edge logs are attributed to '__host__' (not 'transport-http') because host-bin runs the HTTP server via createServer(getHostAPI()) rather than the extension owning its Bun.serve. Logs are captured + correlated; only the per-extension filter is mis-scoped. Tracked in tasks.md. typecheck clean, 498 vitest + 84 bun, biome clean.
-rw-r--r--packages/transport-http/src/app.test.ts150
-rw-r--r--packages/transport-http/src/app.ts62
-rw-r--r--packages/transport-http/src/extension.ts2
-rw-r--r--packages/transport-ws/src/extension.ts35
-rw-r--r--packages/transport-ws/src/server.bun.test.ts213
-rw-r--r--tasks.md23
6 files changed, 469 insertions, 16 deletions
diff --git a/packages/transport-http/src/app.test.ts b/packages/transport-http/src/app.test.ts
index f4707bc..2adf4db 100644
--- a/packages/transport-http/src/app.test.ts
+++ b/packages/transport-http/src/app.test.ts
@@ -1,8 +1,50 @@
-import type { AgentEvent, StoredChunk } from "@dispatch/kernel";
+import type { AgentEvent, Logger, StoredChunk } from "@dispatch/kernel";
import { describe, expect, it } from "vitest";
import { createApp } from "./app.js";
import type { ConversationStore, CredentialStore, SessionOrchestrator } from "./seam.js";
+interface CapturedLog {
+ readonly level: "debug" | "info" | "warn" | "error";
+ readonly msg: string;
+ readonly attrs?: Record<string, unknown>;
+}
+
+function createFakeLogger(): Logger & { readonly records: readonly CapturedLog[] } {
+ const records: CapturedLog[] = [];
+ return {
+ get records() {
+ return records;
+ },
+ debug(msg, attrs) {
+ records.push({ level: "debug", msg, ...(attrs ? { attrs } : {}) });
+ },
+ info(msg, attrs) {
+ records.push({ level: "info", msg, ...(attrs ? { attrs } : {}) });
+ },
+ warn(msg, attrs) {
+ records.push({ level: "warn", msg, ...(attrs ? { attrs } : {}) });
+ },
+ error(msg, attrs) {
+ records.push({ level: "error", msg, ...(attrs ? { attrs } : {}) });
+ },
+ child() {
+ return createFakeLogger();
+ },
+ span() {
+ return {
+ id: "fake-span",
+ log: createFakeLogger(),
+ setAttributes() {},
+ addLink() {},
+ child() {
+ return this;
+ },
+ end() {},
+ };
+ },
+ };
+}
+
function createFakeConversationStore(
store: Map<string, StoredChunk[]> = new Map(),
): ConversationStore {
@@ -75,12 +117,15 @@ function createThrowingCredentialStore(error: Error): CredentialStore {
};
}
+const noopLogger = createFakeLogger();
+
describe("GET /health", () => {
it("returns ok", async () => {
const app = createApp({
conversationStore: createFakeConversationStore(),
orchestrator: createFakeOrchestrator([]),
credentialStore: createFakeCredentialStore([]),
+ logger: noopLogger,
});
const res = await app.request("/health");
expect(res.status).toBe(200);
@@ -95,6 +140,7 @@ describe("GET /models", () => {
conversationStore: createFakeConversationStore(),
orchestrator: createFakeOrchestrator([]),
credentialStore: createFakeCredentialStore(["opencode/m1", "openai/gpt-4"]),
+ logger: noopLogger,
});
const res = await app.request("/models");
expect(res.status).toBe(200);
@@ -107,6 +153,7 @@ describe("GET /models", () => {
conversationStore: createFakeConversationStore(),
orchestrator: createFakeOrchestrator([]),
credentialStore: createFakeCredentialStore([]),
+ logger: noopLogger,
});
const res = await app.request("/models");
expect(res.status).toBe(200);
@@ -119,6 +166,7 @@ describe("GET /models", () => {
conversationStore: createFakeConversationStore(),
orchestrator: createFakeOrchestrator([]),
credentialStore: createThrowingCredentialStore(new Error("db down")),
+ logger: noopLogger,
});
const res = await app.request("/models");
expect(res.status).toBe(502);
@@ -133,6 +181,7 @@ describe("POST /chat", () => {
conversationStore: createFakeConversationStore(),
orchestrator: createFakeOrchestrator([]),
credentialStore: createFakeCredentialStore([]),
+ logger: noopLogger,
});
const res = await app.request("/chat", {
method: "POST",
@@ -415,3 +464,102 @@ describe("GET /conversations/:id", () => {
expect(res.status).toBe(400);
});
});
+
+describe("POST /chat logging", () => {
+ it("POST /chat logs an info line when a request is accepted", async () => {
+ const logger = createFakeLogger();
+ const app = createApp({
+ conversationStore: createFakeConversationStore(),
+ orchestrator: createFakeOrchestrator([
+ { type: "done", conversationId: "conv1", turnId: "turn1", reason: "stop" },
+ ]),
+ credentialStore: createFakeCredentialStore([]),
+ logger,
+ });
+
+ await app.request("/chat", {
+ method: "POST",
+ headers: { "Content-Type": "application/json" },
+ body: JSON.stringify({
+ message: "hi",
+ conversationId: "conv1",
+ model: "opencode/m1",
+ cwd: "/tmp",
+ }),
+ });
+
+ const infoLogs = logger.records.filter((r) => r.level === "info");
+ expect(infoLogs).toHaveLength(1);
+ expect(infoLogs[0]?.msg).toBe("chat: request accepted");
+ expect(infoLogs[0]?.attrs?.conversationId).toBe("conv1");
+ expect(infoLogs[0]?.attrs?.hasModel).toBe(true);
+ expect(infoLogs[0]?.attrs?.hasCwd).toBe(true);
+ });
+
+ it("POST /chat logs a warn on a malformed body (400)", async () => {
+ const logger = createFakeLogger();
+ const app = createApp({
+ conversationStore: createFakeConversationStore(),
+ orchestrator: createFakeOrchestrator([]),
+ credentialStore: createFakeCredentialStore([]),
+ logger,
+ });
+
+ await app.request("/chat", {
+ method: "POST",
+ headers: { "Content-Type": "application/json" },
+ body: "not json",
+ });
+
+ const warnLogs = logger.records.filter((r) => r.level === "warn");
+ expect(warnLogs.length).toBeGreaterThanOrEqual(1);
+ expect(warnLogs[0]?.msg).toBe("chat: invalid JSON body");
+ });
+
+ it("POST /chat logs an error when the turn fails", async () => {
+ const logger = createFakeLogger();
+ const app = createApp({
+ conversationStore: createFakeConversationStore(),
+ orchestrator: createThrowingOrchestrator(new Error("boom")),
+ credentialStore: createFakeCredentialStore([]),
+ logger,
+ });
+
+ await app.request("/chat", {
+ method: "POST",
+ headers: { "Content-Type": "application/json" },
+ body: JSON.stringify({ message: "hi", conversationId: "conv1" }),
+ });
+
+ const errorLogs = logger.records.filter((r) => r.level === "error");
+ expect(errorLogs).toHaveLength(1);
+ expect(errorLogs[0]?.msg).toBe("chat: turn failed");
+ expect(errorLogs[0]?.attrs?.err).toBeInstanceOf(Error);
+ });
+});
+
+describe("GET /conversations/:id logging", () => {
+ it("GET /conversations/:id logs the read (conversationId + sinceSeq + count)", async () => {
+ const logger = createFakeLogger();
+ const sampleChunks: StoredChunk[] = [
+ { seq: 1, role: "user", chunk: { type: "text", text: "hello" } },
+ { seq: 2, role: "assistant", chunk: { type: "text", text: "hi there" } },
+ ];
+ const store = new Map<string, StoredChunk[]>([["conv1", sampleChunks]]);
+ const app = createApp({
+ conversationStore: createFakeConversationStore(store),
+ orchestrator: createFakeOrchestrator([]),
+ credentialStore: createFakeCredentialStore([]),
+ logger,
+ });
+
+ await app.request("/conversations/conv1?sinceSeq=0");
+
+ const infoLogs = logger.records.filter((r) => r.level === "info");
+ expect(infoLogs).toHaveLength(1);
+ expect(infoLogs[0]?.msg).toBe("conversations: read");
+ expect(infoLogs[0]?.attrs?.conversationId).toBe("conv1");
+ expect(infoLogs[0]?.attrs?.sinceSeq).toBe(0);
+ expect(infoLogs[0]?.attrs?.count).toBe(2);
+ });
+});
diff --git a/packages/transport-http/src/app.ts b/packages/transport-http/src/app.ts
index 5f63683..bd9db4e 100644
--- a/packages/transport-http/src/app.ts
+++ b/packages/transport-http/src/app.ts
@@ -1,4 +1,4 @@
-import type { AgentEvent } from "@dispatch/kernel";
+import type { AgentEvent, Logger } from "@dispatch/kernel";
import type { ConversationHistoryResponse, ModelsResponse } from "@dispatch/transport-contract";
import { Hono } from "hono";
import {
@@ -14,11 +14,35 @@ export interface CreateServerOptions {
readonly conversationStore: ConversationStore;
readonly orchestrator: SessionOrchestrator;
readonly credentialStore: CredentialStore;
+ readonly logger?: Logger;
readonly generateId?: () => string;
}
+const noopLogger: Logger = {
+ debug() {},
+ info() {},
+ warn() {},
+ error() {},
+ child() {
+ return noopLogger;
+ },
+ span() {
+ return {
+ id: "noop-span",
+ log: noopLogger,
+ setAttributes() {},
+ addLink() {},
+ child() {
+ return this;
+ },
+ end() {},
+ };
+ },
+};
+
export function createApp(opts: CreateServerOptions): Hono {
const app = new Hono();
+ const log = opts.logger ?? noopLogger;
const generateId = opts.generateId ?? (() => crypto.randomUUID());
app.get("/health", (c) => c.json({ ok: true }));
@@ -27,14 +51,28 @@ export function createApp(opts: CreateServerOptions): Hono {
const conversationId = c.req.param("id");
const sinceSeqResult = parseSinceSeq(c.req.query("sinceSeq"));
if (isSinceSeqError(sinceSeqResult)) {
+ log.warn("conversations: invalid sinceSeq", {
+ conversationId,
+ error: sinceSeqResult.error,
+ });
return c.json({ error: sinceSeqResult.error }, 400);
}
- const chunks = await opts.conversationStore.loadSince(conversationId, sinceSeqResult);
- const latestSeq =
- chunks.length > 0 ? (chunks[chunks.length - 1]?.seq ?? sinceSeqResult) : sinceSeqResult;
- const body: ConversationHistoryResponse = { chunks, latestSeq };
- return c.json(body, 200);
+ try {
+ const chunks = await opts.conversationStore.loadSince(conversationId, sinceSeqResult);
+ const latestSeq =
+ chunks.length > 0 ? (chunks[chunks.length - 1]?.seq ?? sinceSeqResult) : sinceSeqResult;
+ log.info("conversations: read", {
+ conversationId,
+ sinceSeq: sinceSeqResult,
+ count: chunks.length,
+ });
+ const body: ConversationHistoryResponse = { chunks, latestSeq };
+ return c.json(body, 200);
+ } catch (err) {
+ log.error("conversations: store failure", { err });
+ return c.json({ error: "Failed to load conversation" }, 500);
+ }
});
app.get("/models", async (c) => {
@@ -42,7 +80,8 @@ export function createApp(opts: CreateServerOptions): Hono {
const models = await opts.credentialStore.listCatalog();
const body: ModelsResponse = { models };
return c.json(body, 200);
- } catch {
+ } catch (err) {
+ log.error("models: failed to retrieve catalog", { err });
return c.json({ error: "Failed to retrieve model catalog" }, 502);
}
});
@@ -52,15 +91,23 @@ export function createApp(opts: CreateServerOptions): Hono {
try {
body = await c.req.json();
} catch {
+ log.warn("chat: invalid JSON body");
return c.json({ error: "Invalid JSON body" }, 400);
}
const result = parseChatBody(body, generateId);
if (isParseError(result)) {
+ log.warn("chat: validation failed", { reason: result.error });
return c.json({ error: result.error }, 400);
}
const { conversationId, message, model, cwd } = result;
+ log.info("chat: request accepted", {
+ conversationId,
+ hasModel: model !== undefined,
+ hasCwd: cwd !== undefined,
+ });
+
const events: AgentEvent[] = [];
let resolveStream: () => void;
const streamReady = new Promise<void>((resolve) => {
@@ -83,6 +130,7 @@ export function createApp(opts: CreateServerOptions): Hono {
resolveStream();
})
.catch((err) => {
+ log.error("chat: turn failed", { err });
events.push({
type: "error",
conversationId,
diff --git a/packages/transport-http/src/extension.ts b/packages/transport-http/src/extension.ts
index ba45f9d..dda722e 100644
--- a/packages/transport-http/src/extension.ts
+++ b/packages/transport-http/src/extension.ts
@@ -27,7 +27,7 @@ export function createServer(host: HostAPI, _opts?: CreateServerOptions): Hono {
const conversationStore = host.getService(conversationStoreHandle);
const orchestrator = host.getService(sessionOrchestratorHandle);
const credentialStore = host.getService(credentialStoreHandle);
- return createApp({ conversationStore, orchestrator, credentialStore });
+ return createApp({ conversationStore, orchestrator, credentialStore, logger: host.logger });
}
export const extension: Extension = {
diff --git a/packages/transport-ws/src/extension.ts b/packages/transport-ws/src/extension.ts
index ddcb045..0f1a397 100644
--- a/packages/transport-ws/src/extension.ts
+++ b/packages/transport-ws/src/extension.ts
@@ -126,6 +126,7 @@ export function createTransportWsExtension(): Extension {
},
websocket: {
open(ws) {
+ logger.debug("transport-ws: connection open");
send(ws, catalogMessage(registry));
},
@@ -145,6 +146,16 @@ export function createTransportWsExtension(): Extension {
switch (result.kind) {
case "surface": {
+ // Log surface-op errors (unknown surface or invoke failure).
+ for (const reply of result.replies) {
+ if (reply.type === "error") {
+ logger.warn?.("transport-ws: surface-op error", {
+ ...(reply.surfaceId !== undefined ? { surfaceId: reply.surfaceId } : {}),
+ reason: reply.message,
+ });
+ }
+ }
+
// Apply sub change.
if (result.subChange) {
if (result.subChange.op === "add") {
@@ -173,8 +184,13 @@ export function createTransportWsExtension(): Extension {
if (r instanceof Promise) {
r.catch(() => {});
}
- } catch {
- // Provider threw on invoke — log but don't kill the connection.
+ } catch (err: unknown) {
+ const reason = err instanceof Error ? err.message : "invoke failed";
+ logger.warn?.("transport-ws: surface-op error", {
+ surfaceId: result.invoke.surfaceId,
+ actionId: result.invoke.actionId,
+ reason,
+ });
}
}
}
@@ -183,6 +199,11 @@ export function createTransportWsExtension(): Extension {
case "chat": {
// Fire-and-forget the turn; errors are caught inside handleChatTurn.
+ const resolvedId = result.conversationId ?? crypto.randomUUID();
+ logger.info?.("transport-ws: chat.send accepted", {
+ conversationId: resolvedId,
+ model: result.model ?? null,
+ });
void handleChatTurn(
ws,
state,
@@ -195,6 +216,12 @@ export function createTransportWsExtension(): Extension {
}
case "chat-error": {
+ logger.warn?.("transport-ws: malformed chat.send", {
+ reason: result.errorMessage,
+ ...(result.conversationId !== undefined
+ ? { conversationId: result.conversationId }
+ : {}),
+ });
send(ws, {
type: "chat.error",
...(result.conversationId !== undefined
@@ -211,11 +238,15 @@ export function createTransportWsExtension(): Extension {
const state = ws.data;
if (state) {
// Abort any in-flight chat turns.
+ if (!state.abortController.signal.aborted) {
+ logger.debug("transport-ws: in-flight turn aborted (socket closed)");
+ }
state.abortController.abort();
for (const dispose of state.providerDisposers.values()) {
dispose();
}
}
+ logger.debug("transport-ws: connection close");
},
},
});
diff --git a/packages/transport-ws/src/server.bun.test.ts b/packages/transport-ws/src/server.bun.test.ts
index 8c16f72..ea9d80c 100644
--- a/packages/transport-ws/src/server.bun.test.ts
+++ b/packages/transport-ws/src/server.bun.test.ts
@@ -1,11 +1,53 @@
import { afterEach, beforeEach, describe, expect, test } from "bun:test";
-import type { AgentEvent } from "@dispatch/kernel";
+import type { AgentEvent, Attributes, ErrorAttributes, Logger } from "@dispatch/kernel";
import type { SessionOrchestrator } from "@dispatch/session-orchestrator";
import type { SurfaceProvider, SurfaceRegistry } from "@dispatch/surface-registry";
import type { WsServerMessage } from "@dispatch/transport-contract";
import type { SurfaceCatalogEntry, SurfaceClientMessage, SurfaceSpec } from "@dispatch/ui-contract";
import { catalogMessage, routeClientMessage } from "./router.js";
+// ── Fake Logger (captures records for assertions) ───────────────────────────
+
+interface LogEntry {
+ readonly level: "debug" | "info" | "warn" | "error";
+ readonly msg: string;
+ readonly attrs?: Attributes | ErrorAttributes;
+}
+
+function fakeLogger(): Logger & { readonly entries: readonly LogEntry[] } {
+ const entries: LogEntry[] = [];
+ return {
+ entries,
+ debug(msg, attrs) {
+ entries.push({ level: "debug", msg, ...(attrs !== undefined ? { attrs } : {}) });
+ },
+ info(msg, attrs) {
+ entries.push({ level: "info", msg, ...(attrs !== undefined ? { attrs } : {}) });
+ },
+ warn(msg, attrs) {
+ entries.push({ level: "warn", msg, ...(attrs !== undefined ? { attrs } : {}) });
+ },
+ error(msg, attrs) {
+ entries.push({ level: "error", msg, ...(attrs !== undefined ? { attrs } : {}) });
+ },
+ child() {
+ return fakeLogger();
+ },
+ span() {
+ return {
+ id: "fake-span",
+ log: fakeLogger(),
+ setAttributes() {},
+ addLink() {},
+ child() {
+ return this;
+ },
+ end() {},
+ };
+ },
+ };
+}
+
// ── Fake registry (same pattern as router.test.ts) ──────────────────────────
function fakeProvider(id: string, title?: string): SurfaceProvider {
@@ -59,7 +101,13 @@ interface ConnectionState {
// ── Server helper ───────────────────────────────────────────────────────────
-function startServer(registry: SurfaceRegistry, orchestrator: SessionOrchestrator, port = 0) {
+function startServer(
+ registry: SurfaceRegistry,
+ orchestrator: SessionOrchestrator,
+ port = 0,
+ logger?: Logger,
+) {
+ const log = logger ?? fakeLogger();
return Bun.serve<ConnectionState>({
port,
fetch(req, srv) {
@@ -73,6 +121,7 @@ function startServer(registry: SurfaceRegistry, orchestrator: SessionOrchestrato
},
websocket: {
open(ws) {
+ log.debug("transport-ws: connection open");
ws.send(JSON.stringify(catalogMessage(registry)));
},
@@ -92,6 +141,15 @@ function startServer(registry: SurfaceRegistry, orchestrator: SessionOrchestrato
switch (result.kind) {
case "surface": {
+ for (const reply of result.replies) {
+ if (reply.type === "error") {
+ log.warn?.("transport-ws: surface-op error", {
+ ...(reply.surfaceId !== undefined ? { surfaceId: reply.surfaceId } : {}),
+ reason: reply.message,
+ });
+ }
+ }
+
if (result.subChange) {
if (result.subChange.op === "add") {
state.subs.add(result.subChange.surfaceId);
@@ -108,6 +166,10 @@ function startServer(registry: SurfaceRegistry, orchestrator: SessionOrchestrato
case "chat": {
const resolvedId = result.conversationId ?? crypto.randomUUID();
+ log.info?.("transport-ws: chat.send accepted", {
+ conversationId: resolvedId,
+ model: result.model ?? null,
+ });
void (async () => {
try {
await orchestrator.handleMessage({
@@ -129,12 +191,22 @@ function startServer(registry: SurfaceRegistry, orchestrator: SessionOrchestrato
message,
}),
);
+ log.warn?.("transport-ws: chat turn failed", {
+ conversationId: resolvedId,
+ error: message,
+ });
}
})();
break;
}
case "chat-error": {
+ log.warn?.("transport-ws: malformed chat.send", {
+ reason: result.errorMessage,
+ ...(result.conversationId !== undefined
+ ? { conversationId: result.conversationId }
+ : {}),
+ });
ws.send(
JSON.stringify({
type: "chat.error",
@@ -150,11 +222,15 @@ function startServer(registry: SurfaceRegistry, orchestrator: SessionOrchestrato
close(ws) {
const state = ws.data;
if (state) {
+ if (!state.abortController.signal.aborted) {
+ log.debug("transport-ws: in-flight turn aborted (socket closed)");
+ }
state.abortController.abort();
for (const dispose of state.providerDisposers.values()) {
dispose();
}
}
+ log.debug("transport-ws: connection close");
},
},
});
@@ -361,3 +437,136 @@ describe("chat ops", () => {
ws.close();
});
});
+
+describe("logging", () => {
+ let server: ReturnType<typeof Bun.serve>;
+ let port: number;
+
+ afterEach(() => {
+ server.stop();
+ });
+
+ test("logs a warn on a surface-op error", async () => {
+ const logger = fakeLogger();
+ const registry = fakeRegistry([]);
+ server = startServer(registry, fakeOrchestrator(), 0, logger);
+ port = server.port as number;
+
+ const ws = new WebSocket(`ws://localhost:${port}`);
+ await waitForMessage(ws); // drain catalog
+
+ ws.send(JSON.stringify({ type: "subscribe", surfaceId: "nonexistent" }));
+ await waitForMessage(ws); // drain error reply
+ ws.close();
+ // Allow close handler to run
+ await new Promise((r) => setTimeout(r, 50));
+
+ const surfaceErrors = logger.entries.filter(
+ (e) => e.level === "warn" && e.msg === "transport-ws: surface-op error",
+ );
+ expect(surfaceErrors.length).toBeGreaterThanOrEqual(1);
+ expect(surfaceErrors[0]?.attrs).toMatchObject({
+ surfaceId: "nonexistent",
+ reason: "Unknown surface: nonexistent",
+ });
+ });
+
+ test("logs an info when a chat.send is accepted", async () => {
+ const logger = fakeLogger();
+ const orchestrator = fakeOrchestrator(async () => {});
+ const registry = fakeRegistry([]);
+ server = startServer(registry, orchestrator, 0, logger);
+ port = server.port as number;
+
+ const ws = new WebSocket(`ws://localhost:${port}`);
+ await waitForMessage(ws); // drain catalog
+
+ ws.send(
+ JSON.stringify({
+ type: "chat.send",
+ conversationId: "conv-42",
+ message: "hello",
+ model: "gpt-4",
+ }),
+ );
+ // Wait for the async turn to complete
+ await new Promise((r) => setTimeout(r, 100));
+ ws.close();
+ await new Promise((r) => setTimeout(r, 50));
+
+ const accepted = logger.entries.filter(
+ (e) => e.level === "info" && e.msg === "transport-ws: chat.send accepted",
+ );
+ expect(accepted).toHaveLength(1);
+ expect(accepted[0]?.attrs).toMatchObject({
+ conversationId: "conv-42",
+ model: "gpt-4",
+ });
+ });
+
+ test("logs a warn on a malformed chat.send", async () => {
+ const logger = fakeLogger();
+ const registry = fakeRegistry([]);
+ server = startServer(registry, fakeOrchestrator(), 0, logger);
+ port = server.port as number;
+
+ const ws = new WebSocket(`ws://localhost:${port}`);
+ await waitForMessage(ws); // drain catalog
+
+ ws.send(JSON.stringify({ type: "chat.send", message: "" }));
+ await waitForMessage(ws); // drain chat.error reply
+ ws.close();
+ await new Promise((r) => setTimeout(r, 50));
+
+ const malformed = logger.entries.filter(
+ (e) => e.level === "warn" && e.msg === "transport-ws: malformed chat.send",
+ );
+ expect(malformed).toHaveLength(1);
+ expect(malformed[0]?.attrs).toMatchObject({
+ reason: "chat.send requires a non-empty string `message`",
+ });
+ });
+
+ test("does not log a line per chat.delta frame", async () => {
+ const logger = fakeLogger();
+ const events: AgentEvent[] = [
+ { type: "turn-start", conversationId: "c1", turnId: "t1" } as AgentEvent,
+ { type: "text-delta", conversationId: "c1", turnId: "t1", delta: "H" } as AgentEvent,
+ { type: "text-delta", conversationId: "c1", turnId: "t1", delta: "e" } as AgentEvent,
+ { type: "text-delta", conversationId: "c1", turnId: "t1", delta: "l" } as AgentEvent,
+ { type: "text-delta", conversationId: "c1", turnId: "t1", delta: "l" } as AgentEvent,
+ { type: "text-delta", conversationId: "c1", turnId: "t1", delta: "o" } as AgentEvent,
+ { type: "done", conversationId: "c1", turnId: "t1" } as AgentEvent,
+ { type: "turn-sealed", conversationId: "c1", turnId: "t1" } as AgentEvent,
+ ];
+
+ const orchestrator = fakeOrchestrator(async (input) => {
+ for (const event of events) {
+ input.onEvent(event);
+ }
+ });
+
+ const registry = fakeRegistry([]);
+ server = startServer(registry, orchestrator, 0, logger);
+ port = server.port as number;
+
+ const ws = new WebSocket(`ws://localhost:${port}`);
+ await waitForMessage(ws); // drain catalog
+
+ ws.send(JSON.stringify({ type: "chat.send", message: "hello" }));
+ await waitForMessages(ws, events.length);
+ ws.close();
+ await new Promise((r) => setTimeout(r, 50));
+
+ // Should only have: debug(open) + info(accepted) + debug(abort) + debug(close) = 4
+ // NOT one log line per delta frame
+ const chatDeltaLogs = logger.entries.filter(
+ (e) => e.msg.includes("chat.delta") || e.msg.includes("text-delta"),
+ );
+ expect(chatDeltaLogs).toHaveLength(0);
+
+ // Total log lines should be small (open + accepted + close, maybe abort)
+ const chatRelated = logger.entries.filter((e) => e.msg.startsWith("transport-ws:"));
+ expect(chatRelated.length).toBeLessThanOrEqual(5);
+ });
+});
diff --git a/tasks.md b/tasks.md
index 5e10126..e78310c 100644
--- a/tasks.md
+++ b/tasks.md
@@ -299,9 +299,26 @@ But a survey found per-extension/edge coverage thin, and a HARNESS gap as the ro
repair (the §3.4 / bug-catalog "API rejected corrupted history" class) leaves NO trace. Inject a
logger + emit a `reconcile.repair` span. Address when conversation-store is next touched (or as
a dedicated pass).
-- [ ] **#2 INSTRUMENTATION DEBT — transport edges.** transport-http has 0 logger refs (a `/chat`
- 500 / malformed request / the new `GET /conversations` read is invisible); transport-ws logs
- minimally. Add request/error logging at the edges.
+- [x] **#2 DONE — transport-edge logging.** Both edges now emit structured logs via the injected
+ logger (D7-compliant: NO per-`AgentEvent`/`chat.delta` frame logging). **Verified live** — the
+ journal contains the edge records (`{level:info, msg:"conversations: read", attrs:{conversationId,
+ sinceSeq, count}}`, `{level:warn, msg:"chat: validation failed"}`, etc.).
+ - **transport-ws (owner):** +5 log points (connection open/close debug, chat.send accepted info,
+ surface-op + malformed-chat.send warn, abort-on-close debug); +4 bun tests. Correctly attributed
+ `extensionId: transport-ws` (it runs its own `Bun.serve` in `activate` → extension-scoped logger).
+ - **transport-http (owner):** info on accepted `/chat`, warn on 400, error on turn failure, info
+ on `GET /conversations` read, error on `/models`/store failure; +4 vitest tests. (First summon
+ left the build broken — made `logger` required but missed call sites + biome; re-summoned to
+ finish. Trust = independent re-verify.)
+ - **Verified:** typecheck clean, **498 vitest** (+4) + **84 bun** (+4), biome clean, no internal mocks.
+ - **CAVEAT / follow-up (architectural attribution):** transport-http's edge logs land in the journal
+ but are stamped `extensionId: "__host__"`, NOT `transport-http` — because transport-http has no
+ `Bun.serve`; it exports `createServer(host: HostAPI)` which **host-bin** calls with the
+ `__host__`-scoped `getHostAPI()` (`host.ts:224`). transport-ws is correct because it owns its
+ server. Clean fix = make transport-http own its `Bun.serve` in `activate` (full-fidelity, symmetric
+ with transport-ws) so it logs under its extension scope — a boundary/refactor decision (touches
+ host-bin), surfaced to the user. The logs ARE captured + correlated (conversationId); only the
+ per-extension `extensionId` filter is currently mis-scoped.
- D8 `prompt.assembly` segments remain deferred-by-design (await the context-filter chain).
---