Add custom trace spans and heavy-operation duration logs

createTracer (backend-utils/tracing) opens a span and stamps the
ambient observability context onto it as attributes — tracing only,
no logging. Spans cover the two interior operations auto-instrumentation
can't see: agent.run and code.snapshot.rebuild. Chat deletion, workspace
deletion, and storage migration get duration logs; their RPC/constructor
boundaries are already auto-traced.

Author: ndisidore

packages/backend-utils/package.json

@@ -12,6 +12,10 @@
       "types": "./src/observability-context.ts",
       "import": "./src/observability-context.ts"
     },
+    "./tracing": {
+      "types": "./src/tracing.ts",
+      "import": "./src/tracing.ts"
+    },
     "./error-reporting": {
       "types": "./src/error-reporting.ts",
       "import": "./src/error-reporting.ts"

packages/backend-utils/src/tracing.ts

@@ -0,0 +1,40 @@
+import { tracing } from "cloudflare:workers";
+
+type Attribute = boolean | number | string;
+
+// The span surface exposed to callbacks. Lifetime is managed by `traced`, so no `end()`.
+export interface TraceSpan {
+  readonly isTraced: boolean;
+  setAttribute(key: string, value?: Attribute): void;
+}
+
+/**
+ * Creates a span helper that stamps the ambient observability context onto each span as
+ * attributes. Tracing only: never logs, never modifies context. Exceptions propagate
+ * unchanged, marked on the span via an `error` attribute (the beta API has no outcome).
+ */
+export function createTracer(getContext: () => Readonly<Record<string, unknown>>) {
+  return function traced<Result>(name: string, callback: (span: TraceSpan) => Result): Result {
+    return tracing.enterSpan(name, (span) => {
+      if (span.isTraced) {
+        for (const [key, value] of Object.entries(getContext())) {
+          if (typeof value === "boolean" || typeof value === "number" || typeof value === "string") {
+            span.setAttribute(key, value);
+          }
+        }
+      }
+      // Boolean marker only: error text is unbounded and possibly sensitive, so it belongs to
+      // logs/reporting, not trace attributes.
+      const fail = () => span.setAttribute("error", true);
+      try {
+        const result = callback(span);
+        return result instanceof Promise
+            ? result.catch((err) => { fail(); throw err; }) as Result
+            : result;
+      } catch (err) {
+        fail();
+        throw err;
+      }
+    });
+  };
+}

packages/workshop-backend/src/observability.ts

@@ -1,4 +1,5 @@
 import { createObservabilityContext } from "@gadgets/backend-utils/observability-context";
+import { createTracer } from "@gadgets/backend-utils/tracing";
 
 /** Observability fields emitted by the Workshop backend. */
 export type WorkshopObservabilityFields = {
@@ -14,6 +15,7 @@ export type WorkshopObservabilityFields = {
   failureCount: number;
   gadgetId: string;
   gatekeeperId: number | string;
+  logBytes: number;
   modelId: string;
   observerId: string;
   operation: string;
@@ -37,3 +39,6 @@ export const obsContext = createObservabilityContext<WorkshopObservabilityFields
 export function createWorkshopLogger(component: string) {
   return obsContext.createLogger({ component });
 }
+
+/** Runs `callback` in a trace span carrying the ambient observability fields as attributes. */
+export const traced = createTracer(obsContext.get);

packages/workshop-backend/src/overseer.ts

@@ -37,7 +37,7 @@ import { refreshCachedBalance } from "./ai-gateway-billing/cloudflare/connection
 import { SharingManager, SharingCaller, CollaboratorRecord, ShareKeyRecord } from "./sharing";
 import { AutoApprovalDrainer } from "./auto-approval";
 import { collectSlashCommands, invokeSlashCommand } from "./slash-commands";
-import { createWorkshopLogger, obsContext } from "./observability";
+import { createWorkshopLogger, obsContext, traced } from "./observability";
 import type { ChatGatewayRpcTarget, SubmitExternalMessageResult } from "@gadgets/workshop-shared/external-message-gateway";
 import {
   assertChatAttachmentSupportedByProvider,
@@ -1376,6 +1376,7 @@ class OverseerImpl implements AgentHooks {
 
     // Run the whole migration in one transaction so that a mid-migration error can't leave the
     // workspace half-migrated.
+    let startedAt = Date.now();
     this.ctx.storage.transactionSync(() => {
       // Version 0 -> 1: the workspace predates multi-gadget support. If it has any gadget content
       // (code beyond the initial empty snapshot, or named bindings), register that content as the
@@ -1455,6 +1456,10 @@ class OverseerImpl implements AgentHooks {
 
       this.storage.version.put(1);
     });
+
+    this.logger.info("migrated workspace storage", {
+      event: "storage.migration.completed", durationMs: Date.now() - startedAt,
+    });
   }
 
   // Allocate a workpiece ID from the shared counter. (The counter is named `nextGatekeeperId`
@@ -2003,18 +2008,24 @@ class OverseerImpl implements AgentHooks {
       this.#snapshotMetrics.logSize += update.length;
       if (this.#snapshotMetrics.logSize >
           Math.max(this.#snapshotMetrics.snapshotSize, MIN_SNAPSHOT_THRESHOLD)) {
-        let {ydoc} = this.buildYDoc("current");
-        let snapshotUpdate = Y.encodeStateAsUpdateV2(ydoc);
-        this.storage.snapshots.put({
-          version,
-          timestamp,
-          update: snapshotUpdate
+        let logBytes = this.#snapshotMetrics.logSize;
+        let startedAt = Date.now();
+        traced("code.snapshot.rebuild", (span) => {
+          let {ydoc} = this.buildYDoc("current");
+          let snapshotUpdate = Y.encodeStateAsUpdateV2(ydoc);
+          this.storage.snapshots.put({version, timestamp, update: snapshotUpdate});
+          span.setAttribute("gadgetId", this.ctx.id.toString());
+          span.setAttribute("size", snapshotUpdate.length);
+          span.setAttribute("logBytes", logBytes);
+          this.#snapshotMetrics = {
+            snapshotSize: snapshotUpdate.length,
+            logSize: 0,
+          };
+          this.logger.info("rebuilt code snapshot", {
+            event: "code.snapshot.rebuilt", durationMs: Date.now() - startedAt,
+            size: snapshotUpdate.length, logBytes, sequence: version,
+          });
         });
-
-        this.#snapshotMetrics = {
-          snapshotSize: snapshotUpdate.length,
-          logSize: 0,
-        };
       }
     }
 
@@ -3857,8 +3868,8 @@ class OverseerImpl implements AgentHooks {
       gadgetId: this.ctx.id.toString(),
       chatId,
       modelId: aiModel.profile.id,
-    }, () => this.#runAgentTurnWithContext(
-        chatId, aiModel, initiator, callbackInitiated, liveChat));
+    }, () => traced("agent.run", () => this.#runAgentTurnWithContext(
+        chatId, aiModel, initiator, callbackInitiated, liveChat)));
   }
 
   async #runAgentTurnWithContext(chatId: number, aiModel: UserAiModelRecord,
@@ -7311,6 +7322,7 @@ class OverseerClientInterface extends RpcTarget implements Overseer {
     if (!this.isOwner) {
       throw new Error("Only the workspace owner can delete it.");
     }
+    let startedAt = Date.now();
 
     this.impl.recordGadgetAnalytics({
       event_name: "gadget_deleted",
@@ -7337,6 +7349,10 @@ class OverseerClientInterface extends RpcTarget implements Overseer {
       this.impl.scheduleRevocationRestart();
       this.impl.ownerId = undefined;
     });
+
+    this.impl.logger.info("deleted workspace", {
+      event: "workspace.delete.completed", durationMs: Date.now() - startedAt,
+    });
   }
 
   async subscribeToCode(subscriber: RpcStub<CodeSubscriber>, fromVersion: number = 0)
@@ -8390,6 +8406,7 @@ class OverseerClientInterface extends RpcTarget implements Overseer {
   }
 
   async deleteChat(chatId: number): Promise<void> {
+    let startedAt = Date.now();
     let response = this.impl.storage.gadgetResponseDeliveries.undeliveredByChatId.get(chatId);
     if (response?.status === "waiting") {
       this.impl.deliverExternalMessageResponse(response, "The chat was deleted before the agent responded.");
@@ -8459,6 +8476,10 @@ class OverseerClientInterface extends RpcTarget implements Overseer {
 
     // Clean up all in-memory live state for this chat.
     this.impl.destroyLiveChat(chatId);
+
+    this.impl.logger.info("deleted chat", {
+      event: "chat.delete.completed", chatId, durationMs: Date.now() - startedAt,
+    });
   }
 
   async stopAgent(chatId: number): Promise<void> {