init

2026-08-28 11:29:58 +02:00
parent 5cf698e632
commit 112c13f9f0
35 changed files with 11409 additions and 1 deletions
@@ -0,0 +1,314 @@
+package debugtrace
+
+import (
+	"bufio"
+	"context"
+	"crypto/rand"
+	"encoding/hex"
+	"encoding/json"
+	"errors"
+	"fmt"
+	"io"
+	"os"
+	"path/filepath"
+	"sort"
+	"strings"
+	"sync"
+	"time"
+)
+
+type contextKey struct{}
+
+type Config struct {
+	Enabled      bool   `json:"enabled"`
+	Dir          string `json:"dir"`
+	MaxBytes     int64  `json:"maxBytes"`
+	KeepFiles    int    `json:"keepFiles"`
+	MaxString    int    `json:"maxString"`
+	LogHTTPState bool   `json:"logHttpState"`
+}
+
+type Event struct {
+	Schema     string `json:"schema"`
+	Timestamp  string `json:"timestamp"`
+	TraceID    string `json:"trace_id"`
+	Component  string `json:"component"`
+	Stage      string `json:"stage"`
+	Direction  string `json:"direction,omitempty"`
+	Level      string `json:"level,omitempty"`
+	DurationMS int64  `json:"duration_ms,omitempty"`
+	Data       any    `json:"data,omitempty"`
+	Error      string `json:"error,omitempty"`
+}
+
+type Logger struct {
+	mu   sync.Mutex
+	cfg  Config
+	path string
+	file *os.File
+	size int64
+}
+
+func New(cfg Config) (*Logger, error) {
+	if cfg.Dir == "" {
+		cfg.Dir = "./data/debug"
+	}
+	if cfg.MaxBytes <= 0 {
+		cfg.MaxBytes = 25 << 20
+	}
+	if cfg.KeepFiles <= 0 {
+		cfg.KeepFiles = 4
+	}
+	if cfg.MaxString <= 0 {
+		cfg.MaxString = 24000
+	}
+	l := &Logger{cfg: cfg, path: filepath.Join(cfg.Dir, "jarvis-debug.jsonl")}
+	if !cfg.Enabled {
+		return l, nil
+	}
+	if err := os.MkdirAll(cfg.Dir, 0o755); err != nil {
+		return nil, err
+	}
+	f, err := os.OpenFile(l.path, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0o600)
+	if err != nil {
+		return nil, err
+	}
+	l.file = f
+	if st, err := f.Stat(); err == nil {
+		l.size = st.Size()
+	}
+	return l, nil
+}
+
+func (l *Logger) Config() Config { return l.cfg }
+func (l *Logger) Enabled() bool  { return l != nil && l.cfg.Enabled }
+
+func NewTraceID(prefix string) string {
+	if strings.TrimSpace(prefix) == "" {
+		prefix = "trace"
+	}
+	var b [6]byte
+	if _, err := rand.Read(b[:]); err == nil {
+		return fmt.Sprintf("%s_%d_%s", prefix, time.Now().UnixMilli(), hex.EncodeToString(b[:]))
+	}
+	return fmt.Sprintf("%s_%d", prefix, time.Now().UnixNano())
+}
+
+func WithTrace(ctx context.Context, traceID string) context.Context {
+	if strings.TrimSpace(traceID) == "" {
+		traceID = NewTraceID("trace")
+	}
+	return context.WithValue(ctx, contextKey{}, traceID)
+}
+func TraceID(ctx context.Context) string {
+	if ctx == nil {
+		return ""
+	}
+	if v, ok := ctx.Value(contextKey{}).(string); ok {
+		return v
+	}
+	return ""
+}
+func EnsureTrace(ctx context.Context, prefix string) (context.Context, string) {
+	if id := TraceID(ctx); id != "" {
+		return ctx, id
+	}
+	id := NewTraceID(prefix)
+	return WithTrace(ctx, id), id
+}
+
+func (l *Logger) Record(ctx context.Context, component, stage, direction, level string, data any, err error, duration time.Duration) {
+	if !l.Enabled() {
+		return
+	}
+	traceID := TraceID(ctx)
+	if traceID == "" {
+		traceID = NewTraceID("bg")
+	}
+	ev := Event{Schema: "jarvis.debug.v1", Timestamp: time.Now().Format(time.RFC3339Nano), TraceID: traceID, Component: component, Stage: stage, Direction: direction, Level: level, Data: l.sanitize(data)}
+	if err != nil {
+		ev.Error = err.Error()
+	}
+	if duration > 0 {
+		ev.DurationMS = duration.Milliseconds()
+	}
+	b, merr := json.Marshal(ev)
+	if merr != nil {
+		return
+	}
+	l.mu.Lock()
+	defer l.mu.Unlock()
+	if l.file == nil {
+		return
+	}
+	if l.size+int64(len(b)+1) > l.cfg.MaxBytes {
+		_ = l.rotateLocked()
+	}
+	n, werr := l.file.Write(append(b, '\n'))
+	if werr == nil {
+		l.size += int64(n)
+	}
+}
+
+func (l *Logger) rotateLocked() error {
+	if l.file != nil {
+		_ = l.file.Close()
+		l.file = nil
+	}
+	for i := l.cfg.KeepFiles - 1; i >= 1; i-- {
+		old := fmt.Sprintf("%s.%d", l.path, i)
+		next := fmt.Sprintf("%s.%d", l.path, i+1)
+		if i == l.cfg.KeepFiles-1 {
+			_ = os.Remove(next)
+		}
+		_ = os.Rename(old, next)
+	}
+	_ = os.Rename(l.path, l.path+".1")
+	f, err := os.OpenFile(l.path, os.O_CREATE|os.O_TRUNC|os.O_WRONLY, 0o600)
+	if err != nil {
+		return err
+	}
+	l.file = f
+	l.size = 0
+	return nil
+}
+
+func (l *Logger) sanitize(v any) any {
+	b, err := json.Marshal(v)
+	if err != nil {
+		return fmt.Sprint(v)
+	}
+	var x any
+	if err := json.Unmarshal(b, &x); err != nil {
+		return string(b)
+	}
+	return sanitizeValue(x, l.cfg.MaxString)
+}
+func sanitizeValue(v any, max int) any {
+	switch x := v.(type) {
+	case map[string]any:
+		out := make(map[string]any, len(x))
+		for k, val := range x {
+			lk := strings.ToLower(k)
+			if secretKey(lk) {
+				out[k] = "[REDACTED]"
+			} else {
+				out[k] = sanitizeValue(val, max)
+			}
+		}
+		return out
+	case []any:
+		out := make([]any, len(x))
+		for i := range x {
+			out[i] = sanitizeValue(x[i], max)
+		}
+		return out
+	case string:
+		if max > 0 && len([]rune(x)) > max {
+			r := []rune(x)
+			return string(r[:max]) + fmt.Sprintf("\n[… %d chars truncated …]", len(r)-max)
+		}
+		return x
+	default:
+		return v
+	}
+}
+func secretKey(k string) bool {
+	for _, s := range []string{"password", "passwd", "authorization", "api_key", "apikey", "secret", "bearer", "cookie"} {
+		if strings.Contains(k, s) {
+			return true
+		}
+	}
+	return false
+}
+
+func (l *Logger) Clear() error {
+	if !l.Enabled() {
+		return nil
+	}
+	l.mu.Lock()
+	defer l.mu.Unlock()
+	if l.file != nil {
+		_ = l.file.Close()
+		l.file = nil
+	}
+	matches, _ := filepath.Glob(filepath.Join(l.cfg.Dir, "jarvis-debug.jsonl*"))
+	for _, p := range matches {
+		_ = os.Remove(p)
+	}
+	f, err := os.OpenFile(l.path, os.O_CREATE|os.O_TRUNC|os.O_WRONLY, 0o600)
+	if err != nil {
+		return err
+	}
+	l.file = f
+	l.size = 0
+	return nil
+}
+
+func (l *Logger) Events(limit int) ([]json.RawMessage, error) {
+	if !l.Enabled() {
+		return []json.RawMessage{}, nil
+	}
+	l.mu.Lock()
+	if l.file != nil {
+		_ = l.file.Sync()
+	}
+	l.mu.Unlock()
+	paths := []string{}
+	for i := l.cfg.KeepFiles; i >= 1; i-- {
+		p := fmt.Sprintf("%s.%d", l.path, i)
+		if _, err := os.Stat(p); err == nil {
+			paths = append(paths, p)
+		}
+	}
+	if _, err := os.Stat(l.path); err == nil {
+		paths = append(paths, l.path)
+	}
+	events := []json.RawMessage{}
+	for _, p := range paths {
+		f, err := os.Open(p)
+		if err != nil {
+			continue
+		}
+		sc := bufio.NewScanner(f)
+		sc.Buffer(make([]byte, 64*1024), 4<<20)
+		for sc.Scan() {
+			line := append([]byte(nil), sc.Bytes()...)
+			if json.Valid(line) {
+				events = append(events, json.RawMessage(line))
+			}
+		}
+		_ = f.Close()
+	}
+	if limit > 0 && len(events) > limit {
+		events = events[len(events)-limit:]
+	}
+	return events, nil
+}
+
+func (l *Logger) WriteJSONL(w io.Writer, limit int) error {
+	events, err := l.Events(limit)
+	if err != nil {
+		return err
+	}
+	for _, e := range events {
+		if _, err := w.Write(append(e, '\n')); err != nil {
+			return err
+		}
+	}
+	return nil
+}
+
+func (l *Logger) Files() ([]string, error) {
+	if !l.Enabled() {
+		return nil, nil
+	}
+	matches, err := filepath.Glob(filepath.Join(l.cfg.Dir, "jarvis-debug.jsonl*"))
+	if err != nil {
+		return nil, err
+	}
+	sort.Strings(matches)
+	return matches, nil
+}
+
+var ErrDisabled = errors.New("debug tracing disabled")
@@ -0,0 +1,57 @@
+package debugtrace
+
+import (
+	"context"
+	"encoding/json"
+	"strings"
+	"testing"
+)
+
+func TestLoggerWritesTraceAndRedactsSecrets(t *testing.T) {
+	l, err := New(Config{Enabled: true, Dir: t.TempDir(), MaxBytes: 1 << 20, KeepFiles: 2, MaxString: 1000})
+	if err != nil {
+		t.Fatal(err)
+	}
+	ctx := WithTrace(context.Background(), "trace_test")
+	l.Record(ctx, "planner", "request", "input", "info", map[string]any{"message": "Montag Nudeln", "authorization": "Bearer secret"}, nil, 0)
+	evs, err := l.Events(10)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(evs) != 1 {
+		t.Fatalf("events=%d", len(evs))
+	}
+	var ev Event
+	if err := json.Unmarshal(evs[0], &ev); err != nil {
+		t.Fatal(err)
+	}
+	if ev.TraceID != "trace_test" || ev.Component != "planner" || ev.Stage != "request" {
+		t.Fatalf("event=%+v", ev)
+	}
+	b, _ := json.Marshal(ev.Data)
+	s := string(b)
+	if strings.Contains(s, "Bearer secret") || !strings.Contains(s, "REDACTED") {
+		t.Fatalf("secret not redacted: %s", s)
+	}
+	if !strings.Contains(s, "Montag Nudeln") {
+		t.Fatalf("message missing: %s", s)
+	}
+}
+
+func TestLoggerClear(t *testing.T) {
+	l, err := New(Config{Enabled: true, Dir: t.TempDir()})
+	if err != nil {
+		t.Fatal(err)
+	}
+	l.Record(WithTrace(context.Background(), "x"), "http", "request", "input", "info", map[string]any{"a": 1}, nil, 0)
+	if err := l.Clear(); err != nil {
+		t.Fatal(err)
+	}
+	evs, err := l.Events(10)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(evs) != 0 {
+		t.Fatalf("events=%d", len(evs))
+	}
+}