Print out the goroutine id (#3433)

The TXT logger prints out the actual go routine ID

This feature depends on 'loggoroutine' build tag

```go build -tags loggoroutine```
This commit is contained in:
Zoltan Papp 2025-03-07 14:06:47 +01:00 committed by GitHub
parent 4b76d93cec
commit 53b9a2002f
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
22 changed files with 236 additions and 131 deletions

View File

@ -1,83 +0,0 @@
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
}
// SyslogFormatter formats logs into text
type SyslogFormatter struct {
levelDesc []string
}
var validLevelDesc = []string{"PANC", "FATL", "ERRO", "WARN", "INFO", "DEBG", "TRAC"}
// NewTextFormatter create new MyTextFormatter instance
func NewTextFormatter() *TextFormatter {
return &TextFormatter{
levelDesc: validLevelDesc,
timestampFormat: time.RFC3339, // or RFC3339
}
}
// NewSyslogFormatter create new MySyslogFormatter instance
func NewSyslogFormatter() *SyslogFormatter {
return &SyslogFormatter{
levelDesc: validLevelDesc,
}
}
// 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]
}
// Format renders a single log entry
func (f *SyslogFormatter) 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, ", "))
}
return []byte(fmt.Sprintf("%s%s\n", fields, entry.Message)), nil
}

View File

@ -0,0 +1,9 @@
//go:build !loggoroutine
package hook
import log "github.com/sirupsen/logrus"
func additionalEntries(_ *log.Entry) {
// This function is empty and is used to demonstrate the use of additional hooks.
}

View File

@ -0,0 +1,12 @@
//go:build loggoroutine
package hook
import (
"github.com/petermattis/goid"
log "github.com/sirupsen/logrus"
)
func additionalEntries(entry *log.Entry) {
entry.Data[EntryKeyGoroutineID] = goid.Get()
}

View File

@ -1,4 +1,4 @@
package formatter package hook
import ( import (
"fmt" "fmt"
@ -41,7 +41,8 @@ func (hook ContextHook) Levels() []logrus.Level {
// Fire extend with the source information the entry.Data // Fire extend with the source information the entry.Data
func (hook ContextHook) Fire(entry *logrus.Entry) error { func (hook ContextHook) Fire(entry *logrus.Entry) error {
src := hook.parseSrc(entry.Caller.File) src := hook.parseSrc(entry.Caller.File)
entry.Data["source"] = fmt.Sprintf("%s:%v", src, entry.Caller.Line) entry.Data[EntryKeySource] = fmt.Sprintf("%s:%v", src, entry.Caller.Line)
additionalEntries(entry)
if entry.Context == nil { if entry.Context == nil {
return nil return nil

View File

@ -1,4 +1,4 @@
package formatter package hook
import ( import (
"testing" "testing"

6
formatter/hook/keys.go Normal file
View File

@ -0,0 +1,6 @@
package hook
const (
EntryKeySource = "source"
EntryKeyGoroutineID = "goroutine_id"
)

View File

@ -0,0 +1,3 @@
package levels
var ValidLevelDesc = []string{"PANC", "FATL", "ERRO", "WARN", "INFO", "DEBG", "TRAC"}

View File

@ -1,26 +1,28 @@
package formatter package logcat
import ( import (
"fmt" "fmt"
"strings" "strings"
"github.com/sirupsen/logrus" "github.com/sirupsen/logrus"
"github.com/netbirdio/netbird/formatter/levels"
) )
// LogcatFormatter formats logs into text what is fit for logcat // Formatter formats logs into text what is fit for logcat
type LogcatFormatter struct { type Formatter struct {
levelDesc []string levelDesc []string
} }
// NewLogcatFormatter create new LogcatFormatter instance // NewLogcatFormatter create new LogcatFormatter instance
func NewLogcatFormatter() *LogcatFormatter { func NewLogcatFormatter() *Formatter {
return &LogcatFormatter{ return &Formatter{
levelDesc: []string{"PANC", "FATL", "ERRO", "WARN", "INFO", "DEBG", "TRAC"}, levelDesc: levels.ValidLevelDesc,
} }
} }
// Format renders a single log entry // Format renders a single log entry
func (f *LogcatFormatter) Format(entry *logrus.Entry) ([]byte, error) { func (f *Formatter) Format(entry *logrus.Entry) ([]byte, error) {
var fields string var fields string
keys := make([]string, 0, len(entry.Data)) keys := make([]string, 0, len(entry.Data))
for k, v := range entry.Data { for k, v := range entry.Data {
@ -39,7 +41,7 @@ func (f *LogcatFormatter) Format(entry *logrus.Entry) ([]byte, error) {
return []byte(fmt.Sprintf("[%s] %s%s %s\n", level, fields, entry.Data["source"], entry.Message)), nil return []byte(fmt.Sprintf("[%s] %s%s %s\n", level, fields, entry.Data["source"], entry.Message)), nil
} }
func (f *LogcatFormatter) parseLevel(level logrus.Level) string { func (f *Formatter) parseLevel(level logrus.Level) string {
if len(f.levelDesc) < int(level) { if len(f.levelDesc) < int(level) {
return "" return ""
} }

View File

@ -1,4 +1,4 @@
package formatter package logcat
import ( import (
"testing" "testing"
@ -25,4 +25,5 @@ func TestLogcatMessageFormat(t *testing.T) {
if parsedString != expectedString && parsedString != expectedStringVariant { if parsedString != expectedString && parsedString != expectedStringVariant {
t.Errorf("The log messages don't match. Expected: '%s', got: '%s'", expectedString, parsedString) t.Errorf("The log messages don't match. Expected: '%s', got: '%s'", expectedString, parsedString)
} }
} }

View File

@ -2,31 +2,37 @@ package formatter
import ( import (
"github.com/sirupsen/logrus" "github.com/sirupsen/logrus"
"github.com/netbirdio/netbird/formatter/hook"
"github.com/netbirdio/netbird/formatter/logcat"
"github.com/netbirdio/netbird/formatter/syslog"
"github.com/netbirdio/netbird/formatter/txt"
) )
// SetTextFormatter set the text formatter for given logger. // SetTextFormatter set the text formatter for given logger.
func SetTextFormatter(logger *logrus.Logger) { func SetTextFormatter(logger *logrus.Logger) {
logger.Formatter = NewTextFormatter() logger.Formatter = txt.NewTextFormatter()
logger.ReportCaller = true logger.ReportCaller = true
logger.AddHook(NewContextHook()) logger.AddHook(hook.NewContextHook())
} }
// SetSyslogFormatter set the text formatter for given logger. // SetSyslogFormatter set the text formatter for given logger.
func SetSyslogFormatter(logger *logrus.Logger) { func SetSyslogFormatter(logger *logrus.Logger) {
logger.Formatter = NewSyslogFormatter() logger.Formatter = syslog.NewSyslogFormatter()
logger.ReportCaller = true logger.ReportCaller = true
logger.AddHook(NewContextHook()) logger.AddHook(hook.NewContextHook())
} }
// SetJSONFormatter set the JSON formatter for given logger. // SetJSONFormatter set the JSON formatter for given logger.
func SetJSONFormatter(logger *logrus.Logger) { func SetJSONFormatter(logger *logrus.Logger) {
logger.Formatter = &logrus.JSONFormatter{} logger.Formatter = &logrus.JSONFormatter{}
logger.ReportCaller = true logger.ReportCaller = true
logger.AddHook(NewContextHook()) logger.AddHook(hook.NewContextHook())
} }
// SetLogcatFormatter set the logcat formatter for given logger. // SetLogcatFormatter set the logcat formatter for given logger.
func SetLogcatFormatter(logger *logrus.Logger) { func SetLogcatFormatter(logger *logrus.Logger) {
logger.Formatter = NewLogcatFormatter() logger.Formatter = logcat.NewLogcatFormatter()
logger.ReportCaller = true logger.ReportCaller = true
logger.AddHook(NewContextHook()) logger.AddHook(hook.NewContextHook())
} }

View File

@ -0,0 +1,39 @@
package syslog
import (
"fmt"
"strings"
"github.com/sirupsen/logrus"
"github.com/netbirdio/netbird/formatter/levels"
)
// Formatter formats logs into text
type Formatter struct {
levelDesc []string
}
// NewSyslogFormatter create new MySyslogFormatter instance
func NewSyslogFormatter() *Formatter {
return &Formatter{
levelDesc: levels.ValidLevelDesc,
}
}
// Format renders a single log entry
func (f *Formatter) 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, ", "))
}
return []byte(fmt.Sprintf("%s%s\n", fields, entry.Message)), nil
}

View File

@ -0,0 +1,26 @@
package syslog
import (
"testing"
"time"
"github.com/sirupsen/logrus"
"github.com/stretchr/testify/assert"
)
func TestLogSyslogFormat(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 := NewSyslogFormatter()
result, _ := formatter.Format(someEntry)
parsedString := string(result)
expectedString := "^\\[(att1: 1, att2: 2|att2: 2, att1: 1)\\] Some Message\\s+$"
assert.Regexp(t, expectedString, parsedString)
}

31
formatter/txt/format.go Normal file
View File

@ -0,0 +1,31 @@
//go:build !loggoroutine
package txt
import (
"fmt"
"strings"
"github.com/sirupsen/logrus"
"github.com/netbirdio/netbird/formatter/hook"
)
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 == hook.EntryKeySource {
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[hook.EntryKeySource], entry.Message)), nil
}

View File

@ -0,0 +1,35 @@
//go:build loggoroutine
package txt
import (
"fmt"
"strings"
"github.com/sirupsen/logrus"
"github.com/netbirdio/netbird/formatter/hook"
)
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 == hook.EntryKeySource {
continue
}
if k == hook.EntryKeyGoroutineID {
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 %d %s%s: %s\n", entry.Time.Format(f.timestampFormat), level, entry.Data[hook.EntryKeyGoroutineID], fields, entry.Data[hook.EntryKeySource], entry.Message)), nil
}

View File

@ -0,0 +1,31 @@
package txt
import (
"time"
"github.com/sirupsen/logrus"
"github.com/netbirdio/netbird/formatter/levels"
)
// 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: levels.ValidLevelDesc,
timestampFormat: time.RFC3339, // or RFC3339
}
}
func (f *TextFormatter) parseLevel(level logrus.Level) string {
if len(f.levelDesc) < int(level) {
return ""
}
return f.levelDesc[level]
}

View File

@ -1,4 +1,4 @@
package formatter package txt
import ( import (
"testing" "testing"
@ -24,20 +24,3 @@ func TestLogTextFormat(t *testing.T) {
expectedString := "^2021-02-21T01:10:30Z WARN \\[(att1: 1, att2: 2|att2: 2, att1: 1)\\] some/fancy/path.go:46: Some Message\\s+$" expectedString := "^2021-02-21T01:10:30Z WARN \\[(att1: 1, att2: 2|att2: 2, att1: 1)\\] some/fancy/path.go:46: Some Message\\s+$"
assert.Regexp(t, expectedString, parsedString) assert.Regexp(t, expectedString, parsedString)
} }
func TestLogSyslogFormat(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 := NewSyslogFormatter()
result, _ := formatter.Format(someEntry)
parsedString := string(result)
expectedString := "^\\[(att1: 1, att2: 2|att2: 2, att1: 1)\\] Some Message\\s+$"
assert.Regexp(t, expectedString, parsedString)
}

1
go.mod
View File

@ -65,6 +65,7 @@ require (
github.com/okta/okta-sdk-golang/v2 v2.18.0 github.com/okta/okta-sdk-golang/v2 v2.18.0
github.com/oschwald/maxminddb-golang v1.12.0 github.com/oschwald/maxminddb-golang v1.12.0
github.com/patrickmn/go-cache v2.1.0+incompatible github.com/patrickmn/go-cache v2.1.0+incompatible
github.com/petermattis/goid v0.0.0-20250303134427-723919f7f203
github.com/pion/logging v0.2.2 github.com/pion/logging v0.2.2
github.com/pion/randutil v0.1.0 github.com/pion/randutil v0.1.0
github.com/pion/stun/v2 v2.0.0 github.com/pion/stun/v2 v2.0.0

2
go.sum
View File

@ -571,6 +571,8 @@ github.com/pelletier/go-toml v1.9.3/go.mod h1:u1nR/EPcESfeI/szUZKdtJ0xRNbUoANCko
github.com/pelletier/go-toml v1.9.5 h1:4yBQzkHv+7BHq2PQUZF3Mx0IYxG7LsP222s7Agd3ve8= github.com/pelletier/go-toml v1.9.5 h1:4yBQzkHv+7BHq2PQUZF3Mx0IYxG7LsP222s7Agd3ve8=
github.com/pelletier/go-toml/v2 v2.0.9 h1:uH2qQXheeefCCkuBBSLi7jCiSmj3VRh2+Goq2N7Xxu0= github.com/pelletier/go-toml/v2 v2.0.9 h1:uH2qQXheeefCCkuBBSLi7jCiSmj3VRh2+Goq2N7Xxu0=
github.com/pelletier/go-toml/v2 v2.0.9/go.mod h1:tJU2Z3ZkXwnxa4DPO899bsyIoywizdUvyaeZurnPPDc= github.com/pelletier/go-toml/v2 v2.0.9/go.mod h1:tJU2Z3ZkXwnxa4DPO899bsyIoywizdUvyaeZurnPPDc=
github.com/petermattis/goid v0.0.0-20250303134427-723919f7f203 h1:E7Kmf11E4K7B5hDti2K2NqPb1nlYlGYsu02S1JNd/Bs=
github.com/petermattis/goid v0.0.0-20250303134427-723919f7f203/go.mod h1:pxMtw7cyUw6B2bRH0ZBANSPg+AoSud1I1iyJHI69jH4=
github.com/pion/dtls/v2 v2.2.7/go.mod h1:8WiMkebSHFD0T+dIU+UeBaoV7kDhOW5oDCzZ7WZ/F9s= github.com/pion/dtls/v2 v2.2.7/go.mod h1:8WiMkebSHFD0T+dIU+UeBaoV7kDhOW5oDCzZ7WZ/F9s=
github.com/pion/dtls/v2 v2.2.10 h1:u2Axk+FyIR1VFTPurktB+1zoEPGIW3bmyj3LEFrXjAA= github.com/pion/dtls/v2 v2.2.10 h1:u2Axk+FyIR1VFTPurktB+1zoEPGIW3bmyj3LEFrXjAA=
github.com/pion/dtls/v2 v2.2.10/go.mod h1:d9SYc9fch0CqK90mRk1dC7AkzzpwJj6u2GU3u+9pqFE= github.com/pion/dtls/v2 v2.2.10/go.mod h1:d9SYc9fch0CqK90mRk1dC7AkzzpwJj6u2GU3u+9pqFE=

View File

@ -36,7 +36,7 @@ import (
"github.com/netbirdio/management-integrations/integrations" "github.com/netbirdio/management-integrations/integrations"
"github.com/netbirdio/netbird/encryption" "github.com/netbirdio/netbird/encryption"
"github.com/netbirdio/netbird/formatter" "github.com/netbirdio/netbird/formatter/hook"
mgmtProto "github.com/netbirdio/netbird/management/proto" mgmtProto "github.com/netbirdio/netbird/management/proto"
"github.com/netbirdio/netbird/management/server" "github.com/netbirdio/netbird/management/server"
"github.com/netbirdio/netbird/management/server/auth" "github.com/netbirdio/netbird/management/server/auth"
@ -90,7 +90,7 @@ var (
flag.Parse() flag.Parse()
//nolint //nolint
ctx := context.WithValue(cmd.Context(), formatter.ExecutionContextKey, formatter.SystemSource) ctx := context.WithValue(cmd.Context(), hook.ExecutionContextKey, hook.SystemSource)
err := util.InitLog(logLevel, logFile) err := util.InitLog(logLevel, logFile)
if err != nil { if err != nil {
@ -136,7 +136,7 @@ var (
ctx, cancel := context.WithCancel(cmd.Context()) ctx, cancel := context.WithCancel(cmd.Context())
defer cancel() defer cancel()
//nolint //nolint
ctx = context.WithValue(ctx, formatter.ExecutionContextKey, formatter.SystemSource) ctx = context.WithValue(ctx, hook.ExecutionContextKey, hook.SystemSource)
err := handleRebrand(cmd) err := handleRebrand(cmd)
if err != nil { if err != nil {
@ -374,7 +374,7 @@ func unaryInterceptor(
) (interface{}, error) { ) (interface{}, error) {
reqID := uuid.New().String() reqID := uuid.New().String()
//nolint //nolint
ctx = context.WithValue(ctx, formatter.ExecutionContextKey, formatter.GRPCSource) ctx = context.WithValue(ctx, hook.ExecutionContextKey, hook.GRPCSource)
//nolint //nolint
ctx = context.WithValue(ctx, nbContext.RequestIDKey, reqID) ctx = context.WithValue(ctx, nbContext.RequestIDKey, reqID)
return handler(ctx, req) return handler(ctx, req)
@ -389,7 +389,7 @@ func streamInterceptor(
reqID := uuid.New().String() reqID := uuid.New().String()
wrapped := grpcMiddleware.WrapServerStream(ss) wrapped := grpcMiddleware.WrapServerStream(ss)
//nolint //nolint
ctx := context.WithValue(ss.Context(), formatter.ExecutionContextKey, formatter.GRPCSource) ctx := context.WithValue(ss.Context(), hook.ExecutionContextKey, hook.GRPCSource)
//nolint //nolint
wrapped.WrappedContext = context.WithValue(ctx, nbContext.RequestIDKey, reqID) wrapped.WrappedContext = context.WithValue(ctx, nbContext.RequestIDKey, reqID)
return handler(srv, wrapped) return handler(srv, wrapped)

View File

@ -8,7 +8,7 @@ import (
log "github.com/sirupsen/logrus" log "github.com/sirupsen/logrus"
"github.com/spf13/cobra" "github.com/spf13/cobra"
"github.com/netbirdio/netbird/formatter" "github.com/netbirdio/netbird/formatter/hook"
"github.com/netbirdio/netbird/management/server/store" "github.com/netbirdio/netbird/management/server/store"
"github.com/netbirdio/netbird/util" "github.com/netbirdio/netbird/util"
) )
@ -30,7 +30,7 @@ var upCmd = &cobra.Command{
} }
//nolint //nolint
ctx := context.WithValue(cmd.Context(), formatter.ExecutionContextKey, formatter.SystemSource) ctx := context.WithValue(cmd.Context(), hook.ExecutionContextKey, hook.SystemSource)
if err := store.MigrateFileStoreToSqlite(ctx, mgmtDataDir); err != nil { if err := store.MigrateFileStoreToSqlite(ctx, mgmtDataDir); err != nil {
return err return err

View File

@ -20,7 +20,7 @@ import (
"google.golang.org/grpc/keepalive" "google.golang.org/grpc/keepalive"
"github.com/netbirdio/netbird/encryption" "github.com/netbirdio/netbird/encryption"
"github.com/netbirdio/netbird/formatter" "github.com/netbirdio/netbird/formatter/hook"
mgmtProto "github.com/netbirdio/netbird/management/proto" mgmtProto "github.com/netbirdio/netbird/management/proto"
"github.com/netbirdio/netbird/management/server/activity" "github.com/netbirdio/netbird/management/server/activity"
"github.com/netbirdio/netbird/management/server/settings" "github.com/netbirdio/netbird/management/server/settings"
@ -424,7 +424,7 @@ func startManagementForTest(t *testing.T, testFile string, config *Config) (*grp
peersUpdateManager := NewPeersUpdateManager(nil) peersUpdateManager := NewPeersUpdateManager(nil)
eventStore := &activity.InMemoryEventStore{} eventStore := &activity.InMemoryEventStore{}
ctx := context.WithValue(context.Background(), formatter.ExecutionContextKey, formatter.SystemSource) //nolint:staticcheck ctx := context.WithValue(context.Background(), hook.ExecutionContextKey, hook.SystemSource) //nolint:staticcheck
metrics, err := telemetry.NewDefaultAppMetrics(context.Background()) metrics, err := telemetry.NewDefaultAppMetrics(context.Background())
require.NoError(t, err) require.NoError(t, err)

View File

@ -13,7 +13,7 @@ import (
"go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/metric" "go.opentelemetry.io/otel/metric"
"github.com/netbirdio/netbird/formatter" "github.com/netbirdio/netbird/formatter/hook"
nbContext "github.com/netbirdio/netbird/management/server/context" nbContext "github.com/netbirdio/netbird/management/server/context"
) )
@ -167,7 +167,7 @@ func (m *HTTPMiddleware) Handler(h http.Handler) http.Handler {
reqStart := time.Now() reqStart := time.Now()
//nolint //nolint
ctx := context.WithValue(r.Context(), formatter.ExecutionContextKey, formatter.HTTPSource) ctx := context.WithValue(r.Context(), hook.ExecutionContextKey, hook.HTTPSource)
reqID := uuid.New().String() reqID := uuid.New().String()
//nolint //nolint