diff --git a/cmd/entire/cli/agent/agent.go b/cmd/entire/cli/agent/agent.go index f068580dff..ff9dd8a114 100644 --- a/cmd/entire/cli/agent/agent.go +++ b/cmd/entire/cli/agent/agent.go @@ -68,7 +68,7 @@ type Agent interface { ResolveSessionFile(sessionDir, agentSessionID string) string // ReadSession reads session data from agent's storage. - ReadSession(input *HookInput) (*AgentSession, error) + ReadSession(ctx context.Context, input *HookInput) (*AgentSession, error) // WriteSession writes session data for resumption. WriteSession(ctx context.Context, session *AgentSession) error @@ -184,7 +184,7 @@ type TokenCalculator interface { Agent // CalculateTokenUsage computes token usage from the transcript starting at the given offset. - CalculateTokenUsage(transcriptData []byte, fromOffset int) (*TokenUsage, error) + CalculateTokenUsage(ctx context.Context, transcriptData []byte, fromOffset int) (*TokenUsage, error) } // TextGenerator is an optional interface for agents whose CLI supports diff --git a/cmd/entire/cli/agent/agent_test.go b/cmd/entire/cli/agent/agent_test.go index 26e0fc43aa..2d90e7909f 100644 --- a/cmd/entire/cli/agent/agent_test.go +++ b/cmd/entire/cli/agent/agent_test.go @@ -42,7 +42,9 @@ func (m *mockAgent) ResolveSessionFile(sessionDir, agentSessionID string) string } //nolint:nilnil // Mock implementation -func (m *mockAgent) ReadSession(_ *HookInput) (*AgentSession, error) { return nil, nil } +func (m *mockAgent) ReadSession(_ context.Context, _ *HookInput) (*AgentSession, error) { + return nil, nil +} func (m *mockAgent) WriteSession(_ context.Context, _ *AgentSession) error { return nil } func (m *mockAgent) FormatResumeCommand(_ string) string { return "" } diff --git a/cmd/entire/cli/agent/capabilities_test.go b/cmd/entire/cli/agent/capabilities_test.go index 5e884e08a7..c2b8856db8 100644 --- a/cmd/entire/cli/agent/capabilities_test.go +++ b/cmd/entire/cli/agent/capabilities_test.go @@ -23,11 +23,13 @@ func (m *mockBaseAgent) ReadTranscript(string) ([]byte, error) { return n func (m *mockBaseAgent) ChunkTranscript(context.Context, []byte, int) ([][]byte, error) { return nil, nil } -func (m *mockBaseAgent) ReassembleTranscript([][]byte) ([]byte, error) { return nil, nil } -func (m *mockBaseAgent) GetSessionID(*HookInput) string { return "" } -func (m *mockBaseAgent) GetSessionDir(string) (string, error) { return "", nil } -func (m *mockBaseAgent) ResolveSessionFile(string, string) string { return "" } -func (m *mockBaseAgent) ReadSession(*HookInput) (*AgentSession, error) { return nil, nil } //nolint:nilnil // test mock +func (m *mockBaseAgent) ReassembleTranscript([][]byte) ([]byte, error) { return nil, nil } +func (m *mockBaseAgent) GetSessionID(*HookInput) string { return "" } +func (m *mockBaseAgent) GetSessionDir(string) (string, error) { return "", nil } +func (m *mockBaseAgent) ResolveSessionFile(string, string) string { return "" } +func (m *mockBaseAgent) ReadSession(context.Context, *HookInput) (*AgentSession, error) { + return nil, nil //nolint:nilnil // test mock +} func (m *mockBaseAgent) WriteSession(context.Context, *AgentSession) error { return nil } func (m *mockBaseAgent) FormatResumeCommand(string) string { return "" } @@ -76,7 +78,9 @@ func (m *mockFullAgent) ExtractSummary(string) (string, error) { return " func (m *mockFullAgent) PrepareTranscript(context.Context, string) error { return nil } // TokenCalculator -func (m *mockFullAgent) CalculateTokenUsage([]byte, int) (*TokenUsage, error) { return nil, nil } //nolint:nilnil // test mock +func (m *mockFullAgent) CalculateTokenUsage(context.Context, []byte, int) (*TokenUsage, error) { + return nil, nil //nolint:nilnil // test mock +} // TextGenerator func (m *mockFullAgent) GenerateText(context.Context, string, string) (string, error) { diff --git a/cmd/entire/cli/agent/claudecode/claude.go b/cmd/entire/cli/agent/claudecode/claude.go index e0364cbea5..83a29143e9 100644 --- a/cmd/entire/cli/agent/claudecode/claude.go +++ b/cmd/entire/cli/agent/claudecode/claude.go @@ -121,7 +121,7 @@ func (c *ClaudeCodeAgent) GetSessionBaseDir() (string, error) { // ReadSession reads a session from Claude's storage (JSONL transcript file). // The session data is stored in NativeData as raw JSONL bytes. // ModifiedFiles is computed by parsing the transcript. -func (c *ClaudeCodeAgent) ReadSession(input *agent.HookInput) (*agent.AgentSession, error) { +func (c *ClaudeCodeAgent) ReadSession(_ context.Context, input *agent.HookInput) (*agent.AgentSession, error) { if input.SessionRef == "" { return nil, errors.New("session reference (transcript path) is required") } @@ -251,8 +251,8 @@ func (c *ClaudeCodeAgent) FindCheckpointUUID(session *agent.AgentSession, toolUs // ReadSessionFromPath is a convenience method that reads a session directly from a file path. // This is useful when you have the path but not a HookInput. -func (c *ClaudeCodeAgent) ReadSessionFromPath(transcriptPath, sessionID string) (*agent.AgentSession, error) { - return c.ReadSession(&agent.HookInput{ +func (c *ClaudeCodeAgent) ReadSessionFromPath(ctx context.Context, transcriptPath, sessionID string) (*agent.AgentSession, error) { + return c.ReadSession(ctx, &agent.HookInput{ SessionID: sessionID, SessionRef: transcriptPath, }) diff --git a/cmd/entire/cli/agent/claudecode/lifecycle.go b/cmd/entire/cli/agent/claudecode/lifecycle.go index d0f5b99ee7..559a606574 100644 --- a/cmd/entire/cli/agent/claudecode/lifecycle.go +++ b/cmd/entire/cli/agent/claudecode/lifecycle.go @@ -90,7 +90,7 @@ func (c *ClaudeCodeAgent) PrepareTranscript(ctx context.Context, sessionRef stri } // CalculateTokenUsage computes token usage from the transcript starting at the given line offset. -func (c *ClaudeCodeAgent) CalculateTokenUsage(transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { +func (c *ClaudeCodeAgent) CalculateTokenUsage(_ context.Context, transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { return c.CalculateTotalTokenUsage(transcriptData, fromOffset, "") } diff --git a/cmd/entire/cli/agent/codex/codex.go b/cmd/entire/cli/agent/codex/codex.go index 13c03207a9..04e6bb468f 100644 --- a/cmd/entire/cli/agent/codex/codex.go +++ b/cmd/entire/cli/agent/codex/codex.go @@ -119,7 +119,7 @@ func (c *CodexAgent) ResolveRestoredSessionFile(sessionDir, agentSessionID strin func (c *CodexAgent) ProtectedDirs() []string { return []string{".codex"} } // ReadSession reads a session from Codex's storage (JSONL rollout file). -func (c *CodexAgent) ReadSession(input *agent.HookInput) (*agent.AgentSession, error) { +func (c *CodexAgent) ReadSession(_ context.Context, input *agent.HookInput) (*agent.AgentSession, error) { if input.SessionRef == "" { return nil, errors.New("session reference (transcript path) is required") } diff --git a/cmd/entire/cli/agent/codex/codex_test.go b/cmd/entire/cli/agent/codex/codex_test.go index 8cb420a8ef..296bec49ce 100644 --- a/cmd/entire/cli/agent/codex/codex_test.go +++ b/cmd/entire/cli/agent/codex/codex_test.go @@ -125,7 +125,7 @@ func TestCodexAgent_ReadSession(t *testing.T) { ag := &CodexAgent{} path := writeSampleRollout(t) - session, err := ag.ReadSession(&agent.HookInput{ + session, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "codex-session-1", SessionRef: path, }) @@ -145,7 +145,7 @@ func TestCodexAgent_ReadSession_InvalidSessionMeta(t *testing.T) { path := filepath.Join(dir, "rollout.jsonl") require.NoError(t, os.WriteFile(path, []byte(`{"timestamp":"2026-03-25T11:31:11.754Z","type":"response_item","payload":{"type":"message"}}`), 0o600)) - _, err := ag.ReadSession(&agent.HookInput{ + _, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "codex-session-1", SessionRef: path, }) diff --git a/cmd/entire/cli/agent/codex/transcript.go b/cmd/entire/cli/agent/codex/transcript.go index 1e1619a325..9047c16af5 100644 --- a/cmd/entire/cli/agent/codex/transcript.go +++ b/cmd/entire/cli/agent/codex/transcript.go @@ -3,6 +3,7 @@ package codex import ( "bufio" "bytes" + "context" "encoding/json" "errors" "fmt" @@ -197,7 +198,7 @@ func extractFilesFromApplyPatch(input string) []string { // CalculateTokenUsage computes token usage from the transcript starting at the given line offset. // Codex reports cumulative total_token_usage, so we compute the delta between the last // token_count at/before the offset and the last token_count after the offset. -func (c *CodexAgent) CalculateTokenUsage(transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { +func (c *CodexAgent) CalculateTokenUsage(_ context.Context, transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { var baselineUsage *tokenUsageData // last token_count at or before offset var lastUsage *tokenUsageData // last token_count after offset apiCalls := 0 diff --git a/cmd/entire/cli/agent/codex/transcript_test.go b/cmd/entire/cli/agent/codex/transcript_test.go index 1d6419e888..4bc95b6119 100644 --- a/cmd/entire/cli/agent/codex/transcript_test.go +++ b/cmd/entire/cli/agent/codex/transcript_test.go @@ -98,7 +98,7 @@ func TestCalculateTokenUsage(t *testing.T) { ag := &CodexAgent{} // From offset 0 (no baseline), should return full cumulative total - usage, err := ag.CalculateTokenUsage([]byte(sampleRollout), 0) + usage, err := ag.CalculateTokenUsage(t.Context(), []byte(sampleRollout), 0) require.NoError(t, err) require.NotNil(t, usage) @@ -115,7 +115,7 @@ func TestCalculateTokenUsage_WithOffset(t *testing.T) { // Skip past first token_count (line 4) — baseline is {5000, 4000, 100} // Last after offset is {15000, 12000, 300} → delta = {10000, 8000, 200} - usage, err := ag.CalculateTokenUsage([]byte(sampleRollout), 4) + usage, err := ag.CalculateTokenUsage(t.Context(), []byte(sampleRollout), 4) require.NoError(t, err) require.NotNil(t, usage) @@ -130,7 +130,7 @@ func TestCalculateTokenUsage_NoData(t *testing.T) { t.Parallel() ag := &CodexAgent{} - usage, err := ag.CalculateTokenUsage([]byte(`{"timestamp":"t","type":"session_meta","payload":{}}`), 0) + usage, err := ag.CalculateTokenUsage(t.Context(), []byte(`{"timestamp":"t","type":"session_meta","payload":{}}`), 0) require.NoError(t, err) require.Nil(t, usage) } diff --git a/cmd/entire/cli/agent/copilotcli/copilotcli.go b/cmd/entire/cli/agent/copilotcli/copilotcli.go index db6f1e4323..735a872502 100644 --- a/cmd/entire/cli/agent/copilotcli/copilotcli.go +++ b/cmd/entire/cli/agent/copilotcli/copilotcli.go @@ -85,7 +85,7 @@ func (c *CopilotCLIAgent) ProtectedDirs() []string { } // ReadSession reads a session from Copilot CLI's storage (JSONL transcript file). -func (c *CopilotCLIAgent) ReadSession(input *agent.HookInput) (*agent.AgentSession, error) { +func (c *CopilotCLIAgent) ReadSession(_ context.Context, input *agent.HookInput) (*agent.AgentSession, error) { if input.SessionRef == "" { return nil, errors.New("session reference (transcript path) is required") } diff --git a/cmd/entire/cli/agent/copilotcli/copilotcli_test.go b/cmd/entire/cli/agent/copilotcli/copilotcli_test.go index b0607596db..0f63185dcf 100644 --- a/cmd/entire/cli/agent/copilotcli/copilotcli_test.go +++ b/cmd/entire/cli/agent/copilotcli/copilotcli_test.go @@ -156,7 +156,7 @@ func TestReadSession_Success(t *testing.T) { SessionRef: transcriptPath, } - session, err := ag.ReadSession(input) + session, err := ag.ReadSession(t.Context(), input) if err != nil { t.Fatalf("ReadSession() error = %v", err) } @@ -189,7 +189,7 @@ func TestReadSession_NativeDataMatchesFile(t *testing.T) { SessionRef: transcriptPath, } - session, err := ag.ReadSession(input) + session, err := ag.ReadSession(t.Context(), input) if err != nil { t.Fatalf("ReadSession() error = %v", err) } @@ -209,7 +209,7 @@ func TestReadSession_EmptySessionRef(t *testing.T) { ag := &CopilotCLIAgent{} input := &agent.HookInput{SessionID: "sess-no-ref"} - _, err := ag.ReadSession(input) + _, err := ag.ReadSession(t.Context(), input) if err == nil { t.Fatal("ReadSession() should error when SessionRef is empty") } @@ -223,7 +223,7 @@ func TestReadSession_MissingFile(t *testing.T) { SessionRef: "/nonexistent/path/events.jsonl", } - _, err := ag.ReadSession(input) + _, err := ag.ReadSession(t.Context(), input) if err == nil { t.Fatal("ReadSession() should error when transcript file doesn't exist") } @@ -271,7 +271,7 @@ func TestWriteSession_RoundTrip(t *testing.T) { SessionID: "roundtrip-session", SessionRef: transcriptPath, } - session, err := ag.ReadSession(input) + session, err := ag.ReadSession(t.Context(), input) if err != nil { t.Fatalf("ReadSession() error = %v", err) } @@ -562,7 +562,7 @@ func TestReadTranscript_MatchesReadSession(t *testing.T) { t.Fatalf("ReadTranscript() error = %v", err) } - session, err := ag.ReadSession(&agent.HookInput{ + session, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "compare-session", SessionRef: transcriptPath, }) diff --git a/cmd/entire/cli/agent/copilotcli/transcript.go b/cmd/entire/cli/agent/copilotcli/transcript.go index dfaba92fd2..69c5ccc4c3 100644 --- a/cmd/entire/cli/agent/copilotcli/transcript.go +++ b/cmd/entire/cli/agent/copilotcli/transcript.go @@ -7,6 +7,7 @@ import ( "encoding/json" "fmt" "io" + "log/slog" "os" "github.com/entireio/cli/cmd/entire/cli/agent" @@ -267,19 +268,19 @@ const eventTypeSessionShutdown = "session.shutdown" // contains session-wide aggregates. For sliced transcripts, session.shutdown // would overcount because it is not checkpoint-scoped, so we fall back to // summing assistant.message outputTokens within the slice. -func (c *CopilotCLIAgent) CalculateTokenUsage(transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { +func (c *CopilotCLIAgent) CalculateTokenUsage(ctx context.Context, transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { events, err := parseEventsFromOffset(transcriptData, fromOffset) if err != nil { return nil, fmt.Errorf("failed to parse transcript for token usage: %w", err) } - return extractTokenUsageFromEvents(events, fromOffset == 0), nil + return extractTokenUsageFromEvents(ctx, events, fromOffset == 0), nil } // extractTokenUsageFromEvents extracts token usage from parsed events. // Prefers session.shutdown aggregate only when the caller is looking at the // full transcript; otherwise falls back to per-message outputTokens. -func extractTokenUsageFromEvents(events []copilotEvent, preferSessionShutdown bool) *agent.TokenUsage { +func extractTokenUsageFromEvents(ctx context.Context, events []copilotEvent, preferSessionShutdown bool) *agent.TokenUsage { if preferSessionShutdown { // session.shutdown is authoritative, but only for full-session totals. for i := len(events) - 1; i >= 0; i-- { @@ -289,8 +290,8 @@ func extractTokenUsageFromEvents(events []copilotEvent, preferSessionShutdown bo var data sessionShutdownData if err := json.Unmarshal(events[i].Data, &data); err != nil { - logging.Debug(context.Background(), "copilot-cli: session.shutdown data unmarshal failed", - "err", err) + logging.Debug(ctx, "copilot-cli: session.shutdown data unmarshal failed", + slog.String("err", err.Error())) continue } diff --git a/cmd/entire/cli/agent/copilotcli/transcript_test.go b/cmd/entire/cli/agent/copilotcli/transcript_test.go index bff55641a5..44decbf699 100644 --- a/cmd/entire/cli/agent/copilotcli/transcript_test.go +++ b/cmd/entire/cli/agent/copilotcli/transcript_test.go @@ -382,7 +382,7 @@ func TestCalculateTokenUsage_SessionShutdown(t *testing.T) { ) content := []byte(strings.Join(lines, "\n") + "\n") - usage, err := ag.CalculateTokenUsage(content, 0) + usage, err := ag.CalculateTokenUsage(t.Context(), content, 0) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -412,7 +412,7 @@ func TestCalculateTokenUsage_MultiModel(t *testing.T) { } content := []byte(strings.Join(lines, "\n") + "\n") - usage, err := ag.CalculateTokenUsage(content, 0) + usage, err := ag.CalculateTokenUsage(t.Context(), content, 0) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -445,7 +445,7 @@ func TestCalculateTokenUsage_EmptyModelMetrics(t *testing.T) { } content := []byte(strings.Join(lines, "\n") + "\n") - usage, err := ag.CalculateTokenUsage(content, 0) + usage, err := ag.CalculateTokenUsage(t.Context(), content, 0) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -468,7 +468,7 @@ func TestCalculateTokenUsage_FallbackToAssistantMessages(t *testing.T) { } content := []byte(strings.Join(lines, "\n") + "\n") - usage, err := ag.CalculateTokenUsage(content, 0) + usage, err := ag.CalculateTokenUsage(t.Context(), content, 0) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -487,7 +487,7 @@ func TestCalculateTokenUsage_EmptyTranscript(t *testing.T) { t.Parallel() ag := &CopilotCLIAgent{} - usage, err := ag.CalculateTokenUsage([]byte{}, 0) + usage, err := ag.CalculateTokenUsage(t.Context(), []byte{}, 0) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -509,7 +509,7 @@ func TestCalculateTokenUsage_WithOffset(t *testing.T) { } content := []byte(strings.Join(lines, "\n") + "\n") - usage, err := ag.CalculateTokenUsage(content, 1) + usage, err := ag.CalculateTokenUsage(t.Context(), content, 1) if err != nil { t.Fatalf("unexpected error: %v", err) } diff --git a/cmd/entire/cli/agent/cursor/cursor.go b/cmd/entire/cli/agent/cursor/cursor.go index af91d49964..c34641de9e 100644 --- a/cmd/entire/cli/agent/cursor/cursor.go +++ b/cmd/entire/cli/agent/cursor/cursor.go @@ -125,7 +125,7 @@ func (c *CursorAgent) GetSessionBaseDir() (string, error) { // Note: ModifiedFiles is left empty because Cursor's transcript does not contain // tool_use blocks for file detection. TranscriptAnalyzer extracts prompts and // summaries; file detection relies on git status. -func (c *CursorAgent) ReadSession(input *agent.HookInput) (*agent.AgentSession, error) { +func (c *CursorAgent) ReadSession(_ context.Context, input *agent.HookInput) (*agent.AgentSession, error) { if input.SessionRef == "" { return nil, errors.New("session reference (transcript path) is required") } diff --git a/cmd/entire/cli/agent/cursor/cursor_test.go b/cmd/entire/cli/agent/cursor/cursor_test.go index e95117fd69..8dbdb9859f 100644 --- a/cmd/entire/cli/agent/cursor/cursor_test.go +++ b/cmd/entire/cli/agent/cursor/cursor_test.go @@ -239,7 +239,7 @@ func TestReadSession_Success(t *testing.T) { SessionRef: transcriptPath, } - session, err := ag.ReadSession(input) + session, err := ag.ReadSession(t.Context(), input) if err != nil { t.Fatalf("ReadSession() error = %v", err) } @@ -272,7 +272,7 @@ func TestReadSession_NativeDataMatchesFile(t *testing.T) { SessionRef: transcriptPath, } - session, err := ag.ReadSession(input) + session, err := ag.ReadSession(t.Context(), input) if err != nil { t.Fatalf("ReadSession() error = %v", err) } @@ -298,7 +298,7 @@ func TestReadSession_ModifiedFilesEmpty(t *testing.T) { SessionRef: transcriptPath, } - session, err := ag.ReadSession(input) + session, err := ag.ReadSession(t.Context(), input) if err != nil { t.Fatalf("ReadSession() error = %v", err) } @@ -315,7 +315,7 @@ func TestReadSession_EmptySessionRef(t *testing.T) { ag := &CursorAgent{} input := &agent.HookInput{SessionID: "sess-no-ref"} - _, err := ag.ReadSession(input) + _, err := ag.ReadSession(t.Context(), input) if err == nil { t.Fatal("ReadSession() should error when SessionRef is empty") } @@ -329,7 +329,7 @@ func TestReadSession_MissingFile(t *testing.T) { SessionRef: "/nonexistent/path/transcript.jsonl", } - _, err := ag.ReadSession(input) + _, err := ag.ReadSession(t.Context(), input) if err == nil { t.Fatal("ReadSession() should error when transcript file doesn't exist") } @@ -377,7 +377,7 @@ func TestWriteSession_RoundTrip(t *testing.T) { SessionID: "roundtrip-session", SessionRef: transcriptPath, } - session, err := ag.ReadSession(input) + session, err := ag.ReadSession(t.Context(), input) if err != nil { t.Fatalf("ReadSession() error = %v", err) } diff --git a/cmd/entire/cli/agent/cursor/lifecycle_test.go b/cmd/entire/cli/agent/cursor/lifecycle_test.go index 3490ca536d..21a77a9a73 100644 --- a/cmd/entire/cli/agent/cursor/lifecycle_test.go +++ b/cmd/entire/cli/agent/cursor/lifecycle_test.go @@ -627,7 +627,7 @@ func TestReadTranscript_MatchesReadSession(t *testing.T) { } // ReadSession - session, err := ag.ReadSession(&agent.HookInput{ + session, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "compare-session", SessionRef: transcriptPath, }) diff --git a/cmd/entire/cli/agent/external/capabilities.go b/cmd/entire/cli/agent/external/capabilities.go index 791eda074f..07c0fe6b3c 100644 --- a/cmd/entire/cli/agent/external/capabilities.go +++ b/cmd/entire/cli/agent/external/capabilities.go @@ -69,8 +69,8 @@ func (w *wrappedAgent) GetSessionDir(repoPath string) (string, error) { func (w *wrappedAgent) ResolveSessionFile(dir, id string) string { return w.ea.ResolveSessionFile(dir, id) } -func (w *wrappedAgent) ReadSession(input *agent.HookInput) (*agent.AgentSession, error) { - return w.ea.ReadSession(input) +func (w *wrappedAgent) ReadSession(ctx context.Context, input *agent.HookInput) (*agent.AgentSession, error) { + return w.ea.ReadSession(ctx, input) } func (w *wrappedAgent) WriteSession(ctx context.Context, s *agent.AgentSession) error { return w.ea.WriteSession(ctx, s) @@ -114,8 +114,8 @@ func (w *wrappedAgent) PrepareTranscript(ctx context.Context, ref string) error // --- TokenCalculator --- -func (w *wrappedAgent) CalculateTokenUsage(data []byte, offset int) (*agent.TokenUsage, error) { - return w.ea.CalculateTokenUsage(data, offset) +func (w *wrappedAgent) CalculateTokenUsage(ctx context.Context, data []byte, offset int) (*agent.TokenUsage, error) { + return w.ea.CalculateTokenUsage(ctx, data, offset) } // --- TextGenerator --- diff --git a/cmd/entire/cli/agent/external/discovery_test.go b/cmd/entire/cli/agent/external/discovery_test.go index 60057b094d..7334f1eb6b 100644 --- a/cmd/entire/cli/agent/external/discovery_test.go +++ b/cmd/entire/cli/agent/external/discovery_test.go @@ -348,7 +348,7 @@ func (f *fakeBuiltInAgent) ReassembleTranscript([][]byte) ([]byte, error) { retu func (f *fakeBuiltInAgent) GetSessionID(*agent.HookInput) string { return "" } func (f *fakeBuiltInAgent) GetSessionDir(string) (string, error) { return "", nil } func (f *fakeBuiltInAgent) ResolveSessionFile(string, string) string { return "" } -func (f *fakeBuiltInAgent) ReadSession(*agent.HookInput) (*agent.AgentSession, error) { +func (f *fakeBuiltInAgent) ReadSession(context.Context, *agent.HookInput) (*agent.AgentSession, error) { return nil, nil //nolint:nilnil // test fake — no session is a valid state } func (f *fakeBuiltInAgent) WriteSession(context.Context, *agent.AgentSession) error { return nil } diff --git a/cmd/entire/cli/agent/external/external.go b/cmd/entire/cli/agent/external/external.go index 5817c45cca..b2c8b940d8 100644 --- a/cmd/entire/cli/agent/external/external.go +++ b/cmd/entire/cli/agent/external/external.go @@ -184,7 +184,7 @@ func (e *Agent) ResolveSessionFile(sessionDir, agentSessionID string) string { return resp.SessionFile } -func (e *Agent) ReadSession(input *agent.HookInput) (*agent.AgentSession, error) { +func (e *Agent) ReadSession(_ context.Context, input *agent.HookInput) (*agent.AgentSession, error) { data, err := marshalHookInput(input) if err != nil { return nil, fmt.Errorf("read-session: marshal: %w", err) @@ -354,7 +354,7 @@ func (e *Agent) PrepareTranscript(ctx context.Context, sessionRef string) error // --- TokenCalculator methods --- -func (e *Agent) CalculateTokenUsage(transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { +func (e *Agent) CalculateTokenUsage(_ context.Context, transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { stdout, err := e.run(context.Background(), transcriptData, "calculate-tokens", "--offset", strconv.Itoa(fromOffset)) if err != nil { diff --git a/cmd/entire/cli/agent/factoryaidroid/factoryaidroid.go b/cmd/entire/cli/agent/factoryaidroid/factoryaidroid.go index a563ac8abc..158e7df47a 100644 --- a/cmd/entire/cli/agent/factoryaidroid/factoryaidroid.go +++ b/cmd/entire/cli/agent/factoryaidroid/factoryaidroid.go @@ -126,7 +126,7 @@ func (f *FactoryAIDroidAgent) ResolveSessionFile(sessionDir, agentSessionID stri // ReadSession reads a session from Factory AI Droid's storage (JSONL transcript file). // The session data is stored in NativeData as raw JSONL bytes. // ModifiedFiles is computed by parsing the transcript. -func (f *FactoryAIDroidAgent) ReadSession(input *agent.HookInput) (*agent.AgentSession, error) { +func (f *FactoryAIDroidAgent) ReadSession(_ context.Context, input *agent.HookInput) (*agent.AgentSession, error) { if input.SessionRef == "" { return nil, errors.New("session reference (transcript path) is required") } diff --git a/cmd/entire/cli/agent/factoryaidroid/factoryaidroid_test.go b/cmd/entire/cli/agent/factoryaidroid/factoryaidroid_test.go index 4041d5ccbd..692756988e 100644 --- a/cmd/entire/cli/agent/factoryaidroid/factoryaidroid_test.go +++ b/cmd/entire/cli/agent/factoryaidroid/factoryaidroid_test.go @@ -170,7 +170,7 @@ func TestReadSession(t *testing.T) { } ag := &FactoryAIDroidAgent{} - session, err := ag.ReadSession(&agent.HookInput{ + session, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "test-session-123", SessionRef: transcriptPath, }) @@ -198,7 +198,7 @@ func TestReadSession(t *testing.T) { func TestReadSession_EmptyRef(t *testing.T) { t.Parallel() ag := &FactoryAIDroidAgent{} - _, err := ag.ReadSession(&agent.HookInput{SessionID: "test"}) + _, err := ag.ReadSession(t.Context(), &agent.HookInput{SessionID: "test"}) if err == nil { t.Error("ReadSession() should error on empty SessionRef") } @@ -207,7 +207,7 @@ func TestReadSession_EmptyRef(t *testing.T) { func TestReadSession_MissingFile(t *testing.T) { t.Parallel() ag := &FactoryAIDroidAgent{} - _, err := ag.ReadSession(&agent.HookInput{ + _, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "test", SessionRef: "/nonexistent/path/transcript.jsonl", }) @@ -306,7 +306,7 @@ func TestReadWriteSession_RoundTrip(t *testing.T) { ag := &FactoryAIDroidAgent{} // Read from original location - session, err := ag.ReadSession(&agent.HookInput{ + session, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "round-trip-test", SessionRef: originalPath, }) diff --git a/cmd/entire/cli/agent/factoryaidroid/lifecycle.go b/cmd/entire/cli/agent/factoryaidroid/lifecycle.go index e8bddcdb24..d8ee57c0da 100644 --- a/cmd/entire/cli/agent/factoryaidroid/lifecycle.go +++ b/cmd/entire/cli/agent/factoryaidroid/lifecycle.go @@ -148,7 +148,7 @@ func (f *FactoryAIDroidAgent) ExtractSummary(sessionRef string) (string, error) // --- TokenCalculator --- // CalculateTokenUsage computes token usage from pre-loaded transcript bytes starting at the given line offset. -func (f *FactoryAIDroidAgent) CalculateTokenUsage(transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { +func (f *FactoryAIDroidAgent) CalculateTokenUsage(_ context.Context, transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { return CalculateTotalTokenUsageFromBytes(transcriptData, fromOffset, "") } diff --git a/cmd/entire/cli/agent/geminicli/gemini.go b/cmd/entire/cli/agent/geminicli/gemini.go index 664bed3999..4ffe75afb8 100644 --- a/cmd/entire/cli/agent/geminicli/gemini.go +++ b/cmd/entire/cli/agent/geminicli/gemini.go @@ -138,7 +138,7 @@ func (g *GeminiCLIAgent) GetSessionBaseDir() (string, error) { // ReadSession reads a session from Gemini's storage (JSON transcript file). // The session data is stored in NativeData as raw JSON bytes. -func (g *GeminiCLIAgent) ReadSession(input *agent.HookInput) (*agent.AgentSession, error) { +func (g *GeminiCLIAgent) ReadSession(_ context.Context, input *agent.HookInput) (*agent.AgentSession, error) { if input.SessionRef == "" { return nil, errors.New("session reference (transcript path) is required") } diff --git a/cmd/entire/cli/agent/geminicli/gemini_test.go b/cmd/entire/cli/agent/geminicli/gemini_test.go index d5d73602fc..fac209f268 100644 --- a/cmd/entire/cli/agent/geminicli/gemini_test.go +++ b/cmd/entire/cli/agent/geminicli/gemini_test.go @@ -209,7 +209,7 @@ func TestReadSession(t *testing.T) { SessionRef: transcriptPath, } - session, err := ag.ReadSession(input) + session, err := ag.ReadSession(t.Context(), input) if err != nil { t.Fatalf("ReadSession() error = %v", err) } @@ -229,7 +229,7 @@ func TestReadSession_NoSessionRef(t *testing.T) { ag := &GeminiCLIAgent{} input := &agent.HookInput{SessionID: "test-session"} - _, err := ag.ReadSession(input) + _, err := ag.ReadSession(t.Context(), input) if err == nil { t.Error("ReadSession() should error when SessionRef is empty") } diff --git a/cmd/entire/cli/agent/geminicli/lifecycle.go b/cmd/entire/cli/agent/geminicli/lifecycle.go index f9117e6603..31aa982d69 100644 --- a/cmd/entire/cli/agent/geminicli/lifecycle.go +++ b/cmd/entire/cli/agent/geminicli/lifecycle.go @@ -83,7 +83,7 @@ func (g *GeminiCLIAgent) ReadTranscript(sessionRef string) ([]byte, error) { } // CalculateTokenUsage computes token usage from the transcript starting at the given message offset. -func (g *GeminiCLIAgent) CalculateTokenUsage(transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { +func (g *GeminiCLIAgent) CalculateTokenUsage(_ context.Context, transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { var transcript struct { Messages []geminiMessageWithTokens `json:"messages"` } diff --git a/cmd/entire/cli/agent/geminicli/transcript_test.go b/cmd/entire/cli/agent/geminicli/transcript_test.go index 43b304c3ff..9b067a6f64 100644 --- a/cmd/entire/cli/agent/geminicli/transcript_test.go +++ b/cmd/entire/cli/agent/geminicli/transcript_test.go @@ -588,7 +588,7 @@ func TestCalculateTokenUsage_BasicMessages(t *testing.T) { }`) ag := &GeminiCLIAgent{} - usage, err := ag.CalculateTokenUsage(data, 0) + usage, err := ag.CalculateTokenUsage(t.Context(), data, 0) if err != nil { t.Fatalf("CalculateTokenUsage error: %v", err) } @@ -629,7 +629,7 @@ func TestCalculateTokenUsage_StartIndex(t *testing.T) { // Start from index 2 - should only count the last gemini message ag := &GeminiCLIAgent{} - usage, err := ag.CalculateTokenUsage(data, 2) + usage, err := ag.CalculateTokenUsage(t.Context(), data, 2) if err != nil { t.Fatalf("CalculateTokenUsage error: %v", err) } @@ -665,7 +665,7 @@ func TestCalculateTokenUsage_IgnoresUserMessages(t *testing.T) { }`) ag := &GeminiCLIAgent{} - usage, err := ag.CalculateTokenUsage(data, 0) + usage, err := ag.CalculateTokenUsage(t.Context(), data, 0) if err != nil { t.Fatalf("CalculateTokenUsage error: %v", err) } @@ -689,7 +689,7 @@ func TestCalculateTokenUsage_EmptyTranscript(t *testing.T) { data := []byte(`{"messages": []}`) ag := &GeminiCLIAgent{} - usage, err := ag.CalculateTokenUsage(data, 0) + usage, err := ag.CalculateTokenUsage(t.Context(), data, 0) if err != nil { t.Fatalf("CalculateTokenUsage error: %v", err) } @@ -713,7 +713,7 @@ func TestCalculateTokenUsage_InvalidJSON(t *testing.T) { data := []byte(`not valid json`) ag := &GeminiCLIAgent{} - usage, err := ag.CalculateTokenUsage(data, 0) + usage, err := ag.CalculateTokenUsage(t.Context(), data, 0) if err == nil { t.Fatal("expected error for invalid JSON, got nil") } @@ -736,7 +736,7 @@ func TestCalculateTokenUsage_MissingTokensField(t *testing.T) { }`) ag := &GeminiCLIAgent{} - usage, err := ag.CalculateTokenUsage(data, 0) + usage, err := ag.CalculateTokenUsage(t.Context(), data, 0) if err != nil { t.Fatalf("CalculateTokenUsage error: %v", err) } diff --git a/cmd/entire/cli/agent/opencode/opencode.go b/cmd/entire/cli/agent/opencode/opencode.go index 0d312d13ee..2a88866018 100644 --- a/cmd/entire/cli/agent/opencode/opencode.go +++ b/cmd/entire/cli/agent/opencode/opencode.go @@ -184,7 +184,7 @@ func (a *OpenCodeAgent) ResolveSessionFile(sessionDir, agentSessionID string) st return filepath.Join(sessionDir, agentSessionID+".json") } -func (a *OpenCodeAgent) ReadSession(input *agent.HookInput) (*agent.AgentSession, error) { +func (a *OpenCodeAgent) ReadSession(ctx context.Context, input *agent.HookInput) (*agent.AgentSession, error) { if input.SessionRef == "" { return nil, errors.New("no session ref provided") } @@ -196,8 +196,10 @@ func (a *OpenCodeAgent) ReadSession(input *agent.HookInput) (*agent.AgentSession // Parse to extract computed fields modifiedFiles, err := ExtractModifiedFiles(data) if err != nil { - // Non-fatal: we can still return the session without modified files - logging.Warn(context.Background(), "failed to extract modified files from opencode session", + // Non-fatal: we can still return the session without modified files. + // Surfacing this as a warning is important — silent failure here used + // to mask malformed transcripts in production. + logging.Warn(ctx, "failed to extract modified files from opencode session", slog.String("session_ref", input.SessionRef), slog.String("error", err.Error()), ) diff --git a/cmd/entire/cli/agent/opencode/transcript.go b/cmd/entire/cli/agent/opencode/transcript.go index 3e75b88261..bc02f325ea 100644 --- a/cmd/entire/cli/agent/opencode/transcript.go +++ b/cmd/entire/cli/agent/opencode/transcript.go @@ -1,6 +1,7 @@ package opencode import ( + "context" "encoding/json" "fmt" "os" @@ -302,7 +303,7 @@ func (a *OpenCodeAgent) ExtractPrompts(sessionRef string, fromOffset int) ([]str } // CalculateTokenUsage computes token usage from assistant messages starting at the given offset. -func (a *OpenCodeAgent) CalculateTokenUsage(transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { +func (a *OpenCodeAgent) CalculateTokenUsage(_ context.Context, transcriptData []byte, fromOffset int) (*agent.TokenUsage, error) { session, err := ParseExportSession(transcriptData) if err != nil { return nil, fmt.Errorf("failed to parse transcript for token usage: %w", err) diff --git a/cmd/entire/cli/agent/opencode/transcript_test.go b/cmd/entire/cli/agent/opencode/transcript_test.go index ab009b0882..ad290de823 100644 --- a/cmd/entire/cli/agent/opencode/transcript_test.go +++ b/cmd/entire/cli/agent/opencode/transcript_test.go @@ -487,7 +487,7 @@ func TestCalculateTokenUsage(t *testing.T) { ag := &OpenCodeAgent{} // From offset 0 — both assistant messages - usage, err := ag.CalculateTokenUsage([]byte(testExportJSON), 0) + usage, err := ag.CalculateTokenUsage(t.Context(), []byte(testExportJSON), 0) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -513,7 +513,7 @@ func TestCalculateTokenUsage_FromOffset(t *testing.T) { t.Parallel() ag := &OpenCodeAgent{} - usage, err := ag.CalculateTokenUsage([]byte(testExportJSON), 2) + usage, err := ag.CalculateTokenUsage(t.Context(), []byte(testExportJSON), 2) if err != nil { t.Fatalf("unexpected error: %v", err) } @@ -532,7 +532,7 @@ func TestCalculateTokenUsage_EmptyData(t *testing.T) { t.Parallel() ag := &OpenCodeAgent{} - usage, err := ag.CalculateTokenUsage(nil, 0) + usage, err := ag.CalculateTokenUsage(t.Context(), nil, 0) if err != nil { t.Fatalf("unexpected error: %v", err) } diff --git a/cmd/entire/cli/agent/token_usage.go b/cmd/entire/cli/agent/token_usage.go index cd9ec1920f..d2c7650b20 100644 --- a/cmd/entire/cli/agent/token_usage.go +++ b/cmd/entire/cli/agent/token_usage.go @@ -28,7 +28,7 @@ func CalculateTokenUsage(ctx context.Context, ag Agent, transcriptData []byte, t if calculator, ok := AsTokenCalculator(ag); ok { // Fall back to basic token calculation (main transcript only) - usage, err := calculator.CalculateTokenUsage(transcriptData, transcriptLinesAtStart) + usage, err := calculator.CalculateTokenUsage(ctx, transcriptData, transcriptLinesAtStart) if err != nil { logging.Debug(ctx, "failed token extraction", slog.String("error", err.Error())) diff --git a/cmd/entire/cli/agent/vogon/vogon.go b/cmd/entire/cli/agent/vogon/vogon.go index 25331b7b83..0c82f50a79 100644 --- a/cmd/entire/cli/agent/vogon/vogon.go +++ b/cmd/entire/cli/agent/vogon/vogon.go @@ -88,7 +88,7 @@ func (v *Agent) ResolveSessionFile(sessionDir, agentSessionID string) string { return filepath.Join(sessionDir, agentSessionID+".jsonl") } -func (v *Agent) ReadSession(input *agent.HookInput) (*agent.AgentSession, error) { +func (v *Agent) ReadSession(_ context.Context, input *agent.HookInput) (*agent.AgentSession, error) { if input.SessionRef == "" { return nil, errors.New("session reference (transcript path) is required") } diff --git a/cmd/entire/cli/attach.go b/cmd/entire/cli/attach.go index 1c42e46aee..f6d3b567fc 100644 --- a/cmd/entire/cli/attach.go +++ b/cmd/entire/cli/attach.go @@ -76,14 +76,7 @@ external_agents in settings. Run 'entire agent list' to see the full list.`, } func runAttach(ctx context.Context, w io.Writer, sessionID string, agentName types.AgentName, force bool) error { - // Initialize structured logger so logging.Warn/Info write to .entire/logs/ not stderr. - if err := logging.Init(ctx, sessionID); err != nil { - // Init failed — logging will use stderr fallback, non-fatal. - _ = err - } - defer logging.Close() - - logCtx := logging.WithComponent(ctx, "attach") + logCtx := logging.WithSession(logging.WithComponent(ctx, "attach"), sessionID) // Open repository once — shared across all operations. repo, err := openRepository(ctx) diff --git a/cmd/entire/cli/checkpoint/committed_tripwire_test.go b/cmd/entire/cli/checkpoint/committed_tripwire_test.go index 8baa96ef78..ac8e83b4a0 100644 --- a/cmd/entire/cli/checkpoint/committed_tripwire_test.go +++ b/cmd/entire/cli/checkpoint/committed_tripwire_test.go @@ -7,7 +7,6 @@ import ( "github.com/entireio/cli/cmd/entire/cli/checkpoint/id" "github.com/entireio/cli/cmd/entire/cli/jsonutil" - "github.com/entireio/cli/cmd/entire/cli/logging" "github.com/entireio/cli/cmd/entire/cli/paths" "github.com/entireio/cli/cmd/entire/cli/versioninfo" "github.com/entireio/cli/redact" @@ -27,10 +26,8 @@ func TestWriteStandardCheckpointEntries_RefusesUnexpectedSessionZeroOverwrite(t } store := NewGitStore(repo) - if err := logging.Init(context.Background(), ""); err != nil { - t.Fatalf("logging.Init() error = %v", err) - } - defer logging.Close() + // Logger lifecycle is owned by main.go in production; tests just need the + // no-op fallback (slog.Default) for any logging.X calls inside the tripwire. checkpointID, err := id.Generate() if err != nil { diff --git a/cmd/entire/cli/checkpoint/v2_committed_tripwire_test.go b/cmd/entire/cli/checkpoint/v2_committed_tripwire_test.go index 4f2e6e8acd..9b96fef25a 100644 --- a/cmd/entire/cli/checkpoint/v2_committed_tripwire_test.go +++ b/cmd/entire/cli/checkpoint/v2_committed_tripwire_test.go @@ -7,7 +7,6 @@ import ( "github.com/entireio/cli/cmd/entire/cli/checkpoint/id" "github.com/entireio/cli/cmd/entire/cli/jsonutil" - "github.com/entireio/cli/cmd/entire/cli/logging" "github.com/entireio/cli/cmd/entire/cli/paths" "github.com/entireio/cli/cmd/entire/cli/versioninfo" @@ -22,10 +21,8 @@ func TestV2WriteMainCheckpointEntries_RefusesUnexpectedSessionZeroOverwrite(t *t repo := initTestRepo(t) store := NewV2GitStore(repo, "origin") - if err := logging.Init(context.Background(), ""); err != nil { - t.Fatalf("logging.Init() error = %v", err) - } - defer logging.Close() + // Logger lifecycle is owned by main.go in production; tests fall back to + // slog.Default for any logging.X calls inside the tripwire. checkpointID, err := id.Generate() if err != nil { diff --git a/cmd/entire/cli/clean.go b/cmd/entire/cli/clean.go index b59c1cbc23..e7b8bff28e 100644 --- a/cmd/entire/cli/clean.go +++ b/cmd/entire/cli/clean.go @@ -11,7 +11,6 @@ import ( "charm.land/huh/v2" "github.com/entireio/cli/cmd/entire/cli/checkpoint" - "github.com/entireio/cli/cmd/entire/cli/logging" "github.com/entireio/cli/cmd/entire/cli/paths" "github.com/entireio/cli/cmd/entire/cli/session" "github.com/entireio/cli/cmd/entire/cli/settings" @@ -66,18 +65,11 @@ func newCleanCmd() *cobra.Command { return errors.New("--all and --session cannot be used together") } - // Check if in git repository before initializing logging, - // to avoid creating .entire/logs in arbitrary directories. + // Require a git worktree. if _, err := paths.WorktreeRoot(ctx); err != nil { return errors.New("not a git repository") } - // Initialize logging - logging.SetLogLevelGetter(GetLogLevel) - if err := logging.Init(ctx, ""); err == nil { - defer logging.Close() - } - if allFlag { return runCleanAll(ctx, cmd, forceFlag, dryRunFlag) } diff --git a/cmd/entire/cli/explain.go b/cmd/entire/cli/explain.go index c3820a8421..6faf7fef46 100644 --- a/cmd/entire/cli/explain.go +++ b/cmd/entire/cli/explain.go @@ -261,15 +261,6 @@ Note: --session filters the list view; the positional arg, --commit, and --check return nil } - // Only initialize logging when inside a git worktree to avoid - // creating .entire/logs/ in arbitrary directories. - if _, err := paths.WorktreeRoot(cmd.Context()); err == nil { - logging.SetLogLevelGetter(GetLogLevel) - if err := logging.Init(cmd.Context(), ""); err == nil { - defer logging.Close() - } - } - // Positional arg is mutually exclusive with --checkpoint, --commit, --session var positional string if len(args) > 0 { diff --git a/cmd/entire/cli/explain_summary_provider_test.go b/cmd/entire/cli/explain_summary_provider_test.go index 67f10053dc..970ee56f5e 100644 --- a/cmd/entire/cli/explain_summary_provider_test.go +++ b/cmd/entire/cli/explain_summary_provider_test.go @@ -35,7 +35,7 @@ func (s *stubTextAgent) ReassembleTranscript([][]byte) ([]byte, error) { return func (s *stubTextAgent) GetSessionID(*agent.HookInput) string { return "" } func (s *stubTextAgent) GetSessionDir(string) (string, error) { return "", nil } func (s *stubTextAgent) ResolveSessionFile(string, string) string { return "" } -func (s *stubTextAgent) ReadSession(*agent.HookInput) (*agent.AgentSession, error) { +func (s *stubTextAgent) ReadSession(context.Context, *agent.HookInput) (*agent.AgentSession, error) { return nil, nil //nolint:nilnil // test stub } func (s *stubTextAgent) WriteSession(context.Context, *agent.AgentSession) error { return nil } diff --git a/cmd/entire/cli/hook_registry.go b/cmd/entire/cli/hook_registry.go index 0ca44bdae8..daab5317a6 100644 --- a/cmd/entire/cli/hook_registry.go +++ b/cmd/entire/cli/hook_registry.go @@ -20,10 +20,6 @@ import ( "github.com/spf13/cobra" ) -// agentHookLogCleanup stores the cleanup function for agent hook logging. -// Set by PersistentPreRunE, called by PersistentPostRunE. -var agentHookLogCleanup func() - // currentHookAgentName stores the agent name for the currently executing hook. // Set by newAgentHookVerbCmdWithLogging before calling the handler. // This allows handlers to know which agent invoked the hook without guessing. @@ -53,13 +49,7 @@ func newAgentHooksCmd(agentName types.AgentName, handler agent.HookSupport) *cob Short: handler.Description() + " hook handlers", Hidden: true, PersistentPreRunE: func(cmd *cobra.Command, _ []string) error { - agentHookLogCleanup = initHookLogging(cmd.Context()) - return nil - }, - PersistentPostRunE: func(_ *cobra.Command, _ []string) error { - if agentHookLogCleanup != nil { - agentHookLogCleanup() - } + cmd.SetContext(enrichHookContext(cmd.Context())) return nil }, } @@ -86,13 +76,12 @@ func getHookType(hookName string) string { } } -// executeAgentHook runs the core hook execution logic for a given agent and hook name. -// It handles git repo checks, enabled checks, logging, event parsing, and lifecycle dispatch. -// Used by both the registered subcommand path and the RunE fallback for external agents. -// When initLogging is true, it initializes and cleans up hook logging (used by the RunE fallback -// since it doesn't go through PersistentPreRunE). Built-in agent subcommands pass false since -// their parent command's PersistentPreRunE already handles logging. -func executeAgentHook(cmd *cobra.Command, agentName types.AgentName, hookName string, initLogging bool) error { +// executeAgentHook runs the core hook execution logic for a given agent and +// hook name. It handles git repo checks, enabled checks, event parsing, and +// lifecycle dispatch. The caller is responsible for ensuring cmd.Context() +// has been enriched via enrichHookContext (built-in subcommands do this in +// PersistentPreRunE; the external RunE fallback does it before calling). +func executeAgentHook(cmd *cobra.Command, agentName types.AgentName, hookName string) error { // Skip silently if not in a git repository - hooks shouldn't prevent the agent from working if _, err := paths.WorktreeRoot(cmd.Context()); err != nil { return nil @@ -104,11 +93,6 @@ func executeAgentHook(cmd *cobra.Command, agentName types.AgentName, hookName st return nil } - if initLogging { - cleanup := initHookLogging(cmd.Context()) - defer cleanup() - } - // Initialize logging context with agent name ctx := logging.WithAgent(logging.WithComponent(cmd.Context(), "hooks"), agentName) @@ -173,7 +157,7 @@ func newAgentHookVerbCmdWithLogging(agentName types.AgentName, hookName string) Hidden: true, Short: "Called on " + hookName, RunE: func(cmd *cobra.Command, _ []string) error { - return executeAgentHook(cmd, agentName, hookName, false) + return executeAgentHook(cmd, agentName, hookName) }, } } diff --git a/cmd/entire/cli/hook_registry_test.go b/cmd/entire/cli/hook_registry_test.go index f869138847..70693be878 100644 --- a/cmd/entire/cli/hook_registry_test.go +++ b/cmd/entire/cli/hook_registry_test.go @@ -14,6 +14,7 @@ import ( "github.com/entireio/cli/cmd/entire/cli/agent" "github.com/entireio/cli/cmd/entire/cli/agent/claudecode" "github.com/entireio/cli/cmd/entire/cli/logging" + "github.com/entireio/cli/cmd/entire/cli/logging/loggingtest" "github.com/entireio/cli/cmd/entire/cli/paths" "github.com/entireio/cli/cmd/entire/cli/session" "github.com/entireio/cli/cmd/entire/cli/testutil" @@ -82,9 +83,9 @@ func TestNewAgentHookVerbCmd_LogsInvocation(t *testing.T) { // Enable debug logging t.Setenv(logging.LogLevelEnvVar, "DEBUG") - // Initialize logging (normally done by PersistentPreRunE) - cleanup := initHookLogging(context.Background()) - defer cleanup() + // Inject a buffer-backed logger via loggingtest to capture the hook's + // log output. In production main.go installs the logger via WithLogger. + ctx, buf := loggingtest.New(t) // Create a transcript file for the hook input transcriptPath := filepath.Join(tmpDir, "transcript.jsonl") @@ -93,7 +94,7 @@ func TestNewAgentHookVerbCmd_LogsInvocation(t *testing.T) { } // Create stdin with session-start hook input - hookInput := map[string]interface{}{ + hookInput := map[string]any{ "session_id": sessionID, "transcript_path": transcriptPath, } @@ -102,7 +103,8 @@ func TestNewAgentHookVerbCmd_LogsInvocation(t *testing.T) { // Create the command with logging - use session-start hook which is a pass-through cmd := newAgentHookVerbCmdWithLogging(agent.AgentNameClaudeCode, claudecode.HookNameSessionStart) - // Set stdin + // Set stdin and the test ctx + cmd.SetContext(ctx) cmd.SetIn(bytes.NewReader(inputJSON)) cmd.SetOut(&bytes.Buffer{}) cmd.SetErr(&bytes.Buffer{}) @@ -113,50 +115,25 @@ func TestNewAgentHookVerbCmd_LogsInvocation(t *testing.T) { t.Fatalf("command execution failed: %v", err) } - // Close logging to flush - cleanup() - - // Verify log file was created and contains expected content - logFile := filepath.Join(logsDir, "entire.log") - content, err := os.ReadFile(logFile) - if err != nil { - t.Fatalf("failed to read log file: %v", err) + records := loggingtest.Records(t, buf) + if len(records) == 0 { + t.Fatal("expected at least one log record") } - logContent := string(content) - t.Logf("log content: %s", logContent) - - // Parse each log line as JSON - lines := strings.Split(strings.TrimSpace(logContent), "\n") - if len(lines) == 0 { - t.Fatal("expected at least one log line") - } - - // Check for hook invocation log and perf span log foundInvocation := false foundPerfSpan := false - for _, line := range lines { - var entry map[string]interface{} - if err := json.Unmarshal([]byte(line), &entry); err != nil { - t.Errorf("failed to parse log line as JSON: %v", err) - continue - } - - msg, msgOK := entry["msg"].(string) - - // Hook invocation log: msg="hook invoked", hook="session-start" - if msgOK && entry["hook"] == claudecode.HookNameSessionStart && strings.Contains(msg, "invoked") { + for _, rec := range records { + // Hook invocation log: msg contains "invoked", hook="session-start" + if rec.Attrs["hook"] == claudecode.HookNameSessionStart && strings.Contains(rec.Msg, "invoked") { foundInvocation = true - // Verify component is set - if entry["component"] != "hooks" { - t.Errorf("expected component='hooks', got %v", entry["component"]) + if rec.Attrs["component"] != "hooks" { + t.Errorf("expected component='hooks', got %v", rec.Attrs["component"]) } } - // Perf span log: msg="perf", op="session-start", duration_ms present - if msgOK && msg == "perf" && entry["op"] == claudecode.HookNameSessionStart { + if rec.Msg == "perf" && rec.Attrs["op"] == claudecode.HookNameSessionStart { foundPerfSpan = true - if _, ok := entry["duration_ms"]; !ok { + if _, ok := rec.Attrs["duration_ms"]; !ok { t.Error("expected duration_ms in perf span log") } } @@ -188,14 +165,11 @@ func TestClaudeCodeHooksCmd_HasLoggingHooks(t *testing.T) { require.NotNil(t, claudeCodeCmd, "expected to find claude-code subcommand under hooks") - // Verify PersistentPreRunE is set + // PersistentPreRunE enriches the cobra context with the discovered + // session ID. The logger and log file are owned by main.go, so no + // PersistentPostRunE cleanup is needed. if claudeCodeCmd.PersistentPreRunE == nil { - t.Error("expected PersistentPreRunE to be set for logging initialization") - } - - // Verify PersistentPostRunE is set - if claudeCodeCmd.PersistentPostRunE == nil { - t.Error("expected PersistentPostRunE to be set for logging cleanup") + t.Error("expected PersistentPreRunE to be set for ctx enrichment") } } @@ -217,14 +191,11 @@ func TestGeminiCLIHooksCmd_HasLoggingHooks(t *testing.T) { require.NotNil(t, geminiCmd, "expected to find gemini subcommand under hooks") - // Verify PersistentPreRunE is set + // PersistentPreRunE enriches the cobra context with the discovered + // session ID. The logger and log file are owned by main.go, so no + // PersistentPostRunE cleanup is needed. if geminiCmd.PersistentPreRunE == nil { - t.Error("expected PersistentPreRunE to be set for logging initialization") - } - - // Verify PersistentPostRunE is set - if geminiCmd.PersistentPostRunE == nil { - t.Error("expected PersistentPostRunE to be set for logging cleanup") + t.Error("expected PersistentPreRunE to be set for ctx enrichment") } } diff --git a/cmd/entire/cli/hooks_cmd.go b/cmd/entire/cli/hooks_cmd.go index 229dfaa604..390cfd07a4 100644 --- a/cmd/entire/cli/hooks_cmd.go +++ b/cmd/entire/cli/hooks_cmd.go @@ -51,7 +51,8 @@ func newHooksCmd() *cobra.Command { return fmt.Errorf("unknown agent %q (not found as built-in or external plugin)", agentName) } - return executeAgentHook(cmd, agentName, hookName, true) + cmd.SetContext(enrichHookContext(cmd.Context())) + return executeAgentHook(cmd, agentName, hookName) }, } diff --git a/cmd/entire/cli/hooks_git_cmd.go b/cmd/entire/cli/hooks_git_cmd.go index 43a220cf53..eb478d3b75 100644 --- a/cmd/entire/cli/hooks_git_cmd.go +++ b/cmd/entire/cli/hooks_git_cmd.go @@ -58,36 +58,24 @@ func (g *gitHookContext) logCompleted(err error) { g.span.RecordError(err) } -// initHookLogging initializes logging for hooks by finding the most recent session. -// Returns a cleanup function that should be deferred. -// If Entire is not set up or disabled, returns a no-op to avoid creating files. -func initHookLogging(ctx context.Context) func() { - // Don't create any files if Entire is not set up or disabled. - // This is checked here as defense-in-depth (also checked in PersistentPreRunE). +// enrichHookContext attaches the discovered session ID to the ctx-carried +// logger and configures redaction. The logger and log file are owned by +// main.go; this just enriches the per-request context. +// +// Returns the original ctx unchanged if Entire is not set up or disabled. +func enrichHookContext(ctx context.Context) context.Context { if !settings.IsSetUpAndEnabled(ctx) { - return func() {} + return ctx } - - // Set up log level getter so logging can read from settings - logging.SetLogLevelGetter(GetLogLevel) - - // Read session ID for the slog attribute (empty string is fine - log file is fixed) sessionID := strategy.FindMostRecentSession(ctx) - if err := logging.Init(ctx, sessionID); err != nil { - // Init failed - logging will use stderr fallback - return func() {} + if sessionID != "" { + ctx = logging.WithSession(ctx, sessionID) } - // Configure PII redaction once at startup (reads settings, no-op if disabled). strategy.EnsureRedactionConfigured() - - return logging.Close + return ctx } -// hookLogCleanup stores the cleanup function for hook logging. -// Set by PersistentPreRunE, called by PersistentPostRunE. -var hookLogCleanup func() - func newHooksGitCmd() *cobra.Command { cmd := &cobra.Command{ Use: "git", @@ -110,13 +98,7 @@ func newHooksGitCmd() *cobra.Command { discoveryCtx, cancel := context.WithTimeout(ctx, 5*time.Second) defer cancel() external.DiscoverAndRegister(discoveryCtx) - hookLogCleanup = initHookLogging(ctx) - return nil - }, - PersistentPostRunE: func(_ *cobra.Command, _ []string) error { - if hookLogCleanup != nil { - hookLogCleanup() - } + cmd.SetContext(enrichHookContext(ctx)) return nil }, } diff --git a/cmd/entire/cli/hooks_git_cmd_test.go b/cmd/entire/cli/hooks_git_cmd_test.go index a15f374549..60adcb673f 100644 --- a/cmd/entire/cli/hooks_git_cmd_test.go +++ b/cmd/entire/cli/hooks_git_cmd_test.go @@ -11,143 +11,100 @@ import ( "github.com/entireio/cli/cmd/entire/cli/agent" "github.com/entireio/cli/cmd/entire/cli/agent/types" + "github.com/entireio/cli/cmd/entire/cli/logging" "github.com/entireio/cli/cmd/entire/cli/paths" "github.com/entireio/cli/cmd/entire/cli/session" ) -func TestInitHookLogging(t *testing.T) { - // Create a temporary directory to simulate a git repo +func TestEnrichHookContext_AttachesSessionID(t *testing.T) { tmpDir := t.TempDir() - - // Change to temp dir (automatically restored after test) t.Chdir(tmpDir) - // Initialize git repo (required for session state store to find .git common dir) gitInit := exec.CommandContext(context.Background(), "git", "init") gitInit.Dir = tmpDir if err := gitInit.Run(); err != nil { t.Fatalf("failed to init git repo: %v", err) } - t.Run("returns cleanup func when no session state exists", func(t *testing.T) { - // Create settings.json to indicate Entire is set up - entireDir := filepath.Join(tmpDir, paths.EntireDir) - if err := os.MkdirAll(entireDir, 0o755); err != nil { - t.Fatalf("failed to create .entire directory: %v", err) - } - settingsFile := filepath.Join(entireDir, "settings.json") - if err := os.WriteFile(settingsFile, []byte(`{"enabled":true}`), 0o644); err != nil { - t.Fatalf("failed to create settings file: %v", err) - } - - cleanup := initHookLogging(context.Background()) - if cleanup == nil { - t.Fatal("expected cleanup function, got nil") - } - cleanup() // Should not panic - }) - - t.Run("initializes logging when session state exists", func(t *testing.T) { - // Create .entire directory - entireDir := filepath.Join(tmpDir, paths.EntireDir) - if err := os.MkdirAll(entireDir, 0o755); err != nil { - t.Fatalf("failed to create .entire directory: %v", err) - } - - // Create settings.json to indicate Entire is set up in this repo - settingsFile := filepath.Join(entireDir, "settings.json") - if err := os.WriteFile(settingsFile, []byte(`{"enabled":true,"strategy":"manual-commit"}`), 0o644); err != nil { - t.Fatalf("failed to create settings file: %v", err) - } - - // Create session state file in .git/entire-sessions/ - sessionID := "test-session-12345" - stateDir := filepath.Join(tmpDir, ".git", session.SessionStateDirName) - if err := os.MkdirAll(stateDir, 0o755); err != nil { - t.Fatalf("failed to create session state directory: %v", err) - } - - now := time.Now() - state := session.State{ - SessionID: sessionID, - StartedAt: now, - LastInteractionTime: &now, - Phase: session.PhaseActive, - } - data, err := json.Marshal(state) - if err != nil { - t.Fatalf("failed to marshal state: %v", err) - } - stateFile := filepath.Join(stateDir, sessionID+".json") - if err := os.WriteFile(stateFile, data, 0o600); err != nil { - t.Fatalf("failed to write session state file: %v", err) - } - defer os.Remove(stateFile) + entireDir := filepath.Join(tmpDir, paths.EntireDir) + if err := os.MkdirAll(entireDir, 0o755); err != nil { + t.Fatalf("failed to create .entire directory: %v", err) + } + settingsFile := filepath.Join(entireDir, "settings.json") + if err := os.WriteFile(settingsFile, []byte(`{"enabled":true,"strategy":"manual-commit"}`), 0o644); err != nil { + t.Fatalf("failed to create settings file: %v", err) + } - // Create logs directory (logging.Init will try to create the log file) - logsDir := filepath.Join(entireDir, "logs") - if err := os.MkdirAll(logsDir, 0o755); err != nil { - t.Fatalf("failed to create logs directory: %v", err) - } + sessionID := "test-session-12345" + stateDir := filepath.Join(tmpDir, ".git", session.SessionStateDirName) + if err := os.MkdirAll(stateDir, 0o755); err != nil { + t.Fatalf("failed to create session state directory: %v", err) + } + now := time.Now() + state := session.State{ + SessionID: sessionID, + StartedAt: now, + LastInteractionTime: &now, + Phase: session.PhaseActive, + } + data, err := json.Marshal(state) + if err != nil { + t.Fatalf("failed to marshal state: %v", err) + } + stateFile := filepath.Join(stateDir, sessionID+".json") + if err := os.WriteFile(stateFile, data, 0o600); err != nil { + t.Fatalf("failed to write session state file: %v", err) + } + defer os.Remove(stateFile) - cleanup := initHookLogging(context.Background()) - if cleanup == nil { - t.Fatal("expected cleanup function, got nil") - } - defer cleanup() + enriched := enrichHookContext(context.Background()) + if got := logging.SessionIDFromContext(enriched); got != sessionID { + t.Errorf("enriched ctx session = %q, want %q", got, sessionID) + } - // Verify log file was created - logFile := filepath.Join(logsDir, "entire.log") - if _, err := os.Stat(logFile); os.IsNotExist(err) { - t.Errorf("expected log file to be created at %s", logFile) - } - }) + // Enrichment must not create the logs directory — file lifecycle is owned + // by main.go's lazy writer. + logsDir := filepath.Join(entireDir, "logs") + if _, err := os.Stat(logsDir); !os.IsNotExist(err) { + t.Errorf("enrichHookContext should not create %s", logsDir) + } } -// TestInitHookLogging_SkipsWhenNotSetUp tests that initHookLogging(context.Background()) does not -// create .entire/logs/ in repos where Entire has not been set up. -// This is a separate test because it needs its own t.Chdir() to a different directory. -func TestInitHookLogging_SkipsWhenNotSetUp(t *testing.T) { - // Create a temp directory without .entire/settings.json +// TestEnrichHookContext_NoOpWhenNotSetUp asserts enrichment leaves ctx +// untouched when Entire is not set up in the repo. +func TestEnrichHookContext_NoOpWhenNotSetUp(t *testing.T) { tmpDir := t.TempDir() t.Chdir(tmpDir) - // Initialize git repo gitInit := exec.CommandContext(context.Background(), "git", "init") gitInit.Dir = tmpDir if err := gitInit.Run(); err != nil { t.Fatalf("failed to init git repo: %v", err) } - // Do NOT create .entire/settings.json - simulating a repo where Entire is not set up - - cleanup := initHookLogging(context.Background()) - if cleanup == nil { - t.Fatal("expected cleanup function, got nil") + enriched := enrichHookContext(context.Background()) + if got := logging.SessionIDFromContext(enriched); got != "" { + t.Errorf("expected empty session in unset-up repo, got %q", got) } - cleanup() // Should not panic - // Verify .entire/logs was NOT created logsDir := filepath.Join(tmpDir, ".entire", "logs") if _, err := os.Stat(logsDir); !os.IsNotExist(err) { - t.Errorf("expected .entire/logs to NOT be created when Entire is not set up, but it exists") + t.Errorf("expected .entire/logs to NOT be created, but it exists") } } -// TestInitHookLogging_SkipsWhenDisabled tests that initHookLogging(context.Background()) does not -// create .entire/logs/ when Entire is set up but disabled. -func TestInitHookLogging_SkipsWhenDisabled(t *testing.T) { +// TestEnrichHookContext_NoOpWhenDisabled asserts enrichment is a no-op when +// Entire is set up but disabled. +func TestEnrichHookContext_NoOpWhenDisabled(t *testing.T) { tmpDir := t.TempDir() t.Chdir(tmpDir) - // Initialize git repo gitInit := exec.CommandContext(context.Background(), "git", "init") gitInit.Dir = tmpDir if err := gitInit.Run(); err != nil { t.Fatalf("failed to init git repo: %v", err) } - // Create .entire/settings.json with enabled: false entireDir := filepath.Join(tmpDir, paths.EntireDir) if err := os.MkdirAll(entireDir, 0o755); err != nil { t.Fatalf("failed to create .entire directory: %v", err) @@ -157,16 +114,14 @@ func TestInitHookLogging_SkipsWhenDisabled(t *testing.T) { t.Fatalf("failed to create settings file: %v", err) } - cleanup := initHookLogging(context.Background()) - if cleanup == nil { - t.Fatal("expected cleanup function, got nil") + enriched := enrichHookContext(context.Background()) + if got := logging.SessionIDFromContext(enriched); got != "" { + t.Errorf("expected empty session when disabled, got %q", got) } - cleanup() // Should not panic - // Verify .entire/logs was NOT created logsDir := filepath.Join(tmpDir, ".entire", "logs") if _, err := os.Stat(logsDir); !os.IsNotExist(err) { - t.Errorf("expected .entire/logs to NOT be created when Entire is disabled, but it exists") + t.Errorf("expected .entire/logs to NOT be created when disabled, but it exists") } } diff --git a/cmd/entire/cli/integration_test/agent_strategy_test.go b/cmd/entire/cli/integration_test/agent_strategy_test.go index a2962484e8..fa37bce794 100644 --- a/cmd/entire/cli/integration_test/agent_strategy_test.go +++ b/cmd/entire/cli/integration_test/agent_strategy_test.go @@ -37,7 +37,7 @@ func TestAgentStrategyComposition(t *testing.T) { }) // Read session via agent interface - agentSession, err := ag.ReadSession(&agent.HookInput{ + agentSession, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: session.ID, SessionRef: transcriptPath, }) diff --git a/cmd/entire/cli/integration_test/agent_test.go b/cmd/entire/cli/integration_test/agent_test.go index 16e6a4dcf1..04f866ada0 100644 --- a/cmd/entire/cli/integration_test/agent_test.go +++ b/cmd/entire/cli/integration_test/agent_test.go @@ -232,7 +232,7 @@ func TestAgentSessionOperations(t *testing.T) { } ag, _ := agent.Get("claude-code") - session, err := ag.ReadSession(&agent.HookInput{ + session, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "test-session", SessionRef: transcriptPath, }) @@ -274,7 +274,7 @@ func TestAgentSessionOperations(t *testing.T) { t.Fatalf("failed to write source: %v", err) } - session, _ := ag.ReadSession(&agent.HookInput{ + session, _ := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "test", SessionRef: srcPath, }) @@ -337,7 +337,7 @@ func TestClaudeCodeHelperMethods(t *testing.T) { ag, _ := agent.Get("claude-code") ccAgent := ag.(*claudecode.ClaudeCodeAgent) - session, _ := ag.ReadSession(&agent.HookInput{ + session, _ := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "test", SessionRef: transcriptPath, }) @@ -372,7 +372,7 @@ func TestClaudeCodeHelperMethods(t *testing.T) { ag, _ := agent.Get("claude-code") ccAgent := ag.(*claudecode.ClaudeCodeAgent) - session, _ := ag.ReadSession(&agent.HookInput{ + session, _ := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "test", SessionRef: transcriptPath, }) @@ -694,7 +694,7 @@ func TestGeminiCLISessionOperations(t *testing.T) { } ag, _ := agent.Get("gemini") - session, err := ag.ReadSession(&agent.HookInput{ + session, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "test-session", SessionRef: transcriptPath, }) @@ -735,7 +735,7 @@ func TestGeminiCLISessionOperations(t *testing.T) { t.Fatalf("failed to write source: %v", err) } - session, _ := ag.ReadSession(&agent.HookInput{ + session, _ := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "test", SessionRef: srcPath, }) @@ -1084,7 +1084,7 @@ func TestFactoryAIDroidSessionMethods(t *testing.T) { } ag, _ := agent.Get("factoryai-droid") - session, err := ag.ReadSession(&agent.HookInput{ + session, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "test", SessionRef: transcriptPath, }) @@ -1103,7 +1103,7 @@ func TestFactoryAIDroidSessionMethods(t *testing.T) { t.Parallel() ag, _ := agent.Get("factoryai-droid") - _, err := ag.ReadSession(&agent.HookInput{ + _, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "test", SessionRef: "/nonexistent/path/transcript.jsonl", }) @@ -1125,7 +1125,7 @@ func TestFactoryAIDroidSessionMethods(t *testing.T) { } ag, _ := agent.Get("factoryai-droid") - session, err := ag.ReadSession(&agent.HookInput{ + session, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "test", SessionRef: originalPath, }) @@ -1354,7 +1354,7 @@ func TestOpenCodeSessionOperations(t *testing.T) { } ag, _ := agent.Get("opencode") - session, err := ag.ReadSession(&agent.HookInput{ + session, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: "test-session", SessionRef: transcriptPath, }) diff --git a/cmd/entire/cli/integration_test/opencode_hooks_test.go b/cmd/entire/cli/integration_test/opencode_hooks_test.go index eef4bfd3fd..7c5db64e60 100644 --- a/cmd/entire/cli/integration_test/opencode_hooks_test.go +++ b/cmd/entire/cli/integration_test/opencode_hooks_test.go @@ -94,7 +94,7 @@ func TestOpenCodeAgentStrategyComposition(t *testing.T) { }) // Read session via agent interface - agentSession, err := ag.ReadSession(&agent.HookInput{ + agentSession, err := ag.ReadSession(t.Context(), &agent.HookInput{ SessionID: session.ID, SessionRef: transcriptPath, }) diff --git a/cmd/entire/cli/lifecycle_test.go b/cmd/entire/cli/lifecycle_test.go index 0875f9d951..baa7a29a77 100644 --- a/cmd/entire/cli/lifecycle_test.go +++ b/cmd/entire/cli/lifecycle_test.go @@ -65,7 +65,7 @@ func (m *mockLifecycleAgent) ResolveSessionFile(sessionDir, agentSessionID strin } //nolint:nilnil // Mock implementation -func (m *mockLifecycleAgent) ReadSession(_ *agent.HookInput) (*agent.AgentSession, error) { +func (m *mockLifecycleAgent) ReadSession(_ context.Context, _ *agent.HookInput) (*agent.AgentSession, error) { return nil, nil } diff --git a/cmd/entire/cli/logging/context.go b/cmd/entire/cli/logging/context.go index bc25e21c9b..042da763b5 100644 --- a/cmd/entire/cli/logging/context.go +++ b/cmd/entire/cli/logging/context.go @@ -2,12 +2,18 @@ package logging import ( "context" + "log/slog" "github.com/entireio/cli/cmd/entire/cli/agent/types" ) -// Context keys for logging values. -// Using private types to avoid key collisions. +// Context keys for the per-request attrs that log() materialises into slog +// records. We track values here rather than via slog.With on the ctx-logger +// because slog.With appends without deduplicating: chained With("session_id", +// "a") + With("session_id", "b") emits two session_id JSON keys, which +// violates RFC 7159's SHOULD-be-unique recommendation and breaks log +// consumers that pick the first value. Building the attr list per call from +// these typed values guarantees one value per key. type contextKey int const ( @@ -18,92 +24,82 @@ const ( agentKey ) -// WithSession adds a session ID to the context. -// If the context already has a session ID, it becomes the parent session ID. +// WithSession adds a session ID to the context. log() emits session_id on +// every record. If the context already has a different session, that one is +// promoted to parent_session_id (a common pattern for subagents). func WithSession(ctx context.Context, sessionID string) context.Context { - // If there's an existing session, it becomes the parent - existing := SessionIDFromContext(ctx) - if existing != "" && existing != sessionID { + if existing, ok := ctx.Value(sessionIDKey).(string); ok && existing != "" && existing != sessionID { ctx = context.WithValue(ctx, parentSessionIDKey, existing) } return context.WithValue(ctx, sessionIDKey, sessionID) } -// WithParentSession explicitly sets the parent session ID. -// Use this when you need to set the parent explicitly rather than -// having it inferred from an existing session. +// WithParentSession explicitly sets the parent session ID on the context. +// Use this when you need to set the parent explicitly rather than having it +// inferred from an existing session. func WithParentSession(ctx context.Context, parentSessionID string) context.Context { return context.WithValue(ctx, parentSessionIDKey, parentSessionID) } -// WithToolCall adds a tool call ID to the context. +// WithToolCall adds a tool_call_id attr to log records emitted from ctx. func WithToolCall(ctx context.Context, toolCallID string) context.Context { return context.WithValue(ctx, toolCallIDKey, toolCallID) } -// WithComponent adds a component name to the context. +// WithComponent adds a component attr to log records emitted from ctx. // Component names help identify the subsystem generating logs (e.g., "hooks", "strategy", "session"). func WithComponent(ctx context.Context, component string) context.Context { return context.WithValue(ctx, componentKey, component) } -// WithAgent adds an agent name to the context. +// WithAgent adds an agent attr to log records emitted from ctx. // Agent names identify the AI agent generating activity (e.g., "claude-code", "cursor", "aider"). func WithAgent(ctx context.Context, agentName types.AgentName) context.Context { return context.WithValue(ctx, agentKey, string(agentName)) } -// SessionIDFromContext extracts the session ID from the context. -// Returns empty string if not set. +// SessionIDFromContext returns the session ID stored by WithSession, or empty +// string if none. Useful for callers that need the raw ID for non-logging +// decisions (e.g., test assertions, hook routing). func SessionIDFromContext(ctx context.Context) string { - if v := ctx.Value(sessionIDKey); v != nil { - if s, ok := v.(string); ok { - return s - } - } - return "" + return stringFromContext(ctx, sessionIDKey) } -// ParentSessionIDFromContext extracts the parent session ID from the context. -// Returns empty string if not set. +// ParentSessionIDFromContext returns the parent session ID stored by +// WithParentSession or by WithSession's auto-promotion, or empty string if +// none. See SessionIDFromContext for usage notes. func ParentSessionIDFromContext(ctx context.Context) string { - if v := ctx.Value(parentSessionIDKey); v != nil { - if s, ok := v.(string); ok { - return s - } - } - return "" + return stringFromContext(ctx, parentSessionIDKey) } -// ToolCallIDFromContext extracts the tool call ID from the context. -// Returns empty string if not set. -func ToolCallIDFromContext(ctx context.Context) string { - if v := ctx.Value(toolCallIDKey); v != nil { - if s, ok := v.(string); ok { - return s - } +// stringFromContext returns the string value stored under key, or "". +func stringFromContext(ctx context.Context, key contextKey) string { + if s, ok := ctx.Value(key).(string); ok { + return s } return "" } -// ComponentFromContext extracts the component name from the context. -// Returns empty string if not set. -func ComponentFromContext(ctx context.Context) string { - if v := ctx.Value(componentKey); v != nil { - if s, ok := v.(string); ok { - return s - } +// attrsFromContext collects the typed-key attrs into a fresh slog.Attr slice +// in a stable order. Called from log() per-record to materialise enrichment +// without relying on slog.With (which accumulates and would emit duplicate +// keys across chained With* calls). +func attrsFromContext(ctx context.Context) []slog.Attr { + if ctx == nil { + return nil } - return "" + var attrs []slog.Attr + attrs = appendStringAttr(ctx, attrs, sessionIDKey, "session_id") + attrs = appendStringAttr(ctx, attrs, parentSessionIDKey, "parent_session_id") + attrs = appendStringAttr(ctx, attrs, toolCallIDKey, "tool_call_id") + attrs = appendStringAttr(ctx, attrs, componentKey, "component") + attrs = appendStringAttr(ctx, attrs, agentKey, "agent") + return attrs } -// AgentFromContext extracts the agent name from the context. -// Returns empty string if not set. -func AgentFromContext(ctx context.Context) string { - if v := ctx.Value(agentKey); v != nil { - if s, ok := v.(string); ok { - return s - } +func appendStringAttr(ctx context.Context, attrs []slog.Attr, key contextKey, name string) []slog.Attr { + if s := stringFromContext(ctx, key); s != "" { + return append(attrs, slog.String(name, s)) } - return "" + return attrs } diff --git a/cmd/entire/cli/logging/context_test.go b/cmd/entire/cli/logging/context_test.go index 22736b8259..c7e60533b7 100644 --- a/cmd/entire/cli/logging/context_test.go +++ b/cmd/entire/cli/logging/context_test.go @@ -7,201 +7,59 @@ import ( // testComponent and testAgent are defined in logger_test.go -func TestWithSession(t *testing.T) { +// These tests verify the typed-key bookkeeping that powers parent_session_id +// promotion. The attr-baking behaviour itself is covered end-to-end by +// TestEnrichmentChain_ComposesAllAttrs in logger_test.go. + +func TestWithSession_StoresInContext(t *testing.T) { + t.Parallel() ctx := context.Background() sessionID := "2025-01-15-test-session" ctx = WithSession(ctx, sessionID) - got := SessionIDFromContext(ctx) - if got != sessionID { + if got := SessionIDFromContext(ctx); got != sessionID { t.Errorf("SessionIDFromContext() = %q, want %q", got, sessionID) } } -func TestWithSession_SetsParentFromExisting(t *testing.T) { +func TestWithSession_PromotesParentInContext(t *testing.T) { + t.Parallel() ctx := context.Background() parentSessionID := "2025-01-15-parent-session" childSessionID := "2025-01-15-child-session" - // Set parent session ctx = WithSession(ctx, parentSessionID) - - // Set child session - should automatically set parent ctx = WithSession(ctx, childSessionID) - gotSession := SessionIDFromContext(ctx) - gotParent := ParentSessionIDFromContext(ctx) - - if gotSession != childSessionID { - t.Errorf("SessionIDFromContext() = %q, want %q", gotSession, childSessionID) + if got := SessionIDFromContext(ctx); got != childSessionID { + t.Errorf("SessionIDFromContext() = %q, want %q", got, childSessionID) } - if gotParent != parentSessionID { - t.Errorf("ParentSessionIDFromContext() = %q, want %q", gotParent, parentSessionID) + if got := ParentSessionIDFromContext(ctx); got != parentSessionID { + t.Errorf("ParentSessionIDFromContext() = %q, want %q", got, parentSessionID) } } -func TestWithParentSession(t *testing.T) { +func TestWithParentSession_StoresInContext(t *testing.T) { + t.Parallel() ctx := context.Background() parentSessionID := "2025-01-15-explicit-parent" ctx = WithParentSession(ctx, parentSessionID) - got := ParentSessionIDFromContext(ctx) - if got != parentSessionID { + if got := ParentSessionIDFromContext(ctx); got != parentSessionID { t.Errorf("ParentSessionIDFromContext() = %q, want %q", got, parentSessionID) } } -func TestWithToolCall(t *testing.T) { - ctx := context.Background() - toolCallID := "toolu_01ABC123XYZ" - - ctx = WithToolCall(ctx, toolCallID) - - got := ToolCallIDFromContext(ctx) - if got != toolCallID { - t.Errorf("ToolCallIDFromContext() = %q, want %q", got, toolCallID) - } -} - -func TestWithComponent(t *testing.T) { - ctx := context.Background() - - ctx = WithComponent(ctx, testComponent) - - got := ComponentFromContext(ctx) - if got != testComponent { - t.Errorf("ComponentFromContext() = %q, want %q", got, testComponent) - } -} - -func TestWithAgent(t *testing.T) { +func TestContextValues_EmptyByDefault(t *testing.T) { + t.Parallel() ctx := context.Background() - ctx = WithAgent(ctx, testAgent) - - got := AgentFromContext(ctx) - if got != testAgent { - t.Errorf("AgentFromContext() = %q, want %q", got, testAgent) - } -} - -func TestContextValues_Empty(t *testing.T) { - ctx := context.Background() - - // All should return empty strings for unset context if got := SessionIDFromContext(ctx); got != "" { t.Errorf("SessionIDFromContext() on empty = %q, want empty", got) } if got := ParentSessionIDFromContext(ctx); got != "" { t.Errorf("ParentSessionIDFromContext() on empty = %q, want empty", got) } - if got := ToolCallIDFromContext(ctx); got != "" { - t.Errorf("ToolCallIDFromContext() on empty = %q, want empty", got) - } - if got := ComponentFromContext(ctx); got != "" { - t.Errorf("ComponentFromContext() on empty = %q, want empty", got) - } - if got := AgentFromContext(ctx); got != "" { - t.Errorf("AgentFromContext() on empty = %q, want empty", got) - } -} - -func TestContextValues_Chaining(t *testing.T) { - ctx := context.Background() - - // Chain multiple values - ctx = WithSession(ctx, "session-1") - ctx = WithToolCall(ctx, "tool-1") - ctx = WithComponent(ctx, testComponent) - ctx = WithAgent(ctx, testAgent) - - // All values should be preserved - if got := SessionIDFromContext(ctx); got != "session-1" { - t.Errorf("SessionIDFromContext() = %q, want 'session-1'", got) - } - if got := ToolCallIDFromContext(ctx); got != "tool-1" { - t.Errorf("ToolCallIDFromContext() = %q, want 'tool-1'", got) - } - if got := ComponentFromContext(ctx); got != testComponent { - t.Errorf("ComponentFromContext() = %q, want %q", got, testComponent) - } - if got := AgentFromContext(ctx); got != testAgent { - t.Errorf("AgentFromContext() = %q, want %q", got, testAgent) - } -} - -func TestAttrsFromContext(t *testing.T) { - ctx := context.Background() - ctx = WithSession(ctx, "session-123") - ctx = WithParentSession(ctx, "parent-456") - ctx = WithToolCall(ctx, "tool-789") - ctx = WithComponent(ctx, testComponent) - ctx = WithAgent(ctx, testAgent) - - // Pass empty string for globalSessionID to include context session_id - attrs := attrsFromContext(ctx, "") - - // Should have 5 attrs - if len(attrs) != 5 { - t.Errorf("attrsFromContext() returned %d attrs, want 5", len(attrs)) - } - - // Verify attr values - attrMap := make(map[string]string) - for _, attr := range attrs { - attrMap[attr.Key] = attr.Value.String() - } - - if attrMap["session_id"] != "session-123" { - t.Errorf("session_id = %q, want 'session-123'", attrMap["session_id"]) - } - if attrMap["parent_session_id"] != "parent-456" { - t.Errorf("parent_session_id = %q, want 'parent-456'", attrMap["parent_session_id"]) - } - if attrMap["tool_call_id"] != "tool-789" { - t.Errorf("tool_call_id = %q, want 'tool-789'", attrMap["tool_call_id"]) - } - if attrMap["component"] != testComponent { - t.Errorf("component = %q, want %q", attrMap["component"], testComponent) - } - if attrMap["agent"] != testAgent { - t.Errorf("agent = %q, want %q", attrMap["agent"], testAgent) - } -} - -func TestAttrsFromContext_Partial(t *testing.T) { - ctx := context.Background() - ctx = WithSession(ctx, "session-only") - - // Pass empty string for globalSessionID to include context session_id - attrs := attrsFromContext(ctx, "") - - // Should only have 1 attr (session_id) since others are empty - if len(attrs) != 1 { - t.Errorf("attrsFromContext() returned %d attrs, want 1", len(attrs)) - } - - if attrs[0].Key != "session_id" || attrs[0].Value.String() != "session-only" { - t.Errorf("Expected session_id='session-only', got %s=%s", attrs[0].Key, attrs[0].Value.String()) - } -} - -func TestAttrsFromContext_SkipsSessionWhenGlobalSet(t *testing.T) { - ctx := context.Background() - ctx = WithSession(ctx, "context-session") - ctx = WithToolCall(ctx, "tool-123") - - // Pass a global session ID - context session_id should be skipped - attrs := attrsFromContext(ctx, "global-session") - - // Should only have 1 attr (tool_call_id) since session_id is skipped - if len(attrs) != 1 { - t.Errorf("attrsFromContext() returned %d attrs, want 1 (session_id should be skipped)", len(attrs)) - } - - if attrs[0].Key != "tool_call_id" || attrs[0].Value.String() != "tool-123" { - t.Errorf("Expected tool_call_id='tool-123', got %s=%s", attrs[0].Key, attrs[0].Value.String()) - } } diff --git a/cmd/entire/cli/logging/logger.go b/cmd/entire/cli/logging/logger.go index 05e01e1cb4..aec8707c38 100644 --- a/cmd/entire/cli/logging/logger.go +++ b/cmd/entire/cli/logging/logger.go @@ -1,18 +1,27 @@ // Package logging provides structured logging for the Entire CLI using slog. // -// Usage: +// Convention: pass the request-scoped ctx to every Debug/Info/Warn/Error/ +// LogDuration call. Never pass context.Background() or context.TODO() — those +// bypass the ctx-carried logger and route to slog.Default (stderr text), which +// silently drops session_id/component/agent enrichment. If a function needs +// to log but lacks ctx, thread one through — that's almost always the right +// fix and surfaces missing plumbing rather than hiding it. // -// // Initialize logger for a session (typically at session start) -// if err := logging.Init(sessionID); err != nil { -// // handle error -// } -// defer logging.Close() +// The logger lives in context.Context and is initialised once in main.go via +// New + WithLogger. Commands and hooks enrich the ctx-logger with attrs via +// WithSession / WithComponent / WithToolCall / WithAgent / WithParentSession. // -// // Add context values -// ctx = logging.WithSession(ctx, sessionID) -// ctx = logging.WithToolCall(ctx, toolCallID) +// Usage in main.go: +// +// level := logging.ResolveLevel(os.Getenv(logging.LogLevelEnvVar), settings.LogLevel) +// logger, closer := logging.New(ctx, logging.Options{Level: level}) +// defer closer() +// ctx = logging.WithLogger(ctx, logger) +// rootCmd.ExecuteContext(ctx) +// +// Usage in commands and hooks: // -// // Log with context - session/tool IDs extracted automatically +// ctx = logging.WithSession(ctx, sessionID) // logging.Info(ctx, "hook invoked", // slog.String("hook", hookName), // slog.String("branch", branch), @@ -32,7 +41,6 @@ import ( "time" "github.com/entireio/cli/cmd/entire/cli/paths" - "github.com/entireio/cli/cmd/entire/cli/validation" ) // LogLevelEnvVar is the environment variable that controls log level. @@ -41,139 +49,81 @@ const LogLevelEnvVar = "ENTIRE_LOG_LEVEL" // LogsDir is the directory where log files are stored (relative to repo root). const LogsDir = ".entire/logs" -var ( - // logger is the package-level logger instance - logger *slog.Logger - - // logFile holds the current log file handle for cleanup - logFile *os.File - - // logBufWriter wraps logFile with buffered I/O for performance - logBufWriter *bufio.Writer - - // currentSessionID stores the session ID from Init() to include in all logs - currentSessionID string - - // mu protects logger, logFile, logBufWriter, and currentSessionID - mu sync.RWMutex - - // logLevelGetter is an optional callback to get log level from settings. - // Set by SetLogLevelGetter before Init is called. - logLevelGetter func() string -) - -// SetLogLevelGetter sets a callback function to get the log level from settings. -// This allows the logging package to read settings without a circular dependency. -// The callback is only used if ENTIRE_LOG_LEVEL env var is not set. -func SetLogLevelGetter(getter func() string) { - mu.Lock() - defer mu.Unlock() - logLevelGetter = getter +// Closer flushes and closes any IO held by a logger. Idempotent: safe to call +// multiple times. A no-op closer is returned when there is no IO to clean up. +type Closer func() error + +// Options configures New. +type Options struct { + // Output, if non-nil, is used directly. Tests pass *bytes.Buffer here. + // If nil, New returns a logger backed by a lazy writer that opens + // .entire/logs/entire.log on first write, falling back to stderr on + // failure (with a one-shot stderr warning). + Output io.Writer + + // Level is the minimum slog level. Use ResolveLevel to compute from + // env + settings precedence. + Level slog.Level } -// Init initializes the logger for a session, writing JSON logs to -// .entire/logs/entire.log. -// -// If sessionID is non-empty, it is stored as an slog attribute on every log line for filtering. -// If the log file cannot be created, falls back to stderr. -// Log level is controlled by ENTIRE_LOG_LEVEL environment variable. -func Init(ctx context.Context, sessionID string) error { - // Validate session ID if provided (used only for the slog attribute, not the filename) - if sessionID != "" { - if err := validation.ValidateSessionID(sessionID); err != nil { - return fmt.Errorf("invalid session ID for logging: %w", err) - } - } - - mu.Lock() - defer mu.Unlock() - - // Close any existing log file (flush buffer first) - if logBufWriter != nil { - _ = logBufWriter.Flush() - logBufWriter = nil - } - if logFile != nil { - _ = logFile.Close() - logFile = nil - } - - // Get log level from environment first, then settings - levelStr := os.Getenv(LogLevelEnvVar) - if levelStr == "" && logLevelGetter != nil { - levelStr = logLevelGetter() - } - level := parseLogLevel(levelStr) - - // Warn if invalid level was provided - if levelStr != "" && !isValidLogLevel(levelStr) { - fmt.Fprintf(os.Stderr, "[entire] Warning: invalid log level %q, defaulting to INFO\n", levelStr) - } - - // Determine log file path - repoRoot, err := paths.WorktreeRoot(ctx) - if err != nil { - // Fall back to current directory - repoRoot = "." - } +// loggerCtxKey is the private context key for *slog.Logger. +// Type-distinct from contextKey to avoid collisions. +type loggerCtxKey struct{} - logsPath := filepath.Join(repoRoot, LogsDir) - if err := os.MkdirAll(logsPath, 0o750); err != nil { - // Fall back to stderr - logger = createLogger(os.Stderr, level) - return nil +// New constructs a *slog.Logger and a matching Closer. +// +// When opts.Output is nil, the logger writes to .entire/logs/entire.log via +// a lazy writer that opens the file on first write and falls back to stderr +// on failure. +// +// The returned Closer flushes and closes the underlying file (if any). It is +// idempotent — main.go's defer is the canonical caller. +func New(ctx context.Context, opts Options) (*slog.Logger, Closer) { + if opts.Output != nil { + return createLogger(opts.Output, opts.Level), noopCloser } + lw := newLazyWriter(ctx) + return createLogger(lw, opts.Level), lw.Close +} - logFilePath := filepath.Join(logsPath, "entire.log") - f, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0o600) //nolint:gosec // fixed filename, not user-controlled - if err != nil { - // Fall back to stderr - logger = createLogger(os.Stderr, level) - return nil +// WithLogger stores l in ctx so LoggerFromContext can retrieve it later. +func WithLogger(ctx context.Context, l *slog.Logger) context.Context { + if l == nil { + return ctx } - - logFile = f - logBufWriter = bufio.NewWriterSize(f, 8192) // 8KB buffer for batched writes - logger = createLogger(logBufWriter, level) - currentSessionID = sessionID - - return nil + return context.WithValue(ctx, loggerCtxKey{}, l) } -// Close closes the log file if one is open. -// Flushes any buffered data before closing. -// Safe to call multiple times. -func Close() { - mu.Lock() - defer mu.Unlock() - - if logBufWriter != nil { - _ = logBufWriter.Flush() - logBufWriter = nil +// LoggerFromContext returns the logger stored by WithLogger, or slog.Default() +// when none is present. Never returns nil. +func LoggerFromContext(ctx context.Context) *slog.Logger { + if ctx == nil { + return slog.Default() } - if logFile != nil { - _ = logFile.Close() - logFile = nil + if l, ok := ctx.Value(loggerCtxKey{}).(*slog.Logger); ok && l != nil { + return l } - currentSessionID = "" + return slog.Default() } -// resetLogger resets the logger to nil (for testing). -func resetLogger() { - mu.Lock() - defer mu.Unlock() - logger = nil - currentSessionID = "" - if logBufWriter != nil { - _ = logBufWriter.Flush() - logBufWriter = nil - } - if logFile != nil { - _ = logFile.Close() - logFile = nil +// ResolveLevel computes the effective slog.Level using env > settings > Info +// precedence. Empty inputs are skipped; invalid inputs fall back to Info. +func ResolveLevel(envValue, settingsValue string) slog.Level { + for _, v := range []string{envValue, settingsValue} { + if v == "" { + continue + } + if !isValidLogLevel(v) { + fmt.Fprintf(os.Stderr, "[entire] Warning: invalid log level %q, defaulting to INFO\n", v) + return slog.LevelInfo + } + return parseLogLevel(v) } + return slog.LevelInfo } +func noopCloser() error { return nil } + // createLogger creates a JSON logger writing to the given writer at the specified level. func createLogger(w io.Writer, level slog.Level) *slog.Logger { opts := &slog.HandlerOptions{ @@ -210,122 +160,141 @@ func isValidLogLevel(s string) bool { } } -// Debug logs at DEBUG level with context values automatically extracted. +// Debug logs at DEBUG level using the ctx-carried logger. func Debug(ctx context.Context, msg string, attrs ...any) { log(ctx, slog.LevelDebug, msg, attrs...) } -// Info logs at INFO level with context values automatically extracted. +// Info logs at INFO level using the ctx-carried logger. func Info(ctx context.Context, msg string, attrs ...any) { log(ctx, slog.LevelInfo, msg, attrs...) } -// Warn logs at WARN level with context values automatically extracted. +// Warn logs at WARN level using the ctx-carried logger. func Warn(ctx context.Context, msg string, attrs ...any) { log(ctx, slog.LevelWarn, msg, attrs...) } -// Error logs at ERROR level with context values automatically extracted. +// Error logs at ERROR level using the ctx-carried logger. func Error(ctx context.Context, msg string, attrs ...any) { log(ctx, slog.LevelError, msg, attrs...) } // LogDuration logs a message with duration_ms calculated from the start time. -// The level parameter specifies the log level (use slog.LevelDebug, slog.LevelInfo, etc). // Designed for use with defer: // // defer logging.LogDuration(ctx, slog.LevelInfo, "operation completed", time.Now()) -// -// Or with additional attrs: -// -// defer logging.LogDuration(ctx, slog.LevelDebug, "hook executed", start, -// slog.String("hook", hookName), -// slog.Bool("success", true), -// ) func LogDuration(ctx context.Context, level slog.Level, msg string, start time.Time, attrs ...any) { durationMs := time.Since(start).Milliseconds() - - // Prepend duration_ms to attrs allAttrs := make([]any, 0, len(attrs)+1) allAttrs = append(allAttrs, slog.Int64("duration_ms", durationMs)) allAttrs = append(allAttrs, attrs...) - log(ctx, level, msg, allAttrs...) } -// log is the internal logging function that extracts context values and logs. +// log routes a record to the ctx-carried logger, materialising the typed-key +// enrichment attrs (session_id, component, …) from ctx as slog.Attrs. // -// The read lock is held across l.Log so Init/Close cannot close logBufWriter -// mid-write; do not shrink the lock scope to a snapshot pattern. +// Bails out before any allocation when the level is filtered, so a Debug call +// in a hot path costs ~one level compare when DEBUG is disabled. Attrs are +// appended fresh per call rather than baked into the logger via slog.With, +// because slog.With accumulates without deduplicating and would produce +// duplicate JSON keys when WithSession nests. func log(ctx context.Context, level slog.Level, msg string, attrs ...any) { - mu.RLock() - defer mu.RUnlock() - - l := logger - if l == nil { - l = slog.Default() + l := LoggerFromContext(ctx) + if !l.Enabled(ctx, level) { + return } - globalSessionID := currentSessionID - - // Build attributes slice with session ID first (if set) - var allAttrs []any - - // Add session ID from Init() if set (always first for consistency) - if globalSessionID != "" { - allAttrs = append(allAttrs, slog.String("session_id", globalSessionID)) + ctxAttrs := attrsFromContext(ctx) + if len(ctxAttrs) == 0 { + l.Log(ctx, level, msg, attrs...) + return } - - // Extract context values, skipping session_id if already added from Init() - contextAttrs := attrsFromContext(ctx, globalSessionID) - for _, a := range contextAttrs { + allAttrs := make([]any, 0, len(ctxAttrs)+len(attrs)) + for _, a := range ctxAttrs { allAttrs = append(allAttrs, a) } - - // Add caller-provided attributes allAttrs = append(allAttrs, attrs...) + l.Log(ctx, level, msg, allAttrs...) +} - // Pass nil context to slog as we've already extracted context values as attributes. - // slog handlers are expected to handle nil context gracefully. - l.Log(nil, level, msg, allAttrs...) //nolint:staticcheck // nil context is intentional - we extract values as attributes +// lazyWriter opens .entire/logs/entire.log on first write, falling back to +// stderr if the open fails. Subsequent writes go to the chosen target. +// +// Designed so that invocations that emit no log lines (e.g., entire --version) +// never create the file. Closer is sync.Once-guarded; safe to call multiple +// times. +type lazyWriter struct { + ctx context.Context + openOnce sync.Once + closeOnce sync.Once + + target io.Writer + flush func() error + closeFn func() error } -// attrsFromContext extracts logging attributes from a context. -// If globalSessionID is non-empty, skips adding session_id from context to avoid duplicates. -func attrsFromContext(ctx context.Context, globalSessionID string) []slog.Attr { +func newLazyWriter(ctx context.Context) *lazyWriter { if ctx == nil { - return nil + ctx = context.Background() } + return &lazyWriter{ctx: ctx} +} - var attrs []slog.Attr +// Write implements io.Writer. The first call resolves the underlying target +// (file or stderr); subsequent calls reuse it. +func (w *lazyWriter) Write(p []byte) (int, error) { + w.openOnce.Do(w.resolveTarget) + return w.target.Write(p) //nolint:wrapcheck // io.Writer pass-through; wrapping would obscure the underlying error +} - // Only add session_id from context if not already set globally - if globalSessionID == "" { - if v := ctx.Value(sessionIDKey); v != nil { - if s, ok := v.(string); ok && s != "" { - attrs = append(attrs, slog.String("session_id", s)) - } - } +func (w *lazyWriter) resolveTarget() { + // Use a non-cancellable view of the request ctx so SIGINT doesn't prevent + // us from opening the log file during shutdown — the user usually wants + // the shutdown trace to land on disk. + repoRoot, err := paths.WorktreeRoot(context.WithoutCancel(w.ctx)) + if err != nil { + w.useStderr(fmt.Errorf("repo root not found: %w", err)) + return } - if v := ctx.Value(parentSessionIDKey); v != nil { - if s, ok := v.(string); ok && s != "" { - attrs = append(attrs, slog.String("parent_session_id", s)) - } + logsPath := filepath.Join(repoRoot, LogsDir) + if err := os.MkdirAll(logsPath, 0o750); err != nil { + w.useStderr(fmt.Errorf("mkdir %s: %w", logsPath, err)) + return } - if v := ctx.Value(toolCallIDKey); v != nil { - if s, ok := v.(string); ok && s != "" { - attrs = append(attrs, slog.String("tool_call_id", s)) - } + logFilePath := filepath.Join(logsPath, "entire.log") + f, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0o600) //nolint:gosec // fixed filename, not user-controlled + if err != nil { + w.useStderr(fmt.Errorf("open %s: %w", logFilePath, err)) + return } - if v := ctx.Value(componentKey); v != nil { - if s, ok := v.(string); ok && s != "" { - attrs = append(attrs, slog.String("component", s)) + buf := bufio.NewWriterSize(f, 8192) + w.target = buf + w.flush = buf.Flush + w.closeFn = f.Close +} + +func (w *lazyWriter) useStderr(reason error) { + fmt.Fprintf(os.Stderr, "[entire] log file unavailable: %v; logs going to stderr\n", reason) + w.target = os.Stderr + w.flush = func() error { return nil } + w.closeFn = func() error { return nil } +} + +// Close flushes and closes the underlying file. Idempotent. +func (w *lazyWriter) Close() error { + var err error + w.closeOnce.Do(func() { + // If openOnce never fired (no writes happened), there's nothing to do. + if w.flush == nil { + return } - } - if v := ctx.Value(agentKey); v != nil { - if s, ok := v.(string); ok && s != "" { - attrs = append(attrs, slog.String("agent", s)) + if ferr := w.flush(); ferr != nil { + err = ferr } - } - - return attrs + if cerr := w.closeFn(); cerr != nil && err == nil { + err = cerr + } + }) + return err } diff --git a/cmd/entire/cli/logging/logger_test.go b/cmd/entire/cli/logging/logger_test.go index 7ef0dbd387..82ba7b7098 100644 --- a/cmd/entire/cli/logging/logger_test.go +++ b/cmd/entire/cli/logging/logger_test.go @@ -4,6 +4,7 @@ import ( "bytes" "context" "encoding/json" + "io" "log/slog" "os" "os/exec" @@ -19,622 +20,395 @@ const ( testSessionID = "2025-01-15-test-session" testComponent = "hooks" testAgent = "claude-code" - levelINFO = "INFO" ) -// testLogFilePath returns the expected log file path for a test temp directory. -func testLogFilePath(tmpDir string) string { - return filepath.Join(tmpDir, ".entire", "logs", "entire.log") +// initGitRepo initialises a git repo in dir so tests that exercise the lazy +// writer's repo-root resolution can succeed. +func initGitRepo(t testing.TB, dir string) { + t.Helper() + cmd := exec.CommandContext(context.Background(), "git", "init") + cmd.Dir = dir + if err := cmd.Run(); err != nil { + t.Fatalf("git init: %v", err) + } +} + +// withTestLogger returns a ctx pre-loaded with a debug-level logger writing to +// the returned buffer. Cleanup is registered on t. +// +// Mirrors loggingtest.New but lives in this package so tests inside `logging` +// avoid an import cycle with `logging/loggingtest`. +func withTestLogger(t testing.TB) (context.Context, *bytes.Buffer) { + t.Helper() + buf := &bytes.Buffer{} + logger, closer := New(context.Background(), Options{ + Output: buf, + Level: slog.LevelDebug, + }) + t.Cleanup(func() { + if err := closer(); err != nil { + t.Errorf("closer error: %v", err) + } + }) + return WithLogger(context.Background(), logger), buf +} + +// firstRecord parses the first JSONL line from buf into a map; fails the test +// if the buffer is empty or unparseable. +func firstRecord(t testing.TB, buf *bytes.Buffer) map[string]any { + t.Helper() + if buf.Len() == 0 { + t.Fatal("expected at least one log record, buffer is empty") + } + rec := map[string]any{} + dec := json.NewDecoder(bytes.NewReader(buf.Bytes())) + if err := dec.Decode(&rec); err != nil { + t.Fatalf("parse log record: %v", err) + } + return rec } func TestParseLogLevel(t *testing.T) { + t.Parallel() tests := []struct { - name string - envValue string - want slog.Level + input string + want slog.Level }{ - {"empty defaults to INFO", "", slog.LevelInfo}, - {"DEBUG lowercase", "debug", slog.LevelDebug}, - {"DEBUG uppercase", "DEBUG", slog.LevelDebug}, - {"INFO lowercase", "info", slog.LevelInfo}, - {"INFO uppercase", "INFO", slog.LevelInfo}, - {"WARN lowercase", "warn", slog.LevelWarn}, - {"WARN uppercase", "WARN", slog.LevelWarn}, - {"ERROR lowercase", "error", slog.LevelError}, - {"ERROR uppercase", "ERROR", slog.LevelError}, - {"invalid defaults to INFO", "invalid", slog.LevelInfo}, - {"warning alias", "warning", slog.LevelWarn}, + {"DEBUG", slog.LevelDebug}, + {"debug", slog.LevelDebug}, + {"INFO", slog.LevelInfo}, + {"info", slog.LevelInfo}, + {"WARN", slog.LevelWarn}, + {"WARNING", slog.LevelWarn}, + {"ERROR", slog.LevelError}, + {"", slog.LevelInfo}, + {"bogus", slog.LevelInfo}, } + for _, tt := range tests { + got := parseLogLevel(tt.input) + if got != tt.want { + t.Errorf("parseLogLevel(%q) = %v, want %v", tt.input, got, tt.want) + } + } +} +func TestResolveLevel(t *testing.T) { + t.Parallel() + tests := []struct { + name string + env, settings string + want slog.Level + }{ + {"defaults to info", "", "", slog.LevelInfo}, + {"env wins over settings", "DEBUG", "WARN", slog.LevelDebug}, + {"settings used when env empty", "", "WARN", slog.LevelWarn}, + {"invalid env falls back", "bogus", "", slog.LevelInfo}, + {"invalid settings falls back", "", "bogus", slog.LevelInfo}, + } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - got := parseLogLevel(tt.envValue) + t.Parallel() + got := ResolveLevel(tt.env, tt.settings) if got != tt.want { - t.Errorf("parseLogLevel(%q) = %v, want %v", tt.envValue, got, tt.want) + t.Errorf("ResolveLevel(%q, %q) = %v, want %v", tt.env, tt.settings, got, tt.want) } }) } } -func TestInit_CreatesLogDirectory(t *testing.T) { - tmpDir := t.TempDir() - t.Chdir(tmpDir) +func TestNew_OutputBufferOverridesLazyFile(t *testing.T) { + t.Parallel() + var buf bytes.Buffer + logger, closer := New(context.Background(), Options{Output: &buf, Level: slog.LevelDebug}) + t.Cleanup(func() { + if err := closer(); err != nil { + t.Errorf("closer: %v", err) + } + }) - // Initialize git repo so WorktreeRoot works - initGitRepo(t, tmpDir) + logger.Info("hello", slog.String("foo", "bar")) - err := Init(context.Background(), testSessionID) - if err != nil { - t.Fatalf("Init() error = %v", err) - } - defer Close() - - logsDir := filepath.Join(tmpDir, ".entire", "logs") - if _, err := os.Stat(logsDir); os.IsNotExist(err) { - t.Errorf("Init() did not create .entire/logs/ directory") + if !strings.Contains(buf.String(), `"msg":"hello"`) { + t.Errorf("expected hello in output, got: %s", buf.String()) } } -func TestInit_CreatesLogFile(t *testing.T) { +func TestNew_LazyOpensFile(t *testing.T) { + // Cannot use t.Parallel: t.Chdir mutates process-global state. tmpDir := t.TempDir() - t.Chdir(tmpDir) - initGitRepo(t, tmpDir) - - err := Init(context.Background(), testSessionID) - if err != nil { - t.Fatalf("Init() error = %v", err) - } - defer Close() - - if _, err := os.Stat(testLogFilePath(tmpDir)); os.IsNotExist(err) { - t.Errorf("Init() did not create log file at %s", testLogFilePath(tmpDir)) - } -} - -func TestInit_WritesJSONLogs(t *testing.T) { - tmpDir := t.TempDir() t.Chdir(tmpDir) - initGitRepo(t, tmpDir) + logger, closer := New(context.Background(), Options{Level: slog.LevelDebug}) + t.Cleanup(func() { + if err := closer(); err != nil { + t.Errorf("closer: %v", err) + } + }) - sessionID := "2025-01-15-json-test" - err := Init(context.Background(), sessionID) - if err != nil { - t.Fatalf("Init() error = %v", err) + logger.Info("first record") + if err := closer(); err != nil { + t.Fatalf("closer: %v", err) } - // Log something - Info(context.Background(), "test message", slog.String("key", "value")) - - // Close to flush - Close() - - // Read log file - content, err := os.ReadFile(testLogFilePath(tmpDir)) + logFile := filepath.Join(tmpDir, LogsDir, "entire.log") + content, err := os.ReadFile(logFile) if err != nil { - t.Fatalf("Failed to read log file: %v", err) - } - - // Parse as JSON - var logEntry map[string]interface{} - if err := json.Unmarshal(content, &logEntry); err != nil { - t.Errorf("Log output is not valid JSON: %v\nContent: %s", err, content) - } - - // Verify expected fields - if msg, ok := logEntry["msg"].(string); !ok || msg != "test message" { - t.Errorf("Expected msg='test message', got %v", logEntry["msg"]) + t.Fatalf("read log file: %v", err) } - if key, ok := logEntry["key"].(string); !ok || key != "value" { - t.Errorf("Expected key='value', got %v", logEntry["key"]) - } - if _, ok := logEntry["time"]; !ok { - t.Error("Expected 'time' field in log entry") - } - if _, ok := logEntry["level"]; !ok { - t.Error("Expected 'level' field in log entry") + if !strings.Contains(string(content), `"msg":"first record"`) { + t.Errorf("expected log file to contain message, got: %s", content) } } -func TestInit_RespectsLogLevel(t *testing.T) { +func TestNew_NoFileWhenNoWrites(t *testing.T) { + // Cannot use t.Parallel: t.Chdir mutates process-global state. tmpDir := t.TempDir() - t.Chdir(tmpDir) - initGitRepo(t, tmpDir) + t.Chdir(tmpDir) - // Set log level to WARN - t.Setenv(LogLevelEnvVar, "WARN") - - sessionID := "2025-01-15-level-test" - err := Init(context.Background(), sessionID) - if err != nil { - t.Fatalf("Init() error = %v", err) + _, closer := New(context.Background(), Options{Level: slog.LevelDebug}) + if err := closer(); err != nil { + t.Fatalf("closer: %v", err) } - ctx := context.Background() - - // These should NOT be logged - Debug(ctx, "debug message") - Info(ctx, "info message") - - // This SHOULD be logged - Warn(ctx, "warn message") - - Close() - - // Read log file - content, err := os.ReadFile(testLogFilePath(tmpDir)) - if err != nil { - t.Fatalf("Failed to read log file: %v", err) - } - - contentStr := string(content) - if strings.Contains(contentStr, "debug message") { - t.Error("DEBUG message should not be logged when level is WARN") - } - if strings.Contains(contentStr, "info message") { - t.Error("INFO message should not be logged when level is WARN") - } - if !strings.Contains(contentStr, "warn message") { - t.Error("WARN message should be logged when level is WARN") + logFile := filepath.Join(tmpDir, LogsDir, "entire.log") + if _, err := os.Stat(logFile); !os.IsNotExist(err) { + t.Errorf("expected log file to not exist when nothing was logged") } } -func TestInit_InvalidLogLevelWarns(t *testing.T) { +func TestNew_FallsBackToStderrOnIOFailure(t *testing.T) { + // Cannot use t.Parallel: t.Chdir mutates process-global state. tmpDir := t.TempDir() + initGitRepo(t, tmpDir) t.Chdir(tmpDir) - initGitRepo(t, tmpDir) + entireDir := filepath.Join(tmpDir, ".entire") + if err := os.MkdirAll(entireDir, 0o755); err != nil { + t.Fatalf("mkdir entire dir: %v", err) + } + if err := os.Chmod(entireDir, 0o500); err != nil { + t.Fatalf("chmod entire dir: %v", err) + } + t.Cleanup(func() { + if err := os.Chmod(entireDir, 0o755); err != nil { + t.Logf("cleanup chmod: %v", err) + } + }) + + logger, closer := New(context.Background(), Options{Level: slog.LevelDebug}) + t.Cleanup(func() { + if err := closer(); err != nil { + t.Errorf("closer: %v", err) + } + }) + + // First write triggers the open attempt; should not panic. The lazy writer + // emits a warning to stderr and routes the record there. + logger.Info("expect stderr fallback") +} - // Capture stderr +func TestCloser_Idempotent(t *testing.T) { + t.Parallel() var buf bytes.Buffer - oldStderr := os.Stderr - r, w, err := os.Pipe() - if err != nil { - t.Fatalf("Failed to create pipe: %v", err) + _, closer := New(context.Background(), Options{Output: &buf, Level: slog.LevelDebug}) + if err := closer(); err != nil { + t.Fatalf("first close: %v", err) } - os.Stderr = w - - t.Setenv(LogLevelEnvVar, "INVALID_LEVEL") - - sessionID := "2025-01-15-invalid-level" - err = Init(context.Background(), sessionID) - if err != nil { - t.Fatalf("Init() error = %v", err) + if err := closer(); err != nil { + t.Errorf("second close should be a no-op, got: %v", err) } - - w.Close() - os.Stderr = oldStderr - - if _, err := buf.ReadFrom(r); err != nil { - t.Fatalf("Failed to read from pipe: %v", err) - } - stderrOutput := buf.String() - - if !strings.Contains(stderrOutput, "invalid log level") { - t.Errorf("Expected warning about invalid log level on stderr, got: %s", stderrOutput) - } - - Close() } -func TestInit_FallsBackToStderrOnError(t *testing.T) { - tmpDir := t.TempDir() - t.Chdir(tmpDir) - - initGitRepo(t, tmpDir) - - // Make logs directory unwritable (simulate permission error) - logsDir := filepath.Join(tmpDir, ".entire", "logs") - if err := os.MkdirAll(logsDir, 0o755); err != nil { - t.Fatalf("Failed to create logs dir: %v", err) +func TestLoggerFromContext_FallbackToDefault(t *testing.T) { + t.Parallel() + if LoggerFromContext(context.Background()) == nil { + t.Fatal("expected non-nil fallback for empty ctx") } - - // Create a directory with the same name as the log file to cause an error - if err := os.MkdirAll(testLogFilePath(tmpDir), 0o755); err != nil { - t.Fatalf("Failed to create blocking dir: %v", err) - } - - // Init should not return error, but fall back to stderr - err := Init(context.Background(), testSessionID) - if err != nil { - t.Errorf("Init() should not error, but got: %v", err) + if LoggerFromContext(nil) == nil { //nolint:staticcheck // testing nil-safety + t.Fatal("expected non-nil fallback for nil ctx") } - - // Verify logger still works (writing to stderr) - Info(context.Background(), "fallback test") - - Close() } -func TestClose_SafeToCallMultipleTimes(t *testing.T) { - tmpDir := t.TempDir() - t.Chdir(tmpDir) - - initGitRepo(t, tmpDir) +func TestWithLogger_RoundTrip(t *testing.T) { + t.Parallel() + var buf bytes.Buffer + logger, _ := New(context.Background(), Options{Output: &buf, Level: slog.LevelDebug}) + ctx := WithLogger(context.Background(), logger) - sessionID := "2025-01-15-close-test" - err := Init(context.Background(), sessionID) - if err != nil { - t.Fatalf("Init() error = %v", err) + got := LoggerFromContext(ctx) + if got != logger { + t.Errorf("LoggerFromContext returned different logger than WithLogger stored") } - - // Should not panic - Close() - Close() - Close() } -func TestLogging_BeforeInit(_ *testing.T) { - // Reset any global state - resetLogger() +func TestWithSession_BakesAttr(t *testing.T) { + t.Parallel() + ctx, buf := withTestLogger(t) + ctx = WithSession(ctx, testSessionID) + Info(ctx, "session check") - // These should not panic, should use default stderr logger - ctx := context.Background() - Debug(ctx, "debug before init") - Info(ctx, "info before init") - Warn(ctx, "warn before init") - Error(ctx, "error before init") -} - -// Helper to initialize a git repo for tests -func initGitRepo(t *testing.T, dir string) { - t.Helper() - t.Chdir(dir) - cmd := "git init && git config user.email 'test@test.com' && git config user.name 'Test'" - output, err := execCommand(t, "sh", "-c", cmd) - if err != nil { - t.Fatalf("Failed to init git repo: %v\nOutput: %s", err, output) + rec := firstRecord(t, buf) + if rec["session_id"] != testSessionID { + t.Errorf("session_id = %v, want %q", rec["session_id"], testSessionID) } } -func execCommand(t *testing.T, name string, args ...string) (string, error) { - t.Helper() - ctx := context.Background() - cmd := exec.CommandContext(ctx, name, args...) - output, err := cmd.CombinedOutput() - return string(output), err -} - -func TestLogging_IncludesContextValues(t *testing.T) { - tmpDir := t.TempDir() - t.Chdir(tmpDir) +func TestWithSession_PromotesParentFromExisting(t *testing.T) { + t.Parallel() + parent, child := "parent-session-id", "child-session-id" + ctx, buf := withTestLogger(t) + ctx = WithSession(ctx, parent) + ctx = WithSession(ctx, child) + Info(ctx, "child") - initGitRepo(t, tmpDir) - - sessionID := "2025-01-15-context-test" - err := Init(context.Background(), sessionID) - if err != nil { - t.Fatalf("Init() error = %v", err) + rec := firstRecord(t, buf) + if rec["session_id"] != child { + t.Errorf("session_id = %v, want %q", rec["session_id"], child) } - - // Create context with values - // Note: session_id from context is skipped when Init() has already set a global session ID - ctx := context.Background() - ctx = WithSession(ctx, "context-session-id") // Will be ignored, global takes precedence - ctx = WithToolCall(ctx, "toolu_123") - ctx = WithComponent(ctx, testComponent) - ctx = WithAgent(ctx, testAgent) - - // Log with context - Info(ctx, "context test message") - - Close() - - // Read log file - content, err := os.ReadFile(testLogFilePath(tmpDir)) - if err != nil { - t.Fatalf("Failed to read log file: %v", err) - } - - // Parse as JSON - var logEntry map[string]interface{} - if err := json.Unmarshal(content, &logEntry); err != nil { - t.Fatalf("Log output is not valid JSON: %v\nContent: %s", err, content) - } - - // session_id comes from Init() when set, not from context (to avoid duplicates) - if logEntry["session_id"] != sessionID { - t.Errorf("Expected session_id='%s' (from Init), got %v", sessionID, logEntry["session_id"]) - } - if logEntry["tool_call_id"] != "toolu_123" { - t.Errorf("Expected tool_call_id='toolu_123', got %v", logEntry["tool_call_id"]) - } - if logEntry["component"] != testComponent { - t.Errorf("Expected component='%s', got %v", testComponent, logEntry["component"]) - } - if logEntry["agent"] != testAgent { - t.Errorf("Expected agent='%s', got %v", testAgent, logEntry["agent"]) + if rec["parent_session_id"] != parent { + t.Errorf("parent_session_id = %v, want %q", rec["parent_session_id"], parent) } } -func TestLogging_ParentSessionID(t *testing.T) { - tmpDir := t.TempDir() - t.Chdir(tmpDir) - - initGitRepo(t, tmpDir) +func TestWithParentSession_AttachesParent(t *testing.T) { + t.Parallel() + ctx, buf := withTestLogger(t) + ctx = WithParentSession(ctx, "explicit-parent") + Info(ctx, "explicit") - sessionID := "2025-01-15-parent-test" - err := Init(context.Background(), sessionID) - if err != nil { - t.Fatalf("Init() error = %v", err) - } - - // Create parent context, then child context - // Note: WithSession sets parent_session_id when there's already a session in context - ctx := context.Background() - ctx = WithSession(ctx, "parent-session") - ctx = WithSession(ctx, "child-session") // This sets parent_session_id to "parent-session" - - Info(ctx, "nested session test") - - Close() - - // Read log file - content, err := os.ReadFile(testLogFilePath(tmpDir)) - if err != nil { - t.Fatalf("Failed to read log file: %v", err) - } - - // Parse as JSON - var logEntry map[string]interface{} - if err := json.Unmarshal(content, &logEntry); err != nil { - t.Fatalf("Log output is not valid JSON: %v\nContent: %s", err, content) - } - - // session_id comes from Init(), context session_id is skipped to avoid duplicates - if logEntry["session_id"] != sessionID { - t.Errorf("Expected session_id='%s' (from Init), got %v", sessionID, logEntry["session_id"]) - } - // parent_session_id from context is still included - if logEntry["parent_session_id"] != "parent-session" { - t.Errorf("Expected parent_session_id='parent-session', got %v", logEntry["parent_session_id"]) + rec := firstRecord(t, buf) + if rec["parent_session_id"] != "explicit-parent" { + t.Errorf("parent_session_id = %v, want explicit-parent", rec["parent_session_id"]) } } -func TestLogging_AdditionalAttrs(t *testing.T) { - tmpDir := t.TempDir() - t.Chdir(tmpDir) - - initGitRepo(t, tmpDir) - - sessionID := "2025-01-15-attrs-test" - err := Init(context.Background(), sessionID) - if err != nil { - t.Fatalf("Init() error = %v", err) - } - - ctx := WithSession(context.Background(), "context-session") // Will be ignored, global takes precedence - - // Log with additional attrs - Info(ctx, "attrs test", - slog.String("hook", "pre-push"), - slog.Int("duration_ms", 150), - slog.Bool("success", true), - ) - - Close() - - // Read log file - content, err := os.ReadFile(testLogFilePath(tmpDir)) - if err != nil { - t.Fatalf("Failed to read log file: %v", err) - } - - // Parse as JSON - var logEntry map[string]interface{} - if err := json.Unmarshal(content, &logEntry); err != nil { - t.Fatalf("Log output is not valid JSON: %v\nContent: %s", err, content) - } - - // session_id comes from Init(), additional attrs work alongside - if logEntry["session_id"] != sessionID { - t.Errorf("Expected session_id='%s' (from Init), got %v", sessionID, logEntry["session_id"]) - } - if logEntry["hook"] != "pre-push" { - t.Errorf("Expected hook='pre-push', got %v", logEntry["hook"]) - } - if logEntry["duration_ms"] != float64(150) { - t.Errorf("Expected duration_ms=150, got %v", logEntry["duration_ms"]) - } - if logEntry["success"] != true { - t.Errorf("Expected success=true, got %v", logEntry["success"]) - } -} - -func TestLogDuration(t *testing.T) { - tmpDir := t.TempDir() - t.Chdir(tmpDir) - - initGitRepo(t, tmpDir) - - sessionID := "2025-01-15-duration-test" - err := Init(context.Background(), sessionID) - if err != nil { - t.Fatalf("Init() error = %v", err) - } - - ctx := WithSession(context.Background(), "context-session") // Will be ignored, global takes precedence +func TestEnrichmentChain_ComposesAllAttrs(t *testing.T) { + t.Parallel() + ctx, buf := withTestLogger(t) + ctx = WithSession(ctx, "session-1") ctx = WithComponent(ctx, testComponent) + ctx = WithToolCall(ctx, "tool-1") + ctx = WithAgent(ctx, testAgent) + Info(ctx, "all-attrs") - // Simulate some work - start := time.Now().Add(-100 * time.Millisecond) // Fake 100ms ago - - LogDuration(ctx, slog.LevelInfo, "operation completed", start, - slog.String("hook", "pre-push"), - slog.Bool("success", true), - ) - - Close() - - // Read log file - content, err := os.ReadFile(testLogFilePath(tmpDir)) - if err != nil { - t.Fatalf("Failed to read log file: %v", err) - } - - // Parse as JSON - var logEntry map[string]interface{} - if err := json.Unmarshal(content, &logEntry); err != nil { - t.Fatalf("Log output is not valid JSON: %v\nContent: %s", err, content) - } - - // Verify duration_ms is present and reasonable - durationMs, ok := logEntry["duration_ms"].(float64) - if !ok { - t.Fatalf("Expected duration_ms to be a number, got %T: %v", logEntry["duration_ms"], logEntry["duration_ms"]) - } - if durationMs < 90 || durationMs > 200 { - t.Errorf("Expected duration_ms around 100, got %v", durationMs) - } - - // session_id comes from Init(), not context - if logEntry["session_id"] != sessionID { - t.Errorf("Expected session_id='%s' (from Init), got %v", sessionID, logEntry["session_id"]) + rec := firstRecord(t, buf) + checks := map[string]string{ + "session_id": "session-1", + "component": testComponent, + "tool_call_id": "tool-1", + "agent": testAgent, } - if logEntry["component"] != testComponent { - t.Errorf("Expected component='%s', got %v", testComponent, logEntry["component"]) - } - if logEntry["hook"] != "pre-push" { - t.Errorf("Expected hook='pre-push', got %v", logEntry["hook"]) - } - if logEntry["success"] != true { - t.Errorf("Expected success=true, got %v", logEntry["success"]) - } - if logEntry["level"] != levelINFO { - t.Errorf("Expected level='%s', got %v", levelINFO, logEntry["level"]) + for key, want := range checks { + if got := rec[key]; got != want { + t.Errorf("attr %q = %v, want %v", key, got, want) + } } } -func TestLogging_ContextSessionID_WhenNoGlobalSet(t *testing.T) { - // Reset any global state to ensure no global session ID - resetLogger() - - // Create a buffer to capture output since we won't use Init() +func TestLevels_FilterRecords(t *testing.T) { + t.Parallel() var buf bytes.Buffer - mu.Lock() - logger = createLogger(&buf, slog.LevelInfo) - mu.Unlock() - - // Set session_id via context (no global set) - ctx := WithSession(context.Background(), "context-only-session") - ctx = WithComponent(ctx, testComponent) + logger, closer := New(context.Background(), Options{Output: &buf, Level: slog.LevelWarn}) + t.Cleanup(func() { + if err := closer(); err != nil { + t.Errorf("closer: %v", err) + } + }) + ctx := WithLogger(context.Background(), logger) + + Debug(ctx, "skip-debug") + Info(ctx, "skip-info") + Warn(ctx, "include-warn") + Error(ctx, "include-error") + + output := buf.String() + if strings.Contains(output, "skip-debug") || strings.Contains(output, "skip-info") { + t.Errorf("expected debug/info to be filtered at warn level, got: %s", output) + } + if !strings.Contains(output, "include-warn") || !strings.Contains(output, "include-error") { + t.Errorf("expected warn+error to be present, got: %s", output) + } +} - Info(ctx, "context session test") +func TestLogDuration_AttachesDurationMS(t *testing.T) { + t.Parallel() + ctx, buf := withTestLogger(t) - // Parse the output - var logEntry map[string]interface{} - if err := json.Unmarshal(buf.Bytes(), &logEntry); err != nil { - t.Fatalf("Log output is not valid JSON: %v\nContent: %s", err, buf.String()) - } + // Use a defer-style call to mirror real usage. + func() { + defer LogDuration(ctx, slog.LevelInfo, "op", nowFn()) + }() - // When no global session ID is set, context session_id should be used - if logEntry["session_id"] != "context-only-session" { - t.Errorf("Expected session_id='context-only-session' from context, got %v", logEntry["session_id"]) + rec := firstRecord(t, buf) + if _, ok := rec["duration_ms"]; !ok { + t.Errorf("expected duration_ms in record, got: %s", buf.String()) } - - resetLogger() } -func TestLogging_ConcurrentInitAndLog(t *testing.T) { - tmpDir := t.TempDir() - t.Chdir(tmpDir) - initGitRepo(t, tmpDir) +// nowFn is a tiny indirection so we can keep the helper free of time imports +// at top-level (other tests don't need time directly). +func nowFn() (now time.Time) { return time.Now() } - if err := Init(context.Background(), ""); err != nil { - t.Fatalf("Init() error = %v", err) - } - defer Close() +func TestLogging_ConcurrentLogToSharedLogger(t *testing.T) { + t.Parallel() + var buf bytes.Buffer + logger, closer := New(context.Background(), Options{ + // Wrap buf in a synchronised writer so concurrent writes don't trip the + // race detector — slog handlers serialise per-write but we still need a + // thread-safe sink. + Output: &lockedWriter{w: &buf}, + Level: slog.LevelDebug, + }) + t.Cleanup(func() { + if err := closer(); err != nil { + t.Errorf("closer: %v", err) + } + }) + ctx := WithLogger(context.Background(), logger) const ( - logGoroutines = 8 - initGoroutines = 4 - closeGoroutines = 2 - iterations = 200 + goroutines = 16 + iterations = 200 ) var wg sync.WaitGroup start := make(chan struct{}) - for i := range logGoroutines { + for i := range goroutines { wg.Add(1) go func(worker int) { defer wg.Done() <-start for j := range iterations { - Info(context.Background(), "concurrent log", slog.Int("worker", worker), slog.Int("iteration", j)) + Info(ctx, "concurrent log", + slog.Int("worker", worker), + slog.Int("iteration", j), + ) } }(i) } - for range initGoroutines { - wg.Add(1) - go func() { - defer wg.Done() - <-start - for range iterations { - if err := Init(context.Background(), ""); err != nil { - t.Errorf("Init() error = %v", err) - return - } - } - }() - } - - for range closeGoroutines { - wg.Add(1) - go func() { - defer wg.Done() - <-start - for range iterations { - Close() - } - }() - } - close(start) wg.Wait() -} -func TestInit_RejectsInvalidSessionIDs(t *testing.T) { - tests := []struct { - name string - sessionID string - wantErr bool - }{ - {"empty session ID is allowed", "", false}, - {"path traversal with slash", "../../../tmp/evil", true}, - {"path traversal with backslash", "..\\..\\tmp\\evil", true}, - {"contains forward slash", "2025-01-15/session", true}, - {"contains backslash", "2025-01-15\\session", true}, - {"valid session ID", "2025-01-15-valid-session", false}, - {"valid UUID-like ID", "abc123-def456-ghi789", false}, + // Every goroutine emitted iterations records. Count newlines as a sanity + // check (one per JSON line). + got := strings.Count(buf.String(), "\n") + if want := goroutines * iterations; got != want { + t.Errorf("expected %d records, got %d", want, got) } +} - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - // Reset logger state before each test - resetLogger() - - // Set up git repo for cases that we expect to succeed - if !tt.wantErr { - tmpDir := t.TempDir() - t.Chdir(tmpDir) - initGitRepo(t, tmpDir) - } +// lockedWriter serialises writes to an underlying writer. +type lockedWriter struct { + mu sync.Mutex + w io.Writer +} - err := Init(context.Background(), tt.sessionID) - if (err != nil) != tt.wantErr { - t.Errorf("Init(%q) error = %v, wantErr %v", tt.sessionID, err, tt.wantErr) - } - if err != nil && tt.wantErr { - // Verify error message mentions session ID - if !strings.Contains(err.Error(), "session ID") { - t.Errorf("Init(%q) error should mention 'session ID', got: %v", tt.sessionID, err) - } - } - Close() - }) - } +func (l *lockedWriter) Write(p []byte) (int, error) { + l.mu.Lock() + defer l.mu.Unlock() + return l.w.Write(p) } diff --git a/cmd/entire/cli/logging/loggingtest/loggingtest.go b/cmd/entire/cli/logging/loggingtest/loggingtest.go new file mode 100644 index 0000000000..98efe3f540 --- /dev/null +++ b/cmd/entire/cli/logging/loggingtest/loggingtest.go @@ -0,0 +1,102 @@ +// Package loggingtest provides helpers for tests that need a deterministic, +// in-memory logger. +// +// Use New(t) to obtain a context pre-loaded with a debug-level logger writing +// to a *bytes.Buffer; assert on the captured records via Records(t, buf). +package loggingtest + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "io" + "log/slog" + "testing" + + "github.com/entireio/cli/cmd/entire/cli/logging" +) + +// New returns a ctx pre-loaded with a debug-level logger writing to buf. +// Equivalent to NewWithLevel(t, slog.LevelDebug). +func New(t testing.TB) (context.Context, *bytes.Buffer) { + t.Helper() + return NewWithLevel(t, slog.LevelDebug) +} + +// NewWithLevel returns a ctx pre-loaded with a logger at the requested level +// writing to a fresh *bytes.Buffer. The closer is registered via t.Cleanup. +func NewWithLevel(t testing.TB, level slog.Level) (context.Context, *bytes.Buffer) { + t.Helper() + buf := &bytes.Buffer{} + logger, closer := logging.New(context.Background(), logging.Options{ + Output: buf, + Level: level, + }) + t.Cleanup(func() { + if err := closer(); err != nil { + t.Errorf("loggingtest: closer returned error: %v", err) + } + }) + return logging.WithLogger(context.Background(), logger), buf +} + +// Record is a parsed JSON log line for assertions in tests. +type Record struct { + // Time is the slog "time" field, kept as a string so tests can compare + // against the raw value when needed. + Time string + + // Level is the slog "level" field (e.g., "INFO", "DEBUG"). + Level string + + // Msg is the log message. + Msg string + + // Attrs holds every other top-level JSON field attached to the record. + Attrs map[string]any +} + +// Records parses each JSONL line in buf into a Record. Lines that fail to +// parse fail the test. +func Records(t testing.TB, buf *bytes.Buffer) []Record { + t.Helper() + if buf.Len() == 0 { + return nil + } + var records []Record + dec := json.NewDecoder(bytes.NewReader(buf.Bytes())) + // Loop until io.EOF rather than json.Decoder.More: More() is defined for + // elements inside an array/object, and JSONL is a stream of top-level + // values. EOF is the well-defined terminator for that shape. + for { + var raw map[string]any + if err := dec.Decode(&raw); err != nil { + if errors.Is(err, io.EOF) { + break + } + t.Fatalf("loggingtest: parse log line: %v", err) + } + rec := Record{Attrs: map[string]any{}} + for k, v := range raw { + switch k { + case "time": + if s, ok := v.(string); ok { + rec.Time = s + } + case "level": + if s, ok := v.(string); ok { + rec.Level = s + } + case "msg": + if s, ok := v.(string); ok { + rec.Msg = s + } + default: + rec.Attrs[k] = v + } + } + records = append(records, rec) + } + return records +} diff --git a/cmd/entire/cli/migrate.go b/cmd/entire/cli/migrate.go index d6934c2af1..24e0584c11 100644 --- a/cmd/entire/cli/migrate.go +++ b/cmd/entire/cli/migrate.go @@ -48,12 +48,6 @@ func newMigrateCmd() *cobra.Command { return NewSilentError(errors.New("not a git repository")) } - logging.SetLogLevelGetter(GetLogLevel) - if initErr := logging.Init(ctx, ""); initErr != nil { - fmt.Fprintf(cmd.ErrOrStderr(), "Warning: could not initialize logging: %v\n", initErr) - } else { - defer logging.Close() - } return runMigrateCheckpointsV2(ctx, cmd, forceFlag) }, } diff --git a/cmd/entire/cli/objectsigner.go b/cmd/entire/cli/objectsigner.go deleted file mode 100644 index 889b6bcde2..0000000000 --- a/cmd/entire/cli/objectsigner.go +++ /dev/null @@ -1,130 +0,0 @@ -package cli - -import ( - "context" - "fmt" - "net" - "os" - "sync" - - "github.com/entireio/cli/cmd/entire/cli/logging" - "github.com/go-git/go-git/v6/config" - format "github.com/go-git/go-git/v6/plumbing/format/config" - "github.com/go-git/go-git/v6/x/plugin" - "github.com/go-git/x/plugin/objectsigner/auto" - "golang.org/x/crypto/ssh/agent" -) - -var registerObjectSignerOnce sync.Once -var objectSignerLoader = loadObjectSigner - -func RegisterObjectSigner() { - registerObjectSignerOnce.Do(func() { - signer, ok := objectSignerLoader() - if !ok { - return - } - - //nolint:errcheck,gosec // best-effort; if registration fails, commits are left unsigned - plugin.Register(plugin.ObjectSigner(), func() plugin.Signer { - return signer - }) - }) -} - -func loadObjectSigner() (plugin.Signer, bool) { - cfgSource, err := plugin.Get(plugin.ConfigLoader()) - if err != nil { - // No config loader registered; signing not possible. - return nil, false - } - - sysCfg := loadScopedConfig(cfgSource, config.SystemScope) - globalCfg := loadScopedConfig(cfgSource, config.GlobalScope) - - // Merge system then global so that global settings take precedence. - merged := config.Merge(sysCfg, globalCfg) - - if !merged.Commit.GpgSign.IsTrue() { - return nil, false - } - - // When a custom gpg.ssh.program is configured (e.g. 1Password's - // op-ssh-sign), signing happens via an external binary that go-git - // cannot invoke. Skip native signing silently — checkpoint commits - // will be unsigned, which is acceptable since signing is best-effort. - // The default program is "ssh-keygen", which works with go-git's - // native SSH agent signing and does not need to be skipped. - if auto.Format(merged.GPG.Format) == auto.FormatSSH && hasCustomSSHSignProgram(merged.Raw) { - logging.Debug(context.Background(), "skipping native SSH commit signing: custom gpg.ssh.program is configured") - return nil, false - } - - signer, err := auto.FromConfig(auto.Config{ - SigningKey: merged.User.SigningKey, - Format: auto.Format(merged.GPG.Format), - SSHAgent: connectSSHAgent(), - }) - if err != nil { - logging.Debug(context.Background(), "failed to create object signer", "error", err.Error()) - return nil, false - } - - return signer, true -} - -// connectSSHAgent connects to the SSH agent via SSH_AUTH_SOCK. -// Returns nil if the agent is unavailable. -func connectSSHAgent() agent.Agent { - sock := os.Getenv("SSH_AUTH_SOCK") - if sock == "" { - return nil - } - - var d net.Dialer - conn, err := d.DialContext(context.Background(), "unix", sock) - if err != nil { - return nil - } - - return agent.NewClient(conn) -} - -var scopeName = map[config.Scope]string{ - config.GlobalScope: "global", - config.SystemScope: "system", -} - -// hasCustomSSHSignProgram checks whether gpg.ssh.program is set to a -// non-default value in the raw config. The git default is "ssh-keygen", -// which works with go-git's native SSH agent signing. Custom programs -// (e.g. 1Password's op-ssh-sign) use a separate signing mechanism that -// go-git cannot invoke. -// go-git's Config struct does not expose this field, so we read it directly. -func hasCustomSSHSignProgram(raw *format.Config) bool { - if raw == nil { - return false - } - - program := raw.Section("gpg").Subsection("ssh").Option("program") - - return program != "" && program != "ssh-keygen" -} - -func loadScopedConfig(source plugin.ConfigSource, scope config.Scope) *config.Config { - name := scopeName[scope] - - storer, err := source.Load(scope) - if err != nil { - fmt.Fprintf(os.Stderr, "warning: failed to load %s git config: %v\n", name, err) - return config.NewConfig() - } - - cfg, err := storer.Config() - if err != nil { - fmt.Fprintf(os.Stderr, "warning: failed to parse %s git config: %v\n", name, err) - return config.NewConfig() - } - - return cfg -} diff --git a/cmd/entire/cli/objectsigner_test.go b/cmd/entire/cli/objectsigner_test.go deleted file mode 100644 index 891e7af4e4..0000000000 --- a/cmd/entire/cli/objectsigner_test.go +++ /dev/null @@ -1,66 +0,0 @@ -package cli - -import ( - "testing" - - format "github.com/go-git/go-git/v6/plumbing/format/config" -) - -func TestHasCustomSSHSignProgram(t *testing.T) { - t.Parallel() - - tests := []struct { - name string - raw *format.Config - want bool - }{ - { - name: "nil raw config", - raw: nil, - want: false, - }, - { - name: "empty raw config", - raw: format.New(), - want: false, - }, - { - name: "custom program set", - raw: func() *format.Config { - c := format.New() - c.Section("gpg").Subsection("ssh").SetOption("program", "/Applications/1Password.app/Contents/MacOS/op-ssh-sign") - return c - }(), - want: true, - }, - { - name: "default ssh-keygen is not custom", - raw: func() *format.Config { - c := format.New() - c.Section("gpg").Subsection("ssh").SetOption("program", "ssh-keygen") - return c - }(), - want: false, - }, - { - name: "gpg section exists but no ssh.program", - raw: func() *format.Config { - c := format.New() - c.Section("gpg").SetOption("format", "ssh") - return c - }(), - want: false, - }, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - t.Parallel() - - got := hasCustomSSHSignProgram(tt.raw) - if got != tt.want { - t.Errorf("hasCustomSSHSignProgram() = %v, want %v", got, tt.want) - } - }) - } -} diff --git a/cmd/entire/cli/reset.go b/cmd/entire/cli/reset.go index e75851115a..5b192ec34a 100644 --- a/cmd/entire/cli/reset.go +++ b/cmd/entire/cli/reset.go @@ -5,7 +5,6 @@ import ( "fmt" "charm.land/huh/v2" - "github.com/entireio/cli/cmd/entire/cli/logging" "github.com/entireio/cli/cmd/entire/cli/paths" "github.com/spf13/cobra" ) @@ -27,12 +26,6 @@ func newResetCmd() *cobra.Command { return errors.New("not a git repository") } - // Initialize logging - logging.SetLogLevelGetter(GetLogLevel) - if err := logging.Init(ctx, ""); err == nil { - defer logging.Close() - } - strat := GetStrategy(ctx) // Handle --session flag: delegate to clean's session logic diff --git a/cmd/entire/cli/resume.go b/cmd/entire/cli/resume.go index d8b11ad076..5611d71efd 100644 --- a/cmd/entire/cli/resume.go +++ b/cmd/entire/cli/resume.go @@ -67,15 +67,6 @@ most recent commit with a checkpoint. You'll be prompted to confirm resuming in } func runResume(ctx context.Context, cmd *cobra.Command, branchName string, force bool) error { - // Only initialize logging when inside a git worktree to avoid - // creating .entire/logs/ in arbitrary directories. - if _, err := paths.WorktreeRoot(ctx); err == nil { - logging.SetLogLevelGetter(GetLogLevel) - if err := logging.Init(ctx, ""); err == nil { - defer logging.Close() - } - } - w := cmd.OutOrStdout() errW := cmd.ErrOrStderr() @@ -293,7 +284,7 @@ func resumeFromCurrentBranch(ctx context.Context, w, errW io.Writer, branchName } // Read metadata from checkpoint subtree (paths are relative to checkpoint root) - metadata, err := strategy.ReadCheckpointMetadataFromSubtree(ft, checkpointID.Path()) + metadata, err := strategy.ReadCheckpointMetadataFromSubtree(ctx, ft, checkpointID.Path()) if err != nil { logging.Warn(logCtx, "ReadCheckpointMetadataFromSubtree failed, checking remote", slog.String("checkpoint_id", checkpointID.String()), @@ -357,7 +348,7 @@ func resolveLatestCheckpoint(ctx context.Context, checkpointIDs []id.CheckpointI slog.String("error", pfErr.Error()), ) } - metadata, metaErr := strategy.ReadCheckpointMetadataFromSubtree(ft, cpID.Path()) + metadata, metaErr := strategy.ReadCheckpointMetadataFromSubtree(ctx, ft, cpID.Path()) if metaErr != nil { logging.Debug(ctx, "resolveLatestCheckpoint: checkpoint metadata read failed", slog.String("checkpoint_id", cpID.String()), @@ -698,7 +689,7 @@ func checkRemoteMetadata(ctx context.Context, w, errW io.Writer, checkpointID id slog.String("error", pfErr.Error()), ) } - metadata, metaErr := strategy.ReadCheckpointMetadataFromSubtree(ft, checkpointID.Path()) + metadata, metaErr := strategy.ReadCheckpointMetadataFromSubtree(ctx, ft, checkpointID.Path()) if metaErr == nil { return resumeSession(ctx, w, errW, metadata, false) } @@ -790,7 +781,7 @@ func tryReadCheckpointFromTree(ctx context.Context, tree *object.Tree, repo *git slog.String("error", pfErr.Error()), ) } - metadata, err := strategy.ReadCheckpointMetadataFromSubtree(ft, checkpointID.Path()) + metadata, err := strategy.ReadCheckpointMetadataFromSubtree(ctx, ft, checkpointID.Path()) if err != nil { return nil, fmt.Errorf("failed to read checkpoint metadata: %w", err) } diff --git a/cmd/entire/cli/resume_test.go b/cmd/entire/cli/resume_test.go index 525a3de7de..27ff839f7c 100644 --- a/cmd/entire/cli/resume_test.go +++ b/cmd/entire/cli/resume_test.go @@ -106,7 +106,7 @@ func setupResumeTestRepo(t *testing.T, tmpDir string, createFeatureBranch bool) } // Ensure entire/checkpoints/v1 branch exists - if err := strategy.EnsureMetadataBranch(repo); err != nil { + if err := strategy.EnsureMetadataBranch(t.Context(), repo); err != nil { t.Fatalf("Failed to create metadata branch: %v", err) } @@ -295,7 +295,7 @@ func createCheckpointOnMetadataBranchFull(t *testing.T, repo *git.Repository, se t.Helper() // Get existing metadata branch or create it - if err := strategy.EnsureMetadataBranch(repo); err != nil { + if err := strategy.EnsureMetadataBranch(t.Context(), repo); err != nil { t.Fatalf("Failed to ensure metadata branch: %v", err) } diff --git a/cmd/entire/cli/rewind.go b/cmd/entire/cli/rewind.go index 388665b5d8..eb0a658dbc 100644 --- a/cmd/entire/cli/rewind.go +++ b/cmd/entire/cli/rewind.go @@ -64,15 +64,6 @@ your agent's context.`, ctx := cmd.Context() - // Only initialize logging when inside a git worktree to avoid - // creating .entire/logs/ in arbitrary directories. - if _, err := paths.WorktreeRoot(ctx); err == nil { - logging.SetLogLevelGetter(GetLogLevel) - if err := logging.Init(ctx, ""); err == nil { - defer logging.Close() - } - } - // Discover external agents so checkpoints from external agents can be resolved. external.DiscoverAndRegister(ctx) w := cmd.OutOrStdout() diff --git a/cmd/entire/cli/strategy/common.go b/cmd/entire/cli/strategy/common.go index a2843acc92..d559fe15e5 100644 --- a/cmd/entire/cli/strategy/common.go +++ b/cmd/entire/cli/strategy/common.go @@ -75,7 +75,7 @@ func EnsureSetup(ctx context.Context) error { if err := vercelconfig.InitSettings(ctx); err != nil { return fmt.Errorf("failed to initialize vercel settings: %w", err) } - if err := EnsureMetadataBranch(repo); err != nil { + if err := EnsureMetadataBranch(ctx, repo); err != nil { return fmt.Errorf("failed to ensure metadata branch: %w", err) } @@ -386,7 +386,7 @@ func resolveAgentType(ctxAgentType types.AgentType, state *SessionState) types.A // If the remote-tracking branch (origin/entire/checkpoints/v1) exists and the local // branch is missing or empty, creates/updates the local branch from it. // Otherwise creates an empty orphan. -func EnsureMetadataBranch(repo *git.Repository) error { +func EnsureMetadataBranch(ctx context.Context, repo *git.Repository) error { refName := plumbing.NewBranchReferenceName(paths.MetadataBranchName) // Check if remote-tracking branch exists (e.g., after clone/fetch) @@ -416,7 +416,7 @@ func EnsureMetadataBranch(repo *git.Repository) error { // Local has real data and differs from remote — if disconnected // (no common ancestor), reconciliation happens at pre-push time // or via 'entire doctor'. Read paths warn but do not auto-fix. - logging.Debug(context.Background(), "metadata branch differs from remote, reconciliation deferred to read/write time", + logging.Debug(ctx, "metadata branch differs from remote, reconciliation deferred to read/write time", "local_hash", localRef.Hash().String()[:7], "remote_hash", remoteRef.Hash().String()[:7], ) @@ -572,7 +572,7 @@ func decodeSummaryLiteFromTree(checkpointTree checkpoint.FileReader) (checkpoint // // Uses streaming json.Decoder and minimal structs to avoid loading large nested // objects (Summary, InitialAttribution, TokenUsage) into memory. -func ReadCheckpointMetadata(tree checkpoint.FileReader, checkpointPath string) (*CheckpointInfo, error) { +func ReadCheckpointMetadata(ctx context.Context, tree checkpoint.FileReader, checkpointPath string) (*CheckpointInfo, error) { metadataPath := checkpointPath + "/metadata.json" file, err := tree.File(metadataPath) if err != nil { @@ -584,14 +584,14 @@ func ReadCheckpointMetadata(tree checkpoint.FileReader, checkpointPath string) ( normalizePath := func(raw string) string { return strings.TrimPrefix(raw, "/") } - return decodeCheckpointInfo(file, tree, checkpointPath, normalizePath) + return decodeCheckpointInfo(ctx, file, tree, checkpointPath, normalizePath) } // ReadCheckpointMetadataFromSubtree reads checkpoint metadata from a tree that is // already rooted at the checkpoint directory (e.g., after tree.Tree(checkpointID.Path())). // checkpointPath is the original sharded path (e.g., "ca/b75de47439") and is used // to strip the prefix from absolute session metadata paths stored in the summary. -func ReadCheckpointMetadataFromSubtree(tree checkpoint.FileReader, checkpointPath string) (*CheckpointInfo, error) { +func ReadCheckpointMetadataFromSubtree(ctx context.Context, tree checkpoint.FileReader, checkpointPath string) (*CheckpointInfo, error) { file, err := tree.File(paths.MetadataFileName) if err != nil { return nil, fmt.Errorf("failed to find %s in checkpoint subtree: %w", paths.MetadataFileName, err) @@ -603,7 +603,7 @@ func ReadCheckpointMetadataFromSubtree(tree checkpoint.FileReader, checkpointPat normalizePath := func(raw string) string { return strings.TrimPrefix(raw, prefix) } - return decodeCheckpointInfo(file, tree, checkpointPath, normalizePath) + return decodeCheckpointInfo(ctx, file, tree, checkpointPath, normalizePath) } // decodeCheckpointInfo is the shared implementation for ReadCheckpointMetadata and @@ -614,6 +614,7 @@ func ReadCheckpointMetadataFromSubtree(tree checkpoint.FileReader, checkpointPat // paths that are valid for tree.File() lookups (the transform differs depending on // whether tree is a full metadata branch tree or a checkpoint subtree). func decodeCheckpointInfo( + ctx context.Context, file checkpoint.FileOpener, tree checkpoint.FileReader, checkpointPath string, @@ -645,7 +646,7 @@ func decodeCheckpointInfo( sessionMetadataPath := normalizePath(sessionPaths.Metadata) sessionMeta, sErr := decodeSessionMetadataLite(tree, sessionMetadataPath) if sErr != nil { - logging.Debug(context.Background(), "decodeCheckpointInfo: session metadata decode failed", + logging.Debug(ctx, "decodeCheckpointInfo: session metadata decode failed", slog.Int("session_index", i), slog.String("metadata_path", sessionMetadataPath), slog.String("checkpoint_path", checkpointPath), diff --git a/cmd/entire/cli/strategy/common_test.go b/cmd/entire/cli/strategy/common_test.go index bc91eff5a8..40ba7a6090 100644 --- a/cmd/entire/cli/strategy/common_test.go +++ b/cmd/entire/cli/strategy/common_test.go @@ -977,7 +977,7 @@ func TestEnsureMetadataBranch(t *testing.T) { t.Fatalf("failed to open repo: %v", err) } - if err := EnsureMetadataBranch(repo); err != nil { + if err := EnsureMetadataBranch(t.Context(), repo); err != nil { t.Fatalf("EnsureMetadataBranch() failed: %v", err) } @@ -1041,7 +1041,7 @@ func TestEnsureMetadataBranch(t *testing.T) { t.Fatalf("failed to set ref: %v", err) } - if err := EnsureMetadataBranch(repo); err != nil { + if err := EnsureMetadataBranch(t.Context(), repo); err != nil { t.Fatalf("EnsureMetadataBranch() failed: %v", err) } @@ -1063,7 +1063,7 @@ func TestEnsureMetadataBranch(t *testing.T) { if err != nil { t.Fatalf("failed to open repo: %v", err) } - if err := EnsureMetadataBranch(repo); err != nil { + if err := EnsureMetadataBranch(t.Context(), repo); err != nil { t.Fatalf("EnsureMetadataBranch() failed: %v", err) } @@ -1107,7 +1107,7 @@ func TestEnsureMetadataBranch_WritesVercelConfigWhenEnabled(t *testing.T) { t.Fatalf("InitSettings() failed: %v", err) } - if err := EnsureMetadataBranch(repo); err != nil { + if err := EnsureMetadataBranch(t.Context(), repo); err != nil { t.Fatalf("EnsureMetadataBranch() failed: %v", err) } @@ -1197,7 +1197,7 @@ func TestEnsureMetadataBranch_DisconnectedBranchesNotReconciledInEnable(t *testi t.Fatalf("local branch not found: %v", err) } - if err := EnsureMetadataBranch(repo); err != nil { + if err := EnsureMetadataBranch(t.Context(), repo); err != nil { t.Fatalf("EnsureMetadataBranch() failed: %v", err) } @@ -1224,7 +1224,7 @@ func TestEnsureMetadataBranch_DoesNotFastForwardWhenBehind(t *testing.T) { if err != nil { t.Fatalf("failed to open repo: %v", err) } - if err := EnsureMetadataBranch(repo); err != nil { + if err := EnsureMetadataBranch(t.Context(), repo); err != nil { t.Fatalf("first EnsureMetadataBranch() failed: %v", err) } @@ -1264,7 +1264,7 @@ func TestEnsureMetadataBranch_DoesNotFastForwardWhenBehind(t *testing.T) { t.Fatalf("failed to reopen repo: %v", err) } - if err := EnsureMetadataBranch(repo); err != nil { + if err := EnsureMetadataBranch(t.Context(), repo); err != nil { t.Fatalf("second EnsureMetadataBranch() failed: %v", err) } diff --git a/cmd/entire/cli/strategy/manual_commit_condensation_test.go b/cmd/entire/cli/strategy/manual_commit_condensation_test.go index 4cdf265fac..64f241166e 100644 --- a/cmd/entire/cli/strategy/manual_commit_condensation_test.go +++ b/cmd/entire/cli/strategy/manual_commit_condensation_test.go @@ -54,7 +54,7 @@ func (f *fakeTranscriptCompactorAgent) GetSessionDir(string) (string, error) { r func (f *fakeTranscriptCompactorAgent) ResolveSessionFile(_, sessionID string) string { return sessionID } -func (f *fakeTranscriptCompactorAgent) ReadSession(*agent.HookInput) (*agent.AgentSession, error) { +func (f *fakeTranscriptCompactorAgent) ReadSession(context.Context, *agent.HookInput) (*agent.AgentSession, error) { return nil, nil //nolint:nilnil // test stub } func (f *fakeTranscriptCompactorAgent) WriteSession(context.Context, *agent.AgentSession) error { diff --git a/cmd/entire/cli/strategy/metadata_reconcile_test.go b/cmd/entire/cli/strategy/metadata_reconcile_test.go index 4b97122f05..1c8184e0c2 100644 --- a/cmd/entire/cli/strategy/metadata_reconcile_test.go +++ b/cmd/entire/cli/strategy/metadata_reconcile_test.go @@ -98,7 +98,7 @@ func TestReconcileDisconnected_SameHash(t *testing.T) { } // Create local branch from remote (same hash) - if err := EnsureMetadataBranch(repo); err != nil { + if err := EnsureMetadataBranch(t.Context(), repo); err != nil { t.Fatalf("EnsureMetadataBranch failed: %v", err) } @@ -120,7 +120,7 @@ func TestReconcileDisconnected_SharedAncestry(t *testing.T) { } // Create local branch from remote (shared base) - if err := EnsureMetadataBranch(repo); err != nil { + if err := EnsureMetadataBranch(t.Context(), repo); err != nil { t.Fatalf("EnsureMetadataBranch failed: %v", err) } @@ -462,7 +462,7 @@ func TestIsMetadataDisconnected_SameHash(t *testing.T) { t.Fatalf("failed to open repo: %v", err) } - if err := EnsureMetadataBranch(repo); err != nil { + if err := EnsureMetadataBranch(t.Context(), repo); err != nil { t.Fatalf("EnsureMetadataBranch failed: %v", err) } @@ -486,7 +486,7 @@ func TestIsMetadataDisconnected_SharedAncestry(t *testing.T) { t.Fatalf("failed to open repo: %v", err) } - if err := EnsureMetadataBranch(repo); err != nil { + if err := EnsureMetadataBranch(t.Context(), repo); err != nil { t.Fatalf("EnsureMetadataBranch failed: %v", err) } diff --git a/cmd/entire/cli/strategy/readcheckpoint_bench_test.go b/cmd/entire/cli/strategy/readcheckpoint_bench_test.go index 7fddb01725..3ac10b1028 100644 --- a/cmd/entire/cli/strategy/readcheckpoint_bench_test.go +++ b/cmd/entire/cli/strategy/readcheckpoint_bench_test.go @@ -37,7 +37,7 @@ func benchReadCheckpointMetadata(checkpointCount int) func(*testing.B) { b.ReportMetric(float64(checkpointCount), "total_checkpoints") for b.Loop() { - info, err := ReadCheckpointMetadata(tree, cpPath) + info, err := ReadCheckpointMetadata(b.Context(), tree, cpPath) if err != nil { b.Fatalf("ReadCheckpointMetadata: %v", err) } diff --git a/cmd/entire/cli/strategy/rewind_test.go b/cmd/entire/cli/strategy/rewind_test.go index 7db5c51b17..a8cedb7e25 100644 --- a/cmd/entire/cli/strategy/rewind_test.go +++ b/cmd/entire/cli/strategy/rewind_test.go @@ -567,7 +567,7 @@ func (f *fakeExternalAgent) ReassembleTranscript(_ [][]byte) ([]byte, error) { r func (f *fakeExternalAgent) GetSessionID(_ *agent.HookInput) string { return "" } func (f *fakeExternalAgent) GetSessionDir(_ string) (string, error) { return "", nil } func (f *fakeExternalAgent) ResolveSessionFile(_, _ string) string { return "" } -func (f *fakeExternalAgent) ReadSession(_ *agent.HookInput) (*agent.AgentSession, error) { +func (f *fakeExternalAgent) ReadSession(_ context.Context, _ *agent.HookInput) (*agent.AgentSession, error) { return nil, nil //nolint:nilnil // test stub } func (f *fakeExternalAgent) WriteSession(_ context.Context, _ *agent.AgentSession) error { return nil } diff --git a/cmd/entire/cli/summarize/claude_test.go b/cmd/entire/cli/summarize/claude_test.go index b73d398114..a1260715f4 100644 --- a/cmd/entire/cli/summarize/claude_test.go +++ b/cmd/entire/cli/summarize/claude_test.go @@ -45,7 +45,7 @@ func (s *stubTextGenerator) GetSessionDir(string) (string, error) { return "", n func (s *stubTextGenerator) ResolveSessionFile(string, string) string { return "" } -func (s *stubTextGenerator) ReadSession(*agent.HookInput) (*agent.AgentSession, error) { +func (s *stubTextGenerator) ReadSession(context.Context, *agent.HookInput) (*agent.AgentSession, error) { return &agent.AgentSession{}, nil } diff --git a/cmd/entire/cli/summarize/text_generator_test.go b/cmd/entire/cli/summarize/text_generator_test.go index a5dc7d015f..3e2e21a742 100644 --- a/cmd/entire/cli/summarize/text_generator_test.go +++ b/cmd/entire/cli/summarize/text_generator_test.go @@ -30,7 +30,7 @@ func (m *mockTextGenerator) ReassembleTranscript([][]byte) ([]byte, error) { ret func (m *mockTextGenerator) GetSessionID(*agent.HookInput) string { return "" } func (m *mockTextGenerator) GetSessionDir(string) (string, error) { return "", nil } func (m *mockTextGenerator) ResolveSessionFile(string, string) string { return "" } -func (m *mockTextGenerator) ReadSession(*agent.HookInput) (*agent.AgentSession, error) { +func (m *mockTextGenerator) ReadSession(context.Context, *agent.HookInput) (*agent.AgentSession, error) { return nil, nil //nolint:nilnil // test stub } func (m *mockTextGenerator) WriteSession(context.Context, *agent.AgentSession) error { return nil } diff --git a/cmd/entire/main.go b/cmd/entire/main.go index b829d02122..d2084439a9 100644 --- a/cmd/entire/main.go +++ b/cmd/entire/main.go @@ -11,12 +11,21 @@ import ( "syscall" "github.com/entireio/cli/cmd/entire/cli" + "github.com/entireio/cli/cmd/entire/cli/logging" + "github.com/entireio/cli/cmd/entire/cli/settings" "github.com/spf13/cobra" ) func main() { - // Create context that cancels on interrupt + // Run delegates the real work so deferred cleanup (logger close, ctx + // cancel) runs before os.Exit. main itself only translates the result + // into an exit code. + os.Exit(run()) +} + +func run() int { ctx, cancel := context.WithCancel(context.Background()) + defer cancel() // Handle interrupt signals sigChan := make(chan os.Signal, 1) @@ -30,25 +39,41 @@ func main() { cancel() }() + // Initialize the logger once for the whole process. The logger flows + // through the cobra context; commands and hooks enrich it via + // logging.WithSession / WithComponent / etc. The lazy writer means + // no log file is created for invocations that emit no log lines + // (e.g., entire --version outside a repo). + settingsLevel := "" + if s, err := settings.Load(ctx); err == nil { + settingsLevel = s.LogLevel + } + level := logging.ResolveLevel(os.Getenv(logging.LogLevelEnvVar), settingsLevel) + logger, closeLogger := logging.New(ctx, logging.Options{Level: level}) + defer func() { + if err := closeLogger(); err != nil { + fmt.Fprintf(os.Stderr, "[entire] log close: %v\n", err) + } + }() + ctx = logging.WithLogger(ctx, logger) + // Create and execute root command rootCmd := cli.NewRootCmd() err := rootCmd.ExecuteContext(ctx) - if err != nil { - var silent *cli.SilentError - - switch { - case errors.As(err, &silent): - // Command already printed the error - case strings.Contains(err.Error(), "unknown command") || strings.Contains(err.Error(), "unknown flag"): - showSuggestion(rootCmd, err) - default: - fmt.Fprintln(rootCmd.OutOrStderr(), err) - } + if err == nil { + return 0 + } - cancel() - os.Exit(1) + var silent *cli.SilentError + switch { + case errors.As(err, &silent): + // Command already printed the error + case strings.Contains(err.Error(), "unknown command") || strings.Contains(err.Error(), "unknown flag"): + showSuggestion(rootCmd, err) + default: + fmt.Fprintln(rootCmd.OutOrStderr(), err) } - cancel() // Cleanup on successful exit + return 1 } func showSuggestion(cmd *cobra.Command, err error) {