Add comprehensive trace logging and observability features: - Enhanced trace store with owner-scoped queries, filtering (agent, action, time range), pagination, streaming export, and retention cleanup - REST API endpoints: GET /api/traces (list with filters), GET /api/traces/export (streaming JSON/CSV), GET /api/traces/stats (action counts) - Owner isolation enforced at every layer (store, API, tests) - Hand-rolled Prometheus metrics (pure Go, zero CGO): traces_total, traces_by_action, errors_total, active_agents at GET /metrics - Configurable slog JSON handler with --log-level flag - Request ID middleware for cross-referencing logs and traces - Batch trace writing (64 entries or 100ms flush interval) - Background retention cleanup via --trace-retention flag - SQL migration 002 adds owner_id column and composite indexes Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
275 lines
6.2 KiB
Go
275 lines
6.2 KiB
Go
package trace
|
|
|
|
import (
|
|
"context"
|
|
"database/sql"
|
|
"fmt"
|
|
"testing"
|
|
"time"
|
|
|
|
_ "modernc.org/sqlite"
|
|
)
|
|
|
|
func newTestDB(t *testing.T) *sql.DB {
|
|
t.Helper()
|
|
db, err := sql.Open("sqlite", ":memory:")
|
|
if err != nil {
|
|
t.Fatalf("open database: %v", err)
|
|
}
|
|
t.Cleanup(func() { db.Close() })
|
|
|
|
// Create traces table with owner_id (matches migration 001 + 002)
|
|
_, err = db.Exec(`
|
|
CREATE TABLE IF NOT EXISTS traces (
|
|
id INTEGER PRIMARY KEY AUTOINCREMENT,
|
|
agent_name TEXT NOT NULL,
|
|
action TEXT NOT NULL,
|
|
details TEXT NOT NULL DEFAULT '{}',
|
|
error TEXT,
|
|
created_at TIMESTAMP NOT NULL DEFAULT CURRENT_TIMESTAMP,
|
|
owner_id TEXT NOT NULL DEFAULT ''
|
|
)
|
|
`)
|
|
if err != nil {
|
|
t.Fatalf("create traces table: %v", err)
|
|
}
|
|
|
|
return db
|
|
}
|
|
|
|
func TestTracer_Record(t *testing.T) {
|
|
tests := []struct {
|
|
name string
|
|
agent string
|
|
action string
|
|
details any
|
|
}{
|
|
{
|
|
name: "simple trace",
|
|
agent: "test-agent",
|
|
action: "send_message",
|
|
details: map[string]any{
|
|
"to": "other-agent",
|
|
"message": "hello",
|
|
},
|
|
},
|
|
{
|
|
name: "trace with nil details",
|
|
agent: "agent-a",
|
|
action: "read_inbox",
|
|
details: nil,
|
|
},
|
|
{
|
|
name: "trace with string details",
|
|
agent: "agent-b",
|
|
action: "search",
|
|
details: "query string",
|
|
},
|
|
}
|
|
|
|
for _, tt := range tests {
|
|
t.Run(tt.name, func(t *testing.T) {
|
|
db := newTestDB(t)
|
|
tracer := NewTracer(db)
|
|
defer tracer.Close()
|
|
|
|
ctx := context.Background()
|
|
tracer.Record(ctx, tt.agent, tt.action, tt.details)
|
|
|
|
// Give async writer time to process
|
|
time.Sleep(200 * time.Millisecond)
|
|
|
|
// Verify trace was written
|
|
var count int
|
|
err := db.QueryRow(
|
|
"SELECT COUNT(*) FROM traces WHERE agent_name = ? AND action = ?",
|
|
tt.agent, tt.action,
|
|
).Scan(&count)
|
|
if err != nil {
|
|
t.Fatalf("query trace: %v", err)
|
|
}
|
|
if count != 1 {
|
|
t.Errorf("trace count = %d, want 1", count)
|
|
}
|
|
})
|
|
}
|
|
}
|
|
|
|
func TestTracer_RecordWithOwner(t *testing.T) {
|
|
db := newTestDB(t)
|
|
tracer := NewTracer(db)
|
|
defer tracer.Close()
|
|
|
|
ctx := context.Background()
|
|
tracer.RecordWithOwner(ctx, "42", "test-agent", "send_message", map[string]any{"to": "other"})
|
|
|
|
time.Sleep(200 * time.Millisecond)
|
|
|
|
var ownerID string
|
|
err := db.QueryRow(
|
|
"SELECT owner_id FROM traces WHERE agent_name = 'test-agent'",
|
|
).Scan(&ownerID)
|
|
if err != nil {
|
|
t.Fatalf("query trace: %v", err)
|
|
}
|
|
if ownerID != "42" {
|
|
t.Errorf("owner_id = %q, want %q", ownerID, "42")
|
|
}
|
|
}
|
|
|
|
func TestTracer_RecordError(t *testing.T) {
|
|
db := newTestDB(t)
|
|
tracer := NewTracer(db)
|
|
defer tracer.Close()
|
|
|
|
ctx := context.Background()
|
|
tracer.RecordError(ctx, "test-agent", "failed_action",
|
|
map[string]any{"key": "value"},
|
|
fmt.Errorf("something went wrong"),
|
|
)
|
|
|
|
time.Sleep(200 * time.Millisecond)
|
|
|
|
var errorText sql.NullString
|
|
err := db.QueryRow(
|
|
"SELECT error FROM traces WHERE agent_name = 'test-agent' AND action = 'failed_action'",
|
|
).Scan(&errorText)
|
|
if err != nil {
|
|
t.Fatalf("query trace: %v", err)
|
|
}
|
|
if !errorText.Valid || errorText.String != "something went wrong" {
|
|
t.Errorf("error = %v, want 'something went wrong'", errorText)
|
|
}
|
|
}
|
|
|
|
func TestTracer_BatchFlush(t *testing.T) {
|
|
db := newTestDB(t)
|
|
tracer := NewTracer(db)
|
|
|
|
ctx := context.Background()
|
|
|
|
// Record multiple entries to trigger batch
|
|
for i := 0; i < 10; i++ {
|
|
tracer.Record(ctx, "batch-agent", "action", map[string]any{"i": i})
|
|
}
|
|
|
|
// Close flushes remaining entries
|
|
tracer.Close()
|
|
|
|
var count int
|
|
err := db.QueryRow("SELECT COUNT(*) FROM traces WHERE agent_name = 'batch-agent'").Scan(&count)
|
|
if err != nil {
|
|
t.Fatalf("query: %v", err)
|
|
}
|
|
if count != 10 {
|
|
t.Errorf("got %d traces, want 10", count)
|
|
}
|
|
}
|
|
|
|
func TestTracer_GracefulShutdownFlushes(t *testing.T) {
|
|
db := newTestDB(t)
|
|
tracer := NewTracer(db)
|
|
|
|
ctx := context.Background()
|
|
|
|
// Record entries
|
|
tracer.Record(ctx, "shutdown-agent", "action1", nil)
|
|
tracer.Record(ctx, "shutdown-agent", "action2", nil)
|
|
|
|
// Close should flush
|
|
tracer.Close()
|
|
|
|
var count int
|
|
err := db.QueryRow("SELECT COUNT(*) FROM traces WHERE agent_name = 'shutdown-agent'").Scan(&count)
|
|
if err != nil {
|
|
t.Fatalf("query: %v", err)
|
|
}
|
|
if count != 2 {
|
|
t.Errorf("got %d traces after shutdown, want 2", count)
|
|
}
|
|
}
|
|
|
|
func TestTracer_RecordReturnsImmediately(t *testing.T) {
|
|
db := newTestDB(t)
|
|
tracer := NewTracer(db)
|
|
defer tracer.Close()
|
|
|
|
ctx := context.Background()
|
|
|
|
start := time.Now()
|
|
tracer.Record(ctx, "fast-agent", "action", nil)
|
|
elapsed := time.Since(start)
|
|
|
|
// Record should return in under 5ms (it's async)
|
|
if elapsed > 5*time.Millisecond {
|
|
t.Errorf("Record took %v, expected < 5ms (should be non-blocking)", elapsed)
|
|
}
|
|
}
|
|
|
|
func TestTracer_Metrics(t *testing.T) {
|
|
db := newTestDB(t)
|
|
tracer := NewTracer(db)
|
|
|
|
metrics := NewMetrics()
|
|
tracer.SetMetrics(metrics)
|
|
|
|
ctx := context.Background()
|
|
tracer.RecordWithOwner(ctx, "1", "agent", "send_message", nil)
|
|
tracer.RecordErrorWithOwner(ctx, "1", "agent", "error", nil, fmt.Errorf("boom"))
|
|
|
|
tracer.Close()
|
|
|
|
if got := metrics.tracesTotal.Load(); got != 2 {
|
|
t.Errorf("tracesTotal = %d, want 2", got)
|
|
}
|
|
if got := metrics.errorsTotal.Load(); got != 1 {
|
|
t.Errorf("errorsTotal = %d, want 1", got)
|
|
}
|
|
}
|
|
|
|
func TestTraceStore(t *testing.T) {
|
|
db := newTestDB(t)
|
|
tracer := NewTracer(db)
|
|
|
|
ctx := context.Background()
|
|
|
|
// Record some traces
|
|
tracer.Record(ctx, "agent-a", "send_message", map[string]any{"to": "agent-b"})
|
|
tracer.Record(ctx, "agent-a", "read_inbox", map[string]any{"count": 5})
|
|
tracer.Record(ctx, "agent-b", "send_message", map[string]any{"to": "agent-a"})
|
|
|
|
tracer.Close() // flush all entries
|
|
|
|
store := NewSQLiteTraceStore(db)
|
|
|
|
t.Run("get traces by agent", func(t *testing.T) {
|
|
traces, err := store.GetTraces(ctx, "agent-a", 10)
|
|
if err != nil {
|
|
t.Fatalf("GetTraces: %v", err)
|
|
}
|
|
if len(traces) != 2 {
|
|
t.Errorf("got %d traces, want 2", len(traces))
|
|
}
|
|
})
|
|
|
|
t.Run("get traces by action", func(t *testing.T) {
|
|
traces, err := store.GetTracesByAction(ctx, "send_message", 10)
|
|
if err != nil {
|
|
t.Fatalf("GetTracesByAction: %v", err)
|
|
}
|
|
if len(traces) != 2 {
|
|
t.Errorf("got %d traces, want 2", len(traces))
|
|
}
|
|
})
|
|
|
|
t.Run("limit results", func(t *testing.T) {
|
|
traces, err := store.GetTraces(ctx, "agent-a", 1)
|
|
if err != nil {
|
|
t.Fatalf("GetTraces: %v", err)
|
|
}
|
|
if len(traces) != 1 {
|
|
t.Errorf("got %d traces, want 1", len(traces))
|
|
}
|
|
})
|
|
}
|