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

@@ -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

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.5.3-0.20200523233437-d971309a77ba h1:XleOY4IjAEIcxAh+IFwT5JT5Ze3RHiYz6m+4ZfZ0rc0=
-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/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=

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,
+			PrefixPadding: 13,
-			DisableColors:   true,
+			DisableColors: true,
-			FullTimestamp:   false,
+			FullTimestamp: false,
-			ForceFormatting: true,
+
+			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.")
 	}

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("^\\[(.*?)\\]")

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