diff --git a/CLAUDE.md b/CLAUDE.md index 94ab656..72ff27f 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -37,6 +37,7 @@ pkg/detector/ Core detection logic pkg/engine/ AI engine abstraction ├── engine.go copilot/claude/codex CLI adapters; Copilot uses runCLIWithPromptFile, Claude uses runCLI with stdin, Codex passes prompts via codexArgs/runCLIEnv └── tool.go threat_detection_result wrapper provisioning + result-sink watcher +pkg/runlog/ Structured JSONL run-log writer (--log-file); nil-safe no-op logger specs/ Normative spec (threat-detection-spec.md) scripts/ create-threat-detection-sibling-workflows.py (regenerates *-container.lock.yml) skills/ Repo-relevant agent skills (console-rendering, error-messages) @@ -80,6 +81,7 @@ threat-detect [flags] - `--model ` — model override forwarded to the engine - `--prompt-template ` — override the embedded default - `--output ` — write JSON result (defaults to stdout) +- `--log-file ` — write structured JSONL run logs; env: `THREAT_DETECTION_LOG_FILE` - `--retries` (default `1`) — retries for malformed detection outputs; env: `THREAT_DETECTION_RETRIES` **Exit codes** (defined in `cmd/threat-detect/main.go`): diff --git a/README.md b/README.md index 8ec9564..243c6b9 100644 --- a/README.md +++ b/README.md @@ -58,6 +58,7 @@ threat-detect [flags] - `--model` — Model override for the engine - `--prompt-template` — Path to custom prompt template - `--output` — Path to write JSON result (defaults to stdout) +- `--log-file` — Path to write structured JSONL run logs (one JSON object per line). Env: `THREAT_DETECTION_LOG_FILE` - `--retries` — Retries for malformed detection outputs. Default: `1` (env: `THREAT_DETECTION_RETRIES`) - `--version` — Print version and exit @@ -108,6 +109,27 @@ the step, so warn-mode workflows proceed exactly as they do under `gh-aw`'s nati engine (which treats a missing verdict as a recoverable `parse_error`). Only genuine engine/config failures surface as a step failure. See spec TD-21a. +#### JSONL run logs (`--log-file`) + +Pass `--log-file ` (or set `THREAT_DETECTION_LOG_FILE`) to record a +structured trace of the run as [JSON Lines](https://jsonlines.org/): one JSON +object per line, created fresh (truncating any existing file) with `0600` +permissions. Every record starts with `time` (RFC 3339), `level` +(`info`/`error`), and `event`, followed by event-specific fields. Emitted +events include `run_start`, `artifacts_loaded`, `prompt_built`, +`attempt_start`/`attempt_recorded`/`attempt_no_verdict`, `verdict`, +`detection_failed`, and a terminal `status` record carrying the same `reason` +and `exit` code as the stderr status line. The verdict JSON contract +(`--output`) is unchanged; the log file is an additive observability sink. +`--log-file` and `--output` must not resolve to the same file — a collision is +rejected as a configuration error to avoid corrupting both outputs. + +```jsonl +{"time":"2026-07-14T18:00:00Z","level":"info","event":"run_start","engine":"copilot","model":"","retries":1,"version":"1.2.3"} +{"time":"2026-07-14T18:00:03Z","level":"info","event":"verdict","has_threats":false,"malicious_patch":false,"prompt_injection":false,"reasons":[],"secret_leak":false} +{"time":"2026-07-14T18:00:03Z","level":"info","event":"status","exit":0,"reason":"result_recorded"} +``` + #### Concluding a run (`conclude`) In `gh-aw`-compiled workflows the detector runs inside the AWF sandbox, where the diff --git a/cmd/threat-detect/logfile_test.go b/cmd/threat-detect/logfile_test.go new file mode 100644 index 0000000..9c89b09 --- /dev/null +++ b/cmd/threat-detect/logfile_test.go @@ -0,0 +1,175 @@ +package main + +import ( + "encoding/json" + "os" + "path/filepath" + "strings" + "testing" +) + +// readJSONLRecords parses a JSONL file into a slice of decoded records. +func readJSONLRecords(t *testing.T, path string) []map[string]any { + t.Helper() + data, err := os.ReadFile(path) + if err != nil { + t.Fatalf("reading log file: %v", err) + } + var records []map[string]any + for _, line := range strings.Split(strings.TrimRight(string(data), "\n"), "\n") { + if line == "" { + continue + } + var rec map[string]any + if err := json.Unmarshal([]byte(line), &rec); err != nil { + t.Fatalf("log line is not valid JSON (%q): %v", line, err) + } + records = append(records, rec) + } + return records +} + +func findRecord(records []map[string]any, event string) map[string]any { + for _, rec := range records { + if rec["event"] == event { + return rec + } + } + return nil +} + +func TestRunWritesJSONLLog(t *testing.T) { + artifactsDir := t.TempDir() + outputPath := filepath.Join(t.TempDir(), "result.json") + logPath := filepath.Join(t.TempDir(), "run.jsonl") + copilotMarker := filepath.Join(t.TempDir(), "copilot-called") + sinkJSON := `{"prompt_injection":true,"secret_leak":false,"malicious_patch":false,"reasons":["agentic detection"]}` + fakeBinDir := writeFakeCopilotWithSink(t, copilotMarker, sinkJSON, 0) + + code := runWithTestArgs(t, []string{ + "threat-detect", + "-output", outputPath, + "-log-file", logPath, + artifactsDir, + }, map[string]string{ + "PATH": fakeBinDir + string(os.PathListSeparator) + os.Getenv("PATH"), + }) + + if code != exitThreat { + t.Fatalf("run() exit code = %d, want %d", code, exitThreat) + } + + records := readJSONLRecords(t, logPath) + + // The primary audit record must reflect the engine that actually runs: + // an omitted --engine resolves to copilot, not "". + start := findRecord(records, "run_start") + if start == nil { + t.Fatalf("missing run_start record: %#v", records) + } + if start["engine"] != "copilot" { + t.Errorf("run_start engine = %v, want copilot", start["engine"]) + } + + verdict := findRecord(records, "verdict") + if verdict == nil { + t.Fatalf("missing verdict record: %#v", records) + } + if verdict["prompt_injection"] != true { + t.Errorf("verdict prompt_injection = %v, want true", verdict["prompt_injection"]) + } + if verdict["has_threats"] != true { + t.Errorf("verdict has_threats = %v, want true", verdict["has_threats"]) + } + + // The terminal status record must mirror the stderr status line: reason + + // exit, using the JSON number 1 for a detected threat. + status := findRecord(records, "status") + if status == nil { + t.Fatalf("missing status record: %#v", records) + } + if status["reason"] != reasonResultRecorded { + t.Errorf("status reason = %v, want %s", status["reason"], reasonResultRecorded) + } + if exit, ok := status["exit"].(float64); !ok || int(exit) != exitThreat { + t.Errorf("status exit = %v, want %d", status["exit"], exitThreat) + } +} + +func TestRunUsesLogFileEnvVar(t *testing.T) { + artifactsDir := t.TempDir() + outputPath := filepath.Join(t.TempDir(), "result.json") + logPath := filepath.Join(t.TempDir(), "run.jsonl") + copilotMarker := filepath.Join(t.TempDir(), "copilot-called") + sinkJSON := `{"prompt_injection":false,"secret_leak":false,"malicious_patch":false,"reasons":[]}` + fakeBinDir := writeFakeCopilotWithSink(t, copilotMarker, sinkJSON, 0) + + code := runWithTestArgs(t, []string{ + "threat-detect", + "-output", outputPath, + artifactsDir, + }, map[string]string{ + "PATH": fakeBinDir + string(os.PathListSeparator) + os.Getenv("PATH"), + "THREAT_DETECTION_LOG_FILE": logPath, + }) + + if code != exitSafe { + t.Fatalf("run() exit code = %d, want %d", code, exitSafe) + } + records := readJSONLRecords(t, logPath) + if findRecord(records, "run_start") == nil { + t.Fatalf("expected env-configured log file to receive records: %#v", records) + } + status := findRecord(records, "status") + if status == nil || status["reason"] != reasonResultRecorded { + t.Fatalf("expected result_recorded status, got %#v", status) + } +} + +func TestRunRejectsLogFileCollidingWithOutput(t *testing.T) { + artifactsDir := t.TempDir() + shared := filepath.Join(t.TempDir(), "same.json") + + code, stderr := runWithTestArgsCapture(t, []string{ + "threat-detect", + "-output", shared, + "-log-file", shared, + artifactsDir, + }, nil) + + if code != exitError { + t.Fatalf("run() exit code = %d, want %d", code, exitError) + } + if !strings.Contains(stderr, "must not point to the same file") { + t.Fatalf("stderr missing collision error, got:\n%s", stderr) + } + if !strings.Contains(stderr, "reason=config_error") { + t.Fatalf("stderr missing config_error status, got:\n%s", stderr) + } + // Neither file should have been created by the aborted run. + if _, err := os.Stat(shared); !os.IsNotExist(err) { + t.Fatalf("expected no file to be written, stat err = %v", err) + } +} + +func TestRunRejectsUnopenableLogFile(t *testing.T) { + artifactsDir := t.TempDir() + // Parent directory does not exist, so runlog.Open must fail. + logPath := filepath.Join(t.TempDir(), "missing-dir", "run.jsonl") + + code, stderr := runWithTestArgsCapture(t, []string{ + "threat-detect", + "-log-file", logPath, + artifactsDir, + }, nil) + + if code != exitError { + t.Fatalf("run() exit code = %d, want %d", code, exitError) + } + if !strings.Contains(stderr, "Error opening log file") { + t.Fatalf("stderr missing open error, got:\n%s", stderr) + } + if !strings.Contains(stderr, "reason=config_error") { + t.Fatalf("stderr missing config_error status, got:\n%s", stderr) + } +} diff --git a/cmd/threat-detect/main.go b/cmd/threat-detect/main.go index f1fa332..d65b8f3 100644 --- a/cmd/threat-detect/main.go +++ b/cmd/threat-detect/main.go @@ -22,11 +22,13 @@ import ( "fmt" "os" "os/signal" + "path/filepath" "strconv" "github.com/github/gh-aw-threat-detection/pkg/artifacts" "github.com/github/gh-aw-threat-detection/pkg/detector" "github.com/github/gh-aw-threat-detection/pkg/engine" + "github.com/github/gh-aw-threat-detection/pkg/runlog" ) const ( @@ -83,9 +85,16 @@ func run() (code int) { // reason is set at each terminal point; the deferred emitter writes the // single status line. An empty reason (e.g. --version) emits nothing. reason := "" + // logger, when non-nil, mirrors the run's key events (including the terminal + // status) to a JSONL log file. It is nil until --log-file is resolved. + var logger *runlog.Logger defer func() { if reason != "" { emitStatus(reason, code) + logger.Info("status", map[string]any{"reason": reason, "exit": code}) + } + if err := logger.Close(); err != nil { + fmt.Fprintf(os.Stderr, "Error closing log file: %v\n", err) } }() @@ -94,6 +103,7 @@ func run() (code int) { model string promptFile string outputJSON string + logFile string version bool retries int ) @@ -107,6 +117,7 @@ func run() (code int) { flag.StringVar(&model, "model", "", "Model to use for detection") flag.StringVar(&promptFile, "prompt-template", "", "Path to custom prompt template (defaults to built-in)") flag.StringVar(&outputJSON, "output", "", "Path to write JSON result (defaults to stdout)") + flag.StringVar(&logFile, "log-file", os.Getenv("THREAT_DETECTION_LOG_FILE"), "Path to write JSONL run logs (env: THREAT_DETECTION_LOG_FILE)") flag.BoolVar(&version, "version", false, "Print version and exit") flag.IntVar(&retries, "retries", envInt("THREAT_DETECTION_RETRIES", 1), "Retries for malformed detection outputs (env: THREAT_DETECTION_RETRIES)") if err := flag.CommandLine.Parse(os.Args[1:]); err != nil { @@ -123,6 +134,39 @@ func run() (code int) { return exitSafe } + // Reject a --log-file that collides with --output: they are opened and + // truncated independently, so sharing an inode would interleave the JSONL + // trace and the result JSON and corrupt both while still reporting success. + if logFile != "" && outputJSON != "" { + if same, err := samePath(logFile, outputJSON); err != nil { + fmt.Fprintf(os.Stderr, "Error resolving output paths: %v\n", err) + reason = reasonConfigError + return exitError + } else if same { + fmt.Fprintf(os.Stderr, "Error: --log-file and --output must not point to the same file (%q)\n", logFile) + reason = reasonConfigError + return exitError + } + } + + // Open the JSONL run log if requested. A failure here is a config error: + // the caller explicitly asked for logs and should learn they were not written. + if logFile != "" { + l, err := runlog.Open(logFile) + if err != nil { + fmt.Fprintf(os.Stderr, "Error opening log file: %v\n", err) + reason = reasonConfigError + return exitError + } + logger = l + } + logger.Info("run_start", map[string]any{ + "version": detector.Version, + "engine": engine.Canonical(engineID), + "model": model, + "retries": retries, + }) + // Determine artifacts directory from positional args args := flag.Args() if len(args) < 1 { @@ -137,9 +181,11 @@ func run() (code int) { arts, err := artifacts.Load(artifactsDir) if err != nil { fmt.Fprintf(os.Stderr, "Error loading artifacts: %v\n", err) + logger.Error("artifacts_load_failed", map[string]any{"artifacts_dir": artifactsDir, "error": err.Error()}) reason = reasonConfigError return exitError } + logger.Info("artifacts_loaded", map[string]any{"artifacts_dir": artifactsDir}) // Build the prompt promptTemplate := "" @@ -156,14 +202,17 @@ func run() (code int) { prompt, err := detector.BuildPrompt(arts, promptTemplate) if err != nil { fmt.Fprintf(os.Stderr, "Error building prompt: %v\n", err) + logger.Error("prompt_build_failed", map[string]any{"error": err.Error()}) reason = reasonConfigError return exitError } + logger.Info("prompt_built", map[string]any{"prompt_bytes": len(prompt)}) // Create engine eng, err := engine.New(engineID, model) if err != nil { fmt.Fprintf(os.Stderr, "Error creating engine: %v\n", err) + logger.Error("engine_create_failed", map[string]any{"error": err.Error()}) reason = reasonConfigError return exitError } @@ -181,7 +230,7 @@ func run() (code int) { os.Remove(sinkPath) defer os.Remove(sinkPath) - result, err := analyzeWithRetries(ctx, eng, prompt, sinkPath, retries) + result, err := analyzeWithRetries(ctx, eng, prompt, sinkPath, retries, logger) if err != nil { fmt.Fprintf(os.Stderr, "Error running detection: %v\n", err) switch { @@ -192,8 +241,16 @@ func run() (code int) { default: reason = reasonInvalidReportExhausted } + logger.Error("detection_failed", map[string]any{"reason": reason, "error": err.Error()}) return exitError } + logger.Info("verdict", map[string]any{ + "prompt_injection": result.PromptInjection, + "secret_leak": result.SecretLeak, + "malicious_patch": result.MaliciousPatch, + "reasons": result.Reasons, + "has_threats": result.HasThreats(), + }) var resultReason string code, resultReason = writeResult(result, outputJSON) @@ -201,7 +258,7 @@ func run() (code int) { return code } -func analyzeWithRetries(ctx context.Context, eng engine.Engine, prompt, sinkPath string, retries int) (*detector.Result, error) { +func analyzeWithRetries(ctx context.Context, eng engine.Engine, prompt, sinkPath string, retries int, logger *runlog.Logger) (*detector.Result, error) { if sinkPath == "" { return nil, fmt.Errorf("result sink path is required for detection") } @@ -212,6 +269,7 @@ func analyzeWithRetries(ctx context.Context, eng engine.Engine, prompt, sinkPath currentPrompt := prompt var lastErr error for i := 0; i < attempts; i++ { + logger.Info("attempt_start", map[string]any{"attempt": i + 1, "attempts": attempts}) // Remove any stale sink result before each attempt. os.Remove(sinkPath) if _, err := eng.Analyze(ctx, currentPrompt, engine.AnalyzeOptions{ResultSinkPath: sinkPath}); err != nil { @@ -221,9 +279,11 @@ func analyzeWithRetries(ctx context.Context, eng engine.Engine, prompt, sinkPath // threat_detection_result tool, which records it to the sink. result, err := detector.ReadResultFile(sinkPath) if err == nil { + logger.Info("attempt_recorded", map[string]any{"attempt": i + 1}) return result, nil } lastErr = err + logger.Info("attempt_no_verdict", map[string]any{"attempt": i + 1, "error": err.Error()}) currentPrompt = detector.BuildCorrectionPrompt(prompt, detectionCorrectionPrefix, detectionCorrectionMessage, detectionCorrectionInstruction) } return nil, fmt.Errorf("detection model did not record a verdict via the threat_detection_result tool after %d attempt(s): %w", attempts, lastErr) @@ -266,3 +326,46 @@ func envInt(key string, fallback int) int { } return parsed } + +// samePath reports whether a and b refer to the same file. It first compares +// resolved absolute paths (handling "." segments and symlinked directories), +// then, when both files already exist, confirms with os.SameFile so hardlinks +// and other symlink equivalences are caught too. +func samePath(a, b string) (bool, error) { + ra, err := resolvePath(a) + if err != nil { + return false, err + } + rb, err := resolvePath(b) + if err != nil { + return false, err + } + if ra == rb { + return true, nil + } + ia, errA := os.Stat(a) + ib, errB := os.Stat(b) + if errA == nil && errB == nil { + return os.SameFile(ia, ib), nil + } + return false, nil +} + +// resolvePath returns an absolute, symlink-resolved path. When the target does +// not yet exist, it resolves the deepest existing ancestor directory and rejoins +// the remaining components so not-yet-created siblings still compare correctly. +func resolvePath(p string) (string, error) { + abs, err := filepath.Abs(p) + if err != nil { + return "", err + } + if resolved, err := filepath.EvalSymlinks(abs); err == nil { + return resolved, nil + } + dir, base := filepath.Split(abs) + dir = filepath.Clean(dir) + if resolvedDir, err := filepath.EvalSymlinks(dir); err == nil { + return filepath.Join(resolvedDir, base), nil + } + return filepath.Clean(abs), nil +} diff --git a/pkg/engine/engine.go b/pkg/engine/engine.go index 4fb199a..11eaac8 100644 --- a/pkg/engine/engine.go +++ b/pkg/engine/engine.go @@ -29,14 +29,23 @@ type Engine interface { Analyze(ctx context.Context, prompt string, opts AnalyzeOptions) (string, error) } -// New creates a new engine instance based on the engine ID. -// If engineID is empty, it defaults to "copilot". -func New(engineID, model string) (Engine, error) { +// DefaultEngineID is the engine used when no engine is explicitly selected. +const DefaultEngineID = "copilot" + +// Canonical normalizes an engine ID: it applies the default for an empty ID and +// lowercases the result, matching the resolution performed by New. Callers use +// it so audit/log records reflect the engine that will actually run. +func Canonical(engineID string) string { if engineID == "" { - engineID = "copilot" + return DefaultEngineID } + return strings.ToLower(engineID) +} - switch strings.ToLower(engineID) { +// New creates a new engine instance based on the engine ID. +// If engineID is empty, it defaults to "copilot". +func New(engineID, model string) (Engine, error) { + switch Canonical(engineID) { case "copilot": return &copilotEngine{model: model}, nil case "claude": diff --git a/pkg/engine/engine_test.go b/pkg/engine/engine_test.go index 3eb1d31..906ada4 100644 --- a/pkg/engine/engine_test.go +++ b/pkg/engine/engine_test.go @@ -47,6 +47,21 @@ func TestNew_Default(t *testing.T) { } } +func TestCanonical(t *testing.T) { + cases := map[string]string{ + "": DefaultEngineID, + "copilot": "copilot", + "Copilot": "copilot", + "CLAUDE": "claude", + "Codex": "codex", + } + for in, want := range cases { + if got := Canonical(in); got != want { + t.Errorf("Canonical(%q) = %q, want %q", in, got, want) + } + } +} + func TestNew_Unsupported(t *testing.T) { _, err := New("unsupported-engine", "") if err == nil { diff --git a/pkg/runlog/runlog.go b/pkg/runlog/runlog.go new file mode 100644 index 0000000..4c775de --- /dev/null +++ b/pkg/runlog/runlog.go @@ -0,0 +1,163 @@ +// Package runlog provides structured JSON Lines (JSONL) logging for a single +// threat-detection run. Each call to a logging method appends exactly one JSON +// object, terminated by a newline, to the underlying writer. Records always +// begin with the "time", "level", and "event" keys; any additional fields are +// emitted afterwards in a deterministic (sorted) order so logs are stable and +// easy to diff. +// +// A nil *Logger is a valid no-op logger: every method may be called on it +// safely, which lets callers pass nil when JSONL logging is disabled without +// sprinkling nil checks throughout the call sites. +package runlog + +import ( + "encoding/json" + "fmt" + "io" + "os" + "sort" + "strings" + "sync" + "time" +) + +// Log levels emitted in the "level" field. +const ( + LevelInfo = "info" + LevelError = "error" +) + +// Logger writes newline-delimited JSON log records to an underlying writer. +// The zero value is not usable; construct one with New or Open. A nil *Logger +// is a valid no-op. +type Logger struct { + mu sync.Mutex + w io.Writer + closer io.Closer + now func() time.Time + writeErr error +} + +// New returns a Logger that writes records to w. The writer is not closed by +// Close; use Open when the Logger should own a file handle. +func New(w io.Writer) *Logger { + return &Logger{w: w, now: time.Now} +} + +// Open creates (truncating any existing file) a JSONL log file at path with +// 0600 permissions and returns a Logger that owns it. The returned Logger's +// Close closes the file. +func Open(path string) (*Logger, error) { + f, err := os.OpenFile(path, os.O_CREATE|os.O_WRONLY|os.O_TRUNC, 0o600) + if err != nil { + return nil, fmt.Errorf("opening JSONL log file: %w", err) + } + // OpenFile only applies the mode when creating the file; an existing file + // keeps its prior (possibly more permissive) mode. Enforce 0600 explicitly + // so audit data is never left world-readable. + if err := f.Chmod(0o600); err != nil { + f.Close() + return nil, fmt.Errorf("securing JSONL log file permissions: %w", err) + } + return &Logger{w: f, closer: f, now: time.Now}, nil +} + +// Info appends an info-level record for event with the given fields. +func (l *Logger) Info(event string, fields map[string]any) { + l.emit(LevelInfo, event, fields) +} + +// Error appends an error-level record for event with the given fields. +func (l *Logger) Error(event string, fields map[string]any) { + l.emit(LevelError, event, fields) +} + +// Close reports the first write/encode error observed (so callers learn the +// requested log is incomplete) and closes the underlying file when the Logger +// owns one. It is safe to call on a nil Logger or one constructed with New. +func (l *Logger) Close() error { + if l == nil { + return nil + } + l.mu.Lock() + writeErr := l.writeErr + l.mu.Unlock() + + var closeErr error + if l.closer != nil { + closeErr = l.closer.Close() + } + if writeErr != nil { + return writeErr + } + return closeErr +} + +func (l *Logger) emit(level, event string, fields map[string]any) { + if l == nil || l.w == nil { + return + } + line, err := encodeRecord(l.now().UTC(), level, event, fields) + l.mu.Lock() + defer l.mu.Unlock() + if err != nil { + if l.writeErr == nil { + l.writeErr = err + } + return + } + if _, err := l.w.Write(line); err != nil && l.writeErr == nil { + // Preserve the first failure; closing an os.File will not report an + // earlier short/failed Write, so record it for Close to surface. + l.writeErr = err + } +} + +// encodeRecord renders a single JSONL line: the leading time/level/event keys +// followed by the remaining fields in sorted order, terminated by a newline. +// Reserved keys ("time", "level", "event") in fields are ignored so a caller +// cannot accidentally shadow them. +func encodeRecord(t time.Time, level, event string, fields map[string]any) ([]byte, error) { + var b strings.Builder + b.WriteByte('{') + writeKV(&b, "time", t.Format(time.RFC3339Nano), true) + writeKV(&b, "level", level, false) + writeKV(&b, "event", event, false) + + keys := make([]string, 0, len(fields)) + for k := range fields { + switch k { + case "time", "level", "event": + continue + } + keys = append(keys, k) + } + sort.Strings(keys) + for _, k := range keys { + val, err := json.Marshal(fields[k]) + if err != nil { + return nil, err + } + key, err := json.Marshal(k) + if err != nil { + return nil, err + } + b.WriteByte(',') + b.Write(key) + b.WriteByte(':') + b.Write(val) + } + b.WriteString("}\n") + return []byte(b.String()), nil +} + +func writeKV(b *strings.Builder, key, value string, first bool) { + if !first { + b.WriteByte(',') + } + k, _ := json.Marshal(key) + v, _ := json.Marshal(value) + b.Write(k) + b.WriteByte(':') + b.Write(v) +} diff --git a/pkg/runlog/runlog_test.go b/pkg/runlog/runlog_test.go new file mode 100644 index 0000000..1d3f7d5 --- /dev/null +++ b/pkg/runlog/runlog_test.go @@ -0,0 +1,210 @@ +package runlog + +import ( + "bytes" + "encoding/json" + "errors" + "os" + "path/filepath" + "strings" + "testing" + "time" +) + +func TestLoggerWritesJSONLRecords(t *testing.T) { + var buf bytes.Buffer + l := New(&buf) + fixed := time.Date(2026, 7, 14, 18, 0, 0, 0, time.UTC) + l.now = func() time.Time { return fixed } + + l.Info("run_start", map[string]any{"engine": "copilot", "retries": 1}) + l.Error("detection_failed", map[string]any{"reason": "engine_error"}) + + lines := strings.Split(strings.TrimRight(buf.String(), "\n"), "\n") + if len(lines) != 2 { + t.Fatalf("expected 2 lines, got %d: %q", len(lines), buf.String()) + } + + var first map[string]any + if err := json.Unmarshal([]byte(lines[0]), &first); err != nil { + t.Fatalf("line 0 is not valid JSON: %v", err) + } + if first["time"] != "2026-07-14T18:00:00Z" { + t.Errorf("time = %v, want 2026-07-14T18:00:00Z", first["time"]) + } + if first["level"] != LevelInfo { + t.Errorf("level = %v, want %s", first["level"], LevelInfo) + } + if first["event"] != "run_start" { + t.Errorf("event = %v, want run_start", first["event"]) + } + if first["engine"] != "copilot" { + t.Errorf("engine = %v, want copilot", first["engine"]) + } + + var second map[string]any + if err := json.Unmarshal([]byte(lines[1]), &second); err != nil { + t.Fatalf("line 1 is not valid JSON: %v", err) + } + if second["level"] != LevelError { + t.Errorf("level = %v, want %s", second["level"], LevelError) + } +} + +func TestLoggerLeadingKeyOrder(t *testing.T) { + var buf bytes.Buffer + l := New(&buf) + l.now = func() time.Time { return time.Unix(0, 0).UTC() } + l.Info("evt", map[string]any{"zeta": 1, "alpha": 2}) + + line := strings.TrimRight(buf.String(), "\n") + // time, then level, then event must lead; remaining fields sorted. + wantOrder := []string{`"time"`, `"level"`, `"event"`, `"alpha"`, `"zeta"`} + prev := -1 + for _, key := range wantOrder { + idx := strings.Index(line, key) + if idx < 0 { + t.Fatalf("key %s missing from %q", key, line) + } + if idx < prev { + t.Fatalf("key %s out of order in %q", key, line) + } + prev = idx + } +} + +func TestReservedFieldsCannotBeShadowed(t *testing.T) { + var buf bytes.Buffer + l := New(&buf) + l.now = func() time.Time { return time.Date(2026, 1, 1, 0, 0, 0, 0, time.UTC) } + l.Info("evt", map[string]any{"event": "override", "level": "override", "time": "override"}) + + var rec map[string]any + if err := json.Unmarshal([]byte(strings.TrimRight(buf.String(), "\n")), &rec); err != nil { + t.Fatalf("invalid JSON: %v", err) + } + if rec["event"] != "evt" { + t.Errorf("event = %v, want evt (reserved key must not be shadowed)", rec["event"]) + } + if rec["level"] != LevelInfo { + t.Errorf("level = %v, want %s", rec["level"], LevelInfo) + } + if rec["time"] != "2026-01-01T00:00:00Z" { + t.Errorf("time = %v, want fixed timestamp", rec["time"]) + } +} + +func TestNilLoggerIsNoOp(t *testing.T) { + var l *Logger + // None of these must panic. + l.Info("evt", map[string]any{"a": 1}) + l.Error("evt", nil) + if err := l.Close(); err != nil { + t.Fatalf("Close() on nil logger error = %v", err) + } +} + +func TestOpenCreatesFileWith0600(t *testing.T) { + path := filepath.Join(t.TempDir(), "run.jsonl") + l, err := Open(path) + if err != nil { + t.Fatalf("Open() error = %v", err) + } + l.Info("run_start", map[string]any{"engine": "claude"}) + if err := l.Close(); err != nil { + t.Fatalf("Close() error = %v", err) + } + + info, err := os.Stat(path) + if err != nil { + t.Fatalf("stat error = %v", err) + } + if perm := info.Mode().Perm(); perm != 0o600 { + t.Fatalf("file perm = %o, want 600", perm) + } + + data, err := os.ReadFile(path) + if err != nil { + t.Fatalf("read error = %v", err) + } + var rec map[string]any + if err := json.Unmarshal([]byte(strings.TrimRight(string(data), "\n")), &rec); err != nil { + t.Fatalf("file content is not valid JSONL: %v", err) + } + if rec["event"] != "run_start" { + t.Errorf("event = %v, want run_start", rec["event"]) + } +} + +func TestOpenTruncatesExistingFile(t *testing.T) { + path := filepath.Join(t.TempDir(), "run.jsonl") + if err := os.WriteFile(path, []byte("stale content\n"), 0o600); err != nil { + t.Fatalf("seed write error = %v", err) + } + l, err := Open(path) + if err != nil { + t.Fatalf("Open() error = %v", err) + } + l.Info("fresh", nil) + if err := l.Close(); err != nil { + t.Fatalf("Close() error = %v", err) + } + data, err := os.ReadFile(path) + if err != nil { + t.Fatalf("read error = %v", err) + } + if strings.Contains(string(data), "stale content") { + t.Fatalf("file was not truncated: %q", string(data)) + } +} + +func TestOpenTightensExistingPermissions(t *testing.T) { + path := filepath.Join(t.TempDir(), "run.jsonl") + // Seed a pre-existing world-readable file; Open must tighten it to 0600 + // even though O_CREATE's mode only applies to newly created files. + if err := os.WriteFile(path, []byte("old\n"), 0o644); err != nil { + t.Fatalf("seed write error = %v", err) + } + l, err := Open(path) + if err != nil { + t.Fatalf("Open() error = %v", err) + } + if err := l.Close(); err != nil { + t.Fatalf("Close() error = %v", err) + } + info, err := os.Stat(path) + if err != nil { + t.Fatalf("stat error = %v", err) + } + if perm := info.Mode().Perm(); perm != 0o600 { + t.Fatalf("file perm = %o, want 600", perm) + } +} + +// failingWriter returns an error on the Nth write onward. +type failingWriter struct { + failFrom int + count int +} + +func (w *failingWriter) Write(p []byte) (int, error) { + w.count++ + if w.count >= w.failFrom { + return 0, errors.New("disk full") + } + return len(p), nil +} + +func TestCloseSurfacesFirstWriteError(t *testing.T) { + fw := &failingWriter{failFrom: 2} + l := New(fw) + l.Info("ok", nil) // succeeds + l.Info("boom", nil) // fails + l.Info("boom2", nil) // also fails, but first error must be preserved + if err := l.Close(); err == nil { + t.Fatal("Close() error = nil, want the recorded write error") + } else if !strings.Contains(err.Error(), "disk full") { + t.Fatalf("Close() error = %v, want disk full", err) + } +} + diff --git a/specs/threat-detection-spec.md b/specs/threat-detection-spec.md index a1dadb3..bb7ec7c 100644 --- a/specs/threat-detection-spec.md +++ b/specs/threat-detection-spec.md @@ -170,6 +170,16 @@ threat-detection: **TD-20**: The detector MUST support writing the result to a file via the `--output` flag. +**TD-20a**: The detector MUST support writing a structured run log in JSON Lines +(JSONL) format to a file via the `--log-file` flag (also configurable through the +`THREAT_DETECTION_LOG_FILE` environment variable). When enabled, the detector MUST +write one JSON object per line, each containing at least the `time`, `level`, and +`event` keys, and MUST record a terminal `status` event whose `reason` and `exit` +fields carry the same reason string and exit code as the stderr status line. The +run log is an additive observability +sink: it MUST NOT alter the result JSON contract (TD-08) or the exit codes (TD-21). +A failure to open the log file MUST be treated as a configuration error. + **TD-20b**: The detector MUST provide a `conclude` subcommand that reads a structured result file written by a prior detection run and emits the host-side job-output contract (`conclusion`, `reason`, `success`) consumed by the parent orchestrator.