TestVerboseLogCapturesTurnRecords drives a realistic two-round turn (reasoning → bash tool call → final answer) with logging on, and asserts the verbose records that make a session reconstructable for later debugging actually land in log.txt: the session header, the per-round request/packing summary
(t *testing.T)
| 699 | // dated timestamp: a bare clock can't be correlated across a day boundary. This |
| 700 | // is the regression guard against a refactor silently gutting the debug log. |
| 701 | func TestVerboseLogCapturesTurnRecords(t *testing.T) { |
| 702 | var round int |
| 703 | handler := func(w http.ResponseWriter, _ *http.Request) { |
| 704 | w.Header().Set("Content-Type", "text/event-stream") |
| 705 | round++ |
| 706 | if round == 1 { |
| 707 | fmt.Fprintf(w, "data: %s\n\n", `{"choices":[{"delta":{"reasoning":"let me check the file"}}]}`) |
| 708 | fmt.Fprintf(w, "data: %s\n\n", `{"choices":[{"delta":{"tool_calls":[{"index":0,"id":"c1","function":{"name":"bash","arguments":"{\"cmd\":\"echo HAMMER\"}"}}]}}]}`) |
| 709 | fmt.Fprintf(w, "data: %s\n\n", `{"choices":[{"delta":{},"finish_reason":"tool_calls"}],"usage":{"completion_tokens":5}}`) |
| 710 | fmt.Fprint(w, "data: [DONE]\n\n") |
| 711 | return |
| 712 | } |
| 713 | fmt.Fprintf(w, "data: %s\n\n", `{"choices":[{"delta":{"content":"all done"}}]}`) |
| 714 | fmt.Fprintf(w, "data: %s\n\n", `{"choices":[{"delta":{},"finish_reason":"stop"}],"usage":{"completion_tokens":2}}`) |
| 715 | fmt.Fprint(w, "data: [DONE]\n\n") |
| 716 | } |
| 717 | |
| 718 | dir := t.TempDir() |
| 719 | OpenDebugLog(dir) |
| 720 | t.Cleanup(CloseDebugLog) |
| 721 | // Logging is on before New runs (inside newTestModel), so the session header |
| 722 | // is captured too: it writes to the global dbgFile, not cfg.Dir. |
| 723 | m := newTestModel(t, handler) |
| 724 | mm, cmd := m.submit("inspect the repo", "inspect the repo", promptEntry{display: "inspect the repo"}) |
| 725 | drain(mm, cmd) |
| 726 | CloseDebugLog() |
| 727 | |
| 728 | raw, err := os.ReadFile(filepath.Join(dir, "log.txt")) |
| 729 | if err != nil { |
| 730 | t.Fatal(err) |
| 731 | } |
| 732 | logStr := string(raw) |
| 733 | |
| 734 | for _, want := range []string{ |
| 735 | "] session", "context_size=", // backend + budget header |
| 736 | "] user", "inspect the repo", // the prompt |
| 737 | "] request", "packed=", // per-round packing summary |
| 738 | "] reasoning", "let me check the file", // streamed chain-of-thought |
| 739 | "] tool_result", // the bash result |
| 740 | "] assistant", // final assistant message |
| 741 | "] round_done", "elapsed=", // per-round metrics |
| 742 | "] turn_end", // turn totals |
| 743 | } { |
| 744 | if !strings.Contains(logStr, want) { |
| 745 | t.Fatalf("verbose log missing %q\n--- log.txt ---\n%s", want, logStr) |
| 746 | } |
| 747 | } |
| 748 | |
| 749 | // Dated timestamp: "[2006-01-02 15:04:05.000]", not the old bare clock. |
| 750 | first := logStr[:strings.IndexByte(logStr, '\n')] |
| 751 | if len(first) < 21 || first[0] != '[' || first[5] != '-' || first[8] != '-' || first[11] != ' ' { |
| 752 | t.Fatalf("log timestamp missing date component: %q", first) |
| 753 | } |
| 754 | } |
| 755 | |
| 756 | // TestCtxPressureTripwire: the round_done companion warning fires only when the |
| 757 | // server-counted prompt reaches 95% of the active window. The char/4 packer |
nothing calls this directly
no test coverage detected