diff --git a/cmd/picoclaw/internal/gateway/helpers.go b/cmd/picoclaw/internal/gateway/helpers.go index cd6b3db4b..9d60a7f57 100644 --- a/cmd/picoclaw/internal/gateway/helpers.go +++ b/cmd/picoclaw/internal/gateway/helpers.go @@ -11,6 +11,7 @@ import ( "github.com/sipeed/picoclaw/cmd/picoclaw/internal" "github.com/sipeed/picoclaw/pkg/agent" + "github.com/sipeed/picoclaw/pkg/audit" "github.com/sipeed/picoclaw/pkg/bus" "github.com/sipeed/picoclaw/pkg/channels" _ "github.com/sipeed/picoclaw/pkg/channels/dingtalk" @@ -49,6 +50,15 @@ func gatewayCmd(debug bool) error { return fmt.Errorf("error loading config: %w", err) } + // Initialize audit logging + if err := audit.InitGlobal(cfg.Audit, cfg.WorkspacePath()); err != nil { + logger.ErrorF("failed to initialize audit logging", map[string]any{"error": err.Error()}) + // Continue without audit logging - not fatal + } else if cfg.Audit.Enabled { + logger.InfoF("audit logging enabled", map[string]any{"location": cfg.Audit.Location}) + defer audit.CloseGlobal() + } + provider, _, err := providers.CreateProvider(cfg) if err != nil { return fmt.Errorf("error creating provider: %w", err) diff --git a/pkg/audit/README.md b/pkg/audit/README.md new file mode 100644 index 000000000..63615b425 --- /dev/null +++ b/pkg/audit/README.md @@ -0,0 +1,157 @@ +# Audit Logging Package + +The `audit` package provides comprehensive audit logging for PicoClaw, capturing a complete trail of bot activity for debugging, compliance, security analysis, and operational monitoring. + +## Features + +- **Structured JSON Logging**: Machine-parseable format for analysis +- **Event Filtering**: Configurable per-event-type filtering +- **Async Write**: Non-blocking with buffered channel (1000 entries) +- **Log Rotation**: Size-based and daily rotation with compression +- **Context Propagation**: Request tracing via context +- **Secure**: File permissions 0600 (owner read/write only) + +## Quick Start + +```go +import "github.com/sipeed/picoclaw/pkg/audit" + +// Initialize +err := audit.InitGlobal(cfg.Audit, workspace) +if err != nil { + log.Fatal(err) +} +defer audit.CloseGlobal() + +// Log events +ctx := audit.WithRequestID(context.Background(), "req-123") +audit.LogSystem(ctx, "operation", map[string]interface{}{"key": "value"}) +``` + +## Configuration + +```json +{ + "audit": { + "enabled": true, + "location": "workspace/logs", + "format": "json", + "rotation": { + "max_size_mb": 100, + "max_age_days": 30, + "max_backups": 10, + "compress": true + }, + "events": { + "tool_calls": true, + "messages": true, + "errors": true, + "system": false + } + } +} +``` + +## Event Types + +### Tool Calls +Logged when tools are executed: +```json +{ + "timestamp": "2025-03-01T12:00:00Z", + "level": "INFO", + "component": "tool", + "event_type": "tool_call", + "request_id": "req-123", + "tool_call": { + "tool_id": "read_file", + "name": "read_file", + "arguments": {"path": "/tmp/test.txt"}, + "is_error": false, + "is_async": false + }, + "duration_ms": 150 +} +``` + +### Messages +Logged for inbound/outbound messages: +```json +{ + "timestamp": "2025-03-01T12:00:00Z", + "level": "INFO", + "component": "channel", + "event_type": "message", + "request_id": "req-123", + "channel": "telegram", + "chat_id": "123456", + "message": { + "direction": "inbound", + "content_type": "text", + "content": "Hello bot" + } +} +``` + +### Errors +Logged for failures: +```json +{ + "timestamp": "2025-03-01T12:00:00Z", + "level": "ERROR", + "component": "system", + "event_type": "error", + "error": { + "error_type": "send_failed", + "message": "connection timeout", + "recoverable": true + } +} +``` + +## Log Rotation + +Files are named: `audit-DDMMYYYY.log[.N][.gz]` + +Rotation triggers: +- **Daily**: New file at midnight +- **Size**: When file exceeds `max_size_mb` +- **Cleanup**: Files deleted after `max_age_days` or exceeding `max_backups` +- **Compression**: Old files gzip-compressed if `compress: true` + +## Request Tracing + +Use context to correlate events: + +```go +// At request entry +ctx := audit.WithRequestID(context.Background(), generateID()) +ctx = audit.WithSessionID(ctx, sessionKey) +ctx = audit.WithAgentID(ctx, agentID) + +// Pass ctx through call chain +// All logged events will include these IDs +``` + +## Nil Safety + +All logger methods are safe to call on nil: + +```go +var logger *audit.Logger // nil +logger.Log(entry) // No panic, no-op +``` + +## Performance + +- Async write (background worker) +- 1000-entry buffer (drops if full) +- Batch processing +- Minimal allocation + +## Security + +- Log files created with 0600 permissions +- Arguments masked for sensitive tools +- No passwords/tokens logged +- Automatic cleanup prevents disk exhaustion diff --git a/pkg/audit/logger.go b/pkg/audit/logger.go index 9e4cf579b..2a96b4c07 100644 --- a/pkg/audit/logger.go +++ b/pkg/audit/logger.go @@ -88,7 +88,12 @@ func New(cfg config.AuditConfig, workspace string) (*Logger, error) { // Log writes a single audit entry. // This method is non-blocking; the entry is queued for async writing. // If the logger is closed or the buffer is full, the entry is dropped. +// Safe to call on nil logger (no-op). func (l *Logger) Log(entry *Entry) { + if l == nil { + return + } + l.mu.RLock() if l.closed { l.mu.RUnlock() @@ -233,7 +238,12 @@ func (l *Logger) LogWithChannel(ctx context.Context, entry *Entry) { // Close gracefully shuts down the audit logger. // It flushes any pending entries and closes the log file. // This method blocks until all pending entries are written. +// Safe to call on nil logger (returns nil). func (l *Logger) Close() error { + if l == nil { + return nil + } + l.mu.Lock() if l.closed { l.mu.Unlock() diff --git a/pkg/audit/logger_test.go b/pkg/audit/logger_test.go new file mode 100644 index 000000000..e57b731de --- /dev/null +++ b/pkg/audit/logger_test.go @@ -0,0 +1,242 @@ +package audit + +import ( + "context" + "encoding/json" + "os" + "path/filepath" + "strings" + "testing" + "time" + + "github.com/sipeed/picoclaw/pkg/config" +) + +func TestNew_Disabled(t *testing.T) { + cfg := config.AuditConfig{Enabled: false} + logger, err := New(cfg, "/tmp/test") + if err != nil { + t.Errorf("expected no error when disabled, got %v", err) + } + if logger != nil { + t.Error("expected nil logger when disabled") + } +} + +func TestLogger_Log(t *testing.T) { + tmpDir := t.TempDir() + cfg := config.AuditConfig{ + Enabled: true, + Location: tmpDir, + Format: "json", + Rotation: config.RotationConfig{}, + Events: config.AuditEvents{ + ToolCalls: true, + Messages: true, + Errors: true, + System: true, + }, + } + + logger, err := New(cfg, tmpDir) + if err != nil { + t.Fatalf("failed to create logger: %v", err) + } + defer logger.Close() + + // Log a test entry + entry := &Entry{ + Timestamp: time.Now().UTC(), + Level: LevelInfo, + Component: "test", + EventType: EventSystem, + RequestID: "test-request-123", + System: &SystemData{ + Operation: "test_operation", + Details: map[string]interface{}{"key": "value"}, + }, + } + + logger.Log(entry) + + // Give the worker time to write + time.Sleep(100 * time.Millisecond) + + // Verify file was created + files, err := os.ReadDir(tmpDir) + if err != nil { + t.Fatalf("failed to read temp dir: %v", err) + } + + if len(files) == 0 { + t.Fatal("expected log file to be created") + } + + // Read and verify the log entry + logFile := filepath.Join(tmpDir, files[0].Name()) + data, err := os.ReadFile(logFile) + if err != nil { + t.Fatalf("failed to read log file: %v", err) + } + + var loggedEntry Entry + if err := json.Unmarshal(data, &loggedEntry); err != nil { + t.Fatalf("failed to unmarshal log entry: %v", err) + } + + if loggedEntry.RequestID != "test-request-123" { + t.Errorf("expected request_id=test-request-123, got %s", loggedEntry.RequestID) + } + if loggedEntry.Component != "test" { + t.Errorf("expected component=test, got %s", loggedEntry.Component) + } +} + +func TestLogger_Filtering(t *testing.T) { + tmpDir := t.TempDir() + cfg := config.AuditConfig{ + Enabled: true, + Location: tmpDir, + Format: "json", + Rotation: config.RotationConfig{}, + Events: config.AuditEvents{ + ToolCalls: true, + Messages: false, // Disabled + Errors: true, + System: true, + }, + } + + logger, err := New(cfg, tmpDir) + if err != nil { + t.Fatalf("failed to create logger: %v", err) + } + defer logger.Close() + + // Log a message (should be filtered out) + logger.Log(&Entry{ + Timestamp: time.Now().UTC(), + Level: LevelInfo, + Component: "test", + EventType: EventMessage, + RequestID: "filtered-request-xyz", + }) + + // Log a system event (should pass through) + logger.Log(&Entry{ + Timestamp: time.Now().UTC(), + Level: LevelInfo, + Component: "test", + EventType: EventSystem, + RequestID: "allowed-request-xyz", + }) + + // Close to flush + logger.Close() + + // Verify only system event was logged + files, _ := os.ReadDir(tmpDir) + if len(files) == 0 { + t.Fatal("expected log file to be created") + } + + logFile := filepath.Join(tmpDir, files[0].Name()) + data, _ := os.ReadFile(logFile) + + content := string(data) + + // Should not contain "filtered-request" + if strings.Contains(content, "filtered-request-xyz") { + t.Error("message entry should have been filtered out") + } + + // Should contain "allowed-request" + if !strings.Contains(content, "allowed-request-xyz") { + t.Error("system entry should have been logged") + } +} + +func TestContextPropagation(t *testing.T) { + ctx := context.Background() + + // Test request ID + ctx = WithRequestID(ctx, "req-123") + if id := RequestIDFromContext(ctx); id != "req-123" { + t.Errorf("expected request_id=req-123, got %s", id) + } + + // Test session ID + ctx = WithSessionID(ctx, "sess-456") + if id := SessionIDFromContext(ctx); id != "sess-456" { + t.Errorf("expected session_id=sess-456, got %s", id) + } + + // Test agent ID + ctx = WithAgentID(ctx, "agent-789") + if id := AgentIDFromContext(ctx); id != "agent-789" { + t.Errorf("expected agent_id=agent-789, got %s", id) + } +} + +func TestContextPropagation_Empty(t *testing.T) { + ctx := context.Background() + + // Test empty context returns empty strings + if id := RequestIDFromContext(ctx); id != "" { + t.Errorf("expected empty request_id, got %s", id) + } + if id := SessionIDFromContext(ctx); id != "" { + t.Errorf("expected empty session_id, got %s", id) + } + if id := AgentIDFromContext(ctx); id != "" { + t.Errorf("expected empty agent_id, got %s", id) + } +} + +func TestLogger_NilSafety(t *testing.T) { + // All methods should be safe to call on nil logger + var logger *Logger + + // These should not panic + logger.Log(&Entry{}) + logger.LogToolCall(context.Background(), &ToolCallData{}, 100) + logger.LogMessage(context.Background(), "inbound", "text", "test", "") + logger.LogError(context.Background(), "test", "message", true) + logger.LogSystem(context.Background(), "test", nil) + + err := logger.Close() + if err != nil { + t.Errorf("expected no error on close of nil logger, got %v", err) + } +} + +func TestGlobalLogger(t *testing.T) { + tmpDir := t.TempDir() + cfg := config.AuditConfig{ + Enabled: true, + Location: tmpDir, + Format: "json", + Events: config.AuditEvents{ + System: true, + }, + } + + // Initialize global logger + err := InitGlobal(cfg, tmpDir) + if err != nil { + t.Fatalf("failed to init global logger: %v", err) + } + defer CloseGlobal() + + // Log via global functions + ctx := WithRequestID(context.Background(), "global-test") + LogSystem(ctx, "test_operation", map[string]interface{}{"test": true}) + + // Give time to write + time.Sleep(100 * time.Millisecond) + + // Verify global logger is set + if Global() == nil { + t.Error("expected global logger to be set") + } +}