feat(audit): Phase 7 - Tests, docs, and initialization
Add comprehensive test suite and documentation: - logger_test.go: Unit tests for logger, filtering, context propagation - README.md: Complete package documentation - Add audit.InitGlobal() in gateway startup - Add graceful shutdown with audit.CloseGlobal() Tests cover: - Logger creation and lifecycle - Event filtering by type - Context propagation (request/session/agent IDs) - Nil safety for all public methods - Global logger initialization Fixes: - Add nil checks to Log() and Close() methods - Ensure safe concurrent access
This commit is contained in:
parent
fa590585ca
commit
723e20d70b
4 changed files with 419 additions and 0 deletions
|
|
@ -11,6 +11,7 @@ import (
|
||||||
|
|
||||||
"github.com/sipeed/picoclaw/cmd/picoclaw/internal"
|
"github.com/sipeed/picoclaw/cmd/picoclaw/internal"
|
||||||
"github.com/sipeed/picoclaw/pkg/agent"
|
"github.com/sipeed/picoclaw/pkg/agent"
|
||||||
|
"github.com/sipeed/picoclaw/pkg/audit"
|
||||||
"github.com/sipeed/picoclaw/pkg/bus"
|
"github.com/sipeed/picoclaw/pkg/bus"
|
||||||
"github.com/sipeed/picoclaw/pkg/channels"
|
"github.com/sipeed/picoclaw/pkg/channels"
|
||||||
_ "github.com/sipeed/picoclaw/pkg/channels/dingtalk"
|
_ "github.com/sipeed/picoclaw/pkg/channels/dingtalk"
|
||||||
|
|
@ -49,6 +50,15 @@ func gatewayCmd(debug bool) error {
|
||||||
return fmt.Errorf("error loading config: %w", err)
|
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)
|
provider, _, err := providers.CreateProvider(cfg)
|
||||||
if err != nil {
|
if err != nil {
|
||||||
return fmt.Errorf("error creating provider: %w", err)
|
return fmt.Errorf("error creating provider: %w", err)
|
||||||
|
|
|
||||||
157
pkg/audit/README.md
Normal file
157
pkg/audit/README.md
Normal file
|
|
@ -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
|
||||||
|
|
@ -88,7 +88,12 @@ func New(cfg config.AuditConfig, workspace string) (*Logger, error) {
|
||||||
// Log writes a single audit entry.
|
// Log writes a single audit entry.
|
||||||
// This method is non-blocking; the entry is queued for async writing.
|
// 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.
|
// 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) {
|
func (l *Logger) Log(entry *Entry) {
|
||||||
|
if l == nil {
|
||||||
|
return
|
||||||
|
}
|
||||||
|
|
||||||
l.mu.RLock()
|
l.mu.RLock()
|
||||||
if l.closed {
|
if l.closed {
|
||||||
l.mu.RUnlock()
|
l.mu.RUnlock()
|
||||||
|
|
@ -233,7 +238,12 @@ func (l *Logger) LogWithChannel(ctx context.Context, entry *Entry) {
|
||||||
// Close gracefully shuts down the audit logger.
|
// Close gracefully shuts down the audit logger.
|
||||||
// It flushes any pending entries and closes the log file.
|
// It flushes any pending entries and closes the log file.
|
||||||
// This method blocks until all pending entries are written.
|
// This method blocks until all pending entries are written.
|
||||||
|
// Safe to call on nil logger (returns nil).
|
||||||
func (l *Logger) Close() error {
|
func (l *Logger) Close() error {
|
||||||
|
if l == nil {
|
||||||
|
return nil
|
||||||
|
}
|
||||||
|
|
||||||
l.mu.Lock()
|
l.mu.Lock()
|
||||||
if l.closed {
|
if l.closed {
|
||||||
l.mu.Unlock()
|
l.mu.Unlock()
|
||||||
|
|
|
||||||
242
pkg/audit/logger_test.go
Normal file
242
pkg/audit/logger_test.go
Normal file
|
|
@ -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")
|
||||||
|
}
|
||||||
|
}
|
||||||
Loading…
Add table
Reference in a new issue