Expose memory traces in heartbeat logs

Co-Authored-By: Paperclip <noreply@paperclip.ing>

server/src/__tests__/memory-hook-trace.test.ts

@@ -0,0 +1,49 @@
+import { describe, expect, it } from "vitest";
+import {
+  buildPreRunHydrateTrace,
+  buildSkippedMemoryHookTrace,
+  formatMemoryHookTraceLog,
+} from "../services/memory-hook-trace.js";
+
+describe("memory hook trace logs", () => {
+  it("formats hydrated records with binding, provider, operation, and record ids", () => {
+    const trace = buildPreRunHydrateTrace(
+      {
+        id: "binding-1",
+        key: "company-default",
+        providerKey: "local_basic",
+      },
+      {
+        preamble: "Use the deployment notes.",
+        operation: {
+          id: "operation-1",
+          operationType: "query",
+          status: "succeeded",
+        },
+        records: [
+          {
+            id: "record-1",
+            title: "Deployment notes",
+            source: { kind: "issue_document", issueId: "issue-1", documentKey: "plan" },
+            citation: { label: "Issue document", sourceTitle: "Plan" },
+          },
+        ],
+      } as any,
+    );
+
+    expect(formatMemoryHookTraceLog(trace)).toBe(
+      "[paperclip:memory] pre-run hydrate hydrated; 1 record; binding=company-default; provider=local_basic; operation=operation-1; preambleBytes=25; records=record-1 (Deployment notes)\n",
+    );
+  });
+
+  it("formats skipped hook decisions with an explicit reason", () => {
+    const trace = buildSkippedMemoryHookTrace({
+      hookKind: "post_run_capture",
+      reason: "no_run_summary",
+    });
+
+    expect(formatMemoryHookTraceLog(trace)).toBe(
+      "[paperclip:memory] post-run capture skipped; 0 records; reason=no_run_summary\n",
+    );
+  });
+});

server/src/services/heartbeat.ts

@@ -38,6 +38,12 @@ import {
   mergeHeartbeatRunResultJson,
   summarizeHeartbeatRunResultJson,
 } from "./heartbeat-run-summary.js";
+import {
+  buildErroredMemoryHookTrace,
+  buildSkippedMemoryHookTrace,
+  formatMemoryHookTraceLog,
+  type MemoryHookTrace,
+} from "./memory-hook-trace.js";
 import {
   buildWorkspaceReadyComment,
   cleanupExecutionWorkspaceArtifacts,
@@ -3137,7 +3143,7 @@ export function heartbeatService(
         .where(eq(heartbeatRuns.id, runId));
 
       const currentUserRedactionOptions = await getCurrentUserRedactionOptions();
-      const onLog = async (stream: "stdout" | "stderr", chunk: string) => {
+      const appendLog = async (stream: "stdout" | "stderr" | "system", chunk: string) => {
         const sanitizedChunk = redactCurrentUserText(chunk, currentUserRedactionOptions);
         if (stream === "stdout") stdoutExcerpt = appendExcerpt(stdoutExcerpt, sanitizedChunk);
         if (stream === "stderr") stderrExcerpt = appendExcerpt(stderrExcerpt, sanitizedChunk);
@@ -3169,6 +3175,17 @@ export function heartbeatService(
           },
         });
       };
+      const onLog = async (stream: "stdout" | "stderr", chunk: string) => appendLog(stream, chunk);
+      const appendMemoryTrace = async (trace: MemoryHookTrace) => {
+        await appendLog("system", formatMemoryHookTraceLog(trace));
+        await appendRunEvent(currentRun, seq++, {
+          eventType: "memory.trace",
+          stream: trace.status === "errored" ? "stderr" : "system",
+          level: trace.status === "errored" ? "error" : trace.status === "skipped" ? "warn" : "info",
+          message: formatMemoryHookTraceLog(trace).trim(),
+          payload: trace as unknown as Record<string, unknown>,
+        });
+      };
       for (const warning of runtimeWorkspaceWarnings) {
         const logEntry = formatRuntimeWorkspaceWarningLog(warning);
         await onLog(logEntry.stream, logEntry.chunk);
@@ -3224,7 +3241,7 @@ export function heartbeatService(
       }
       if (issueRef) {
         try {
-          const memoryPreamble = await memorySvc.preRunHydrate({
+          const memoryHydration = await memorySvc.preRunHydrate({
             companyId: agent.companyId,
             agentId: agent.id,
             projectId: issueRef.projectId ?? null,
@@ -3234,8 +3251,9 @@ export function heartbeatService(
               .filter((value): value is string => typeof value === "string" && value.trim().length > 0)
               .join("\n"),
           });
-          if (memoryPreamble) {
-            context.paperclipMemoryPreamble = memoryPreamble;
+          await appendMemoryTrace(memoryHydration.trace);
+          if (memoryHydration.preamble) {
+            context.paperclipMemoryPreamble = memoryHydration.preamble;
             await db
               .update(heartbeatRuns)
               .set({
@@ -3245,11 +3263,13 @@ export function heartbeatService(
               .where(eq(heartbeatRuns.id, run.id));
           }
         } catch (err) {
-          await onLog(
-            "stderr",
-            `[paperclip] Failed to hydrate memory: ${err instanceof Error ? err.message : String(err)}\n`,
-          );
+          await appendMemoryTrace(buildErroredMemoryHookTrace({ hookKind: "pre_run_hydrate", error: err }));
         }
+      } else {
+        await appendMemoryTrace(buildSkippedMemoryHookTrace({
+          hookKind: "pre_run_hydrate",
+          reason: "no_issue_context",
+        }));
       }
       const onAdapterMeta = async (meta: AdapterInvocationMeta) => {
         if (meta.env && secretKeys.size > 0) {
@@ -3378,9 +3398,6 @@ export function heartbeatService(
       }
 
       let logSummary: { bytes: number; sha256?: string; compressed: boolean } | null = null;
-      if (handle) {
-        logSummary = await runLogStore.finalize(handle);
-      }
 
       const status =
         outcome === "succeeded"
@@ -3421,6 +3438,34 @@ export function heartbeatService(
         adapterResult.resultJson ?? null,
         adapterResult.summary ?? null,
       );
+      const memorySummary =
+        buildHeartbeatRunIssueComment(adapterResult.resultJson ?? null)
+        ?? (typeof adapterResult.summary === "string" ? adapterResult.summary.trim() || null : null);
+      if (memorySummary) {
+        try {
+          const captureResult = await memorySvc.captureRunSummary({
+            companyId: agent.companyId,
+            agentId: agent.id,
+            projectId: issueRef?.projectId ?? null,
+            issueId: issueRef?.id ?? null,
+            runId: run.id,
+            title: issueRef?.title ? `Run summary: ${issueRef.title}` : "Run summary",
+            summary: memorySummary,
+          });
+          await appendMemoryTrace(captureResult.trace);
+        } catch (err) {
+          await appendMemoryTrace(buildErroredMemoryHookTrace({ hookKind: "post_run_capture", error: err }));
+        }
+      } else {
+        await appendMemoryTrace(buildSkippedMemoryHookTrace({
+          hookKind: "post_run_capture",
+          reason: "no_run_summary",
+        }));
+      }
+
+      if (handle) {
+        logSummary = await runLogStore.finalize(handle);
+      }
 
       await setRunStatus(run.id, status, {
         finishedAt: new Date(),
@@ -3481,27 +3526,6 @@ export function heartbeatService(
             );
           }
         }
-        const memorySummary =
-          buildHeartbeatRunIssueComment(adapterResult.resultJson ?? null)
-          ?? (typeof adapterResult.summary === "string" ? adapterResult.summary.trim() || null : null);
-        if (memorySummary) {
-          try {
-            await memorySvc.captureRunSummary({
-              companyId: agent.companyId,
-              agentId: agent.id,
-              projectId: issueRef?.projectId ?? null,
-              issueId: issueRef?.id ?? null,
-              runId: finalizedRun.id,
-              title: issueRef?.title ? `Run summary: ${issueRef.title}` : "Run summary",
-              summary: memorySummary,
-            });
-          } catch (err) {
-            await onLog(
-              "stderr",
-              `[paperclip] Failed to capture run summary to memory: ${err instanceof Error ? err.message : String(err)}\n`,
-            );
-          }
-        }
         await finalizeIssueCommentPolicy(finalizedRun, agent);
         await releaseIssueExecutionAndPromote(finalizedRun);
       }

server/src/services/memory-hook-trace.ts

@@ -0,0 +1,188 @@
+import type {
+  MemoryBinding,
+  MemoryCaptureResult,
+  MemoryHookKind,
+  MemoryOperation,
+  MemoryQueryResult,
+  MemoryRecord,
+} from "@paperclipai/shared";
+
+type MemoryHookTraceAction = "hydrate" | "capture";
+type MemoryHookTraceStatus = "hydrated" | "captured" | "skipped" | "errored";
+
+export interface MemoryHookRecordTrace {
+  id: string;
+  title: string | null;
+  sourceKind: string | null;
+  sourceIssueId: string | null;
+  sourceCommentId: string | null;
+  sourceDocumentKey: string | null;
+  sourceRunId: string | null;
+  citationLabel: string | null;
+  citationSourceTitle: string | null;
+}
+
+export interface MemoryHookTrace {
+  hookKind: MemoryHookKind;
+  action: MemoryHookTraceAction;
+  status: MemoryHookTraceStatus;
+  reason: string | null;
+  binding: {
+    id: string;
+    key: string;
+    providerKey: string;
+  } | null;
+  operation: {
+    id: string;
+    operationType: MemoryOperation["operationType"];
+    status: MemoryOperation["status"];
+  } | null;
+  recordCount: number;
+  records: MemoryHookRecordTrace[];
+  preambleLength: number | null;
+  error: string | null;
+}
+
+function actionForHook(hookKind: MemoryHookKind): MemoryHookTraceAction {
+  return hookKind === "pre_run_hydrate" ? "hydrate" : "capture";
+}
+
+function bindingTrace(binding: Pick<MemoryBinding, "id" | "key" | "providerKey"> | null | undefined) {
+  if (!binding) return null;
+  return {
+    id: binding.id,
+    key: binding.key,
+    providerKey: binding.providerKey,
+  };
+}
+
+function operationTrace(operation: MemoryOperation | null | undefined): MemoryHookTrace["operation"] {
+  if (!operation) return null;
+  return {
+    id: operation.id,
+    operationType: operation.operationType,
+    status: operation.status,
+  };
+}
+
+function recordTrace(record: MemoryRecord): MemoryHookRecordTrace {
+  return {
+    id: record.id,
+    title: record.title ?? null,
+    sourceKind: record.source?.kind ?? null,
+    sourceIssueId: record.source?.issueId ?? null,
+    sourceCommentId: record.source?.commentId ?? null,
+    sourceDocumentKey: record.source?.documentKey ?? null,
+    sourceRunId: record.source?.runId ?? null,
+    citationLabel: record.citation?.label ?? null,
+    citationSourceTitle: record.citation?.sourceTitle ?? null,
+  };
+}
+
+export function buildSkippedMemoryHookTrace(input: {
+  hookKind: MemoryHookKind;
+  reason: string;
+  binding?: Pick<MemoryBinding, "id" | "key" | "providerKey"> | null;
+}): MemoryHookTrace {
+  return {
+    hookKind: input.hookKind,
+    action: actionForHook(input.hookKind),
+    status: "skipped",
+    reason: input.reason,
+    binding: bindingTrace(input.binding),
+    operation: null,
+    recordCount: 0,
+    records: [],
+    preambleLength: null,
+    error: null,
+  };
+}
+
+export function buildErroredMemoryHookTrace(input: {
+  hookKind: MemoryHookKind;
+  error: unknown;
+  binding?: Pick<MemoryBinding, "id" | "key" | "providerKey"> | null;
+}): MemoryHookTrace {
+  return {
+    hookKind: input.hookKind,
+    action: actionForHook(input.hookKind),
+    status: "errored",
+    reason: null,
+    binding: bindingTrace(input.binding),
+    operation: null,
+    recordCount: 0,
+    records: [],
+    preambleLength: null,
+    error: input.error instanceof Error ? input.error.message : String(input.error),
+  };
+}
+
+export function buildPreRunHydrateTrace(
+  binding: Pick<MemoryBinding, "id" | "key" | "providerKey">,
+  result: MemoryQueryResult,
+): MemoryHookTrace {
+  return {
+    hookKind: "pre_run_hydrate",
+    action: "hydrate",
+    status: "hydrated",
+    reason: null,
+    binding: bindingTrace(binding),
+    operation: operationTrace(result.operation),
+    recordCount: result.records.length,
+    records: result.records.map(recordTrace),
+    preambleLength: result.preamble?.length ?? 0,
+    error: null,
+  };
+}
+
+export function buildPostRunCaptureTrace(
+  binding: Pick<MemoryBinding, "id" | "key" | "providerKey">,
+  result: MemoryCaptureResult,
+): MemoryHookTrace {
+  return {
+    hookKind: "post_run_capture",
+    action: "capture",
+    status: "captured",
+    reason: null,
+    binding: bindingTrace(binding),
+    operation: operationTrace(result.operation),
+    recordCount: result.records.length,
+    records: result.records.map(recordTrace),
+    preambleLength: null,
+    error: null,
+  };
+}
+
+function describeHook(hookKind: MemoryHookKind) {
+  switch (hookKind) {
+    case "pre_run_hydrate":
+      return "pre-run hydrate";
+    case "post_run_capture":
+      return "post-run capture";
+    case "issue_comment_capture":
+      return "issue comment capture";
+    case "issue_document_capture":
+      return "issue document capture";
+    default:
+      return hookKind;
+  }
+}
+
+function describeRecord(record: MemoryHookRecordTrace) {
+  const label = record.title || record.citationSourceTitle || record.citationLabel || "untitled";
+  return `${record.id} (${label})`;
+}
+
+export function formatMemoryHookTraceLog(trace: MemoryHookTrace) {
+  const parts = [
+    `[paperclip:memory] ${describeHook(trace.hookKind)} ${trace.status}`,
+    `${trace.recordCount} record${trace.recordCount === 1 ? "" : "s"}`,
+  ];
+  if (trace.reason) parts.push(`reason=${trace.reason}`);
+  if (trace.binding) parts.push(`binding=${trace.binding.key}`, `provider=${trace.binding.providerKey}`);
+  if (trace.operation) parts.push(`operation=${trace.operation.id}`);
+  if (trace.preambleLength !== null) parts.push(`preambleBytes=${trace.preambleLength}`);
+  if (trace.records.length > 0) parts.push(`records=${trace.records.map(describeRecord).join(", ")}`);
+  if (trace.error) parts.push(`error=${trace.error}`);
+  return `${parts.join("; ")}\n`;
+}

server/src/services/memory.ts

@@ -50,6 +50,12 @@ import {
   getDefaultPluginMemoryProviderDispatcher,
   type PluginMemoryProviderDispatcher,
 } from "./plugin-memory-provider-dispatcher.js";
+import {
+  buildPostRunCaptureTrace,
+  buildPreRunHydrateTrace,
+  buildSkippedMemoryHookTrace,
+  type MemoryHookTrace,
+} from "./memory-hook-trace.js";
 
 type ActorInfo = {
   actorType: "agent" | "user" | "system";
@@ -65,6 +71,15 @@ type OperationRow = typeof memoryOperations.$inferSelect;
 type RecordRow = typeof memoryLocalRecords.$inferSelect;
 type ExtractionJobRow = typeof memoryExtractionJobs.$inferSelect;
 
+export interface MemoryPreRunHydrateResult {
+  preamble: string | null;
+  trace: MemoryHookTrace;
+}
+
+export interface MemoryPostRunCaptureResult {
+  trace: MemoryHookTrace;
+}
+
 const LOCAL_BASIC_PROVIDER_KEY = "local_basic";
 
 const localBasicConfigSchema = z
@@ -1661,7 +1676,7 @@ export function memoryService(
       issueId?: string | null;
       runId: string;
       query: string;
-    }) => {
+    }): Promise<MemoryPreRunHydrateResult> => {
       const resolved = await resolveBindingInternal(
         input.companyId,
         {
@@ -1673,10 +1688,24 @@ export function memoryService(
         null,
       );
       if (!resolved.binding || !resolved.binding.enabled) {
-        return null;
+        return {
+          preamble: null,
+          trace: buildSkippedMemoryHookTrace({
+            hookKind: "pre_run_hydrate",
+            reason: resolved.binding ? "binding_disabled" : "no_binding",
+            binding: resolved.binding ? mapBinding(resolved.binding) : null,
+          }),
+        };
       }
       if (!isHookEnabled(resolved.binding, "preRunHydrate")) {
-        return null;
+        return {
+          preamble: null,
+          trace: buildSkippedMemoryHookTrace({
+            hookKind: "pre_run_hydrate",
+            reason: "hook_disabled",
+            binding: mapBinding(resolved.binding),
+          }),
+        };
       }
       const result = await service.query(
         input.companyId,
@@ -1703,7 +1732,10 @@ export function memoryService(
         "hook",
         "pre_run_hydrate",
       );
-      return result.preamble;
+      return {
+        preamble: result.preamble,
+        trace: buildPreRunHydrateTrace(mapBinding(resolved.binding), result),
+      };
     },
 
     captureRunSummary: async (input: {
@@ -1714,7 +1746,7 @@ export function memoryService(
       runId: string;
       title?: string | null;
       summary: string;
-    }) => {
+    }): Promise<MemoryPostRunCaptureResult> => {
       const resolved = await resolveBindingInternal(
         input.companyId,
         {
@@ -1726,12 +1758,24 @@ export function memoryService(
         null,
       );
       if (!resolved.binding || !resolved.binding.enabled) {
-        return null;
+        return {
+          trace: buildSkippedMemoryHookTrace({
+            hookKind: "post_run_capture",
+            reason: resolved.binding ? "binding_disabled" : "no_binding",
+            binding: resolved.binding ? mapBinding(resolved.binding) : null,
+          }),
+        };
       }
       if (!isHookEnabled(resolved.binding, "postRunCapture")) {
-        return null;
+        return {
+          trace: buildSkippedMemoryHookTrace({
+            hookKind: "post_run_capture",
+            reason: "hook_disabled",
+            binding: mapBinding(resolved.binding),
+          }),
+        };
       }
-      return service.capture(
+      const result = await service.capture(
         input.companyId,
         {
           scope: {
@@ -1768,6 +1812,9 @@ export function memoryService(
         "hook",
         "post_run_capture",
       );
+      return {
+        trace: buildPostRunCaptureTrace(mapBinding(resolved.binding), result),
+      };
     },
 
     captureIssueComment: async (input: {