From 9440b9e3138805945214aa4d86368bb40da07cc2 Mon Sep 17 00:00:00 2001 From: Wim Date: Sun, 24 May 2020 13:58:15 +0200 Subject: [PATCH] Increase debug logging with function,file and linenumber (#1147) Show the function name,file and linenumber like this [0000] INFO main: [setupLogger:matterbridge.go:100] Enabling debug logging. [0000] INFO main: [main:matterbridge.go:46] Running version 1.17.5-dev Only enable this for debug as this adds some overhead. --- go.mod | 2 +- go.sum | 4 +- matterbridge.go | 25 +++++++-- .../logrus-prefixed-formatter/formatter.go | 54 +++++++++++++++++-- vendor/modules.txt | 2 +- 5 files changed, 75 insertions(+), 12 deletions(-) diff --git a/go.mod b/go.mod index dc1e29db..e29b3cb3 100644 --- a/go.mod +++ b/go.mod @@ -26,7 +26,7 @@ require ( github.com/matterbridge/go-xmpp v0.0.0-20200418225040-c8a3a57b4050 github.com/matterbridge/gomatrix v0.0.0-20200209224845-c2104d7936a6 github.com/matterbridge/gozulipbot v0.0.0-20190212232658-7aa251978a18 - github.com/matterbridge/logrus-prefixed-formatter v0.0.0-20180806162718-01618749af61 + github.com/matterbridge/logrus-prefixed-formatter v0.5.3-0.20200523233437-d971309a77ba github.com/mattermost/mattermost-server v5.5.0+incompatible github.com/mattn/godown v0.0.0-20200217152941-afc959f6a561 github.com/mgutz/ansi v0.0.0-20170206155736-9520e82c474b // indirect diff --git a/go.sum b/go.sum index 436a03bd..c1e79f85 100644 --- a/go.sum +++ b/go.sum @@ -189,8 +189,8 @@ github.com/matterbridge/gomatrix v0.0.0-20200209224845-c2104d7936a6 h1:Kl65VJv38 github.com/matterbridge/gomatrix v0.0.0-20200209224845-c2104d7936a6/go.mod h1:+jWeaaUtXQbBRdKYWfjW6JDDYiI2XXE+3NnTjW5kg8g= github.com/matterbridge/gozulipbot v0.0.0-20190212232658-7aa251978a18 h1:fLhwXtWGtfTgZVxHG1lcKjv+re7dRwyyuYFNu69xdho= github.com/matterbridge/gozulipbot v0.0.0-20190212232658-7aa251978a18/go.mod h1:yAjnZ34DuDyPHMPHHjOsTk/FefW4JJjoMMCGt/8uuQA= -github.com/matterbridge/logrus-prefixed-formatter v0.0.0-20180806162718-01618749af61 h1:R/MgM/eUyRBQx2FiH6JVmXck8PaAuKfe2M1tWIzW7nE= -github.com/matterbridge/logrus-prefixed-formatter v0.0.0-20180806162718-01618749af61/go.mod h1:iXGEotOvwI1R1SjLxRc+BF5rUORTMtE0iMZBT2lxqAU= +github.com/matterbridge/logrus-prefixed-formatter v0.5.3-0.20200523233437-d971309a77ba h1:XleOY4IjAEIcxAh+IFwT5JT5Ze3RHiYz6m+4ZfZ0rc0= +github.com/matterbridge/logrus-prefixed-formatter v0.5.3-0.20200523233437-d971309a77ba/go.mod h1:iXGEotOvwI1R1SjLxRc+BF5rUORTMtE0iMZBT2lxqAU= github.com/mattermost/mattermost-server v5.5.0+incompatible h1:0wcLGgYtd+YImtLDPf2AOfpBHxbU4suATx+6XKw1XbU= github.com/mattermost/mattermost-server v5.5.0+incompatible/go.mod h1:5L6MjAec+XXQwMIt791Ganu45GKsSiM+I0tLR9wUj8Y= github.com/mattn/go-colorable v0.0.9/go.mod h1:9vuHe8Xs5qXnSaW/c/ABM9alt+Vo+STaOChaDxuIBZU= diff --git a/matterbridge.go b/matterbridge.go index da0df103..24caa5d9 100644 --- a/matterbridge.go +++ b/matterbridge.go @@ -4,6 +4,7 @@ import ( "flag" "fmt" "os" + "runtime" "strings" "github.com/42wim/matterbridge/bridge/config" @@ -67,17 +68,31 @@ func setupLogger() *logrus.Logger { Formatter: &prefixed.TextFormatter{ PrefixPadding: 13, DisableColors: true, - FullTimestamp: true, }, Level: logrus.InfoLevel, } if *flagDebug || os.Getenv("DEBUG") == "1" { + logger.SetReportCaller(true) logger.Formatter = &prefixed.TextFormatter{ - PrefixPadding: 13, - DisableColors: true, - FullTimestamp: false, - ForceFormatting: true, + PrefixPadding: 13, + DisableColors: true, + FullTimestamp: false, + + CallerFormatter: func(function, file string) string { + return fmt.Sprintf(" [%s:%s]", function, file) + }, + CallerPrettyfier: func(f *runtime.Frame) (string, string) { + sp := strings.SplitAfter(f.File, "/matterbridge/") + filename := f.File + if len(sp) > 1 { + filename = sp[1] + } + s := strings.Split(f.Function, ".") + funcName := s[len(s)-1] + return funcName, fmt.Sprintf("%s:%d", filename, f.Line) + }, } + logger.Level = logrus.DebugLevel logger.WithFields(logrus.Fields{"prefix": "main"}).Info("Enabling debug logging.") } diff --git a/vendor/github.com/matterbridge/logrus-prefixed-formatter/formatter.go b/vendor/github.com/matterbridge/logrus-prefixed-formatter/formatter.go index 7cb807da..434c2982 100644 --- a/vendor/github.com/matterbridge/logrus-prefixed-formatter/formatter.go +++ b/vendor/github.com/matterbridge/logrus-prefixed-formatter/formatter.go @@ -6,6 +6,7 @@ import ( "io" "os" "regexp" + "runtime" "sort" "strings" "sync" @@ -121,6 +122,14 @@ type TextFormatter struct { // Whether the logger's out is to a terminal. isTerminal bool + // CallerPrettyfier can be set by the user to modify the content + // of the function and file keys in the data when ReportCaller is + // activated. If any of the returned value is the empty string the + // corresponding key will be removed from fields. + CallerPrettyfier func(*runtime.Frame) (function string, file string) + + CallerFormatter func(function, file string) string + sync.Once } @@ -217,6 +226,23 @@ func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) { if entry.Message != "" { f.appendKeyValue(b, "msg", entry.Message, lastKeyIdx >= 0) } + + if entry.HasCaller() { + var funcVal, fileVal string + if f.CallerPrettyfier != nil { + funcVal, fileVal = f.CallerPrettyfier(entry.Caller) + } else { + funcVal, fileVal = extractCallerInfo(entry.Caller) + } + + if funcVal != "" { + f.appendKeyValue(b, "func", funcVal, true) + } + if fileVal != "" { + f.appendKeyValue(b, "file", fileVal, true) + } + } + for i, key := range keys { f.appendKeyValue(b, key, entry.Data[key], lastKeyIdx != i) } @@ -276,7 +302,7 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys prefixFormat := "%s" if f.PrefixPadding != 0 { - prefixFormat = fmt.Sprintf("%%-%ds", adjustedPrefixPadding) + prefixFormat = fmt.Sprintf("%%-%ds%%s", adjustedPrefixPadding) } messageFormat := "%s" @@ -284,8 +310,24 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys messageFormat = fmt.Sprintf("%%-%ds", f.SpacePadding) } + caller := "" + if entry.HasCaller() { + var funcVal, fileVal string + if f.CallerPrettyfier != nil { + funcVal, fileVal = f.CallerPrettyfier(entry.Caller) + } else { + funcVal, fileVal = extractCallerInfo(entry.Caller) + } + + if f.CallerFormatter != nil { + caller = f.CallerFormatter(funcVal, fileVal) + } else { + caller = fmt.Sprintf(" (%s: %s)", fileVal, funcVal) + } + } + if f.DisableTimestamp { - fmt.Fprintf(b, "%s"+prefixFormat+" "+messageFormat, level, prefix, message) + fmt.Fprintf(b, "%s"+prefixFormat+" "+messageFormat, level, prefix, caller, message) } else { var timestamp string if !f.FullTimestamp { @@ -293,7 +335,7 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys } else { timestamp = fmt.Sprintf("[%s]", entry.Time.Format(timestampFormat)) } - fmt.Fprintf(b, "%s %s"+prefixFormat+" "+messageFormat, colorScheme.TimestampColor(timestamp), level, prefix, message) + fmt.Fprintf(b, "%s %s"+prefixFormat+" "+messageFormat, colorScheme.TimestampColor(timestamp), level, prefix, caller, message) } for _, k := range keys { if k != "prefix" { @@ -318,6 +360,12 @@ func (f *TextFormatter) needsQuoting(text string) bool { return false } +func extractCallerInfo(caller *runtime.Frame) (string, string) { + funcVal := caller.Function + fileVal := fmt.Sprintf("%s:%d", caller.File, caller.Line) + return funcVal, fileVal +} + func extractPrefix(msg string) (string, string) { prefix := "" regex := regexp.MustCompile("^\\[(.*?)\\]") diff --git a/vendor/modules.txt b/vendor/modules.txt index f1893020..d940a05b 100644 --- a/vendor/modules.txt +++ b/vendor/modules.txt @@ -107,7 +107,7 @@ github.com/matterbridge/go-xmpp github.com/matterbridge/gomatrix # github.com/matterbridge/gozulipbot v0.0.0-20190212232658-7aa251978a18 github.com/matterbridge/gozulipbot -# github.com/matterbridge/logrus-prefixed-formatter v0.0.0-20180806162718-01618749af61 +# github.com/matterbridge/logrus-prefixed-formatter v0.5.3-0.20200523233437-d971309a77ba github.com/matterbridge/logrus-prefixed-formatter # github.com/mattermost/mattermost-server v5.5.0+incompatible github.com/mattermost/mattermost-server/mlog