From 19a7206d12e066f9a8e9638d7f7888961e6c59ef Mon Sep 17 00:00:00 2001 From: Autumn-27 <53844290+Autumn-27@users.noreply.github.com> Date: Tue, 25 Aug 2026 09:40:05 -0400 Subject: [PATCH] =?UTF-8?q?feat(llmrec):=20=E5=BD=95=E5=88=B6=20LLM=20?= =?UTF-8?q?=E8=AF=B7=E6=B1=82/=E5=93=8D=E5=BA=94=20HTTP=20=E5=8E=9F?= =?UTF-8?q?=E6=96=87?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 归一化视图(request_body/response_body)会丢弃工具 schema、tool_use 块， 且看不到原始 SSE 帧，排查 provider 侧问题时信息不足。新增在 HTTP transport 层捕获真实 wire body 的能力： - llmrec: 新增 Capture，Recorder 挂到 ctx，quotaAwareTransport 填充。 请求取 GetBody 副本(不消费原 body)，响应用 tee 保持流式;norma 内部重试 的多次尝试逐次保留(旧代码会读掉丢弃),单次时为字节级原文。 - db: llm_records 增加 raw_request/raw_response 两列，含旧库 ALTER 迁移。 - web: 录制页详情面板增加「原文」视图切换，及请求/响应内容复制按钮 (兼容非安全上下文的 execCommand 回退)。 - 测试: 单元(capture)、端到端(逐字节比对捕获=服务器实际收到)、 迁移(真实 PG 事务回滚)、全链路(Recorder→provider→PG 落库)。 --- agent/provider.go | 37 ++++- agent/provider_capture_e2e_test.go | 131 ++++++++++++++++ agent/provider_capture_test.go | 125 ++++++++++++++++ db/commands.go | 28 +++- db/llm_records_migrate_test.go | 62 ++++++++ llmrec/capture.go | 140 ++++++++++++++++++ llmrec/capture_test.go | 103 +++++++++++++ llmrec/llmrec.go | 15 +- server/llmrec_raw_test.go | 133 +++++++++++++++++ .../app/(main)/function/llm-records/page.tsx | 86 ++++++++++- web/src/lib/mock/data.ts | 36 +++++ web/src/lib/types.ts | 5 + 12 files changed, 884 insertions(+), 17 deletions(-) create mode 100644 agent/provider_capture_e2e_test.go create mode 100644 agent/provider_capture_test.go create mode 100644 db/llm_records_migrate_test.go create mode 100644 llmrec/capture.go create mode 100644 llmrec/capture_test.go create mode 100644 server/llmrec_raw_test.go diff --git a/agent/provider.go b/agent/provider.go index 6011ada..3a576e7 100644 --- a/agent/provider.go +++ b/agent/provider.go @@ -19,6 +19,7 @@ import ( "strings" "time" + "github.com/Autumn-27/artex/llmrec" "github.com/Autumn-27/norma/agentcore" "github.com/Autumn-27/norma/compaction" "github.com/Autumn-27/norma/llm" @@ -247,10 +248,25 @@ func IsQuotaExhaustedMessage(message string) bool { type quotaAwareTransport struct{ base http.RoundTripper } func (t quotaAwareTransport) RoundTrip(req *http.Request) (*http.Response, error) { + // When LLM recording is on, the Recorder puts a Capture on the context so the + // raw wire bodies can be persisted. This is the only layer that still sees + // them: norma builds the request body internally and decodes the SSE response + // before either reaches the recorder. + capt := llmrec.CaptureFrom(req.Context()) + capt.SetRequest(requestBodySnapshot(req)) + resp, err := t.base.RoundTrip(req) - if err != nil || resp == nil || resp.StatusCode != http.StatusTooManyRequests { + if err != nil || resp == nil { return resp, err } + // Tee rather than read: a 200 is an SSE stream that must keep streaming. The + // 429 branch below reads through this wrapper, so its body lands in the + // capture before being replaced. + resp.Body = capt.TeeResponse(resp.StatusCode, resp.Body) + + if resp.StatusCode != http.StatusTooManyRequests { + return resp, nil + } body, readErr := io.ReadAll(resp.Body) _ = resp.Body.Close() resp.Body = io.NopCloser(bytes.NewReader(body)) @@ -265,6 +281,25 @@ func (t quotaAwareTransport) RoundTrip(req *http.Request) (*http.Response, error return resp, nil } +// requestBodySnapshot copies an outgoing request body without consuming it. +// norma builds every model request from a *bytes.Reader, so net/http populates +// GetBody and the copy has no effect on what gets sent. +func requestBodySnapshot(req *http.Request) string { + if req.GetBody == nil { + return "" + } + rc, err := req.GetBody() + if err != nil { + return "" + } + defer rc.Close() + b, err := io.ReadAll(rc) + if err != nil { + return "" + } + return string(b) +} + func quotaAwareHTTPClient(proxy string) (*http.Client, error) { transport := http.DefaultTransport.(*http.Transport).Clone() proxy = strings.TrimSpace(proxy) diff --git a/agent/provider_capture_e2e_test.go b/agent/provider_capture_e2e_test.go new file mode 100644 index 0000000..3405f6d --- /dev/null +++ b/agent/provider_capture_e2e_test.go @@ -0,0 +1,131 @@ +package agent + +import ( + "context" + "encoding/json" + "io" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/Autumn-27/artex/llmrec" + "github.com/Autumn-27/norma/llm" +) + +// End-to-end through a real norma provider: the Capture rides the context into +// norma, survives its internal request building, and comes back holding the +// exact bytes buildBody() put on the wire. This is the load-bearing assumption +// of the whole feature — norma must propagate the caller's context down to +// http.NewRequestWithContext. +func TestCapturePropagatesThroughNormaProvider(t *testing.T) { + sse := strings.Join([]string{ + `event: message_start`, + `data: {"type":"message_start","message":{"id":"msg_1","usage":{"input_tokens":11,"output_tokens":1}}}`, + ``, + `event: content_block_delta`, + `data: {"type":"content_block_delta","index":0,"delta":{"type":"text_delta","text":"hello"}}`, + ``, + `event: message_delta`, + `data: {"type":"message_delta","delta":{"stop_reason":"end_turn"},"usage":{"output_tokens":7}}`, + ``, + `event: message_stop`, + `data: {"type":"message_stop"}`, + ``, + }, "\n") + + // Record exactly what the server receives, so the capture can be compared + // against it byte for byte rather than merely spot-checked for fields. + var gotPath, serverSaw string + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + gotPath = r.URL.Path + b, err := io.ReadAll(r.Body) + if err != nil { + t.Errorf("server read body: %v", err) + } + serverSaw = string(b) + w.Header().Set("content-type", "text/event-stream") + _, _ = io.WriteString(w, sse) + })) + defer srv.Close() + + cfg := Config{ + Format: llm.FormatAnthropic, + BaseURL: srv.URL, + APIKey: "test-key", + Model: "claude-test", + } + prov, err := cfg.NewProvider() + if err != nil { + t.Fatalf("NewProvider: %v", err) + } + + ctx, capt := llmrec.NewCapture(context.Background()) + req := llm.CompletionRequest{ + System: []string{"you are a scanner"}, + Messages: []llm.Message{{Role: "user", Content: []llm.ContentBlock{{Type: "text", Text: "go"}}}}, + Tools: []llm.ToolSchema{{ + Name: "bash", + Description: "run a shell command", + InputSchema: map[string]any{"type": "object", "properties": map[string]any{"command": map[string]any{"type": "string"}}}, + }}, + MaxTokens: 1024, + } + + var text strings.Builder + for ev, err := range prov.Stream(ctx, req) { + if err != nil { + t.Fatalf("stream: %v", err) + } + if ev.Type == llm.SETextDelta { + text.WriteString(ev.Text) + } + } + if text.String() != "hello" { + t.Fatalf("stream text=%q, capture interfered with delivery", text.String()) + } + if gotPath != "/v1/messages" { + t.Fatalf("path=%q", gotPath) + } + + // The raw request must be what norma actually sent, not the recorder's + // re-serialization — which is exactly why it carries fields the normalized + // view drops. + raw := capt.RawRequest() + if raw == "" { + t.Fatal("no raw request captured — context did not reach the transport") + } + // The load-bearing claim: what we stored equals, byte for byte, what the + // server received — not merely "has the right fields". + if raw != serverSaw { + t.Fatalf("captured request != what the server received:\n got: %q\nsaw: %q", raw, serverSaw) + } + var body map[string]any + if err := json.Unmarshal([]byte(raw), &body); err != nil { + t.Fatalf("raw request is not valid JSON: %v\n%s", err, raw) + } + if body["model"] != "claude-test" { + t.Errorf("model=%v want claude-test (absent from CompletionRequest)", body["model"]) + } + if body["stream"] != true { + t.Errorf("stream=%v want true", body["stream"]) + } + // The full tool schema is the headline gain: the normalized view keeps names only. + tools, _ := body["tools"].([]any) + if len(tools) != 1 { + t.Fatalf("tools=%v", body["tools"]) + } + tool, _ := tools[0].(map[string]any) + if tool["description"] != "run a shell command" { + t.Errorf("tool description missing: %v", tool) + } + if tool["input_schema"] == nil { + t.Errorf("tool input_schema missing: %v", tool) + } + + // And the response is the untouched SSE frames, including the events the + // recorder never turns into stored output. + if capt.RawResponse() != sse { + t.Errorf("RawResponse mismatch:\n got: %q\nwant: %q", capt.RawResponse(), sse) + } +} diff --git a/agent/provider_capture_test.go b/agent/provider_capture_test.go new file mode 100644 index 0000000..514b2c7 --- /dev/null +++ b/agent/provider_capture_test.go @@ -0,0 +1,125 @@ +package agent + +import ( + "io" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/Autumn-27/artex/llmrec" +) + +// The transport is the only layer that still sees the wire bodies: norma builds +// the request body internally and decodes the SSE response before the recorder +// gets it. This checks the round trip preserves both directions untouched. +func TestRoundTripCapturesRawBodies(t *testing.T) { + const sse = "event: message_start\ndata: {\"type\":\"message_start\"}\n\nevent: message_stop\ndata: {}\n\n" + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("content-type", "text/event-stream") + _, _ = io.WriteString(w, sse) + })) + defer srv.Close() + + client, err := quotaAwareHTTPClient("") + if err != nil { + t.Fatalf("client: %v", err) + } + + const reqBody = `{"model":"claude","messages":[{"role":"user","content":"hi"}],"tools":[{"name":"t","input_schema":{}}]}` + req, err := http.NewRequest(http.MethodPost, srv.URL, strings.NewReader(reqBody)) + if err != nil { + t.Fatalf("request: %v", err) + } + ctx, capt := llmrec.NewCapture(req.Context()) + req = req.WithContext(ctx) + + resp, err := client.Do(req) + if err != nil { + t.Fatalf("do: %v", err) + } + got, err := io.ReadAll(resp.Body) + if err != nil { + t.Fatalf("read: %v", err) + } + _ = resp.Body.Close() + + if string(got) != sse { + t.Fatal("capture altered the response delivered to norma") + } + if capt.RawRequest() != reqBody { + t.Fatalf("RawRequest()=%q want %q", capt.RawRequest(), reqBody) + } + if capt.RawResponse() != sse { + t.Fatalf("RawResponse()=%q want the raw SSE frames", capt.RawResponse()) + } +} + +// A 429 body is read and replaced in-place by the quota check. Capturing must +// still see it, and the replacement body must remain readable downstream. +func TestRoundTripCaptures429BodyAlongsideQuotaRewrite(t *testing.T) { + const body = `{"error":{"message":"insufficient_quota"}}` + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusTooManyRequests) + _, _ = io.WriteString(w, body) + })) + defer srv.Close() + + client, err := quotaAwareHTTPClient("") + if err != nil { + t.Fatalf("client: %v", err) + } + req, err := http.NewRequest(http.MethodPost, srv.URL, strings.NewReader("{}")) + if err != nil { + t.Fatalf("request: %v", err) + } + ctx, capt := llmrec.NewCapture(req.Context()) + req = req.WithContext(ctx) + + resp, err := client.Do(req) + if err != nil { + t.Fatalf("do: %v", err) + } + defer resp.Body.Close() + + // Quota exhaustion is normalized to 402 so the router fails over. + if resp.StatusCode != http.StatusPaymentRequired { + t.Fatalf("status=%d want 402", resp.StatusCode) + } + if capt.RawResponse() != body { + t.Fatalf("RawResponse()=%q want %q", capt.RawResponse(), body) + } + rest, err := io.ReadAll(resp.Body) + if err != nil { + t.Fatalf("read replaced body: %v", err) + } + if string(rest) != body { + t.Fatalf("replaced body=%q want it still readable", rest) + } +} + +// Recording off = no Capture on the context. The transport must behave exactly +// as before, including the quota rewrite. +func TestRoundTripWithoutCaptureIsUnchanged(t *testing.T) { + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + _, _ = io.WriteString(w, "ok") + })) + defer srv.Close() + + client, err := quotaAwareHTTPClient("") + if err != nil { + t.Fatalf("client: %v", err) + } + resp, err := client.Post(srv.URL, "application/json", strings.NewReader("{}")) + if err != nil { + t.Fatalf("post: %v", err) + } + defer resp.Body.Close() + got, err := io.ReadAll(resp.Body) + if err != nil { + t.Fatalf("read: %v", err) + } + if string(got) != "ok" { + t.Fatalf("body=%q", got) + } +} diff --git a/db/commands.go b/db/commands.go index 27172da..9a696d0 100644 --- a/db/commands.go +++ b/db/commands.go @@ -99,6 +99,13 @@ type LLMRecord struct { Error string `json:"error,omitempty"` RequestBody string `json:"request_body,omitempty"` ResponseBody string `json:"response_body,omitempty"` + // RawRequest / RawResponse are the untouched HTTP bodies exchanged with the + // provider — the request as buildBody() sent it (full tool schemas included) + // and the raw SSE frames. RequestBody/ResponseBody above are the normalized + // view, which drops tool schemas and tool_use blocks entirely. Empty for + // records written before this was added, or when the call never reached HTTP. + RawRequest string `json:"raw_request,omitempty"` + RawResponse string `json:"raw_response,omitempty"` } const llmRecordsSchema = ` @@ -118,7 +125,9 @@ CREATE TABLE IF NOT EXISTS llm_records ( status TEXT, error TEXT, request_body TEXT, - response_body TEXT + response_body TEXT, + raw_request TEXT, + raw_response TEXT ); CREATE INDEX IF NOT EXISTS idx_llm_records_ts ON llm_records(ts); CREATE INDEX IF NOT EXISTS idx_llm_records_session ON llm_records(session_id); @@ -129,6 +138,8 @@ const llmRecordsMigrate = ` ALTER TABLE llm_records ADD COLUMN IF NOT EXISTS task_id TEXT; ALTER TABLE llm_records ADD COLUMN IF NOT EXISTS worker TEXT; ALTER TABLE llm_records ADD COLUMN IF NOT EXISTS profile_name TEXT; +ALTER TABLE llm_records ADD COLUMN IF NOT EXISTS raw_request TEXT; +ALTER TABLE llm_records ADD COLUMN IF NOT EXISTS raw_response TEXT; ` // EnsureLLMRecordsTable creates the llm_records table if it does not exist. @@ -143,11 +154,12 @@ func (d *DB) EnsureLLMRecordsTable() error { // InsertLLMRecord stores one LLM call record. func (d *DB) InsertLLMRecord(r *LLMRecord) error { _, err := d.Exec(` -INSERT INTO llm_records(model, profile_name, session_id, task_id, worker, latency_ms, input_tokens, output_tokens, cache_read, cache_write, status, error, request_body, response_body) -VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)`, +INSERT INTO llm_records(model, profile_name, session_id, task_id, worker, latency_ms, input_tokens, output_tokens, cache_read, cache_write, status, error, request_body, response_body, raw_request, raw_response) +VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14,$15,$16)`, r.Model, nullIfEmpty(r.ProfileName), r.SessionID, nullIfEmpty(r.TaskID), nullIfEmpty(r.Worker), r.LatencyMs, r.InputTokens, r.OutputTokens, r.CacheRead, r.CacheWrite, - r.Status, nullIfEmpty(r.Error), nullIfEmpty(r.RequestBody), nullIfEmpty(r.ResponseBody)) + r.Status, nullIfEmpty(r.Error), nullIfEmpty(r.RequestBody), nullIfEmpty(r.ResponseBody), + nullIfEmpty(r.RawRequest), nullIfEmpty(r.RawResponse)) return err } @@ -260,19 +272,21 @@ func (d *DB) DeleteLLMRecords(task string) (int64, error) { // GetLLMRecord returns a single LLM record with full request/response bodies. func (d *DB) GetLLMRecord(id int64) (*LLMRecord, error) { var r LLMRecord - var reqBody, respBody sql.NullString + var reqBody, respBody, rawReq, rawResp sql.NullString err := d.QueryRow(`SELECT id, ts, COALESCE(model,''), COALESCE(profile_name,''), COALESCE(session_id,''), COALESCE(task_id,''), COALESCE(worker,''), COALESCE(latency_ms,0), COALESCE(input_tokens,0), COALESCE(output_tokens,0), COALESCE(cache_read,0), COALESCE(cache_write,0), - COALESCE(status,''), COALESCE(error,''), request_body, response_body + COALESCE(status,''), COALESCE(error,''), request_body, response_body, raw_request, raw_response FROM llm_records WHERE id=$1`, id). Scan(&r.ID, &r.Ts, &r.Model, &r.ProfileName, &r.SessionID, &r.TaskID, &r.Worker, &r.LatencyMs, &r.InputTokens, &r.OutputTokens, &r.CacheRead, &r.CacheWrite, &r.Status, &r.Error, - &reqBody, &respBody) + &reqBody, &respBody, &rawReq, &rawResp) if err != nil { return nil, err } r.RequestBody = reqBody.String r.ResponseBody = respBody.String + r.RawRequest = rawReq.String + r.RawResponse = rawResp.String return &r, nil } diff --git a/db/llm_records_migrate_test.go b/db/llm_records_migrate_test.go new file mode 100644 index 0000000..135f06f --- /dev/null +++ b/db/llm_records_migrate_test.go @@ -0,0 +1,62 @@ +package db + +import ( + "testing" +) + +// The raw-body columns were added after release, so existing installs only get +// them through llmRecordsMigrate. This runs the real migration against the dev +// PG on a table stripped back to its pre-upgrade shape, inside a transaction +// that is always rolled back — PG does transactional DDL, so nothing persists. +func TestLLMRecordsMigrateAddsRawColumnsToOldTable(t *testing.T) { + d, err := Open(testDSN(t)) + if err != nil { + t.Skipf("postgres unavailable (%v) — skipping", err) + } + defer d.Close() + if err := d.EnsureLLMRecordsTable(); err != nil { + t.Fatalf("ensure: %v", err) + } + + tx, err := d.Begin() + if err != nil { + t.Fatalf("begin: %v", err) + } + defer tx.Rollback() //nolint:errcheck // the test never commits + + // Roll the table back to how a pre-upgrade install looks. + if _, err := tx.Exec(`ALTER TABLE llm_records DROP COLUMN IF EXISTS raw_request, DROP COLUMN IF EXISTS raw_response`); err != nil { + t.Fatalf("simulate old table: %v", err) + } + if _, err := tx.Exec(llmRecordsMigrate); err != nil { + t.Fatalf("migrate: %v", err) + } + + for _, col := range []string{"raw_request", "raw_response"} { + var n int + if err := tx.QueryRow( + `SELECT count(*) FROM information_schema.columns + WHERE table_name='llm_records' AND column_name=$1`, col).Scan(&n); err != nil { + t.Fatalf("inspect %s: %v", col, err) + } + if n != 1 { + t.Errorf("column %s missing after migrate", col) + } + } + + // Re-running must stay a no-op (the migration runs on every startup). + if _, err := tx.Exec(llmRecordsMigrate); err != nil { + t.Fatalf("migrate is not idempotent: %v", err) + } + + // An insert carrying raw bodies must round-trip through the migrated table. + var got string + if err := tx.QueryRow( + `INSERT INTO llm_records(model, raw_request, raw_response) VALUES ('m','{"a":1}','data: x') + RETURNING raw_response`).Scan(&got); err != nil { + t.Fatalf("insert into migrated table: %v", err) + } + if got != "data: x" { + t.Errorf("raw_response=%q want %q", got, "data: x") + } +} diff --git a/llmrec/capture.go b/llmrec/capture.go new file mode 100644 index 0000000..d0fea40 --- /dev/null +++ b/llmrec/capture.go @@ -0,0 +1,140 @@ +package llmrec + +import ( + "context" + "fmt" + "io" + "strings" + "sync" +) + +type captureContextKey struct{} + +// Capture collects the untouched wire bodies of one logical LLM call. The +// Recorder creates it and puts it on the context; the HTTP transport that norma +// dials through (agent.quotaAwareTransport) finds it there and fills it in. +// +// This exists because everything the Recorder itself sees is already normalized: +// llm.CompletionRequest is re-serialized rather than the body buildBody() sent, +// and the response arrives as decoded StreamEvents, not the SSE frames. For +// debugging a live provider, the bytes on the wire are the only ground truth. +// +// norma's doStream retries the request-establishment phase, so one Stream can +// issue several HTTP attempts. Each attempt is kept: the discarded ones (see +// norma/llm/retry.go, which closes non-final bodies unread) are exactly what +// makes rate-limit and gateway failures diagnosable. +// +// The transport writes from norma's stream-reading goroutine while the Recorder +// snapshots at stream end, so all state is mutex-guarded. +type Capture struct { + mu sync.Mutex + request string + attempts []*attempt +} + +type attempt struct { + status int + body strings.Builder +} + +// NewCapture returns a context carrying a fresh Capture, plus the Capture itself. +func NewCapture(ctx context.Context) (context.Context, *Capture) { + c := &Capture{} + return context.WithValue(ctx, captureContextKey{}, c), c +} + +// CaptureFrom returns the Capture attached to ctx, or nil when raw capture is +// off. Callers must tolerate nil — recording is a toggle, and non-recorded +// providers dial through the same transport. +func CaptureFrom(ctx context.Context) *Capture { + if ctx == nil { + return nil + } + c, _ := ctx.Value(captureContextKey{}).(*Capture) + return c +} + +// SetRequest stores the outgoing request body. Retries re-send identical bytes, +// so only the first attempt's body is kept. +func (c *Capture) SetRequest(body string) { + if c == nil || body == "" { + return + } + c.mu.Lock() + defer c.mu.Unlock() + if c.request == "" { + c.request = body + } +} + +// TeeResponse opens a new attempt and wraps rc so everything read from it is +// mirrored into that attempt. It tees rather than reads because a successful +// response is an SSE stream that must keep streaming to the caller. +func (c *Capture) TeeResponse(status int, rc io.ReadCloser) io.ReadCloser { + if c == nil || rc == nil { + return rc + } + a := &attempt{status: status} + c.mu.Lock() + c.attempts = append(c.attempts, a) + c.mu.Unlock() + return &teeBody{rc: rc, c: c, a: a} +} + +// RawRequest returns the request body as sent, or "" if nothing was captured. +func (c *Capture) RawRequest() string { + if c == nil { + return "" + } + c.mu.Lock() + defer c.mu.Unlock() + return c.request +} + +// RawResponse returns the response bytes as received. A single attempt yields +// the untouched original (copy-pasteable straight into a replay); multiple +// attempts are concatenated behind per-attempt header lines so a retry sequence +// stays readable. +func (c *Capture) RawResponse() string { + if c == nil { + return "" + } + c.mu.Lock() + defer c.mu.Unlock() + switch len(c.attempts) { + case 0: + return "" + case 1: + return c.attempts[0].body.String() + } + var b strings.Builder + for i, a := range c.attempts { + fmt.Fprintf(&b, "===== attempt %d/%d — HTTP %d =====\n", i+1, len(c.attempts), a.status) + body := a.body.String() + b.WriteString(body) + if !strings.HasSuffix(body, "\n") { + b.WriteByte('\n') + } + } + return b.String() +} + +// teeBody mirrors reads into a Capture attempt, guarded by the Capture's mutex +// so a snapshot taken mid-stream never races the writer. +type teeBody struct { + rc io.ReadCloser + c *Capture + a *attempt +} + +func (t *teeBody) Read(p []byte) (int, error) { + n, err := t.rc.Read(p) + if n > 0 { + t.c.mu.Lock() + t.a.body.Write(p[:n]) + t.c.mu.Unlock() + } + return n, err +} + +func (t *teeBody) Close() error { return t.rc.Close() } diff --git a/llmrec/capture_test.go b/llmrec/capture_test.go new file mode 100644 index 0000000..3386202 --- /dev/null +++ b/llmrec/capture_test.go @@ -0,0 +1,103 @@ +package llmrec + +import ( + "context" + "io" + "strings" + "testing" +) + +func TestCaptureFromNilAndMissing(t *testing.T) { + var nilCtx context.Context // the transport reaches here on any unrecorded call + if CaptureFrom(nilCtx) != nil { + t.Fatal("nil context should yield no capture") + } + if CaptureFrom(context.Background()) != nil { + t.Fatal("bare context should yield no capture") + } +} + +// A nil *Capture is the "recording off" path: the transport calls these on every +// request, so they must all be no-ops rather than panics. +func TestNilCaptureIsInert(t *testing.T) { + var c *Capture + c.SetRequest("body") + if got := c.RawRequest(); got != "" { + t.Fatalf("RawRequest()=%q want empty", got) + } + if got := c.RawResponse(); got != "" { + t.Fatalf("RawResponse()=%q want empty", got) + } + rc := io.NopCloser(strings.NewReader("x")) + if c.TeeResponse(200, rc) != rc { + t.Fatal("nil capture must pass the body through untouched") + } +} + +func TestCaptureSingleAttemptKeepsBytesVerbatim(t *testing.T) { + ctx, c := NewCapture(context.Background()) + if CaptureFrom(ctx) != c { + t.Fatal("capture not retrievable from its own context") + } + c.SetRequest(`{"model":"x"}`) + // Retries re-send identical bytes; only the first is kept. + c.SetRequest(`{"model":"ignored"}`) + + const sse = "event: message_start\ndata: {\"type\":\"message_start\"}\n\nevent: message_stop\ndata: {}\n\n" + body := c.TeeResponse(200, io.NopCloser(strings.NewReader(sse))) + got, err := io.ReadAll(body) + if err != nil { + t.Fatalf("read: %v", err) + } + if string(got) != sse { + t.Fatal("tee altered the stream delivered to the caller") + } + if err := body.Close(); err != nil { + t.Fatalf("close: %v", err) + } + + if c.RawRequest() != `{"model":"x"}` { + t.Fatalf("RawRequest()=%q", c.RawRequest()) + } + // A lone attempt must stay byte-identical — no headers, no framing added, so + // it can be replayed as-is. + if c.RawResponse() != sse { + t.Fatalf("RawResponse()=%q want verbatim SSE", c.RawResponse()) + } +} + +// norma's doStream discards the bodies of retried attempts (retry.go closes them +// unread), so the capture is the only place a 429 body survives. +func TestCaptureRetriedAttemptsAreAllKept(t *testing.T) { + _, c := NewCapture(context.Background()) + + first := c.TeeResponse(429, io.NopCloser(strings.NewReader(`{"error":"rate_limit"}`))) + if _, err := io.ReadAll(first); err != nil { + t.Fatalf("read first: %v", err) + } + second := c.TeeResponse(200, io.NopCloser(strings.NewReader("data: ok\n"))) + if _, err := io.ReadAll(second); err != nil { + t.Fatalf("read second: %v", err) + } + + raw := c.RawResponse() + if !strings.Contains(raw, `{"error":"rate_limit"}`) { + t.Fatalf("dropped the retried attempt body: %q", raw) + } + if !strings.Contains(raw, "data: ok") { + t.Fatalf("dropped the final attempt body: %q", raw) + } + if !strings.Contains(raw, "attempt 1/2 — HTTP 429") || !strings.Contains(raw, "attempt 2/2 — HTTP 200") { + t.Fatalf("attempts not delimited: %q", raw) + } + if strings.Index(raw, "rate_limit") > strings.Index(raw, "data: ok") { + t.Fatal("attempts stored out of order") + } +} + +func TestCaptureEmptyWhenNoHTTPHappened(t *testing.T) { + _, c := NewCapture(context.Background()) + if c.RawRequest() != "" || c.RawResponse() != "" { + t.Fatal("unused capture should be empty") + } +} diff --git a/llmrec/llmrec.go b/llmrec/llmrec.go index 1bbd55c..5fc77d1 100644 --- a/llmrec/llmrec.go +++ b/llmrec/llmrec.go @@ -110,9 +110,15 @@ func (r *Recorder) Stream(ctx context.Context, req llm.CompletionRequest) iter.S } // Serialize the request only when storing bodies (this is the expensive part). + // Alongside it, attach a Capture so the HTTP transport can hand back the + // untouched wire bodies — the normalized view below cannot reconstruct them + // (tool schemas are dropped, tool_use blocks never reach this layer, and the + // SSE framing is already decoded). See capture.go. reqBody := "" + var capt *Capture if recordBodies { reqBody = r.serializeRequest(req) + ctx, capt = NewCapture(ctx) } return func(yield func(llm.StreamEvent, error) bool) { @@ -133,7 +139,7 @@ func (r *Recorder) Stream(ctx context.Context, req llm.CompletionRequest) iter.S r.recordUsage(taskID, expID, worker, usage, int(time.Since(start).Milliseconds()), status) // Heavy trace row — only when body recording is on. if recordBodies { - r.record(req, session, taskID, worker, reqBody, start, textBuf.String(), thinkingBuf.String(), usage, stopReason, err) + r.record(req, session, taskID, worker, reqBody, capt, start, textBuf.String(), thinkingBuf.String(), usage, stopReason, err) } } @@ -210,7 +216,7 @@ func (r *Recorder) recordUsage(taskID string, expID int64, worker string, usage // record persists one LLM call to PostgreSQL before the provider stream returns. // Keeping the write inside the owning task operation means task deletion can // drain calls and then remove records without a late async insert recreating one. -func (r *Recorder) record(req llm.CompletionRequest, session, taskID, worker, reqBody string, start time.Time, text, thinking string, usage llm.Usage, stopReason string, streamErr error) { +func (r *Recorder) record(req llm.CompletionRequest, session, taskID, worker, reqBody string, capt *Capture, start time.Time, text, thinking string, usage llm.Usage, stopReason string, streamErr error) { latency := int(time.Since(start).Milliseconds()) status := "ok" errMsg := "" @@ -256,6 +262,11 @@ func (r *Recorder) record(req llm.CompletionRequest, session, taskID, worker, re Error: errMsg, RequestBody: reqBody, ResponseBody: string(respBody), + // Raw wire bodies; empty when the transport did not fill the Capture + // (e.g. a provider dialing through a client without the capture hook, or + // a call that failed before any HTTP request went out). + RawRequest: capt.RawRequest(), + RawResponse: capt.RawResponse(), } if err := r.pg.InsertLLMRecord(rec); err != nil { diff --git a/server/llmrec_raw_test.go b/server/llmrec_raw_test.go new file mode 100644 index 0000000..673ce1a --- /dev/null +++ b/server/llmrec_raw_test.go @@ -0,0 +1,133 @@ +package server + +import ( + "context" + "encoding/json" + "io" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/Autumn-27/artex/agent" + "github.com/Autumn-27/artex/llmrec" + "github.com/Autumn-27/norma/llm" + "github.com/Autumn-27/norma/transcript" +) + +// Full chain against a real PG: Recorder → norma provider → capturing transport +// → llm_records. The unit tests cover each hop; this proves the raw bodies +// actually survive all the way into the row an operator opens when debugging. +func TestRecorderPersistsRawWireBodies(t *testing.T) { + m, err := NewManager(t.TempDir(), "") + if err != nil { + t.Skipf("postgres unavailable (%v) — skipping", err) + } + defer m.Close() + pg := m.PG() + if err := pg.EnsureLLMRecordsTable(); err != nil { + t.Fatalf("ensure table: %v", err) + } + + sse := strings.Join([]string{ + `event: message_start`, + `data: {"type":"message_start","message":{"id":"msg_raw","usage":{"input_tokens":5,"output_tokens":1}}}`, + ``, + `event: content_block_delta`, + `data: {"type":"content_block_delta","index":0,"delta":{"type":"text_delta","text":"probing"}}`, + ``, + // A tool_use block: the normalized response body drops these entirely, so + // its presence in raw_response is the whole point of the feature. + `event: content_block_start`, + `data: {"type":"content_block_start","index":1,"content_block":{"type":"tool_use","id":"toolu_raw","name":"bash"}}`, + ``, + `event: content_block_delta`, + `data: {"type":"content_block_delta","index":1,"delta":{"type":"input_json_delta","partial_json":"{\"command\":\"id\"}"}}`, + ``, + `event: message_delta`, + `data: {"type":"message_delta","delta":{"stop_reason":"tool_use"},"usage":{"output_tokens":9}}`, + ``, + `event: message_stop`, + `data: {"type":"message_stop"}`, + ``, + }, "\n") + + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("content-type", "text/event-stream") + _, _ = io.WriteString(w, sse) + })) + defer srv.Close() + + cfg := agent.Config{Format: llm.FormatAnthropic, BaseURL: srv.URL, APIKey: "k", Model: "claude-raw-test"} + inner, err := cfg.NewProvider() + if err != nil { + t.Fatalf("NewProvider: %v", err) + } + const session = "exp999999-rawtest" + rec := llmrec.Wrap(inner, pg, cfg.Model, "raw-test-profile", "", "", func() bool { return true }) + + // Clean up whatever this test writes, whether or not it passes. Must be a + // defer registered after `defer m.Close()` (LIFO puts it first) — a + // t.Cleanup would run after the manager already closed the pool. + defer func() { + if _, err := pg.Exec(`DELETE FROM llm_records WHERE session_id = $1`, session); err != nil { + t.Logf("cleanup: %v", err) + } + }() + + ctx := transcript.WithSessionID(context.Background(), session) + for _, err := range rec.Stream(ctx, llm.CompletionRequest{ + System: []string{"system prompt"}, + Messages: []llm.Message{{Role: "user", Content: []llm.ContentBlock{{Type: "text", Text: "go"}}}}, + Tools: []llm.ToolSchema{{ + Name: "bash", + Description: "run a shell command", + InputSchema: map[string]any{"type": "object"}, + }}, + MaxTokens: 512, + }) { + if err != nil { + t.Fatalf("stream: %v", err) + } + } + + var id int64 + if err := pg.QueryRow(`SELECT id FROM llm_records WHERE session_id=$1 ORDER BY id DESC LIMIT 1`, session).Scan(&id); err != nil { + t.Fatalf("no record written: %v", err) + } + got, err := pg.GetLLMRecord(id) + if err != nil { + t.Fatalf("GetLLMRecord: %v", err) + } + + if got.RawResponse != sse { + t.Errorf("raw_response is not the wire bytes:\n got: %q\nwant: %q", got.RawResponse, sse) + } + // The tool call is absent from the normalized body but present in the raw one + // — the specific gap this feature closes. + if strings.Contains(got.ResponseBody, "toolu_raw") { + t.Error("normalized body unexpectedly contains the tool_use block; test no longer proves the gap") + } + if !strings.Contains(got.RawResponse, "toolu_raw") { + t.Error("raw_response lost the tool_use block") + } + + var body map[string]any + if err := json.Unmarshal([]byte(got.RawRequest), &body); err != nil { + t.Fatalf("raw_request is not valid JSON: %v\n%s", err, got.RawRequest) + } + if body["model"] != "claude-raw-test" { + t.Errorf("raw_request model=%v", body["model"]) + } + tools, _ := body["tools"].([]any) + if len(tools) != 1 { + t.Fatalf("raw_request tools=%v", body["tools"]) + } + if tool, _ := tools[0].(map[string]any); tool["input_schema"] == nil { + t.Errorf("raw_request lost the tool schema: %v", tool) + } + // The normalized request keeps tool names only, so the schema is unique to raw. + if strings.Contains(got.RequestBody, "input_schema") { + t.Error("normalized request unexpectedly carries schemas; test no longer proves the gap") + } +} diff --git a/web/src/app/(main)/function/llm-records/page.tsx b/web/src/app/(main)/function/llm-records/page.tsx index cb70c44..5f05618 100644 --- a/web/src/app/(main)/function/llm-records/page.tsx +++ b/web/src/app/(main)/function/llm-records/page.tsx @@ -9,6 +9,8 @@ import { Loader2Icon, XIcon, Trash2Icon, + CopyIcon, + CheckIcon, } from "lucide-react"; import { @@ -74,6 +76,47 @@ function tryFormatJSON(s: string): string { } } +// 复制当前框内文本的小按钮。复制成功后短暂显示对勾。text 为空/仅占位符时禁用。 +function CopyButton({ text }: { text: string }) { + const [copied, setCopied] = React.useState(false); + const timer = React.useRef | null>(null); + React.useEffect(() => () => { if (timer.current) clearTimeout(timer.current); }, []); + + const disabled = !text; + const copy = async () => { + if (disabled) return; + try { + await navigator.clipboard.writeText(text); + } catch { + // navigator.clipboard 在非安全上下文(如 http 局域网)不可用，回退到 execCommand。 + const ta = document.createElement("textarea"); + ta.value = text; + ta.style.position = "fixed"; + ta.style.opacity = "0"; + document.body.appendChild(ta); + ta.select(); + try { document.execCommand("copy"); } catch { /* 忽略：不支持则静默 */ } + document.body.removeChild(ta); + } + setCopied(true); + if (timer.current) clearTimeout(timer.current); + timer.current = setTimeout(() => setCopied(false), 1500); + }; + + return ( + + ); +} + const PAGE_SIZES = [25, 50, 100]; export default function LLMRecordsPage() { @@ -96,6 +139,21 @@ export default function LLMRecordsPage() { const [selected, setSelected] = React.useState(null); const [detail, setDetail] = React.useState(null); const [detailLoading, setDetailLoading] = React.useState(false); + // 归一化视图 / HTTP 原文视图。原文是排查 provider 侧问题的唯一依据：归一化视图 + // 不含工具 schema，响应里也没有 tool_use 块。 + const [rawView, setRawView] = React.useState(false); + + const hasRaw = !!(detail?.raw_request || detail?.raw_response); + // 开关保持用户选择，但切到一条无原文的旧记录时自动落回解析视图，而不是显示空白。 + const showRaw = rawView && hasRaw; + // 原文请求体是 JSON，pretty-print 只改排版不改语义，便于阅读；原文响应是 SSE + // 帧，tryFormatJSON 解析失败会原样返回，故两边共用一个函数即可。 + const reqText = showRaw + ? detail?.raw_request && tryFormatJSON(detail.raw_request) + : detail?.request_body && tryFormatJSON(detail.request_body); + const respText = showRaw + ? detail?.raw_response + : detail?.response_body && tryFormatJSON(detail.response_body); // Per-task delete (task picker + confirm dialog) const [tasks, setTasks] = React.useState([]); @@ -427,10 +485,22 @@ export default function LLMRecordsPage() { ) : ( Error )} + {/* 原文视图开关。旧记录没有原文，此时禁用而非静默回退，避免看着像 + 「原文与解析一致」。 */} +