Enhance debug output to include response content files and update related metadata handling

This commit is contained in:
2026-07-08 08:52:19 -05:00
parent 68ec69f2e4
commit 610bdb4fea
6 changed files with 178 additions and 41 deletions

View File

@@ -90,8 +90,10 @@ current run ID. The runner writes framework-boundary inputs, outputs,
structured LLM calls, validator calls, timing, and retry attempt metadata structured LLM calls, validator calls, timing, and retry attempt metadata
through that interface. Each retry or validator attempt records any LLM calls through that interface. Each retry or validator attempt records any LLM calls
made within that attempt in an `llm_calls` array and writes paired made within that attempt in an `llm_calls` array and writes paired
`prompt-000N.json` and `response-000N.json` files under the attempt directory. `prompt-000N.json` and `response-000N.json` metadata files under the attempt
Debug output is not used for resume and can contain sensitive source, directory. LLM response bodies are written as sibling `response-content-000N.*`
files, using pretty-printed JSON when the content is valid JSON and raw text
otherwise. Debug output is not used for resume and can contain sensitive source,
reference, prompt, and model-output material. Concrete modules still do not reference, prompt, and model-output material. Concrete modules still do not
receive workspace paths. receive workspace paths.

View File

@@ -139,14 +139,16 @@ Debug artifacts include framework-boundary inputs and outputs for source,
chunk, extract, merge, normalize, and output work, structured LLM request and chunk, extract, merge, normalize, and output work, structured LLM request and
response data from Notarius contracts, validator requests and results, timing, response data from Notarius contracts, validator requests and results, timing,
and retry attempt metadata. LLM calls made inside a retry or validator attempt and retry attempt metadata. LLM calls made inside a retry or validator attempt
write paired `prompt-000N.json` and `response-000N.json` files under that write `prompt-000N.json`, `response-000N.json`, and
attempt directory and are linked from the attempt `llm_calls` array. Prompt and `response-content-000N.*` files under that attempt directory and are linked from
response content in those artifacts is written as raw text for inspection. the attempt `llm_calls` array. Prompt content is written inline in the prompt
Debug artifacts may contain source material, reference material, prompt inputs, artifact. Response metadata is written to `response-000N.json`, while the
model outputs, and other sensitive data. API keys are not written, and obvious response body is written separately as pretty-printed JSON when possible or as
credential-shaped values and sensitive map keys are redacted in framework raw text otherwise. Debug artifacts may contain source material, reference
envelopes, but debug directories should still be protected as sensitive local material, prompt inputs, model outputs, and other sensitive data. API keys are
state. not written, and obvious credential-shaped values and sensitive map keys are
redacted in framework envelopes, but debug directories should still be protected
as sensitive local state.
## Retention ## Retention

View File

@@ -2247,6 +2247,7 @@ func TestRunPipelineWritesDebugWhenWorkspaceDebugEnabled(t *testing.T) {
"extract/spells/chunk-000001/attempt-01.json", "extract/spells/chunk-000001/attempt-01.json",
"extract/spells/chunk-000001/attempt-01/prompt-0001.json", "extract/spells/chunk-000001/attempt-01/prompt-0001.json",
"extract/spells/chunk-000001/attempt-01/response-0001.json", "extract/spells/chunk-000001/attempt-01/response-0001.json",
"extract/spells/chunk-000001/attempt-01/response-content-0001.json",
"extract/spells/output.json", "extract/spells/output.json",
"merge/spells/input.json", "merge/spells/input.json",
"merge/spells/output.json", "merge/spells/output.json",
@@ -2260,12 +2261,16 @@ func TestRunPipelineWritesDebugWhenWorkspaceDebugEnabled(t *testing.T) {
} }
} }
attemptDebug := string(readFile(t, filepath.Join(debugDir, "extract/spells/chunk-000001/attempt-01.json"))) attemptDebug := string(readFile(t, filepath.Join(debugDir, "extract/spells/chunk-000001/attempt-01.json")))
if !strings.Contains(attemptDebug, `"llm_calls"`) || !strings.Contains(attemptDebug, `"prompt_path"`) || !strings.Contains(attemptDebug, `"response_path"`) { if !strings.Contains(attemptDebug, `"llm_calls"`) || !strings.Contains(attemptDebug, `"prompt_path"`) || !strings.Contains(attemptDebug, `"response_path"`) || !strings.Contains(attemptDebug, `"response_content_path"`) {
t.Fatalf("extract attempt debug = %s, want prompt/response llm_calls", attemptDebug) t.Fatalf("extract attempt debug = %s, want prompt/response llm_calls", attemptDebug)
} }
responseDebug := string(readFile(t, filepath.Join(debugDir, "extract/spells/chunk-000001/attempt-01/response-0001.json"))) responseDebug := string(readFile(t, filepath.Join(debugDir, "extract/spells/chunk-000001/attempt-01/response-0001.json")))
if !strings.Contains(responseDebug, `"content"`) || !strings.Contains(responseDebug, `spell_casts`) { if !strings.Contains(responseDebug, `"content_path"`) || strings.Contains(responseDebug, `spell_casts`) {
t.Fatalf("response debug = %s, want raw response content", responseDebug) t.Fatalf("response debug = %s, want metadata with content path and no inline response", responseDebug)
}
responseContent := string(readFile(t, filepath.Join(debugDir, "extract/spells/chunk-000001/attempt-01/response-content-0001.json")))
if !strings.Contains(responseContent, `"spell_casts"`) || !strings.Contains(responseContent, "\n ") {
t.Fatalf("response content = %s, want pretty JSON response body", responseContent)
} }
assertPathNotExist(t, filepath.Join(debugDir, "llm/call-0001.json")) assertPathNotExist(t, filepath.Join(debugDir, "llm/call-0001.json"))
assertPathNotExist(t, filepath.Join(debugDir, "extract/spells/chunk-000001-attempt-01/llm-call-0001.json")) assertPathNotExist(t, filepath.Join(debugDir, "extract/spells/chunk-000001-attempt-01/llm-call-0001.json"))
@@ -3751,6 +3756,9 @@ func assertDebugTreeDoesNotContain(t *testing.T, root string, forbidden ...strin
if entry.IsDir() { if entry.IsDir() {
return nil return nil
} }
if strings.HasPrefix(filepath.Base(path), "response-content-") {
return nil
}
data, err := os.ReadFile(path) data, err := os.ReadFile(path)
if err != nil { if err != nil {
return err return err

View File

@@ -32,3 +32,10 @@ func (r *WorkspaceRecorder) WriteJSON(name string, payload any) error {
} }
return coreworkspace.WriteJSON(r.root, name, payload) return coreworkspace.WriteJSON(r.root, name, payload)
} }
func (r *WorkspaceRecorder) WriteBytes(name string, data []byte) error {
if !r.Enabled() {
return nil
}
return coreworkspace.WriteBytes(r.root, name, data)
}

View File

@@ -1,10 +1,12 @@
package pipeline package pipeline
import ( import (
"bytes"
"context" "context"
"crypto/sha256" "crypto/sha256"
"encoding/base64" "encoding/base64"
"encoding/hex" "encoding/hex"
"encoding/json"
"errors" "errors"
"fmt" "fmt"
"path" "path"
@@ -22,6 +24,7 @@ import (
type DebugRecorder interface { type DebugRecorder interface {
Enabled() bool Enabled() bool
WriteJSON(name string, payload any) error WriteJSON(name string, payload any) error
WriteBytes(name string, data []byte) error
} }
type noopDebugRecorder struct{} type noopDebugRecorder struct{}
@@ -30,6 +33,7 @@ func NoopDebugRecorder() DebugRecorder { return noopDebugRecorder{} }
func (noopDebugRecorder) Enabled() bool { return false } func (noopDebugRecorder) Enabled() bool { return false }
func (noopDebugRecorder) WriteJSON(string, any) error { return nil } func (noopDebugRecorder) WriteJSON(string, any) error { return nil }
func (noopDebugRecorder) WriteBytes(string, []byte) error { return nil }
func debugPathComponent(value string) string { func debugPathComponent(value string) string {
value = strings.TrimSpace(value) value = strings.TrimSpace(value)
if value == "" { if value == "" {
@@ -174,6 +178,7 @@ type debugLLMResponseArtifact struct {
CallID string `json:"call_id"` CallID string `json:"call_id"`
Response *contracts.LLMDebugResponse `json:"response,omitempty"` Response *contracts.LLMDebugResponse `json:"response,omitempty"`
Fallback *debugStructuredCompletionResponse `json:"fallback,omitempty"` Fallback *debugStructuredCompletionResponse `json:"fallback,omitempty"`
ContentPath string `json:"content_path,omitempty"`
Error string `json:"error,omitempty"` Error string `json:"error,omitempty"`
} }
@@ -181,6 +186,7 @@ type debugLLMCallReference struct {
CallID string `json:"call_id"` CallID string `json:"call_id"`
PromptPath string `json:"prompt_path,omitempty"` PromptPath string `json:"prompt_path,omitempty"`
ResponsePath string `json:"response_path"` ResponsePath string `json:"response_path"`
ResponseContentPath string `json:"response_content_path,omitempty"`
PromptID string `json:"prompt_id,omitempty"` PromptID string `json:"prompt_id,omitempty"`
ProfileID string `json:"profile_id,omitempty"` ProfileID string `json:"profile_id,omitempty"`
Model string `json:"model,omitempty"` Model string `json:"model,omitempty"`
@@ -274,6 +280,10 @@ func (client *debugLLMClient) CompleteStructured(ctx context.Context, req contra
})) }))
} }
responsePath := path.Join(scopePrefix, "response-"+callID+".json") responsePath := path.Join(scopePrefix, "response-"+callID+".json")
responseMaterial := debugResponseMaterial(response)
fallbackMaterial := debugCompletionFallback(response)
responseContentPath, responseForArtifact, fallbackForArtifact, contentErr := writeDebugResponseContent(client.recorder, scopePrefix, callID, responseMaterial, fallbackMaterial)
writeErr = errors.Join(writeErr, contentErr)
writeErr = errors.Join(writeErr, writeDebugTimed(client.recorder, responsePath, debugTimedEnvelope{ writeErr = errors.Join(writeErr, writeDebugTimed(client.recorder, responsePath, debugTimedEnvelope{
Stage: req.StageName, Stage: req.StageName,
ModuleKey: req.StageName, ModuleKey: req.StageName,
@@ -282,8 +292,9 @@ func (client *debugLLMClient) CompleteStructured(ctx context.Context, req contra
DurationMS: completed.Sub(started).Milliseconds(), DurationMS: completed.Sub(started).Milliseconds(),
Payload: debugLLMResponseArtifact{ Payload: debugLLMResponseArtifact{
CallID: callID, CallID: callID,
Response: debugResponseMaterial(response), Response: responseForArtifact,
Fallback: debugCompletionFallback(response), Fallback: fallbackForArtifact,
ContentPath: responseContentPath,
Error: errorText, Error: errorText,
}, },
Error: errorText, Error: errorText,
@@ -292,6 +303,7 @@ func (client *debugLLMClient) CompleteStructured(ctx context.Context, req contra
CallID: callID, CallID: callID,
PromptPath: promptPath, PromptPath: promptPath,
ResponsePath: responsePath, ResponsePath: responsePath,
ResponseContentPath: responseContentPath,
PromptID: req.PromptID, PromptID: req.PromptID,
ProfileID: debugFirstNonEmptyString(response.ProfileID, req.ProfileID), ProfileID: debugFirstNonEmptyString(response.ProfileID, req.ProfileID),
Model: debugFirstNonEmptyString(response.Model, debugResponseModel(response)), Model: debugFirstNonEmptyString(response.Model, debugResponseModel(response)),
@@ -593,6 +605,60 @@ func debugCompletionFallback(response contracts.StructuredCompletionResponse) *d
return &fallback return &fallback
} }
func writeDebugResponseContent(recorder DebugRecorder, scopePrefix string, callID string, response *contracts.LLMDebugResponse, fallback *debugStructuredCompletionResponse) (string, *contracts.LLMDebugResponse, *debugStructuredCompletionResponse, error) {
responseCopy := cloneDebugResponseWithoutContent(response)
fallbackCopy := cloneDebugFallbackWithoutContent(fallback)
content := ""
if response != nil {
content = response.Content
}
if content == "" && fallback != nil {
content = fallback.Content
}
if content == "" {
return "", responseCopy, fallbackCopy, nil
}
contentPath, data := debugResponseContentFile(scopePrefix, callID, content)
if recorder == nil || !recorder.Enabled() {
return contentPath, responseCopy, fallbackCopy, nil
}
if err := recorder.WriteBytes(contentPath, data); err != nil {
return contentPath, responseCopy, fallbackCopy, err
}
return contentPath, responseCopy, fallbackCopy, nil
}
func cloneDebugResponseWithoutContent(response *contracts.LLMDebugResponse) *contracts.LLMDebugResponse {
if response == nil {
return nil
}
clone := *response
clone.Content = ""
return &clone
}
func cloneDebugFallbackWithoutContent(fallback *debugStructuredCompletionResponse) *debugStructuredCompletionResponse {
if fallback == nil {
return nil
}
clone := *fallback
clone.Content = ""
return &clone
}
func debugResponseContentFile(scopePrefix string, callID string, content string) (string, []byte) {
raw := []byte(content)
if json.Valid(raw) {
var formatted bytes.Buffer
if err := json.Indent(&formatted, raw, "", " "); err == nil {
formatted.WriteByte('\n')
return path.Join(scopePrefix, "response-content-"+callID+".json"), formatted.Bytes()
}
}
return path.Join(scopePrefix, "response-content-"+callID+".txt"), raw
}
func debugResponseMaterial(response contracts.StructuredCompletionResponse) *contracts.LLMDebugResponse { func debugResponseMaterial(response contracts.StructuredCompletionResponse) *contracts.LLMDebugResponse {
if response.Debug == nil { if response.Debug == nil {
return nil return nil

View File

@@ -1310,7 +1310,7 @@ func TestRunDebugFailedChunkAttemptReferencesScopedLLMOutput(t *testing.T) {
t.Fatalf("llm_calls = %#v, want one scoped call", attempt.LLMCalls) t.Fatalf("llm_calls = %#v, want one scoped call", attempt.LLMCalls)
} }
call := attempt.LLMCalls[0] call := attempt.LLMCalls[0]
if call.CallID != "0001" || call.PromptPath != "chunk/attempt-01/prompt-0001.json" || call.ResponsePath != "chunk/attempt-01/response-0001.json" { if call.CallID != "0001" || call.PromptPath != "chunk/attempt-01/prompt-0001.json" || call.ResponsePath != "chunk/attempt-01/response-0001.json" || call.ResponseContentPath != "chunk/attempt-01/response-content-0001.json" {
t.Fatalf("llm call reference = %#v, want prompt and response paths", call) t.Fatalf("llm call reference = %#v, want prompt and response paths", call)
} }
if call.PromptID != "runner.chunk" || call.ProfileID != "debug-profile" || call.Model != "debug-model" || call.Error { if call.PromptID != "runner.chunk" || call.ProfileID != "debug-profile" || call.Model != "debug-model" || call.Error {
@@ -1331,8 +1331,14 @@ func TestRunDebugFailedChunkAttemptReferencesScopedLLMOutput(t *testing.T) {
if !ok { if !ok {
t.Fatalf("response payload type = %T, want debugLLMResponseArtifact", response.Payload) t.Fatalf("response payload type = %T, want debugLLMResponseArtifact", response.Payload)
} }
if responsePayload.Response == nil || responsePayload.Response.Content != `{"raw":true}` { if responsePayload.ContentPath != call.ResponseContentPath {
t.Fatalf("response payload = %#v, want raw LLM response", responsePayload) t.Fatalf("response content path = %q, want %q", responsePayload.ContentPath, call.ResponseContentPath)
}
if responsePayload.Response == nil || responsePayload.Response.Content != "" {
t.Fatalf("response payload = %#v, want metadata without inline content", responsePayload)
}
if got := string(recorder.bytes[call.ResponseContentPath]); got != "{\n \"raw\": true\n}\n" {
t.Fatalf("response content file = %q, want pretty JSON", got)
} }
if _, ok := recorder.payloads["llm/call-0001.json"]; ok { if _, ok := recorder.payloads["llm/call-0001.json"]; ok {
t.Fatalf("old canonical LLM debug artifact was written") t.Fatalf("old canonical LLM debug artifact was written")
@@ -1342,6 +1348,43 @@ func TestRunDebugFailedChunkAttemptReferencesScopedLLMOutput(t *testing.T) {
} }
} }
func TestRunDebugWritesNonJSONLLMResponseContentAsText(t *testing.T) {
modules := defaultRunnerModules()
modules.chunker.callLLM = true
modules.chunker.llmPromptID = "runner.chunk"
modules.chunker.err = errors.New("malformed structured output")
recorder := newMemoryDebugRecorder()
_, err := New(newRunnerRegistries(t, modules)).Run(context.Background(), RunInput{
Pipeline: resolvedPipeline(),
LLMClient: debugResponseLLMClient{content: []byte("plain text response"), profileID: "debug-profile"},
Debug: recorder,
})
if err == nil || !strings.Contains(err.Error(), "malformed structured output") {
t.Fatalf("Run() error = %v, want chunk failure", err)
}
attempt := recorder.envelope(t, "chunk/attempt-01.json")
if len(attempt.LLMCalls) != 1 {
t.Fatalf("llm_calls = %#v, want one scoped call", attempt.LLMCalls)
}
call := attempt.LLMCalls[0]
if call.ResponseContentPath != "chunk/attempt-01/response-content-0001.txt" {
t.Fatalf("response content path = %q, want .txt file", call.ResponseContentPath)
}
if got := string(recorder.bytes[call.ResponseContentPath]); got != "plain text response" {
t.Fatalf("response text content = %q, want raw text", got)
}
response := recorder.envelope(t, call.ResponsePath)
responsePayload, ok := response.Payload.(debugLLMResponseArtifact)
if !ok {
t.Fatalf("response payload type = %T, want debugLLMResponseArtifact", response.Payload)
}
if responsePayload.Response == nil || responsePayload.Response.Content != "" {
t.Fatalf("response payload = %#v, want metadata without inline content", responsePayload)
}
}
func TestRunStopsRetryAfterConfiguredAttemptsAndRecordsAttemptCount(t *testing.T) { func TestRunStopsRetryAfterConfiguredAttemptsAndRecordsAttemptCount(t *testing.T) {
modules := defaultRunnerModules() modules := defaultRunnerModules()
validator := &runnerChainValidator{name: "chain-extract", approved: []bool{false}, reason: "bad_extract", message: "extract rejected"} validator := &runnerChainValidator{name: "chain-extract", approved: []bool{false}, reason: "bad_extract", message: "extract rejected"}
@@ -2367,10 +2410,14 @@ func (client debugResponseLLMClient) CompleteStructured(ctx context.Context, req
type memoryDebugRecorder struct { type memoryDebugRecorder struct {
payloads map[string]any payloads map[string]any
bytes map[string][]byte
} }
func newMemoryDebugRecorder() *memoryDebugRecorder { func newMemoryDebugRecorder() *memoryDebugRecorder {
return &memoryDebugRecorder{payloads: map[string]any{}} return &memoryDebugRecorder{
payloads: map[string]any{},
bytes: map[string][]byte{},
}
} }
func (recorder *memoryDebugRecorder) Enabled() bool { return true } func (recorder *memoryDebugRecorder) Enabled() bool { return true }
@@ -2380,6 +2427,11 @@ func (recorder *memoryDebugRecorder) WriteJSON(name string, payload any) error {
return nil return nil
} }
func (recorder *memoryDebugRecorder) WriteBytes(name string, data []byte) error {
recorder.bytes[name] = append([]byte(nil), data...)
return nil
}
func (recorder *memoryDebugRecorder) envelope(t *testing.T, name string) debugTimedEnvelope { func (recorder *memoryDebugRecorder) envelope(t *testing.T, name string) debugTimedEnvelope {
t.Helper() t.Helper()
payload, ok := recorder.payloads[name] payload, ok := recorder.payloads[name]