Add human-readbale log output (#681)

Add human-readable log output. It prints out the exact source code line information.

formatter/formatter.go

@@ -0,0 +1,51 @@
+package formatter
+
+import (
+	"fmt"
+	"strings"
+	"time"
+
+	"github.com/sirupsen/logrus"
+)
+
+// TextFormatter formats logs into text with included source code's path
+type TextFormatter struct {
+	TimestampFormat string
+	LevelDesc       []string
+}
+
+// NewTextFormatter create new MyTextFormatter instance
+func NewTextFormatter() *TextFormatter {
+	return &TextFormatter{
+		LevelDesc:       []string{"PANC", "FATL", "ERRO", "WARN", "INFO", "DEBG", "TRAC"},
+		TimestampFormat: time.RFC3339, // or RFC3339
+	}
+}
+
+// Format renders a single log entry
+func (f *TextFormatter) Format(entry *logrus.Entry) ([]byte, error) {
+	var fields string
+	keys := make([]string, 0, len(entry.Data))
+	for k, v := range entry.Data {
+		if k == "source" {
+			continue
+		}
+		keys = append(keys, fmt.Sprintf("%s: %v", k, v))
+	}
+
+	if len(keys) > 0 {
+		fields = fmt.Sprintf("[%s] ", strings.Join(keys, ", "))
+	}
+
+	level := f.parseLevel(entry.Level)
+
+	return []byte(fmt.Sprintf("%s %s %s%s: %s\n", entry.Time.Format(f.TimestampFormat), level, fields, entry.Data["source"], entry.Message)), nil
+}
+
+func (f *TextFormatter) parseLevel(level logrus.Level) string {
+	if len(f.LevelDesc) < int(level) {
+		return ""
+	}
+
+	return f.LevelDesc[level]
+}

formatter/formatter_test.go

@@ -0,0 +1,27 @@
+package formatter
+
+import (
+	"testing"
+	"time"
+
+	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestLogMessageFormat(t *testing.T) {
+
+	someEntry := &logrus.Entry{
+		Data:    logrus.Fields{"att1": 1, "att2": 2, "source": "some/fancy/path.go:46"},
+		Time:    time.Date(2021, time.Month(2), 21, 1, 10, 30, 0, time.UTC),
+		Level:   3,
+		Message: "Some Message",
+	}
+
+	formatter := NewTextFormatter()
+	result, _ := formatter.Format(someEntry)
+
+	expectedString := "2021-02-21T01:10:30Z WARN [att1: 1, att2: 2] some/fancy/path.go:46: Some Message\n"
+	parsedString := string(result)
+	assert.Equal(t, expectedString, parsedString, "The log messages don't match.")
+
+}

formatter/hook.go

@@ -0,0 +1,61 @@
+package formatter
+
+import (
+	"fmt"
+	"path"
+	"runtime/debug"
+	"strings"
+
+	"github.com/sirupsen/logrus"
+)
+
+// ContextHook is a custom hook for add the source information for the entry
+type ContextHook struct {
+	goModuleName string
+}
+
+// NewContextHook instantiate a new context hook
+func NewContextHook() *ContextHook {
+	hook := &ContextHook{}
+	hook.goModuleName = hook.moduleName() + "/"
+	return hook
+}
+
+// Levels set the supported levels for this hook
+func (hook ContextHook) Levels() []logrus.Level {
+	return logrus.AllLevels
+}
+
+// Fire extend with the source information the entry.Data
+func (hook ContextHook) Fire(entry *logrus.Entry) error {
+	src := hook.parseSrc(entry.Caller.File)
+	entry.Data["source"] = fmt.Sprintf("%s:%v", src, entry.Caller.Line)
+	return nil
+}
+
+func (hook ContextHook) moduleName() string {
+	info, ok := debug.ReadBuildInfo()
+	if ok && info.Main.Path != "" {
+		return info.Main.Path
+	}
+
+	return "netbird"
+}
+
+func (hook ContextHook) parseSrc(filePath string) string {
+	netbirdPath := strings.SplitAfter(filePath, hook.goModuleName)
+	if len(netbirdPath) > 1 {
+		return netbirdPath[len(netbirdPath)-1]
+	}
+
+	// in case of forked repo
+	netbirdPath = strings.SplitAfter(filePath, "netbird/")
+	if len(netbirdPath) > 1 {
+		return netbirdPath[len(netbirdPath)-1]
+	}
+
+	// in case if log entry is come from external pkg
+	_, pkg := path.Split(path.Dir(filePath))
+	file := path.Base(filePath)
+	return fmt.Sprintf("%s/%s", pkg, file)
+}

formatter/hook_test.go

@@ -0,0 +1,39 @@
+package formatter
+
+import (
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestFilePathParsing(t *testing.T) {
+
+	testCases := []struct {
+		filePath         string
+		expectedFileName string
+	}{
+		// locally cloned repo
+		{
+			filePath:         "/Users/user/Github/Netbird/netbird/formatter/formatter.go",
+			expectedFileName: "formatter/formatter.go",
+		},
+		// locally cloned repo with duplicated name in path
+		{
+			filePath:         "/Users/user/netbird/repos/netbird/formatter/formatter.go",
+			expectedFileName: "formatter/formatter.go",
+		},
+		// locally cloned repo with renamed package root
+		{
+			filePath:         "/Users/user/Github/MyOwnNetbirdClient/formatter/formatter.go",
+			expectedFileName: "formatter/formatter.go",
+		},
+	}
+
+	hook := NewContextHook()
+
+	for _, testCase := range testCases {
+		parsedString := hook.parseSrc(testCase.filePath)
+		assert.Equal(t, testCase.expectedFileName, parsedString, "Parsed filepath does not match expected for %s", testCase.filePath)
+	}
+
+}

formatter/set.go

@@ -0,0 +1,10 @@
+package formatter
+
+import "github.com/sirupsen/logrus"
+
+// SetTextFormatter set the formatter for given logger.
+func SetTextFormatter(logger *logrus.Logger) {
+	logger.Formatter = NewTextFormatter()
+	logger.ReportCaller = true
+	logger.AddHook(NewContextHook())
+}

util/log.go

@@ -1,14 +1,13 @@
 package util
 
 import (
+	"io"
+	"path/filepath"
+
 	log "github.com/sirupsen/logrus"
 	"gopkg.in/natefinch/lumberjack.v2"
-	"io"
+
-	"path"
+	"github.com/netbirdio/netbird/formatter"
-	"path/filepath"
-	"runtime"
-	"strconv"
-	"time"
 )
 
 // InitLog parses and sets log-level input
@@ -31,21 +30,7 @@ func InitLog(logLevel string, logPath string) error {
 		log.SetOutput(io.Writer(lumberjackLogger))
 	}
 
-	logFormatter := new(log.TextFormatter)
+	formatter.SetTextFormatter(log.StandardLogger())
-	logFormatter.TimestampFormat = time.RFC3339 // or RFC3339
-	logFormatter.FullTimestamp = true
-	logFormatter.CallerPrettyfier = func(frame *runtime.Frame) (function string, file string) {
-		fileName := path.Base(frame.File) + ":" + strconv.Itoa(frame.Line)
-		//return frame.Function, fileName
-		return "", fileName
-	}
-
-	if level > log.WarnLevel {
-		log.SetReportCaller(true)
-	}
-
-	log.SetFormatter(logFormatter)
 	log.SetLevel(level)
-
 	return nil
 }