navidrome/log/log.go

package log

import (
	"cmp"
	"context"
	"errors"
	"fmt"
	"io"
	"iter"
	"net/http"
	"os"
	"runtime"
	"slices"
	"strings"
	"sync"
	"sync/atomic"
	"time"

	"github.com/sirupsen/logrus"
)

type Level uint32

type LevelFunc = func(ctx any, msg any, keyValuePairs ...any)

var redacted = &Hook{
	AcceptedLevels: logrus.AllLevels,
	RedactionList: []string{
		// Keys from the config
		"(ApiKey:[\\s]*\")[\\w]*",
		"(Secret:[\\s]*\")[\\w]*",
		"(PasswordEncryptionKey:[\\s]*\")[^\"]*",
		"(UserHeader:[\\s]*\")[^\"]*",
		"(TrustedSources:[\\s]*\")[^\"]*",
		"(MetricsPath:[\\s]*\")[^\"]*",
		"(DevAutoCreateAdminPassword:[\\s]*\")[^\"]*",
		"(DevAutoLoginUsername:[\\s]*\")[^\"]*",
		// Prometheus.Password. Any character is allowed, so skip escaped quotes in the value
		`(Password:[\s]*")(?:[^"\\]|\\.)*`,

		// UI appConfig
		"(subsonicToken:)[\\w]+(\\s)",
		"(subsonicSalt:)[\\w]+(\\s)",
		"(token:)[^\\s]+",

		// Subsonic query params
		"([^\\w]t=)[\\w]+",
		"([^\\w]s=)[^&]+",
		"([^\\w]p=)[^&]+",
		"([^\\w]jwt=)[^&]+",

		// External services query params. Values can be JWTs (dots, dashes), so match everything up
		// to the next query separator or whitespace, not just word chars. A [\w]+ class would stop
		// at a JWT's first '.' and leak its payload and signature. Case-insensitive with an
		// optional underscore: the API accepts api_key, apikey and ApiKey alike.
		"(?i)([^\\w]api_?key=)[^&\\s]+",

		// Sensitive request headers, logged as a JSON blob at trace level and never matched by the
		// query-param patterns above. Blank the whole value array; values may hold escaped quotes.
		`(?i)("(?:Authorization|X-Emby-Token|X-MediaBrowser-Token|X-Nd-Authorization)":\[")[^\]]*("\])`,
	},
}

const (
	LevelFatal = Level(logrus.FatalLevel)
	LevelError = Level(logrus.ErrorLevel)
	LevelWarn  = Level(logrus.WarnLevel)
	LevelInfo  = Level(logrus.InfoLevel)
	LevelDebug = Level(logrus.DebugLevel)
	LevelTrace = Level(logrus.TraceLevel)
)

type contextKey string

const loggerCtxKey = contextKey("logger")

type levelPath struct {
	path  string
	level Level
}

var (
	currentLevel         atomic.Uint32
	hasLogLevelOverrides atomic.Bool
	loggerMu             sync.RWMutex
	defaultLogger        = logrus.New()
	logSourceLine        = false
	rootPath             string
	logLevels            []levelPath
)

// SetLevel sets the global log level used by the simple logger.
func SetLevel(l Level) {
	loggerMu.Lock()
	currentLevel.Store(uint32(l))
	defaultLogger.Level = logrus.TraceLevel
	loggerMu.Unlock()
	logrus.SetLevel(logrus.Level(l))
}

func SetLevelString(l string) {
	level := ParseLogLevel(l)
	SetLevel(level)
}

func ParseLogLevel(l string) Level {
	envLevel := strings.ToLower(l)
	var level Level
	switch envLevel {
	case "fatal":
		level = LevelFatal
	case "error":
		level = LevelError
	case "warn":
		level = LevelWarn
	case "debug":
		level = LevelDebug
	case "trace":
		level = LevelTrace
	default:
		level = LevelInfo
	}
	return level
}

// SetLogLevels sets the log levels for specific paths in the codebase.
func SetLogLevels(levels map[string]string) {
	loggerMu.Lock()
	defer loggerMu.Unlock()
	logLevels = nil
	for k, v := range levels {
		logLevels = append(logLevels, levelPath{path: k, level: ParseLogLevel(v)})
	}
	slices.SortFunc(logLevels, func(a, b levelPath) int {
		return cmp.Compare(b.path, a.path)
	})
	hasLogLevelOverrides.Store(len(logLevels) != 0)
}

func SetLogSourceLine(enabled bool) {
	logSourceLine = enabled
}

func SetRedacting(enabled bool) {
	if enabled {
		loggerMu.Lock()
		defer loggerMu.Unlock()
		defaultLogger.AddHook(redacted)
	}
}

func SetOutput(w io.Writer) {
	if runtime.GOOS == "windows" {
		w = CRLFWriter(w)
	}
	loggerMu.Lock()
	defer loggerMu.Unlock()
	defaultLogger.SetOutput(w)
}

// EnableJournalFormat wraps the current logger formatter with syslog
// priority prefixes for systemd-journald. Only call this when output
// goes to stderr and JOURNAL_STREAM is set.
func EnableJournalFormat() {
	loggerMu.Lock()
	defer loggerMu.Unlock()
	defaultLogger.Formatter = &journalFormatter{inner: defaultLogger.Formatter}
}

// Redact applies redaction to a single string
func Redact(msg string) string {
	r, _ := redacted.redact(msg)
	return r
}

func NewContext(ctx context.Context, keyValuePairs ...any) context.Context {
	if ctx == nil {
		ctx = context.Background()
	}

	logger, ok := ctx.Value(loggerCtxKey).(*logrus.Entry)
	if !ok {
		logger = createNewLogger()
	}
	logger = addFields(logger, keyValuePairs)
	ctx = context.WithValue(ctx, loggerCtxKey, logger)

	return ctx
}

// SetDefaultLogger swaps the process-wide logger and returns the previous one,
// so tests can restore the original (with its hooks and formatter) on cleanup.
func SetDefaultLogger(l *logrus.Logger) *logrus.Logger {
	loggerMu.Lock()
	defer loggerMu.Unlock()
	prev := defaultLogger
	defaultLogger = l
	return prev
}

func CurrentLevel() Level {
	return Level(currentLevel.Load())
}

// IsGreaterOrEqualTo returns true if the caller's current log level is equal or greater than the provided level.
func IsGreaterOrEqualTo(level Level) bool {
	return shouldLog(level, 2)
}

func Fatal(args ...any) {
	log(LevelFatal, args...)
	os.Exit(1)
}

func Error(args ...any) {
	log(LevelError, args...)
}

func Warn(args ...any) {
	log(LevelWarn, args...)
}

func Info(args ...any) {
	log(LevelInfo, args...)
}

func Debug(args ...any) {
	log(LevelDebug, args...)
}

func Trace(args ...any) {
	log(LevelTrace, args...)
}

func Log(level Level, args ...any) {
	log(level, args...)
}

func log(level Level, args ...any) {
	if !shouldLog(level, 3) {
		return
	}

	logger, msg := parseArgs(args)
	logger.Log(logrus.Level(level), msg)
}

func Writer() io.Writer {
	loggerMu.RLock()
	defer loggerMu.RUnlock()
	return defaultLogger.Writer()
}

func shouldLog(requiredLevel Level, skip int) bool {
	level := Level(currentLevel.Load())
	if level >= requiredLevel {
		return true
	}
	if !hasLogLevelOverrides.Load() {
		return false
	}

	loggerMu.RLock()
	levels := logLevels
	loggerMu.RUnlock()

	_, file, _, ok := runtime.Caller(skip)
	if !ok {
		return false
	}

	file = strings.TrimPrefix(file, rootPath)
	for _, lp := range levels {
		if strings.HasPrefix(file, lp.path) {
			return lp.level >= requiredLevel
		}
	}
	return false
}

func parseArgs(args []any) (*logrus.Entry, string) {
	var l *logrus.Entry
	var err error
	if args[0] == nil {
		l = createNewLogger()
		args = args[1:]
	} else {
		l, err = extractLogger(args[0])
		if err != nil {
			l = createNewLogger()
		} else {
			args = args[1:]
		}
	}
	if len(args) > 1 {
		kvPairs := args[1:]
		l = addFields(l, kvPairs)
	}
	if logSourceLine {
		_, file, line, ok := runtime.Caller(3)
		if !ok {
			file = "???"
			line = 0
		}
		//_, filename := path.Split(file)
		//l = l.WithField("filename", filename).WithField("line", line)
		l = l.WithField(" source", fmt.Sprintf("file://%s:%d", file, line))
	}

	switch msg := args[0].(type) {
	case error:
		return l, msg.Error()
	case string:
		return l, msg
	}

	return l, ""
}

func addFields(logger *logrus.Entry, keyValuePairs []any) *logrus.Entry {
	for i := 0; i < len(keyValuePairs); i += 2 {
		switch name := keyValuePairs[i].(type) {
		case error:
			logger = logger.WithField("error", name.Error())
		case string:
			if i+1 >= len(keyValuePairs) {
				logger = logger.WithField(name, "!!!!Invalid number of arguments in log call!!!!")
			} else {
				switch v := keyValuePairs[i+1].(type) {
				case time.Duration:
					logger = logger.WithField(name, ShortDur(v))
				case fmt.Stringer:
					logger = logger.WithField(name, StringerValue(v))
				case iter.Seq[string]:
					logger = logger.WithField(name, formatSeq(v))
				case []string:
					logger = logger.WithField(name, formatSlice(v))
				default:
					logger = logger.WithField(name, v)
				}
			}
		}
	}
	return logger
}

func extractLogger(ctx any) (*logrus.Entry, error) {
	switch ctx := ctx.(type) {
	case *logrus.Entry:
		return ctx, nil
	case context.Context:
		logger := ctx.Value(loggerCtxKey)
		if logger != nil {
			return logger.(*logrus.Entry), nil
		}
		return extractLogger(NewContext(ctx))
	case *http.Request:
		return extractLogger(ctx.Context())
	}
	return nil, errors.New("no logger found")
}

func createNewLogger() *logrus.Entry {
	//logrus.SetFormatter(&logrus.TextFormatter{ForceColors: true, DisableTimestamp: false, FullTimestamp: true})
	//l.Formatter = &logrus.TextFormatter{ForceColors: true, DisableTimestamp: false, FullTimestamp: true}
	loggerMu.RLock()
	defer loggerMu.RUnlock()
	logger := logrus.NewEntry(defaultLogger)
	return logger
}

func init() {
	defaultLogger.Level = logrus.TraceLevel
	_, file, _, ok := runtime.Caller(0)
	if !ok {
		return
	}
	rootPath = strings.TrimSuffix(file, "log/log.go")
}