From cd1ff9d4b66aeea137720d182a143359b982f2af01c09c4155943bcc7519a595 Mon Sep 17 00:00:00 2001 From: Lixen Wraith Date: Fri, 17 Jul 2026 12:53:28 -0400 Subject: [PATCH] v0.1.6 fix to formatter and sanitizer for async use, doc update --- constant.go | 5 +- doc/api.md | 16 +- doc/formatting.md | 96 ++++-- doc/getting-started.md | 48 ++- doc/quick-guide_lixenwraith_log.md | 518 ----------------------------- doc/storage.md | 24 +- format_test.go | 5 +- formatter/formatter.go | 352 +++++++++++--------- formatter/formatter_test.go | 113 ++++++- logger.go | 11 +- logger_test.go | 10 +- processor.go | 29 +- processor_test.go | 51 +-- sanitizer/sanitizer.go | 121 +++++-- sanitizer/sanitizer_test.go | 69 +++- 15 files changed, 678 insertions(+), 790 deletions(-) delete mode 100644 doc/quick-guide_lixenwraith_log.md diff --git a/constant.go b/constant.go index 7f7bcb1..a9c1bc5 100644 --- a/constant.go +++ b/constant.go @@ -28,6 +28,8 @@ const ( FlagShowTimestamp = formatter.FlagShowTimestamp FlagShowLevel = formatter.FlagShowLevel FlagStructuredJSON = formatter.FlagStructuredJSON + FlagNoTimestamp = formatter.FlagNoTimestamp + FlagNoLevel = formatter.FlagNoLevel FlagDefault = formatter.FlagDefault ) @@ -54,4 +56,5 @@ const ( // Factors to adjust check interval adaptiveIntervalFactor float64 = 1.5 // Slow down adaptiveSpeedUpFactor float64 = 0.8 // Speed up -) \ No newline at end of file +) + diff --git a/doc/api.md b/doc/api.md index 175d935..15ef933 100644 --- a/doc/api.md +++ b/doc/api.md @@ -267,13 +267,13 @@ if err != nil { func (l *Logger) Flush(timeout time.Duration) error ``` -Explicitly triggers a sync of the current log file buffer to disk. +Explicitly triggers a sync of the current log file buffer to disk. Uses **barrier semantics**: it guarantees that all log records enqueued *before* the `Flush` call are fully processed and formatted before the disk sync occurs and confirmation is returned. **Parameters:** - `timeout`: Maximum time to wait for flush completion **Returns:** -- `error`: Flush error if timeout exceeded +- `error`: Flush error if timeout exceeded or logger is uninitialized. **Example:** ```go @@ -331,10 +331,12 @@ level, err := log.Level("debug") // Returns -4 ```go const ( - FlagRaw = formatter.FlagRaw // Bypass formatting - FlagShowTimestamp = formatter.FlagShowTimestamp // Include timestamp - FlagShowLevel = formatter.FlagShowLevel // Include level - FlagStructuredJSON = formatter.FlagStructuredJSON // Structured JSON + FlagRaw = formatter.FlagRaw // Bypass formatting and sanitization + FlagShowTimestamp = formatter.FlagShowTimestamp // Force include timestamp + FlagShowLevel = formatter.FlagShowLevel // Force include level + FlagStructuredJSON = formatter.FlagStructuredJSON // Structured JSON output + FlagNoTimestamp = formatter.FlagNoTimestamp // Suppress timestamp + FlagNoLevel = formatter.FlagNoLevel // Suppress level FlagDefault = formatter.FlagDefault // Default flags ) ``` @@ -412,4 +414,4 @@ func (s *Service) ProcessRequest(id string) error { func (s *Service) Shutdown() error { return s.logger.Shutdown(5 * time.Second) } -``` \ No newline at end of file +``` diff --git a/doc/formatting.md b/doc/formatting.md index df90312..b4a9dd1 100644 --- a/doc/formatting.md +++ b/doc/formatting.md @@ -35,31 +35,40 @@ data := f.Format( ) ``` -### Formatter Methods +### Formatter Methods and Concurrency -#### Format Configuration -- `Type(format string)` - Set output format: "txt", "json", or "raw" -- `TimestampFormat(format string)` - Set timestamp format (Go time format) -- `ShowLevel(show bool)` - Include level in output -- `ShowTimestamp(show bool)` - Include timestamp in output +The formatter provides two classes of methods. **You must understand the concurrency contract** when using these standalone: -#### Formatting Methods -- `Format(flags int64, timestamp time.Time, level int64, trace string, args []any) []byte` -- `FormatWithOptions(format string, flags int64, timestamp time.Time, level int64, trace string, args []any) []byte` -- `FormatValue(v any) []byte` - Format a single value -- `FormatArgs(args ...any) []byte` - Format multiple arguments +**1. Buffered Methods (Single Goroutine Only)** +These methods reuse an internal buffer to prevent allocations. **The returned byte slice is valid ONLY until the next buffered call.** You must copy the result (`bytes.Clone()`) before retention or async hand-off. +* `Format(flags int64, timestamp time.Time, level int64, trace string, args []any) []byte` +* `FormatWithOptions(format string, flags int64, timestamp time.Time, level int64, trace string, args []any) []byte` +* `FormatValue(v any) []byte` +* `FormatArgs(args ...any) []byte` + +**2. Append Methods (Thread-Safe)** +These methods write to a caller-provided destination buffer. Once the formatter is configured, these are **safe for concurrent use** and are preferred for async sinks. +* `AppendFormat(dst []byte, flags int64, timestamp time.Time, level int64, trace string, args []any) []byte` +* `AppendFormatWithOptions(dst []byte, format string, flags int64, timestamp time.Time, level int64, trace string, args []any) []byte` +* `AppendValue(dst []byte, v any) []byte` +* `AppendArgs(dst []byte, args ...any) []byte` ### Format Flags +Flags use an additive resolution system. `No*` flags suppress output, `Show*` flags force output, and if neither is specified, the configured default applies. (`No*` flags win on conflicts). + ```go const ( - FlagRaw int64 = 0b0001 // Bypass formatter and sanitizer - FlagShowTimestamp int64 = 0b0010 // Include timestamp - FlagShowLevel int64 = 0b0100 // Include level - FlagStructuredJSON int64 = 0b1000 // Use structured JSON with message/fields + FlagRaw int64 = 0b0001 // Bypass formatter and sanitizer completely + FlagShowTimestamp int64 = 0b0010 // Force include timestamp + FlagShowLevel int64 = 0b0100 // Force include level + FlagStructuredJSON int64 = 0b1000 // Use structured JSON with message/fields + FlagNoTimestamp int64 = 0b010000 // Suppress timestamp + FlagNoLevel int64 = 0b100000 // Suppress level FlagDefault = FlagShowTimestamp | FlagShowLevel ) ``` +*Note: `FormatWithOptions` and `AppendFormatWithOptions` bypass configured defaults entirely. Unset `Show*` bits in these methods mean the feature is off.* ### Level Constants @@ -105,7 +114,7 @@ const ( - **PolicyRaw**: Pass through all characters unchanged - **PolicyTxt**: Hex-encode non-printable characters as `` - **PolicyJSON**: Escape control characters with JSON-style backslashes -- **PolicyShell**: Strip shell metacharacters and whitespace +- **PolicyShell**: Strips shell metacharacters (``` ` $ ; | & > < ( ) # ' " \ * ? [ ] { } ~ ! ```), whitespace, and control characters. *Note: Used for defense-in-depth logging, NOT for safely constructing executable shell commands.* ### Filter Flags @@ -158,6 +167,44 @@ serializer.WriteBool(&buf, true) // "true" serializer.WriteNil(&buf) // "null" ``` +## JSON Escaping Layers + +The sanitizer is a content transform; JSON string escaping is transport +encoding applied afterward, unconditionally. Output is valid JSON for any +sanitization policy. Multi-byte UTF-8 passes through unescaped. + +- `format=json` + `sanitization=raw`: recommended; transport escaping only. +- `format=json` + `sanitization=txt`: non-printables appear as `` inside + JSON strings. +- `format=json` + `sanitization=json`: redundant; produces visible `\\n` + double escapes. Use `raw` instead. +- Structured JSON (`FlagStructuredJSON`) marshals the fields map via + `encoding/json` and bypasses the sanitizer; validity is guaranteed, + content-level sanitization is not applied to field values. + +## PolicyShell Scope + +`PolicyShell` strips metacharacters, whitespace, and control characters as +defense-in-depth for logged values. It is not sufficient for constructing +shell commands from untrusted input; pass arguments via exec argv. + +## Hex Marker Integrity + +`PolicyTxt` hex-encodes literal `<` as `<3c>`. Every `<` in sanitized output +therefore starts a genuine marker; encoded sequences cannot be spoofed by +input containing literal `` text. + +## Format Flags + +| Flag | Effect | +|---|---| +| `FlagShowTimestamp` / `FlagShowLevel` | Force display on | +| `FlagNoTimestamp` / `FlagNoLevel` | Force display off (wins over Show) | +| neither | Configured default applies (`Format`/`AppendFormat` only) | + +`FormatWithOptions`/`AppendFormatWithOptions` ignore configured defaults: +unset Show bits mean off. Unknown format strings fall back to `"txt"`. + ## Integration with Logger The logger uses these packages internally but configuration remains simple: @@ -227,8 +274,17 @@ scriptLog := txtFormatter.Format(...) - Formatter reuses internal buffers via `Reset()` - No regex or reflection in hot paths -## Thread Safety +## Ownership and Thread Safety -- `Formatter` instances are **NOT** thread-safe (use separate instances per goroutine) -- `Sanitizer` instances **ARE** thread-safe (immutable after creation) -- For concurrent formatting, create a formatter per goroutine or use sync.Pool \ No newline at end of file +- Configuration (`Type`, `ShowLevel`, `Rule`, `RuleFunc`, `Policy`, ...) must + complete before an instance is shared between goroutines. +- `Formatter` buffered methods (`Format`, `FormatWithOptions`, `FormatValue`, + `FormatArgs`) reuse an internal buffer. The returned slice is valid only + until the next buffered call. Copy (`bytes.Clone`) before retaining or + handing off to async queues. Single goroutine only. +- `Formatter` append methods (`AppendFormat`, `AppendFormatWithOptions`, + `AppendValue`, `AppendArgs`) write to a caller-provided buffer and are safe + for concurrent use. Preferred for async sinks and multi-goroutine callers. +- `Sanitizer` is immutable after configuration; `Sanitize`/`AppendSanitize` + are safe for concurrent use. `Sanitize` returns the input unchanged + (allocation-free) when no rule matches. diff --git a/doc/getting-started.md b/doc/getting-started.md index bcd7279..b8cb4f9 100644 --- a/doc/getting-started.md +++ b/doc/getting-started.md @@ -53,6 +53,52 @@ func main() { } ``` +## Recommended Usage (Builder Pattern) + +The Builder pattern provides a fluent API with compile-time safety and deferred validation, making it the most robust way to initialize your logger: + +```go +package main + +import ( + "fmt" + "os" + "time" + + "github.com/lixenwraith/log" +) + +func main() { + // Build logger with fluent configuration + logger, err := log.NewBuilder(). + Directory("/var/log/myapp"). // Log directory path + LevelString("info"). // Minimum log level + Format("json"). // Output format + Sanitization("json"). // Sanitization policy + EnableFile(true). // Enable file output (disabled by default) + BufferSize(2048). // Channel buffer size + MaxSizeMB(10). // Max file size before rotation + HeartbeatLevel(1). // Enable operational monitoring + HeartbeatIntervalS(300). // Every 5 minutes + Build() // Build the logger instance + + if err != nil { + panic(fmt.Errorf("logger build failed: %w", err)) + } + + // Ensure logs are flushed on shutdown + defer logger.Shutdown(5 * time.Second) + + // Start the background async processor (required before logging) + if err := logger.Start(); err != nil { + panic(fmt.Errorf("logger start failed: %w", err)) + } + + // Begin logging with structured key-value pairs + logger.Info("Application started", "version", "1.0.0", "pid", os.Getpid()) +} +``` + ## Next Steps 1. **[Learn about configuration options](configuration.md)** - Customize behavior for your needs @@ -114,4 +160,4 @@ func loggingMiddleware(logger *log.Logger) func(http.Handler) http.Handler { }) } } -``` \ No newline at end of file +``` diff --git a/doc/quick-guide_lixenwraith_log.md b/doc/quick-guide_lixenwraith_log.md deleted file mode 100644 index 42b213b..0000000 --- a/doc/quick-guide_lixenwraith_log.md +++ /dev/null @@ -1,518 +0,0 @@ -I'll search the project knowledge to understand the current state of the log package and update the quick-guide documentation accordingly.# FILE: doc/quick-guide_lixenwraith_log.md - -# lixenwraith/log Quick Reference Guide - -High-performance buffered rotating file logger with disk management, operational monitoring, and exported formatter/sanitizer packages. - -## Quick Start: Recommended Usage - -Builder pattern with type-safe configuration (compile-time safety, no runtime errors): - -```go -package main - -import ( - "fmt" - "os" - "time" - - "github.com/lixenwraith/log" -) - -func main() { - // Build logger with configuration - logger, err := log.NewBuilder(). - Directory("/var/log/myapp"). // Log directory path - LevelString("info"). // Minimum log level - Format("json"). // Output format - Sanitization("json"). // Sanitization policy - EnableFile(true). // Enable file output (disabled by default) - BufferSize(2048). // Channel buffer size - MaxSizeMB(10). // Max file size before rotation - HeartbeatLevel(1). // Enable operational monitoring - HeartbeatIntervalS(300). // Every 5 minutes - Build() // Build the logger instance - if err != nil { - panic(fmt.Errorf("logger build failed: %w", err)) - } - defer logger.Shutdown(5 * time.Second) - - // Start the logger (required before logging) - if err := logger.Start(); err != nil { - panic(fmt.Errorf("logger start failed: %w", err)) - } - - // Begin logging with structured key-value pairs - logger.Info("Application started", "version", "1.0.0", "pid", os.Getpid()) - logger.Debug("Debug information", "user_id", 12345) - logger.Warn("High memory usage", "used_mb", 1800, "limit_mb", 2048) - logger.Error("Connection failed", "host", "db.example.com", "error", err) -} -``` - -## Alternative Initialization Methods - -### Using ApplyConfigString (Quick Configuration) - -```go -logger := log.NewLogger() -err := logger.ApplyConfigString( - "directory=/var/log/app", - "format=json", - "sanitization=json", - "level=debug", - "max_size_kb=5000", -) -if err != nil { - return fmt.Errorf("config failed: %w", err) -} -defer logger.Shutdown() -logger.Start() -``` - -### Using ApplyConfig (Full Control) - -```go -logger := log.NewLogger() -cfg := log.DefaultConfig() -cfg.Directory = "/var/log/app" -cfg.Format = "json" -cfg.Sanitization = log.PolicyJSON -cfg.Level = log.LevelDebug -cfg.MaxSizeKB = 5000 -cfg.HeartbeatLevel = 2 // Process + disk stats -err := logger.ApplyConfig(cfg) -if err != nil { - return fmt.Errorf("config failed: %w", err) -} -defer logger.Shutdown() -logger.Start() -``` - -## Builder Pattern - -```go -func NewBuilder() *Builder -func (b *Builder) Build() (*Logger, error) -``` - -### Builder Methods - -All builder methods return `*Builder` for chaining. - -**Basic Configuration:** -- `Level(level int64)`: Set numeric log level (-4 to 8) -- `LevelString(level string)`: Set level by name ("debug", "info", "warn", "error") -- `Directory(dir string)`: Set log directory path -- `Name(name string)`: Set base filename (default: "log") -- `Format(format string)`: Set format ("txt", "json", "raw") -- `Sanitization(policy string)`: Set sanitization policy ("txt", "json", "raw", "shell") -- `Extension(ext string)`: Set file extension (default: ".log") - -**Buffer and Performance:** -- `BufferSize(size int64)`: Channel buffer size (default: 1024) -- `FlushIntervalMs(ms int64)`: Buffer flush interval (default: 100ms) -- `TraceDepth(depth int64)`: Default function trace depth 0-10 (default: 0) - -**File Management:** -- `MaxSizeKB(size int64)` / `MaxSizeMB(size int64)`: Max file size before rotation -- `MaxTotalSizeKB(size int64)` / `MaxTotalSizeMB(size int64)`: Max total directory size -- `MinDiskFreeKB(size int64)` / `MinDiskFreeMB(size int64)`: Required free disk space -- `RetentionPeriodHrs(hours float64)`: Hours to keep logs (0=disabled) -- `RetentionCheckMins(mins float64)`: Retention check interval - -**Output Control:** -- `EnableConsole(enable bool)`: Enable stdout/stderr output -- `EnableFile(enable bool)`: Enable file output -- `ConsoleTarget(target string)`: "stdout", "stderr", or "split" - -**Formatting:** -- `ShowTimestamp(show bool)`: Add timestamps -- `ShowLevel(show bool)`: Add level labels -- `TimestampFormat(format string)`: Go time format string - -**Monitoring:** -- `HeartbeatLevel(level int64)`: 0=off, 1=proc, 2=+disk, 3=+sys -- `HeartbeatIntervalS(seconds int64)`: Heartbeat interval - -**Disk Monitoring:** -- `DiskCheckIntervalMs(ms int64)`: Base disk check interval -- `EnableAdaptiveInterval(enable bool)`: Adjust interval based on load -- `MinCheckIntervalMs(ms int64)`: Minimum adaptive interval -- `MaxCheckIntervalMs(ms int64)`: Maximum adaptive interval -- `EnablePeriodicSync(enable bool)`: Periodic disk sync - -**Error Handling:** -- `InternalErrorsToStderr(enable bool)`: Send internal errors to stderr - -## API Reference - -### Logger Creation - -```go -func NewLogger() *Logger -``` -Creates a new uninitialized logger with default configuration. - -### Configuration Methods - -```go -func (l *Logger) ApplyConfig(cfg *Config) error -func (l *Logger) ApplyConfigString(overrides ...string) error -func (l *Logger) GetConfig() *Config -``` - -### Lifecycle Methods - -```go -func (l *Logger) Start() error // Start log processing -func (l *Logger) Stop(timeout ...time.Duration) error // Stop (can restart) -func (l *Logger) Shutdown(timeout ...time.Duration) error // Terminal shutdown -func (l *Logger) Flush(timeout time.Duration) error // Force buffer flush -``` - -### Standard Logging Methods - -```go -func (l *Logger) Debug(args ...any) // Level -4 -func (l *Logger) Info(args ...any) // Level 0 -func (l *Logger) Warn(args ...any) // Level 4 -func (l *Logger) Error(args ...any) // Level 8 -``` - -### Trace Logging Methods - -Include function call traces (depth 0-10): - -```go -func (l *Logger) DebugTrace(depth int, args ...any) -func (l *Logger) InfoTrace(depth int, args ...any) -func (l *Logger) WarnTrace(depth int, args ...any) -func (l *Logger) ErrorTrace(depth int, args ...any) -``` - -### Special Logging Methods - -```go -func (l *Logger) LogStructured(level int64, message string, fields map[string]any) -func (l *Logger) Write(args ...any) // Raw output, no formatting -func (l *Logger) Log(args ...any) // Timestamp only, no level -func (l *Logger) Message(args ...any) // No timestamp or level -func (l *Logger) LogTrace(depth int, args ...any) // Timestamp + trace, no level -``` - -## Constants and Levels - -### Standard Log Levels - -```go -const ( - LevelDebug int64 = -4 // Verbose debugging - LevelInfo int64 = 0 // Informational messages - LevelWarn int64 = 4 // Warning conditions - LevelError int64 = 8 // Error conditions -) -``` - -### Heartbeat Monitoring Levels - -Special levels that bypass filtering: - -```go -const ( - LevelProc int64 = 12 // Process statistics - LevelDisk int64 = 16 // Disk usage statistics - LevelSys int64 = 20 // System statistics -) -``` - -### Sanitization Policies - -```go -const ( - PolicyRaw = "raw" // No-op passthrough - PolicyJSON = "json" // JSON-safe output - PolicyTxt = "txt" // Text file safe - PolicyShell = "shell" // Shell-safe output -) -``` - -### Level Helper - -```go -func Level(levelStr string) (int64, error) -``` -Converts level string to numeric constant: "debug", "info", "warn", "error", "proc", "disk", "sys". - -## Output Formats - -### JSON Format - -```json -{"timestamp":"2024-01-01T12:00:00Z","level":"INFO","fields":["Application started","version","1.0.0"]} -``` - -### TXT Format - -``` -2024-01-01T12:00:00Z INFO Application started version="1.0.0" pid=1234 -``` - -### RAW Format - -Minimal format without timestamps or levels: -``` -Application started version="1.0.0" pid=1234 -Connection failed host="db.example.com" error="timeout" -``` - -## Standalone Formatter/Sanitizer Packages - -### Formatter Package - -```go -import ( - "time" - "github.com/lixenwraith/log/formatter" - "github.com/lixenwraith/log/sanitizer" -) - -// Create formatter with sanitizer -s := sanitizer.New().Policy(sanitizer.PolicyJSON) -f := formatter.New(s) - -// Configure and format -f.Type("json").ShowTimestamp(true) -data := f.Format( - formatter.FlagDefault, - time.Now(), - 0, // Info level - "", // No trace - []any{"User action", "user_id", 42}, -) -``` - -### Sanitizer Package - -```go -import "github.com/lixenwraith/log/sanitizer" - -// Predefined policy -s := sanitizer.New().Policy(sanitizer.PolicyJSON) -clean := s.Sanitize("hello\nworld") // "hello\\nworld" - -// Custom rules -s = sanitizer.New(). - Rule(sanitizer.FilterControl, sanitizer.TransformStrip). - Rule(sanitizer.FilterNonPrintable, sanitizer.TransformHexEncode) -``` - -## Framework Adapters (compat package) - -### gnet v2 Adapter - -```go -import ( - "github.com/lixenwraith/log" - "github.com/lixenwraith/log/compat" - "github.com/panjf2000/gnet/v2" -) - -// Create adapter -adapter := compat.NewGnetAdapter(logger) - -// Use with gnet -gnet.Run(handler, "tcp://127.0.0.1:9000", gnet.WithLogger(adapter)) -``` - -### fasthttp Adapter - -```go -import ( - "github.com/lixenwraith/log" - "github.com/lixenwraith/log/compat" - "github.com/valyala/fasthttp" -) - -// Create adapter -adapter := compat.NewFastHTTPAdapter(logger) - -// Use with fasthttp -server := &fasthttp.Server{ - Handler: requestHandler, - Logger: adapter, -} -``` - -### Adapter Builder Pattern - -```go -// Share logger across adapters -builder := compat.NewBuilder().WithLogger(logger) - -gnetAdapter, err := builder.BuildGnet() -fasthttpAdapter, err := builder.BuildFastHTTP() - -// Or create structured adapters -structuredGnet, err := builder.BuildStructuredGnet() -``` - -## Common Patterns - -### Service with Shared Logger - -```go -type Service struct { - logger *log.Logger -} - -func NewService() (*Service, error) { - logger, err := log.NewBuilder(). - Directory("/var/log/service"). - Format("json"). - BufferSize(2048). - HeartbeatLevel(2). - Build() - if err != nil { - return nil, err - } - - if err := logger.Start(); err != nil { - return nil, err - } - - return &Service{logger: logger}, nil -} - -func (s *Service) Close() error { - return s.logger.Shutdown(5 * time.Second) -} - -func (s *Service) ProcessRequest(id string) { - s.logger.Info("Processing", "request_id", id) - // ... process ... - s.logger.Info("Completed", "request_id", id) -} -``` - -### HTTP Middleware - -```go -func loggingMiddleware(logger *log.Logger) func(http.Handler) http.Handler { - return func(next http.Handler) http.Handler { - return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - start := time.Now() - wrapped := &responseWriter{ResponseWriter: w, status: 200} - - next.ServeHTTP(wrapped, r) - - logger.Info("HTTP request", - "method", r.Method, - "path", r.URL.Path, - "status", wrapped.status, - "duration_ms", time.Since(start).Milliseconds(), - "remote_addr", r.RemoteAddr, - ) - }) - } -} -``` - -### Hot Reconfiguration - -```go -// Initial configuration -logger.ApplyConfigString("level=info") - -// Debugging reconfiguration -logger.ApplyConfigString( - "level=debug", - "heartbeat_level=3", - "heartbeat_interval_s=60", -) - -// Revert to normal -logger.ApplyConfigString( - "level=info", - "heartbeat_level=1", - "heartbeat_interval_s=300", -) -``` - -### Security-Focused Sanitization - -```go -// User input logging with shell-safe sanitization -userInput := getUserInput() -s := sanitizer.New().Policy(sanitizer.PolicyShell) -logger.Info("User command", "input", s.Sanitize(userInput)) - -// Or configure logger-wide -logger.ApplyConfigString("sanitization=shell") -``` - -### Graceful Shutdown - -```go -// Setup signal handling -sigChan := make(chan os.Signal, 1) -signal.Notify(sigChan, syscall.SIGTERM, syscall.SIGINT) - -// Shutdown sequence -<-sigChan -logger.Info("Shutdown initiated") - -// Flush pending logs with timeout -if err := logger.Shutdown(5 * time.Second); err != nil { - fmt.Fprintf(os.Stderr, "Logger shutdown error: %v\n", err) -} -``` - -## Thread Safety - -All public methods are thread-safe. The logger uses: -- Atomic operations for state management -- Channels for log record passing -- No locks in the critical logging path - -## Performance Characteristics - -- **Zero-allocation logging path**: Pre-allocated buffers -- **Lock-free async design**: Non-blocking sends to buffered channel -- **Adaptive disk checks**: Adjusts I/O based on load -- **Batch writes**: Flushes buffer periodically, not per-record -- **Drop tracking**: Counts dropped logs when buffer full - -## Migration Guide - -### From standard log package - -```go -// Before: standard log -log.Printf("User login: id=%d name=%s", id, name) - -// After: lixenwraith/log -logger.Info("User login", "id", id, "name", name) -``` - -### From other structured loggers - -```go -// Before: zap -zap.Info("User login", - zap.Int("id", id), - zap.String("name", name)) - -// After: lixenwraith/log -logger.Info("User login", "id", id, "name", name) -``` - -## Best Practices - -1. **Use Builder pattern** for configuration - compile-time safety -2. **Use structured logging** - consistent key-value pairs -3. **Use appropriate levels** - filter noise in logs -4. **Configure sanitization** - prevent log injection attacks -5. **Monitor heartbeats** - track logger health in production -6. **Handle shutdown** - always call Shutdown() to flush logs -7. **Use standalone packages** - reuse formatter/sanitizer for other needs \ No newline at end of file diff --git a/doc/storage.md b/doc/storage.md index 9087e51..e87a18d 100644 --- a/doc/storage.md +++ b/doc/storage.md @@ -6,11 +6,11 @@ Comprehensive guide to log file rotation, retention policies, and disk space man ### Automatic Rotation -Log files are automatically rotated when they reach the configured size limit: +Log files are automatically rotated when they reach the configured size limit in Kilobytes: ```go logger.ApplyConfigString( - "max_size_kb=100", // Rotate at 100MB + "max_size_kb=102400", // Rotate at 100MB (102400 KB) ) ``` @@ -62,23 +62,23 @@ When limits are exceeded, the logger: ```go // Conservative: Strict limits logger.ApplyConfigString( - "max_size_kb=500", // 500KB files - "max_total_size_kb=5000", // 5MB total - "min_disk_free_kb=1000000", // 1GB free required + "max_size_kb=500", // 500 KB files + "max_total_size_kb=5000", // 5 MB total log directory limit + "min_disk_free_kb=1048576", // 1 GB free space required on disk ) // Generous: Large files, external archival logger.ApplyConfigString( - "max_size_kb=100000", // 100MB files - "max_total_size_kb=0", // No total limit - "min_disk_free_kb=10000", // 10MB free required + "max_size_kb=102400", // 100 MB files + "max_total_size_kb=0", // No total limit + "min_disk_free_kb=10240", // 10 MB free required ) // Balanced: Production defaults logger.ApplyConfigString( - "max_size_kb=100000", // 100MB files - "max_total_size_kb=5000000", // 5GB total - "min_disk_free_kb=500000", // 500MB free required + "max_size_kb=102400", // 100 MB files + "max_total_size_kb=5242880", // 5 GB total limit + "min_disk_free_kb=512000", // 500 MB free required ) ``` @@ -180,4 +180,4 @@ ls -t /var/log/myapp/*.log | tail -n 20 | xargs rm # Verify space df -h /var/log -``` \ No newline at end of file +``` diff --git a/format_test.go b/format_test.go index ee1dca6..6b2215e 100644 --- a/format_test.go +++ b/format_test.go @@ -68,8 +68,6 @@ func TestLoggerFormatterIntegration(t *testing.T) { err = logger.Flush(time.Second) require.NoError(t, err) - time.Sleep(50 * time.Millisecond) - content, err := os.ReadFile(filepath.Join(tmpDir, "log.log")) require.NoError(t, err) @@ -158,4 +156,5 @@ func TestRawSanitizedOutputWithFormatter(t *testing.T) { }, " ") assert.Equal(t, expectedOutput, logOutput) -} \ No newline at end of file +} + diff --git a/formatter/formatter.go b/formatter/formatter.go index e2f62d1..b0bb2be 100644 --- a/formatter/formatter.go +++ b/formatter/formatter.go @@ -1,3 +1,17 @@ +// Package formatter provides buffered and append-style formatting of log +// entries in txt, json, and raw formats. +// +// Ownership and concurrency contract: +// - Configure via the fluent API (Type, TimestampFormat, ShowLevel, +// ShowTimestamp) before sharing an instance; configuration is not +// synchronized. +// - Buffered methods (Format, FormatWithOptions, FormatValue, FormatArgs) +// reuse an internal buffer. The returned slice is valid only until the +// next buffered call; copy before retention or async hand-off. Single +// goroutine only. +// - Append methods (AppendFormat, AppendFormatWithOptions, AppendValue, +// AppendArgs) write to a caller-provided buffer and are safe for +// concurrent use after configuration. package formatter import ( @@ -10,16 +24,20 @@ import ( "github.com/lixenwraith/log/sanitizer" ) -// Format flags for controlling output structure +// Format flags. Resolution in Format/AppendFormat: FlagNo* suppresses, +// FlagShow* enables, otherwise configured default applies; FlagNo* wins on conflict. +// FormatWithOptions/AppendFormatWithOptions are explicit: unset FlagShow* bits mean off. const ( FlagRaw int64 = 0b0001 FlagShowTimestamp int64 = 0b0010 FlagShowLevel int64 = 0b0100 FlagStructuredJSON int64 = 0b1000 + FlagNoTimestamp int64 = 0b010000 + FlagNoLevel int64 = 0b100000 FlagDefault = FlagShowTimestamp | FlagShowLevel ) -// Formatter manages the buffered writing and formatting of log entries +// Formatter manages formatting of log entries type Formatter struct { sanitizer *sanitizer.Sanitizer format string @@ -73,93 +91,169 @@ func (f *Formatter) ShowTimestamp(show bool) *Formatter { return f } -// Format formats a log entry using configured options and explicit flags +// Format formats using configured options resolved against explicit flags. +// Returned slice aliases the internal buffer. func (f *Formatter) Format(flags int64, timestamp time.Time, level int64, trace string, args []any) []byte { - // Override configured values with explicit flags - effectiveShowTimestamp := (flags&FlagShowTimestamp) != 0 || (flags == 0 && f.showTimestamp) - effectiveShowLevel := (flags&FlagShowLevel) != 0 || (flags == 0 && f.showLevel) - - // Build effective flags - effectiveFlags := flags - if effectiveShowTimestamp { - effectiveFlags |= FlagShowTimestamp - } - if effectiveShowLevel { - effectiveFlags |= FlagShowLevel - } - - return f.FormatWithOptions(f.format, effectiveFlags, timestamp, level, trace, args) + f.buf = f.AppendFormat(f.buf[:0], flags, timestamp, level, trace, args) + return f.buf } -// FormatWithOptions formats with explicit format and flags, ignoring configured values -func (f *Formatter) FormatWithOptions(format string, flags int64, timestamp time.Time, level int64, trace string, args []any) []byte { - f.Reset() +// AppendFormat appends a formatted entry to dst using configured options +// resolved against explicit flags. Safe for concurrent use. +func (f *Formatter) AppendFormat(dst []byte, flags int64, timestamp time.Time, level int64, trace string, args []any) []byte { + // CHANGED: D3 — additive resolution replaces `flags == 0` guard + eff := flags &^ (FlagShowTimestamp | FlagShowLevel) + if resolveShow(flags, FlagShowTimestamp, FlagNoTimestamp, f.showTimestamp) { + eff |= FlagShowTimestamp + } + if resolveShow(flags, FlagShowLevel, FlagNoLevel, f.showLevel) { + eff |= FlagShowLevel + } + return f.AppendFormatWithOptions(dst, f.format, eff, timestamp, level, trace, args) +} +func resolveShow(flags, show, no int64, configured bool) bool { + switch { + case flags&no != 0: + return false + case flags&show != 0: + return true + default: + return configured + } +} + +// FormatWithOptions formats with explicit format and flags, ignoring +// configured display defaults. Returned slice aliases the internal buffer. +func (f *Formatter) FormatWithOptions(format string, flags int64, timestamp time.Time, level int64, trace string, args []any) []byte { + f.buf = f.AppendFormatWithOptions(f.buf[:0], format, flags, timestamp, level, trace, args) + return f.buf +} + +// AppendFormatWithOptions is the allocation-explicit core. Safe for +// concurrent use. Unknown formats fall back to "txt". +func (f *Formatter) AppendFormatWithOptions(dst []byte, format string, flags int64, timestamp time.Time, level int64, trace string, args []any) []byte { // FlagRaw completely bypasses formatting and sanitization if flags&FlagRaw != 0 { for i, arg := range args { if i > 0 { - f.buf = append(f.buf, ' ') + dst = append(dst, ' ') } - // Direct conversion without sanitization switch v := arg.(type) { case string: - f.buf = append(f.buf, v...) + dst = append(dst, v...) case []byte: - f.buf = append(f.buf, v...) + dst = append(dst, v...) case fmt.Stringer: - f.buf = append(f.buf, v.String()...) + dst = append(dst, v.String()...) case error: - f.buf = append(f.buf, v.Error()...) + dst = append(dst, v.Error()...) default: - f.buf = append(f.buf, fmt.Sprint(v)...) + dst = append(dst, fmt.Sprint(v)...) } } - return f.buf + return dst } - // Create the serializer based on the effective format + // unknown formats normalize to txt instead of returning nil + format = normalizeFormat(format) serializer := sanitizer.NewSerializer(format, f.sanitizer) switch format { case "raw": - // Raw formatting serializes the arguments and adds NO metadata or newlines for i, arg := range args { - f.convertValue(&f.buf, arg, serializer, i > 0) + dst = f.appendValue(dst, arg, serializer, i > 0) } - return f.buf - + return dst case "json": - return f.formatJSON(flags, timestamp, level, trace, args, serializer) - - case "txt": - return f.formatTxt(flags, timestamp, level, trace, args, serializer) + return f.appendJSON(dst, flags, timestamp, level, trace, args, serializer) + default: // "txt" + return f.appendTxt(dst, flags, timestamp, level, trace, args, serializer) } - - return nil // forcing panic on unrecognized format } -// FormatValue formats a single value according to the formatter's configuration +func normalizeFormat(format string) string { + switch format { + case "raw", "json", "txt": + return format + default: + return "txt" + } +} + +// FormatValue formats a single value. Returned slice aliases the internal buffer. func (f *Formatter) FormatValue(v any) []byte { - f.Reset() - serializer := sanitizer.NewSerializer(f.format, f.sanitizer) - f.convertValue(&f.buf, v, serializer, false) + f.buf = f.AppendValue(f.buf[:0], v) return f.buf } -// FormatArgs formats multiple arguments as space-separated values +// AppendValue appends a single formatted value to dst. Safe for concurrent use. +// ADDED: R1 +func (f *Formatter) AppendValue(dst []byte, v any) []byte { + serializer := sanitizer.NewSerializer(normalizeFormat(f.format), f.sanitizer) + return f.appendValue(dst, v, serializer, false) +} + +// FormatArgs formats multiple arguments. Returned slice aliases the internal buffer. func (f *Formatter) FormatArgs(args ...any) []byte { - f.Reset() - serializer := sanitizer.NewSerializer(f.format, f.sanitizer) - for i, arg := range args { - f.convertValue(&f.buf, arg, serializer, i > 0) - } + f.buf = f.AppendArgs(f.buf[:0], args...) return f.buf } -// Reset clears the formatter buffer for reuse -func (f *Formatter) Reset() { - f.buf = f.buf[:0] +// AppendArgs appends multiple space-separated values to dst. Safe for +// concurrent use. +// ADDED: R1 +func (f *Formatter) AppendArgs(dst []byte, args ...any) []byte { + serializer := sanitizer.NewSerializer(normalizeFormat(f.format), f.sanitizer) + for i, arg := range args { + dst = f.appendValue(dst, arg, serializer, i > 0) + } + return dst +} + +// appendValue provides unified type conversion (was convertValue; now +// value-return style over caller buffer). Type switch body unchanged except +// buffer plumbing — replace every `serializer.WriteX(buf, ...)` with +// `serializer.WriteX(&dst, ...)` and `return dst`. +func (f *Formatter) appendValue(dst []byte, v any, serializer *sanitizer.Serializer, needsSpace bool) []byte { + if needsSpace && len(dst) > 0 { + dst = append(dst, ' ') + } + switch val := v.(type) { + case string: + serializer.WriteString(&dst, val) + case []byte: + serializer.WriteString(&dst, string(val)) + case rune: + var runeStr [utf8.UTFMax]byte + n := utf8.EncodeRune(runeStr[:], val) + serializer.WriteString(&dst, string(runeStr[:n])) + case int: + serializer.WriteNumber(&dst, string(strconv.AppendInt(nil, int64(val), 10))) + case int64: + serializer.WriteNumber(&dst, string(strconv.AppendInt(nil, val, 10))) + case uint: + serializer.WriteNumber(&dst, string(strconv.AppendUint(nil, uint64(val), 10))) + case uint64: + serializer.WriteNumber(&dst, string(strconv.AppendUint(nil, val, 10))) + case float32: + serializer.WriteNumber(&dst, string(strconv.AppendFloat(nil, float64(val), 'f', -1, 32))) + case float64: + serializer.WriteNumber(&dst, string(strconv.AppendFloat(nil, val, 'f', -1, 64))) + case bool: + serializer.WriteBool(&dst, val) + case nil: + serializer.WriteNil(&dst) + case time.Time: + serializer.WriteString(&dst, val.Format(f.timestampFormat)) + case error: + serializer.WriteString(&dst, val.Error()) + case fmt.Stringer: + serializer.WriteString(&dst, val.String()) + default: + serializer.WriteComplex(&dst, val) + } + return dst } // LevelToString converts integer level values to string @@ -184,97 +278,34 @@ func LevelToString(level int64) string { } } -// convertValue provides unified type conversion -func (f *Formatter) convertValue(buf *[]byte, v any, serializer *sanitizer.Serializer, needsSpace bool) { - if needsSpace && len(*buf) > 0 { - *buf = append(*buf, ' ') - } - - switch val := v.(type) { - case string: - serializer.WriteString(buf, val) - - case []byte: - serializer.WriteString(buf, string(val)) - - case rune: - var runeStr [utf8.UTFMax]byte - n := utf8.EncodeRune(runeStr[:], val) - serializer.WriteString(buf, string(runeStr[:n])) - - case int: - num := strconv.AppendInt(nil, int64(val), 10) - serializer.WriteNumber(buf, string(num)) - - case int64: - num := strconv.AppendInt(nil, val, 10) - serializer.WriteNumber(buf, string(num)) - - case uint: - num := strconv.AppendUint(nil, uint64(val), 10) - serializer.WriteNumber(buf, string(num)) - - case uint64: - num := strconv.AppendUint(nil, val, 10) - serializer.WriteNumber(buf, string(num)) - - case float32: - num := strconv.AppendFloat(nil, float64(val), 'f', -1, 32) - serializer.WriteNumber(buf, string(num)) - - case float64: - num := strconv.AppendFloat(nil, val, 'f', -1, 64) - serializer.WriteNumber(buf, string(num)) - - case bool: - serializer.WriteBool(buf, val) - - case nil: - serializer.WriteNil(buf) - - case time.Time: - timeStr := val.Format(f.timestampFormat) - serializer.WriteString(buf, timeStr) - - case error: - serializer.WriteString(buf, val.Error()) - - case fmt.Stringer: - serializer.WriteString(buf, val.String()) - - default: - serializer.WriteComplex(buf, val) - } -} - -// formatJSON unifies JSON output -func (f *Formatter) formatJSON(flags int64, timestamp time.Time, level int64, trace string, args []any, serializer *sanitizer.Serializer) []byte { - f.buf = append(f.buf, '{') +// appendJSON unifies JSON output over a caller-provided buffer +func (f *Formatter) appendJSON(dst []byte, flags int64, timestamp time.Time, level int64, trace string, args []any, serializer *sanitizer.Serializer) []byte { + dst = append(dst, '{') needsComma := false if flags&FlagShowTimestamp != 0 { - f.buf = append(f.buf, `"time":"`...) - f.buf = timestamp.AppendFormat(f.buf, f.timestampFormat) - f.buf = append(f.buf, '"') + dst = append(dst, `"time":"`...) + dst = timestamp.AppendFormat(dst, f.timestampFormat) + dst = append(dst, '"') needsComma = true } if flags&FlagShowLevel != 0 { if needsComma { - f.buf = append(f.buf, ',') + dst = append(dst, ',') } - f.buf = append(f.buf, `"level":"`...) - f.buf = append(f.buf, LevelToString(level)...) - f.buf = append(f.buf, '"') + dst = append(dst, `"level":"`...) + dst = append(dst, LevelToString(level)...) + dst = append(dst, '"') needsComma = true } if trace != "" { if needsComma { - f.buf = append(f.buf, ',') + dst = append(dst, ',') } - f.buf = append(f.buf, `"trace":`...) - serializer.WriteString(&f.buf, trace) + dst = append(dst, `"trace":`...) + serializer.WriteString(&dst, trace) needsComma = true } @@ -283,25 +314,24 @@ func (f *Formatter) formatJSON(flags int64, timestamp time.Time, level int64, tr if message, ok := args[0].(string); ok { if fields, ok := args[1].(map[string]any); ok { if needsComma { - f.buf = append(f.buf, ',') + dst = append(dst, ',') } - f.buf = append(f.buf, `"message":`...) - serializer.WriteString(&f.buf, message) + dst = append(dst, `"message":`...) + serializer.WriteString(&dst, message) - f.buf = append(f.buf, ',') - f.buf = append(f.buf, `"fields":`...) + dst = append(dst, `,"fields":`...) marshaledFields, err := json.Marshal(fields) if err != nil { - f.buf = append(f.buf, `{"_marshal_error":"`...) - serializer.WriteString(&f.buf, err.Error()) - f.buf = append(f.buf, `"}`...) + dst = append(dst, `{"_marshal_error":"`...) + serializer.WriteString(&dst, err.Error()) + dst = append(dst, `"}`...) } else { - f.buf = append(f.buf, marshaledFields...) + dst = append(dst, marshaledFields...) } - f.buf = append(f.buf, '}', '\n') - return f.buf + dst = append(dst, '}', '\n') + return dst } } } @@ -309,42 +339,42 @@ func (f *Formatter) formatJSON(flags int64, timestamp time.Time, level int64, tr // Regular JSON with fields array if len(args) > 0 { if needsComma { - f.buf = append(f.buf, ',') + dst = append(dst, ',') } - f.buf = append(f.buf, `"fields":[`...) + dst = append(dst, `"fields":[`...) for i, arg := range args { if i > 0 { - f.buf = append(f.buf, ',') + dst = append(dst, ',') } - f.convertValue(&f.buf, arg, serializer, false) + dst = f.appendValue(dst, arg, serializer, false) } - f.buf = append(f.buf, ']') + dst = append(dst, ']') } - f.buf = append(f.buf, '}', '\n') - return f.buf + dst = append(dst, '}', '\n') + return dst } -// formatTxt handles txt format output -func (f *Formatter) formatTxt(flags int64, timestamp time.Time, level int64, trace string, args []any, serializer *sanitizer.Serializer) []byte { +// appendTxt handles txt format output over a caller-provided buffer +func (f *Formatter) appendTxt(dst []byte, flags int64, timestamp time.Time, level int64, trace string, args []any, serializer *sanitizer.Serializer) []byte { needsSpace := false if flags&FlagShowTimestamp != 0 { - f.buf = timestamp.AppendFormat(f.buf, f.timestampFormat) + dst = timestamp.AppendFormat(dst, f.timestampFormat) needsSpace = true } if flags&FlagShowLevel != 0 { if needsSpace { - f.buf = append(f.buf, ' ') + dst = append(dst, ' ') } - f.buf = append(f.buf, LevelToString(level)...) + dst = append(dst, LevelToString(level)...) needsSpace = true } if trace != "" { if needsSpace { - f.buf = append(f.buf, ' ') + dst = append(dst, ' ') } // Sanitize trace to prevent terminal control sequence injection traceHandler := sanitizer.NewSerializer("txt", f.sanitizer) @@ -352,18 +382,24 @@ func (f *Formatter) formatTxt(flags int64, timestamp time.Time, level int64, tra traceHandler.WriteString(&tempBuf, trace) // Extract content without quotes if added by txt serializer if len(tempBuf) > 2 && tempBuf[0] == '"' && tempBuf[len(tempBuf)-1] == '"' { - f.buf = append(f.buf, tempBuf[1:len(tempBuf)-1]...) + dst = append(dst, tempBuf[1:len(tempBuf)-1]...) } else { - f.buf = append(f.buf, tempBuf...) + dst = append(dst, tempBuf...) } needsSpace = true } for _, arg := range args { - f.convertValue(&f.buf, arg, serializer, needsSpace) + dst = f.appendValue(dst, arg, serializer, needsSpace) needsSpace = true } - f.buf = append(f.buf, '\n') - return f.buf -} \ No newline at end of file + dst = append(dst, '\n') + return dst +} + +// Reset clears the internal buffer for reuse +func (f *Formatter) Reset() { + f.buf = f.buf[:0] +} + diff --git a/formatter/formatter_test.go b/formatter/formatter_test.go index c15eb8d..2fb7f2f 100644 --- a/formatter/formatter_test.go +++ b/formatter/formatter_test.go @@ -1,9 +1,11 @@ package formatter import ( + "bytes" "encoding/json" "errors" "strings" + "sync" "testing" "time" @@ -97,7 +99,9 @@ func TestFormatter(t *testing.T) { }) t.Run("special characters escaping", func(t *testing.T) { - s := sanitizer.New().Policy(sanitizer.PolicyJSON) + // PolicyRaw — transport escaping applies exactly once. + // PolicyJSON + json format double-escapes (see TestJSONSanitizerLayering). + s := sanitizer.New().Policy(sanitizer.PolicyRaw) f := New(s).Type("json") data := f.Format(FlagDefault, timestamp, 0, "", @@ -119,6 +123,111 @@ func TestFormatter(t *testing.T) { }) } +func TestJSONUTF8Passthrough(t *testing.T) { + timestamp := time.Date(2024, 1, 1, 12, 0, 0, 0, time.UTC) + f := New(sanitizer.New()).Type("json") + in := "héllo 世界 ✓" + data := f.Format(FlagDefault, timestamp, 0, "", []any{in}) + + var result map[string]any + require.NoError(t, json.Unmarshal(bytes.TrimSuffix(data, []byte("\n")), &result)) + assert.Equal(t, in, result["fields"].([]any)[0]) + assert.NotContains(t, string(data), `\u00`, "no per-byte escapes of UTF-8") +} + +func TestJSONSanitizerLayering(t *testing.T) { + timestamp := time.Date(2024, 1, 1, 12, 0, 0, 0, time.UTC) + + // Content transform (PolicyTxt) applied before transport escaping + f := New(sanitizer.New().Policy(sanitizer.PolicyTxt)).Type("json") + data := f.Format(FlagDefault, timestamp, 0, "", []any{"a\x07b"}) + var result map[string]any + require.NoError(t, json.Unmarshal(bytes.TrimSuffix(data, []byte("\n")), &result)) + assert.Equal(t, "a<07>b", result["fields"].([]any)[0]) + + // PolicyJSON + json format: content transform emits literal backslash + // sequences; transport escaping preserves them (double-escape by design) + f2 := New(sanitizer.New().Policy(sanitizer.PolicyJSON)).Type("json") + data2 := f2.Format(FlagDefault, timestamp, 0, "", []any{"a\nb"}) + require.NoError(t, json.Unmarshal(bytes.TrimSuffix(data2, []byte("\n")), &result)) + assert.Equal(t, `a\nb`, result["fields"].([]any)[0]) +} + +func TestFlagResolution(t *testing.T) { + timestamp := time.Date(2024, 1, 1, 12, 0, 0, 0, time.UTC) + f := New(sanitizer.New()).Type("txt").ShowTimestamp(true).ShowLevel(true) + + // Non-display flags alone inherit configured defaults + str := string(f.Format(FlagStructuredJSON, timestamp, 0, "", []any{"m"})) + assert.Contains(t, str, "2024-01-01") + assert.Contains(t, str, "INFO") + + // Explicit suppression + str = string(f.Format(FlagNoLevel, timestamp, 0, "", []any{"m"})) + assert.Contains(t, str, "2024-01-01") + assert.NotContains(t, str, "INFO") + + str = string(f.Format(FlagNoTimestamp|FlagNoLevel, timestamp, 0, "", []any{"m"})) + assert.NotContains(t, str, "2024-01-01") + assert.NotContains(t, str, "INFO") + + // FormatWithOptions is fully explicit: unset Show bits mean off + str = string(f.FormatWithOptions("txt", 0, timestamp, 0, "", []any{"m"})) + assert.NotContains(t, str, "INFO") +} + +func TestUnknownFormatFallback(t *testing.T) { + timestamp := time.Date(2024, 1, 1, 12, 0, 0, 0, time.UTC) + f := New(sanitizer.New()).Type("txt") + data := f.FormatWithOptions("xml", FlagShowLevel, timestamp, 8, "", []any{"boom"}) + require.NotNil(t, data) + assert.Contains(t, string(data), "ERROR") + assert.Contains(t, string(data), "boom") +} + +func TestReturnedSliceInvalidation(t *testing.T) { + timestamp := time.Date(2024, 1, 1, 12, 0, 0, 0, time.UTC) + f := New(sanitizer.New()).Type("txt").ShowTimestamp(false).ShowLevel(false) + + first := f.Format(0, timestamp, 0, "", []any{"aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"}) + snapshot := string(first) + _ = f.Format(0, timestamp, 0, "", []any{"b"}) + assert.NotEqual(t, snapshot, string(first), + "buffered Format output is invalidated by the next buffered call") +} + +func TestAppendFormatStable(t *testing.T) { + timestamp := time.Date(2024, 1, 1, 12, 0, 0, 0, time.UTC) + f := New(sanitizer.New()).Type("txt").ShowTimestamp(false).ShowLevel(false) + + first := f.AppendFormat(nil, 0, timestamp, 0, "", []any{"first-payload"}) + snapshot := string(first) + _ = f.Format(0, timestamp, 0, "", []any{"interleaved-buffered-call"}) + second := f.AppendFormat(nil, 0, timestamp, 0, "", []any{"second"}) + + assert.Equal(t, snapshot, string(first), "caller-owned buffer unaffected by buffered calls") + assert.Equal(t, "second\n", string(second)) +} + +func TestFormatterConcurrentAppend(t *testing.T) { + f := New(sanitizer.New().Policy(sanitizer.PolicyTxt)).Type("json") + var wg sync.WaitGroup + for i := 0; i < 16; i++ { + wg.Add(1) + go func(id int) { + defer wg.Done() + for j := 0; j < 200; j++ { + out := f.AppendFormat(nil, FlagDefault, time.Now(), 0, "", []any{"w", id, "i", j, "s", "x\x00y"}) + if !json.Valid(bytes.TrimSuffix(out, []byte("\n"))) { + t.Errorf("invalid JSON: %s", out) + return + } + } + }(i) + } + wg.Wait() +} + func TestLevelToString(t *testing.T) { tests := []struct { level int64 @@ -139,4 +248,4 @@ func TestLevelToString(t *testing.T) { assert.Equal(t, tt.expected, LevelToString(tt.level)) }) } -} \ No newline at end of file +} diff --git a/logger.go b/logger.go index 430257e..5a8896c 100644 --- a/logger.go +++ b/logger.go @@ -16,9 +16,9 @@ import ( // Logger is the core struct that encapsulates all logger functionality type Logger struct { currentConfig atomic.Value // stores *Config + formatter atomic.Value // stores *formatter.Formatter state State initMu sync.Mutex - formatter atomic.Value // stores *formatter.Formatter } // NewLogger creates a new Logger instance with default settings @@ -320,17 +320,17 @@ func (l *Logger) ErrorTrace(depth int, args ...any) { // Log writes a timestamp-only record without level information func (l *Logger) Log(args ...any) { - l.log(FlagShowTimestamp, LevelInfo, 0, args...) + l.log(FlagShowTimestamp|FlagNoLevel, LevelInfo, 0, args...) } // Message writes a plain record without timestamp or level info func (l *Logger) Message(args ...any) { - l.log(0, LevelInfo, 0, args...) + l.log(FlagNoTimestamp|FlagNoLevel, LevelInfo, 0, args...) } // LogTrace writes a timestamp record with call trace but no level info func (l *Logger) LogTrace(depth int, args ...any) { - l.log(FlagShowTimestamp, LevelInfo, int64(depth), args...) + l.log(FlagShowTimestamp|FlagNoLevel, LevelInfo, int64(depth), args...) } // LogStructured logs a message with structured fields as proper JSON @@ -460,4 +460,5 @@ func (l *Logger) applyConfig(cfg *Config) error { } return nil -} \ No newline at end of file +} + diff --git a/logger_test.go b/logger_test.go index 96b6a48..5db33b4 100644 --- a/logger_test.go +++ b/logger_test.go @@ -250,9 +250,6 @@ func TestLoggerFormats(t *testing.T) { err = logger.Flush(time.Second) require.NoError(t, err) - // Small delay for flush - time.Sleep(50 * time.Millisecond) - content, err := os.ReadFile(filepath.Join(tmpDir, "log.log")) require.NoError(t, err) @@ -267,11 +264,11 @@ func TestLoggerConcurrency(t *testing.T) { defer logger.Shutdown() var wg sync.WaitGroup - for i := 0; i < 10; i++ { + for i := range 10 { wg.Add(1) go func(i int) { defer wg.Done() - for j := 0; j < 100; j++ { + for j := range 100 { logger.Info("goroutine", i, "log", j) } }(i) @@ -318,4 +315,5 @@ func TestLoggerWrite(t *testing.T) { assert.Contains(t, string(content), "raw output 123") assert.True(t, strings.HasSuffix(string(content), "raw output 123")) -} \ No newline at end of file +} + diff --git a/processor.go b/processor.go index eb451b8..fb4faa4 100644 --- a/processor.go +++ b/processor.go @@ -81,7 +81,8 @@ func (l *Logger) processLogs(ch <-chan logRecord) { } case confirmChan := <-l.state.flushRequestChan: - l.handleFlushRequest(confirmChan) + // Barrier semantics — drain queued records before sync + l.handleFlushRequest(ch, confirmChan) case <-timers.retentionChan: l.handleRetentionCheck() @@ -192,10 +193,25 @@ func (l *Logger) handleFlushTick() { } } -// handleFlushRequest handles an explicit flush request -func (l *Logger) handleFlushRequest(confirmChan chan struct{}) { - l.performSync() - close(confirmChan) +// handleFlushRequest drains pending records, then syncs. Gives Flush barrier semantics: +// Records enqueued before the Flush call are processed before confirmation. +// Channel close is left to the main loop. +func (l *Logger) handleFlushRequest(ch <-chan logRecord, confirmChan chan struct{}) { + for { + select { + case record, ok := <-ch: + if !ok { + l.performSync() + close(confirmChan) + return + } + l.processLogRecord(record) + default: + l.performSync() + close(confirmChan) + return + } + } } // handleRetentionCheck performs file retention check and cleanup @@ -264,4 +280,5 @@ func (l *Logger) adjustDiskCheckInterval(timers *TimerSet, lastCheckTime time.Ti } timers.diskCheckTicker.Reset(newInterval) -} \ No newline at end of file +} + diff --git a/processor_test.go b/processor_test.go index 0f7962b..596e8dd 100644 --- a/processor_test.go +++ b/processor_test.go @@ -151,6 +151,11 @@ func TestDroppedLogRecoveryOnDroppedHeartbeat(t *testing.T) { logger.Info("flood", i) } + // Drops during flood are nondeterministic (consumer runs concurrently); + // capture actual count as the assertion baseline + floodDrops := logger.state.TotalDroppedLogs.Load() + require.Greater(t, floodDrops, uint64(0), "flood must produce drops") + // Wait for the first heartbeat to be generated and report ~50 drops time.Sleep(1100 * time.Millisecond) @@ -190,22 +195,28 @@ func TestDroppedLogRecoveryOnDroppedHeartbeat(t *testing.T) { lines := strings.Split(string(content), "\n") for _, line := range lines { - // Find the last valid heartbeat with drop stats - if strings.Contains(line, `"level":"PROC"`) && strings.Contains(line, "dropped_since_last") { - foundHeartbeat = true - var entry map[string]any - err := json.Unmarshal([]byte(line), &entry) - require.NoError(t, err, "Failed to parse heartbeat log line: %s", line) - - fields := entry["fields"].([]any) - for i := 0; i < len(fields)-1; i += 2 { - if key, ok := fields[i].(string); ok { - if key == "dropped_since_last" { - intervalDropCount, _ = fields[i+1].(float64) - } - if key == "total_dropped_logs" { - totalDropCount, _ = fields[i+1].(float64) - } + // Track the last PROC heartbeat unconditionally; + // an omitted dropped_since_last means 0 drops in that interval + if !strings.Contains(line, `"level":"PROC"`) { + continue + } + var entry map[string]any + if err := json.Unmarshal([]byte(line), &entry); err != nil { + continue + } + fields, ok := entry["fields"].([]any) + if !ok { + continue + } + foundHeartbeat = true + intervalDropCount = 0 + for i := 0; i < len(fields)-1; i += 2 { + if key, ok := fields[i].(string); ok { + if key == "dropped_since_last" { + intervalDropCount, _ = fields[i+1].(float64) + } + if key == "total_dropped_logs" { + totalDropCount, _ = fields[i+1].(float64) } } } @@ -217,6 +228,8 @@ func TestDroppedLogRecoveryOnDroppedHeartbeat(t *testing.T) { // Since we disabled internal errors, it should only be the logs explicitly sent assert.LessOrEqual(t, intervalDropCount, float64(10), "Interval drops should be minimal after fixing disk") - // The 'total_dropped_logs' counter should be accurate, reflecting the initial flood (~50) + the one dropped heartbeat - assert.True(t, totalDropCount >= float64(floodCount), "Total drop count should be at least the number of flooded logs plus the dropped heartbeat.") -} \ No newline at end of file + // Compare against observed flood drops, not the flood constant; + // TotalDroppedLogs monotonically includes the dropped heartbeat + assert.GreaterOrEqual(t, totalDropCount, float64(floodDrops), + "Total drop count must cover flood drops plus the dropped heartbeat") +} diff --git a/sanitizer/sanitizer.go b/sanitizer/sanitizer.go index 43c4c04..7314bc0 100644 --- a/sanitizer/sanitizer.go +++ b/sanitizer/sanitizer.go @@ -1,5 +1,10 @@ // Package sanitizer provides a fluent and composable interface for sanitizing // strings based on configurable rules using bitwise filter flags and transforms. +// +// Concurrency contract: a Sanitizer is immutable after configuration. +// Configure via Rule/RuleFunc/Policy before sharing; Sanitize and +// AppendSanitize are then safe for concurrent use. Serializer is stateless +// and inherits the same contract. package sanitizer import ( @@ -32,24 +37,37 @@ const ( type PolicyPreset string const ( - PolicyRaw PolicyPreset = "raw" // Raw is a no-op (passthrough) - PolicyJSON PolicyPreset = "json" // Policy for sanitizing strings to be embedded in JSON - PolicyTxt PolicyPreset = "txt" // Policy for sanitizing text written to log files + PolicyRaw PolicyPreset = "raw" // Raw is a no-op (passthrough) + PolicyJSON PolicyPreset = "json" // Policy for sanitizing strings to be embedded in JSON + PolicyTxt PolicyPreset = "txt" // Policy for sanitizing text written to log files + // PolicyShell strips shell metacharacters, whitespace, and control characters. NOT sufficient for safe shell construction. Pass arguments via exec argv instead. PolicyShell PolicyPreset = "shell" // Policy for sanitizing arguments passed to shell commands ) // rule represents a single sanitization rule type rule struct { + fn func(rune) bool // predicate rules (RuleFunc) filter uint64 transform uint64 } +func (rl rule) matches(r rune) bool { + if rl.fn != nil { + return rl.fn(r) + } + return matchesFilter(r, rl.filter) +} + // policyRules contains pre-configured rules for each policy var policyRules = map[PolicyPreset][]rule{ - PolicyRaw: {}, - PolicyTxt: {{filter: FilterNonPrintable, transform: TransformHexEncode}}, + PolicyRaw: {}, + PolicyTxt: { + {fn: func(r rune) bool { return r == '<' }, transform: TransformHexEncode}, + {filter: FilterNonPrintable, transform: TransformHexEncode}, + }, + // PolicyTxt: {{filter: FilterNonPrintable, transform: TransformHexEncode}}, PolicyJSON: {{filter: FilterControl, transform: TransformJSONEscape}}, - PolicyShell: {{filter: FilterShellSpecial | FilterWhitespace, transform: TransformStrip}}, + PolicyShell: {{filter: FilterShellSpecial | FilterWhitespace | FilterControl, transform: TransformStrip}}, } // filterCheckers maps individual filter flags to their check functions @@ -59,7 +77,9 @@ var filterCheckers = map[uint64]func(rune) bool{ FilterWhitespace: unicode.IsSpace, FilterShellSpecial: func(r rune) bool { switch r { - case '`', '$', ';', '|', '&', '>', '<', '(', ')', '#': + // CHANGED: D2 — added quotes, backslash, glob, braces, '~', '!' + case '`', '$', ';', '|', '&', '>', '<', '(', ')', '#', + '\'', '"', '\\', '*', '?', '[', ']', '{', '}', '~', '!': return true } return false @@ -69,14 +89,12 @@ var filterCheckers = map[uint64]func(rune) bool{ // Sanitizer provides chainable text sanitization type Sanitizer struct { rules []rule - buf []byte } // New creates a new Sanitizer instance func New() *Sanitizer { return &Sanitizer{ rules: []rule{}, - buf: make([]byte, 0, 256), } } @@ -87,7 +105,13 @@ func (s *Sanitizer) Rule(filter uint64, transform uint64) *Sanitizer { return s } -// Policy applies a pre-configured policy to the sanitizer (appended) +// RuleFunc adds a predicate-based rule (appended, earliest rule applies first) +func (s *Sanitizer) RuleFunc(fn func(rune) bool, transform uint64) *Sanitizer { + s.rules = append(s.rules, rule{fn: fn, transform: transform}) + return s +} + +// Policy applies a pre-configured policy (appended) func (s *Sanitizer) Policy(preset PolicyPreset) *Sanitizer { if rules, ok := policyRules[preset]; ok { s.rules = append(s.rules, rules...) @@ -95,29 +119,57 @@ func (s *Sanitizer) Policy(preset PolicyPreset) *Sanitizer { return s } -// Sanitize applies all configured rules to the input string +// Sanitize applies all configured rules. Returns the input unchanged (no +// allocation) when no rule matches. Safe for concurrent use. func (s *Sanitizer) Sanitize(data string) string { - // Reset buffer - s.buf = s.buf[:0] + if len(s.rules) == 0 { + return data + } + i := s.firstMatch(data) + if i < 0 { + return data + } + buf := make([]byte, 0, len(data)+16) + buf = append(buf, data[:i]...) + buf = s.appendSanitized(buf, data[i:]) + return string(buf) +} - // Process each rune +// AppendSanitize appends the sanitized form of data to dst and returns the extended slice. Safe for concurrent use. +func (s *Sanitizer) AppendSanitize(dst []byte, data string) []byte { + if len(s.rules) == 0 { + return append(dst, data...) + } + return s.appendSanitized(dst, data) +} + +// firstMatch returns the byte index of the first rune matching any rule, -1 if none +func (s *Sanitizer) firstMatch(data string) int { + for i, r := range data { + for _, rl := range s.rules { + if rl.matches(r) { + return i + } + } + } + return -1 +} + +func (s *Sanitizer) appendSanitized(dst []byte, data string) []byte { for _, r := range data { matched := false - // Check rules in order (first match wins) - for _, rl := range s.rules { - if matchesFilter(r, rl.filter) { - applyTransform(&s.buf, r, rl.transform) + for _, rl := range s.rules { // first match wins + if rl.matches(r) { + applyTransform(&dst, r, rl.transform) matched = true break } } - // If no rule matched, append original rune if !matched { - s.buf = utf8.AppendRune(s.buf, r) + dst = utf8.AppendRune(dst, r) } } - - return string(s.buf) + return dst } // matchesFilter checks if a rune matches any filter in the mask @@ -171,8 +223,8 @@ func applyTransform(buf *[]byte, r rune, transformMask uint64) { // Serializer implements format-specific output behaviors type Serializer struct { - format string sanitizer *Sanitizer + format string } // NewSerializer creates a handler with format-specific behavior @@ -183,7 +235,9 @@ func NewSerializer(format string, san *Sanitizer) *Serializer { } } -// WriteString writes a string with format-specific handling +// WriteString writes a string with format-specific handling. +// Layering: the sanitizer runs first as a content transform; +// json transport escaping is always applied last, guaranteeing valid JSON output regardless of policy. func (se *Serializer) WriteString(buf *[]byte, s string) { switch se.format { case "raw": @@ -205,14 +259,21 @@ func (se *Serializer) WriteString(buf *[]byte, s string) { } case "json": + // Sanitizer applied as content transform before escaping + s = se.sanitizer.Sanitize(s) *buf = append(*buf, '"') - // Direct JSON escaping for i := 0; i < len(s); { c := s[i] - if c >= ' ' && c != '"' && c != '\\' && c < 0x7f { + // raw UTF-8 is valid in JSON strings. Only <0x20, '"', '\\', 0x7f are escaped. + if c >= 0x20 && c != '"' && c != '\\' && c != 0x7f { start := i - for i < len(s) && s[i] >= ' ' && s[i] != '"' && s[i] != '\\' && s[i] < 0x7f { - i++ + for i < len(s) { + c = s[i] + if c >= 0x20 && c != '"' && c != '\\' && c != 0x7f { + i++ + } else { + break + } } *buf = append(*buf, s[start:i]...) } else { @@ -236,6 +297,7 @@ func (se *Serializer) WriteString(buf *[]byte, s string) { } } *buf = append(*buf, '"') + } } @@ -308,4 +370,5 @@ func (se *Serializer) NeedsQuotes(s string) bool { default: return false } -} \ No newline at end of file +} + diff --git a/sanitizer/sanitizer_test.go b/sanitizer/sanitizer_test.go index 94ff68f..bd0d146 100644 --- a/sanitizer/sanitizer_test.go +++ b/sanitizer/sanitizer_test.go @@ -2,6 +2,7 @@ package sanitizer import ( "strings" + "sync" "testing" "github.com/stretchr/testify/assert" @@ -93,8 +94,8 @@ func TestChaining(t *testing.T) { Rule(FilterWhitespace, TransformStrip). Rule(FilterShellSpecial, TransformHexEncode) - // Shell special chars are checked first (prepended), get hex encoded - // Whitespace rule is second, strips spaces + // Rules append in call order; first match wins. + // Whitespace rule strips spaces; shell rule hex-encodes ';'. assert.Equal(t, "cmd<3b>echohello", s.Sanitize("cmd; echo hello")) } @@ -176,6 +177,20 @@ func TestSerializer(t *testing.T) { assert.Contains(t, string(buf), "map[") }) + t.Run("json utf8 passthrough", func(t *testing.T) { + handler := NewSerializer("json", New()) + var buf []byte + handler.WriteString(&buf, "héllo 世界") + assert.Equal(t, `"héllo 世界"`, string(buf)) + }) + + t.Run("json sanitizer applied", func(t *testing.T) { + handler := NewSerializer("json", New().Policy(PolicyTxt)) + var buf []byte + handler.WriteString(&buf, "a\x00b") + assert.Equal(t, `"a<00>b"`, string(buf)) + }) + t.Run("nil handling", func(t *testing.T) { san := New() @@ -237,4 +252,52 @@ func TestTransformPriority(t *testing.T) { // Should strip (first flag checked), not hex encode assert.Equal(t, "ab", s.Sanitize("a\x00b")) -} \ No newline at end of file +} + +func TestSanitizerConcurrent(t *testing.T) { + s := New().Policy(PolicyTxt) + var wg sync.WaitGroup + for i := 0; i < 16; i++ { + wg.Add(1) + go func() { + defer wg.Done() + for j := 0; j < 500; j++ { + if got := s.Sanitize("a\x00b\x07c"); got != "a<00>b<07>c" { + t.Errorf("got %q", got) + return + } + } + }() + } + wg.Wait() +} + +func TestSanitizeCleanFastPath(t *testing.T) { + s := New().Policy(PolicyTxt) + in := "clean ascii text" + assert.Equal(t, in, s.Sanitize(in)) + assert.Zero(t, testing.AllocsPerRun(100, func() { _ = s.Sanitize(in) })) +} + +func TestAppendSanitize(t *testing.T) { + s := New().Policy(PolicyTxt) + buf := append([]byte(nil), "prefix:"...) + buf = s.AppendSanitize(buf, "a\x00b") + assert.Equal(t, "prefix:a<00>b", string(buf)) +} + +func TestHexMarkerEscaping(t *testing.T) { + s := New().Policy(PolicyTxt) + assert.Equal(t, "a<00>b", s.Sanitize("a\x00b")) // actual NUL + assert.Equal(t, "a<3c>00>b", s.Sanitize("a<00>b")) // literal text "<00>" — unambiguous +} + +func TestPolicyShellExtended(t *testing.T) { + s := New().Policy(PolicyShell) + assert.Equal(t, "abc", s.Sanitize(`a'b"c`)) + assert.Equal(t, "ab", s.Sanitize(`a\b`)) + assert.Equal(t, "file", s.Sanitize("file*?")) + assert.Equal(t, "rm-rf", s.Sanitize("rm -rf *")) + assert.Equal(t, "ab", s.Sanitize("a\x00\x1bb")) // control stripped +} +