diff --git a/cmd/odek/cleanup.go b/cmd/odek/cleanup.go index 6b8afcfb..742f9e59 100644 --- a/cmd/odek/cleanup.go +++ b/cmd/odek/cleanup.go @@ -11,6 +11,7 @@ import ( "github.com/BackendStack21/odek/internal/config" "github.com/BackendStack21/odek/internal/maintenance" + "github.com/BackendStack21/odek/internal/runtimelog" "github.com/BackendStack21/odek/internal/session" ) @@ -82,11 +83,12 @@ func startStorageMaintenance(ctx context.Context, resolved config.ResolvedConfig // success line when there was nothing to do. func printCleanupReport(r maintenance.Report) { if r.SessionsRemoved == 0 && r.AuditRemoved == 0 && r.PlansRemoved == 0 && - r.ArtifactsRemoved == 0 && r.MediaFreedBytes == 0 && len(r.LogsRotated) == 0 { + r.RuntimeLogRecordsRemoved == 0 && r.ArtifactsRemoved == 0 && r.MediaFreedBytes == 0 && len(r.LogsRotated) == 0 { fmt.Println("Storage is clean — nothing to remove.") return } fmt.Println("Cleanup complete:") + fmt.Printf(" runtime records removed: %d\n", r.RuntimeLogRecordsRemoved) fmt.Printf(" sessions removed: %d\n", r.SessionsRemoved) fmt.Printf(" audit records removed: %d\n", r.AuditRemoved) fmt.Printf(" plans removed: %d\n", r.PlansRemoved) @@ -220,12 +222,23 @@ func filesOlderThan(dir string, cutoff time.Time, recursive bool) []string { // printCleanupDryRun reports the candidate list without removing anything. func printCleanupDryRun(home string, cfg maintenance.Config) { + expired := 0 + if cfg.RuntimeLogMaxAgeHours > 0 { + n, err := runtimelog.Prune(context.Background(), filepath.Join(home, "runtime.log"), time.Now().Add(-time.Duration(maintenance.ClampRetentionHours(cfg.RuntimeLogMaxAgeHours))*time.Hour), true) + if err != nil { + fmt.Fprintf(os.Stderr, "runtime log preview failed: %v\n", err) + } else { + expired = n + } + } + c := collectCleanupCandidates(home, cfg) - if len(c.sessions) == 0 && len(c.audit) == 0 && len(c.plans) == 0 && len(c.logs) == 0 && len(c.artifacts) == 0 { + if expired == 0 && len(c.sessions) == 0 && len(c.audit) == 0 && len(c.plans) == 0 && len(c.logs) == 0 && len(c.artifacts) == 0 { fmt.Println("Dry run: storage is clean — nothing would be removed.") return } fmt.Println("Dry run — nothing removed. Would remove:") + fmt.Printf(" runtime records expired: %d\n", expired) fmt.Printf(" sessions: %d\n", len(c.sessions)) fmt.Printf(" audit records: %d\n", len(c.audit)) fmt.Printf(" plans: %d\n", len(c.plans)) diff --git a/cmd/odek/dispatch.go b/cmd/odek/dispatch.go index f4beb0a3..8463c532 100644 --- a/cmd/odek/dispatch.go +++ b/cmd/odek/dispatch.go @@ -6,8 +6,11 @@ import ( "fmt" "os" "runtime" + "slices" "github.com/BackendStack21/odek/internal/budget" + "github.com/BackendStack21/odek/internal/diagnostics" + "github.com/BackendStack21/odek/internal/events" ) // dispatch routes a top-level CLI invocation to its handler. It takes the @@ -27,6 +30,19 @@ func dispatch(args []string) int { cmd := args[0] rest := args[1:] + // Protocol children relay diagnostics through their parent once initialized. + // Keep version queries independent of configuration and filesystem writes. + preview := cmd == "cleanup" && slices.Contains(rest, "--dry-run") + if !preview && (cmd != "subagent" || subagentDepth() == 0) && cmd != "version" && cmd != "--version" && cmd != "-v" { + closeLog := startOperationalLogging(commandSurface(cmd)) + defer closeLog() + defer func() { + if value := recover(); value != nil { + diagnostics.Emit(events.Event{Type: "panic_recovered", Data: map[string]any{"component": "cli", "operation": "dispatch", "error_class": "panic"}}) + panic(value) // preserve the original crash behavior after flushing + } + }() + } switch cmd { case "run": @@ -66,6 +82,7 @@ func dispatch(args []string) int { case "upgrade": return cliExit(upgradeCmd(rest)) default: + diagnostics.Warning("cli", "unknown_command", nil) fmt.Fprintf(os.Stderr, "odek: unknown command %q\n", cmd) printUsage() return 1 @@ -78,6 +95,7 @@ func cliExit(err error) int { if err == nil { return 0 } + logCommandFailure(err) fmt.Fprintf(os.Stderr, "odek: %v\n", err) return 1 } @@ -90,6 +108,7 @@ func runExit(err error) int { if err == nil { return 0 } + logCommandFailure(err) fmt.Fprintf(os.Stderr, "odek: %v\n", err) if _, ok := budget.As(err); ok { return 4 @@ -123,6 +142,7 @@ func subagentExit(err error) int { // Pre-run budget stop (share-mode exhaustion): the typed budget // error arrived before any run started. Same wire contract as a // mid-run exhaustion — budget_exhausted envelope, exit code 4. + logCommandFailure(err) fmt.Fprintf(os.Stderr, "odek: %v\n", err) _ = json.NewEncoder(os.Stdout).Encode(subagentResult{ Status: "budget_exhausted", @@ -131,6 +151,7 @@ func subagentExit(err error) int { }) return 4 } + logCommandFailure(err) fmt.Fprintf(os.Stderr, "odek: %v\n", err) _ = json.NewEncoder(os.Stdout).Encode(subagentResult{ Status: "error", @@ -150,3 +171,13 @@ func printVersion() { fmt.Printf(" built: %s\n", date) } } + +// commandSurface never copies an arbitrary CLI argument into metadata. +func commandSurface(cmd string) string { + switch cmd { + case "run", "subagent", "continue", "init", "session", "audit", "repl", "skill", "serve", "mcp", "telegram", "schedule", "memory", "cleanup", "upgrade": + return cmd + default: + return "cli" + } +} diff --git a/cmd/odek/introspect.go b/cmd/odek/introspect.go index 81d04d63..2571fd83 100644 --- a/cmd/odek/introspect.go +++ b/cmd/odek/introspect.go @@ -83,12 +83,14 @@ func buildConfigView(resolved config.ResolvedConfig) map[string]any { "enabled": resolved.Tools.Enabled, "disabled": resolved.Tools.Disabled, }, + "logging": map[string]any{"enabled": resolved.Logging.Enabled}, "maintenance": map[string]any{ - "enabled": resolved.Maintenance.Enabled, - "interval_minutes": resolved.Maintenance.IntervalMinutes, - "sessions_max_age_days": resolved.Maintenance.SessionsMaxAgeDays, - "audit_max_age_days": resolved.Maintenance.AuditMaxAgeDays, - "plans_max_age_days": resolved.Maintenance.PlansMaxAgeDays, + "runtime_log_max_age_hours": resolved.Maintenance.RuntimeLogMaxAgeHours, + "enabled": resolved.Maintenance.Enabled, + "interval_minutes": resolved.Maintenance.IntervalMinutes, + "sessions_max_age_days": resolved.Maintenance.SessionsMaxAgeDays, + "audit_max_age_days": resolved.Maintenance.AuditMaxAgeDays, + "plans_max_age_days": resolved.Maintenance.PlansMaxAgeDays, }, "dangerous_default_action": resolved.Dangerous.DefaultAction, "guard_scan": guardScanView(resolved.Guard.Scan), diff --git a/cmd/odek/main.go b/cmd/odek/main.go index 0e5da749..a6fd0564 100644 --- a/cmd/odek/main.go +++ b/cmd/odek/main.go @@ -18,6 +18,7 @@ import ( "github.com/BackendStack21/odek/internal/budget" "github.com/BackendStack21/odek/internal/config" "github.com/BackendStack21/odek/internal/danger" + "github.com/BackendStack21/odek/internal/diagnostics" "github.com/BackendStack21/odek/internal/events" "github.com/BackendStack21/odek/internal/guard" "github.com/BackendStack21/odek/internal/llmclient" @@ -1528,12 +1529,14 @@ const globalConfigTemplate = `{ "timezone": "UTC", "catchup": false }, + "logging": {"enabled": false}, "maintenance": { "enabled": true, "interval_minutes": 60, "sessions_max_age_days": 30, "audit_max_age_days": 14, "log_max_mb": 50, + "runtime_log_max_age_hours": 168, "plans_max_age_days": 30, "artifacts_max_age_hours": 24 }, @@ -1963,6 +1966,7 @@ func run(args []string) error { Limits: resolved.Limits, } applyResolvedProvider(&runCfg, resolved) + runCfg.RuntimeLogSurface = "run" agent, err := odek.New(runCfg) if err != nil { return err @@ -2055,6 +2059,7 @@ func run(args []string) error { if sessionID == "" { sessionID = session.GenerateID() } + agent.SetToolSessionID(sessionID) ctx = withReadLedger(ctx, sessionID) if auditStore == nil { store, err := session.NewStore() @@ -2319,6 +2324,7 @@ func ensureSandbox(resolved config.ResolvedConfig, tools []odek.Tool, cfg sandbo } func setupSandbox(tools []odek.Tool, cfg sandboxConfig) (containerName string, cleanup func() error, err error) { + defer func() { diagnostics.Report("sandbox", "setup", "", err) }() // An implicit Dockerfile.odek build executes repo-controlled code on the // host; refuse to proceed unless it was approved (startup prompt, trusted // project, or ODEK_APPROVE_PROJECT_SANDBOX=1). Skipped when an explicit @@ -2507,6 +2513,14 @@ type toolConfig struct { // applyResolvedProvider copies the v2 LLM identity (provider registry + // timeout/window) onto an odek.Config built from a ResolvedConfig. func applyResolvedProvider(cfg *odek.Config, resolved config.ResolvedConfig) { + if resolved.Logging.Enabled { + cfg.RuntimeLogPath = expandHome("~/.odek/runtime.log") + cfg.RuntimeLogMaxMB = resolved.Maintenance.LogMaxMB + // Prices support estimates on every surface without adding budget caps. + cfg.Limits.InputCostPerMillionUSD = resolved.Limits.InputCostPerMillionUSD + cfg.Limits.OutputCostPerMillionUSD = resolved.Limits.OutputCostPerMillionUSD + cfg.Limits.ModelPrices = resolved.Limits.ModelPrices + } cfg.Provider = resolved.Provider cfg.Providers = resolved.ProviderOverrides() if resolved.LLM.RequestTimeoutSeconds > 0 { @@ -3345,7 +3359,9 @@ func continueCmd(args []string) error { Guard: injectionGuard, GuardConfig: resolved.Guard, } + contCfg.EventContext.SessionID = sess.ID applyResolvedProvider(&contCfg, resolved) + contCfg.RuntimeLogSurface = "continue" agent, err := odek.New(contCfg) if err != nil { return err diff --git a/cmd/odek/operational_logging.go b/cmd/odek/operational_logging.go new file mode 100644 index 00000000..7929ce5d --- /dev/null +++ b/cmd/odek/operational_logging.go @@ -0,0 +1,72 @@ +package main + +import ( + "fmt" + "os" + "path/filepath" + "sync" + + "github.com/BackendStack21/odek/internal/config" + "github.com/BackendStack21/odek/internal/diagnostics" + "github.com/BackendStack21/odek/internal/events" + "github.com/BackendStack21/odek/internal/runtimelog" +) + +// startOperationalLogging covers failures before an Agent exists and between +// turns. Agent loggers use the same process identity and cooperating file lock. +func startOperationalLogging(surface string) func() { + var mu sync.Mutex + var pending []events.Event + var lost int + var logger *runtimelog.Logger + booting := true + restore := diagnostics.Install(func(ev events.Event) { + mu.Lock() + defer mu.Unlock() + if logger != nil { + logger.Emit(ev) + } else if booting { + if len(pending) < 128 { + pending = append(pending, ev) + } else { + lost++ + } + } + }) + enabled, maxMB := config.LoadLoggingSettings() + mu.Lock() + booting = false + if enabled { + var err error + logger, err = runtimelog.Open(filepath.Join(expandHome("~/.odek"), "runtime.log"), surface, maxMB) + if err != nil { + fmt.Fprintf(os.Stderr, "odek: operational logging unavailable: %v\n", err) + } else { + for _, ev := range pending { + logger.Emit(ev) + } + if lost > 0 { + logger.Emit(events.Event{Type: "logging_dropped", Data: map[string]any{"dropped": lost}}) + } + } + } + pending = nil + mu.Unlock() + var once sync.Once + return func() { + once.Do(func() { + restore() + mu.Lock() + l := logger + logger = nil + mu.Unlock() + if l != nil { + l.Close() + } + }) + } +} + +func logCommandFailure(err error) { + diagnostics.Report("cli", "command", "", err) +} diff --git a/cmd/odek/operational_logging_test.go b/cmd/odek/operational_logging_test.go new file mode 100644 index 00000000..87d259f0 --- /dev/null +++ b/cmd/odek/operational_logging_test.go @@ -0,0 +1,207 @@ +package main + +import ( + "encoding/json" + "errors" + "net/http" + "net/http/httptest" + "os" + "path/filepath" + "strings" + "syscall" + "testing" + + "github.com/BackendStack21/odek/internal/diagnostics" + "github.com/BackendStack21/odek/internal/events" + "github.com/BackendStack21/odek/internal/maintenance" + "github.com/BackendStack21/odek/internal/session" +) + +func operationalTestHome(t *testing.T) string { + t.Helper() + home := t.TempDir() + t.Setenv("HOME", home) + t.Setenv("ODEK_LOGGING_ENABLED", "true") + t.Chdir(home) + if err := os.Mkdir(filepath.Join(home, ".odek"), 0700); err != nil { + t.Fatal(err) + } + return home +} + +func readOperationalRecords(t *testing.T, home string) []map[string]any { + t.Helper() + b, err := os.ReadFile(filepath.Join(home, ".odek", "runtime.log")) + if err != nil { + t.Fatal(err) + } + if strings.Contains(string(b), "PRIVATE") { + t.Fatalf("private data leaked: %s", b) + } + var records []map[string]any + for _, line := range strings.Split(strings.TrimSpace(string(b)), "\n") { + var record map[string]any + if err := json.Unmarshal([]byte(line), &record); err != nil { + t.Fatal(err) + } + if record["process_id"] == "" || record["pid"] != float64(os.Getpid()) { + t.Fatal(record) + } + records = append(records, record) + } + return records +} + +func TestOperationalLoggingStartupAndCommandFailure(t *testing.T) { + home := operationalTestHome(t) + if err := os.WriteFile(filepath.Join(home, ".odek", "config.json"), []byte(`{"PRIVATE":`), 0600); err != nil { + t.Fatal(err) + } + if code := dispatch([]string{"run", "--PRIVATE-invalid-flag"}); code == 0 { + t.Fatal("invalid command succeeded") + } + records := readOperationalRecords(t, home) + var configFailure, commandFailure bool + for _, record := range records { + data := record["data"].(map[string]any) + configFailure = configFailure || data["operation"] == "decode_file" + commandFailure = commandFailure || data["component"] == "cli" && record["level"] == "ERROR" + } + if !configFailure || !commandFailure { + t.Fatalf("missing startup/command diagnostics: %+v", records) + } +} + +func TestOperationalLoggingStorageAndMaintenance(t *testing.T) { + home := operationalTestHome(t) + closeLog := startOperationalLogging("test") + t.Cleanup(closeLog) + store, err := session.NewStoreWithDir(filepath.Join(home, "sessions")) + if err != nil { + t.Fatal(err) + } + sess, err := store.Create(nil, "test", "PRIVATE task") + if err != nil { + t.Fatal(err) + } + // Replacing index.json with a directory forces a real persistence failure. + index := filepath.Join(home, "sessions", "index.json") + if err := os.Remove(index); err != nil { + t.Fatal(err) + } + if err := os.Mkdir(index, 0700); err != nil { + t.Fatal(err) + } + if err := store.SaveNoIndex(sess); err == nil { + t.Fatal("save unexpectedly succeeded") + } + brokenHome := filepath.Join(home, "broken") + if err := os.MkdirAll(filepath.Join(brokenHome, "runtime.log"), 0700); err != nil { + t.Fatal(err) + } + if _, err := maintenance.Sweep(t.Context(), brokenHome, maintenance.Config{RuntimeLogMaxAgeHours: 1, LogMaxMB: 1}); err == nil { + t.Fatal("sweep unexpectedly succeeded") + } + closeLog() + records := readOperationalRecords(t, home) + operations := map[string]bool{} + for _, record := range records { + data := record["data"].(map[string]any) + operations[data["component"].(string)+"/"+data["operation"].(string)] = true + if data["component"] == "session" && record["session_id"] != sess.ID { + t.Fatal("session correlation lost") + } + } + for _, op := range []string{"session/save", "maintenance/runtime_log_retention", "maintenance/log_rotation"} { + if !operations[op] { + t.Fatalf("missing %s: %+v", op, records) + } + } +} + +func TestOperationalLoggingDisabledAndUnavailable(t *testing.T) { + home := operationalTestHome(t) + t.Setenv("ODEK_LOGGING_ENABLED", "false") + closeLog := startOperationalLogging("test") + diagnostics.Report("test", "disabled", "", syscall.ENOSPC) + closeLog() + path := filepath.Join(home, ".odek", "runtime.log") + if _, err := os.Stat(path); !os.IsNotExist(err) { + t.Fatal("disabled logger created file") + } + t.Setenv("ODEK_LOGGING_ENABLED", "true") + if err := os.Mkdir(path, 0700); err != nil { + t.Fatal(err) + } + closeLog = startOperationalLogging("test") + diagnostics.Report("test", "unavailable", "", syscall.ENOSPC) + closeLog() // logging failure must not crash the command or recurse +} + +func TestOperationalLoggingKeepsCleanupPreviewReadOnly(t *testing.T) { + home := operationalTestHome(t) + if code := dispatch([]string{"cleanup", "--dry-run"}); code != 0 { + t.Fatalf("preview exit %d", code) + } + for _, name := range []string{"runtime.log", "runtime.log.lock"} { + if _, err := os.Stat(filepath.Join(home, ".odek", name)); !os.IsNotExist(err) { + t.Fatalf("preview created %s", name) + } + } +} + +func TestHTTPDiagnosticsPrivacyAndResponseSemantics(t *testing.T) { + var got []events.Event + restore := diagnostics.Install(func(ev events.Event) { got = append(got, ev) }) + defer restore() + mux := http.NewServeMux() + mux.HandleFunc("/failed/{id}", func(w http.ResponseWriter, r *http.Request) { http.Error(w, "PRIVATE response", 503) }) + mux.HandleFunc("/flush", func(w http.ResponseWriter, r *http.Request) { w.(http.Flusher).Flush(); _, _ = w.Write([]byte("ok")) }) + mux.HandleFunc("/ok", func(w http.ResponseWriter, r *http.Request) { _, _ = w.Write([]byte("ok")) }) + mux.HandleFunc("/panic", func(w http.ResponseWriter, r *http.Request) { panic("PRIVATE panic") }) + handler := diagnosticHTTPHandler(mux) + w := httptest.NewRecorder() + handler.ServeHTTP(w, httptest.NewRequest("GET", "/failed/PRIVATE?token=PRIVATE", nil)) + if w.Code != 503 || !strings.Contains(w.Body.String(), "PRIVATE response") { + t.Fatal("response changed") + } + if len(got) != 1 || got[0].Data["operation"] != "/failed/{id}" || got[0].Data["http_status"] != 503 || got[0].Type != "operation_failed" { + t.Fatal(got) + } + handler.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "/PRIVATE-missing", nil)) + if got[1].Type != "operation_warning" || got[1].Data["operation"] != "unmatched_route" { + t.Fatal(got[1]) + } + w = httptest.NewRecorder() + handler.ServeHTTP(w, httptest.NewRequest("GET", "/flush", nil)) + if !w.Flushed || w.Body.String() != "ok" || len(got) != 2 { + t.Fatal("flush behavior changed") + } + w = httptest.NewRecorder() + handler.ServeHTTP(w, httptest.NewRequest("GET", "/ok", nil)) + if w.Code != http.StatusOK || w.Body.String() != "ok" || len(got) != 2 { + t.Fatal("implicit successful response changed") + } + func() { + defer func() { + if recover() != "PRIVATE panic" { + t.Error("panic swallowed or changed") + } + }() + handler.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "/panic", nil)) + }() + if len(got) != 3 || got[2].Type != "panic_recovered" { + t.Fatal(got) + } + b, _ := json.Marshal(got) + if strings.Contains(string(b), "PRIVATE") { + t.Fatalf("request or panic leaked: %s", b) + } + recorder := &diagnosticResponseWriter{ResponseWriter: httptest.NewRecorder()} + if _, _, err := recorder.Hijack(); !errors.Is(err, http.ErrNotSupported) { + t.Fatal(err) + } + if recorder.Unwrap() != recorder.ResponseWriter { + t.Fatal("response controller cannot unwrap") + } +} diff --git a/cmd/odek/repl.go b/cmd/odek/repl.go index 2276f488..3ed8870b 100644 --- a/cmd/odek/repl.go +++ b/cmd/odek/repl.go @@ -210,7 +210,11 @@ func replCmd(args []string) error { Guard: injectionGuard, GuardConfig: resolved.Guard, } + if sess != nil { + replCfg.EventContext.SessionID = sess.ID + } applyResolvedProvider(&replCfg, resolved) + replCfg.RuntimeLogSurface = "repl" agent, err := odek.New(replCfg) if err != nil { return err diff --git a/cmd/odek/schedule.go b/cmd/odek/schedule.go index b39a67f5..16426622 100644 --- a/cmd/odek/schedule.go +++ b/cmd/odek/schedule.go @@ -756,6 +756,7 @@ func runTaskHeadless(ctx context.Context, resolved config.ResolvedConfig, system DangerousConfig: &dangerCfg, } applyResolvedProvider(&schedCfg, resolved) + schedCfg.RuntimeLogSurface = "schedule" agent, err := odek.New(schedCfg) if err != nil { return "", 0, err @@ -769,6 +770,7 @@ func runTaskHeadless(ctx context.Context, resolved config.ResolvedConfig, system // runLoop choke point. Keeping the returned history lets unattended runs // receive the same IPI ingest/divergence audit as interactive surfaces. auditID := fmt.Sprintf("schedule-%d", time.Now().UnixNano()) + agent.SetToolSessionID(auditID) auditStore := session.NewAuditStore(expandHome("~/.odek/sessions")) ctx = withAuditRecorder(ctx, auditStore, auditID, 1) ctx = withReadLedger(ctx, auditID) diff --git a/cmd/odek/serve.go b/cmd/odek/serve.go index 9928fdce..7384ee9c 100644 --- a/cmd/odek/serve.go +++ b/cmd/odek/serve.go @@ -30,6 +30,7 @@ import ( "github.com/BackendStack21/odek/internal/bgproc" "github.com/BackendStack21/odek/internal/budget" "github.com/BackendStack21/odek/internal/config" + "github.com/BackendStack21/odek/internal/diagnostics" "github.com/BackendStack21/odek/internal/events" "github.com/BackendStack21/odek/internal/guard" "github.com/BackendStack21/odek/internal/llmclient" @@ -459,6 +460,7 @@ func serveCmd(args []string) error { defer sl.Close() sl.logf("serve_started addr=%s pid=%d", addr, os.Getpid()) } else { + diagnostics.Warning("serve", "surface_log_open", err) fmt.Fprintf(os.Stderr, "odek serve: durable run log disabled (%v)\n", err) } @@ -716,7 +718,7 @@ func requestServeShutdown() { // pre-request header phase and idle keep-alives are timed). func newServeHTTPServer(mux *http.ServeMux) *http.Server { return &http.Server{ - Handler: mux, + Handler: diagnosticHTTPHandler(mux), ReadHeaderTimeout: 10 * time.Second, IdleTimeout: 120 * time.Second, } @@ -743,6 +745,7 @@ func serveOnListener(listener net.Listener, mux *http.ServeMux) error { var servingError error select { case servingError = <-serveErr: + diagnostics.Report("serve", "listener", "", servingError) fmt.Fprintf(os.Stderr, "odek serve: listener failed: %v; shutting down...\n", servingError) case sig := <-quit: fmt.Fprintf(os.Stderr, "\nodek serve: %s received, shutting down...\n", sig) @@ -754,6 +757,7 @@ func serveOnListener(listener net.Listener, mux *http.ServeMux) error { httpCtx, httpCancel := context.WithTimeout(context.Background(), 5*time.Second) defer httpCancel() if err := srv.Shutdown(httpCtx); err != nil { + diagnostics.Report("serve", "shutdown", "", err) fmt.Fprintf(os.Stderr, "odek serve: http shutdown: %v\n", err) } @@ -1070,6 +1074,7 @@ func newServeAgent(resolved config.ResolvedConfig, system string, runKey string, }, } applyResolvedProvider(&serveCfg, resolved) + serveCfg.RuntimeLogSurface = "serve" agent, err := odek.New(serveCfg) if err != nil { // Container was started but agent construction failed — clean up now @@ -1842,6 +1847,11 @@ func handlePrompt( // failed turn must not unwind a daemon goroutine and terminate the host. defer func() { if recovered := recover(); recovered != nil { + sid := "" + if sess != nil { + sid = sess.ID + } + diagnostics.Emit(events.Event{Type: "panic_recovered", SessionID: sid, TurnID: turnID, Data: map[string]any{"component": "serve", "operation": "turn", "error_class": "panic"}}) atomic.AddInt64(&serveStats.PromptsFailed, 1) serveLogf("turn panic contained") if sess != nil { @@ -2964,6 +2974,7 @@ func newSubagentLogRelay(send func(v any) error) func(taskIdx int, taskID string } func sendError(send func(map[string]any), msg string) { + diagnostics.Warning("serve", "request_rejected", nil) send(map[string]any{"type": "error", "message": msg}) } diff --git a/cmd/odek/serve_diagnostics.go b/cmd/odek/serve_diagnostics.go new file mode 100644 index 00000000..595a540e --- /dev/null +++ b/cmd/odek/serve_diagnostics.go @@ -0,0 +1,58 @@ +package main + +import ( + "bufio" + "net" + "net/http" + + "github.com/BackendStack21/odek/internal/diagnostics" + "github.com/BackendStack21/odek/internal/events" +) + +// diagnosticHTTPHandler records failed responses by registered route pattern. +// Request URLs, query strings, headers and response bodies never enter logs. +func diagnosticHTTPHandler(mux *http.ServeMux) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + _, pattern := mux.Handler(r) + if pattern == "" { + pattern = "unmatched_route" + } + recorder := &diagnosticResponseWriter{ResponseWriter: w} + defer func() { + if value := recover(); value != nil { + diagnostics.Emit(events.Event{Type: "panic_recovered", Data: map[string]any{"component": "serve", "operation": pattern, "error_class": "panic"}}) + panic(value) // net/http keeps its existing recovery and connection handling + } + if recorder.status >= 400 { + typ := "operation_warning" + if recorder.status >= 500 { + typ = "operation_failed" + } + diagnostics.Emit(events.Event{Type: typ, Data: map[string]any{"component": "serve", "operation": pattern, "error_class": "http_response", "http_status": recorder.status}}) + } + }() + mux.ServeHTTP(recorder, r) + }) +} + +type diagnosticResponseWriter struct { + http.ResponseWriter + status int +} + +func (w *diagnosticResponseWriter) Unwrap() http.ResponseWriter { return w.ResponseWriter } +func (w *diagnosticResponseWriter) WriteHeader(status int) { + if w.status == 0 && (status >= 200 || status == http.StatusSwitchingProtocols) { + w.status = status + } + w.ResponseWriter.WriteHeader(status) +} +func (w *diagnosticResponseWriter) Flush() { + if w.status == 0 { + w.WriteHeader(http.StatusOK) + } + _ = http.NewResponseController(w.ResponseWriter).Flush() +} +func (w *diagnosticResponseWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) { + return http.NewResponseController(w.ResponseWriter).Hijack() +} diff --git a/cmd/odek/serve_runs.go b/cmd/odek/serve_runs.go index 8efcaf31..dc44d9ed 100644 --- a/cmd/odek/serve_runs.go +++ b/cmd/odek/serve_runs.go @@ -42,6 +42,7 @@ import ( "time" "github.com/BackendStack21/odek/internal/config" + "github.com/BackendStack21/odek/internal/diagnostics" "github.com/BackendStack21/odek/internal/events" "github.com/BackendStack21/odek/internal/resource" "github.com/BackendStack21/odek/internal/session" @@ -930,6 +931,7 @@ func startServeRun( defer serveRunsWG.Done() defer func() { if recovered := recover(); recovered != nil { + diagnostics.Emit(events.Event{Type: "panic_recovered", Data: map[string]any{"component": "serve", "operation": "headless_run", "error_class": "panic"}}) run.finish("failed", "run failed: internal error") serveLogf("run panic contained run_id=%s", run.ID) } diff --git a/cmd/odek/subagent.go b/cmd/odek/subagent.go index 66012347..cf1bc43b 100644 --- a/cmd/odek/subagent.go +++ b/cmd/odek/subagent.go @@ -4,7 +4,6 @@ import ( "context" "encoding/json" "fmt" - "github.com/BackendStack21/odek/internal/session" "io" "os" "os/signal" @@ -19,9 +18,13 @@ import ( "github.com/BackendStack21/odek/internal/budget" "github.com/BackendStack21/odek/internal/config" "github.com/BackendStack21/odek/internal/danger" + "github.com/BackendStack21/odek/internal/diagnostics" + "github.com/BackendStack21/odek/internal/events" "github.com/BackendStack21/odek/internal/loop" "github.com/BackendStack21/odek/internal/redact" "github.com/BackendStack21/odek/internal/render" + "github.com/BackendStack21/odek/internal/runtimelog" + "github.com/BackendStack21/odek/internal/session" "github.com/BackendStack21/odek/internal/skills" ) @@ -718,16 +721,18 @@ func parseSubagentFlags(args []string) (subagentFlags, error) { // operator-defined capability profile; it was previously dropped by the // inline parser, so profiled delegate_tasks tasks silently ran bare. type taskFileSpec struct { - TaskID string `json:"task_id,omitempty"` - Protocol int `json:"protocol,omitempty"` - Goal string `json:"goal"` - Context string `json:"context"` - Guidance string `json:"guidance,omitempty"` - TrustLevel string `json:"trust_level,omitempty"` - MaxRisk string `json:"max_risk,omitempty"` - Profile string `json:"profile,omitempty"` - Budget *taskBudget `json:"budget,omitempty"` - ParentTrust string `json:"parent_trust,omitempty"` + EventContext events.Context `json:"event_context,omitempty"` + RuntimeEvents bool `json:"runtime_events,omitempty"` + TaskID string `json:"task_id,omitempty"` + Protocol int `json:"protocol,omitempty"` + Goal string `json:"goal"` + Context string `json:"context"` + Guidance string `json:"guidance,omitempty"` + TrustLevel string `json:"trust_level,omitempty"` + MaxRisk string `json:"max_risk,omitempty"` + Profile string `json:"profile,omitempty"` + Budget *taskBudget `json:"budget,omitempty"` + ParentTrust string `json:"parent_trust,omitempty"` // ArtifactRoot is the per-task directory the PARENT created // (~/.odek/artifacts//). When set, the runner scans it at // exit and attaches odek.artifact-ref/v1 refs to the result. Additive @@ -779,11 +784,13 @@ func subagentCmd(args []string) error { var taskGuidance string // how-to-approach guidance from the parent (if any) var taskTrust string // "trusted" or "untrusted" (from parent agent) var taskMaxRisk string - var taskProfile string // capability profile selected by the parent - var taskBudgetBlock *taskBudget // parent's remaining budget (share mode) - var taskArtifactRoot string // per-task artifact dir from the envelope - var taskTaskID string // envelope task id (staging key) - var parentTrust string // parent's own effective trust + var taskProfile string // capability profile selected by the parent + var taskBudgetBlock *taskBudget // parent's remaining budget (share mode) + var taskArtifactRoot string // per-task artifact dir from the envelope + var taskTaskID string // envelope task id (staging key) + var parentTrust string // parent's own effective trust + var eventContext events.Context + var runtimeEvents bool var taskID string // telemetry correlation id (protocol-2 parents) var taskProtocol int // telemetry protocol version from the envelope var taskProvider string // parent-selected go-llm-sdk provider @@ -821,6 +828,9 @@ func subagentCmd(args []string) error { // stamp a task id; the child echoes it on every stdout record and // frames its final result so the parent cannot misparse. taskID = taskSpec.TaskID + eventContext = taskSpec.EventContext + eventContext.TaskID = taskID + runtimeEvents = taskSpec.RuntimeEvents taskProtocol = taskSpec.Protocol taskProvider = taskSpec.Provider taskModel = taskSpec.Model @@ -1108,34 +1118,47 @@ func subagentCmd(args []string) error { if cfg.stream { protocol2 = taskID != "" && taskProtocol >= subagentProtocolV2 if protocol2 { - telemetry = newSubagentTelemetryWriter(os.Stdout, taskID) - telemetry.emit(map[string]any{ - "type": "subagent_started", - "pid": os.Getpid(), - "depth": subagentDepth(), - "timeout_s": cfg.timeout, - "max_iter": cfg.maxIter, - }) + telemetry = newSubagentTelemetryWriterWithWire(os.Stdout, taskID, wireCtx) + telemetry.emitStarted(os.Getpid(), subagentDepth(), cfg.timeout, cfg.maxIter) + if runtimeEvents { + aCfg.EventContext = eventContext + aCfg.EventHandler = func(ev events.Event) { + if safe, ok := runtimelog.Sanitize(ev); ok { + telemetry.emit(map[string]any{"type": "runtime_event", "event": safe}) + } + } + } } aCfg.ToolEventHandler = func(event, name, data string) { - line, _ := json.Marshal(map[string]string{ - "type": event, - "name": name, - "data": data, - }) - os.Stdout.Write(line) - os.Stdout.Write([]byte("\n")) + rec := map[string]any{"type": event, "name": name, "data": data} + if telemetry != nil { + telemetry.emit(rec) + } else { + line, _ := json.Marshal(rec) + _, _ = os.Stdout.Write(append(line, '\n')) + } if telemetry != nil && event == "tool_call" { telemetry.emitProgress(name) } } } + if aCfg.EventContext.SessionID == "" { + aCfg.EventContext.SessionID = cfg.parentSession + } applyResolvedProvider(&aCfg, resolved) + aCfg.RuntimeLogSurface = "subagent" + if protocol2 { + aCfg.RuntimeLogPath = "" + } agent, err = odek.New(aCfg) if err != nil { return fmt.Errorf("create agent: %w", err) } defer agent.Close() + if protocol2 && runtimeEvents { + restoreDiagnostics := diagnostics.Install(agent.EmitEvent) + defer restoreDiagnostics() + } if bgRT != nil { agent.SetBackgroundNoticeProvider(bgRT.provider) } @@ -1252,6 +1275,14 @@ func subagentCmd(args []string) error { result.CostUSD = usage.CostUSD } + // Drain runtime records before the terminal envelope. Close is idempotent + // for the emitter; the deferred Agent.Close still handles other resources. + if runtimeEvents { + agent.FlushEvents() + if n := agent.DroppedEvents(); n > 0 { + telemetry.emit(map[string]any{"type": "runtime_event", "event": events.Event{Type: "logging_dropped", RunID: agent.RunID(), TaskID: taskID, Data: map[string]any{"dropped": n}}}) + } + } // Output JSON to stdout — the envelope is emitted exactly once, here. // Protocol-2 children emit a compact subagent_finished record followed // by a FRAMED result ({"type":"result",…}) so the parent's parser @@ -1292,13 +1323,7 @@ func subagentCmd(args []string) error { if merr == nil { var inner map[string]any _ = json.Unmarshal(raw, &inner) - framed, _ := json.Marshal(map[string]any{ - "type": "result", - "task_id": taskID, - "result": inner, - }) - os.Stdout.Write(framed) - os.Stdout.Write([]byte("\n")) + telemetry.emit(map[string]any{"type": "result", "result": inner}) } else { enc := json.NewEncoder(os.Stdout) enc.Encode(result) diff --git a/cmd/odek/subagent_logging.go b/cmd/odek/subagent_logging.go new file mode 100644 index 00000000..b5d33b21 --- /dev/null +++ b/cmd/odek/subagent_logging.go @@ -0,0 +1,146 @@ +package main + +import ( + "encoding/json" + "io" + "sync" + "time" + + "github.com/BackendStack21/odek/internal/events" + "github.com/BackendStack21/odek/internal/runtimelog" +) + +func (t *delegateTasksTool) SetEventContext(c events.Context) { + t.eventMu.Lock() + defer t.eventMu.Unlock() + t.eventContext = c +} +func (t *delegateTasksTool) childEventContext(taskID string) events.Context { + t.eventMu.Lock() + defer t.eventMu.Unlock() + c := t.eventContext + return events.Context{RootRunID: c.RootRunID, ParentRunID: c.RunID, ParentTurnID: c.TurnID, SessionID: c.SessionID, TaskID: taskID, ParentTaskID: c.TaskID} +} + +// subagentActivity tracks observations, not inferred health. Pending calls can +// be waiting for approval/concurrency; only executing records mark activity. +type subagentActivity struct { + mu sync.Mutex + last time.Time + llm bool + pending map[string]bool + active map[string]bool +} + +func newSubagentActivity() *subagentActivity { + return &subagentActivity{last: time.Now(), pending: map[string]bool{}, active: map[string]bool{}} +} +func (a *subagentActivity) observe(ev events.Event) { + a.mu.Lock() + defer a.mu.Unlock() + a.last = time.Now() + id, _ := ev.Data["call_id"].(string) + switch ev.Type { + case "llm_call_started": + a.llm = true + case "llm_call_completed", "llm_call_failed": + a.llm = false + case "tool_call_started": + a.pending[id] = true + case "tool_call_executing": + delete(a.pending, id) + a.active[id] = true + case "tool_call_completed", "tool_call_failed", "tool_execution_completed": + delete(a.pending, id) + delete(a.active, id) + } +} +func (a *subagentActivity) snapshot(start time.Time) map[string]any { + a.mu.Lock() + defer a.mu.Unlock() + activity := "process_running" + if a.llm { + activity = "llm_request" + } + if len(a.pending) > 0 { + activity = "tools_pending" + } + if len(a.active) > 0 { + activity = "tool_execution" + } + return map[string]any{"activity": activity, "active_calls": len(a.active), "pending_calls": len(a.pending), "elapsed_seconds": time.Since(start).Seconds(), "last_event_age_seconds": time.Since(a.last).Seconds()} +} + +// relayRuntimeRecord never persists raw child log lines. Only a recognized, +// metadata-only event is forwarded; the parent owns session/root correlation. +func (t *delegateTasksTool) relayRuntimeRecord(taskID, line string, a *subagentActivity) bool { + var rec struct { + Type string `json:"type"` + Event events.Event `json:"event"` + } + if json.Unmarshal([]byte(line), &rec) != nil { + return false + } + if rec.Type == "subagent_started" { + var meta struct { + PID int `json:"pid"` + Profile string `json:"profile"` + MaxRisk string `json:"max_risk"` + BudgetSeconds int `json:"budget_seconds"` + BudgetIterations int `json:"budget_iterations"` + BudgetCost float64 `json:"budget_cost_usd"` + } + if json.Unmarshal([]byte(line), &meta) == nil { + t.emitSubagentEvent(events.Event{Type: "subagent_started", TaskID: taskID, Data: map[string]any{"pid": meta.PID, "profile": meta.Profile, "max_risk": meta.MaxRisk, "budget_seconds": meta.BudgetSeconds, "budget_iterations": meta.BudgetIterations, "budget_cost_usd": meta.BudgetCost}}) + } + return false // the existing UI relay still receives this lifecycle frame + } + if rec.Type != "runtime_event" { + return false + } + ev, ok := runtimelog.Sanitize(rec.Event) + if !ok { + return true + } + c := t.childEventContext(taskID) + ev.SourceTaskID = taskID + ev.SessionID = c.SessionID + ev.RootRunID = c.RootRunID + if ev.TaskID == "" || ev.TaskID == taskID { + ev.TaskID = taskID + ev.ParentTaskID = c.ParentTaskID + ev.ParentRunID = c.ParentRunID + ev.ParentTurnID = c.ParentTurnID + a.observe(ev) + } + t.emitSubagentEvent(ev) + return true +} + +// boundedStderr counts diagnostics without retaining private child output. +// The default runtime log records only the byte count; raw text never enters it. +type boundedStderr struct{ n int64 } + +func (b *boundedStderr) Write(p []byte) (int, error) { b.n += int64(len(p)); return len(p), nil } + +var _ io.Writer = (*boundedStderr)(nil) + +func (t *delegateTasksTool) monitorSubagent(taskID string, a *subagentActivity, interval time.Duration) func() { + stop, done := make(chan struct{}), make(chan struct{}) + start := time.Now() + go func() { + defer close(done) + ticker := time.NewTicker(interval) + defer ticker.Stop() + for { + select { + case <-stop: + return + case <-ticker.C: + t.emitSubagentEvent(events.Event{Type: "subagent_running", TaskID: taskID, Data: a.snapshot(start)}) + } + } + }() + var once sync.Once + return func() { once.Do(func() { close(stop); <-done }) } +} diff --git a/cmd/odek/subagent_logging_test.go b/cmd/odek/subagent_logging_test.go new file mode 100644 index 00000000..808be953 --- /dev/null +++ b/cmd/odek/subagent_logging_test.go @@ -0,0 +1,278 @@ +package main + +import ( + "bytes" + "encoding/json" + "net/http" + "net/http/httptest" + "os" + "path/filepath" + "strings" + "sync" + "testing" + "time" + + "github.com/BackendStack21/odek/internal/events" + "github.com/BackendStack21/odek/internal/maintenance" + "github.com/BackendStack21/odek/internal/runtimelog" +) + +func TestSubagentRuntimeRelaySessionAncestryAndPrivacy(t *testing.T) { + var got []events.Event + tool := &delegateTasksTool{} + tool.SetEventContext(events.Context{RunID: "parent", RootRunID: "root", TurnID: "turn", SessionID: "session", TaskID: "parent-task"}) + tool.SetEventEmitter(func(ev events.Event) { got = append(got, ev) }) + a := newSubagentActivity() + feed := func(ev events.Event) { + t.Helper() + b, _ := json.Marshal(map[string]any{"type": "runtime_event", "event": ev}) + if !tool.relayRuntimeRecord("child", string(b), a) { + t.Fatal("record not consumed") + } + } + feed(events.Event{Type: "tool_call_started", RunID: "child-run", TaskID: "child", SessionID: "forged-session", Data: map[string]any{"call_id": "one", "args": "private task content"}}) + feed(events.Event{Type: "tool_call_started", RunID: "grandchild-run", TaskID: "grandchild", ParentTaskID: "child", ParentRunID: "child-run", Data: map[string]any{"call_id": "two"}}) + for _, ev := range got { + if ev.SessionID != "session" || ev.RootRunID != "root" || ev.SourceTaskID != "child" { + t.Fatalf("lost verified source: %+v", ev) + } + if ev.Data["args"] != nil { + t.Fatal("raw args forwarded") + } + } + if got[0].ParentTaskID != "parent-task" || got[0].ParentRunID != "parent" || got[1].ParentTaskID != "child" || got[1].RunID != "grandchild-run" { + t.Fatalf("ancestry: %+v", got) + } + if n := a.snapshot(time.Now())["pending_calls"]; n != 1 { + t.Fatalf("descendant polluted direct activity: %v", n) + } +} + +func TestSubagentRuntimeRelayLegacyStartMetadata(t *testing.T) { + var got []events.Event + tool := &delegateTasksTool{} + tool.SetEventEmitter(func(ev events.Event) { got = append(got, ev) }) + line := `{"type":"subagent_started","pid":123,"profile":"fast","max_risk":"read_only","budget_seconds":60,"budget_iterations":5,"budget_cost_usd":0.25,"goal":"private task","stderr":"private output"}` + if tool.relayRuntimeRecord("child", line, newSubagentActivity()) { + t.Fatal("legacy lifecycle frame must remain available to the UI") + } + if len(got) != 1 { + t.Fatalf("got %d lifecycle events", len(got)) + } + ev := got[0] + if ev.Type != "subagent_started" || ev.TaskID != "child" || len(ev.Data) != 6 || ev.Data["pid"] != 123 || ev.Data["profile"] != "fast" || ev.Data["max_risk"] != "read_only" || ev.Data["budget_seconds"] != 60 || ev.Data["budget_iterations"] != 5 || ev.Data["budget_cost_usd"] != 0.25 { + t.Fatalf("unexpected lifecycle metadata: %+v", ev) + } +} +func TestSubagentActivityParallelExecution(t *testing.T) { + a := newSubagentActivity() + for _, id := range []string{"fast", "slow"} { + a.observe(events.Event{Type: "tool_call_started", Data: map[string]any{"call_id": id}}) + a.observe(events.Event{Type: "tool_call_executing", Data: map[string]any{"call_id": id}}) + } + a.observe(events.Event{Type: "tool_execution_completed", Data: map[string]any{"call_id": "fast"}}) + got := a.snapshot(time.Now()) + if got["active_calls"] != 1 || got["activity"] != "tool_execution" { + t.Fatalf("completed tool still active: %v", got) + } +} +func TestSubagentPeriodicObservationStops(t *testing.T) { + tool := &delegateTasksTool{} + got := make(chan events.Event, 10) + tool.SetEventEmitter(func(ev events.Event) { got <- ev }) + stop := tool.monitorSubagent("child", newSubagentActivity(), time.Millisecond) + select { + case ev := <-got: + if ev.TaskID != "child" || ev.Data["activity"] != "process_running" { + t.Fatal(ev) + } + case <-time.After(time.Second): + t.Fatal("no activity summary") + } + stop() + stop() +} +func TestSubagentTelemetryConcurrentFrames(t *testing.T) { + var out bytes.Buffer + w := newSubagentTelemetryWriter(&out, "child") + var wg sync.WaitGroup + for i := 0; i < 8; i++ { + wg.Add(1) + go func() { + defer wg.Done() + for j := 0; j < 100; j++ { + w.emit(map[string]any{"type": "runtime_event", "event": events.Event{Type: "run_started"}}) + } + }() + } + wg.Wait() + lines := strings.Split(strings.TrimSpace(out.String()), "\n") + if len(lines) != 800 { + t.Fatal(len(lines)) + } + for _, line := range lines { + if !json.Valid([]byte(line)) { + t.Fatalf("interleaved JSON: %s", line) + } + } +} + +func TestE2E_SubagentRuntimeLogging(t *testing.T) { + skipIfNoE2E(t) + provider := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`{"choices":[{"message":{"content":"private answer"},"finish_reason":"stop"}],"usage":{"prompt_tokens":100,"completion_tokens":20}}`)) + })) + defer provider.Close() + home := t.TempDir() + t.Setenv("HOME", home) + t.Chdir(home) + _ = os.Mkdir(filepath.Join(home, ".odek"), 0700) + _ = os.WriteFile(filepath.Join(home, ".odek", "config.json"), []byte(`{"logging":{"enabled":true},"memory":{"enabled":false},"limits":{"input_cost_per_million_usd":2,"output_cost_per_million_usd":4}}`), 0600) + path := filepath.Join(home, ".odek", "runtime.log") + logger, err := runtimelog.Open(path, "test", 50) + if err != nil { + t.Fatal(err) + } + emitter := events.NewEmitter(logger.Emit, "parent-run") + emitter.SetContext(events.Context{SessionID: "session-1", TurnID: "turn-1"}) + tool := &delegateTasksTool{odekPath: e2eBinary, apiKey: "test-key", timeout: 20 * time.Second, provider: "deepseek", model: "test-model", baseURL: provider.URL} + tool.SetEventEmitter(emitter.Emit) + tool.SetEventContext(emitter.Context()) + var started map[string]any + tool.OnSubagentLog = func(_ int, _ string, line string) { + var rec map[string]any + if json.Unmarshal([]byte(line), &rec) == nil && rec["type"] == "subagent_started" { + started = rec + } + } + result := tool.runTask(0, "child-task", "private goal", "", "", "trusted", "safe", "", "") + emitter.Close() + logger.Close() + var res map[string]any + if json.Unmarshal([]byte(result), &res) != nil || res["status"] != "success" { + t.Fatalf("child failed: %s", result) + } + if started["budget_seconds"] == nil || started["max_risk"] == nil { + t.Fatalf("resolved live telemetry not wired: %v", started) + } + b, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + if strings.Contains(string(b), "private") || strings.Contains(string(b), "test-key") { + t.Fatalf("private content leaked: %s", b) + } + seen := map[string]bool{} + for _, line := range strings.Split(strings.TrimSpace(string(b)), "\n") { + var ev events.Event + if err := json.Unmarshal([]byte(line), &ev); err != nil { + t.Fatal(err) + } + if ev.SessionID != "session-1" || ev.TaskID != "child-task" { + t.Fatalf("missing session/task: %+v", ev) + } + seen[ev.Type] = true + if ev.Type == "subagent_completed" && (ev.Data["exit_status"] != "exited" || ev.Data["cost_usd"] == nil) { + t.Fatalf("terminal diagnostics: %+v", ev) + } + } + for _, typ := range []string{"subagent_spawned", "turn_started", "llm_call_started", "llm_call_completed", "run_completed", "subagent_completed"} { + if !seen[typ] { + t.Errorf("missing %s", typ) + } + } +} + +func TestRuntimeExpirationDryRunReportsWork(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "runtime.log") + b, _ := json.Marshal(events.Event{Type: "run_completed", Timestamp: time.Now().Add(-48 * time.Hour)}) + _ = os.WriteFile(path, append(b, '\n'), 0600) + out := captureStdout(func() { printCleanupDryRun(dir, maintenance.Config{RuntimeLogMaxAgeHours: 24}) }) + if !strings.Contains(out, "runtime records expired: 1") || strings.Contains(out, "storage is clean") { + t.Fatalf("misleading preview: %s", out) + } + after, _ := os.ReadFile(path) + if !bytes.Equal(after, append(b, '\n')) { + t.Fatal("dry run modified log") + } +} + +func TestSubagentActivityTransitionsAndTiming(t *testing.T) { + a := newSubagentActivity() + start := time.Now().Add(-time.Minute) + a.mu.Lock() + a.last = time.Now().Add(-time.Second) + a.mu.Unlock() + before := a.snapshot(start) + if before["elapsed_seconds"].(float64) < 60 || before["last_event_age_seconds"].(float64) < 1 { + t.Fatalf("missing timing: %v", before) + } + cases := []struct { + event, id, want string + pending, active int + }{ + {"llm_call_started", "", "llm_request", 0, 0}, + {"llm_call_completed", "", "process_running", 0, 0}, + {"llm_call_started", "", "llm_request", 0, 0}, + {"llm_call_failed", "", "process_running", 0, 0}, + {"tool_call_started", "one", "tools_pending", 1, 0}, + {"tool_call_executing", "one", "tool_execution", 0, 1}, + {"tool_call_started", "two", "tool_execution", 1, 1}, + {"tool_call_failed", "two", "tool_execution", 0, 1}, + {"tool_call_completed", "one", "process_running", 0, 0}, + } + for _, tc := range cases { + a.observe(events.Event{Type: tc.event, Data: map[string]any{"call_id": tc.id}}) + got := a.snapshot(start) + if got["activity"] != tc.want || got["pending_calls"] != tc.pending || got["active_calls"] != tc.active { + t.Fatalf("after %s: %v", tc.event, got) + } + } + if age := a.snapshot(start)["last_event_age_seconds"].(float64); age > 0.5 { + t.Fatalf("new observations did not update event age: %v", age) + } +} + +func TestSubagentRuntimeRelayRejectsMalformedAndUnknown(t *testing.T) { + tool := &delegateTasksTool{} + var got []events.Event + tool.SetEventEmitter(func(ev events.Event) { got = append(got, ev) }) + tool.SetEventContext(events.Context{RunID: "parent", SessionID: "session", TurnID: "turn", TaskID: "parent-task"}) + a := newSubagentActivity() + for _, tc := range []struct { + line string + consumed bool + }{ + {`{broken`, false}, {`{"type":"tool_call","data":"private"}`, false}, + {`{"type":"runtime_event","event":{"type":"unknown","data":{"goal":"private"}}}`, true}, + {`{"type":"subagent_started","pid":"invalid"}`, false}, + } { + if got := tool.relayRuntimeRecord("child", tc.line, a); got != tc.consumed { + t.Fatalf("consumed=%v for %s", got, tc.line) + } + } + if len(got) != 0 { + t.Fatalf("malformed records emitted events: %v", got) + } + if !tool.relayRuntimeRecord("child", `{"type":"runtime_event","event":{"type":"llm_call_started","task_id":"","session_id":"forged"}}`, a) { + t.Fatal("valid legacy event rejected") + } + if len(got) != 1 || got[0].TaskID != "child" || got[0].SessionID != "session" || got[0].ParentTurnID != "turn" { + t.Fatalf("parent correlation not restored: %v", got) + } +} + +func TestSubagentStderrCountsWithoutRetainingContent(t *testing.T) { + var b boundedStderr + for _, p := range [][]byte{nil, []byte("private error"), bytes.Repeat([]byte("secret"), 1<<16)} { + n, err := b.Write(p) + if err != nil || n != len(p) { + t.Fatalf("write=%d,%v", n, err) + } + } + if b.n != int64(len("private error")+6*(1<<16)) { + t.Fatal("wrong diagnostic byte count") + } +} diff --git a/cmd/odek/subagent_tool.go b/cmd/odek/subagent_tool.go index 8cce1fbc..6c67d1f8 100644 --- a/cmd/odek/subagent_tool.go +++ b/cmd/odek/subagent_tool.go @@ -113,8 +113,9 @@ type delegateTasksTool struct { // eventMu/emitEventFn carry the runtime event emitter injected by // odek.New (SetEventEmitter); used to surface child denials as // subagent_denied events. - eventMu sync.Mutex - emitEventFn func(events.Event) + eventMu sync.Mutex + emitEventFn func(events.Event) + eventContext events.Context // OnSubagentLog, if set, is called with each NDJSON progress line // emitted by a sub-agent. taskIdx is the index within the current @@ -163,6 +164,7 @@ func (t *delegateTasksTool) getSessionID() string { // and max_risk carry the DECLARED values here; the child's started record // overwrites them with the effective post-clamp values. func (t *delegateTasksTool) emitSubagentQueued(taskIdx int, taskID, goal, profile, maxRisk string) { + t.emitSubagentEvent(events.Event{Type: "subagent_queued", TaskID: taskID, Data: map[string]any{"task_index": taskIdx, "profile": profile, "max_risk": maxRisk}}) if t.OnSubagentLog == nil { return // no wire attached (bare-struct tests, non-serve runs) } @@ -359,7 +361,17 @@ func (t *delegateTasksTool) Call(args string) (string, error) { dirs[i] = d } } - t.acquireSem(sem, emitFn, i) + queuedAt := time.Now() + waitEmit := emitFn + if emitFn != nil { + waitEmit = func(ev events.Event) { + ev.TaskID = taskID + ev.ParentTaskID = t.childEventContext(taskID).ParentTaskID + emitFn(ev) + } + } + t.acquireSem(sem, waitEmit, i) + t.emitSubagentEvent(events.Event{Type: "subagent_slot_acquired", TaskID: taskID, Data: map[string]any{"waited_ms": time.Since(queuedAt).Milliseconds()}}) run := t.runTaskFn model := selectedModels[i] wg.Add(1) @@ -403,8 +415,9 @@ func (t *delegateTasksTool) Call(args string) (string, error) { } for _, d := range r.Denials { emit(events.Event{ - Type: subagentDeniedEvent, - Tool: d.Tool, + Type: subagentDeniedEvent, + TaskID: taskIDs[i], + Tool: d.Tool, Data: map[string]any{ "task_index": i, "class": d.Class, @@ -457,7 +470,15 @@ func (t *delegateTasksTool) runTask(taskIdx int, taskID, goal, taskContext, guid return t.runTaskWithModel(taskIdx, taskID, goal, taskContext, guidance, trustLevel, maxRisk, profile, artifactDir, "") } -func (t *delegateTasksTool) runTaskWithModel(taskIdx int, taskID, goal, taskContext, guidance, trustLevel, maxRisk, profile, artifactDir, model string) string { +func (t *delegateTasksTool) runTaskWithModel(taskIdx int, taskID, goal, taskContext, guidance, trustLevel, maxRisk, profile, artifactDir, model string) (output string) { + terminalEmitted := false + setupClass := "profile_error" + taskStart := time.Now() + defer func() { + if !terminalEmitted { + t.emitSubagentEvent(events.Event{Type: "subagent_failed", TaskID: taskID, Data: map[string]any{"error_class": setupClass, "duration_seconds": time.Since(taskStart).Seconds()}}) + } + }() // Parent-side fail-closed validation: an unknown profile name must // fail the task BEFORE a child is spawned — the tool schema promises // "unknown names fail the task", and a silently-bare child would run @@ -479,6 +500,7 @@ func (t *delegateTasksTool) runTaskWithModel(taskIdx int, taskID, goal, taskCont ctx, cancel := context.WithTimeout(parentCtx, t.timeout) defer cancel() + setupClass = "budget_error" reservation, err := t.reserveChildBudget() if err != nil { return fmt.Sprintf(`{"status":"error","error":%q,"summary":"","tokens_used":0}`, err.Error()) @@ -487,6 +509,7 @@ func (t *delegateTasksTool) runTaskWithModel(taskIdx int, taskID, goal, taskCont taskBudgetBlock := reservation.limits // Write task to temp file (avoids CLI arg length limits) + setupClass = "task_file_error" taskFile, err := os.CreateTemp("", "odek-task-*.json") if err != nil { return fmt.Sprintf(`{"error":"temp file: %v"}`, err) @@ -503,6 +526,8 @@ func (t *delegateTasksTool) runTaskWithModel(taskIdx int, taskID, goal, taskCont defer registerSubagentCancel(taskID, cancel)() task := newTaskEnvelope(taskID, goal, taskContext, guidance, trustLevel, maxRisk, profile, taskBudgetBlock, t.selfTrust) + task.EventContext = t.childEventContext(taskID) + task.RuntimeEvents = task.EventContext.ParentRunID != "" task.ArtifactRoot = artifactDir task.Provider = t.provider task.Model = t.model @@ -538,6 +563,7 @@ func (t *delegateTasksTool) runTaskWithModel(taskIdx int, taskID, goal, taskCont // result to `read |0: file already closed`. We dup the write end // to the child, close our copy after Start, and only force-close // the reader if the scanner is still blocked (orphaned writers). + setupClass = "pipe_error" stdout, stdoutW, err := os.Pipe() if err != nil { return fmt.Sprintf(`{"error":"pipe: %v"}`, err) @@ -545,7 +571,7 @@ func (t *delegateTasksTool) runTaskWithModel(taskIdx int, taskID, goal, taskCont cmd.Stdout = stdoutW // Capture stderr for optional relay - stderrBuf := &strings.Builder{} + stderrBuf := &boundedStderr{} cmd.Stderr = stderrBuf // Hand the API key to the sub-agent via FD 3 instead of an env var. @@ -561,6 +587,7 @@ func (t *delegateTasksTool) runTaskWithModel(taskIdx int, taskID, goal, taskCont subagentDepthEnvVar+"="+strconv.Itoa(subagentDepth()+1)) var keyFile *os.File var keyCleanup func() + setupClass = "key_handoff_error" if t.apiKey != "" { f, cleanup, err := writeKeyToUnlinkedFile(t.apiKey) if err != nil { @@ -579,6 +606,7 @@ func (t *delegateTasksTool) runTaskWithModel(taskIdx int, taskID, goal, taskCont }() } + setupClass = "spawn_error" if err := cmd.Start(); err != nil { _ = stdoutW.Close() _ = stdout.Close() @@ -594,9 +622,16 @@ func (t *delegateTasksTool) runTaskWithModel(taskIdx int, taskID, goal, taskCont // result. A streamed tool_call event can embed full tool arguments (e.g. a // large write_file), so lines routinely exceed bufio.Scanner's default 64KB // token cap; scanSubagentStream raises the cap to avoid losing the result. - var onLog func(line string) - if t.OnSubagentLog != nil { - onLog = func(line string) { t.OnSubagentLog(taskIdx, taskID, line) } + activity := newSubagentActivity() + stopMonitor := t.monitorSubagent(taskID, activity, 60*time.Second) + defer stopMonitor() + onLog := func(line string) { + if t.relayRuntimeRecord(taskID, line, activity) { + return + } + if t.OnSubagentLog != nil { + t.OnSubagentLog(taskIdx, taskID, line) + } } // Scan the child's stdout concurrently with cmd.Wait. A full-drain // read BEFORE Wait would let a killed child's orphaned grandchildren @@ -638,7 +673,22 @@ func (t *delegateTasksTool) runTaskWithModel(taskIdx int, taskID, goal, taskCont result, lastLine, scannerErr := scan.result, scan.lastLine, scan.err status := subagentExitStatus(result, waitErr, ctx, scannerErr) - t.emitSubagentEvent(subagentCompletedEvent(taskID, result, status)) + stopMonitor() + completed := subagentCompletedEvent(taskID, result, status) + completed.Data["exit_status"] = "exited" + if waitErr != nil { + completed.Data["exit_status"] = "nonzero_exit" + } + if ctx.Err() != nil { + completed.Data["exit_status"] = events.ErrorClass(ctx.Err()) + } + completed.Data["duration_seconds"] = time.Since(taskStart).Seconds() + completed.Data["stderr_bytes"] = stderrBuf.n + if cmd.ProcessState != nil { + completed.Data["exit_code"] = cmd.ProcessState.ExitCode() + } + t.emitSubagentEvent(completed) + terminalEmitted = true if result == nil && t.OnSubagentDone != nil { // The child died without reporting (user cancel, turn cancel, // timeout, flood-kill, crash): it cannot emit its own @@ -1051,20 +1101,22 @@ func taskBudgetFromSnapshot(s budget.Snapshot) *taskBudget { // taskEnvelope is the task-file JSON contract handed to `odek subagent`. type taskEnvelope struct { - TaskID string `json:"task_id"` - Protocol int `json:"protocol,omitempty"` - Goal string `json:"goal"` - Context string `json:"context,omitempty"` - Guidance string `json:"guidance,omitempty"` - TrustLevel string `json:"trust_level,omitempty"` - MaxRisk string `json:"max_risk,omitempty"` - Profile string `json:"profile,omitempty"` - Budget *taskBudget `json:"budget,omitempty"` - ParentTrust string `json:"parent_trust,omitempty"` - ArtifactRoot string `json:"artifact_root,omitempty"` - Provider string `json:"provider,omitempty"` - Model string `json:"model,omitempty"` - BaseURL string `json:"base_url,omitempty"` + EventContext events.Context `json:"event_context,omitempty"` + RuntimeEvents bool `json:"runtime_events,omitempty"` + TaskID string `json:"task_id"` + Protocol int `json:"protocol,omitempty"` + Goal string `json:"goal"` + Context string `json:"context,omitempty"` + Guidance string `json:"guidance,omitempty"` + TrustLevel string `json:"trust_level,omitempty"` + MaxRisk string `json:"max_risk,omitempty"` + Profile string `json:"profile,omitempty"` + Budget *taskBudget `json:"budget,omitempty"` + ParentTrust string `json:"parent_trust,omitempty"` + ArtifactRoot string `json:"artifact_root,omitempty"` + Provider string `json:"provider,omitempty"` + Model string `json:"model,omitempty"` + BaseURL string `json:"base_url,omitempty"` } // subagentProtocolV2 is the telemetry protocol version stamped into task @@ -1204,6 +1256,9 @@ func (t *delegateTasksTool) emitSubagentEvent(ev events.Event) { t.eventMu.Lock() defer t.eventMu.Unlock() if t.emitEventFn != nil { + if ev.TaskID != "" && ev.TaskID != t.eventContext.TaskID && ev.ParentTaskID == "" { + ev.ParentTaskID = t.eventContext.TaskID + } t.emitEventFn(ev) } } @@ -1214,7 +1269,8 @@ func (t *delegateTasksTool) emitSubagentEvent(ev events.Event) { func subagentSpawnedEvent(taskID string, pid, depth, timeoutSeconds int, goal string) events.Event { sum := sha256.Sum256([]byte(goal)) return events.Event{ - Type: events.TypeSubagentSpawned, + Type: events.TypeSubagentSpawned, + TaskID: taskID, Data: map[string]any{ "task_id": taskID, "pid": pid, @@ -1239,7 +1295,7 @@ func subagentCompletedEvent(taskID string, result map[string]any, fallbackStatus status = s // the child's own classification wins data["status"] = status } - for _, k := range []string{"iterations", "duration_seconds", "tokens_used"} { + for _, k := range []string{"iterations", "duration_seconds", "tokens_used", "cost_usd"} { if v, ok := result[k]; ok { data[k] = v } @@ -1251,8 +1307,9 @@ func subagentCompletedEvent(taskID string, result map[string]any, fallbackStatus } } return events.Event{ - Type: events.TypeSubagentCompleted, - Data: data, + Type: events.TypeSubagentCompleted, + TaskID: taskID, + Data: data, } } diff --git a/cmd/odek/telegram.go b/cmd/odek/telegram.go index dbd9dff5..3f9d640d 100644 --- a/cmd/odek/telegram.go +++ b/cmd/odek/telegram.go @@ -7,6 +7,8 @@ import ( "encoding/json" "errors" "fmt" + "github.com/BackendStack21/odek/internal/diagnostics" + "github.com/BackendStack21/odek/internal/events" "os" "os/signal" "path/filepath" @@ -1385,6 +1387,7 @@ func handleChatMessage( // Recover from panics so a single bad agent run doesn't deadlock the chat. defer func() { if r := recover(); r != nil { + diagnostics.Emit(events.Event{Type: "panic_recovered", Data: map[string]any{"component": "telegram", "operation": "handler", "error_class": "panic"}}) log.Error("panic in handleChatMessage", "chat_id", chatID, "panic", r) reportError(bot, chatID, messageID, fmt.Sprintf( "Internal error: %v\n\nThe bot is still running. Use /new to start a fresh session.", r, @@ -1992,7 +1995,9 @@ func handleChatMessage( GuardConfig: telegramGuardCfg, } + agentCfg.EventContext.SessionID = sess.ID applyResolvedProvider(&agentCfg, resolved) + agentCfg.RuntimeLogSurface = "telegram" agent, err := odek.New(agentCfg) if err != nil { reportError(bot, chatID, messageID, "Failed to create agent: "+err.Error()) @@ -2462,6 +2467,7 @@ func sendAsync(bot *telegram.Bot, chatID int64, text string, opts *telegram.Send go func() { defer func() { if r := recover(); r != nil { + diagnostics.Emit(events.Event{Type: "panic_recovered", Data: map[string]any{"component": "telegram", "operation": "handler", "error_class": "panic"}}) fmt.Fprintf(os.Stderr, "odek telegram: async send panic: %v\n", r) } }() diff --git a/docs/CONFIG.md b/docs/CONFIG.md index 1a633dfa..687135a9 100644 --- a/docs/CONFIG.md +++ b/docs/CONFIG.md @@ -1468,3 +1468,15 @@ odek run --memory-extended-enabled "remember that I prefer Go over Python" # CLI flag always wins odek run --model gpt-4o --base-url https://api.openai.com/v1 "task" ``` + +## Runtime logging + +Operator-only `logging.enabled` (default `false`; environment +`ODEK_LOGGING_ENABLED`) enables metadata-only JSONL logging to +`~/.odek/runtime.log` across all execution surfaces. The janitor expires records +using `maintenance.runtime_log_max_age_hours` (default `168`, `0` = keep; +`ODEK_MAINTENANCE_RUNTIME_LOG_MAX_AGE_HOURS`). Size rotation uses +`maintenance.log_max_mb`. Logging also covers command/startup failures, service +diagnostics, and storage errors with component/operation labels and typed error +categories. Writer process IDs correlate records emitted before a session exists. +See [Runtime logging](LOGGING.md) for troubleshooting queries and coverage. diff --git a/docs/EXTENSIONS.md b/docs/EXTENSIONS.md index 8ffd8c0e..1d644cf3 100644 --- a/docs/EXTENSIONS.md +++ b/docs/EXTENSIONS.md @@ -205,7 +205,7 @@ Per-type `data` fields: | `subagent_completed` | `task_id`, `status`, plus optional `iterations`, `duration_seconds`, `tokens_used`, `artifact_count` when the child result carried them | | `subagent_concurrency_wait` | `task_index`, `waited_ms` | -`budget_warning` and `reply_ledger_mismatch` are **not** `odek.event/v1` types. They are `loop.SignalEvent`s (`Config.AgentSignalHandler`, WebSocket `agent_signal`). +`budget_warning` and `reply_ledger_mismatch` are `loop.SignalEvent`s (`Config.AgentSignalHandler`, WebSocket `agent_signal`). The Agent also forwards metadata-only `budget_warning` and `tool_recovery` runtime events; raw signal detail text is excluded. `reply_ledger_mismatch` remains signal-only. `call_id` is the stable correlation key between a `tool_call_started` and its matching `tool_call_completed`/`tool_call_failed` event: the provider's @@ -332,3 +332,22 @@ metadata-only lines in the model context, content inlined for text artifacts tool (id-keyed; paths never enter the model context). See `docs/SUBAGENTS.md — Result artifacts` and `docs/SECURITY.md` for the invariants. + +## Runtime logging event additions + +The additive event envelope also carries `turn_id`, `root_run_id`, +`parent_run_id`, `parent_turn_id`, `task_id`, `parent_task_id`, and +`source_task_id` when applicable. `run_id` identifies an Agent instance; +`turn_id` distinguishes repeated Run/RunWithMessages calls on that instance. +Additional types include `turn_started`, `llm_call_started/completed/failed`, +`tool_call_executing`, `tool_execution_completed`, `subagent_queued`, +`subagent_slot_acquired`, `subagent_started`, `subagent_running`, +`subagent_failed`, and `logging_dropped`. Consumers must ignore unknown fields +and types. Parent relay preserves child run IDs and stamps the owning session. +See [Runtime logging](LOGGING.md) for timing and correlation semantics. + +Operational logging additionally emits `operation_failed`, `operation_warning`, +and `panic_recovered`, with component/operation labels and typed error metadata +(no raw error text). Runtime JSONL records include writer `process_id` and `pid`; +these fields are additions to the log envelope, not required event-stream fields. +See [failure diagnostics](LOGGING.md#investigating-failures) for coverage and limits. diff --git a/docs/LOGGING.md b/docs/LOGGING.md new file mode 100644 index 00000000..633445f1 --- /dev/null +++ b/docs/LOGGING.md @@ -0,0 +1,333 @@ +# Runtime logging + +Enable metadata-only operational logging in `~/.odek/config.json`: + +```json +{ + "logging": { "enabled": true }, + "maintenance": { + "enabled": true, + "interval_minutes": 60, + "log_max_mb": 50, + "runtime_log_max_age_hours": 168 + } +} +``` + +Logging is off by default. `ODEK_LOGGING_ENABLED=true` overrides the operator +file. Project `odek.json` cannot enable or disable logging or change retention. +`odek init --global` includes these settings. No external service is required. + +CLI run/continue, REPL, serve, Telegram, scheduled executions, and standalone +subagents use `~/.odek/runtime.log`. Delegated children forward metadata through +stdout to their parent; the top-level parent writes their records to its log. +Existing surface logs and `run --events-jsonl` continue to work independently. +`serve.log` remains the web server's startup/turn/failure log, including its +provider-failure summaries. `runtime.log` is the first place to investigate +application failures, with structured service diagnostics and model/tool/subagent +activity across execution surfaces. Serve turn boundaries consequently +appear in both files; retaining them preserves existing log consumers. +In particular, `--events-include-args` never enables arguments in runtime.log. + +## Reading the log + +Every line is JSON with the additive `odek.event/v1` envelope, `level`, and the +originating top-level `surface`. Use `tail -F` to follow across rotation: + +```sh +tail -F ~/.odek/runtime.log | jq --unbuffered . +tail -F ~/.odek/runtime.log | jq --unbuffered 'select(.session_id == "SESSION_ID")' +tail -F ~/.odek/runtime.log | jq --unbuffered 'select(.task_id == "TASK_ID")' +``` + +The correlation fields have distinct meanings: + +| Field | Meaning | +| --- | --- | +| `session_id` | Session or transient audit-session ID. Inherited by children and grandchildren. Omitted on setup records emitted before a session is known. | +| `run_id` | Agent instance ID. It remains stable when the same Agent handles multiple turns. | +| `turn_id` | Fresh ID per `Run` / `RunWithMessages` invocation. | +| `root_run_id` | Root Agent of the delegation tree. | +| `task_id`, `parent_task_id` | Delegated task and its immediate task ancestor. | +| `parent_run_id`, `parent_turn_id` | Parent invocation for a child's own events. | +| `source_task_id` | Parent-verified direct child that relayed a record. Nested task metadata is child-reported; this field identifies the actual IPC source. | +| `data.call_id` | Correlates tool lifecycle records within a turn. | + +`run_started` describes Agent setup, `turn_started` begins an invocation, and +`run_completed` / `run_failed` ends that invocation. Model calls emit +`llm_call_started`, `llm_call_completed`, or `llm_call_failed`, with durations and +available usage. Budget warnings and tool-recovery signals carry bounded +metadata without raw detail text. Detailed SDK-internal retries are not +currently logged. + +Tool records distinguish a requested call (`tool_call_started`) from actual +execution (`tool_call_executing`). `tool_execution_completed` is emitted when +that worker finishes, even while other parallel tools remain active. Existing +`tool_call_completed` / `tool_call_failed` records describe ordered result +processing after the batch finishes. Do not count both as separate executions. + +Subagents emit queue/slot/start/completion records, including effective profile +and budgets when available. Every 60 seconds a parent emits `subagent_running` +with `activity`, `active_calls`, `pending_calls`, elapsed time, and the age of the +last observed child runtime event. This says the parent has not yet observed +process completion; it is not a health guarantee or proof of useful progress. +`tools_pending` may mean approval or concurrency waiting. Children never wait +for interactive approval: denied operations are reported separately. + +Terminal records include available usage, estimated cost, artifact count, +parent-observed exit code/status, and stderr byte count. Child-reported task +`status` is separate from process `exit_status`; a partial result may accompany +a nonzero exit. Cost is an operator-price estimate, not a bill, and is omitted +when prices are unavailable. Run and task terminal records overlap: do not sum +costs or tokens across all event types. Use the root terminal record for a tree +whose child usage was settled through shared budgets. In operator-budget mode +child usage can be separate: inspect +task completion records. Ancestor and descendant totals must not be added +blindly; these records follow the existing budget-accounting semantics. + +## Investigating failures + +Start with warnings and errors, then follow the matching process or session: + +```sh +# Follow new warnings/errors across rotation and janitor replacements. +tail -F ~/.odek/runtime.log | jq --unbuffered 'select(.level == "WARN" or .level == "ERROR")' + +# Include the rotated backup when investigating an earlier failure. +jq -c 'select(.session_id == "SESSION_ID")' ~/.odek/runtime.log.1 ~/.odek/runtime.log + +# Startup and service-wide failures have no session: correlate by process_id. +jq -c 'select(.process_id == "PROCESS_ID")' ~/.odek/runtime.log +``` + +The backup exists only after the first rotation; omit it from the command if it +is absent. `process_id` is a random identifier for the writing process and `pid` +is its OS process ID. Every runtime log record includes both. They join CLI +startup diagnostics to agent records without inventing a session or run ID for +work that happens outside an agent. Relayed child records carry the parent's +writer identity; use `source_task_id` and delegation ancestry to identify the +child, and subagent start metadata for its PID. + +Application diagnostics use these event types: + +| Event | Severity | Meaning | +| --- | --- | --- | +| `operation_failed` | ERROR | An application operation failed. | +| `operation_warning` | WARN | A configuration fallback, rejected request, or other degraded state. | +| `panic_recovered` | ERROR | A panic reached an instrumented boundary. Service boundaries keep their existing recovery behavior; the main command and HTTP boundaries rethrow after reporting. | + +`data.component` identifies the subsystem and `data.operation` identifies the +step. `data.error_class` categorizes the cause; `data.error_type` preserves the +Go error type where an error is available, and `data.http_status` carries a +provider/API/HTTP response status when known. Messages, error strings, provider +response bodies, panic values, and stack traces are not copied into this file. +Unknown error types retain the `error` category; a record does not always contain +enough detail to reconstruct the underlying failure. + +| Component | Recorded failures and warnings | +| --- | --- | +| `cli`, `agent` | Command errors (including parsing/setup), unknown commands, agent initialization, and main-command panics. | +| `config` | Unreadable, oversized, or malformed configuration; unsafe permissions; invalid environment values; secrets-file permissions/read failures. | +| `session`, `audit` | Session save/load and vector-index failures; audit writes. Missing sessions encountered during ordinary store probing are excluded. | +| `maintenance` | Each failed sweep category: sessions, audit, runtime retention, rotation, plans, artifacts, media. All failed categories are logged even though the command returns only the first error. | +| `serve` | Listener/shutdown failures, surface-log initialization, HTTP 4xx/5xx responses, WebSocket error responses, and contained turn/run panics. HTTP operations use registered route patterns, never request URLs, query strings, headers, or bodies. | +| `schedule` | Store reads/writes, failed job execution, and delivery failures. | +| `telegram` | API requests/uploads after retries finish and instrumented handler panics. | +| `mcp`, `sandbox` | MCP process setup/discovery and sandbox setup failures, including a failed sandbox setup followed by unsandboxed fallback. | +| `llm` | Auxiliary model calls used by memory, titles, compaction, and similar helpers. Main-loop failures retain `llm_call_failed` and `run_failed`. | + +Common causes and checks: + +| `error_class` | What to check | +| --- | --- | +| `provider_auth`, `provider_config` | Operator credentials, provider selection, and model configuration. | +| `rate_limited`, `provider_unavailable`, `provider_request` | Provider quota/availability and HTTP status. | +| `dns_failure`, `connection_refused`, `network_timeout`, `tls_certificate` | Endpoint, connectivity, DNS, and certificate trust. | +| `permission_denied`, `read_only_filesystem`, `invalid_file_type`, `symlink_rejected` | Ownership, permissions, and expected regular files/directories. | +| `disk_full`, `file_descriptors_exhausted` | Free space or process/system file-descriptor limits. | +| `address_in_use` | Another process already using the configured listening address. | +| `executable_not_found`, `process_exit` | Required executable availability or subprocess exit diagnostics. | +| `invalid_json` | Configuration or persisted data syntax/schema. | +| `context_canceled`, `deadline_exceeded`, `stream_idle_timeout`, `execution_budget` | Cancellation, timeouts, and configured budgets. | + +A single incident can produce several records: for example, a provider failure, +a failed run, and a failed command. These describe different boundaries, not +three independent incidents. Use process/session/turn correlation when counting +or investigating failures. + +### Startup and fallback behavior + +The CLI initializes operational logging before parsing the command or constructing +an agent. It reads only operator logging policy; project configuration cannot +turn it on. Diagnostics generated while reading that policy are buffered (up to +128 records) and flushed when logging opens. Version queries and +`cleanup --dry-run` bypass operational logging so previews remain read-only. +If the operator config itself is unreadable or invalid, use +`ODEK_LOGGING_ENABLED=true` to explicitly enable startup diagnostics: + +```sh +ODEK_LOGGING_ENABLED=true odek serve +``` + +Logging remains off by default. Existing stderr and surface diagnostics remain +available. If the runtime log cannot open or storage fails, stderr is the +fallback; the failed log cannot reliably report its own failure. The logger +also reports queue losses and shutdown timeouts there. + +Delegated children route operational diagnostics through their serialized parent +telemetry channel once initialized. Earlier child setup failures remain visible +through parent-observed subagent failure/completion records. Standalone subagent +commands initialize operational logging like other CLI commands. + +This is best-effort diagnostics, not a crash recorder: SIGKILL, OOM termination, +fatal runtime errors, and panics outside instrumented boundaries can lose the +last records. SDK-internal retry attempts and arbitrary third-party stderr are +not captured. Go library users get agent events via `RuntimeLogPath`; the +process-wide application diagnostic sink is installed by the CLI. + +## Content and delivery + +Fields are explicitly allowlisted. Goals, prompts, answers, raw arguments, +argument summaries/paths, tool output, denial text, stderr text, and artifact +content are excluded. Selected identifiers and metadata strings are bounded and +secret-redacted. Tool and model names remain visible. Files and lock files use +0600 permissions; log targets must be regular files and may not be symlinks. + +A bounded background queue isolates execution and child stdout readers from +disk I/O. Queue overflow and write failures produce throttled stderr diagnostics; +event-emitter losses produce `logging_dropped` records on shutdown when possible. +Ordinary lock contention retries the pending batch. Shutdown drains for at most +two seconds before reporting possible loss. Logging is best effort: crashes, +forced termination, a full queue, or failing storage can lose records. Routine +writes do not fsync each event; `--events-jsonl` retains its separate durability +contract. + +## Rotation and expiration + +Runtime log expiration is integrated into the existing storage janitor. The +shared maintenance sweep prunes expired runtime records before rotating logs; +the background services and `odek cleanup` call that same sweep. No separate +logging daemon or expiration command is needed. + +### Settings + +All settings below belong in the operator's `~/.odek/config.json`. Environment +variables take precedence over the file; project configuration cannot change +these settings. + +| Setting | Default | Environment override | Effect | +| --- | --- | --- | --- | +| `logging.enabled` | `false` | `ODEK_LOGGING_ENABLED` | Write new runtime records. Turning it off does not prevent cleanup of existing logs. | +| `maintenance.enabled` | `true` | `ODEK_MAINTENANCE_ENABLED` | Start the background janitor in supported long-lived services. Manual cleanup remains available when false. | +| `maintenance.interval_minutes` | `60` | `ODEK_MAINTENANCE_INTERVAL_MINUTES` | Time between background sweeps. Non-positive values use the 60-minute default. | +| `maintenance.runtime_log_max_age_hours` | `168` | `ODEK_MAINTENANCE_RUNTIME_LOG_MAX_AGE_HOURS` | Expire runtime records older than this many hours. `0` disables age-based expiration. | +| `maintenance.log_max_mb` | `50` | `ODEK_MAINTENANCE_LOG_MAX_MB` | Rotate oversized logs, in MiB. `0` disables size rotation. This existing setting also applies to other surface logs. | + +Runtime retention hours clamp to the range 0–36,500. Negative values therefore +disable age-based expiration. Restart a long-lived service after changing its +janitor configuration: the running janitor uses the policy loaded at startup. + +### When cleanup runs + +| Execution mode | Background expiration | +| --- | --- | +| `odek serve` | Runs while the server is active and maintenance is enabled. | +| `odek telegram` | Runs while the bot is active and maintenance is enabled. | +| `odek schedule daemon` | Runs while the scheduler daemon is active and maintenance is enabled. | +| CLI run/continue, REPL, standalone subagent | Does not start a background janitor. Use manual cleanup or a running service above. | +| `odek cleanup` | Performs one sweep immediately, even if `maintenance.enabled` is false. | +| `odek cleanup --dry-run` | Reports candidates without changing logs or creating a log lock file. | + +The first background sweep occurs **after one interval**, not immediately at +startup. With the default settings, a record becomes eligible after seven days +and is removed at a subsequent hourly sweep. Expiration is not an exact deletion +deadline: the service must be running and the sweep must succeed. Restarting a +service starts a new interval; it does not perform an immediate catch-up sweep. + +### What expiration removes + +The janitor removes records whose `timestamp` is older than the cutoff from +both `~/.odek/runtime.log` and `~/.odek/runtime.log.1`. The cutoff is the sweep +time minus the configured number of hours. Eligibility uses each record's +timestamp, not the file modification time, session age, or task completion +status. An old record in an active session can expire while newer records for +that same session remain. + +Recent records, malformed records, and records without a usable timestamp are +retained. Expiration does not delete sessions or subagent artifacts, and it +does not age-prune `serve.log`, `telegram.log`, `schedule.log`, custom +`--events-jsonl` destinations, or custom Go API runtime-log paths. Those other +storage categories retain their own maintenance rules. See +[Storage maintenance](MAINTENANCE.md). + +Each file replacement is atomic. If scanning a file fails, that file is left +intact; changes already completed to the other file are not rolled back. The +background janitor reports failures in `runtime.log` when operational logging is +enabled, also reports the first error on stderr, and tries again at its next +scheduled sweep. A successful background sweep is quiet. + +### Size rotation and concurrent writers + +Runtime writers check size before appending each batch. When the current file +exceeds `maintenance.log_max_mb`, it becomes `runtime.log.1`, replacing the +previous backup. There is one backup generation. The janitor also checks size +during its sweep. A batch can take the file above the threshold before the next +check, so the setting is a rotation threshold rather than a strict byte cap. + +Writers and the janitor share a stable `runtime.log.lock` and reopen the log for +each batch. Rotation and expiration therefore cannot leave a cooperating writer +appending to an obsolete file. Writers retain and retry their pending batch +while cleanup holds the lock; their bounded queues and shutdown limits still +apply. Use `tail -F` to follow the log when rotation or pruning replaces it. + +Disabling the background janitor delays expiration until manual cleanup; size +rotation still runs in the writer. Size rotation may discard records sooner +than the age limit. To retain records without either automatic size eviction or +age expiration, set **both** `log_max_mb` and `runtime_log_max_age_hours` to `0`. + +### Previewing and running cleanup + +Use the policy currently configured for the operator: + +```sh +odek cleanup --dry-run +odek cleanup +``` + +An expiration-only preview includes a line such as: + +```text + runtime records expired: 42 +``` + +The completed sweep reports: + +```text + runtime records removed: 42 +``` + +These counts cover both current and backup runtime logs. Preview and execution +can differ if records arrive, rotate, or cross the age cutoff between commands. +`odek cleanup` also applies the configured retention rules for sessions, audit +records, plans, artifacts, and media; it is not a log-only command. + +To preview a different runtime retention period for one invocation: + +```sh +ODEK_MAINTENANCE_RUNTIME_LOG_MAX_AGE_HOURS=24 odek cleanup --dry-run +``` + +This environment override does not edit the global configuration or change the +policy of services already running. Remove `--dry-run` to perform that sweep. + +### Troubleshooting retention + +| Observation | Check | +| --- | --- | +| Old records remain just after starting serve or Telegram | Wait for the first maintenance interval, or run `odek cleanup` immediately. | +| Old records remain after CLI-only usage | CLI runs write logs but do not host a janitor. Use manual cleanup or a long-lived service. | +| Records never expire by age | Check `runtime_log_max_age_hours`, environment overrides, and whether the background janitor is enabled and running. A value of `0` disables expiration. | +| A record survives an otherwise successful sweep | Check its timestamp. Missing, malformed, and future timestamps do not qualify for expiration at the current cutoff. | +| Logs disappear sooner than seven days | Size rotation can replace the single backup before the age limit is reached. | +| A sweep reports an error | Inspect stderr for `odek: maintenance sweep:` or the manual cleanup error. Check permissions, regular-file targets, available disk space for replacement files, and lock contention. | +| An old `serve.log` entry remains | Runtime record expiration applies only to `runtime.log` and its backup. `serve.log` follows the existing size-rotation policy. | diff --git a/docs/MAINTENANCE.md b/docs/MAINTENANCE.md index 91a05be0..c53919ff 100644 --- a/docs/MAINTENANCE.md +++ b/docs/MAINTENANCE.md @@ -41,7 +41,7 @@ commands (`odek run`, `odek repl`, …) do not run the janitor — use | Plans | `~/.odek/plans/**/*.md` (by mtime) | `plans_max_age_days` | 30 days | | Sub-agent artifacts | `~/.odek/artifacts///` and `~/.odek/artifacts/unfiled//` (task dirs by their own mtime; aged session dirs also go wholesale) | `artifacts_max_age_hours` | 24 hours (backstop — live removal happens on session delete) | | Telegram media | `~/.odek/media/` (by mtime) | fixed: 1 hour | freed bytes reported | -| Logs | `~/.odek/telegram.log`, `~/.odek/schedule.log`, `~/.odek/serve.log` | `log_max_mb` | 50 MB (rotated) | +| Logs | `~/.odek/telegram.log`, `~/.odek/schedule.log`, `~/.odek/serve.log`, `~/.odek/runtime.log` | `log_max_mb` | 50 MB (rotated) | Age for sessions is measured from the session's `updated_at`; for audit records, plans, and media from the file's modification time. Sub-agent @@ -89,6 +89,7 @@ The `[maintenance]` section (all keys optional — defaults shown): | `sessions_max_age_days` | `30` | Delete sessions older than this | | `audit_max_age_days` | `14` | Delete prompt-injection audit records older than this | | `log_max_mb` | `50` | Rotate logs larger than this | +| `runtime_log_max_age_hours` | `168` | Remove older timestamped runtime records from current and backup logs; `0` keeps them indefinitely | | `plans_max_age_days` | `30` | Delete plans older than this | | `artifacts_max_age_hours` | `24` | Sweep sub-agent artifact task dirs older than this, in any parent (including `unfiled`; emptied parent dirs are pruned; `0` keeps them forever; live removal still happens on session delete) | @@ -144,3 +145,5 @@ you want to inspect the candidate list. - `internal/session` — session files are also capped at 32 MiB **at write time**: an oversized transcript is trimmed (oldest turns first, keeping the system message and the most recent turns) so it never becomes unloadable. + +See [Runtime logging](LOGGING.md) for runtime log expiration, correlation, and rotation semantics. diff --git a/docs/SUBAGENTS.md b/docs/SUBAGENTS.md index 7f567b5b..dd8bf31b 100644 --- a/docs/SUBAGENTS.md +++ b/docs/SUBAGENTS.md @@ -638,3 +638,11 @@ outcomes. - **Provide file paths** in context — saves the sub-agent from crawling the project tree. - **Check the trade-off** — spawning a sub-agent takes ~500ms. Don't delegate tasks that complete in 2 tool calls. - **Observation**: sub-agents work best for **greenfield** work (creating new files). Refactoring existing code often has too many implicit dependencies. + +## Persistent runtime logs + +Enable operator `logging.enabled` to monitor delegated tasks through +`~/.odek/runtime.log`. Child records inherit the parent session ID and include +task ancestry, model/tool timings, periodic activity observations, and terminal +usage and exit diagnostics. Records expire according to +`maintenance.runtime_log_max_age_hours`. See [Runtime logging](LOGGING.md). diff --git a/internal/config/loader.go b/internal/config/loader.go index 79f0437f..4f1269c5 100644 --- a/internal/config/loader.go +++ b/internal/config/loader.go @@ -29,6 +29,7 @@ import ( sdk "github.com/BackendStack21/go-llm-sdk" "github.com/BackendStack21/odek/internal/budget" "github.com/BackendStack21/odek/internal/danger" + "github.com/BackendStack21/odek/internal/diagnostics" "github.com/BackendStack21/odek/internal/embedding" "github.com/BackendStack21/odek/internal/guard" @@ -373,13 +374,14 @@ type ToolConfig struct { // Operator-controlled: rejected from project-level ./odek.json because it // governs DELETION of user data. type MaintenanceConfig struct { - Enabled *bool `json:"enabled,omitempty"` - IntervalMinutes *int `json:"interval_minutes,omitempty"` - SessionsMaxAgeDays *int `json:"sessions_max_age_days,omitempty"` - AuditMaxAgeDays *int `json:"audit_max_age_days,omitempty"` - LogMaxMB *int64 `json:"log_max_mb,omitempty"` - PlansMaxAgeDays *int `json:"plans_max_age_days,omitempty"` - ArtifactsMaxAgeHours *int `json:"artifacts_max_age_hours,omitempty"` + RuntimeLogMaxAgeHours *int `json:"runtime_log_max_age_hours,omitempty"` + Enabled *bool `json:"enabled,omitempty"` + IntervalMinutes *int `json:"interval_minutes,omitempty"` + SessionsMaxAgeDays *int `json:"sessions_max_age_days,omitempty"` + AuditMaxAgeDays *int `json:"audit_max_age_days,omitempty"` + LogMaxMB *int64 `json:"log_max_mb,omitempty"` + PlansMaxAgeDays *int `json:"plans_max_age_days,omitempty"` + ArtifactsMaxAgeHours *int `json:"artifacts_max_age_hours,omitempty"` } // ToolsConfig is the "tools" section of odek.json. It is intentionally a @@ -536,7 +538,14 @@ func DefaultBackgroundConfig() BackgroundConfig { // FileConfig is the JSON schema used by ~/.odek/config.json and ./odek.json. // Pointer booleans distinguish "explicitly set to false" from "not set". +// LoggingConfig enables local metadata-only runtime logs. This section is +// operator-only; project files cannot enable or disable logging. +type LoggingConfig struct { + Enabled bool `json:"enabled"` +} + type FileConfig struct { + Logging *LoggingConfig `json:"logging,omitempty"` Provider string `json:"provider,omitempty"` Model string `json:"model,omitempty"` BaseURL string `json:"base_url,omitempty"` @@ -770,6 +779,7 @@ type ProjectSandboxOverride struct { // ResolvedConfig is the fully merged result. Every field has a concrete // value — callers can read directly without checking for "not set". type ResolvedConfig struct { + Logging LoggingConfig Provider string Model string BaseURL string @@ -997,6 +1007,9 @@ func loadFile(path string) FileConfig { } f, err := os.Open(path) if err != nil { + if !os.IsNotExist(err) { + diagnostics.Warning("config", "open_file", err) + } return FileConfig{} // missing or unreadable = empty } defer f.Close() @@ -1009,6 +1022,7 @@ func loadFile(path string) FileConfig { // covered only secrets.env). if info, serr := f.Stat(); serr == nil { if perm := info.Mode().Perm(); perm&0077 != 0 { + diagnostics.Warning("config", "file_permissions", nil) fmt.Fprintf(os.Stderr, "odek: WARNING: config %s is group/world-readable (%04o) and may contain secrets; run `chmod 600 %s`\n", path, perm, path) } } @@ -1018,14 +1032,17 @@ func loadFile(path string) FileConfig { // closes the TOCTOU window between stat and read. data, err := io.ReadAll(io.LimitReader(f, maxConfigFileBytes+1)) if err != nil { + diagnostics.Warning("config", "read_file", err) return FileConfig{} } if int64(len(data)) > maxConfigFileBytes { + diagnostics.Warning("config", "file_size_limit", nil) fmt.Fprintf(os.Stderr, "odek: warning: config %s: file exceeds maximum size %d bytes — ignoring file\n", path, maxConfigFileBytes) return FileConfig{} } var cfg FileConfig if err := json.Unmarshal(data, &cfg); err != nil { + diagnostics.Warning("config", "decode_file", err) fmt.Fprintf(os.Stderr, "odek: warning: config %s: invalid JSON — ignoring file: %v\n", path, err) return FileConfig{} // invalid JSON = empty } @@ -1165,6 +1182,7 @@ func envBool(key string) *bool { // var is set but cannot be parsed and its value will be ignored (the // default applies), consistent with the other loader warnings. func warnBadEnvValue(key, v string, err error) { + diagnostics.Warning("config", "environment_value", err) fmt.Fprintf(os.Stderr, "odek: warning: invalid ODEK_%s value %q — ignoring: %v\n", key, v, err) } @@ -1328,6 +1346,9 @@ func resolveMaintenance(cfg *MaintenanceConfig) maintenance.Config { if cfg.PlansMaxAgeDays != nil { def.PlansMaxAgeDays = maintenance.ClampRetentionDays(*cfg.PlansMaxAgeDays) } + if cfg.RuntimeLogMaxAgeHours != nil { + def.RuntimeLogMaxAgeHours = maintenance.ClampRetentionHours(*cfg.RuntimeLogMaxAgeHours) + } if cfg.ArtifactsMaxAgeHours != nil { def.ArtifactsMaxAgeHours = maintenance.ClampRetentionHours(*cfg.ArtifactsMaxAgeHours) } @@ -1691,6 +1712,10 @@ func LoadConfig(cli CLIFlags) ResolvedConfig { } // The maintenance section governs DELETION of user data (sessions, audit // records, plans, logs). A malicious repo must not be able to set it. + if project.Logging != nil { + fmt.Fprintln(os.Stderr, "odek: WARNING: ignoring logging from project config; set it via ~/.odek/config.json or ODEK_LOGGING_ENABLED") + project.Logging = nil + } if project.Maintenance != nil { fmt.Fprintf(os.Stderr, "odek: WARNING: ignoring maintenance from project config (%s); set it via ~/.odek/config.json or ODEK_MAINTENANCE_*\n", ProjectConfigPath()) project.Maintenance = nil @@ -2192,9 +2217,17 @@ func LoadConfig(cli CLIFlags) ResolvedConfig { } } + if v := envBool("LOGGING_ENABLED"); v != nil { + cfg.Logging = &LoggingConfig{Enabled: *v} + } + // Maintenance env overrides (ODEK_MAINTENANCE_*). Explicit 0 is meaningful // for the retention knobs (0 = keep forever / disable), so they parse via // the pointer helpers rather than envInt. + if v := envIntPtr("MAINTENANCE_RUNTIME_LOG_MAX_AGE_HOURS"); v != nil { + cfg.Maintenance = ensureMaintenance(cfg.Maintenance) + cfg.Maintenance.RuntimeLogMaxAgeHours = v + } if v := envBool("MAINTENANCE_ENABLED"); v != nil { cfg.Maintenance = ensureMaintenance(cfg.Maintenance) cfg.Maintenance.Enabled = v @@ -2544,6 +2577,10 @@ func LoadConfig(cli CLIFlags) ResolvedConfig { ToolProgress: ifZero(cfg.ToolProgress, "all"), } + if cfg.Logging != nil { + resolved.Logging = *cfg.Logging + } + // Built-in default sub-agent capability profile: unless the // operator disabled it or defined their own "default" profile, // materialize the local_write-capped envelope so delegate_tasks and @@ -3673,6 +3710,9 @@ func overlayFile(base, override FileConfig) FileConfig { if override.Memory != nil { base.Memory = override.Memory } + if override.Logging != nil { + base.Logging = override.Logging + } if override.Maintenance != nil { base.Maintenance = override.Maintenance } @@ -3941,6 +3981,7 @@ func loadSecretsEnv() { // to other local users (finding #78). if info, err := f.Stat(); err == nil { if perm := info.Mode().Perm(); perm&0077 != 0 { + diagnostics.Warning("config", "secrets_permissions", nil) fmt.Fprintf(os.Stderr, "odek: WARNING: %s is group/world-readable (%04o); refusing to load secrets\n", path, perm) return } @@ -4002,6 +4043,7 @@ func loadSecretsEnv() { } } if err := scanner.Err(); err != nil { + diagnostics.Warning("config", "secrets_read", err) fmt.Fprintf(os.Stderr, "odek: WARNING: %s: %v — remaining secrets were NOT loaded\n", path, err) } } diff --git a/internal/config/logging.go b/internal/config/logging.go new file mode 100644 index 00000000..63233d0d --- /dev/null +++ b/internal/config/logging.go @@ -0,0 +1,20 @@ +package config + +// LoadLoggingSettings resolves only operator logging policy before command +// parsing and service initialization. Project config cannot enable logging. +// Diagnostics produced while reading the policy are buffered by the caller. +func LoadLoggingSettings() (enabled bool, maxMB int64) { + loadSecretsEnv() + cfg := loadFile(GlobalConfigPath()) + if cfg.Logging != nil { + enabled = cfg.Logging.Enabled + } + if v := envBool("LOGGING_ENABLED"); v != nil { + enabled = *v + } + maxMB = resolveMaintenance(cfg.Maintenance).LogMaxMB + if v := envInt64Ptr("MAINTENANCE_LOG_MAX_MB"); v != nil { + maxMB = *v + } + return enabled, maxMB +} diff --git a/internal/config/maintenance_test.go b/internal/config/maintenance_test.go index a6390e76..bd204e96 100644 --- a/internal/config/maintenance_test.go +++ b/internal/config/maintenance_test.go @@ -41,13 +41,14 @@ func TestLoadConfig_MaintenanceGlobalFile(t *testing.T) { cfg := LoadConfig(CLIFlags{}) want := maintenance.Config{ - Enabled: false, - IntervalMinutes: 15, - SessionsMaxAgeDays: 90, - AuditMaxAgeDays: 7, - LogMaxMB: 100, - PlansMaxAgeDays: 60, - ArtifactsMaxAgeHours: 24, // absent from the file ⇒ loader default applies + RuntimeLogMaxAgeHours: 168, + Enabled: false, + IntervalMinutes: 15, + SessionsMaxAgeDays: 90, + AuditMaxAgeDays: 7, + LogMaxMB: 100, + PlansMaxAgeDays: 60, + ArtifactsMaxAgeHours: 24, // absent from the file ⇒ loader default applies } if cfg.Maintenance != want { t.Errorf("Maintenance = %+v, want %+v", cfg.Maintenance, want) @@ -143,13 +144,14 @@ func TestLoadConfig_MaintenanceEnvVars(t *testing.T) { cfg := LoadConfig(CLIFlags{}) want := maintenance.Config{ - Enabled: false, - IntervalMinutes: 5, - SessionsMaxAgeDays: 7, - AuditMaxAgeDays: 3, - LogMaxMB: 10, - PlansMaxAgeDays: 15, - ArtifactsMaxAgeHours: 0, // explicit 0 via env = keep forever + RuntimeLogMaxAgeHours: 168, + Enabled: false, + IntervalMinutes: 5, + SessionsMaxAgeDays: 7, + AuditMaxAgeDays: 3, + LogMaxMB: 10, + PlansMaxAgeDays: 15, + ArtifactsMaxAgeHours: 0, // explicit 0 via env = keep forever } if cfg.Maintenance != want { t.Errorf("Maintenance = %+v, want %+v", cfg.Maintenance, want) diff --git a/internal/config/runtime_logging_test.go b/internal/config/runtime_logging_test.go new file mode 100644 index 00000000..3b4a7fd9 --- /dev/null +++ b/internal/config/runtime_logging_test.go @@ -0,0 +1,65 @@ +package config + +import ( + "os" + "path/filepath" + "testing" +) + +func TestRuntimeLoggingOperatorConfigAndExpiration(t *testing.T) { + home := t.TempDir() + t.Setenv("HOME", home) + t.Chdir(home) + _ = os.Mkdir(filepath.Join(home, ".odek"), 0700) + _ = os.WriteFile(filepath.Join(home, ".odek", "config.json"), []byte(`{"logging":{"enabled":true},"maintenance":{"runtime_log_max_age_hours":12}}`), 0600) + _ = os.WriteFile(filepath.Join(home, "odek.json"), []byte(`{"logging":{"enabled":false},"maintenance":{"runtime_log_max_age_hours":1}}`), 0600) + got := LoadConfig(CLIFlags{}) + if !got.Logging.Enabled || got.Maintenance.RuntimeLogMaxAgeHours != 12 { + t.Fatalf("project changed operator logging: %+v %+v", got.Logging, got.Maintenance) + } + t.Setenv("ODEK_LOGGING_ENABLED", "false") + t.Setenv("ODEK_MAINTENANCE_RUNTIME_LOG_MAX_AGE_HOURS", "0") + got = LoadConfig(CLIFlags{}) + if got.Logging.Enabled || got.Maintenance.RuntimeLogMaxAgeHours != 0 { + t.Fatalf("env overrides: %+v %+v", got.Logging, got.Maintenance) + } +} +func TestRuntimeLogExpirationClamps(t *testing.T) { + for _, n := range []int{-1, 999999999, 0, 24} { + got := resolveMaintenance(&MaintenanceConfig{RuntimeLogMaxAgeHours: &n}).RuntimeLogMaxAgeHours + if got < 0 || got > 36500 { + t.Fatalf("unbounded retention: %d", got) + } + if n == 0 && got != 0 { + t.Fatal("zero must retain forever") + } + } +} + +func TestEarlyLoggingPolicyMatchesOperatorPrecedence(t *testing.T) { + home := t.TempDir() + t.Setenv("HOME", home) + t.Chdir(home) + t.Setenv("ODEK_LOGGING_ENABLED", "") + t.Setenv("ODEK_MAINTENANCE_LOG_MAX_MB", "") + if err := os.Mkdir(filepath.Join(home, ".odek"), 0700); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(filepath.Join(home, "odek.json"), []byte(`{"logging":{"enabled":true}}`), 0600); err != nil { + t.Fatal(err) + } + if enabled, maxMB := LoadLoggingSettings(); enabled || maxMB != 50 { + t.Fatalf("project or defaults affected bootstrap: %v %d", enabled, maxMB) + } + if err := os.WriteFile(GlobalConfigPath(), []byte(`{"logging":{"enabled":true},"maintenance":{"log_max_mb":7}}`), 0600); err != nil { + t.Fatal(err) + } + if enabled, maxMB := LoadLoggingSettings(); !enabled || maxMB != 7 { + t.Fatalf("operator config ignored: %v %d", enabled, maxMB) + } + t.Setenv("ODEK_LOGGING_ENABLED", "false") + t.Setenv("ODEK_MAINTENANCE_LOG_MAX_MB", "0") + if enabled, maxMB := LoadLoggingSettings(); enabled || maxMB != 0 { + t.Fatalf("environment ignored: %v %d", enabled, maxMB) + } +} diff --git a/internal/diagnostics/diagnostics.go b/internal/diagnostics/diagnostics.go new file mode 100644 index 00000000..e53beef7 --- /dev/null +++ b/internal/diagnostics/diagnostics.go @@ -0,0 +1,69 @@ +// Package diagnostics routes application failures to an optional process-wide +// observer. It never captures stderr, error text, paths, or request content. +package diagnostics + +import ( + "sync" + "time" + + "github.com/BackendStack21/odek/internal/events" +) + +var observer struct { + sync.RWMutex + handler func(events.Event) +} + +// Install registers a non-blocking observer and returns a function restoring +// the previous observer. The process owner installs it before loading config +// and removes it after its services stop. Library use is opt-in. +func Install(handler func(events.Event)) func() { + observer.Lock() + previous := observer.handler + observer.handler = handler + observer.Unlock() + var once sync.Once + return func() { + once.Do(func() { + observer.Lock() + observer.handler = previous + observer.Unlock() + }) + } +} + +// Report records an operation failure. component and operation must be static +// program labels, never user input. A session ID is optional for global work. +// Callers retain responsibility for their existing user-facing diagnostics. +func Report(component, operation, sessionID string, err error) { + if err == nil { + return + } + Emit(Failure(component, operation, sessionID, err)) +} + +func Failure(component, operation, sessionID string, err error) events.Event { + data := events.ErrorData(err) + data["component"], data["operation"] = component, operation + return events.Event{Type: "operation_failed", SessionID: sessionID, Data: data} +} + +// Warning records a known degraded state, including validation fallbacks. +func Warning(component, operation string, err error) { + ev := Failure(component, operation, "", err) + ev.Type = "operation_warning" + Emit(ev) +} + +func Emit(ev events.Event) { + if ev.Timestamp.IsZero() { + ev.Timestamp = time.Now().UTC() + } + observer.RLock() + handler := observer.handler + observer.RUnlock() + if handler != nil { + defer func() { _ = recover() }() + handler(ev) + } +} diff --git a/internal/diagnostics/diagnostics_test.go b/internal/diagnostics/diagnostics_test.go new file mode 100644 index 00000000..6fe445db --- /dev/null +++ b/internal/diagnostics/diagnostics_test.go @@ -0,0 +1,43 @@ +package diagnostics + +import ( + "errors" + "sync" + "syscall" + "testing" + + "github.com/BackendStack21/odek/internal/events" +) + +func TestObserverLifecycleAndConcurrentReports(t *testing.T) { + var mu sync.Mutex + var got []events.Event + restore := Install(func(ev events.Event) { mu.Lock(); defer mu.Unlock(); got = append(got, ev) }) + t.Cleanup(restore) + Report("storage", "write", "session", nil) + var wg sync.WaitGroup + for range 4 { + wg.Go(func() { + for range 20 { + Report("storage", "write", "session", syscall.ENOSPC) + } + }) + } + wg.Wait() + Warning("config", "fallback", nil) + if len(got) != 81 || got[0].SessionID != "session" || got[0].Data["error_class"] != "disk_full" || got[80].Type != "operation_warning" { + t.Fatalf("unexpected reports: %+v", got) + } + undo := Install(func(events.Event) { panic("observer failed") }) + Report("test", "panic_isolation", "", errors.New("private")) + undo() + Report("storage", "restored", "", syscall.EACCES) + if len(got) != 82 { + t.Fatal("previous observer not restored") + } + restore() + Report("storage", "disabled", "", syscall.EACCES) + if len(got) != 82 { + t.Fatal("observer remains active") + } +} diff --git a/internal/events/context_test.go b/internal/events/context_test.go new file mode 100644 index 00000000..af08482d --- /dev/null +++ b/internal/events/context_test.go @@ -0,0 +1,84 @@ +package events + +import ( + "reflect" + "sync" + "testing" +) + +func TestEmitterContextSnapshotsAcrossTurnsAndSessions(t *testing.T) { + handler, got := collect() + em := NewEmitter(handler, "local-run") + t.Cleanup(em.Close) + em.SetSessionID("first-session") + em.SetContext(Context{RunID: "ignored", TaskID: "task", ParentTaskID: "parent-task", ParentRunID: "parent-run", ParentTurnID: "parent-turn"}) + em.SetTurnID("first-turn") + first := em.Context() + if first.RunID != em.RunID() || first.RootRunID != "local-run" || first.SessionID != "first-session" { + t.Fatalf("context defaults: %+v", first) + } + em.Emit(Event{Type: TypeRunStarted}) + em.SetTurnID("second-turn") + em.SetSessionID("second-session") + em.Emit(Event{Type: TypeRunStarted, RunID: em.RunID()}) + em.Close() + evs := got() + if len(evs) != 2 { + t.Fatalf("got %d events", len(evs)) + } + for i, ev := range evs { + want := []string{"first", "second"}[i] + if ev.TurnID != want+"-turn" || ev.SessionID != want+"-session" || ev.RunID != "local-run" || ev.RootRunID != "local-run" || ev.TaskID != "task" || ev.ParentTaskID != "parent-task" || ev.ParentRunID != "parent-run" || ev.ParentTurnID != "parent-turn" { + t.Fatalf("event context changed after enqueue: %+v", ev) + } + } + if first.TurnID != "first-turn" || first.SessionID != "first-session" { + t.Fatalf("previous context snapshot changed: %+v", first) + } +} + +func TestEmitterPreservesRelayedChildContext(t *testing.T) { + handler, got := collect() + em := NewEmitter(handler, "parent-run") + t.Cleanup(em.Close) + em.SetContext(Context{RootRunID: "root", SessionID: "session", TurnID: "parent-turn", TaskID: "parent-task"}) + if c := em.Context(); c.RootRunID != "root" || c.SessionID != "session" { + t.Fatalf("explicit context lost: %+v", c) + } + child := Event{Type: TypeRunStarted, RunID: "child-run", TurnID: "child-turn", RootRunID: "explicit-root", SessionID: "explicit-session", TaskID: "child-task", ParentRunID: "parent-run", ParentTurnID: "parent-turn", ParentTaskID: "parent-task", SourceTaskID: "verified-child"} + em.Emit(child) + em.Emit(Event{Type: TypeRunStarted, RunID: "legacy-child"}) + em.Close() + evs := got() + if len(evs) != 2 { + t.Fatalf("got %d events", len(evs)) + } + child.Schema, child.Timestamp = evs[0].Schema, evs[0].Timestamp + if !reflect.DeepEqual(evs[0], child) { + t.Fatalf("child context overwritten: %+v", evs[0]) + } + legacy := evs[1] + if legacy.RootRunID != "root" || legacy.SessionID != "session" || legacy.TurnID != "" || legacy.TaskID != "" || legacy.ParentRunID != "" || legacy.ParentTurnID != "" || legacy.ParentTaskID != "" { + t.Fatalf("parent identity attributed to legacy child: %+v", legacy) + } +} + +func TestEmitterContextConcurrentAccess(t *testing.T) { + em := NewEmitter(nil, "run") + t.Cleanup(em.Close) + var wg sync.WaitGroup + for worker := 0; worker < 4; worker++ { + wg.Go(func() { + for i := 0; i < 100; i++ { + em.SetContext(Context{SessionID: "session", RootRunID: "root"}) + em.SetTurnID("turn") + em.SetSessionID("session") + em.Emit(Event{Type: TypeRunStarted}) + if c := em.Context(); c.RunID != em.RunID() || c.SessionID != "session" || c.RootRunID != "root" { + t.Errorf("inconsistent context: %+v", c) + } + } + }) + } + wg.Wait() +} diff --git a/internal/events/errors.go b/internal/events/errors.go new file mode 100644 index 00000000..fc2cabf2 --- /dev/null +++ b/internal/events/errors.go @@ -0,0 +1,113 @@ +package events + +import ( + "context" + "crypto/x509" + "encoding/json" + "errors" + "fmt" + "io" + "io/fs" + "net" + "os/exec" + "syscall" + + sdk "github.com/BackendStack21/go-llm-sdk" + "github.com/BackendStack21/odek/internal/budget" +) + +// ErrorData describes the cause without copying an error's message, which can +// contain credentials, file contents, request URLs, or provider response bodies. +func ErrorData(err error) map[string]any { + data := map[string]any{"error_class": ErrorClass(err)} + if err == nil { + return data + } + data["error_type"] = fmt.Sprintf("%T", err) + var api *sdk.APIError + if errors.As(err, &api) { + data["http_status"] = api.Status + } + return data +} + +func classifyError(err error) string { + switch { + case err == nil: + return "" + case errors.Is(err, context.Canceled): + return "context_canceled" + case errors.Is(err, context.DeadlineExceeded): + return "deadline_exceeded" + case errors.Is(err, sdk.ErrIdleTimeout): + return "stream_idle_timeout" + case errors.Is(err, fs.ErrPermission): + return "permission_denied" + case errors.Is(err, fs.ErrNotExist): + return "not_found" + case errors.Is(err, syscall.ENOSPC): + return "disk_full" + case errors.Is(err, syscall.EROFS): + return "read_only_filesystem" + case errors.Is(err, syscall.EMFILE), errors.Is(err, syscall.ENFILE): + return "file_descriptors_exhausted" + case errors.Is(err, syscall.EADDRINUSE): + return "address_in_use" + case errors.Is(err, syscall.ENOTDIR), errors.Is(err, syscall.EISDIR): + return "invalid_file_type" + case errors.Is(err, syscall.ELOOP): + return "symlink_rejected" + case errors.Is(err, exec.ErrNotFound): + return "executable_not_found" + case errors.Is(err, syscall.ECONNREFUSED): + return "connection_refused" + case errors.Is(err, syscall.ECONNRESET), errors.Is(err, syscall.EPIPE): + return "connection_closed" + case errors.Is(err, io.EOF), errors.Is(err, io.ErrUnexpectedEOF): + return "unexpected_eof" + } + if _, ok := budget.As(err); ok { + return "execution_budget" + } + var exit *exec.ExitError + if errors.As(err, &exit) { + return "process_exit" + } + var api *sdk.APIError + if errors.As(err, &api) { + switch { + case api.Status == 401 || api.Status == 403: + return "provider_auth" + case api.Status == 429: + return "rate_limited" + case api.Status >= 500: + return "provider_unavailable" + default: + return "provider_request" + } + } + var cfg *sdk.ConfigError + if errors.As(err, &cfg) { + return "provider_config" + } + var syntax *json.SyntaxError + var typeError *json.UnmarshalTypeError + if errors.As(err, &syntax) || errors.As(err, &typeError) { + return "invalid_json" + } + var dns *net.DNSError + if errors.As(err, &dns) { + return "dns_failure" + } + var cert x509.UnknownAuthorityError + var invalid x509.CertificateInvalidError + var host x509.HostnameError + if errors.As(err, &cert) || errors.As(err, &invalid) || errors.As(err, &host) { + return "tls_certificate" + } + var network net.Error + if errors.As(err, &network) && network.Timeout() { + return "network_timeout" + } + return "error" +} diff --git a/internal/events/errors_test.go b/internal/events/errors_test.go new file mode 100644 index 00000000..4b405f37 --- /dev/null +++ b/internal/events/errors_test.go @@ -0,0 +1,69 @@ +package events + +import ( + "context" + "crypto/x509" + "encoding/json" + "errors" + "fmt" + "github.com/BackendStack21/odek/internal/budget" + "io" + "net" + "net/url" + "os" + "os/exec" + "strings" + "syscall" + "testing" + + sdk "github.com/BackendStack21/go-llm-sdk" +) + +func TestErrorCategoriesAndPrivacy(t *testing.T) { + cases := []struct { + err error + class string + }{ + {nil, ""}, {&budget.Error{}, "execution_budget"}, {&exec.ExitError{}, "process_exit"}, {exec.ErrNotFound, "executable_not_found"}, {syscall.ENOTDIR, "invalid_file_type"}, {syscall.EISDIR, "invalid_file_type"}, {syscall.ELOOP, "symlink_rejected"}, {context.Canceled, "context_canceled"}, {context.DeadlineExceeded, "deadline_exceeded"}, + {sdk.ErrIdleTimeout, "stream_idle_timeout"}, {os.ErrPermission, "permission_denied"}, {os.ErrNotExist, "not_found"}, + {syscall.ENOSPC, "disk_full"}, {syscall.EROFS, "read_only_filesystem"}, {syscall.EMFILE, "file_descriptors_exhausted"}, {syscall.ENFILE, "file_descriptors_exhausted"}, + {syscall.EADDRINUSE, "address_in_use"}, {syscall.ECONNREFUSED, "connection_refused"}, {syscall.ECONNRESET, "connection_closed"}, {syscall.EPIPE, "connection_closed"}, + {io.EOF, "unexpected_eof"}, {io.ErrUnexpectedEOF, "unexpected_eof"}, + {&sdk.APIError{Status: 401, Message: "PRIVATE"}, "provider_auth"}, {&sdk.APIError{Status: 403}, "provider_auth"}, + {&sdk.RateLimitError{APIError: sdk.APIError{Status: 429, Message: "PRIVATE"}}, "rate_limited"}, + {&sdk.APIError{Status: 503}, "provider_unavailable"}, {&sdk.APIError{Status: 400}, "provider_request"}, + {&sdk.ConfigError{Msg: "PRIVATE"}, "provider_config"}, {&json.SyntaxError{}, "invalid_json"}, {&json.UnmarshalTypeError{}, "invalid_json"}, + {&net.DNSError{Name: "PRIVATE"}, "dns_failure"}, {x509.UnknownAuthorityError{}, "tls_certificate"}, {x509.CertificateInvalidError{}, "tls_certificate"}, {x509.HostnameError{}, "tls_certificate"}, + {&net.DNSError{IsTimeout: true}, "dns_failure"}, {&net.OpError{Op: "dial", Err: os.ErrDeadlineExceeded}, "network_timeout"}, + {errors.New("PRIVATE"), "error"}, + } + for _, tc := range cases { + t.Run(tc.class+fmt.Sprintf("_%T", tc.err), func(t *testing.T) { + err := tc.err + if err != nil { + err = &privacyWrappedError{err: err} + } + if got := ErrorClass(err); got != tc.class { + t.Fatalf("got %s, want %s", got, tc.class) + } + b, marshalErr := json.Marshal(ErrorData(err)) + if marshalErr != nil || strings.Contains(string(b), "PRIVATE") { + t.Fatalf("unsafe details: %s %v", b, marshalErr) + } + }) + } + err := &url.Error{Op: "Post", URL: "https://PRIVATE/path?key=PRIVATE", Err: &sdk.APIError{Status: 429, Message: "PRIVATE"}} + data := ErrorData(err) + if data["http_status"] != 429 || data["error_class"] != "rate_limited" { + t.Fatal(data) + } + b, _ := json.Marshal(data) + if strings.Contains(string(b), "PRIVATE") { + t.Fatal(string(b)) + } +} + +type privacyWrappedError struct{ err error } + +func (e *privacyWrappedError) Error() string { return "PRIVATE" } +func (e *privacyWrappedError) Unwrap() error { return e.err } diff --git a/internal/events/events.go b/internal/events/events.go index b948592c..268ae98c 100644 --- a/internal/events/events.go +++ b/internal/events/events.go @@ -10,11 +10,9 @@ package events import ( - "context" "crypto/rand" "crypto/sha256" "encoding/hex" - "errors" "runtime" "strconv" "strings" @@ -63,20 +61,40 @@ const ( LimitCostUSD = "cost_usd" ) +// Context identifies an invocation and its delegation ancestry. SessionID is +// inherited by children; TurnID distinguishes calls on a reused Agent. +type Context struct { + RunID string `json:"run_id,omitempty"` + SessionID string `json:"session_id,omitempty"` + TurnID string `json:"turn_id,omitempty"` + RootRunID string `json:"root_run_id,omitempty"` + ParentRunID string `json:"parent_run_id,omitempty"` + ParentTurnID string `json:"parent_turn_id,omitempty"` + TaskID string `json:"task_id,omitempty"` + ParentTaskID string `json:"parent_task_id,omitempty"` +} + // Event is a single structured runtime event (schema odek.event/v1). // // Not every field is set for every Type; the zero value means "not // applicable" and is omitted from the JSON form. Data carries the per-type // fields documented in docs/EXTENSIONS.md. type Event struct { - Schema string `json:"schema"` - Type string `json:"type"` - RunID string `json:"run_id,omitempty"` - SessionID string `json:"session_id,omitempty"` - Iteration int `json:"iteration,omitempty"` - Tool string `json:"tool,omitempty"` - Timestamp time.Time `json:"timestamp"` - Data map[string]any `json:"data,omitempty"` + SourceTaskID string `json:"source_task_id,omitempty"` + TurnID string `json:"turn_id,omitempty"` + RootRunID string `json:"root_run_id,omitempty"` + ParentRunID string `json:"parent_run_id,omitempty"` + ParentTurnID string `json:"parent_turn_id,omitempty"` + TaskID string `json:"task_id,omitempty"` + ParentTaskID string `json:"parent_task_id,omitempty"` + Schema string `json:"schema"` + Type string `json:"type"` + RunID string `json:"run_id,omitempty"` + SessionID string `json:"session_id,omitempty"` + Iteration int `json:"iteration,omitempty"` + Tool string `json:"tool,omitempty"` + Timestamp time.Time `json:"timestamp"` + Data map[string]any `json:"data,omitempty"` } // NewRunID returns a random 128-bit hex run identifier. A fresh ID is @@ -104,16 +122,7 @@ func ArgsDigest(args string) string { // tool_call_failed / run_failed events. Raw error text is never emitted: // it may contain attacker-controlled or secret-bearing content. func ErrorClass(err error) string { - switch { - case err == nil: - return "" - case errors.Is(err, context.Canceled): - return "context_canceled" - case errors.Is(err, context.DeadlineExceeded): - return "deadline_exceeded" - default: - return "error" - } + return classifyError(err) } // DefaultBufferSize is the default capacity of an Emitter's dispatch queue. @@ -136,6 +145,7 @@ type Emitter struct { mu sync.RWMutex // guards runID, sessionID, and closed runID string sessionID string + context Context closed bool // dispatchGoroutine identifies the dispatch goroutine so Close can tell @@ -220,8 +230,29 @@ func (e *Emitter) Emit(ev Event) { if e.closed { return } - if ev.RunID == "" { + if ev.RunID == "" || ev.RunID == e.runID { ev.RunID = e.runID + if ev.TurnID == "" { + ev.TurnID = e.context.TurnID + } + if ev.TaskID == "" { + ev.TaskID = e.context.TaskID + } + if ev.ParentTaskID == "" { + ev.ParentTaskID = e.context.ParentTaskID + } + if ev.ParentRunID == "" { + ev.ParentRunID = e.context.ParentRunID + } + if ev.ParentTurnID == "" { + ev.ParentTurnID = e.context.ParentTurnID + } + } + if ev.RootRunID == "" { + ev.RootRunID = e.context.RootRunID + if ev.RootRunID == "" { + ev.RootRunID = e.runID + } } if ev.SessionID == "" { ev.SessionID = e.sessionID @@ -320,3 +351,25 @@ func (e *Emitter) Close() { } e.wg.Wait() } + +// SetContext installs trusted correlation metadata before execution begins. +func (e *Emitter) SetContext(c Context) { + e.mu.Lock() + defer e.mu.Unlock() + e.context = c + if c.SessionID != "" { + e.sessionID = c.SessionID + } +} +func (e *Emitter) SetTurnID(id string) { e.mu.Lock(); e.context.TurnID = id; e.mu.Unlock() } +func (e *Emitter) Context() Context { + e.mu.RLock() + defer e.mu.RUnlock() + c := e.context + c.RunID = e.runID + c.SessionID = e.sessionID + if c.RootRunID == "" { + c.RootRunID = e.runID + } + return c +} diff --git a/internal/flock/file_test.go b/internal/flock/file_test.go new file mode 100644 index 00000000..84c1102b --- /dev/null +++ b/internal/flock/file_test.go @@ -0,0 +1,48 @@ +package flock + +import ( + "errors" + "os" + "path/filepath" + "testing" +) + +func TestTryLockFileOwnershipAndContention(t *testing.T) { + path := filepath.Join(t.TempDir(), "lock") + open := func() *os.File { + t.Helper() + f, err := os.OpenFile(path, os.O_CREATE|os.O_RDWR, 0600) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { _ = f.Close() }) + return f + } + first, second := open(), open() + unlock, err := TryLockFile(first) + if err != nil { + t.Fatal(err) + } + if release, err := TryLockFile(second); !errors.Is(err, ErrLocked) { + if release != nil { + release() + } + unlock() + t.Fatalf("competing lock: %v", err) + } + unlock() + if _, err := first.WriteString("still owned by caller"); err != nil { + t.Fatalf("unlock closed caller's file: %v", err) + } + release, err := TryLockFile(second) + if err != nil { + t.Fatalf("lock not released: %v", err) + } + release() + if err := first.Close(); err != nil { + t.Fatal(err) + } + if release, err := TryLockFile(first); err == nil || errors.Is(err, ErrLocked) || release != nil { + t.Fatalf("closed descriptor: release=%v err=%v", release != nil, err) + } +} diff --git a/internal/flock/flock.go b/internal/flock/flock.go index baf653fa..41c138de 100644 --- a/internal/flock/flock.go +++ b/internal/flock/flock.go @@ -65,3 +65,14 @@ func TryLock(path string) (func(), error) { f.Close() }, nil } + +// TryLockFile locks an already-open file without reopening its path. The caller +// retains ownership of f and must keep it open until the returned unlock runs. +// This permits callers to enforce no-symlink/regular-file checks on the exact +// inode being locked. +func TryLockFile(f *os.File) (func(), error) { + if err := tryLockFile(int(f.Fd())); err != nil { + return nil, err + } + return func() { unlockFile(int(f.Fd())) }, nil +} diff --git a/internal/llmclient/client.go b/internal/llmclient/client.go index 144fbdc6..4ec52705 100644 --- a/internal/llmclient/client.go +++ b/internal/llmclient/client.go @@ -14,6 +14,7 @@ import ( sdk "github.com/BackendStack21/go-llm-sdk" + "github.com/BackendStack21/odek/internal/diagnostics" "github.com/BackendStack21/odek/internal/session" "github.com/BackendStack21/odek/internal/transport" ) @@ -250,7 +251,8 @@ func (c *Client) IsAnthropic() bool { } // SimpleCall is the memory/title helper: one buffered turn, no tools. -func (c *Client) SimpleCall(ctx context.Context, systemPrompt, userPrompt string) (string, error) { +func (c *Client) SimpleCall(ctx context.Context, systemPrompt, userPrompt string) (_ string, callErr error) { + defer func() { diagnostics.Report("llm", "simple_call", "", callErr) }() res, err := c.Chat.Call(ctx, &sdk.ChatRequest{ System: []sdk.SystemBlock{{Text: systemPrompt}}, Messages: []sdk.Message{{Role: sdk.RoleUser, Content: userPrompt}}, @@ -290,7 +292,8 @@ func (c *Client) prepareSideCall(messages []session.Message) *sdk.ChatRequest { // SideCall is the compaction / progress-summary helper: one buffered turn, // thinking off, no tools, capped MaxTokens. Usage still comes back on // CallResult so the loop can charge budgets. -func (c *Client) SideCall(ctx context.Context, messages []session.Message) (*CallResult, error) { +func (c *Client) SideCall(ctx context.Context, messages []session.Message) (_ *CallResult, callErr error) { + defer func() { diagnostics.Report("llm", "side_call", "", callErr) }() if c == nil || c.Chat == nil { return nil, fmt.Errorf("llm: no client") } diff --git a/internal/llmclient/diagnostics_test.go b/internal/llmclient/diagnostics_test.go new file mode 100644 index 00000000..26a801c4 --- /dev/null +++ b/internal/llmclient/diagnostics_test.go @@ -0,0 +1,47 @@ +package llmclient + +import ( + "encoding/json" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/BackendStack21/odek/internal/diagnostics" + "github.com/BackendStack21/odek/internal/events" + "github.com/BackendStack21/odek/internal/session" +) + +func TestAuxiliaryFailureDiagnostics(t *testing.T) { + var got []events.Event + restore := diagnostics.Install(func(ev events.Event) { got = append(got, ev) }) + defer restore() + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(401) + _, _ = w.Write([]byte(`{"error":{"message":"PRIVATE provider body"}}`)) + })) + defer server.Close() + client, err := Dial("legacy", "test", "PRIVATE-key", server.URL) + if err != nil { + t.Fatal(err) + } + if _, err := client.SimpleCall(t.Context(), "PRIVATE system", "PRIVATE prompt"); err == nil { + t.Fatal("simple call failure swallowed") + } + if _, err := client.SideCall(t.Context(), []session.Message{{Role: "user", Content: "PRIVATE prompt"}}); err == nil { + t.Fatal("side call failure swallowed") + } + if len(got) != 2 { + t.Fatal(got) + } + for i, operation := range []string{"simple_call", "side_call"} { + if got[i].Data["component"] != "llm" || got[i].Data["operation"] != operation || got[i].Data["error_class"] != "provider_auth" || got[i].Data["http_status"] != 401 { + t.Fatal(got[i]) + } + } + b, _ := json.Marshal(got) + if strings.Contains(string(b), "PRIVATE") { + t.Fatalf("private data leaked: %s", b) + } +} diff --git a/internal/loop/events_test.go b/internal/loop/events_test.go index 7966d8df..2f25ef58 100644 --- a/internal/loop/events_test.go +++ b/internal/loop/events_test.go @@ -85,9 +85,12 @@ func TestEngine_Events_ToolRunOrderAndShape(t *testing.T) { // Expected order: tool started → tool completed → iteration 1 completed → // iteration 2 (final answer) completed. want := []string{ + "llm_call_started", "llm_call_completed", events.TypeToolCallStarted, + "tool_call_executing", "tool_execution_completed", events.TypeToolCallCompleted, events.TypeIterationCompleted, + "llm_call_started", "llm_call_completed", events.TypeIterationCompleted, } got := col.types() @@ -103,7 +106,7 @@ func TestEngine_Events_ToolRunOrderAndShape(t *testing.T) { evs := col.all() // tool_call_started: digest + size only, correct iteration. - start := evs[0] + start := evs[2] if start.Tool != "echo" || start.Iteration != 1 { t.Errorf("start event tool=%q iteration=%d, want echo/1", start.Tool, start.Iteration) } @@ -118,7 +121,7 @@ func TestEngine_Events_ToolRunOrderAndShape(t *testing.T) { // tool_call_completed: same tool/iteration, carries duration + result size; // correlated with the start event via the shared digest (recomputed here — // the completed event deliberately carries no args fields of its own). - complete := evs[1] + complete := evs[5] if complete.Tool != start.Tool || complete.Iteration != start.Iteration { t.Errorf("completed event does not correlate with start: %+v vs %+v", complete, start) } @@ -133,7 +136,7 @@ func TestEngine_Events_ToolRunOrderAndShape(t *testing.T) { } // iteration_completed: cumulative tokens + tools_called. - iter1 := evs[2] + iter1 := evs[6] if iter1.Iteration != 1 { t.Errorf("iteration_completed #1 iteration = %d, want 1", iter1.Iteration) } @@ -143,7 +146,7 @@ func TestEngine_Events_ToolRunOrderAndShape(t *testing.T) { if tok, _ := iter1.Data["input_tokens"].(int); tok != 11 { t.Errorf("iteration 1 input_tokens = %v, want 11", tok) } - iter2 := evs[3] + iter2 := evs[9] if n, _ := iter2.Data["tools_called"].(int); n != 0 { t.Errorf("final iteration tools_called = %v, want 0", n) } @@ -238,3 +241,28 @@ func TestEngine_Events_NilHandlerNoPanic(t *testing.T) { t.Fatalf("Run() error: %v", err) } } + +type contextPanicTool struct{ fakeTool } + +func (*contextPanicTool) SetContext(context.Context) { panic("context failure") } + +func TestExecutionCompletionReportsContextPanic(t *testing.T) { + server := newToolLoopServer("panic_context", `{}`) + defer server.Close() + registry := tool.NewRegistry([]tool.Tool{&contextPanicTool{fakeTool{name: "panic_context", description: "test panic"}}}) + engine := New(testChatClient(t, server.URL), registry, 3, "", nil, 0) + col := &eventCollector{} + engine.SetEventHandler(col.handle) + if _, err := engine.Run(t.Context(), "run tool"); err != nil { + t.Fatal(err) + } + for _, ev := range col.all() { + if ev.Type == "tool_execution_completed" { + if ev.Data["status"] != "failed" { + t.Fatalf("panic reported as success: %+v", ev) + } + return + } + } + t.Fatal("missing immediate execution outcome") +} diff --git a/internal/loop/loop.go b/internal/loop/loop.go index 7ca23a4d..ad97d320 100644 --- a/internal/loop/loop.go +++ b/internal/loop/loop.go @@ -740,7 +740,27 @@ func (e *Engine) SetDeltaHandler(cb DeltaHandler) { e.deltaHandler = cb } // docs/STREAMING.md) and dispatches to CallStream when streaming is enabled. // Tool-argument deltas are suppressed: they are partial JSON and noise for // terminal consumers (the assembled calls still arrive via the result). -func (e *Engine) callLLM(ctx context.Context, messages []session.Message, tools []llmclient.ToolDef) (*llmclient.CallResult, error) { +func (e *Engine) callLLM(ctx context.Context, messages []session.Message, tools []llmclient.ToolDef) (result *llmclient.CallResult, callErr error) { + observedStart := time.Now() + e.emitEvent(events.Event{Type: "llm_call_started"}) + defer func() { + typ := "llm_call_completed" + data := map[string]any{"duration_ms": time.Since(observedStart).Milliseconds()} + if result != nil { + data["input_tokens"] = result.InputTokens + data["output_tokens"] = result.OutputTokens + if result.TTFTMs > 0 { + data["ttft_ms"] = result.TTFTMs + } + } + if callErr != nil { + typ = "llm_call_failed" + for key, value := range events.ErrorData(callErr) { + data[key] = value + } + } + e.emitEvent(events.Event{Type: typ, Data: data}) + }() callCtx := ctx if t := e.client.RequestTimeout(); t > 0 { var cancel context.CancelFunc @@ -3417,6 +3437,15 @@ func (e *Engine) runLoop(ctx context.Context, in []session.Message) (answer stri defer func() { <-sem }() // release callStart := time.Now() + executionReturned := false + defer func() { + status := "success" + if !executionReturned || results[idx].errored { + status = "failed" + } + e.emitEvent(events.Event{Type: "tool_execution_completed", Iteration: iterNum, Tool: tcRef.Function.Name, Data: map[string]any{"call_id": callIDs[idx], "duration_ms": time.Since(callStart).Milliseconds(), "status": status}}) + }() + e.emitEvent(events.Event{Type: "tool_call_executing", Iteration: iterNum, Tool: tcRef.Function.Name, Data: map[string]any{"call_id": callIDs[idx]}}) callCtx := danger.BeginReadDelivery(toolCtx) outcome := tool.Outcome{Status: "failed", ErrorClass: "tool_error"} intact := false @@ -3495,6 +3524,7 @@ func (e *Engine) runLoop(ctx context.Context, in []session.Message) (answer stri } } results[idx] = execResult{output: output, errored: errored, durationMs: time.Since(callStart).Milliseconds(), outcome: outcome, deliveryCtx: callCtx, intact: intact} + executionReturned = true }(i, tc) } workers.Wait() @@ -3535,9 +3565,9 @@ func (e *Engine) runLoop(ctx context.Context, in []session.Message) (answer stri output := results[i].output fullOutput := output e.recordPlanCheckResult(checkEpoch, tc, callIDs[i], results[i].errored) - if results[i].errored { - e.recordPlanCheckDenied(checkEpoch, tc, callIDs[i], results[i].output) - } + if results[i].errored { + e.recordPlanCheckDenied(checkEpoch, tc, callIDs[i], results[i].output) + } // ledger the mutating calls that completed this run so the // final reply can be reconciled against what actually happened. @@ -3641,7 +3671,7 @@ func (e *Engine) runLoop(ctx context.Context, in []session.Message) (answer stri e.planProvisionalFlag = true } - toolMessage := []session.Message{{ + toolMessage := []session.Message{{ Role: "tool", Content: strings.Replace(delimited, output, fullOutput, 1), ToolOutcome: func() string { diff --git a/internal/maintenance/maintenance.go b/internal/maintenance/maintenance.go index 8627d7b6..83c47e6e 100644 --- a/internal/maintenance/maintenance.go +++ b/internal/maintenance/maintenance.go @@ -17,6 +17,8 @@ import ( "path/filepath" "time" + "github.com/BackendStack21/odek/internal/diagnostics" + "github.com/BackendStack21/odek/internal/runtimelog" "github.com/BackendStack21/odek/internal/session" ) @@ -27,33 +29,36 @@ const mediaMaxAge = time.Hour // Config controls the storage-maintenance janitor. type Config struct { - Enabled bool - IntervalMinutes int // janitor tick; default 60 - SessionsMaxAgeDays int // delete sessions older than this; default 30; 0 = keep forever - AuditMaxAgeDays int // delete audit records older than this; default 14; 0 = keep - LogMaxMB int64 // rotate telegram/schedule logs larger than this; default 50; 0 = no rotation - PlansMaxAgeDays int // delete telegram plans older than this; default 30; 0 = keep - ArtifactsMaxAgeHours int // delete delegate_tasks artifact task dirs older than this, in any parent (incl. the shared unfiled bucket; aged session dirs go wholesale); default 24; 0 = keep + RuntimeLogMaxAgeHours int // record retention; default 168 (7 days); 0 = keep + Enabled bool + IntervalMinutes int // janitor tick; default 60 + SessionsMaxAgeDays int // delete sessions older than this; default 30; 0 = keep forever + AuditMaxAgeDays int // delete audit records older than this; default 14; 0 = keep + LogMaxMB int64 // rotate telegram/schedule logs larger than this; default 50; 0 = no rotation + PlansMaxAgeDays int // delete telegram plans older than this; default 30; 0 = keep + ArtifactsMaxAgeHours int // delete delegate_tasks artifact task dirs older than this, in any parent (incl. the shared unfiled bucket; aged session dirs go wholesale); default 24; 0 = keep } // DefaultConfig returns the out-of-the-box maintenance policy. func DefaultConfig() Config { return Config{ - Enabled: true, - IntervalMinutes: 60, - SessionsMaxAgeDays: 30, - AuditMaxAgeDays: 14, - LogMaxMB: 50, - PlansMaxAgeDays: 30, - ArtifactsMaxAgeHours: 24, + Enabled: true, + RuntimeLogMaxAgeHours: 168, + IntervalMinutes: 60, + SessionsMaxAgeDays: 30, + AuditMaxAgeDays: 14, + LogMaxMB: 50, + PlansMaxAgeDays: 30, + ArtifactsMaxAgeHours: 24, } } // Report summarises what one Sweep pass removed. type Report struct { - SessionsRemoved int - AuditRemoved int - PlansRemoved int + RuntimeLogRecordsRemoved int + SessionsRemoved int + AuditRemoved int + PlansRemoved int // ArtifactsRemoved counts every artifacts removal: expired task // subtrees, wholesale session dirs, and pruned empty parents. ArtifactsRemoved int @@ -70,7 +75,8 @@ type Report struct { func Sweep(ctx context.Context, home string, cfg Config) (Report, error) { var rep Report var firstErr error - fail := func(err error) { + fail := func(operation string, err error) { + diagnostics.Report("maintenance", operation, "", err) if err != nil && firstErr == nil { firstErr = err } @@ -82,7 +88,7 @@ func Sweep(ctx context.Context, home string, cfg Config) (Report, error) { } n, err := sweepSessions(home, cfg.SessionsMaxAgeDays) rep.SessionsRemoved = n - fail(err) + fail("sessions", err) } if cfg.AuditMaxAgeDays > 0 { @@ -91,16 +97,21 @@ func Sweep(ctx context.Context, home string, cfg Config) (Report, error) { } n, err := sweepAudit(home, cfg.AuditMaxAgeDays) rep.AuditRemoved = n - fail(err) + fail("audit", err) } + if cfg.RuntimeLogMaxAgeHours > 0 { + n, err := runtimelog.Prune(ctx, filepath.Join(home, "runtime.log"), time.Now().Add(-time.Duration(ClampRetentionHours(cfg.RuntimeLogMaxAgeHours))*time.Hour), false) + rep.RuntimeLogRecordsRemoved = n + fail("runtime_log_retention", err) + } if cfg.LogMaxMB > 0 { if err := ctx.Err(); err != nil { return rep, err } rotated, err := rotateLogs(home, cfg.LogMaxMB) rep.LogsRotated = rotated - fail(err) + fail("log_rotation", err) } if cfg.PlansMaxAgeDays > 0 { @@ -109,7 +120,7 @@ func Sweep(ctx context.Context, home string, cfg Config) (Report, error) { } n, err := sweepPlans(home, cfg.PlansMaxAgeDays) rep.PlansRemoved = n - fail(err) + fail("plans", err) } if cfg.ArtifactsMaxAgeHours > 0 { @@ -119,7 +130,7 @@ func Sweep(ctx context.Context, home string, cfg Config) (Report, error) { n, freed, err := sweepArtifacts(home, time.Duration(cfg.ArtifactsMaxAgeHours)*time.Hour) rep.ArtifactsRemoved = n rep.ArtifactsFreed = freed - fail(err) + fail("artifacts", err) } if err := ctx.Err(); err != nil { @@ -127,7 +138,7 @@ func Sweep(ctx context.Context, home string, cfg Config) (Report, error) { } freed, err := sweepMedia(home) rep.MediaFreedBytes = freed - fail(err) + fail("media", err) return rep, firstErr } @@ -429,7 +440,7 @@ func sweepAudit(home string, maxAgeDays int) (int, error) { // serve.log was once rotated by the real sweep while the preview only knew // about two logs. func LogRotationNames() []string { - return []string{"telegram.log", "schedule.log", "serve.log"} + return []string{"telegram.log", "schedule.log", "serve.log", "runtime.log"} } // rotateLogs rotates each log named by LogRotationNames when it exceeds @@ -444,6 +455,16 @@ func rotateLogs(home string, maxMB int64) ([]string, error) { var rotated []string for _, name := range LogRotationNames() { path := filepath.Join(home, name) + if name == "runtime.log" { + did, err := runtimelog.Rotate(path, limit) + if err != nil { + return rotated, fmt.Errorf("maintenance: rotate runtime.log: %w", err) + } + if did { + rotated = append(rotated, path) + } + continue + } info, err := os.Stat(path) if err != nil { if os.IsNotExist(err) { diff --git a/internal/maintenance/maintenance_test.go b/internal/maintenance/maintenance_test.go index 731de7df..098a9e8a 100644 --- a/internal/maintenance/maintenance_test.go +++ b/internal/maintenance/maintenance_test.go @@ -46,13 +46,14 @@ func writeSessionFixture(t *testing.T, home, id string, updatedAt time.Time) { func TestDefaultConfig(t *testing.T) { cfg := DefaultConfig() want := Config{ - Enabled: true, - IntervalMinutes: 60, - SessionsMaxAgeDays: 30, - AuditMaxAgeDays: 14, - LogMaxMB: 50, - PlansMaxAgeDays: 30, - ArtifactsMaxAgeHours: 24, + RuntimeLogMaxAgeHours: 168, + Enabled: true, + IntervalMinutes: 60, + SessionsMaxAgeDays: 30, + AuditMaxAgeDays: 14, + LogMaxMB: 50, + PlansMaxAgeDays: 30, + ArtifactsMaxAgeHours: 24, } if cfg != want { t.Errorf("DefaultConfig() = %+v, want %+v", cfg, want) diff --git a/internal/maintenance/runtime_logging_test.go b/internal/maintenance/runtime_logging_test.go new file mode 100644 index 00000000..6e4a6143 --- /dev/null +++ b/internal/maintenance/runtime_logging_test.go @@ -0,0 +1,40 @@ +package maintenance + +import ( + "context" + "encoding/json" + "os" + "path/filepath" + "strings" + "testing" + "time" + + "github.com/BackendStack21/odek/internal/events" +) + +func TestSweepRuntimeLogExpiration(t *testing.T) { + home := t.TempDir() + path := filepath.Join(home, "runtime.log") + expired, _ := json.Marshal(events.Event{Type: "run_completed", Timestamp: time.Now().Add(-48 * time.Hour), SessionID: "expired"}) + recent, _ := json.Marshal(events.Event{Type: "run_completed", Timestamp: time.Now(), SessionID: "recent"}) + raw := append(append(append(expired, '\n'), recent...), '\n') + for _, name := range []string{path, path + ".1"} { + if err := os.WriteFile(name, raw, 0600); err != nil { + t.Fatal(err) + } + } + rep, err := Sweep(context.Background(), home, Config{RuntimeLogMaxAgeHours: 0}) + if err != nil || rep.RuntimeLogRecordsRemoved != 0 { + t.Fatalf("zero retention: %+v %v", rep, err) + } + rep, err = Sweep(context.Background(), home, Config{RuntimeLogMaxAgeHours: 24}) + if err != nil || rep.RuntimeLogRecordsRemoved != 2 { + t.Fatalf("sweep: %+v %v", rep, err) + } + for _, name := range []string{path, path + ".1"} { + b, _ := os.ReadFile(name) + if strings.Contains(string(b), "expired") || !strings.Contains(string(b), "recent") { + t.Fatalf("retention: %s", b) + } + } +} diff --git a/internal/mcpclient/client.go b/internal/mcpclient/client.go index eba12da7..c3374975 100644 --- a/internal/mcpclient/client.go +++ b/internal/mcpclient/client.go @@ -42,6 +42,7 @@ import ( "unicode/utf8" "github.com/BackendStack21/odek/internal/artifact" + "github.com/BackendStack21/odek/internal/diagnostics" ) // ── Protocol Constants ────────────────────────────────────────────────── @@ -359,7 +360,8 @@ func validateName(kind, name string) error { // New spawns an MCP server process and returns a client connected to it. // The server process is started immediately and cleaned up on Close(). -func New(name string, cfg ServerConfig) (*Client, error) { +func New(name string, cfg ServerConfig) (_ *Client, setupErr error) { + defer func() { diagnostics.Report("mcp", "connect", "", setupErr) }() if err := validateName("server", name); err != nil { return nil, err } @@ -568,7 +570,8 @@ func (c *Client) Warnings() []string { return append([]string(nil), c.warnings.. func (c *Client) ArtifactRoots() []string { return append([]string(nil), c.artifactRoots...) } // Discover performs the MCP handshake and returns all available tools. -func (c *Client) Discover(ctx context.Context) ([]ToolDef, error) { +func (c *Client) Discover(ctx context.Context) (_ []ToolDef, setupErr error) { + defer func() { diagnostics.Report("mcp", "discover", "", setupErr) }() // Step 1: Initialize if _, err := c.call(ctx, "initialize", json.RawMessage(`{"protocolVersion":"`+ProtocolVersion+`","capabilities":{},"clientInfo":{"name":"odek","version":"dev"}}`)); err != nil { return nil, fmt.Errorf("mcpclient %s: initialize: %w", c.name, err) diff --git a/internal/mcpclient/diagnostics_test.go b/internal/mcpclient/diagnostics_test.go new file mode 100644 index 00000000..f9a3d45f --- /dev/null +++ b/internal/mcpclient/diagnostics_test.go @@ -0,0 +1,21 @@ +package mcpclient + +import ( + "path/filepath" + "testing" + + "github.com/BackendStack21/odek/internal/diagnostics" + "github.com/BackendStack21/odek/internal/events" +) + +func TestStartupFailureDiagnostic(t *testing.T) { + var got []events.Event + restore := diagnostics.Install(func(ev events.Event) { got = append(got, ev) }) + defer restore() + if _, err := New("test", ServerConfig{Command: filepath.Join(t.TempDir(), "missing")}); err == nil { + t.Fatal("missing executable started") + } + if len(got) != 1 || got[0].Data["component"] != "mcp" || got[0].Data["operation"] != "connect" || got[0].Data["error_class"] != "not_found" { + t.Fatalf("missing MCP startup report: %+v", got) + } +} diff --git a/internal/runtimelog/edge_test.go b/internal/runtimelog/edge_test.go new file mode 100644 index 00000000..1e05a94a --- /dev/null +++ b/internal/runtimelog/edge_test.go @@ -0,0 +1,383 @@ +package runtimelog + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "math" + "os" + "path/filepath" + "strings" + "testing" + "time" + + "github.com/BackendStack21/odek/internal/events" + "github.com/BackendStack21/odek/internal/flock" +) + +func TestLogLevelsAndInvalidRecords(t *testing.T) { + path := filepath.Join(t.TempDir(), "runtime.log") + l, err := Open(path, "test", math.MaxInt64) + if err != nil { + t.Fatal(err) + } + if l.maxBytes != math.MaxInt64 { + t.Fatal("rotation size overflowed") + } + cases := []struct{ typ, status, level string }{ + {"operation_failed", "", "ERROR"}, {"operation_warning", "", "WARN"}, {"panic_recovered", "", "ERROR"}, + {"run_started", "", "INFO"}, {"run_failed", "", "ERROR"}, {"llm_call_failed", "", "ERROR"}, + {"subagent_failed", "", "ERROR"}, {"tool_call_failed", "", "WARN"}, {"subagent_denied", "", "WARN"}, + {"budget_warning", "", "WARN"}, {"tool_recovery", "", "WARN"}, {"logging_dropped", "", "WARN"}, + {"subagent_completed", "success", "INFO"}, {"subagent_completed", "completed", "INFO"}, + {"subagent_completed", "partial", "WARN"}, {"subagent_completed", "cancelled", "WARN"}, + {"subagent_completed", "timeout", "ERROR"}, {"subagent_completed", "", "ERROR"}, + } + for _, tc := range cases { + l.Emit(events.Event{Type: tc.typ, Data: map[string]any{"status": tc.status}}) + } + l.Emit(events.Event{Type: "run_completed", Data: map[string]any{"cost_usd": math.NaN()}}) + if l.Dropped() != 1 { + t.Fatal("non-finite JSON record was not rejected") + } + l.Close() + l.Close() + before, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + l.Emit(events.Event{Type: "run_started"}) + after, _ := os.ReadFile(path) + if !bytes.Equal(before, after) { + t.Fatal("Emit after Close changed log") + } + lines := strings.Split(strings.TrimSpace(string(before)), "\n") + if len(lines) != len(cases) { + t.Fatalf("records=%d want=%d", len(lines), len(cases)) + } + for i, line := range lines { + var rec struct{ Type, Level string } + if err := json.Unmarshal([]byte(line), &rec); err != nil { + t.Fatal(err) + } + if rec.Type != cases[i].typ || rec.Level != cases[i].level { + t.Fatalf("record %d: %+v", i, rec) + } + } + // An oversized origin label cannot bypass the per-record byte bound. + oversized := &Logger{queue: make(chan []byte, 1), surface: strings.Repeat("x", maxRecordBytes)} + oversized.Emit(events.Event{Type: "run_started"}) + if oversized.Dropped() != 1 || len(oversized.queue) != 0 { + t.Fatal("oversized record entered queue") + } +} + +func TestSanitizePreservesScalarMetadataOnly(t *testing.T) { + stamp := time.Now().UTC().Truncate(time.Millisecond) + input := events.Event{Type: "run_started", Timestamp: stamp, Tool: strings.Repeat("x", 200), SourceTaskID: "source", RunID: "run", TurnID: "turn", SessionID: "session", RootRunID: "root", ParentRunID: "parent", ParentTurnID: "parent-turn", TaskID: "task", ParentTaskID: "parent-task", Data: map[string]any{ + "model": "model", "pid": int32(10), "depth": int64(2), "count": uint(3), "dropped": uint64(4), "cost_usd": float32(0.5), "duration_ms": float64(12), "iterations": 7, "sandbox": true, + "call_id": []string{"private"}, "profile": map[string]any{"private": "content"}, "input_tokens": "private", "goal": "private", "args_summary": "private", + }} + out, ok := Sanitize(input) + if !ok { + t.Fatal("known event rejected") + } + if len(out.Tool) != 128 || !out.Timestamp.Equal(stamp) || out.SourceTaskID != "source" || out.Schema != events.Schema { + t.Fatalf("envelope damaged: %+v", out) + } + for _, key := range []string{"model", "pid", "depth", "count", "dropped", "cost_usd", "duration_ms", "iterations", "sandbox"} { + if out.Data[key] != input.Data[key] { + t.Fatalf("scalar %s lost", key) + } + } + for _, key := range []string{"call_id", "profile", "input_tokens", "goal", "args_summary"} { + if _, ok := out.Data[key]; ok { + t.Fatalf("unsafe field survived: %s", key) + } + } + out.Data["model"] = "changed" + if input.Data["model"] != "model" { + t.Fatal("sanitizer aliases caller map") + } + out, _ = Sanitize(events.Event{Type: "run_started", Data: map[string]any{"sandbox": "private"}}) + if _, ok := out.Data["sandbox"]; ok { + t.Fatal("nonboolean sandbox retained") + } + key := "sk-" + strings.Repeat("a", 48) + if strings.Contains(short(key), key) { + t.Fatal("identifier secret not redacted") + } +} + +func TestFilesystemRejectionsPreserveTargets(t *testing.T) { + dir := t.TempDir() + file := filepath.Join(dir, "file") + if err := os.WriteFile(file, []byte("keep"), 0600); err != nil { + t.Fatal(err) + } + if _, err := Open(filepath.Join(file, "runtime.log"), "test", 50); err == nil { + t.Fatal("accepted nondirectory parent") + } + if _, err := openPrivate(os.DevNull); err == nil { + t.Fatal("accepted device log") + } + path := filepath.Join(dir, "runtime.log") + if rotated, err := Rotate(path, 0); err != nil || rotated { + t.Fatalf("missing rotation: %v %v", rotated, err) + } + if rotated, err := rotateLocked(path, 0); err != nil || rotated { + t.Fatalf("missing locked rotation: %v %v", rotated, err) + } + if _, err := rotateLocked(filepath.Join(file, "child"), 0); err == nil { + t.Fatal("expected stat error") + } + if err := os.Symlink(file, path); err != nil { + t.Fatal(err) + } + if _, err := Rotate(path, 0); err == nil { + t.Fatal("rotated symlink") + } + l := &Logger{path: path, maxBytes: 1} + if err := l.append([]byte("replace")); err == nil { + t.Fatal("append followed rotating symlink") + } + l.maxBytes = 0 + if err := l.append([]byte("replace")); err == nil { + t.Fatal("append followed symlink") + } + if err := os.Remove(path); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(path, []byte("original"), 0600); err != nil { + t.Fatal(err) + } + if err := os.Mkdir(path+".1", 0700); err != nil { + t.Fatal(err) + } + if _, err := Rotate(path, 0); err == nil { + t.Fatal("rotation replaced backup directory") + } + b, _ := os.ReadFile(path) + if string(b) != "original" { + t.Fatal("failed rotation damaged current log") + } + if err := os.Remove(path + ".lock"); err != nil { + t.Fatal(err) + } + if err := os.Symlink(file, path+".lock"); err != nil { + t.Fatal(err) + } + if _, err := Rotate(path, 0); err == nil { + t.Fatal("accepted symlink lock") + } + b, _ = os.ReadFile(file) + if string(b) != "keep" { + t.Fatal("modified protected target") + } +} + +func TestRotationKeepsExactlyOneBackupAndReopens(t *testing.T) { + path := filepath.Join(t.TempDir(), "runtime.log") + l, err := Open(path, "test", 0) + if err != nil { + t.Fatal(err) + } + // Exercise synchronous writer batches deterministically, with its real lock. + if err := l.append([]byte("first\n")); err != nil { + t.Fatal(err) + } + if changed, err := Rotate(path, 1); err != nil || !changed { + t.Fatalf("first rotation: %v %v", changed, err) + } + if err := l.append([]byte("second\n")); err != nil { + t.Fatal(err) + } + if changed, err := Rotate(path, 1); err != nil || !changed { + t.Fatalf("second rotation: %v %v", changed, err) + } + if err := l.append([]byte("third\n")); err != nil { + t.Fatal(err) + } + l.Close() + current, _ := os.ReadFile(path) + backup, _ := os.ReadFile(path + ".1") + if string(current) != "third\n" || string(backup) != "second\n" { + t.Fatalf("stale descriptor or wrong backup: %q %q", current, backup) + } + if _, err := os.Stat(path + ".2"); !os.IsNotExist(err) { + t.Fatal("unexpected second backup") + } +} + +func TestShutdownAbortsPersistentContention(t *testing.T) { + entered := make(chan struct{}, 1) + l := &Logger{queue: make(chan []byte, 2), done: make(chan struct{}), abort: make(chan struct{})} + l.write = func([]byte) error { + select { + case entered <- struct{}{}: + default: + } + return flock.ErrLocked + } + go l.run() + l.Emit(events.Event{Type: "run_started"}) + <-entered + l.Close() + select { + case <-l.done: + case <-time.After(time.Second): + t.Fatal("contended writer leaked after shutdown") + } + if l.failures.Load() != 1 { + t.Fatal("abandoned batch not reported") + } +} + +func TestIdleWriterReportsLossWithoutClosing(t *testing.T) { + dir := t.TempDir() + stderr, err := os.Create(filepath.Join(dir, "stderr")) + if err != nil { + t.Fatal(err) + } + previous := os.Stderr + os.Stderr = stderr + t.Cleanup(func() { os.Stderr = previous; _ = stderr.Close() }) + l, err := Open(filepath.Join(dir, "runtime.log"), "test", 0) + if err != nil { + t.Fatal(err) + } + l.Emit(events.Event{Type: "run_completed", Data: map[string]any{"cost_usd": math.Inf(1)}}) + t.Cleanup(l.Close) + deadline := time.Now().Add(3 * time.Second) + for { + b, err := os.ReadFile(stderr.Name()) + if err != nil { + t.Fatal(err) + } + if strings.Contains(string(b), "dropped=1") { + break + } + if time.Now().After(deadline) { + l.Close() + t.Fatal("no periodic loss diagnostic") + } + time.Sleep(10 * time.Millisecond) + } + l.Close() +} + +func TestRetentionMissingAndBackupOnly(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "runtime.log") + for _, p := range []string{filepath.Join(dir, "missing", "runtime.log"), path} { + if n, err := Prune(t.Context(), p, time.Now(), false); err != nil || n != 0 { + t.Fatalf("missing path: %d %v", n, err) + } + } + if _, err := os.Stat(path + ".lock"); !os.IsNotExist(err) { + t.Fatal("empty retention created lock") + } + b, _ := json.Marshal(events.Event{Type: "run_completed", Timestamp: time.Now().Add(-time.Hour)}) + if err := os.WriteFile(path+".1", append(b, '\n'), 0600); err != nil { + t.Fatal(err) + } + if n, err := Prune(t.Context(), path, time.Now(), false); err != nil || n != 1 { + t.Fatalf("backup-only retention: %d %v", n, err) + } + if _, err := os.Stat(path); !os.IsNotExist(err) { + t.Fatal("backup cleanup created current log") + } +} + +func TestRetentionUnsafeTargetsAndCancellation(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "runtime.log") + original := []byte(`{"timestamp":"2020-01-01T00:00:00Z"}` + "\n") + if err := os.WriteFile(path, original, 0600); err != nil { + t.Fatal(err) + } + ctx, cancel := context.WithCancel(t.Context()) + cancel() + if _, err := Prune(ctx, path, time.Now(), false); !errors.Is(err, context.Canceled) { + t.Fatalf("cancel: %v", err) + } + b, _ := os.ReadFile(path) + if !bytes.Equal(b, original) { + t.Fatal("cancelled pruning committed changes") + } + matches, _ := filepath.Glob(filepath.Join(dir, ".runtime-prune-*")) + if len(matches) != 0 { + t.Fatal("cancel left temporary files") + } + if err := os.Symlink(path, path+".1"); err != nil { + t.Fatal(err) + } + if n, err := Prune(t.Context(), path, time.Now(), false); err == nil || n != 1 { + t.Fatalf("expected partial commit before rejecting backup: n=%d err=%v", n, err) + } + b, _ = os.ReadFile(path) + if len(b) != 0 { + t.Fatal("successful first replacement rolled back") + } + if _, err := pruneFile(t.Context(), dir, time.Now(), true); err == nil { + t.Fatal("accepted directory input") + } + if err := os.Remove(path + ".lock"); err != nil { + t.Fatal(err) + } + if err := os.Symlink(path, path+".lock"); err != nil { + t.Fatal(err) + } + if _, err := Prune(t.Context(), path, time.Now(), false); err == nil { + t.Fatal("accepted symlink lock") + } +} + +func TestRetentionPreservesBoundaryFutureAndUndated(t *testing.T) { + path := filepath.Join(t.TempDir(), "runtime.log") + cutoff := time.Now().UTC().Truncate(time.Second) + var lines []string + for _, stamp := range []time.Time{cutoff.Add(-time.Nanosecond), cutoff, cutoff.Add(time.Hour)} { + b, _ := json.Marshal(events.Event{Timestamp: stamp}) + lines = append(lines, string(b)) + } + lines = append(lines, `{"timestamp":"bad"}`, `{"type":"undated"}`, `{"timestamp":"0001-01-01T00:00:00Z"}`) + if err := os.WriteFile(path, []byte(strings.Join(lines, "\n")+"\n"), 0600); err != nil { + t.Fatal(err) + } + if n, err := Prune(t.Context(), path, cutoff, false); err != nil || n != 1 { + t.Fatalf("strict cutoff: %d %v", n, err) + } + b, _ := os.ReadFile(path) + if string(b) != strings.Join(lines[1:], "\n")+"\n" { + t.Fatal("retention removed ineligible records") + } +} + +func TestRetentionTempCreationFailurePreservesOriginal(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "runtime.log") + raw := []byte(`{"timestamp":"2020-01-01T00:00:00Z"}` + "\n") + if err := os.WriteFile(path, raw, 0600); err != nil { + t.Fatal(err) + } + if err := os.Chmod(dir, 0500); err != nil { + t.Fatal(err) + } + defer os.Chmod(dir, 0700) + probe, err := os.CreateTemp(dir, "permission-probe-*") + if err == nil { + _ = probe.Close() + _ = os.Remove(probe.Name()) + t.Skip("filesystem or user bypasses directory write permissions") + } + // This direct helper invocation isolates temp creation from lock creation. + if n, err := pruneFile(t.Context(), path, time.Now(), false); err == nil || n != 0 { + t.Fatalf("temp creation unexpectedly succeeded: n=%d err=%v", n, err) + } + b, _ := os.ReadFile(path) + if !bytes.Equal(b, raw) { + t.Fatal("failed temp creation changed input") + } +} diff --git a/internal/runtimelog/log.go b/internal/runtimelog/log.go new file mode 100644 index 00000000..38605ca6 --- /dev/null +++ b/internal/runtimelog/log.go @@ -0,0 +1,345 @@ +// Package runtimelog writes bounded, metadata-only operational logs. Producers +// never wait for disk I/O; every cooperating writer and rotator uses one lock. +package runtimelog + +import ( + "encoding/json" + "errors" + "fmt" + "math" + "os" + "path/filepath" + "sync" + "sync/atomic" + "syscall" + "time" + + "github.com/BackendStack21/odek/internal/events" + "github.com/BackendStack21/odek/internal/flock" + "github.com/BackendStack21/odek/internal/redact" +) + +var processID = events.NewRunID() + +const queueSize = 1024 +const maxRecordBytes = 8192 + +// Logger owns a bounded queue and a background writer. Close is bounded even +// when a filesystem stops responding. Records are best effort, not an audit WAL. +type Logger struct { + path string + maxBytes int64 + surface string + mu sync.Mutex + closed bool + queue chan []byte + done chan struct{} + dropped atomic.Uint64 + failures atomic.Uint64 + abort chan struct{} + abortOnce sync.Once + write func([]byte) error +} + +func Open(path, surface string, maxMB int64) (*Logger, error) { + if err := os.MkdirAll(filepath.Dir(path), 0700); err != nil { + return nil, err + } + // Validate before accepting work, even if no event is ever emitted. + f, err := openPrivate(path) + if err != nil { + return nil, err + } + if err := f.Close(); err != nil { + return nil, err + } + l := &Logger{path: path, surface: surface, queue: make(chan []byte, queueSize), done: make(chan struct{}), abort: make(chan struct{})} + if maxMB > 0 { + l.maxBytes = math.MaxInt64 + if maxMB <= math.MaxInt64/(1<<20) { + l.maxBytes = maxMB << 20 + } + } + l.write = l.append + go l.run() + return l, nil +} + +func openPrivate(path string) (*os.File, error) { + f, err := os.OpenFile(path, os.O_CREATE|os.O_APPEND|os.O_WRONLY|syscall.O_NOFOLLOW|syscall.O_NONBLOCK, 0600) + if err != nil { + return nil, err + } + st, err := f.Stat() + if err == nil && !st.Mode().IsRegular() { + err = fmt.Errorf("runtime log must be a regular file") + } + if err == nil { + err = f.Chmod(0600) + } + if err != nil { + _ = f.Close() + return nil, err + } + return f, nil +} + +// lock bounds lock contention and rejects symlinks using the same hardened +// opener as the log. flock then locks that stable, private sidecar inode. +func lock(path string) (func(), error) { + f, err := openPrivate(path + ".lock") + if err != nil { + return nil, err + } + deadline := time.Now().Add(250 * time.Millisecond) + for { + release, err := flock.TryLockFile(f) + if err == nil { + return func() { release(); _ = f.Close() }, nil + } + if !errors.Is(err, flock.ErrLocked) { + _ = f.Close() + return nil, err + } + if time.Now().After(deadline) { + _ = f.Close() + return nil, err + } + time.Sleep(5 * time.Millisecond) + } +} + +func (l *Logger) append(b []byte) error { + release, err := lock(l.path) + if err != nil { + return err + } + defer release() + if l.maxBytes > 0 { + if _, err := rotateLocked(l.path, l.maxBytes); err != nil { + return err + } + } + f, err := openPrivate(l.path) + if err != nil { + return err + } + _, err = f.Write(b) + closeErr := f.Close() + if err != nil { + return err + } + return closeErr +} + +// Rotate participates in the writers' sidecar-lock protocol. It is also used +// by the maintenance janitor; the caller supplies a byte limit. +func Rotate(path string, maxBytes int64) (bool, error) { + if _, err := os.Lstat(path); os.IsNotExist(err) { + return false, nil + } + release, err := lock(path) + if err != nil { + return false, err + } + defer release() + return rotateLocked(path, maxBytes) +} +func rotateLocked(path string, maxBytes int64) (bool, error) { + st, err := os.Lstat(path) + if os.IsNotExist(err) { + return false, nil + } + if err != nil { + return false, err + } + if !st.Mode().IsRegular() { + return false, fmt.Errorf("runtime log must be a regular file") + } + if st.Size() <= maxBytes { + return false, nil + } + if err := os.Rename(path, path+".1"); err != nil { + return false, err + } + f, err := openPrivate(path) + if err != nil { + return false, err + } + return true, f.Close() +} + +// Emit applies a field allowlist regardless of other event sinks' argument +// settings. Neither redaction nor truncation is a substitute for this boundary. +func (l *Logger) Emit(ev events.Event) { + ev, ok := Sanitize(ev) + if !ok { + return + } + level := "INFO" + switch ev.Type { + case "run_failed", "subagent_failed", "llm_call_failed", "operation_failed", "panic_recovered": + level = "ERROR" + case "operation_warning", "tool_call_failed", "subagent_denied", "budget_exceeded", "budget_warning", "tool_recovery", "logging_dropped": + level = "WARN" + } + if ev.Type == "subagent_completed" { + status, _ := ev.Data["status"].(string) + switch status { + case "success", "completed": + case "partial", "cancelled": + level = "WARN" + default: + level = "ERROR" + } + } + record := struct { + events.Event + Level string `json:"level"` + Surface string `json:"surface,omitempty"` + ProcessID string `json:"process_id"` + PID int `json:"pid"` + }{ev, level, l.surface, processID, os.Getpid()} + b, err := json.Marshal(record) + if err != nil || len(b) > maxRecordBytes { + l.dropped.Add(1) + return + } + b = append(b, '\n') + l.mu.Lock() + defer l.mu.Unlock() + if l.closed { + return + } + select { + case l.queue <- b: + default: + l.dropped.Add(1) + } +} + +func (l *Logger) run() { + defer close(l.done) + ticker := time.NewTicker(time.Second) + defer ticker.Stop() + var reportedDrops, reportedFailures uint64 + report := func() { + drops, failures := l.dropped.Load(), l.failures.Load() + if drops != reportedDrops || failures != reportedFailures { + // Fixed diagnostics: never print filesystem errors or producer content. + fmt.Fprintf(os.Stderr, "odek: runtime logging lost records: dropped=%d write_failures=%d\n", drops, failures) + reportedDrops, reportedFailures = drops, failures + } + } + defer report() + for { + select { + case b, ok := <-l.queue: + if !ok { + return + } + batch := append([]byte(nil), b...) + for i := 0; i < 63; i++ { + select { + case next, ok := <-l.queue: + if ok { + batch = append(batch, next...) + } + default: + i = 63 + } + } + for { + err := l.write(batch) + if errors.Is(err, flock.ErrLocked) { + select { + case <-l.abort: + l.failures.Add(1) + return + case <-time.After(10 * time.Millisecond): + continue + } + } + if err != nil { + l.failures.Add(1) + } + break + } + case <-ticker.C: + report() + } + } +} + +func (l *Logger) Dropped() uint64 { return l.dropped.Load() } +func (l *Logger) Close() { + l.mu.Lock() + if !l.closed { + l.closed = true + close(l.queue) + } + l.mu.Unlock() + select { + case <-l.done: + case <-time.After(2 * time.Second): + l.abortOnce.Do(func() { close(l.abort) }) + fmt.Fprintln(os.Stderr, "odek: runtime logging shutdown timed out; records may be lost") + } +} + +var allowedTypes = map[string]bool{} + +func init() { + for _, s := range []string{"operation_failed", "operation_warning", "panic_recovered", "run_started", "turn_started", "run_completed", "run_failed", "iteration_completed", "tool_call_started", "tool_call_executing", "tool_execution_completed", "tool_call_completed", "tool_call_failed", "llm_call_started", "llm_call_completed", "llm_call_failed", "session_saved", "context_trimmed", "budget_exceeded", "budget_warning", "tool_recovery", "subagent_slot_acquired", "subagent_queued", "subagent_spawned", "subagent_completed", "subagent_failed", "subagent_running", "subagent_denied", "subagent_concurrency_wait", "subagent_started", "side_call_usage", "logging_dropped"} { + allowedTypes[s] = true + } +} + +// Sanitize returns a fresh metadata-only event, also suitable for child IPC. +// Unknown event types and non-scalar values are rejected, never serialized. +func Sanitize(ev events.Event) (events.Event, bool) { + if !allowedTypes[ev.Type] { + return events.Event{}, false + } + ev.Schema = events.Schema + if ev.Timestamp.IsZero() { + ev.Timestamp = time.Now().UTC() + } + ev.Tool = short(ev.Tool) + ev.RunID = short(ev.RunID) + ev.SessionID = short(ev.SessionID) + ev.TurnID = short(ev.TurnID) + ev.RootRunID = short(ev.RootRunID) + ev.ParentRunID = short(ev.ParentRunID) + ev.TaskID = short(ev.TaskID) + ev.ParentTaskID = short(ev.ParentTaskID) + ev.ParentTurnID = short(ev.ParentTurnID) + ev.SourceTaskID = short(ev.SourceTaskID) + data := make(map[string]any) + for k, v := range ev.Data { + switch k { + case "component", "operation", "error_type", "call_id", "model", "profile", "max_risk", "status", "exit_status", "error_class", "class", "activity", "limit_name", "kind", "mode", "task_id": + if s, ok := v.(string); ok { + data[k] = short(s) + } + case "http_status", "count", "threshold_percent", "pid", "depth", "timeout_seconds", "max_iterations", "iterations", "duration_ms", "duration_seconds", "elapsed_seconds", "last_event_age_seconds", "active_calls", "pending_calls", "tokens_used", "input_tokens", "output_tokens", "cost_usd", "artifact_count", "result_bytes", "task_index", "waited_ms", "tools_called", "call_duration_ms", "ttft_ms", "generation_ms", "call_input_tokens", "call_output_tokens", "cache_read", "cache_create", "budget_seconds", "budget_iterations", "budget_cost_usd", "exit_code", "stderr_bytes", "message_count", "dropped_groups", "truncated_results", "observed", "limit", "dropped", "queue_wait_ms": + switch v.(type) { + case int, int32, int64, uint, uint64, float64, float32: + data[k] = v + } + case "sandbox": + if b, ok := v.(bool); ok { + data[k] = b + } + } + } + ev.Data = data + return ev, true +} +func short(s string) string { + s = redact.RedactSecrets(s) + if len(s) > 128 { + s = s[:128] + } + return s +} diff --git a/internal/runtimelog/log_test.go b/internal/runtimelog/log_test.go new file mode 100644 index 00000000..9a93c724 --- /dev/null +++ b/internal/runtimelog/log_test.go @@ -0,0 +1,276 @@ +package runtimelog + +import ( + "bufio" + "context" + "encoding/json" + "errors" + "fmt" + "os" + "os/exec" + "path/filepath" + "strings" + "sync" + "testing" + "time" + + "github.com/BackendStack21/odek/internal/events" + "github.com/BackendStack21/odek/internal/flock" +) + +func records(t *testing.T, path string) []events.Event { + t.Helper() + b, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + var out []events.Event + scanner := bufio.NewScanner(strings.NewReader(string(b))) + for scanner.Scan() { + var ev events.Event + if err := json.Unmarshal(scanner.Bytes(), &ev); err != nil { + t.Fatal(err) + } + out = append(out, ev) + } + if err := scanner.Err(); err != nil { + t.Fatal(err) + } + return out +} +func TestMetadataBoundary(t *testing.T) { + path := filepath.Join(t.TempDir(), "runtime.log") + l, err := Open(path, "test", 50) + if err != nil { + t.Fatal(err) + } + l.Emit(events.Event{Type: "tool_call_started", SessionID: "session-1", TaskID: "child", Data: map[string]any{ + "call_id": "call-1", "args": "private arguments", "args_summary": map[string]any{"path": "private path"}, "goal": "private goal", "result": "private result", "reason": "private denial", "duration_ms": map[string]any{"secret": "nested"}, + }}) + l.Emit(events.Event{Type: "unknown", Data: map[string]any{"model": "private unknown"}}) + l.Close() + b, _ := os.ReadFile(path) + if strings.Contains(string(b), "private") || strings.Contains(string(b), "nested") { + t.Fatalf("content leaked: %s", b) + } + evs := records(t, path) + if len(evs) != 1 || evs[0].SessionID != "session-1" || evs[0].TaskID != "child" { + t.Fatalf("records: %+v", evs) + } + st, _ := os.Stat(path) + if st.Mode().Perm() != 0600 { + t.Fatal(st.Mode()) + } +} +func TestSlowSinkDoesNotBlockProducerAndReportsDrops(t *testing.T) { + entered, release := make(chan struct{}), make(chan struct{}) + l := &Logger{queue: make(chan []byte, 2), done: make(chan struct{}), abort: make(chan struct{})} + var once sync.Once + l.write = func([]byte) error { once.Do(func() { close(entered) }); <-release; return nil } + go l.run() + l.Emit(events.Event{Type: "run_started"}) + <-entered + done := make(chan struct{}) + go func() { + for i := 0; i < 100; i++ { + l.Emit(events.Event{Type: "run_started"}) + } + close(done) + }() + select { + case <-done: + case <-time.After(time.Second): + t.Fatal("producer blocked") + } + if l.Dropped() == 0 { + t.Fatal("expected loss accounting") + } + close(release) + l.Close() +} +func TestContentionRetainsBatch(t *testing.T) { + path := filepath.Join(t.TempDir(), "runtime.log") + l, err := Open(path, "test", 50) + if err != nil { + t.Fatal(err) + } + release, err := lock(path) + if err != nil { + t.Fatal(err) + } + l.Emit(events.Event{Type: "run_completed", SessionID: "retained"}) + time.Sleep(350 * time.Millisecond) // exceed one lock attempt, as a janitor scan can + release() + l.Close() + if l.failures.Load() != 0 || len(records(t, path)) != 1 { + t.Fatal("ordinary lock contention lost the batch") + } +} +func TestSymlinksRejected(t *testing.T) { + dir := t.TempDir() + victim := filepath.Join(dir, "victim") + _ = os.WriteFile(victim, []byte("keep"), 0600) + path := filepath.Join(dir, "runtime.log") + _ = os.Symlink(victim, path) + if l, err := Open(path, "test", 50); err == nil { + l.Close() + t.Fatal("accepted log symlink") + } + _ = os.Remove(path) + _ = os.Symlink(victim, path+".lock") + if _, err := lock(path); err == nil { + t.Fatal("accepted lock symlink") + } + b, _ := os.ReadFile(victim) + if string(b) != "keep" { + t.Fatal("modified symlink target") + } +} +func TestPruneRetentionAndPreview(t *testing.T) { + path := filepath.Join(t.TempDir(), "runtime.log") + old := time.Now().Add(-48 * time.Hour) + recent := time.Now() + write := func(name string) { + a, _ := json.Marshal(events.Event{Type: "run_started", Timestamp: old, SessionID: "expired"}) + b, _ := json.Marshal(events.Event{Type: "run_started", Timestamp: recent, SessionID: "keep"}) + if err := os.WriteFile(name, []byte(string(a)+"\n"+string(b)+"\n{malformed}\n"), 0600); err != nil { + t.Fatal(err) + } + } + write(path) + write(path + ".1") + before, _ := os.ReadFile(path) + cutoff := time.Now().Add(-24 * time.Hour) + if n, err := Prune(context.Background(), path, cutoff, true); err != nil || n != 2 { + t.Fatalf("preview %d %v", n, err) + } + after, _ := os.ReadFile(path) + if string(before) != string(after) { + t.Fatal("preview mutated log") + } + if _, err := os.Stat(path + ".lock"); !os.IsNotExist(err) { + t.Fatal("preview created lock") + } + if n, err := Prune(context.Background(), path, cutoff, false); err != nil || n != 2 { + t.Fatalf("prune %d %v", n, err) + } + for _, name := range []string{path, path + ".1"} { + b, _ := os.ReadFile(name) + if strings.Contains(string(b), "expired") || !strings.Contains(string(b), "keep") || !strings.Contains(string(b), "malformed") { + t.Fatalf("unexpected retention: %s", b) + } + } +} +func TestPruneFailurePreservesOriginal(t *testing.T) { + path := filepath.Join(t.TempDir(), "runtime.log") + raw := strings.Repeat("x", 2<<20) + _ = os.WriteFile(path, []byte(raw), 0600) + if _, err := Prune(context.Background(), path, time.Now(), false); err == nil { + t.Fatal("expected oversized record failure") + } + b, _ := os.ReadFile(path) + if string(b) != raw { + t.Fatal("scan failure replaced log") + } +} + +// This test invokes a second copy of the test executable to exercise kernel +// locking between processes, rather than relying on an in-process mutex. +func TestMultiprocessWriter(t *testing.T) { + if path := os.Getenv("ODEK_RUNTIME_LOG_TEST_PATH"); path != "" { + l, err := Open(path, "helper", 0) + if err != nil { + t.Fatal(err) + } + for i := 0; i < 150; i++ { + l.Emit(events.Event{Type: "run_completed", SessionID: fmt.Sprintf("pid-%d-%d", os.Getpid(), i)}) + } + l.Close() + if l.failures.Load() != 0 || l.Dropped() != 0 { + t.Fatal("helper lost records") + } + return + } + path := filepath.Join(t.TempDir(), "runtime.log") + var cmds []*exec.Cmd + for i := 0; i < 3; i++ { + cmd := exec.Command(os.Args[0], "-test.run=^TestMultiprocessWriter$") + cmd.Env = append(os.Environ(), "ODEK_RUNTIME_LOG_TEST_PATH="+path) + if err := cmd.Start(); err != nil { + t.Fatal(err) + } + cmds = append(cmds, cmd) + } + for _, cmd := range cmds { + if err := cmd.Wait(); err != nil { + t.Fatal(err) + } + } + if n := len(records(t, path)); n != 450 { + t.Fatalf("records=%d", n) + } +} +func TestConcurrentRotationPruningAndAppend(t *testing.T) { + path := filepath.Join(t.TempDir(), "runtime.log") + l, err := Open(path, "test", 0) + if err != nil { + t.Fatal(err) + } + var wg sync.WaitGroup + wg.Add(1) + go func() { + defer wg.Done() + for i := 0; i < 100; i++ { + l.Emit(events.Event{Type: "run_completed", SessionID: fmt.Sprintf("session-%d", i)}) + } + }() + // One rotation preserves all records across current + backup; repeated + // rotations intentionally evict older backups and cannot promise completeness. + _, err = Rotate(path, 0) + if err != nil && !errors.Is(err, flock.ErrLocked) { + t.Fatal(err) + } + for i := 0; i < 3; i++ { + if _, err := Prune(context.Background(), path, time.Now().Add(-time.Hour), false); err != nil { + t.Fatal(err) + } + } + wg.Wait() + l.Close() + all := records(t, path) + if _, err := os.Stat(path + ".1"); err == nil { + all = append(all, records(t, path+".1")...) + } + if len(all) != 100 { + t.Fatalf("retention/rotation lost appends: %d", len(all)) + } +} + +func TestShutdownBoundedDuringBlockedSink(t *testing.T) { + entered, release := make(chan struct{}), make(chan struct{}) + l := &Logger{queue: make(chan []byte, 2), done: make(chan struct{}), abort: make(chan struct{})} + l.write = func([]byte) error { close(entered); <-release; return nil } + go l.run() + l.Emit(events.Event{Type: "run_started"}) + <-entered + start := time.Now() + l.Close() + if time.Since(start) > 3*time.Second { + t.Fatal("shutdown waited indefinitely") + } + close(release) + select { + case <-l.done: + case <-time.After(time.Second): + t.Fatal("worker did not drain") + } +} +func TestWriteFailureReported(t *testing.T) { + l := &Logger{queue: make(chan []byte, 2), done: make(chan struct{}), abort: make(chan struct{}), write: func([]byte) error { return errors.New("disk failure with private data") }} + go l.run() + l.Emit(events.Event{Type: "run_started"}) + l.Close() + if l.failures.Load() != 1 { + t.Fatal("write failure not counted") + } +} diff --git a/internal/runtimelog/retention.go b/internal/runtimelog/retention.go new file mode 100644 index 00000000..5d6949cc --- /dev/null +++ b/internal/runtimelog/retention.go @@ -0,0 +1,103 @@ +package runtimelog + +import ( + "bufio" + "context" + "encoding/json" + "fmt" + "os" + "path/filepath" + "syscall" + "time" +) + +// Prune removes timestamp-expired records from the current log and backup. +// Each replacement is atomic under the writers' lock. Malformed/undated records +// are retained; a scan error leaves the original file intact. Preview is read-only. +func Prune(ctx context.Context, path string, cutoff time.Time, preview bool) (int, error) { + if _, err := os.Lstat(filepath.Dir(path)); os.IsNotExist(err) { + return 0, nil + } + if _, err := os.Lstat(path); os.IsNotExist(err) { + if _, err := os.Lstat(path + ".1"); os.IsNotExist(err) { + return 0, nil + } + } + if !preview { + release, err := lock(path) + if err != nil { + return 0, err + } + defer release() + } + total := 0 + for _, name := range []string{path, path + ".1"} { + n, err := pruneFile(ctx, name, cutoff, preview) + total += n + if err != nil { + return total, err + } + } + return total, nil +} +func pruneFile(ctx context.Context, path string, cutoff time.Time, preview bool) (int, error) { + f, err := os.OpenFile(path, os.O_RDONLY|syscall.O_NOFOLLOW|syscall.O_NONBLOCK, 0) + if os.IsNotExist(err) { + return 0, nil + } + if err != nil { + return 0, err + } + defer f.Close() + st, err := f.Stat() + if err != nil { + return 0, err + } + if !st.Mode().IsRegular() { + return 0, fmt.Errorf("runtime log must be a regular file") + } + var tmp *os.File + if !preview { + tmp, err = os.CreateTemp(filepath.Dir(path), ".runtime-prune-*") + if err != nil { + return 0, err + } + defer func() { _ = tmp.Close(); _ = os.Remove(tmp.Name()) }() + } + removed := 0 + scanner := bufio.NewScanner(f) + scanner.Buffer(make([]byte, 64<<10), 1<<20) + for scanner.Scan() { + if err := ctx.Err(); err != nil { + return 0, err + } + line := scanner.Bytes() + var rec struct { + Timestamp time.Time `json:"timestamp"` + } + if json.Unmarshal(line, &rec) == nil && !rec.Timestamp.IsZero() && rec.Timestamp.Before(cutoff) { + removed++ + continue + } + if tmp != nil { + if _, err := tmp.Write(append(line, '\n')); err != nil { + return 0, err + } + } + } + if err := scanner.Err(); err != nil { + return 0, err + } + if tmp != nil && removed > 0 { + if err := tmp.Sync(); err != nil { + return 0, err + } + if err := tmp.Close(); err != nil { + return 0, err + } + if err := os.Rename(tmp.Name(), path); err != nil { + return 0, err + } + } + return removed, nil +} diff --git a/internal/schedule/scheduler.go b/internal/schedule/scheduler.go index 7dcca88f..bb940b05 100644 --- a/internal/schedule/scheduler.go +++ b/internal/schedule/scheduler.go @@ -4,6 +4,8 @@ import ( "context" "sync" "time" + + "github.com/BackendStack21/odek/internal/diagnostics" ) // Runner executes one scheduled job's task and returns the agent's final text, @@ -397,11 +399,13 @@ func (s *Scheduler) execute(ctx context.Context, job Job, firedAt time.Time) { case err != nil: st.LastStatus = StatusError st.LastError = err.Error() + diagnostics.Report("schedule", "run_job", "", err) s.log.Error("scheduler: job run failed", "id", job.ID, "name", job.Name, "error", err) default: if derr := s.deliverer.Deliver(runCtx, job, result); derr != nil { st.LastStatus = StatusError st.LastError = "delivery: " + derr.Error() + diagnostics.Report("schedule", "delivery", "", derr) s.log.Error("scheduler: delivery failed", "id", job.ID, "name", job.Name, "error", derr) } else { st.LastStatus = StatusOK diff --git a/internal/schedule/store.go b/internal/schedule/store.go index 87a4342f..ba8d2db2 100644 --- a/internal/schedule/store.go +++ b/internal/schedule/store.go @@ -13,6 +13,7 @@ import ( "syscall" "time" + "github.com/BackendStack21/odek/internal/diagnostics" "github.com/BackendStack21/odek/internal/fsatomic" ) @@ -363,7 +364,8 @@ func (s *Store) saveState(sd *stateDoc) error { // its zero/default value so callers start from an empty document. Files larger // than maxScheduleFileBytes are rejected to prevent OOM from a tampered or // corrupted multi-gigabyte blob. -func readJSON(path string, v any) error { +func readJSON(path string, v any) (readErr error) { + defer func() { diagnostics.Report("schedule", "read_store", "", readErr) }() fd, err := os.OpenFile(path, os.O_RDONLY|syscall.O_NOFOLLOW|syscall.O_NONBLOCK, 0) if err != nil { if os.IsNotExist(err) { @@ -406,7 +408,8 @@ func readJSON(path string, v any) error { // The actual atomic write is delegated to internal/fsatomic, which uses a // random temp name with O_EXCL (so a pre-created symlink cannot be opened) // and fsyncs both the data and the parent directory before returning. -func writeJSONAtomic(path string, v any) error { +func writeJSONAtomic(path string, v any) (writeErr error) { + defer func() { diagnostics.Report("schedule", "write_store", "", writeErr) }() data, err := json.MarshalIndent(v, "", " ") if err != nil { return fmt.Errorf("schedule: marshal %s: %w", filepath.Base(path), err) diff --git a/internal/session/audit.go b/internal/session/audit.go index 09bb6443..8c7b86be 100644 --- a/internal/session/audit.go +++ b/internal/session/audit.go @@ -25,6 +25,7 @@ import ( "sync" "time" + "github.com/BackendStack21/odek/internal/diagnostics" "github.com/BackendStack21/odek/internal/fsatomic" ) @@ -167,7 +168,8 @@ func (s *AuditStore) loadLocked(sessionID string) (AuditLog, error) { return log, nil } -func (s *AuditStore) saveLocked(sessionID string, log AuditLog) error { +func (s *AuditStore) saveLocked(sessionID string, log AuditLog) (saveErr error) { + defer func() { diagnostics.Report("audit", "save", sessionID, saveErr) }() if err := os.MkdirAll(s.dir, 0700); err != nil { return err } diff --git a/internal/session/session.go b/internal/session/session.go index d465ee55..6c9cc45a 100644 --- a/internal/session/session.go +++ b/internal/session/session.go @@ -33,6 +33,7 @@ import ( "unicode" "github.com/BackendStack21/odek/internal/artifact" + "github.com/BackendStack21/odek/internal/diagnostics" "github.com/BackendStack21/odek/internal/embedding" "github.com/BackendStack21/odek/internal/flock" "github.com/BackendStack21/odek/internal/fsatomic" @@ -520,6 +521,7 @@ func (s *Store) addToVectorIndex(sess *Session) error { return nil } if err := s.Vec.Add(sess.ID, sess.Messages); err != nil { + diagnostics.Report("session", "vector_index", sess.ID, err) return fmt.Errorf("session: vector index add: %w", err) } return nil @@ -540,6 +542,7 @@ func redactMessageFP(m Message) string { } func (s *Store) saveLocked(sess *Session) (err error) { + defer func() { diagnostics.Report("session", "save", sess.ID, err) }() // Reject malformed or traversal-bearing session IDs before the ID is used // to build a filesystem path. A planted session file with an embedded // "id":"../config" must not cause a subsequent Save/Append to overwrite @@ -802,7 +805,12 @@ func (s *Store) trimToFileCapLocked(sess *Session, data []byte) ([]byte, error) // Load reads a session from disk by ID. Returns an error if the file // doesn't exist or can't be parsed. -func (s *Store) Load(id string) (*Session, error) { +func (s *Store) Load(id string) (_ *Session, loadErr error) { + defer func() { + if ValidateSessionID(id) == nil && !os.IsNotExist(loadErr) { + diagnostics.Report("session", "load", id, loadErr) + } + }() if err := ValidateSessionID(id); err != nil { return nil, err } diff --git a/internal/telegram/bot.go b/internal/telegram/bot.go index 38ef4ed9..117fb37f 100644 --- a/internal/telegram/bot.go +++ b/internal/telegram/bot.go @@ -16,6 +16,7 @@ import ( "sync" "time" + "github.com/BackendStack21/odek/internal/diagnostics" "github.com/BackendStack21/odek/internal/flock" "github.com/BackendStack21/odek/internal/transport" ) @@ -84,7 +85,8 @@ func (b *Bot) url(method string) string { // doJSONContext is like doJSON but respects context cancellation. // It uses context-aware HTTP requests and checks context.Done() during retry backoff. -func (b *Bot) doJSONContext(ctx context.Context, method string, body any, dest any) error { +func (b *Bot) doJSONContext(ctx context.Context, method string, body any, dest any) (requestErr error) { + defer func() { reportAPIFailure("api_request", requestErr) }() var reqBody []byte if body != nil { var err error @@ -191,7 +193,8 @@ func (b *Bot) StopRetries() { // Retries on transient errors: network errors, 429 (rate limit), and 5xx // server errors, with exponential backoff (1s, 2s, 4s, 8s; max 4 retries). // Does NOT retry on 4xx errors (except 429) — those are client errors. -func (b *Bot) doJSON(method string, body any, dest any) error { +func (b *Bot) doJSON(method string, body any, dest any) (requestErr error) { + defer func() { reportAPIFailure("api_request", requestErr) }() var reqBody []byte if body != nil { var err error @@ -283,7 +286,8 @@ func (b *Bot) doJSON(method string, body any, dest any) error { // NOTE: The entire file is read into memory before sending (bodyBytes). // This is intentional — it allows retry without re-reading the file from disk. // Telegram's 50 MB upload limit makes this acceptable for bot use cases. -func (b *Bot) doUpload(method string, field string, path string, params map[string]any, dest any) error { +func (b *Bot) doUpload(method string, field string, path string, params map[string]any, dest any) (requestErr error) { + defer func() { reportAPIFailure("upload", requestErr) }() file, err := os.Open(path) if err != nil { b.log.Error("open file failed", "method", method, "path", path, "error", err) @@ -785,3 +789,16 @@ func (b *Bot) SendChatAction(chatID int64, action string) error { } return b.doJSON("sendChatAction", params, nil) } + +func reportAPIFailure(operation string, err error) { + if err == nil { + return + } + ev := diagnostics.Failure("telegram", operation, "", err) + var api *TelegramError + if errors.As(err, &api) { + ev.Data["http_status"] = api.Code + ev.Data["error_class"] = "telegram_api" + } + diagnostics.Emit(ev) +} diff --git a/internal/telegram/diagnostics_test.go b/internal/telegram/diagnostics_test.go new file mode 100644 index 00000000..55102486 --- /dev/null +++ b/internal/telegram/diagnostics_test.go @@ -0,0 +1,43 @@ +package telegram + +import ( + "encoding/json" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/BackendStack21/odek/internal/diagnostics" + "github.com/BackendStack21/odek/internal/events" +) + +func TestAPIFailureDiagnosticsExcludeTokensAndBodies(t *testing.T) { + var got []events.Event + restore := diagnostics.Install(func(ev events.Event) { got = append(got, ev) }) + defer restore() + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusForbidden) + _, _ = w.Write([]byte(`{"ok":false,"error_code":403,"description":"PRIVATE response"}`)) + })) + defer server.Close() + bot := NewBot("PRIVATE-token") + bot.BaseURL = server.URL + if _, err := bot.SendMessageContext(t.Context(), 123, "PRIVATE message", nil); err == nil { + t.Fatal("API failure swallowed") + } + if _, err := bot.SendMessage(123, "PRIVATE message", nil); err == nil { + t.Fatal("legacy API failure swallowed") + } + if len(got) != 2 { + t.Fatalf("unexpected reports: %+v", got) + } + for _, ev := range got { + if ev.Data["component"] != "telegram" || ev.Data["operation"] != "api_request" || ev.Data["http_status"] != 403 { + t.Fatal(ev) + } + } + b, _ := json.Marshal(got) + if strings.Contains(string(b), "PRIVATE") { + t.Fatalf("private payload leaked: %s", b) + } +} diff --git a/odek.go b/odek.go index 504662c2..a1db5c9f 100644 --- a/odek.go +++ b/odek.go @@ -31,6 +31,7 @@ import ( "github.com/BackendStack21/odek/internal/budget" "github.com/BackendStack21/odek/internal/config" "github.com/BackendStack21/odek/internal/danger" + "github.com/BackendStack21/odek/internal/diagnostics" "github.com/BackendStack21/odek/internal/events" "github.com/BackendStack21/odek/internal/guard" "github.com/BackendStack21/odek/internal/llmclient" @@ -39,6 +40,7 @@ import ( "github.com/BackendStack21/odek/internal/memory/extended" "github.com/BackendStack21/odek/internal/narrate" "github.com/BackendStack21/odek/internal/render" + "github.com/BackendStack21/odek/internal/runtimelog" "github.com/BackendStack21/odek/internal/session" "github.com/BackendStack21/odek/internal/skills" "github.com/BackendStack21/odek/internal/tool" @@ -54,6 +56,13 @@ type Tool interface { // Config configures an Agent instance. type Config struct { + // RuntimeLogPath enables asynchronous metadata-only JSONL logging. Empty + // disables it. RuntimeLogMaxMB=0 disables size rotation; Surface labels CLI use. + RuntimeLogPath string + RuntimeLogMaxMB int64 + RuntimeLogSurface string + EventContext events.Context + // Provider is the go-llm-sdk registry id (deepseek, openai, anthropic, // gemini, zai, kimi, or a custom id from Providers). Empty defaults to // deepseek. @@ -313,6 +322,7 @@ type Agent struct { sandboxCleanup func() error // destroys the sandbox container on Close() skillManager *skills.SkillManager memoryManager *memory.MemoryManager + runtimeLog *runtimelog.Logger emitter *events.Emitter // non-nil when Config.EventHandler is set } @@ -396,7 +406,8 @@ const ( // If Config.SandboxCleanup is set, the cleanup function is called when // Close() is invoked. The caller is responsible for creating the sandbox // container and wiring up tool executables to use it before calling New(). -func New(cfg Config) (*Agent, error) { +func New(cfg Config) (_ *Agent, setupErr error) { + defer func() { diagnostics.Report("agent", "initialize", cfg.EventContext.SessionID, setupErr) }() for i, r := range cfg.ExternalRefs { if err := r.Validate(); err != nil { return nil, fmt.Errorf("odek: config external_refs[%d]: %w", i, err) @@ -741,10 +752,19 @@ func New(cfg Config) (*Agent, error) { // Wire agent-loop signal observability (context trim, tool recovery): fan // out to the programmatic handler and the terminal renderer. - if cfg.AgentSignalHandler != nil || cfg.Renderer != nil { + if cfg.AgentSignalHandler != nil || cfg.Renderer != nil || cfg.EventHandler != nil || cfg.RuntimeLogPath != "" { handler := cfg.AgentSignalHandler renderer := cfg.Renderer engine.SetSignalHandler(func(ev loop.SignalEvent) { + if ev.Type == "budget_warning" || ev.Type == "tool_recovery" { + data := map[string]any{"count": ev.Count} + for _, threshold := range []int{50, 75, 90} { + if strings.HasPrefix(ev.Detail, fmt.Sprintf("threshold_%d:", threshold)) { + data["threshold_percent"] = threshold + } + } + agent.EmitEvent(events.Event{Type: ev.Type, Tool: ev.Tool, Data: data}) + } if handler != nil { handler(ev) } @@ -772,8 +792,23 @@ func New(cfg Config) (*Agent, error) { // emitter dispatches on its own goroutine — buffered, drop-on-full, // panic-isolated — so a slow or panicking handler can never stall or // crash the loop. - if cfg.EventHandler != nil { - agent.emitter = events.NewEmitter(cfg.EventHandler, events.NewRunID()) + handler := cfg.EventHandler + if cfg.RuntimeLogPath != "" { + logger, err := runtimelog.Open(cfg.RuntimeLogPath, cfg.RuntimeLogSurface, cfg.RuntimeLogMaxMB) + if err != nil { + return nil, fmt.Errorf("open runtime log: %w", err) + } + agent.runtimeLog = logger + handler = func(ev events.Event) { + logger.Emit(ev) + if cfg.EventHandler != nil { + cfg.EventHandler(ev) + } + } + } + if handler != nil { + agent.emitter = events.NewEmitter(handler, events.NewRunID()) + agent.emitter.SetContext(cfg.EventContext) engine.SetEventHandler(agent.emitter.Emit) engine.SetEventsIncludeArgs(cfg.EventsIncludeArgs) } @@ -844,6 +879,7 @@ func (a *Agent) SystemPrompt() string { // Run executes the agent loop for the given task and returns the final answer. func (a *Agent) Run(ctx context.Context, task string) (string, error) { start := time.Now() + a.beginTurn() result, err := a.engine.Run(ctx, task) a.emitRunFinished(start, err) return result, err @@ -859,11 +895,31 @@ func (a *Agent) Run(ctx context.Context, task string) (string, error) { // the conversation can be continued in a future call. func (a *Agent) RunWithMessages(ctx context.Context, messages []session.Message) (string, []session.Message, error) { start := time.Now() + a.beginTurn() result, msgs, err := a.engine.RunWithMessages(ctx, messages) a.emitRunFinished(start, err) return result, msgs, err } +func (a *Agent) beginTurn() { + if a.emitter == nil { + return + } + a.emitter.SetTurnID(events.NewRunID()) + a.bindEventContext() + a.emitter.Emit(events.Event{Type: "turn_started", Data: map[string]any{"model": a.config.Model}}) +} +func (a *Agent) bindEventContext() { + if a.emitter == nil || a.registry == nil { + return + } + for _, t := range a.registry.Tools() { + if b, ok := t.(interface{ SetEventContext(events.Context) }); ok { + b.SetEventContext(a.emitter.Context()) + } + } +} + // emitRunFinished emits run_completed / run_failed for a finished Run or // RunWithMessages call. No-op when no EventHandler is configured. func (a *Agent) emitRunFinished(start time.Time, err error) { @@ -873,9 +929,15 @@ func (a *Agent) emitRunFinished(start time.Time, err error) { durationMs := time.Since(start).Milliseconds() if err != nil { data := map[string]any{ - "duration_ms": durationMs, - "error_class": events.ErrorClass(err), + "duration_ms": durationMs, + "error_class": events.ErrorClass(err), + "input_tokens": a.engine.TotalInputTokens, + "output_tokens": a.engine.TotalOutputTokens, + } + for key, value := range events.ErrorData(err) { + data[key] = value } + a.appendRuntimeCost(data) a.engine.AppendRunLLMMetrics(data) a.emitter.Emit(events.Event{ Type: events.TypeRunFailed, @@ -888,6 +950,7 @@ func (a *Agent) emitRunFinished(start time.Time, err error) { "input_tokens": a.engine.TotalInputTokens, "output_tokens": a.engine.TotalOutputTokens, } + a.appendRuntimeCost(data) a.engine.AppendRunLLMMetrics(data) a.emitter.Emit(events.Event{ Type: events.TypeRunCompleted, @@ -912,6 +975,7 @@ func (a *Agent) SetEventSessionID(id string) { return } a.emitter.SetSessionID(id) + a.bindEventContext() } // sessionToolBinder is implemented by built-in tools that scope persistent @@ -929,6 +993,7 @@ type sessionToolBinder interface { // session surfaces (run/continue/repl/telegram) bind once at startup or per // agent construction. No-op on a nil agent or when no tool qualifies. func (a *Agent) SetToolSessionID(id string) { + a.SetEventSessionID(id) if a == nil || a.registry == nil { return } @@ -1066,6 +1131,12 @@ func (a *Agent) Close() error { if a.emitter != nil { a.emitter.Close() } + if a.runtimeLog != nil { + if a.emitter != nil && a.emitter.Dropped() > 0 { + a.runtimeLog.Emit(events.Event{Type: "logging_dropped", RunID: a.RunID(), SessionID: a.emitter.Context().SessionID, Data: map[string]any{"dropped": a.emitter.Dropped()}}) + } + a.runtimeLog.Close() + } if a.sandboxCleanup != nil { return a.sandboxCleanup() } @@ -1370,3 +1441,26 @@ func (a *Agent) SetInitialToolCalls(calls []session.ToolCall) { a.engine.SetInitialToolCalls(calls) } } + +// FlushEvents drains and closes the event stream when a one-shot child must +// write its terminal protocol frame before running deferred cleanup. +func (a *Agent) FlushEvents() { + if a.emitter != nil { + a.emitter.Close() + } +} + +func (a *Agent) appendRuntimeCost(data map[string]any) { + in, out := a.config.Limits.ResolvePrices(a.config.Model) + if in > 0 || out > 0 { + data["cost_usd"] = a.engine.BudgetUsage().CostUSD + } +} + +// DroppedEvents reports loss before the configured event handler received data. +func (a *Agent) DroppedEvents() uint64 { + if a.emitter == nil { + return 0 + } + return a.emitter.Dropped() +} diff --git a/runtime_logging_test.go b/runtime_logging_test.go new file mode 100644 index 00000000..e7eb9d85 --- /dev/null +++ b/runtime_logging_test.go @@ -0,0 +1,113 @@ +package odek + +import ( + "bufio" + "encoding/json" + "net/http" + "net/http/httptest" + "os" + "path/filepath" + "strings" + "testing" + + "github.com/BackendStack21/odek/internal/budget" + "github.com/BackendStack21/odek/internal/events" +) + +func TestRuntimeLoggingSessionAndDistinctTurns(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`{"choices":[{"message":{"content":"private answer"},"finish_reason":"stop"}],"usage":{"prompt_tokens":100,"completion_tokens":20}}`)) + })) + defer server.Close() + path := filepath.Join(t.TempDir(), "runtime.log") + a, err := New(Config{Model: "test", BaseURL: server.URL, APIKey: "test-key", MaxIterations: 2, RuntimeLogPath: path, Limits: budget.Limits{InputCostPerMillionUSD: 2, OutputCostPerMillionUSD: 4}, InteractionMode: "off", NoProjectFile: true}) + if err != nil { + t.Fatal(err) + } + a.SetToolSessionID("session-123") // binds events as well as tool artifacts + for i := 0; i < 2; i++ { + if _, err := a.Run(t.Context(), "private task"); err != nil { + t.Fatal(err) + } + } + _ = a.Close() + b, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + if strings.Contains(string(b), "private") || strings.Contains(string(b), "test-key") { + t.Fatal("private content leaked") + } + turns := map[string]bool{} + finished := 0 + scanner := bufio.NewScanner(strings.NewReader(string(b))) + for scanner.Scan() { + var ev events.Event + if err := json.Unmarshal(scanner.Bytes(), &ev); err != nil { + t.Fatal(err) + } + if ev.Type == "run_started" { + if ev.SessionID != "" { + t.Fatal("fabricated pre-session ID") + } + continue + } + if ev.SessionID != "session-123" || ev.TurnID == "" { + t.Fatalf("missing correlation: %+v", ev) + } + if ev.Type == "turn_started" { + turns[ev.TurnID] = true + } + if ev.Type == "run_completed" { + finished++ + if ev.Data["cost_usd"] == nil { + t.Fatal("missing configured cost") + } + } + } + if len(turns) != 2 || finished != 2 { + t.Fatalf("turns=%v finished=%d", turns, finished) + } +} + +func TestRuntimeLoggingProviderFailure(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(http.StatusUnauthorized) + _, _ = w.Write([]byte(`{"error":{"message":"PRIVATE response body","type":"authentication_error"}}`)) + })) + defer server.Close() + path := filepath.Join(t.TempDir(), "runtime.log") + a, err := New(Config{Model: "test", BaseURL: server.URL, APIKey: "PRIVATE-key", RuntimeLogPath: path, NoProjectFile: true, InteractionMode: "off", EventContext: events.Context{SessionID: "session"}}) + if err != nil { + t.Fatal(err) + } + if _, err := a.Run(t.Context(), "PRIVATE prompt"); err == nil { + t.Fatal("provider failure swallowed") + } + _ = a.Close() + b, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + if strings.Contains(string(b), "PRIVATE") { + t.Fatal("request/provider text leaked") + } + found := map[string]bool{} + for _, line := range strings.Split(strings.TrimSpace(string(b)), "\n") { + var ev events.Event + if err := json.Unmarshal([]byte(line), &ev); err != nil { + t.Fatal(err) + } + if ev.Type == "llm_call_failed" || ev.Type == "run_failed" { + if ev.SessionID != "session" || ev.TurnID == "" || ev.Data["error_class"] != "provider_auth" || ev.Data["http_status"] != float64(401) { + t.Fatalf("missing failure detail/correlation: %+v", ev) + } + found[ev.Type] = true + } + } + if len(found) != 2 { + t.Fatalf("missing failure lifecycle: %v", found) + } +}