diff --git a/src/routes/chatStream.ts b/src/routes/chatStream.ts index e31c6c5..60adf6c 100644 --- a/src/routes/chatStream.ts +++ b/src/routes/chatStream.ts @@ -318,6 +318,11 @@ export const streamPromptResponse = async ({ const reasoningDeltas = new Map(); const reasoningStatuses = new Map(); const toolStatuses = new Map(); + let firstSessionEventLogged = false; + let firstNonStatusEventLogged = false; + let firstTokenLogged = false; + let firstReasoningLogged = false; + let firstToolEventLogged = false; let lastSessionStatus: string | null = null; let lastSessionStatusMessage: string | null = null; let emittedText = false; @@ -470,6 +475,16 @@ export const streamPromptResponse = async ({ continue; } + if (!firstSessionEventLogged) { + firstSessionEventLogged = true; + logDevelopmentDebug("first session event received", { + ...debugContext, + eventType: event.type, + elapsedMs: Math.max(0, Date.now() - requestStartedAt), + sincePromptDispatchMs: Math.max(0, Date.now() - promptStartedAt), + }); + } + if (event.type === "session.status") { const nextStatus = event.properties.status.type; const nextStatusMessage = @@ -505,6 +520,16 @@ export const streamPromptResponse = async ({ continue; } + if (!firstNonStatusEventLogged) { + firstNonStatusEventLogged = true; + logDevelopmentDebug("first non-status session event received", { + ...debugContext, + eventType: event.type, + elapsedMs: Math.max(0, Date.now() - requestStartedAt), + sincePromptDispatchMs: Math.max(0, Date.now() - promptStartedAt), + }); + } + if (isSkillEvent(event)) { const { name, reason, payload } = extractSkillAuditInfo(event); logDevelopmentDebug("skill event received", { @@ -532,12 +557,30 @@ export const streamPromptResponse = async ({ if (event.type === "message.part.delta" && event.properties.field === "text") { const partType = partTypes.get(event.properties.partID); if (partType === "text") { + if (!firstTokenLogged) { + firstTokenLogged = true; + logDevelopmentDebug("first response token emitted", { + ...debugContext, + partId: event.properties.partID, + elapsedMs: Math.max(0, Date.now() - requestStartedAt), + sincePromptDispatchMs: Math.max(0, Date.now() - promptStartedAt), + }); + } emittedText = true; write("token", { session_id: clientSessionId, content: event.properties.delta, }); } else if (partType === "reasoning") { + if (!firstReasoningLogged) { + firstReasoningLogged = true; + logDevelopmentDebug("first reasoning delta received", { + ...debugContext, + partId: event.properties.partID, + elapsedMs: Math.max(0, Date.now() - requestStartedAt), + sincePromptDispatchMs: Math.max(0, Date.now() - promptStartedAt), + }); + } const pending = reasoningDeltas.get(event.properties.partID) ?? []; pending.push(event.properties.delta); reasoningDeltas.set(event.properties.partID, pending); @@ -593,6 +636,17 @@ export const streamPromptResponse = async ({ }); } if (part.type === "tool") { + if (!firstToolEventLogged) { + firstToolEventLogged = true; + logDevelopmentDebug("first tool event received", { + ...debugContext, + partId: part.id, + tool: part.tool, + status: part.state.status, + elapsedMs: Math.max(0, Date.now() - requestStartedAt), + sincePromptDispatchMs: Math.max(0, Date.now() - promptStartedAt), + }); + } const toolParams = normalizeToolParams(part.state.input); const reason = extractRequestReason(toolParams); const isToolFinalState = diff --git a/src/runtime/opencode.ts b/src/runtime/opencode.ts index 087fcc2..0a8c089 100644 --- a/src/runtime/opencode.ts +++ b/src/runtime/opencode.ts @@ -7,6 +7,18 @@ import { import { config } from "../config.js"; import { logger } from "../logger.js"; +const isDevelopmentDebugLoggingEnabled = process.env.NODE_ENV === "development"; + +const logDevelopmentDebug = ( + message: string, + metadata: Record, +) => { + if (!isDevelopmentDebugLoggingEnabled) { + return; + } + logger.info(metadata, message); +}; + export type RuntimeHealth = { healthy: boolean; version: string; @@ -59,11 +71,27 @@ export class OpencodeRuntimeAdapter { async prompt(sessionId: string, text: string, model?: RuntimeModelOverride) { const client = await this.ensureClient(); + const startedAt = Date.now(); + logDevelopmentDebug( + "dispatching opencode session.prompt", + { + sessionId, + model: model ?? null, + textChars: text.length, + }, + ); await client.session.prompt({ sessionID: sessionId, model, parts: [{ type: "text", text }], }); + logDevelopmentDebug( + "opencode session.prompt returned", + { + sessionId, + elapsedMs: Math.max(0, Date.now() - startedAt), + }, + ); } async messages(sessionId: string, limit = 20) {