feat(observability): add debug logging and enhanced metrics

- Add debug logs to all event handlers (session, message, permission, activity)
- Log level now follows opencode --log-level via plugin config hook
- Add 7 new metrics: cache.count (cacheRead/cacheCreation), session.duration,
  message.count, session.token.total, session.cost.total, model.usage, retry.count
- Track per-session totals (tokens, cost, messages) via sessionTotals map
- Record session duration and totals histograms on session.idle
- Increment retry counter on session.status retry events
- Fix cache counter to use occurrence counts (1) with cacheRead/cacheCreation types
- Fix accumulateSessionTotals to use setBoundedMap (immutable update)
- Fix sessionTotals leak: only delete by real sessionID in session.error
- Move accumulateSessionTotals to util.ts to eliminate cross-handler import
- Change sessionTokenGauge/sessionCostGauge from UpDownCounter to Histogram
- Include cache tokens in totalTokens for session gauge accuracy
- Add session.id attribute to modelUsageCounter for join capability
- Redact shell command arguments from debug log (log length only)
- Deduplicate config debug log (unique fields only after info startup log)
- Rename status.message to retryMessage to clarify intent
- Merge duplicate session.idle debug log into single call
- Add tests for all new behaviors (102 total, up from 86)

Author: dialupdisaster

.npmrc

@@ -0,0 +1 @@
+//registry.npmjs.org/:_authToken="${NPM_TOKEN}"

src/handlers/activity.ts

@@ -5,35 +5,47 @@ import type { HandlerContext } from "../types.ts"
 /** Records lines-added and lines-removed metrics for each file in the diff. */
 export function handleSessionDiff(e: EventSessionDiff, ctx: HandlerContext) {
   const sessionID = e.properties.sessionID
+  let totalAdded = 0
+  let totalRemoved = 0
   for (const fileDiff of e.properties.diff) {
     if (fileDiff.additions > 0) {
       ctx.instruments.linesCounter.add(fileDiff.additions, {
         ...ctx.commonAttrs,
         "session.id": sessionID,
         type: "added",
       })
+      totalAdded += fileDiff.additions
     }
     if (fileDiff.deletions > 0) {
       ctx.instruments.linesCounter.add(fileDiff.deletions, {
         ...ctx.commonAttrs,
         "session.id": sessionID,
         type: "removed",
       })
+      totalRemoved += fileDiff.deletions
     }
   }
+  ctx.log("debug", "otel: lines_of_code counter incremented", {
+    sessionID,
+    files: e.properties.diff.length,
+    added: totalAdded,
+    removed: totalRemoved,
+  })
 }
 
 const GIT_COMMIT_RE = /\bgit\s+commit(?![-\w])/
 
 /** Detects `git commit` invocations in bash tool calls and increments the commit counter and emits a `commit` log event. */
 export function handleCommandExecuted(e: EventCommandExecuted, ctx: HandlerContext) {
   if (e.properties.name !== "bash") return
+  ctx.log("debug", "otel: command.executed (bash)", { sessionID: e.properties.sessionID, argumentsLength: e.properties.arguments.length })
   if (!GIT_COMMIT_RE.test(e.properties.arguments)) return
 
   ctx.instruments.commitCounter.add(1, {
     ...ctx.commonAttrs,
     "session.id": e.properties.sessionID,
   })
+  ctx.log("debug", "otel: commit counter incremented", { sessionID: e.properties.sessionID })
   ctx.logger.emit({
     severityNumber: SeverityNumber.INFO,
     severityText: "INFO",

src/handlers/message.ts

@@ -1,7 +1,6 @@
 import { SeverityNumber } from "@opentelemetry/api-logs"
 import type { AssistantMessage, EventMessageUpdated, EventMessagePartUpdated, ToolPart } from "@opencode-ai/sdk"
-import { errorSummary } from "../util.ts"
-import { setBoundedMap } from "../util.ts"
+import { errorSummary, setBoundedMap, accumulateSessionTotals } from "../util.ts"
 import type { HandlerContext } from "../types.ts"
 
 /**
@@ -18,13 +17,38 @@ export function handleMessageUpdated(e: EventMessageUpdated, ctx: HandlerContext
   const duration = assistant.time.completed - assistant.time.created
   const { tokenCounter, costCounter } = ctx.instruments
 
+  const totalTokens = assistant.tokens.input + assistant.tokens.output + assistant.tokens.reasoning
+    + assistant.tokens.cache.read + assistant.tokens.cache.write
   tokenCounter.add(assistant.tokens.input, { ...ctx.commonAttrs, "session.id": sessionID, model: modelID, type: "input" })
   tokenCounter.add(assistant.tokens.output, { ...ctx.commonAttrs, "session.id": sessionID, model: modelID, type: "output" })
   tokenCounter.add(assistant.tokens.reasoning, { ...ctx.commonAttrs, "session.id": sessionID, model: modelID, type: "reasoning" })
   tokenCounter.add(assistant.tokens.cache.read, { ...ctx.commonAttrs, "session.id": sessionID, model: modelID, type: "cacheRead" })
   tokenCounter.add(assistant.tokens.cache.write, { ...ctx.commonAttrs, "session.id": sessionID, model: modelID, type: "cacheCreation" })
   costCounter.add(assistant.cost, { ...ctx.commonAttrs, "session.id": sessionID, model: modelID })
 
+  if (assistant.tokens.cache.read > 0) {
+    ctx.instruments.cacheCounter.add(1, { ...ctx.commonAttrs, "session.id": sessionID, model: modelID, type: "cacheRead" })
+  }
+  if (assistant.tokens.cache.write > 0) {
+    ctx.instruments.cacheCounter.add(1, { ...ctx.commonAttrs, "session.id": sessionID, model: modelID, type: "cacheCreation" })
+  }
+
+  ctx.instruments.messageCounter.add(1, { ...ctx.commonAttrs, "session.id": sessionID, model: modelID })
+  ctx.instruments.modelUsageCounter.add(1, { ...ctx.commonAttrs, "session.id": sessionID, model: modelID, provider: providerID })
+
+  accumulateSessionTotals(sessionID, totalTokens, assistant.cost, ctx)
+
+  ctx.log("debug", "otel: token+cost counters incremented", {
+    sessionID,
+    model: modelID,
+    input: assistant.tokens.input,
+    output: assistant.tokens.output,
+    reasoning: assistant.tokens.reasoning,
+    cacheRead: assistant.tokens.cache.read,
+    cacheWrite: assistant.tokens.cache.write,
+    cost_usd: assistant.cost,
+  })
+
   if (assistant.error) {
     ctx.logger.emit({
       severityNumber: SeverityNumber.ERROR,
@@ -98,6 +122,7 @@ export function handleMessagePartUpdated(e: EventMessagePartUpdated, ctx: Handle
       sessionID: toolPart.sessionID,
       startMs: toolPart.state.time.start,
     })
+    ctx.log("debug", "otel: tool span started", { sessionID: toolPart.sessionID, tool: toolPart.tool, key })
     return
   }
 
@@ -138,6 +163,12 @@ export function handleMessagePartUpdated(e: EventMessagePartUpdated, ctx: Handle
       ...ctx.commonAttrs,
     },
   })
+  ctx.log("debug", "otel: tool.duration histogram recorded", {
+    sessionID: toolPart.sessionID,
+    tool_name: toolPart.tool,
+    duration_ms,
+    success,
+  })
   return ctx.log(success ? "info" : "error", "otel: tool_result", {
     sessionID: toolPart.sessionID,
     tool_name: toolPart.tool,

src/handlers/permission.ts

@@ -11,6 +11,7 @@ export function handlePermissionUpdated(e: EventPermissionUpdated, ctx: HandlerC
     title: perm.title,
     sessionID: perm.sessionID,
   })
+  ctx.log("debug", "otel: permission stored", { permissionID: perm.id, sessionID: perm.sessionID, type: perm.type, title: perm.title })
 }
 
 /** Emits a `tool_decision` log event recording whether the permission was accepted or rejected. */
@@ -19,6 +20,7 @@ export function handlePermissionReplied(e: EventPermissionReplied, ctx: HandlerC
   const pending = ctx.pendingPermissions.get(permissionID)
   ctx.pendingPermissions.delete(permissionID)
   const decision = response === "allow" || response === "allowAlways" ? "accept" : "reject"
+  ctx.log("debug", "otel: tool_decision emitted", { permissionID, sessionID, decision, source: response, tool_name: pending?.title ?? "unknown" })
   ctx.logger.emit({
     severityNumber: SeverityNumber.INFO,
     severityText: "INFO",

src/handlers/session.ts

@@ -1,13 +1,14 @@
 import { SeverityNumber } from "@opentelemetry/api-logs"
-import type { EventSessionCreated, EventSessionIdle, EventSessionError } from "@opencode-ai/sdk"
-import { errorSummary } from "../util.ts"
+import type { EventSessionCreated, EventSessionIdle, EventSessionError, EventSessionStatus } from "@opencode-ai/sdk"
+import { errorSummary, setBoundedMap } from "../util.ts"
 import type { HandlerContext } from "../types.ts"
 
-/** Increments the session counter and emits a `session.created` log event. */
+/** Increments the session counter, records start time, and emits a `session.created` log event. */
 export function handleSessionCreated(e: EventSessionCreated, ctx: HandlerContext) {
   const sessionID = e.properties.info.id
   const createdAt = e.properties.info.time.created
   ctx.instruments.sessionCounter.add(1, { ...ctx.commonAttrs, "session.id": sessionID })
+  setBoundedMap(ctx.sessionTotals, sessionID, { startMs: createdAt, tokens: 0, cost: 0, messages: 0 })
   ctx.logger.emit({
     severityNumber: SeverityNumber.INFO,
     severityText: "INFO",
@@ -16,7 +17,7 @@ export function handleSessionCreated(e: EventSessionCreated, ctx: HandlerContext
     body: "session.created",
     attributes: { "event.name": "session.created", "session.id": sessionID, ...ctx.commonAttrs },
   })
-  return ctx.log("info", "otel: session.created", { sessionID })
+  return ctx.log("info", "otel: session.created", { sessionID, createdAt })
 }
 
 function sweepSession(sessionID: string, ctx: HandlerContext) {
@@ -28,23 +29,50 @@ function sweepSession(sessionID: string, ctx: HandlerContext) {
   }
 }
 
-/** Emits a `session.idle` log event and clears any pending tool spans and permissions for the session. */
+/** Emits a `session.idle` log event, records duration and session total histograms, and clears pending state. */
 export function handleSessionIdle(e: EventSessionIdle, ctx: HandlerContext) {
   const sessionID = e.properties.sessionID
+  const totals = ctx.sessionTotals.get(sessionID)
+  ctx.sessionTotals.delete(sessionID)
   sweepSession(sessionID, ctx)
+
+  const attrs = { ...ctx.commonAttrs, "session.id": sessionID }
+  let duration_ms: number | undefined
+
+  if (totals) {
+    duration_ms = Date.now() - totals.startMs
+    ctx.instruments.sessionDurationHistogram.record(duration_ms, attrs)
+    ctx.instruments.sessionTokenGauge.record(totals.tokens, attrs)
+    ctx.instruments.sessionCostGauge.record(totals.cost, attrs)
+  }
+
   ctx.logger.emit({
     severityNumber: SeverityNumber.INFO,
     severityText: "INFO",
     timestamp: Date.now(),
     observedTimestamp: Date.now(),
     body: "session.idle",
-    attributes: { "event.name": "session.idle", "session.id": sessionID, ...ctx.commonAttrs },
+    attributes: {
+      "event.name": "session.idle",
+      "session.id": sessionID,
+      total_tokens: totals?.tokens ?? 0,
+      total_cost_usd: totals?.cost ?? 0,
+      total_messages: totals?.messages ?? 0,
+      ...ctx.commonAttrs,
+    },
+  })
+  ctx.log("debug", "otel: session.idle", {
+    sessionID,
+    ...(totals ? { duration_ms, total_tokens: totals.tokens, total_cost_usd: totals.cost, total_messages: totals.messages } : {}),
   })
 }
 
 /** Emits a `session.error` log event and clears any pending tool spans and permissions for the session. */
 export function handleSessionError(e: EventSessionError, ctx: HandlerContext) {
-  const sessionID = e.properties.sessionID ?? "unknown"
+  const rawID = e.properties.sessionID
+  const sessionID = rawID ?? "unknown"
+  const error = errorSummary(e.properties.error)
+  if (rawID) ctx.sessionTotals.delete(rawID)
   sweepSession(sessionID, ctx)
   ctx.logger.emit({
     severityNumber: SeverityNumber.ERROR,
@@ -55,8 +83,18 @@ export function handleSessionError(e: EventSessionError, ctx: HandlerContext) {
     attributes: {
       "event.name": "session.error",
       "session.id": sessionID,
-      error: errorSummary(e.properties.error),
+      error,
       ...ctx.commonAttrs,
     },
   })
+  ctx.log("error", "otel: session.error", { sessionID, error })
+}
+
+/** Increments the retry counter when the session enters a retry state. */
+export function handleSessionStatus(e: EventSessionStatus, ctx: HandlerContext) {
+  if (e.properties.status.type !== "retry") return
+  const { sessionID, status } = e.properties
+  const { attempt, message: retryMessage } = status
+  ctx.instruments.retryCounter.add(1, { ...ctx.commonAttrs, "session.id": sessionID })
+  ctx.log("debug", "otel: retry counter incremented", { sessionID, attempt, retryMessage })
 }

src/index.ts

@@ -6,6 +6,7 @@ import type {
   EventSessionCreated,
   EventSessionIdle,
   EventSessionError,
+  EventSessionStatus,
   EventMessageUpdated,
   EventMessagePartUpdated,
   EventPermissionUpdated,
@@ -17,7 +18,7 @@ import { LEVELS, type Level, type HandlerContext } from "./types.ts"
 import { loadConfig, resolveLogLevel } from "./config.ts"
 import { probeEndpoint } from "./probe.ts"
 import { setupOtel, createInstruments } from "./otel.ts"
-import { handleSessionCreated, handleSessionIdle, handleSessionError } from "./handlers/session.ts"
+import { handleSessionCreated, handleSessionIdle, handleSessionError, handleSessionStatus } from "./handlers/session.ts"
 import { handleMessageUpdated, handleMessagePartUpdated } from "./handlers/message.ts"
 import { handlePermissionUpdated, handlePermissionReplied } from "./handlers/permission.ts"
 import { handleSessionDiff, handleCommandExecuted } from "./handlers/activity.ts"
@@ -51,6 +52,11 @@ export const OtelPlugin: Plugin = async ({ project, client }) => {
     metricPrefix: config.metricPrefix,
   })
 
+  await log("debug", "config loaded", {
+    headersSet: !!config.otlpHeaders,
+    resourceAttributesSet: !!config.resourceAttributes,
+  })
+
   const probe = await probeEndpoint(config.endpoint)
   if (probe.ok) {
     await log("info", "OTLP endpoint reachable", { endpoint: config.endpoint, ms: probe.ms })
@@ -73,6 +79,7 @@ export const OtelPlugin: Plugin = async ({ project, client }) => {
   const logger = logs.getLogger("com.opencode")
   const pendingToolSpans = new Map()
   const pendingPermissions = new Map()
+  const sessionTotals = new Map()
   const commonAttrs = { "project.id": project.id } as const
 
   const ctx: HandlerContext = {
@@ -82,6 +89,7 @@ export const OtelPlugin: Plugin = async ({ project, client }) => {
     commonAttrs,
     pendingToolSpans,
     pendingPermissions,
+    sessionTotals,
   }
 
   async function shutdown() {
@@ -113,7 +121,7 @@ export const OtelPlugin: Plugin = async ({ project, client }) => {
         const next = resolveLogLevel(cfg.logLevel, minLevel)
         if (next !== minLevel) {
           minLevel = next
-          await log("debug", `log level set to "${minLevel}"`)
+          await log("info", `log level set to "${minLevel}"`)
         } else if (cfg.logLevel.toLowerCase() !== minLevel) {
           await log("warn", `unknown log level "${cfg.logLevel}", keeping "${minLevel}"`)
         }
@@ -155,6 +163,9 @@ export const OtelPlugin: Plugin = async ({ project, client }) => {
         case "session.error":
           handleSessionError(event as EventSessionError, ctx)
           break
+        case "session.status":
+          handleSessionStatus(event as EventSessionStatus, ctx)
+          break
         case "session.diff":
           handleSessionDiff(event as EventSessionDiff, ctx)
           break

src/otel.ts

@@ -105,5 +105,33 @@ export function createInstruments(prefix: string): Instruments {
       unit: "ms",
       description: "Duration of tool executions in milliseconds",
     }),
+    cacheCounter: meter.createCounter(`${prefix}cache.count`, {
+      unit: "count",
+      description: "Token cache hits (read) and misses (write) per completed assistant message",
+    }),
+    sessionDurationHistogram: meter.createHistogram(`${prefix}session.duration`, {
+      unit: "ms",
+      description: "Duration of a session from created to idle in milliseconds",
+    }),
+    messageCounter: meter.createCounter(`${prefix}message.count`, {
+      unit: "count",
+      description: "Number of completed assistant messages per session",
+    }),
+    sessionTokenGauge: meter.createHistogram(`${prefix}session.token.total`, {
+      unit: "tokens",
+      description: "Total tokens consumed per session, recorded as a histogram on session idle",
+    }),
+    sessionCostGauge: meter.createHistogram(`${prefix}session.cost.total`, {
+      unit: "USD",
+      description: "Total cost per session in USD, recorded as a histogram on session idle",
+    }),
+    modelUsageCounter: meter.createCounter(`${prefix}model.usage`, {
+      unit: "count",
+      description: "Number of completed assistant messages per model and provider",
+    }),
+    retryCounter: meter.createCounter(`${prefix}retry.count`, {
+      unit: "count",
+      description: "Number of API retries observed via session.status events",
+    }),
   }
 }

src/types.ts

@@ -42,6 +42,21 @@ export type Instruments = {
   linesCounter: Counter
   commitCounter: Counter
   toolDurationHistogram: Histogram
+  cacheCounter: Counter
+  sessionDurationHistogram: Histogram
+  messageCounter: Counter
+  sessionTokenGauge: Histogram
+  sessionCostGauge: Histogram
+  modelUsageCounter: Counter
+  retryCounter: Counter
+}
+
+/** Accumulated per-session totals used for gauge snapshots on session.idle. */
+export type SessionTotals = {
+  startMs: number
+  tokens: number
+  cost: number
+  messages: number
 }
 
 /** Shared context threaded through every event handler. */
@@ -52,4 +67,5 @@ export type HandlerContext = {
   commonAttrs: CommonAttrs
   pendingToolSpans: Map<string, PendingToolSpan>
   pendingPermissions: Map<string, PendingPermission>
+  sessionTotals: Map<string, SessionTotals>
 }

src/util.ts

@@ -1,4 +1,5 @@
 import { MAX_PENDING } from "./types.ts"
+import type { HandlerContext } from "./types.ts"
 
 /** Returns a human-readable summary string from an opencode error object. */
 export function errorSummary(err: { name: string; data?: unknown } | undefined): string {
@@ -20,3 +21,24 @@ export function setBoundedMap<K, V>(map: Map<K, V>, key: K, value: V) {
   }
   map.set(key, value)
 }
+
+/**
+ * Accumulates token and cost totals for a session, and increments the message count.
+ * Uses `setBoundedMap` to produce a new object rather than mutating in-place.
+ * No-ops silently if the session was not previously registered via `handleSessionCreated`.
+ */
+export function accumulateSessionTotals(
+  sessionID: string,
+  tokens: number,
+  cost: number,
+  ctx: HandlerContext,
+) {
+  const existing = ctx.sessionTotals.get(sessionID)
+  if (!existing) return
+  setBoundedMap(ctx.sessionTotals, sessionID, {
+    startMs: existing.startMs,
+    tokens: existing.tokens + tokens,
+    cost: existing.cost + cost,
+    messages: existing.messages + 1,
+  })
+}