Merge pull request #8 from DEVtheOPS/feat/enhanced-observability

dialupdisaster · web-flow · commit 46681d816dbe · 2026-03-14T15:54:16.000-04:00
feat(observability): add debug logging and enhanced metrics (v0.3.0)
fix(otel): use UCUM-compliant unit strings for all metric instruments
diff --git a/.npmrc b/.npmrc
@@ -0,0 +1 @@
+//registry.npmjs.org/:_authToken="${NPM_TOKEN}"
diff --git a/package.json b/package.json
@@ -1,6 +1,6 @@
 {
   "name": "@devtheops/opencode-plugin-otel",
-  "version": "0.2.1",
+  "version": "0.3.0",
   "module": "src/index.ts",
   "main": "src/index.ts",
   "type": "module",
diff --git a/src/handlers/activity.ts b/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",
diff --git a/src/handlers/message.ts b/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,
diff --git a/src/handlers/permission.ts b/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",
diff --git a/src/handlers/session.ts b/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 })
 }
diff --git a/src/index.ts b/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
diff --git a/src/otel.ts b/src/otel.ts
@@ -82,28 +82,56 @@ export function createInstruments(prefix: string): Instruments {
   const meter = metrics.getMeter("com.opencode")
   return {
     sessionCounter: meter.createCounter(`${prefix}session.count`, {
-      unit: "count",
+      unit: "{session}",
       description: "Count of opencode sessions started",
     }),
     tokenCounter: meter.createCounter(`${prefix}token.usage`, {
-      unit: "tokens",
+      unit: "{token}",
       description: "Number of tokens used",
     }),
     costCounter: meter.createCounter(`${prefix}cost.usage`, {
-      unit: "USD",
+      unit: "[USD]",
       description: "Cost of the opencode session in USD",
     }),
     linesCounter: meter.createCounter(`${prefix}lines_of_code.count`, {
-      unit: "count",
+      unit: "{line}",
       description: "Count of lines of code added or removed",
     }),
     commitCounter: meter.createCounter(`${prefix}commit.count`, {
-      unit: "count",
+      unit: "{commit}",
       description: "Number of git commits created",
     }),
     toolDurationHistogram: meter.createHistogram(`${prefix}tool.duration`, {
       unit: "ms",
       description: "Duration of tool executions in milliseconds",
     }),
+    cacheCounter: meter.createCounter(`${prefix}cache.count`, {
+      unit: "{request}",
+      description: "Token cache activity (cacheRead/cacheCreation) 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: "{message}",
+      description: "Number of completed assistant messages per session",
+    }),
+    sessionTokenGauge: meter.createHistogram(`${prefix}session.token.total`, {
+      unit: "{token}",
+      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: "{request}",
+      description: "Number of completed assistant messages per model and provider",
+    }),
+    retryCounter: meter.createCounter(`${prefix}retry.count`, {
+      unit: "{retry}",
+      description: "Number of API retries observed via session.status events",
+    }),
   }
 }
diff --git a/src/types.ts b/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>
 }
diff --git a/src/util.ts b/src/util.ts
diff --git a/tests/handlers/message.test.ts b/tests/handlers/message.test.ts
diff --git a/tests/handlers/session.test.ts b/tests/handlers/session.test.ts
diff --git a/tests/helpers.ts b/tests/helpers.ts

Original file line number	Diff line number	Diff line change
`@@ -0,0 +1 @@`
	`1`	`+//registry.npmjs.org/:_authToken="${NPM_TOKEN}"`
Original file line number	Diff line number	Diff line change
`@@ -1,6 +1,6 @@`
`1`	`1`	`{`
`2`	`2`	`"name": "@devtheops/opencode-plugin-otel",`
`3`		`- "version": "0.2.1",`
	`3`	`+ "version": "0.3.0",`
`4`	`4`	`"module": "src/index.ts",`
`5`	`5`	`"main": "src/index.ts",`
`6`	`6`	`"type": "module",`