github/portmaster
1
0
Fork 0
Code Issues Pull Requests Actions 1 Packages Projects Releases Wiki Activity

[service] Move logging to the core, remove pkg level logs

Browse Source
This commit is contained in:
Daniel
2024-11-14 17:33:27 +01:00
parent 8b1bdc7eb1
commit f91003d077
22 changed files with 360 additions and 306 deletions
Download Patch File Download Diff File Expand all files Collapse all files

5
base/api/endpoints_debug.go
View File

@@ -12,6 +12,7 @@ import (
"time"
"github.com/safing/portmaster/base/info"
"github.com/safing/portmaster/base/log"
"github.com/safing/portmaster/base/utils/debug"
)
@@ -152,12 +153,12 @@ func getStack(_ *Request) (data []byte, err error) {
// printStack prints the current goroutine stack to stderr.
func printStack(_ *Request) (msg string, err error) {
_, err = fmt.Fprint(os.Stderr, "===== PRINTING STACK =====\n")
_, err = fmt.Fprint(log.GlobalWriter, "===== PRINTING STACK =====\n")
if err == nil {
err = pprof.Lookup("goroutine").WriteTo(os.Stderr, 1)
}
if err == nil {
_, err = fmt.Fprint(os.Stderr, "===== END OF STACK =====\n")
_, err = fmt.Fprint(log.GlobalWriter, "===== END OF STACK =====\n")
}
if err != nil {
return "", err

22
base/info/version.go
View File

@@ -153,6 +153,28 @@ func FullVersion() string {
return builder.String()
}
// CondensedVersion returns the rather complete, but condensed version string.
func CondensedVersion() string {
info := GetInfo()
cgoInfo := "-cgo"
if info.CGO {
cgoInfo = "+cgo"
}
dirtyInfo := "clean"
if info.Dirty {
dirtyInfo = "dirty"
}
return fmt.Sprintf(
"%s %s (%s; built with %s [%s %s] from %s [%s] at %s)",
info.Name, version,
runtime.GOOS,
runtime.Version(), runtime.Compiler, cgoInfo,
info.Commit, dirtyInfo, info.CommitTime,
)
}
// CheckVersion checks if the metadata is ok.
func CheckVersion() error {
switch {

13
base/log/flags.go
View File

@@ -1,13 +0,0 @@
package log
import "flag"
var (
logLevelFlag string
pkgLogLevelsFlag string
)
func init() {
flag.StringVar(&logLevelFlag, "log", "", "set log level to [trace|debug|info|warning|error|critical]")
flag.StringVar(&pkgLogLevelsFlag, "plog", "", "set log level of packages: database=trace,notifications=debug")
}

39
base/log/input.go
View File

@@ -3,7 +3,6 @@ package log
import (
"fmt"
"runtime"
"strings"
"sync/atomic"
"time"
)
@@ -25,6 +24,11 @@ func log(level Severity, msg string, tracer *ContextTracer) {
return
}
// Check log level.
if uint32(level) < atomic.LoadUint32(logLevel) {
return
}
// get time
now := time.Now()
@@ -41,31 +45,6 @@ func log(level Severity, msg string, tracer *ContextTracer) {
}
}
// check if level is enabled for file or generally
if pkgLevelsActive.IsSet() {
pathSegments := strings.Split(file, "/")
if len(pathSegments) < 2 {
// file too short for package levels
return
}
pkgLevelsLock.Lock()
severity, ok := pkgLevels[pathSegments[len(pathSegments)-2]]
pkgLevelsLock.Unlock()
if ok {
if level < severity {
return
}
} else {
// no package level set, check against global level
if uint32(level) < atomic.LoadUint32(logLevel) {
return
}
}
} else if uint32(level) < atomic.LoadUint32(logLevel) {
// no package levels set, check against global level
return
}
// create log object
log := &logLine{
msg: msg,
@@ -101,13 +80,7 @@ func log(level Severity, msg string, tracer *ContextTracer) {
}
func fastcheck(level Severity) bool {
if pkgLevelsActive.IsSet() {
return true
}
if uint32(level) >= atomic.LoadUint32(logLevel) {
return true
}
return false
return uint32(level) >= atomic.LoadUint32(logLevel)
}
// Trace is used to log tiny steps. Log traces to context if you can!

96
base/log/logging.go
View File

@@ -2,6 +2,7 @@ package log
import (
"fmt"
"log/slog"
"os"
"strings"
"sync"
@@ -33,6 +34,26 @@ import (
// Severity describes a log level.
type Severity uint32
func (s Severity) toSLogLevel() slog.Level {
// Convert to slog level.
switch s {
case TraceLevel:
return slog.LevelDebug
case DebugLevel:
return slog.LevelDebug
case InfoLevel:
return slog.LevelInfo
case WarningLevel:
return slog.LevelWarn
case ErrorLevel:
return slog.LevelError
case CriticalLevel:
return slog.LevelError
}
// Failed to convert, return default log level
return slog.LevelWarn
}
// Message describes a log level message and is implemented
// by logLine.
type Message interface {
@@ -105,10 +126,6 @@ var (
logLevelInt = uint32(InfoLevel)
logLevel = &logLevelInt
pkgLevelsActive = abool.NewBool(false)
pkgLevels = make(map[string]Severity)
pkgLevelsLock sync.Mutex
logsWaiting = make(chan struct{}, 1)
logsWaitingFlag = abool.NewBool(false)
@@ -121,19 +138,6 @@ var (
startedSignal = make(chan struct{})
)
// SetPkgLevels sets individual log levels for packages. Only effective after Start().
func SetPkgLevels(levels map[string]Severity) {
pkgLevelsLock.Lock()
pkgLevels = levels
pkgLevelsLock.Unlock()
pkgLevelsActive.Set()
}
// UnSetPkgLevels removes all individual log levels for packages.
func UnSetPkgLevels() {
pkgLevelsActive.UnSet()
}
// GetLogLevel returns the current log level.
func GetLogLevel() Severity {
return Severity(atomic.LoadUint32(logLevel))
@@ -187,47 +191,36 @@ func ParseLevel(level string) Severity {
}
// Start starts the logging system. Must be called in order to see logs.
func Start() (err error) {
func Start(level string, logToStdout bool, logDir string) (err error) {
if !initializing.SetToIf(false, true) {
return nil
}
logBuffer = make(chan *logLine, 1024)
if logLevelFlag != "" {
initialLogLevel := ParseLevel(logLevelFlag)
// Parse log level argument.
initialLogLevel := InfoLevel
if level != "" {
initialLogLevel = ParseLevel(level)
if initialLogLevel == 0 {
fmt.Fprintf(os.Stderr, "log warning: invalid log level \"%s\", falling back to level info\n", logLevelFlag)
fmt.Fprintf(os.Stderr, "log warning: invalid log level %q, falling back to level info\n", level)
initialLogLevel = InfoLevel
}
}
SetLogLevel(initialLogLevel)
// Setup writer.
if logToStdout {
GlobalWriter = NewStdoutWriter()
} else {
// Setup slog here for the transition period.
setupSLog(GetLogLevel())
// Create file log writer.
var err error
GlobalWriter, err = NewFileWriter(logDir)
if err != nil {
return fmt.Errorf("failed to initialize log file: %w", err)
}
}
// get and set file loglevels
pkgLogLevels := pkgLogLevelsFlag
if len(pkgLogLevels) > 0 {
newPkgLevels := make(map[string]Severity)
for _, pair := range strings.Split(pkgLogLevels, ",") {
splitted := strings.Split(pair, "=")
if len(splitted) != 2 {
err = fmt.Errorf("log warning: invalid file log level \"%s\", ignoring", pair)
fmt.Fprintf(os.Stderr, "%s\n", err.Error())
break
}
fileLevel := ParseLevel(splitted[1])
if fileLevel == 0 {
err = fmt.Errorf("log warning: invalid file log level \"%s\", ignoring", pair)
fmt.Fprintf(os.Stderr, "%s\n", err.Error())
break
}
newPkgLevels[splitted[0]] = fileLevel
}
SetPkgLevels(newPkgLevels)
}
// Init logging systems.
SetLogLevel(initialLogLevel)
logBuffer = make(chan *logLine, 1024)
if !schedulingEnabled {
close(writeTrigger)
@@ -237,6 +230,14 @@ func Start() (err error) {
started.Set()
close(startedSignal)
// Delete all logs older than one month.
if !logToStdout {
err = CleanOldLogs(logDir, 30*24*time.Hour)
if err != nil {
Errorf("log: failed to clean old log files: %s", err)
}
}
return err
}
@@ -246,4 +247,5 @@ func Shutdown() {
close(shutdownSignal)
}
shutdownWaitGroup.Wait()
GlobalWriter.Close()
}

5
base/log/logging_test.go
View File

@@ -7,7 +7,7 @@ import (
)
func init() {
err := Start()
err := Start("info", true, "")
if err != nil {
panic(fmt.Sprintf("start failed: %s", err))
}
@@ -56,9 +56,6 @@ func TestLogging(t *testing.T) {
// wait logs to be written
time.Sleep(1 * time.Millisecond)
// just for show
UnSetPkgLevels()
// do not really shut down, we may need logging for other tests
// ShutdownLogging()
}

162
base/log/output.go
View File

@@ -2,78 +2,25 @@ package log
import (
"fmt"
"os"
"runtime/debug"
"sync"
"time"
"github.com/safing/portmaster/base/info"
)
type (
// Adapter is used to write logs.
Adapter interface {
// Write is called for each log message.
Write(msg Message, duplicates uint64)
}
// AdapterFunc is a convenience type for implementing
// Adapter.
AdapterFunc func(msg Message, duplicates uint64)
// FormatFunc formats msg into a string.
FormatFunc func(msg Message, duplicates uint64) string
// SimpleFileAdapter implements Adapter and writes all
// messages to File.
SimpleFileAdapter struct {
Format FormatFunc
File *os.File
}
)
// Adapter is used to write logs.
type Adapter interface {
// Write is called for each log message.
WriteMessage(msg Message, duplicates uint64)
}
var (
// StdoutAdapter is a simple file adapter that writes
// all logs to os.Stdout using a predefined format.
StdoutAdapter = &SimpleFileAdapter{
File: os.Stdout,
Format: defaultColorFormater,
}
// StderrAdapter is a simple file adapter that writes
// all logs to os.Stdout using a predefined format.
StderrAdapter = &SimpleFileAdapter{
File: os.Stderr,
Format: defaultColorFormater,
}
)
var (
adapter Adapter = StdoutAdapter
schedulingEnabled = false
writeTrigger = make(chan struct{})
)
// SetAdapter configures the logging adapter to use.
// This must be called before the log package is initialized.
func SetAdapter(a Adapter) {
if initializing.IsSet() || a == nil {
return
}
adapter = a
}
// Write implements Adapter and calls fn.
func (fn AdapterFunc) Write(msg Message, duplicates uint64) {
fn(msg, duplicates)
}
// Write implements Adapter and writes msg the underlying file.
func (fileAdapter *SimpleFileAdapter) Write(msg Message, duplicates uint64) {
fmt.Fprintln(fileAdapter.File, fileAdapter.Format(msg, duplicates))
}
// EnableScheduling enables external scheduling of the logger. This will require to manually trigger writes via TriggerWrite whenevery logs should be written. Please note that full buffers will also trigger writing. Must be called before Start() to have an effect.
// EnableScheduling enables external scheduling of the logger. This will require to manually trigger writes via TriggerWrite whenever logs should be written. Please note that full buffers will also trigger writing. Must be called before Start() to have an effect.
func EnableScheduling() {
if !initializing.IsSet() {
schedulingEnabled = true
@@ -95,27 +42,47 @@ func TriggerWriterChannel() chan struct{} {
return writeTrigger
}
func defaultColorFormater(line Message, duplicates uint64) string {
return formatLine(line.(*logLine), duplicates, true) //nolint:forcetypeassert // TODO: improve
}
func startWriter() {
fmt.Printf(
"%s%s%s %sBOF %s%s\n",
if GlobalWriter.isStdout {
fmt.Fprintf(GlobalWriter,
"%s%s%s %sBOF %s%s\n",
dimColor(),
time.Now().Format(timeFormat),
endDimColor(),
dimColor(),
time.Now().Format(timeFormat),
endDimColor(),
blueColor(),
rightArrow,
endColor(),
)
blueColor(),
rightArrow,
endColor(),
)
} else {
fmt.Fprintf(GlobalWriter,
"%s BOF %s\n",
time.Now().Format(timeFormat),
rightArrow,
)
}
writeVersion()
shutdownWaitGroup.Add(1)
go writerManager()
}
func writeVersion() {
if GlobalWriter.isStdout {
fmt.Fprintf(GlobalWriter, "%s%s%s running %s%s%s\n",
dimColor(),
time.Now().Format(timeFormat),
endDimColor(),
blueColor(),
info.CondensedVersion(),
endColor())
} else {
fmt.Fprintf(GlobalWriter, "%s running %s\n", time.Now().Format(timeFormat), info.CondensedVersion())
}
}
func writerManager() {
defer shutdownWaitGroup.Done()
@@ -129,18 +96,17 @@ func writerManager() {
}
}
// defer should be able to edit the err. So naked return is required.
// nolint:golint,nakedret
func writer() (err error) {
func writer() error {
var err error
defer func() {
// recover from panic
panicVal := recover()
if panicVal != nil {
err = fmt.Errorf("%s", panicVal)
_, err = fmt.Fprintf(GlobalWriter, "%s", panicVal)
// write stack to stderr
fmt.Fprintf(
os.Stderr,
GlobalWriter,
`===== Error Report =====
Message: %s
StackTrace:
@@ -169,7 +135,7 @@ StackTrace:
case <-forceEmptyingOfBuffer: // log buffer is full!
case <-shutdownSignal: // shutting down
finalizeWriting()
return
return err
}
// wait for timeslot to log
@@ -178,7 +144,7 @@ StackTrace:
case <-forceEmptyingOfBuffer: // log buffer is full!
case <-shutdownSignal: // shutting down
finalizeWriting()
return
return err
}
// write all the logs!
@@ -201,7 +167,7 @@ StackTrace:
}
// if currentLine and line are _not_ equal, output currentLine
adapter.Write(currentLine, duplicates)
GlobalWriter.WriteMessage(currentLine, duplicates)
// add to unexpected logs
addUnexpectedLogs(currentLine)
// reset duplicate counter
@@ -215,7 +181,7 @@ StackTrace:
// write final line
if currentLine != nil {
adapter.Write(currentLine, duplicates)
GlobalWriter.WriteMessage(currentLine, duplicates)
// add to unexpected logs
addUnexpectedLogs(currentLine)
}
@@ -225,7 +191,7 @@ StackTrace:
case <-time.After(10 * time.Millisecond):
case <-shutdownSignal:
finalizeWriting()
return
return err
}
}
@@ -235,19 +201,27 @@ func finalizeWriting() {
for {
select {
case line := <-logBuffer:
adapter.Write(line, 0)
GlobalWriter.WriteMessage(line, 0)
case <-time.After(10 * time.Millisecond):
fmt.Printf(
"%s%s%s %sEOF %s%s\n",
if GlobalWriter.isStdout {
fmt.Fprintf(GlobalWriter,
"%s%s%s %sEOF %s%s\n",
dimColor(),
time.Now().Format(timeFormat),
endDimColor(),
dimColor(),
time.Now().Format(timeFormat),
endDimColor(),
blueColor(),
leftArrow,
endColor(),
)
blueColor(),
leftArrow,
endColor(),
)
} else {
fmt.Fprintf(GlobalWriter,
"%s EOF %s\n",
time.Now().Format(timeFormat),
leftArrow,
)
}
return
}
}

41
base/log/slog.go
View File

@@ -6,54 +6,36 @@ import (
"runtime"
"github.com/lmittmann/tint"
"github.com/mattn/go-colorable"
"github.com/mattn/go-isatty"
)
func setupSLog(logLevel Severity) {
// Convert to slog level.
var level slog.Level
switch logLevel {
case TraceLevel:
level = slog.LevelDebug
case DebugLevel:
level = slog.LevelDebug
case InfoLevel:
level = slog.LevelInfo
case WarningLevel:
level = slog.LevelWarn
case ErrorLevel:
level = slog.LevelError
case CriticalLevel:
level = slog.LevelError
}
func setupSLog(level Severity) {
// Set highest possible level, so it can be changed in runtime.
handlerLogLevel := level.toSLogLevel()
// Setup logging.
// Define output.
logOutput := os.Stdout
// Create handler depending on OS.
var logHandler slog.Handler
switch runtime.GOOS {
case "windows":
logHandler = tint.NewHandler(
colorable.NewColorable(logOutput),
GlobalWriter,
&tint.Options{
AddSource: true,
Level: level,
Level: handlerLogLevel,
TimeFormat: timeFormat,
NoColor: !GlobalWriter.IsStdout(), // FIXME: also check for tty.
},
)
case "linux":
logHandler = tint.NewHandler(logOutput, &tint.Options{
logHandler = tint.NewHandler(GlobalWriter, &tint.Options{
AddSource: true,
Level: level,
Level: handlerLogLevel,
TimeFormat: timeFormat,
NoColor: !isatty.IsTerminal(logOutput.Fd()),
NoColor: !GlobalWriter.IsStdout(), // FIXME: also check for tty.
})
default:
logHandler = tint.NewHandler(os.Stdout, &tint.Options{
AddSource: true,
Level: level,
Level: handlerLogLevel,
TimeFormat: timeFormat,
NoColor: true,
})
@@ -61,5 +43,6 @@ func setupSLog(logLevel Severity) {
// Set as default logger.
slog.SetDefault(slog.New(logHandler))
slog.SetLogLoggerLevel(level)
// Set actual log level.
slog.SetLogLoggerLevel(handlerLogLevel)
}

33
base/log/trace.go
View File

@@ -4,7 +4,6 @@ import (
"context"
"fmt"
"runtime"
"strings"
"sync"
"sync/atomic"
"time"
@@ -24,36 +23,8 @@ var key = ContextTracerKey{}
// AddTracer adds a ContextTracer to the returned Context. Will return a nil ContextTracer if logging level is not set to trace. Will return a nil ContextTracer if one already exists. Will return a nil ContextTracer in case of an error. Will return a nil context if nil.
func AddTracer(ctx context.Context) (context.Context, *ContextTracer) {
if ctx != nil && fastcheck(TraceLevel) {
// check pkg levels
if pkgLevelsActive.IsSet() {
// get file
_, file, _, ok := runtime.Caller(1)
if !ok {
// cannot get file, ignore
return ctx, nil
}
pathSegments := strings.Split(file, "/")
if len(pathSegments) < 2 {
// file too short for package levels
return ctx, nil
}
pkgLevelsLock.Lock()
severity, ok := pkgLevels[pathSegments[len(pathSegments)-2]]
pkgLevelsLock.Unlock()
if ok {
// check against package level
if TraceLevel < severity {
return ctx, nil
}
} else {
// no package level set, check against global level
if uint32(TraceLevel) < atomic.LoadUint32(logLevel) {
return ctx, nil
}
}
} else if uint32(TraceLevel) < atomic.LoadUint32(logLevel) {
// no package levels set, check against global level
// Check log level.
if atomic.LoadUint32(logLevel) > uint32(TraceLevel) {
return ctx, nil
}

119
base/log/writer.go Normal file
View File

@@ -0,0 +1,119 @@
package log
import (
"fmt"
"os"
"path/filepath"
"sync"
"time"
)
// GlobalWriter is the global log writer.
var GlobalWriter *LogWriter = nil
type LogWriter struct {
writeLock sync.Mutex
isStdout bool
file *os.File
}
// NewStdoutWriter creates a new log writer thet will write to the stdout.
func NewStdoutWriter() *LogWriter {
return &LogWriter{
file: os.Stdout,
isStdout: true,
}
}
// NewFileWriter creates a new log writer that will write to a file. The file path will be <dir>/2006-01-02_15-04-05.log (with current date and time)
func NewFileWriter(dir string) (*LogWriter, error) {
// Make sure log dir exists, if not, create with strict permission, as logs can contain sensitive data.
_ = os.MkdirAll(dir, 0o700)
// Open new log file.
logFile := time.Now().UTC().Format("2006-01-02_15-04-05") + ".log"
file, err := os.Create(filepath.Join(dir, logFile))
if err != nil {
return nil, err
}
return &LogWriter{
file: file,
isStdout: false,
}, nil
}
// Write writes the buffer to the writer.
func (l *LogWriter) Write(buf []byte) (int, error) {
if l == nil {
return 0, fmt.Errorf("log writer not initialized")
}
// No need to lock in stdout context.
if !l.isStdout {
l.writeLock.Lock()
defer l.writeLock.Unlock()
}
return l.file.Write(buf)
}
// WriteMessage writes the message to the writer.
func (l *LogWriter) WriteMessage(msg Message, duplicates uint64) {
if l == nil {
return
}
// No need to lock in stdout context.
if !l.isStdout {
l.writeLock.Lock()
defer l.writeLock.Unlock()
}
fmt.Fprintln(l.file, formatLine(msg.(*logLine), duplicates, l.isStdout))
}
// IsStdout returns true if writer was initialized with stdout.
func (l *LogWriter) IsStdout() bool {
return l != nil && l.isStdout
}
// Close closes the writer.
func (l *LogWriter) Close() {
if l != nil && !l.isStdout {
_ = l.file.Close()
}
}
// CleanOldLogs deletes all log files in given directory that are older than the given threshold.
func CleanOldLogs(dir string, threshold time.Duration) error {
// Get current log file name.
var currentLogFile string
if GlobalWriter != nil && GlobalWriter.file != nil {
currentLogFile = GlobalWriter.file.Name()
}
// Read dir entries.
files, err := os.ReadDir(dir)
if err != nil {
return fmt.Errorf("failed to read dir: %w", err)
}
// Remove files older than threshold
deleteOlderThan := time.Now().Add(-threshold)
for _, f := range files {
// Skip directories and the current log file.
if f.IsDir() || f.Name() == currentLogFile {
continue
}
// Delete log files.
if fileInfo, err := f.Info(); err == nil {
if fileInfo.ModTime().Before(deleteOlderThan) {
_ = os.Remove(filepath.Join(dir, f.Name()))
}
}
}
return nil
}