From 2af9af235923a9636c98dd0755358ec4b60f793a34256a8a57222afc5c3af8ce Mon Sep 17 00:00:00 2001 From: Lixen Wraith Date: Sat, 1 Aug 2026 05:09:51 -0400 Subject: [PATCH] v0.1.9 kv flag added, unix and nofs build tags, heartbeat and rotation filename and test update --- builder.go | 18 +- constant.go | 2 +- formatter/formatter.go | 231 ++++++++++++--- heartbeat.go | 8 +- integration_test.go | 7 +- logger.go | 639 +++++++++++++++++++++++++---------------- processor.go | 74 ++--- processor_test.go | 50 +++- record.go | 139 +++++---- state.go | 10 +- storage.go | 98 ++++--- storage_nofs.go | 11 + storage_test.go | 22 +- storage_unix.go | 30 ++ type.go | 15 +- 15 files changed, 873 insertions(+), 481 deletions(-) create mode 100644 storage_nofs.go create mode 100644 storage_unix.go diff --git a/builder.go b/builder.go index a4dcdb6..6a30a82 100644 --- a/builder.go +++ b/builder.go @@ -7,8 +7,10 @@ import ( // Builder provides a fluent API for building logger configurations // It wraps a Config instance and provides chainable methods for setting values type Builder struct { - cfg *Config - err error // Accumulate errors for deferred handling + err error // Accumulate errors for deferred handling + cfg *Config + ctxTag string + ctxVals []string } // NewBuilder creates a new configuration builder with default values @@ -18,6 +20,13 @@ func NewBuilder() *Builder { } } +// ContextKeys names the record keys for Context values +func (b *Builder) ContextKeys(tag string, vals ...string) *Builder { + b.ctxTag = tag + b.ctxVals = vals + return b +} + // Build creates a new Logger instance with the specified configuration func (b *Builder) Build() (*Logger, error) { if b.err != nil { @@ -31,6 +40,9 @@ func (b *Builder) Build() (*Logger, error) { if err := logger.ApplyConfig(b.cfg); err != nil { return nil, err } + if b.ctxTag != "" || len(b.ctxVals) > 0 { + logger.SetContextKeys(b.ctxTag, b.ctxVals...) + } return logger, nil } @@ -249,4 +261,4 @@ func (b *Builder) EnableConsole(enable bool) *Builder { // defer logger.Shutdown() // logger.Info("Logger initialized successfully") // -// } \ No newline at end of file +// } diff --git a/constant.go b/constant.go index a9c1bc5..9ad4adc 100644 --- a/constant.go +++ b/constant.go @@ -28,6 +28,7 @@ const ( FlagShowTimestamp = formatter.FlagShowTimestamp FlagShowLevel = formatter.FlagShowLevel FlagStructuredJSON = formatter.FlagStructuredJSON + FlagKV = formatter.FlagKV FlagNoTimestamp = formatter.FlagNoTimestamp FlagNoLevel = formatter.FlagNoLevel FlagDefault = formatter.FlagDefault @@ -57,4 +58,3 @@ const ( adaptiveIntervalFactor float64 = 1.5 // Slow down adaptiveSpeedUpFactor float64 = 0.8 // Speed up ) - diff --git a/formatter/formatter.go b/formatter/formatter.go index b0bb2be..ccaf3f9 100644 --- a/formatter/formatter.go +++ b/formatter/formatter.go @@ -34,6 +34,7 @@ const ( FlagStructuredJSON int64 = 0b1000 FlagNoTimestamp int64 = 0b010000 FlagNoLevel int64 = 0b100000 + FlagKV int64 = 0b1000000 // args are alternating string keys and values FlagDefault = FlagShowTimestamp | FlagShowLevel ) @@ -44,7 +45,31 @@ type Formatter struct { timestampFormat string showTimestamp bool showLevel bool + ctxKeys ContextKeys buf []byte + + // Serializers are stateless and format-fixed; built once to keep the + // per-record path allocation-free + serTxt *sanitizer.Serializer + serJSON *sanitizer.Serializer + serRaw *sanitizer.Serializer +} + +// ContextSlots is the number of correlation values a Context carries +const ContextSlots = 3 + +// Context carries caller-stamped values emitted with a record. +// Tag names the source; Vals are correlation counters keyed by ContextKeys. +type Context struct { + Tag string + Vals [ContextSlots]uint64 +} + +// ContextKeys names the record keys for Context fields; empty names are omitted. +// Names are emitted verbatim and must be plain identifiers. +type ContextKeys struct { + Tag string + Vals [ContextSlots]string } // New creates a formatter with the provided sanitizer @@ -62,6 +87,30 @@ func New(s ...*sanitizer.Sanitizer) *Formatter { showTimestamp: true, showLevel: true, buf: make([]byte, 0, 1024), + serTxt: sanitizer.NewSerializer("txt", san), + serJSON: sanitizer.NewSerializer("json", san), + serRaw: sanitizer.NewSerializer("raw", san), + } +} + +// ContextKeys sets the record keys used for Context values +func (f *Formatter) ContextKeys(tag string, vals ...string) *Formatter { + f.ctxKeys = ContextKeys{Tag: tag} + for i := 0; i < len(vals) && i < ContextSlots; i++ { + f.ctxKeys.Vals[i] = vals[i] + } + return f +} + +// serializerFor returns the cached serializer for a normalized format name +func (f *Formatter) serializerFor(format string) *sanitizer.Serializer { + switch format { + case "json": + return f.serJSON + case "raw": + return f.serRaw + default: + return f.serTxt } } @@ -94,14 +143,24 @@ func (f *Formatter) ShowTimestamp(show bool) *Formatter { // 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 { - f.buf = f.AppendFormat(f.buf[:0], flags, timestamp, level, trace, args) + return f.FormatCtx(Context{}, flags, timestamp, level, trace, args) +} + +// FormatCtx is Format with caller-stamped context. +// Returned slice aliases the internal buffer. +func (f *Formatter) FormatCtx(ctx Context, flags int64, timestamp time.Time, level int64, trace string, args []any) []byte { + f.buf = f.AppendFormatCtx(f.buf[:0], ctx, flags, timestamp, level, trace, args) return f.buf } // 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 + return f.AppendFormatCtx(dst, Context{}, flags, timestamp, level, trace, args) +} + +// AppendFormatCtx is AppendFormat with caller-stamped context +func (f *Formatter) AppendFormatCtx(dst []byte, ctx Context, flags int64, timestamp time.Time, level int64, trace string, args []any) []byte { eff := flags &^ (FlagShowTimestamp | FlagShowLevel) if resolveShow(flags, FlagShowTimestamp, FlagNoTimestamp, f.showTimestamp) { eff |= FlagShowTimestamp @@ -109,31 +168,25 @@ func (f *Formatter) AppendFormat(dst []byte, flags int64, timestamp time.Time, l 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 - } + return f.AppendFormatWithOptionsCtx(dst, f.format, ctx, eff, timestamp, level, trace, args) } // 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) + f.buf = f.AppendFormatWithOptionsCtx(f.buf[:0], format, Context{}, flags, timestamp, level, trace, args) return f.buf } -// AppendFormatWithOptions is the allocation-explicit core. Safe for -// concurrent use. Unknown formats fall back to "txt". +// AppendFormatWithOptions is the compatibility wrapper over the context core 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 + return f.AppendFormatWithOptionsCtx(dst, format, Context{}, flags, timestamp, level, trace, args) +} + +// AppendFormatWithOptionsCtx is the allocation-explicit core. Safe for +// concurrent use. Unknown formats fall back to "txt". +func (f *Formatter) AppendFormatWithOptionsCtx(dst []byte, format string, ctx Context, flags int64, timestamp time.Time, level int64, trace string, args []any) []byte { + // FlagRaw completely bypasses formatting, context, and sanitization if flags&FlagRaw != 0 { for i, arg := range args { if i > 0 { @@ -155,9 +208,8 @@ func (f *Formatter) AppendFormatWithOptions(dst []byte, format string, flags int return dst } - // unknown formats normalize to txt instead of returning nil format = normalizeFormat(format) - serializer := sanitizer.NewSerializer(format, f.sanitizer) + serializer := f.serializerFor(format) switch format { case "raw": @@ -166,9 +218,20 @@ func (f *Formatter) AppendFormatWithOptions(dst []byte, format string, flags int } return dst case "json": - return f.appendJSON(dst, flags, timestamp, level, trace, args, serializer) + return f.appendJSON(dst, ctx, flags, timestamp, level, trace, args, serializer) default: // "txt" - return f.appendTxt(dst, flags, timestamp, level, trace, args, serializer) + return f.appendTxt(dst, ctx, flags, timestamp, level, trace, args, serializer) + } +} + +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 } } @@ -188,10 +251,8 @@ func (f *Formatter) FormatValue(v any) []byte { } // 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) + return f.appendValue(dst, v, f.serializerFor(normalizeFormat(f.format)), false) } // FormatArgs formats multiple arguments. Returned slice aliases the internal buffer. @@ -202,9 +263,8 @@ func (f *Formatter) FormatArgs(args ...any) []byte { // 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) + serializer := f.serializerFor(normalizeFormat(f.format)) for i, arg := range args { dst = f.appendValue(dst, arg, serializer, i > 0) } @@ -278,8 +338,29 @@ func LevelToString(level int64) string { } } +// appendJSONKey writes a quoted literal key followed by ':' +func appendJSONKey(dst []byte, key string) []byte { + dst = append(dst, '"') + dst = append(dst, key...) + dst = append(dst, '"', ':') + return dst +} + +// isKV reports whether args form an even-length list with string keys +func isKV(args []any) bool { + if len(args) == 0 || len(args)%2 != 0 { + return false + } + for i := 0; i < len(args); i += 2 { + if _, ok := args[i].(string); !ok { + return false + } + } + return true +} + // 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 { +func (f *Formatter) appendJSON(dst []byte, ctx Context, flags int64, timestamp time.Time, level int64, trace string, args []any, serializer *sanitizer.Serializer) []byte { dst = append(dst, '{') needsComma := false @@ -300,6 +381,27 @@ func (f *Formatter) appendJSON(dst []byte, flags int64, timestamp time.Time, lev needsComma = true } + // Caller-stamped context, emitted as top-level keys + if ctx.Tag != "" && f.ctxKeys.Tag != "" { + if needsComma { + dst = append(dst, ',') + } + dst = appendJSONKey(dst, f.ctxKeys.Tag) + serializer.WriteString(&dst, ctx.Tag) + needsComma = true + } + for i, key := range f.ctxKeys.Vals { + if key == "" { + continue + } + if needsComma { + dst = append(dst, ',') + } + dst = appendJSONKey(dst, key) + dst = strconv.AppendUint(dst, ctx.Vals[i], 10) + needsComma = true + } + if trace != "" { if needsComma { dst = append(dst, ',') @@ -336,19 +438,32 @@ func (f *Formatter) appendJSON(dst []byte, flags int64, timestamp time.Time, lev } } - // Regular JSON with fields array if len(args) > 0 { if needsComma { dst = append(dst, ',') } - dst = append(dst, `"fields":[`...) - for i, arg := range args { - if i > 0 { - dst = append(dst, ',') + // Keyed object when the caller declares k/v args, positional array otherwise + if flags&FlagKV != 0 && isKV(args) { + dst = append(dst, `"fields":{`...) + for i := 0; i < len(args); i += 2 { + if i > 0 { + dst = append(dst, ',') + } + serializer.WriteString(&dst, args[i].(string)) + dst = append(dst, ':') + dst = f.appendValue(dst, args[i+1], serializer, false) } - dst = f.appendValue(dst, arg, serializer, false) + dst = append(dst, '}') + } else { + dst = append(dst, `"fields":[`...) + for i, arg := range args { + if i > 0 { + dst = append(dst, ',') + } + dst = f.appendValue(dst, arg, serializer, false) + } + dst = append(dst, ']') } - dst = append(dst, ']') } dst = append(dst, '}', '\n') @@ -356,7 +471,7 @@ func (f *Formatter) appendJSON(dst []byte, flags int64, timestamp time.Time, lev } // 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 { +func (f *Formatter) appendTxt(dst []byte, ctx Context, flags int64, timestamp time.Time, level int64, trace string, args []any, serializer *sanitizer.Serializer) []byte { needsSpace := false if flags&FlagShowTimestamp != 0 { @@ -372,14 +487,35 @@ func (f *Formatter) appendTxt(dst []byte, flags int64, timestamp time.Time, leve needsSpace = true } + if ctx.Tag != "" && f.ctxKeys.Tag != "" { + if needsSpace { + dst = append(dst, ' ') + } + dst = append(dst, f.ctxKeys.Tag...) + dst = append(dst, '=') + dst = f.appendValue(dst, ctx.Tag, serializer, false) + needsSpace = true + } + for i, key := range f.ctxKeys.Vals { + if key == "" { + continue + } + if needsSpace { + dst = append(dst, ' ') + } + dst = append(dst, key...) + dst = append(dst, '=') + dst = strconv.AppendUint(dst, ctx.Vals[i], 10) + needsSpace = true + } + if trace != "" { if needsSpace { dst = append(dst, ' ') } // Sanitize trace to prevent terminal control sequence injection - traceHandler := sanitizer.NewSerializer("txt", f.sanitizer) tempBuf := make([]byte, 0, len(trace)*2) - traceHandler.WriteString(&tempBuf, trace) + f.serTxt.WriteString(&tempBuf, trace) // Extract content without quotes if added by txt serializer if len(tempBuf) > 2 && tempBuf[0] == '"' && tempBuf[len(tempBuf)-1] == '"' { dst = append(dst, tempBuf[1:len(tempBuf)-1]...) @@ -389,9 +525,21 @@ func (f *Formatter) appendTxt(dst []byte, flags int64, timestamp time.Time, leve needsSpace = true } - for _, arg := range args { - dst = f.appendValue(dst, arg, serializer, needsSpace) - needsSpace = true + if flags&FlagKV != 0 && isKV(args) { + for i := 0; i < len(args); i += 2 { + if needsSpace { + dst = append(dst, ' ') + } + dst = append(dst, args[i].(string)...) + dst = append(dst, '=') + dst = f.appendValue(dst, args[i+1], serializer, false) + needsSpace = true + } + } else { + for _, arg := range args { + dst = f.appendValue(dst, arg, serializer, needsSpace) + needsSpace = true + } } dst = append(dst, '\n') @@ -402,4 +550,3 @@ func (f *Formatter) appendTxt(dst []byte, flags int64, timestamp time.Time, leve func (f *Formatter) Reset() { f.buf = f.buf[:0] } - diff --git a/heartbeat.go b/heartbeat.go index cb18285..0aa6c7a 100644 --- a/heartbeat.go +++ b/heartbeat.go @@ -128,20 +128,18 @@ func (l *Logger) logSysHeartbeat() { l.writeHeartbeatRecord(LevelSys, sysArgs) } -// writeHeartbeatRecord creates and sends a heartbeat log record through the main processing channel +// writeHeartbeatRecord creates and sends a heartbeat record, bypassing the level gate func (l *Logger) writeHeartbeatRecord(level int64, args []any) { if l.state.LoggerDisabled.Load() || l.state.ShutdownCalled.Load() { return } - // Create heartbeat record with appropriate flags record := logRecord{ - Flags: FlagDefault | FlagShowLevel, + Flags: FlagDefault | FlagKV, TimeStamp: time.Now(), Level: level, - Trace: "", Args: args, } l.sendLogRecord(record) -} \ No newline at end of file +} diff --git a/integration_test.go b/integration_test.go index a8e75e8..b08ce23 100644 --- a/integration_test.go +++ b/integration_test.go @@ -53,7 +53,7 @@ func TestFullLifecycle(t *testing.T) { // MaxSizeKB=1 forces rotation, so assertions span every file in the directory mustEventually(t, 3*time.Second, "proc heartbeat emitted", func() bool { - return strings.Contains(readAllLogs(t, tmpDir), `"type","proc"`) + return strings.Contains(readAllLogs(t, tmpDir), `"type":"proc"`) }) mustNoErr(t, logger.Flush(time.Second), "Flush") @@ -63,8 +63,8 @@ func TestFullLifecycle(t *testing.T) { contains(t, content, `"user_id":123`, "structured field") contains(t, content, "raw data write", "raw write") contains(t, content, "after reconfiguration", "post-reconfiguration record") - contains(t, content, `"type","disk"`, "disk heartbeat") - contains(t, content, `"type","sys"`, "sys heartbeat") + contains(t, content, `"type":"disk"`, "disk heartbeat") + contains(t, content, `"type":"sys"`, "sys heartbeat") files, err := os.ReadDir(tmpDir) mustNoErr(t, err, "ReadDir") @@ -162,4 +162,3 @@ func TestErrorRecovery(t *testing.T) { isTrue(t, logger.state.DiskStatusOK.Load(), "DiskStatusOK after recovery") }) } - diff --git a/logger.go b/logger.go index 42ecbf5..195b872 100644 --- a/logger.go +++ b/logger.go @@ -4,6 +4,7 @@ import ( "errors" "fmt" "io" + "math" "os" "sync" "sync/atomic" @@ -17,10 +18,16 @@ import ( type Logger struct { currentConfig atomic.Value // stores *Config formatter atomic.Value // stores *formatter.Formatter + ctxKeys atomic.Pointer[formatter.ContextKeys] + spawner atomic.Pointer[func(func())] + errHandler atomic.Pointer[func(string)] state State initMu sync.Mutex } +// levelOff closes the emit gate without touching configuration +const levelOff int64 = math.MaxInt64 + // NewLogger creates a new Logger instance with default settings func NewLogger() *Logger { l := &Logger{} @@ -28,14 +35,20 @@ func NewLogger() *Logger { // Set default configuration defaultCfg := DefaultConfig() l.currentConfig.Store(defaultCfg) + l.rebuildFormatter(defaultCfg) - // Initialize default formatter to prevent nil access - defaultFormatter := formatter.New(sanitizer.New()). - Type(defaultCfg.Format). - TimestampFormat(defaultCfg.TimestampFormat). - ShowLevel(defaultCfg.ShowLevel). - ShowTimestamp(defaultCfg.ShowTimestamp) - l.formatter.Store(defaultFormatter) + // Emission stays closed until ApplyConfig and Start succeed + l.state.Level.Store(levelOff) + l.state.Flags.Store(flagsFromConfig(defaultCfg)) + l.state.TraceDepth.Store(defaultCfg.TraceDepth) + + // // Initialize default formatter to prevent nil access + // defaultFormatter := formatter.New(sanitizer.New()). + // Type(defaultCfg.Format). + // TimestampFormat(defaultCfg.TimestampFormat). + // ShowLevel(defaultCfg.ShowLevel). + // ShowTimestamp(defaultCfg.ShowTimestamp) + // l.formatter.Store(defaultFormatter) // Initialize the state l.state.IsInitialized.Store(false) @@ -54,13 +67,17 @@ func NewLogger() *Logger { l.state.TotalRotations.Store(0) l.state.TotalDeletions.Store(0) - // Create a closed channel initially to prevent nil pointer issues - initialChan := make(chan logRecord) - close(initialChan) - l.state.ActiveLogChannel.Store(initialChan) - + // Typed nil: a non-blocking send on a nil channel always takes default + l.state.ActiveLogChannel.Store((chan logRecord)(nil)) l.state.flushRequestChan = make(chan chan struct{}, 1) + // // Create a closed channel initially to prevent nil pointer issues + // initialChan := make(chan logRecord) + // close(initialChan) + // l.state.ActiveLogChannel.Store(initialChan) + // + // l.state.flushRequestChan = make(chan chan struct{}, 1) + return l } @@ -112,237 +129,6 @@ func (l *Logger) GetConfig() *Config { return l.getConfig().Clone() } -// Start begins log processing. Safe to call multiple times -// Returns error if logger is not initialized -func (l *Logger) Start() error { - if !l.state.IsInitialized.Load() { - return fmtErrorf("logger not initialized, call ApplyConfig first") - } - - // Check if processor didn't exit cleanly last time - if l.state.Started.Load() && !l.state.ProcessorExited.Load() { - // Force stop to clean up - l.internalLog("warning - processor still running from previous start, forcing stop\n") - if err := l.Stop(); err != nil { - return fmtErrorf("failed to stop hung processor: %w", err) - } - } - - // Only start if not already started - if l.state.Started.CompareAndSwap(false, true) { - cfg := l.getConfig() - - // Create log channel - logChannel := make(chan logRecord, cfg.BufferSize) - l.state.ActiveLogChannel.Store(logChannel) - - // Start processor - l.state.ProcessorExited.Store(false) - go l.processLogs(logChannel) - } - - return nil -} - -// Stop halts log processing. Can be restarted with Start() -// Returns nil if already stopped -func (l *Logger) Stop(timeout ...time.Duration) error { - if !l.state.Started.CompareAndSwap(true, false) { - return nil // Already stopped - } - - // Calculate effective timeout - var effectiveTimeout time.Duration - if len(timeout) > 0 { - effectiveTimeout = timeout[0] - } else { - cfg := l.getConfig() - effectiveTimeout = 2 * time.Duration(cfg.FlushIntervalMs) * time.Millisecond - } - - // Get current channel and close it - ch := l.getCurrentLogChannel() - if ch != nil { - // Create closed channel for immediate replacement - closedChan := make(chan logRecord) - close(closedChan) - l.state.ActiveLogChannel.Store(closedChan) - - // Close the actual channel to signal processor - close(ch) - } - - // Wait for processor to exit (with timeout) - deadline := time.Now().Add(effectiveTimeout) - for time.Now().Before(deadline) { - if l.state.ProcessorExited.Load() { - break - } - time.Sleep(10 * time.Millisecond) - } - - if !l.state.ProcessorExited.Load() { - return fmtErrorf("processor did not exit within timeout (%v)", effectiveTimeout) - } - - return nil -} - -// Shutdown gracefully closes the logger, attempting to flush pending records -// If no timeout is provided, uses a default of 2x flush interval -func (l *Logger) Shutdown(timeout ...time.Duration) error { - if !l.state.ShutdownCalled.CompareAndSwap(false, true) { - return nil - } - - l.state.LoggerDisabled.Store(true) - - if !l.state.IsInitialized.Load() { - l.state.ShutdownCalled.Store(false) - l.state.LoggerDisabled.Store(false) - l.state.ProcessorExited.Store(true) - return nil - } - - var stopErr error - if l.state.Started.Load() { - stopErr = l.Stop(timeout...) - } - - l.state.IsInitialized.Store(false) - - var finalErr error - cfPtr := l.state.CurrentFile.Load() - if cfPtr != nil { - if currentLogFile, ok := cfPtr.(*os.File); ok && currentLogFile != nil { - if err := currentLogFile.Sync(); err != nil { - syncErr := fmtErrorf("failed to sync log file '%s' during shutdown: %w", currentLogFile.Name(), err) - finalErr = errors.Join(finalErr, syncErr) - } - if err := currentLogFile.Close(); err != nil { - closeErr := fmtErrorf("failed to close log file '%s' during shutdown: %w", currentLogFile.Name(), err) - finalErr = errors.Join(finalErr, closeErr) - } - l.state.CurrentFile.Store((*os.File)(nil)) - } - } - - if stopErr != nil { - finalErr = errors.Join(finalErr, stopErr) - } - - return finalErr -} - -// Flush explicitly triggers a sync of the current log file buffer to disk and waits for completion or timeout -func (l *Logger) Flush(timeout time.Duration) error { - l.state.flushMutex.Lock() - defer l.state.flushMutex.Unlock() - - // State checks - if !l.state.IsInitialized.Load() || l.state.ShutdownCalled.Load() { - return fmtErrorf("logger not initialized or already shut down") - } - if !l.state.Started.Load() { - return fmtErrorf("logger not started") - } - - // Create a channel to wait for confirmation from the processor - confirmChan := make(chan struct{}) - - // Send the request with the confirmation channel - select { - case l.state.flushRequestChan <- confirmChan: - // Request sent - case <-time.After(minWaitTime): // Short timeout to prevent blocking if processor is stuck - return fmtErrorf("failed to send flush request to processor (possible deadlock or high load)") - } - - select { - case <-confirmChan: - return nil - case <-time.After(timeout): - return fmtErrorf("timeout waiting for flush confirmation (%v)", timeout) - } -} - -// Debug logs a message at debug level -func (l *Logger) Debug(args ...any) { - flags := l.getFlags() - cfg := l.getConfig() - l.log(flags, LevelDebug, cfg.TraceDepth, args...) -} - -// Info logs a message at info level -func (l *Logger) Info(args ...any) { - flags := l.getFlags() - cfg := l.getConfig() - l.log(flags, LevelInfo, cfg.TraceDepth, args...) -} - -// Warn logs a message at warning level -func (l *Logger) Warn(args ...any) { - flags := l.getFlags() - cfg := l.getConfig() - l.log(flags, LevelWarn, cfg.TraceDepth, args...) -} - -// Error logs a message at error level -func (l *Logger) Error(args ...any) { - flags := l.getFlags() - cfg := l.getConfig() - l.log(flags, LevelError, cfg.TraceDepth, args...) -} - -// DebugTrace logs a debug message with function call trace -func (l *Logger) DebugTrace(depth int, args ...any) { - flags := l.getFlags() - l.log(flags, LevelDebug, int64(depth), args...) -} - -// InfoTrace logs an info message with function call trace -func (l *Logger) InfoTrace(depth int, args ...any) { - flags := l.getFlags() - l.log(flags, LevelInfo, int64(depth), args...) -} - -// WarnTrace logs a warning message with function call trace -func (l *Logger) WarnTrace(depth int, args ...any) { - flags := l.getFlags() - l.log(flags, LevelWarn, int64(depth), args...) -} - -// ErrorTrace logs an error message with function call trace -func (l *Logger) ErrorTrace(depth int, args ...any) { - flags := l.getFlags() - l.log(flags, LevelError, int64(depth), args...) -} - -// Log writes a timestamp-only record without level information -func (l *Logger) Log(args ...any) { - 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(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|FlagNoLevel, LevelInfo, int64(depth), args...) -} - -// LogStructured logs a message with structured fields as proper JSON -func (l *Logger) LogStructured(level int64, message string, fields map[string]any) { - l.log(l.getFlags()|FlagStructuredJSON, level, 0, message, fields) -} - -// Write outputs raw, unformatted data ignoring configured format and sanitization without trailing new line -func (l *Logger) Write(args ...any) { - l.log(FlagRaw, LevelInfo, 0, args...) -} - // getConfig returns the current configuration (thread-safe) func (l *Logger) getConfig() *Config { return l.currentConfig.Load().(*Config) @@ -353,20 +139,19 @@ func (l *Logger) applyConfig(cfg *Config) error { oldCfg := l.getConfig() l.currentConfig.Store(cfg) - // Create formatter with sanitizer - s := sanitizer.New().Policy(cfg.Sanitization) - newFormatter := formatter.New(s). - Type(cfg.Format). - TimestampFormat(cfg.TimestampFormat). - ShowLevel(cfg.ShowLevel). - ShowTimestamp(cfg.ShowTimestamp) - l.formatter.Store(newFormatter) + // Shared formatter and sanitizer constructor with SetContextKeys + l.rebuildFormatter(cfg) + + // Emit fast-path mirrors + l.state.Flags.Store(flagsFromConfig(cfg)) + l.state.TraceDepth.Store(cfg.TraceDepth) // Ensure log directory exists if file output is enabled if cfg.EnableFile { if err := os.MkdirAll(cfg.Directory, 0755); err != nil { l.state.LoggerDisabled.Store(true) l.currentConfig.Store(oldCfg) // Rollback + l.refreshLevelGate() return fmtErrorf("failed to create log directory '%s': %w", cfg.Directory, err) } } @@ -453,6 +238,7 @@ func (l *Logger) applyConfig(cfg *Config) error { l.state.ShutdownCalled.Store(false) l.state.DiskFullLogged.Store(false) l.state.DiskStatusOK.Store(true) + l.refreshLevelGate() // Restart processor if it was running and needs restart if needsRestart { @@ -461,3 +247,354 @@ func (l *Logger) applyConfig(cfg *Config) error { return nil } + +// Start begins log processing. Safe to call multiple times +// Returns error if logger is not initialized +func (l *Logger) Start() error { + if !l.state.IsInitialized.Load() { + return fmtErrorf("logger not initialized, call ApplyConfig first") + } + + // Check if processor didn't exit cleanly last time + if l.state.Started.Load() && !l.state.ProcessorExited.Load() { + // Force stop to clean up + l.internalLog("warning - processor still running from previous start, forcing stop\n") + if err := l.Stop(); err != nil { + return fmtErrorf("failed to stop hung processor: %w", err) + } + } + + // Only start if not already started + if l.state.Started.CompareAndSwap(false, true) { + cfg := l.getConfig() + + // Create log channels + ch := make(chan logRecord, cfg.BufferSize) + stop := make(chan struct{}) + done := make(chan struct{}) + + l.state.ActiveLogChannel.Store(ch) + l.state.ProcStop.Store(stop) + l.state.ProcDone.Store(done) + l.state.ProcessorExited.Store(false) + + // Start processor + l.spawn(func() { l.processLogs(ch, stop, done) }) + } + + l.refreshLevelGate() + return nil +} + +// Stop halts log processing. Can be restarted with Start() +// The record channel is never closed: producers are detached to a nil channel +// first, so a concurrent send falls through to the drop counter instead of +// racing a close. +func (l *Logger) Stop(timeout ...time.Duration) error { + if !l.state.Started.CompareAndSwap(true, false) { + return nil // Already stopped + } + l.refreshLevelGate() + + // Calculate effective timeout + var effectiveTimeout time.Duration + if len(timeout) > 0 { + effectiveTimeout = timeout[0] + } else { + effectiveTimeout = 2 * time.Duration(l.getConfig().FlushIntervalMs) * time.Millisecond + } + if effectiveTimeout < minWaitTime { + effectiveTimeout = minWaitTime + } + + // 1. Detach producers + l.state.ActiveLogChannel.Store((chan logRecord)(nil)) + + // 2. Signal the processor to drain and exit + if s, ok := l.state.ProcStop.Load().(chan struct{}); ok && s != nil { + close(s) + } + + // 3. Join + d, _ := l.state.ProcDone.Load().(chan struct{}) + if d == nil { + return nil + } + select { + case <-d: + return nil + case <-time.After(effectiveTimeout): + return fmtErrorf("processor did not exit within timeout (%v)", effectiveTimeout) + } +} + +// Shutdown gracefully closes the logger, attempting to flush pending records +// If no timeout is provided, uses a default of 2x flush interval +func (l *Logger) Shutdown(timeout ...time.Duration) error { + if !l.state.ShutdownCalled.CompareAndSwap(false, true) { + return nil + } + + l.state.LoggerDisabled.Store(true) + l.refreshLevelGate() + + if !l.state.IsInitialized.Load() { + l.state.ShutdownCalled.Store(false) + l.state.LoggerDisabled.Store(false) + l.state.ProcessorExited.Store(true) + l.refreshLevelGate() + return nil + } + + var stopErr error + if l.state.Started.Load() { + stopErr = l.Stop(timeout...) + } + + l.state.IsInitialized.Store(false) + + var finalErr error + cfPtr := l.state.CurrentFile.Load() + if cfPtr != nil { + if currentLogFile, ok := cfPtr.(*os.File); ok && currentLogFile != nil { + if err := currentLogFile.Sync(); err != nil { + syncErr := fmtErrorf("failed to sync log file '%s' during shutdown: %w", currentLogFile.Name(), err) + finalErr = errors.Join(finalErr, syncErr) + } + if err := currentLogFile.Close(); err != nil { + closeErr := fmtErrorf("failed to close log file '%s' during shutdown: %w", currentLogFile.Name(), err) + finalErr = errors.Join(finalErr, closeErr) + } + l.state.CurrentFile.Store((*os.File)(nil)) + } + } + + if stopErr != nil { + finalErr = errors.Join(finalErr, stopErr) + } + + return finalErr +} + +// Flush explicitly triggers a sync of the current log file buffer to disk and waits for completion or timeout +func (l *Logger) Flush(timeout time.Duration) error { + l.state.flushMutex.Lock() + defer l.state.flushMutex.Unlock() + + // State checks + if !l.state.IsInitialized.Load() || l.state.ShutdownCalled.Load() { + return fmtErrorf("logger not initialized or already shut down") + } + if !l.state.Started.Load() { + return fmtErrorf("logger not started") + } + + // Create a channel to wait for confirmation from the processor + confirmChan := make(chan struct{}) + + // Send the request with the confirmation channel + select { + case l.state.flushRequestChan <- confirmChan: + // Request sent + case <-time.After(minWaitTime): // Short timeout to prevent blocking if processor is stuck + return fmtErrorf("failed to send flush request to processor (possible deadlock or high load)") + } + + select { + case <-confirmChan: + return nil + case <-time.After(timeout): + return fmtErrorf("timeout waiting for flush confirmation (%v)", timeout) + } +} + +// SetSpawn installs the goroutine launcher used by Start. Hosts that own +// panic recovery and terminal teardown pass their own launcher here. +// Call before Start; a nil fn restores the default. +func (l *Logger) SetSpawn(fn func(func())) { + if fn == nil { + l.spawner.Store(nil) + return + } + l.spawner.Store(&fn) +} + +// SetErrorHandler routes internal diagnostics to fn instead of stderr. +// Required for TUI hosts, where stderr writes corrupt the display. +func (l *Logger) SetErrorHandler(fn func(string)) { + if fn == nil { + l.errHandler.Store(nil) + return + } + l.errHandler.Store(&fn) +} + +// SetContextKeys names the record keys for Context values; empty names are +// omitted. Safe to call at any time; rebuilds the formatter. +func (l *Logger) SetContextKeys(tag string, vals ...string) { + l.initMu.Lock() + defer l.initMu.Unlock() + + k := formatter.ContextKeys{Tag: tag} + for i := 0; i < len(vals) && i < formatter.ContextSlots; i++ { + k.Vals[i] = vals[i] + } + l.ctxKeys.Store(&k) + l.rebuildFormatter(l.getConfig()) +} + +// SetLevel changes the emit threshold in place, leaving the formatter and the +// processor untouched +func (l *Logger) SetLevel(level int64) { + l.initMu.Lock() + cfg := l.getConfig().Clone() + cfg.Level = level + l.currentConfig.Store(cfg) + l.initMu.Unlock() + l.refreshLevelGate() +} + +// Enabled reports whether a record at level would be emitted. Single atomic +// load: the intended guard for hot call sites, where argument slices are +// built before the call and would otherwise escape to the heap. +func (l *Logger) Enabled(level int64) bool { + return level >= l.state.Level.Load() +} + +// Flags returns the default record flags derived from display config +func (l *Logger) Flags() int64 { + return l.state.Flags.Load() +} + +// LogContext emits a record with caller-supplied context and explicit flags +func (l *Logger) LogContext(ctx Context, flags, level, depth int64, args ...any) { + if level < l.state.Level.Load() { + return + } + l.emit(ctx, flags, level, depth, args) +} + +// spawn runs fn via the configured launcher; the default is a bare goroutine +func (l *Logger) spawn(fn func()) { + if p := l.spawner.Load(); p != nil { + (*p)(fn) + return + } + go fn() +} + +// rebuildFormatter installs a formatter matching cfg and the current context keys +func (l *Logger) rebuildFormatter(cfg *Config) { + f := formatter.New(sanitizer.New().Policy(cfg.Sanitization)). + Type(cfg.Format). + TimestampFormat(cfg.TimestampFormat). + ShowLevel(cfg.ShowLevel). + ShowTimestamp(cfg.ShowTimestamp) + if k := l.ctxKeys.Load(); k != nil { + f.ContextKeys(k.Tag, k.Vals[:]...) + } + l.formatter.Store(f) +} + +// flagsFromConfig derives the default record flags from display settings +func flagsFromConfig(cfg *Config) int64 { + var flags int64 + if cfg.ShowLevel { + flags |= FlagShowLevel + } + if cfg.ShowTimestamp { + flags |= FlagShowTimestamp + } + return flags +} + +// refreshLevelGate recomputes the emit gate from lifecycle state. +// MUST be called after every transition of IsInitialized, Started, +// LoggerDisabled, or ShutdownCalled. +func (l *Logger) refreshLevelGate() { + if !l.state.IsInitialized.Load() || !l.state.Started.Load() || + l.state.LoggerDisabled.Load() || l.state.ShutdownCalled.Load() { + l.state.Level.Store(levelOff) + return + } + l.state.Level.Store(l.getConfig().Level) +} + +// === Logging methods === + +// Debug logs a message at debug level +func (l *Logger) Debug(args ...any) { + if LevelDebug < l.state.Level.Load() { + return + } + l.emit(Context{}, l.getFlags(), LevelDebug, l.state.TraceDepth.Load(), args) +} + +// Info logs a message at info level +func (l *Logger) Info(args ...any) { + if LevelInfo < l.state.Level.Load() { + return + } + l.emit(Context{}, l.getFlags(), LevelInfo, l.state.TraceDepth.Load(), args) +} + +// Warn logs a message at warning level +func (l *Logger) Warn(args ...any) { + if LevelWarn < l.state.Level.Load() { + return + } + l.emit(Context{}, l.getFlags(), LevelWarn, l.state.TraceDepth.Load(), args) +} + +// Error logs a message at error level +func (l *Logger) Error(args ...any) { + if LevelError < l.state.Level.Load() { + return + } + l.emit(Context{}, l.getFlags(), LevelError, l.state.TraceDepth.Load(), args) +} + +// DebugTrace logs a debug message with function call trace +func (l *Logger) DebugTrace(depth int, args ...any) { + l.LogContext(Context{}, l.getFlags(), LevelDebug, int64(depth), args...) +} + +// InfoTrace logs an info message with function call trace +func (l *Logger) InfoTrace(depth int, args ...any) { + l.LogContext(Context{}, l.getFlags(), LevelInfo, int64(depth), args...) +} + +// WarnTrace logs a warning message with function call trace +func (l *Logger) WarnTrace(depth int, args ...any) { + l.LogContext(Context{}, l.getFlags(), LevelWarn, int64(depth), args...) +} + +// ErrorTrace logs an error message with function call trace +func (l *Logger) ErrorTrace(depth int, args ...any) { + l.LogContext(Context{}, l.getFlags(), LevelError, int64(depth), args...) +} + +// Log writes a timestamp-only record without level information +func (l *Logger) Log(args ...any) { + l.LogContext(Context{}, FlagShowTimestamp|FlagNoLevel, LevelInfo, 0, args...) +} + +// Message writes a plain record without timestamp or level info +func (l *Logger) Message(args ...any) { + l.LogContext(Context{}, 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.LogContext(Context{}, FlagShowTimestamp|FlagNoLevel, LevelInfo, int64(depth), args...) +} + +// LogStructured logs a message with structured fields as proper JSON +func (l *Logger) LogStructured(level int64, message string, fields map[string]any) { + l.LogContext(Context{}, l.getFlags()|FlagStructuredJSON, level, 0, message, fields) +} + +// Write outputs raw, unformatted data ignoring configured format and sanitization +func (l *Logger) Write(args ...any) { + l.LogContext(Context{}, FlagRaw, LevelInfo, 0, args...) +} diff --git a/processor.go b/processor.go index fb4faa4..58b3bb6 100644 --- a/processor.go +++ b/processor.go @@ -7,10 +7,14 @@ import ( "github.com/lixenwraith/log/formatter" ) -// processLogs is the main log processing loop running in a separate goroutine -func (l *Logger) processLogs(ch <-chan logRecord) { - l.state.ProcessorExited.Store(false) - defer l.state.ProcessorExited.Store(true) +// processLogs is the main log processing loop running in a separate goroutine. +// Exits on stop, draining buffered records first. No panic recovery: a fault +// here is fatal by design and is surfaced by the host's spawner. +func (l *Logger) processLogs(ch <-chan logRecord, stop <-chan struct{}, done chan<- struct{}) { + defer func() { + l.state.ProcessorExited.Store(true) + close(done) + }() // Set up timers and state variables timers := l.setupProcessingTimers() @@ -45,12 +49,12 @@ func (l *Logger) processLogs(ch <-chan logRecord) { // --- Main Loop --- for { select { - case record, ok := <-ch: - if !ok { - l.performSync() - return - } + case <-stop: + l.drain(ch) + l.performSync() + return + case record := <-ch: // Process the received log record bytesWritten := l.processLogRecord(record) if bytesWritten > 0 { @@ -81,7 +85,7 @@ func (l *Logger) processLogs(ch <-chan logRecord) { } case confirmChan := <-l.state.flushRequestChan: - // Barrier semantics — drain queued records before sync + // Barrier: drain queued records before sync l.handleFlushRequest(ch, confirmChan) case <-timers.retentionChan: @@ -93,6 +97,26 @@ func (l *Logger) processLogs(ch <-chan logRecord) { } } +// drain processes every buffered record without blocking +func (l *Logger) drain(ch <-chan logRecord) { + for { + select { + case record := <-ch: + l.processLogRecord(record) + default: + return + } + } +} + +// handleFlushRequest drains pending records, then syncs. Gives Flush barrier +// semantics: records enqueued before the Flush call are processed first. +func (l *Logger) handleFlushRequest(ch <-chan logRecord, confirmChan chan struct{}) { + l.drain(ch) + l.performSync() + close(confirmChan) +} + // processLogRecord handles individual log records and returns bytes written func (l *Logger) processLogRecord(record logRecord) int64 { c := l.getConfig() @@ -113,7 +137,8 @@ func (l *Logger) processLogRecord(record logRecord) int64 { f := formatterPtr.(*formatter.Formatter) // Format the log entry using atomically-loaded formatter - formattedData := f.Format( + formattedData := f.FormatCtx( + record.Ctx, record.Flags, record.TimeStamp, record.Level, @@ -193,27 +218,6 @@ func (l *Logger) handleFlushTick() { } } -// 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 func (l *Logger) handleRetentionCheck() { c := l.getConfig() @@ -244,10 +248,7 @@ func (l *Logger) adjustDiskCheckInterval(timers *TimerSet, lastCheckTime time.Ti return } - elapsed := time.Since(lastCheckTime) - if elapsed < minWaitTime { // Min arbitrary reasonable value - elapsed = minWaitTime - } + elapsed := max(time.Since(lastCheckTime), minWaitTime) // Min arbitrary reasonable value logsPerSecond := float64(logsSinceLastCheck) / elapsed.Seconds() targetLogsPerSecond := float64(100) // Baseline @@ -281,4 +282,3 @@ func (l *Logger) adjustDiskCheckInterval(timers *TimerSet, lastCheckTime time.Ti timers.diskCheckTicker.Reset(newInterval) } - diff --git a/processor_test.go b/processor_test.go index 8674a6b..0909c2b 100644 --- a/processor_test.go +++ b/processor_test.go @@ -7,8 +7,37 @@ import ( "time" ) +// // procRecords parses PROC heartbeat records out of json-formatted content. +// // Heartbeat arguments are emitted as a flat key/value array. +// func procRecords(tb testing.TB, content string) []map[string]any { +// tb.Helper() +// var out []map[string]any +// for _, line := range strings.Split(content, "\n") { +// if !strings.Contains(line, `"level":"PROC"`) { +// continue +// } +// var entry map[string]any +// if json.Unmarshal([]byte(line), &entry) != nil { +// continue +// } +// fields, ok := entry["fields"].([]any) +// if !ok { +// continue +// } +// rec := make(map[string]any, len(fields)/2) +// for i := 0; i+1 < len(fields); i += 2 { +// if key, ok := fields[i].(string); ok { +// rec[key] = fields[i+1] +// } +// } +// out = append(out, rec) +// } +// return out +// } + // procRecords parses PROC heartbeat records out of json-formatted content. -// Heartbeat arguments are emitted as a flat key/value array. +// Heartbeat arguments are emitted as a keyed object (FlagKV); the flat +// key/value array is still accepted for records written without the flag. func procRecords(tb testing.TB, content string) []map[string]any { tb.Helper() var out []map[string]any @@ -20,17 +49,18 @@ func procRecords(tb testing.TB, content string) []map[string]any { if json.Unmarshal([]byte(line), &entry) != nil { continue } - fields, ok := entry["fields"].([]any) - if !ok { - continue - } - rec := make(map[string]any, len(fields)/2) - for i := 0; i+1 < len(fields); i += 2 { - if key, ok := fields[i].(string); ok { - rec[key] = fields[i+1] + switch fields := entry["fields"].(type) { + case map[string]any: + out = append(out, fields) + case []any: + rec := make(map[string]any, len(fields)/2) + for i := 0; i+1 < len(fields); i += 2 { + if key, ok := fields[i].(string); ok { + rec[key] = fields[i+1] + } } + out = append(out, rec) } - out = append(out, rec) } return out } diff --git a/record.go b/record.go index 4d63225..93163a4 100644 --- a/record.go +++ b/record.go @@ -7,56 +7,27 @@ import ( "time" ) -// getCurrentLogChannel safely retrieves the current log channel +// getCurrentLogChannel returns the active record channel, nil when detached func (l *Logger) getCurrentLogChannel() chan logRecord { - chVal := l.state.ActiveLogChannel.Load() - // No defensive nil check required in correct use of initialized logger - return chVal.(chan logRecord) + ch, _ := l.state.ActiveLogChannel.Load().(chan logRecord) + return ch } -// getFlags from config +// getFlags returns the cached default record flags func (l *Logger) getFlags() int64 { - var flags int64 = 0 - cfg := l.getConfig() - - if cfg.ShowLevel { - flags |= FlagShowLevel - } - if cfg.ShowTimestamp { - flags |= FlagShowTimestamp - } - return flags + return l.state.Flags.Load() } -// sendLogRecord handles safe sending to the active channel +// sendLogRecord queues a record without blocking. The channel is never closed, +// so no recovery is needed: a detached (nil) channel takes the default branch. func (l *Logger) sendLogRecord(record logRecord) { - defer func() { - if r := recover(); r != nil { - // A panic is only expected when a race condition occurs during shutdown - if err, ok := r.(error); ok && err.Error() == "send on closed channel" { - // Expected race condition between logging and shutdown - l.handleFailedSend() - } else { - // Unexpected panic, re-throw to surface - panic(r) - } - } - }() - - if l.state.ShutdownCalled.Load() || - l.state.LoggerDisabled.Load() || - !l.state.Started.Load() { - // Process drops even if logger is disabled or shutting down + if l.state.LoggerDisabled.Load() { l.handleFailedSend() return } - ch := l.getCurrentLogChannel() - - // Non-blocking send select { case ch <- record: - // Success default: l.handleFailedSend() } @@ -68,59 +39,79 @@ func (l *Logger) handleFailedSend() { l.state.TotalDroppedLogs.Add(1) // Total counter } -// log handles the core logging logic -func (l *Logger) log(flags int64, level int64, depth int64, args ...any) { - // State checks - if !l.state.IsInitialized.Load() { - return - } - - if !l.state.Started.Load() { - // Log to internal error channel if configured - cfg := l.getConfig() - if cfg.InternalErrorsToStderr { - l.internalLog("warning - logger not started, dropping log entry\n") - } - return - } - - // Discard or proceed based on level - cfg := l.getConfig() - if level < cfg.Level { - return - } - - // Get trace info from runtime +// emit builds and queues a record; the caller has already passed the level gate +func (l *Logger) emit(ctx Context, flags, level, depth int64, args []any) { // Depth filter hard-coded based on call stack of current package design var trace string if depth > 0 { - const skipTrace = 3 // log.Info -> log -> getTrace (Adjust if call stack changes) + const skipTrace = 3 // Logger.Info -> emit -> getTrace trace = getTrace(depth, skipTrace) } - record := logRecord{ + l.sendLogRecord(logRecord{ + Ctx: ctx, Flags: flags, TimeStamp: time.Now(), Level: level, Trace: trace, Args: args, - } - l.sendLogRecord(record) + }) } -// internalLog handles writing internal logger diagnostics to stderr if enabled +// internalLog reports logger diagnostics to the registered handler, or to +// stderr when configured. Hosts owning a terminal must register a handler. func (l *Logger) internalLog(format string, args ...any) { - // Check if internal error reporting is enabled - cfg := l.getConfig() - if !cfg.InternalErrorsToStderr { - return - } - - // Ensure consistent "log: " prefix if !strings.HasPrefix(format, "log: ") { format = "log: " + format } - // Write to stderr + if h := l.errHandler.Load(); h != nil { + (*h)(strings.TrimRight(fmt.Sprintf(format, args...), "\n")) + return + } + + if !l.getConfig().InternalErrorsToStderr { + return + } fmt.Fprintf(os.Stderr, format, args...) -} \ No newline at end of file +} + +// // log handles the core logging logic +// func (l *Logger) log(flags int64, level int64, depth int64, args ...any) { +// // State checks +// if !l.state.IsInitialized.Load() { +// return +// } +// +// if !l.state.Started.Load() { +// // Log to internal error channel if configured +// cfg := l.getConfig() +// if cfg.InternalErrorsToStderr { +// l.internalLog("warning - logger not started, dropping log entry\n") +// } +// return +// } +// +// // Discard or proceed based on level +// cfg := l.getConfig() +// if level < cfg.Level { +// return +// } +// +// // Get trace info from runtime +// // Depth filter hard-coded based on call stack of current package design +// var trace string +// if depth > 0 { +// const skipTrace = 3 // log.Info -> log -> getTrace (Adjust if call stack changes) +// trace = getTrace(depth, skipTrace) +// } +// +// record := logRecord{ +// Flags: flags, +// TimeStamp: time.Now(), +// Level: level, +// Trace: trace, +// Args: args, +// } +// l.sendLogRecord(record) +// } diff --git a/state.go b/state.go index 08d62b2..c7fd306 100644 --- a/state.go +++ b/state.go @@ -16,6 +16,12 @@ type State struct { Started atomic.Bool // Tracks calls to Start() and Stop() ProcessorExited atomic.Bool // Tracks if the processor goroutine is running or has exited + // Emit fast path: config mirrors refreshed by applyConfig and the + // lifecycle transitions. Level holds levelOff while emission is closed + Level atomic.Int64 + Flags atomic.Int64 + TraceDepth atomic.Int64 + // Flushing state flushRequestChan chan chan struct{} // Channel to request a flush flushMutex sync.Mutex // Protect concurrent Flush calls @@ -30,6 +36,8 @@ type State struct { // Log state ActiveLogChannel atomic.Value // stores chan logRecord + ProcStop atomic.Value // stores chan struct{}, closed to signal exit + ProcDone atomic.Value // stores chan struct{}, closed by the processor DroppedLogs atomic.Uint64 // Counter for logs dropped since last heartbeat TotalDroppedLogs atomic.Uint64 // Counter for total logs dropped since logger start @@ -39,4 +47,4 @@ type State struct { TotalLogsProcessed atomic.Uint64 // Counter for non-heartbeat logs successfully processed TotalRotations atomic.Uint64 // Counter for successful log rotations TotalDeletions atomic.Uint64 // Counter for successful log deletions (cleanup/retention) -} \ No newline at end of file +} diff --git a/storage.go b/storage.go index 20f1ebb..7449f01 100644 --- a/storage.go +++ b/storage.go @@ -5,8 +5,6 @@ import ( "os" "path/filepath" "sort" - "strings" - "syscall" "time" ) @@ -25,10 +23,14 @@ func (l *Logger) performSync() { if err := currentLogFile.Sync(); err != nil { // Log sync error syncErrRecord := logRecord{ - Flags: FlagDefault, + Flags: FlagDefault | FlagKV, TimeStamp: time.Now(), Level: LevelWarn, - Args: []any{"Log file sync failed", "file", currentLogFile.Name(), "error", err.Error()}, + Args: []any{ + "msg", "log file sync failed", + "file", currentLogFile.Name(), + "error", err.Error(), + }, } l.sendLogRecord(syncErrRecord) } @@ -106,8 +108,11 @@ func (l *Logger) performDiskCheck(forceCleanup bool) bool { if err := l.cleanOldLogs(spaceToFree); err != nil { if !l.state.DiskFullLogged.Swap(true) { diskFullRecord := logRecord{ - Flags: FlagDefault, TimeStamp: time.Now(), Level: LevelError, - Args: []any{"Log directory full or disk space low, cleanup failed", "error", err.Error()}, + Flags: FlagDefault | FlagKV, TimeStamp: time.Now(), Level: LevelError, + Args: []any{ + "msg", "log directory full or disk space low, cleanup failed", + "error", err.Error(), + }, } l.sendLogRecord(diskFullRecord) } @@ -135,27 +140,27 @@ func (l *Logger) performDiskCheck(forceCleanup bool) bool { } } -// getDiskFreeSpace retrieves available disk space for the given path -func (l *Logger) getDiskFreeSpace(path string) (int64, error) { - var stat syscall.Statfs_t - info, err := os.Stat(path) - if err != nil { - if os.IsNotExist(err) { - return 0, fmtErrorf("log directory '%s' does not exist for disk check: %w", path, err) - } - return 0, fmtErrorf("failed to stat log directory '%s': %w", path, err) - } - if !info.IsDir() { - path = filepath.Dir(path) - } - - if err := syscall.Statfs(path, &stat); err != nil { - return 0, fmtErrorf("failed to get disk stats for '%s': %w", path, err) - } - // Explicit cast to int64 to satisfy both Linux and FreebSD - availableBytes := int64(stat.Bavail) * int64(stat.Bsize) - return availableBytes, nil -} +// // getDiskFreeSpace retrieves available disk space for the given path +// func (l *Logger) getDiskFreeSpace(path string) (int64, error) { +// var stat syscall.Statfs_t +// info, err := os.Stat(path) +// if err != nil { +// if os.IsNotExist(err) { +// return 0, fmtErrorf("log directory '%s' does not exist for disk check: %w", path, err) +// } +// return 0, fmtErrorf("failed to stat log directory '%s': %w", path, err) +// } +// if !info.IsDir() { +// path = filepath.Dir(path) +// } +// +// if err := syscall.Statfs(path, &stat); err != nil { +// return 0, fmtErrorf("failed to get disk stats for '%s': %w", path, err) +// } +// // Explicit cast to int64 to satisfy both Linux and FreebSD +// availableBytes := int64(stat.Bavail) * int64(stat.Bsize) +// return availableBytes, nil +// } // getLogDirSize calculates total size of log files matching the current extension func (l *Logger) getLogDirSize(dir, ext string) (int64, error) { @@ -254,7 +259,9 @@ func (l *Logger) cleanOldLogs(required int64) error { return nil } -// updateEarliestFileTime scans the log directory for the oldest log file +// updateEarliestFileTime scans the log directory for the oldest log file. +// Matches by extension only: a name-prefix filter would hide files written by +// earlier runs when the active name carries a per-run timestamp. func (l *Logger) updateEarliestFileTime() { c := l.getConfig() dir := c.Directory @@ -275,17 +282,15 @@ func (l *Logger) updateEarliestFileTime() { } targetExt := "." + ext - prefix := name + "_" for _, entry := range entries { if entry.IsDir() { continue } fname := entry.Name() - // Skip the active log file if fname == staticLogName { - continue + continue // Skip the active log file } - if !strings.HasPrefix(fname, prefix) || (ext != "" && filepath.Ext(fname) != targetExt) { + if ext != "" && filepath.Ext(fname) != targetExt { continue } info, errInfo := entry.Info() @@ -371,19 +376,28 @@ func (l *Logger) getStaticLogFilePath() string { return filepath.Join(dir, filename) } -// generateArchiveLogFileName creates a timestamped filename for archived logs during rotation +// fileExists reports whether path names an existing regular file +func fileExists(path string) bool { + info, err := os.Stat(path) + return err == nil && !info.IsDir() +} + +// generateArchiveLogFileName creates a second-resolution name for a rotated +// log, disambiguating with a counter when that name is already taken func (l *Logger) generateArchiveLogFileName(timestamp time.Time) string { c := l.getConfig() - ext := c.Extension - name := c.Name - tsFormat := timestamp.Format("060102_150405") - nano := timestamp.Nanosecond() - - if ext != "" { - return fmt.Sprintf("%s_%s_%d.%s", name, tsFormat, nano, ext) + suffix := "" + if c.Extension != "" { + suffix = "." + c.Extension } - return fmt.Sprintf("%s_%s_%d", name, tsFormat, nano) + base := fmt.Sprintf("%s_%s", c.Name, timestamp.Format("060102_150405")) + + name := base + suffix + for i := 1; i < 1000 && fileExists(filepath.Join(c.Directory, name)); i++ { + name = fmt.Sprintf("%s_%d%s", base, i, suffix) + } + return name } // createNewLogFile generates a unique name and opens a new log file @@ -449,6 +463,7 @@ func (l *Logger) rotateLogFile() error { l.internalLog("failed to rename log file from '%s' to '%s': %v. file logging disabled.", currentPath, archivePath, err) l.state.LoggerDisabled.Store(true) + l.refreshLevelGate() return fmtErrorf("failed to rotate log file, logging is disabled: %w", err) } @@ -492,4 +507,3 @@ func (l *Logger) getLogFileCount(dir, ext string) (int, error) { } return count, nil } - diff --git a/storage_nofs.go b/storage_nofs.go new file mode 100644 index 0000000..8b760a8 --- /dev/null +++ b/storage_nofs.go @@ -0,0 +1,11 @@ +//go:build !unix + +package log + +import "math" + +// getDiskFreeSpace reports unlimited space where statfs is unavailable. +// Total-size limits still apply; only the free-space check is inert. +func (l *Logger) getDiskFreeSpace(path string) (int64, error) { + return math.MaxInt64, nil +} diff --git a/storage_test.go b/storage_test.go index 492a1b9..77db85f 100644 --- a/storage_test.go +++ b/storage_test.go @@ -42,7 +42,7 @@ func TestLogRotation(t *testing.T) { switch { case name == "log.log": hasActive = true - // Archive pattern: log_YYMMDD_HHMMSS_.log + // Archive pattern: log_YYMMDD_HHMMSS[_N].log case strings.HasPrefix(name, "log_") && strings.HasSuffix(name, ".log"): archives++ default: @@ -195,7 +195,8 @@ func TestLogDirAccounting(t *testing.T) { equal(t, count, 0, "count of missing dir") } -// TestArchiveNaming verifies archive names are unique and carry the base name. +// TestArchiveNaming verifies archive names carry the base name and never +// collide with a file already present in the directory. func TestArchiveNaming(t *testing.T) { logger, tmpDir := newTestLogger(t) @@ -203,12 +204,17 @@ func TestArchiveNaming(t *testing.T) { ts := time.Now() first := logger.generateArchiveLogFileName(ts) - second := logger.generateArchiveLogFileName(ts.Add(time.Nanosecond)) - isTrue(t, strings.HasPrefix(first, "log_"), "archive prefix") isTrue(t, strings.HasSuffix(first, ".log"), "archive extension") - if first == second { - t.Errorf("archive names must be unique at nanosecond resolution: %s", first) - } -} + // Names are second-resolution; the counter disambiguates against files + // already on disk, not against clock resolution + mustNoErr(t, os.WriteFile(filepath.Join(tmpDir, first), []byte("archived"), 0644), "WriteFile archive") + + second := logger.generateArchiveLogFileName(ts) + if second == first { + t.Errorf("archive name collided with existing file: %s", second) + } + isTrue(t, strings.HasPrefix(second, "log_"), "archive prefix") + isTrue(t, strings.HasSuffix(second, ".log"), "archive extension") +} diff --git a/storage_unix.go b/storage_unix.go new file mode 100644 index 0000000..3de700f --- /dev/null +++ b/storage_unix.go @@ -0,0 +1,30 @@ +//go:build unix + +package log + +import ( + "os" + "path/filepath" + "syscall" +) + +// getDiskFreeSpace retrieves available disk space for the given path +func (l *Logger) getDiskFreeSpace(path string) (int64, error) { + var stat syscall.Statfs_t + info, err := os.Stat(path) + if err != nil { + if os.IsNotExist(err) { + return 0, fmtErrorf("log directory '%s' does not exist for disk check: %w", path, err) + } + return 0, fmtErrorf("failed to stat log directory '%s': %w", path, err) + } + if !info.IsDir() { + path = filepath.Dir(path) + } + + if err := syscall.Statfs(path, &stat); err != nil { + return 0, fmtErrorf("failed to get disk stats for '%s': %w", path, err) + } + // Explicit cast to int64 to satisfy both Linux and FreeBSD + return int64(stat.Bavail) * int64(stat.Bsize), nil +} diff --git a/type.go b/type.go index 7d5e897..5affcbc 100644 --- a/type.go +++ b/type.go @@ -3,15 +3,24 @@ package log import ( "io" "time" + + "github.com/lixenwraith/log/formatter" ) +// Context carries caller-stamped values emitted with a record +type Context = formatter.Context + +// ContextSlots is the number of correlation values a Context carries +const ContextSlots = formatter.ContextSlots + // logRecord represents a single log entry type logRecord struct { - Flags int64 TimeStamp time.Time - Level int64 Trace string Args []any + Ctx Context + Flags int64 + Level int64 } // TimerSet holds all timers used in processLogs @@ -27,4 +36,4 @@ type TimerSet struct { // sink is a wrapper around an io.Writer, atomic value type change workaround type sink struct { w io.Writer -} \ No newline at end of file +}