From 9b65dc612f68ff65720d3405c3fb42f3fc549d40 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Thilo=20Karra=C3=9F?= Date: Tue, 9 Jan 2024 11:17:15 +0100 Subject: [PATCH] Add stack traces, errors, a simple formatter --- envelope.go | 102 ++++++++++++++++++++++++++++++++++++++++++--- example/example.go | 21 ++++++++-- formatter.go | 6 ++- formatter_plain.go | 18 ++++++-- level.go | 26 +++++++++--- logger.go | 28 +++++++++---- 6 files changed, 174 insertions(+), 27 deletions(-) diff --git a/envelope.go b/envelope.go index 0833b37..8fc89d8 100644 --- a/envelope.go +++ b/envelope.go @@ -2,6 +2,9 @@ package log import ( "fmt" + "os" + "runtime" + "strings" "time" ) @@ -13,22 +16,87 @@ type envelope struct { // err is an error attached to the envelope err error - args map[string]string + args []*Argument + + trace level +} + +type Argument struct { + Name string + Value string +} + +func (a Argument) String() string { + return "(" + a.Name + "=" + a.Value + ")" } func (e *envelope) Msg(f string, args ...any) { + e.msgT(time.Now(), f, args...) +} + +func (e *envelope) msgT(t time.Time, f string, args ...any) { if e.log.Level() < e.lvl { return // No logging } - // formatter and output things here - E := &envelopeData{*e, time.Now()} + // Convert to a public readable Envelope + E := &envelopeData{*e, t} msg := fmt.Sprintf(f, args...) + // lock loggers[e.log].format.Output(msg, E) - e.lvl.Hook(msg) + if e.trace > 0 || (e.err != nil && e.log.Autotrace() > 0) { + e.stack(t) + } + // unlock + e.lvl.hook(msg) +} + +var trimpathwarned = false + +// WithStack dumps a stack trace after the log message +func (e *envelope) WithStack() *envelope { + return e.WithStackAs(e.lvl) +} + +// WithStackAs dumps a stack trace after the log message using the given log level +func (e *envelope) WithStackAs(lvl level) *envelope { + e.trace = lvl + return e +} + +func (e *envelope) stack(et time.Time) { + if _, file, _, ok := runtime.Caller(1); ok { + if !trimpathwarned && strings.HasPrefix(file, "/") { + WARN.Msg("Binary includes build host information.\n") + WARN.Msg("Consider recompiling using the -trimpath flag.\n") + trimpathwarned = true + } + //e.trace.To(e.log).Msg("called from: %v:%v\n", file, line) + } else { + e.trace.To(e.log).Msg("cannot get caller") + return + } + pc := make([]uintptr, 10, 10) + n := runtime.Callers(2, pc) + frames := runtime.CallersFrames(pc[:n]) + frame, more := frames.Next() + + // use autotrace level, but if the envelope defines an explicit level use that one instead: + elvl := e.log.Autotrace() + if e.trace > 0 { + elvl = e.trace + } + + for more { + // skip traces within the log module + if !strings.HasPrefix(frame.Function, "udico.de/util/log.") { + elvl.To(e.log).msgT(et, "@%v:%v in %v()\n", frame.File, frame.Line, frame.Function) + } + frame, more = frames.Next() + } } func (e *envelope) Arg(name string, value any) *envelope { - e.args[name] = fmt.Sprintf("%v", value) + e.args = append(e.args, &Argument{name, fmt.Sprintf("%v", value)}) return e } @@ -49,3 +117,27 @@ func (e *envelope) If(msg func(Fn)) { msg(e.Msg) } } + +// Explain dumps the current log configuration using the logger and log level from the given envelope. +func (e *envelope) Explain() { + for _, v := range loggers { + name := v.name + if name == "" { + name = "default" + } + env := e.lvl.To(e.log).Arg("name", name) + if file, ok := v.target.(*os.File); ok { + tname := file.Name() + switch file.Fd() { + case os.Stdout.Fd(): + tname = "stdout" + case os.Stderr.Fd(): + tname = "stderr" + } + env.Arg("target", tname) + } else { + env.Arg("target", "custom") + } + env.Arg("formatter", v.format).Msg("Logger %v", name) + } +} diff --git a/example/example.go b/example/example.go index 803d4af..b09e241 100644 --- a/example/example.go +++ b/example/example.go @@ -1,13 +1,25 @@ package main import ( + "fmt" "udico.de/util/log" ) -var logger = log.Logger("MyLogger").SetLevel(log.TRACE) +var logger = log.Logger("MyLogger").SetLevel(log.TRACE).SetAutotrace(log.TRACE) + +func anotherFunc() { + log.NOTICE.WithStackAs(log.INFO).Msg("Let's dump a stack trace!") +} + +func aFunc() { + log.INFO.Msg("in aFunc") + anotherFunc() +} func main() { - log.DefaultLogger.SetLevel(log.DEBUG) + log.DefaultLogger.SetLevel(log.DEBUG).SetAutotrace(log.TRACE) + // dump logger config: + log.INFO.Explain() log.WARN.To(logger).Msg("Now doing things :)") log.INFO.Msg("hallo %v", "bla") @@ -16,8 +28,11 @@ func main() { msg("hi!") }) - log.PANIC.To(logger).Msg("Bad things happened :(") + aFunc() + + log.ERROR.To(logger).WithStackAs(log.ERROR).Msg("Bad things happened :(") log.NOTICE.Msg("I'm done!") + log.INFO.Err(fmt.Errorf("oh, an error!")).Msg("what's this?") } /* diff --git a/formatter.go b/formatter.go index 74e2e43..dada579 100644 --- a/formatter.go +++ b/formatter.go @@ -11,6 +11,8 @@ import "time" // -> Answer: should be added to the Envelope right before the call to Output() // -> There should be an in between layer doing the channel thing calling Output() type Formatter interface { + + // Output generates a log entry based on the given message and Envelope Output(message string, e Envelope) } @@ -18,7 +20,7 @@ type Envelope interface { Logger() logger Level() level Error() error - Arguments() map[string]string + Arguments() []*Argument Time() time.Time } @@ -40,7 +42,7 @@ func (e envelopeData) Error() error { return e.err } -func (e envelopeData) Arguments() map[string]string { +func (e envelopeData) Arguments() []*Argument { return e.args } diff --git a/formatter_plain.go b/formatter_plain.go index 78b8817..ec0fd56 100644 --- a/formatter_plain.go +++ b/formatter_plain.go @@ -5,6 +5,7 @@ import ( "golang.org/x/term" "io" "os" + "strings" ) // ColorMode indicates if colorized output should be used @@ -91,6 +92,10 @@ var levelColorDatas = []levelColorData{ /* TRACE */ {Dark: "\033[90m", Light: ""}, } +func (f *PlainFormatter) String() string { + return "PlainFormatter" +} + func (f *PlainFormatter) Output(message string, envelope Envelope) { o := envelope.Logger().Target() cm := f.resolveColorMode(o) @@ -104,13 +109,18 @@ func (f *PlainFormatter) Output(message string, envelope Envelope) { msg += "[" + envelope.Logger().String() + "] " } msg += envelope.Level().String() + ": " - msg += message + msg += strings.TrimSpace(message) + if envelope.Error() != nil { + msg += fmt.Sprintf(" [err=%v]", envelope.Error()) + } + for _, v := range envelope.Arguments() { + msg += " " + v.String() + } if cm.Colorize() { msg += "\033[0m" } - if msg[len(msg)-1] != '\n' { - msg += "\n" - } + msg += "\n" + // "time (logger) level message args" fmt.Fprint(o, msg) diff --git a/level.go b/level.go index 99035af..858b32c 100644 --- a/level.go +++ b/level.go @@ -68,10 +68,9 @@ var levelDatas = []levelData{ // No, it's not a map! Indexing into a slice is fa // To sends the resulting log message to a given logger func (l level) To(log logger) *envelope { return &envelope{ - log: log, - lvl: l, - err: nil, - args: make(map[string]string), + log: log, + lvl: l, + err: nil, } } @@ -80,6 +79,16 @@ func (l level) Msg(format string, args ...any) { l.To(0).Msg(format, args...) } +// WithStack dumps a stack trace after the log message +func (l level) WithStack() *envelope { + return l.To(0).WithStack() +} + +// WithStackAs dumps a stack trace after the log message using the given log level +func (l level) WithStackAs(lvl level) *envelope { + return l.To(0).WithStackAs(lvl) +} + // Err attaches an error to the log message. func (l level) Err(err error) *envelope { return l.To(0).Err(err) @@ -95,8 +104,8 @@ func (l level) If(msg func(Fn)) { l.To(0).If(msg) } -// Hook executes the associated hook, if any -func (l level) Hook(msg string) { +// hook executes the associated hook, if any +func (l level) hook(msg string) { if levelDatas[l].Hook != nil { levelDatas[l].Hook(msg) } @@ -106,6 +115,11 @@ func (l level) String() string { return levelDatas[l].Name } +// Explain dumps the current log configuration to the default logger using the given log level +func (l level) Explain() { + l.To(0).Explain() +} + func ParseLevel(levelstring string) (level, error) { switch strings.ToLower(levelstring) { case "silent", "off", "none": diff --git a/logger.go b/logger.go index 2fa1ffa..789eab0 100644 --- a/logger.go +++ b/logger.go @@ -17,18 +17,21 @@ const DefaultLogger logger = 0 //var targets []io.Writer = make([]io.Writer, 1, 10) type loggerData struct { - name string - level level - target io.Writer - format Formatter + name string + level level + target io.Writer + format Formatter + autotrace level } var loggers []loggerData = make([]loggerData, 1, 10) func init() { - DefaultLogger.SetLevel(INFO) - DefaultLogger.SetTarget(os.Stdout) - DefaultLogger.SetFormatter(&PlainFormatter{}) + DefaultLogger. + SetLevel(INFO). + SetTarget(os.Stdout). + SetFormatter(&PlainFormatter{}). + SetAutotrace(DEBUG) } // Logger returns a logger with the given name. If there is no logger with this @@ -78,6 +81,17 @@ func (l logger) SetFormatter(f Formatter) logger { return l } +func (l logger) Autotrace() level { + return loggers[l].autotrace +} + +// SetAutotrace sets the level to send the stack trace to in case an error is logged. (which is a +// log message with an error attached to it). +func (l logger) SetAutotrace(lvl level) logger { + loggers[l].autotrace = lvl + return l +} + func (l logger) String() string { return loggers[l].name }