256 lines
7.0 KiB
Go
256 lines
7.0 KiB
Go
// Package logging provides centralized structured logging using slog
|
|
// with configurable log levels. Call InitLogger() from main() to configure.
|
|
//
|
|
// Dynamic debug logging:
|
|
// Send SIGUSR1 to toggle debug mode at runtime (auto-reverts after 30 minutes).
|
|
// Example: docker kill -s SIGUSR1 <container>
|
|
package logging
|
|
|
|
import (
|
|
"fmt"
|
|
"io"
|
|
"log/slog"
|
|
"os"
|
|
"os/signal"
|
|
"strings"
|
|
"sync"
|
|
"sync/atomic"
|
|
"syscall"
|
|
"time"
|
|
)
|
|
|
|
const debugTimeout = 30 * time.Minute
|
|
|
|
var (
|
|
levelVar *slog.LevelVar
|
|
originalLevel slog.Level
|
|
debugEnabled atomic.Bool
|
|
revertTimer *time.Timer
|
|
revertMu sync.Mutex
|
|
|
|
// asyncHandler holds the global async handler for shutdown
|
|
asyncHandler *AsyncHandler
|
|
)
|
|
|
|
// InitLogger initializes the global slog default logger with the specified log level.
|
|
// Valid levels: debug, info, warn, error (case-insensitive)
|
|
// If level is empty or invalid, defaults to INFO.
|
|
// Call this from main() at startup.
|
|
//
|
|
// Also starts a signal handler for SIGUSR1 to toggle debug mode at runtime.
|
|
func InitLogger(level string) {
|
|
InitLoggerWithShipper(level, ShipperConfig{})
|
|
}
|
|
|
|
// InitLoggerWithShipper initializes the global slog default logger with the specified
|
|
// log level and optional remote log shipping.
|
|
// Valid levels: debug, info, warn, error (case-insensitive)
|
|
// If level is empty or invalid, defaults to INFO.
|
|
// Call this from main() at startup.
|
|
//
|
|
// If shipperCfg.Backend is non-empty, logs will be shipped to the configured
|
|
// remote service in addition to stdout.
|
|
//
|
|
// Also starts a signal handler for SIGUSR1 to toggle debug mode at runtime.
|
|
func InitLoggerWithShipper(level string, shipperCfg ShipperConfig) {
|
|
var logLevel slog.Level
|
|
|
|
switch strings.ToLower(strings.TrimSpace(level)) {
|
|
case "debug":
|
|
logLevel = slog.LevelDebug
|
|
case "info", "":
|
|
logLevel = slog.LevelInfo
|
|
case "warn", "warning":
|
|
logLevel = slog.LevelWarn
|
|
case "error":
|
|
logLevel = slog.LevelError
|
|
default:
|
|
logLevel = slog.LevelInfo
|
|
}
|
|
|
|
// Store original level for toggle-back and use LevelVar for dynamic changes
|
|
originalLevel = logLevel
|
|
levelVar = new(slog.LevelVar)
|
|
levelVar.Set(logLevel)
|
|
|
|
opts := &slog.HandlerOptions{
|
|
Level: levelVar,
|
|
AddSource: true,
|
|
ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
|
|
if a.Key == slog.SourceKey {
|
|
if src, ok := a.Value.Any().(*slog.Source); ok {
|
|
a.Value = slog.StringValue(shortenSource(src.File, src.Line))
|
|
}
|
|
}
|
|
return a
|
|
},
|
|
}
|
|
|
|
// Create stdout handler
|
|
stdoutHandler := slog.NewTextHandler(os.Stdout, opts)
|
|
|
|
// Create shipper if configured
|
|
var shipper Shipper
|
|
if shipperCfg.Backend != "" {
|
|
var err error
|
|
shipper, err = NewShipper(shipperCfg)
|
|
if err != nil {
|
|
// Log error but continue without shipping
|
|
fmt.Fprintf(os.Stderr, "log shipper initialization failed: %v (continuing with stdout only)\n", err)
|
|
}
|
|
}
|
|
|
|
// Create async handler (wraps stdout + optional shipper)
|
|
asyncHandler = NewAsyncHandler(stdoutHandler, shipper, shipperCfg, opts)
|
|
slog.SetDefault(slog.New(asyncHandler))
|
|
|
|
// Start signal handler for dynamic debug toggle
|
|
go handleDebugSignal()
|
|
}
|
|
|
|
// Shutdown flushes any remaining logs and closes the log shipper.
|
|
// Call this during graceful shutdown to ensure all logs are delivered.
|
|
func Shutdown() {
|
|
if asyncHandler != nil {
|
|
asyncHandler.Shutdown()
|
|
}
|
|
}
|
|
|
|
func handleDebugSignal() {
|
|
sigChan := make(chan os.Signal, 1)
|
|
signal.Notify(sigChan, syscall.SIGUSR1)
|
|
|
|
for range sigChan {
|
|
ToggleDebug()
|
|
}
|
|
}
|
|
|
|
// ToggleDebug toggles between the original log level and DEBUG.
|
|
// When enabling debug, starts a 30-minute timer that auto-reverts.
|
|
// Typically called via SIGUSR1 signal.
|
|
func ToggleDebug() {
|
|
revertMu.Lock()
|
|
defer revertMu.Unlock()
|
|
|
|
wasDebug := debugEnabled.Swap(!debugEnabled.Load())
|
|
|
|
// Cancel any existing revert timer
|
|
if revertTimer != nil {
|
|
revertTimer.Stop()
|
|
revertTimer = nil
|
|
}
|
|
|
|
if wasDebug {
|
|
// Turning debug OFF
|
|
levelVar.Set(originalLevel)
|
|
slog.Info("Log level changed",
|
|
"from", "DEBUG",
|
|
"to", levelToString(originalLevel),
|
|
"trigger", "SIGUSR1")
|
|
} else {
|
|
// Turning debug ON - start auto-revert timer
|
|
levelVar.Set(slog.LevelDebug)
|
|
revertTimer = time.AfterFunc(debugTimeout, autoRevert)
|
|
slog.Info("Log level changed",
|
|
"from", levelToString(originalLevel),
|
|
"to", "DEBUG",
|
|
"trigger", "SIGUSR1",
|
|
"auto_revert_in", debugTimeout)
|
|
}
|
|
}
|
|
|
|
func autoRevert() {
|
|
revertMu.Lock()
|
|
defer revertMu.Unlock()
|
|
|
|
if !debugEnabled.Load() {
|
|
return // Already reverted manually
|
|
}
|
|
|
|
debugEnabled.Store(false)
|
|
levelVar.Set(originalLevel)
|
|
revertTimer = nil
|
|
|
|
slog.Info("Log level changed",
|
|
"from", "DEBUG",
|
|
"to", levelToString(originalLevel),
|
|
"trigger", "auto-revert")
|
|
}
|
|
|
|
// shortenSource shortens file paths for cleaner log output.
|
|
// - Our code (atcr.io/): shows pkg/appview/jetstream/processor.go:73
|
|
// - Library code (/pkg/mod/): shows indigo/atproto/identity/handle.go:225
|
|
// - Other: shows last 3 path components
|
|
func shortenSource(file string, line int) string {
|
|
// Our code: strip everything up to and including atcr.io/
|
|
if idx := strings.Index(file, "atcr.io/"); idx != -1 {
|
|
return fmt.Sprintf("%s:%d", file[idx+8:], line) // 8 = len("atcr.io/")
|
|
}
|
|
|
|
// Library code in go mod cache: extract module name + relative path
|
|
// Example: /go/pkg/mod/github.com/bluesky-social/indigo@v0.0.0-.../atproto/identity/handle.go
|
|
// becomes: indigo/atproto/identity/handle.go:225
|
|
if idx := strings.Index(file, "/pkg/mod/"); idx != -1 {
|
|
modPath := file[idx+9:] // 9 = len("/pkg/mod/")
|
|
if atIdx := strings.Index(modPath, "@"); atIdx != -1 {
|
|
// Get module path before @
|
|
modFullPath := modPath[:atIdx]
|
|
parts := strings.Split(modFullPath, "/")
|
|
|
|
// Get module name - skip version suffix like "v3" if present
|
|
modName := parts[len(parts)-1]
|
|
if len(parts) >= 2 && len(modName) >= 2 && modName[0] == 'v' && modName[1] >= '0' && modName[1] <= '9' {
|
|
modName = parts[len(parts)-2]
|
|
}
|
|
|
|
// Get path after version
|
|
afterAt := modPath[atIdx+1:]
|
|
if slashIdx := strings.Index(afterAt, "/"); slashIdx != -1 {
|
|
return fmt.Sprintf("%s%s:%d", modName, afterAt[slashIdx:], line)
|
|
}
|
|
}
|
|
}
|
|
|
|
// Fallback: show last 3 path components
|
|
parts := strings.Split(file, "/")
|
|
if len(parts) > 3 {
|
|
parts = parts[len(parts)-3:]
|
|
}
|
|
return fmt.Sprintf("%s:%d", strings.Join(parts, "/"), line)
|
|
}
|
|
|
|
func levelToString(l slog.Level) string {
|
|
switch l {
|
|
case slog.LevelDebug:
|
|
return "DEBUG"
|
|
case slog.LevelInfo:
|
|
return "INFO"
|
|
case slog.LevelWarn:
|
|
return "WARN"
|
|
case slog.LevelError:
|
|
return "ERROR"
|
|
default:
|
|
return l.String()
|
|
}
|
|
}
|
|
|
|
// SetupTestLogger configures logging for tests to reduce noise.
|
|
// Sets log level to WARN and outputs to io.Discard to suppress DEBUG and INFO messages.
|
|
// Returns a cleanup function that should be called when the test completes (use t.Cleanup).
|
|
func SetupTestLogger() func() {
|
|
// Save original logger to restore later
|
|
originalLogger := slog.Default()
|
|
|
|
// Set level to WARN and discard output to silence tests
|
|
opts := &slog.HandlerOptions{
|
|
Level: slog.LevelWarn,
|
|
}
|
|
handler := slog.NewTextHandler(io.Discard, opts)
|
|
slog.SetDefault(slog.New(handler))
|
|
|
|
// Return cleanup function
|
|
return func() {
|
|
slog.SetDefault(originalLogger)
|
|
}
|
|
}
|