syncthing/lib/logger/logger.go
Jakob Borg 416b9e8924
lib/logger: Reduce API surface (#9404)
There is no need to expose the IsTraced() thing; it's just used in
initialisation, and thereafter ShouldDebug() is the corresponding
correct call.
2024-02-09 11:17:44 +01:00

409 lines
9.6 KiB
Go

// Copyright (C) 2014 Jakob Borg. All rights reserved. Use of this source code
// is governed by an MIT-style license that can be found in the LICENSE file.
//go:generate -command counterfeiter go run github.com/maxbrunsfeld/counterfeiter/v6
//go:generate counterfeiter -o mocks/logger.go --fake-name Recorder . Recorder
// Package logger implements a standardized logger with callback functionality
package logger
import (
"fmt"
"io"
"log"
"os"
"strings"
"sync"
"time"
"golang.org/x/exp/slices"
)
// This package uses stdlib sync as it may be used to debug syncthing/lib/sync
// and that would cause an implosion of the universe.
type LogLevel int
const (
LevelDebug LogLevel = iota
LevelVerbose
LevelInfo
LevelWarn
NumLevels
)
const (
DefaultFlags = log.Ltime | log.Ldate
DebugFlags = log.Ltime | log.Ldate | log.Lmicroseconds | log.Lshortfile
)
// A MessageHandler is called with the log level and message text.
type MessageHandler func(l LogLevel, msg string)
type Logger interface {
AddHandler(level LogLevel, h MessageHandler)
SetFlags(flag int)
SetPrefix(prefix string)
Debugln(vals ...interface{})
Debugf(format string, vals ...interface{})
Verboseln(vals ...interface{})
Verbosef(format string, vals ...interface{})
Infoln(vals ...interface{})
Infof(format string, vals ...interface{})
Warnln(vals ...interface{})
Warnf(format string, vals ...interface{})
ShouldDebug(facility string) bool
SetDebug(facility string, enabled bool)
Facilities() map[string]string
FacilityDebugging() []string
NewFacility(facility, description string) Logger
}
type logger struct {
logger *log.Logger
handlers [NumLevels][]MessageHandler
facilities map[string]string // facility name => description
debug map[string]struct{} // only facility names with debugging enabled
traces []string
mut sync.Mutex
}
// DefaultLogger logs to standard output with a time prefix.
var DefaultLogger = New()
func New() Logger {
if os.Getenv("LOGGER_DISCARD") != "" {
// Hack to completely disable logging, for example when running
// benchmarks.
return newLogger(io.Discard)
}
return newLogger(controlStripper{os.Stdout})
}
func newLogger(w io.Writer) Logger {
traces := strings.FieldsFunc(os.Getenv("STTRACE"), func(r rune) bool {
return strings.ContainsRune(",; ", r)
})
if len(traces) > 0 {
if slices.Contains(traces, "all") {
traces = []string{"all"}
} else {
slices.Sort(traces)
}
}
return &logger{
logger: log.New(w, "", DefaultFlags),
traces: traces,
facilities: make(map[string]string),
debug: make(map[string]struct{}),
}
}
// AddHandler registers a new MessageHandler to receive messages with the
// specified log level or above.
func (l *logger) AddHandler(level LogLevel, h MessageHandler) {
l.mut.Lock()
defer l.mut.Unlock()
l.handlers[level] = append(l.handlers[level], h)
}
// See log.SetFlags
func (l *logger) SetFlags(flag int) {
l.logger.SetFlags(flag)
}
// See log.SetPrefix
func (l *logger) SetPrefix(prefix string) {
l.logger.SetPrefix(prefix)
}
func (l *logger) callHandlers(level LogLevel, s string) {
for ll := LevelDebug; ll <= level; ll++ {
for _, h := range l.handlers[ll] {
h(level, strings.TrimSpace(s))
}
}
}
// Debugln logs a line with a DEBUG prefix.
func (l *logger) Debugln(vals ...interface{}) {
l.debugln(3, vals...)
}
func (l *logger) debugln(level int, vals ...interface{}) {
s := fmt.Sprintln(vals...)
l.mut.Lock()
defer l.mut.Unlock()
l.logger.Output(level, "DEBUG: "+s)
l.callHandlers(LevelDebug, s)
}
// Debugf logs a formatted line with a DEBUG prefix.
func (l *logger) Debugf(format string, vals ...interface{}) {
l.debugf(3, format, vals...)
}
func (l *logger) debugf(level int, format string, vals ...interface{}) {
s := fmt.Sprintf(format, vals...)
l.mut.Lock()
defer l.mut.Unlock()
l.logger.Output(level, "DEBUG: "+s)
l.callHandlers(LevelDebug, s)
}
// Infoln logs a line with a VERBOSE prefix.
func (l *logger) Verboseln(vals ...interface{}) {
s := fmt.Sprintln(vals...)
l.mut.Lock()
defer l.mut.Unlock()
l.logger.Output(2, "VERBOSE: "+s)
l.callHandlers(LevelVerbose, s)
}
// Infof logs a formatted line with a VERBOSE prefix.
func (l *logger) Verbosef(format string, vals ...interface{}) {
s := fmt.Sprintf(format, vals...)
l.mut.Lock()
defer l.mut.Unlock()
l.logger.Output(2, "VERBOSE: "+s)
l.callHandlers(LevelVerbose, s)
}
// Infoln logs a line with an INFO prefix.
func (l *logger) Infoln(vals ...interface{}) {
s := fmt.Sprintln(vals...)
l.mut.Lock()
defer l.mut.Unlock()
l.logger.Output(2, "INFO: "+s)
l.callHandlers(LevelInfo, s)
}
// Infof logs a formatted line with an INFO prefix.
func (l *logger) Infof(format string, vals ...interface{}) {
s := fmt.Sprintf(format, vals...)
l.mut.Lock()
defer l.mut.Unlock()
l.logger.Output(2, "INFO: "+s)
l.callHandlers(LevelInfo, s)
}
// Warnln logs a formatted line with a WARNING prefix.
func (l *logger) Warnln(vals ...interface{}) {
s := fmt.Sprintln(vals...)
l.mut.Lock()
defer l.mut.Unlock()
l.logger.Output(2, "WARNING: "+s)
l.callHandlers(LevelWarn, s)
}
// Warnf logs a formatted line with a WARNING prefix.
func (l *logger) Warnf(format string, vals ...interface{}) {
s := fmt.Sprintf(format, vals...)
l.mut.Lock()
defer l.mut.Unlock()
l.logger.Output(2, "WARNING: "+s)
l.callHandlers(LevelWarn, s)
}
// ShouldDebug returns true if the given facility has debugging enabled.
func (l *logger) ShouldDebug(facility string) bool {
l.mut.Lock()
_, res := l.debug[facility]
l.mut.Unlock()
return res
}
// SetDebug enabled or disables debugging for the given facility name.
func (l *logger) SetDebug(facility string, enabled bool) {
l.mut.Lock()
defer l.mut.Unlock()
if _, ok := l.debug[facility]; enabled && !ok {
l.SetFlags(DebugFlags)
l.debug[facility] = struct{}{}
} else if !enabled && ok {
delete(l.debug, facility)
if len(l.debug) == 0 {
l.SetFlags(DefaultFlags)
}
}
}
// isTraced returns whether the facility name is contained in STTRACE.
func (l *logger) isTraced(facility string) bool {
if len(l.traces) > 0 {
if l.traces[0] == "all" {
return true
}
_, found := slices.BinarySearch(l.traces, facility)
return found
}
return false
}
// FacilityDebugging returns the set of facilities that have debugging
// enabled.
func (l *logger) FacilityDebugging() []string {
enabled := make([]string, 0, len(l.debug))
l.mut.Lock()
for facility := range l.debug {
enabled = append(enabled, facility)
}
l.mut.Unlock()
return enabled
}
// Facilities returns the currently known set of facilities and their
// descriptions.
func (l *logger) Facilities() map[string]string {
l.mut.Lock()
res := make(map[string]string, len(l.facilities))
for facility, descr := range l.facilities {
res[facility] = descr
}
l.mut.Unlock()
return res
}
// NewFacility returns a new logger bound to the named facility.
func (l *logger) NewFacility(facility, description string) Logger {
l.SetDebug(facility, l.isTraced(facility))
l.mut.Lock()
l.facilities[facility] = description
l.mut.Unlock()
return &facilityLogger{
logger: l,
facility: facility,
}
}
// A facilityLogger is a regular logger but bound to a facility name. The
// Debugln and Debugf methods are no-ops unless debugging has been enabled for
// this facility on the parent logger.
type facilityLogger struct {
*logger
facility string
}
// Debugln logs a line with a DEBUG prefix.
func (l *facilityLogger) Debugln(vals ...interface{}) {
if !l.ShouldDebug(l.facility) {
return
}
l.logger.debugln(3, vals...)
}
// Debugf logs a formatted line with a DEBUG prefix.
func (l *facilityLogger) Debugf(format string, vals ...interface{}) {
if !l.ShouldDebug(l.facility) {
return
}
l.logger.debugf(3, format, vals...)
}
// A Recorder keeps a size limited record of log events.
type Recorder interface {
Since(t time.Time) []Line
Clear()
}
type recorder struct {
lines []Line
initial int
mut sync.Mutex
}
// A Line represents a single log entry.
type Line struct {
When time.Time `json:"when"`
Message string `json:"message"`
Level LogLevel `json:"level"`
}
func NewRecorder(l Logger, level LogLevel, size, initial int) Recorder {
r := &recorder{
lines: make([]Line, 0, size),
initial: initial,
}
l.AddHandler(level, r.append)
return r
}
func (r *recorder) Since(t time.Time) []Line {
r.mut.Lock()
defer r.mut.Unlock()
res := r.lines
for i := 0; i < len(res); i++ {
if res[i].When.After(t) {
// We must copy the result as r.lines can be mutated as soon as the lock
// is released.
res = res[i:]
cp := make([]Line, len(res))
copy(cp, res)
return cp
}
}
return nil
}
func (r *recorder) Clear() {
r.mut.Lock()
r.lines = r.lines[:0]
r.mut.Unlock()
}
func (r *recorder) append(l LogLevel, msg string) {
line := Line{
When: time.Now(), // intentionally high precision
Message: msg,
Level: l,
}
r.mut.Lock()
defer r.mut.Unlock()
if len(r.lines) == cap(r.lines) {
if r.initial > 0 {
// Shift all lines one step to the left, keeping the "initial" first intact.
copy(r.lines[r.initial+1:], r.lines[r.initial+2:])
} else {
copy(r.lines, r.lines[1:])
}
// Add the new one at the end
r.lines[len(r.lines)-1] = line
return
}
r.lines = append(r.lines, line)
if len(r.lines) == r.initial {
r.lines = append(r.lines, Line{time.Now(), "...", l})
}
}
// controlStripper is a Writer that replaces control characters
// with spaces.
type controlStripper struct {
io.Writer
}
func (s controlStripper) Write(data []byte) (int, error) {
for i, b := range data {
if b == '\n' || b == '\r' {
// Newlines are OK
continue
}
if b < 32 {
// Characters below 32 are control characters
data[i] = ' '
}
}
return s.Writer.Write(data)
}