diff --git a/server/src/__tests__/memory-hook-trace.test.ts b/server/src/__tests__/memory-hook-trace.test.ts new file mode 100644 index 00000000000..94447354d53 --- /dev/null +++ b/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", + ); + }); +}); diff --git a/server/src/services/heartbeat.ts b/server/src/services/heartbeat.ts index fd7f4f7cac1..2de20783162 100644 --- a/server/src/services/heartbeat.ts +++ b/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, + }); + }; 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); } diff --git a/server/src/services/memory-hook-trace.ts b/server/src/services/memory-hook-trace.ts new file mode 100644 index 00000000000..432778ec6c2 --- /dev/null +++ b/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 | 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 | 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 | 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, + 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, + 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`; +} diff --git a/server/src/services/memory.ts b/server/src/services/memory.ts index 48974605aaa..77de4668b7d 100644 --- a/server/src/services/memory.ts +++ b/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 => { 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 => { 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: {