From 24e031ab74112e7dc8fb6733ed1fc38517545794 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jakub=20Ko=C5=82odziejczak?= <31549762+mrl5@users.noreply.github.com> Date: Thu, 1 Aug 2024 18:22:02 +0200 Subject: [PATCH] Fix syslog output containing duplicated timestamps (#2292) ```console journalctl ``` ```diff - Jul 19 14:41:01 rpi /usr/bin/netbird[614]: 2024-07-19T14:41:01+02:00 ERRO %!s(): error while handling message of Peer [key: REDACTED] error: [wrongly addressed message REDACTED] - Jul 19 21:53:03 rpi /usr/bin/netbird[614]: 2024-07-19T21:53:03+02:00 WARN %!s(): disconnected from the Signal service but will retry silently. Reason: rpc error: code = Internal desc = server closed the stream without sending trailers - Jul 19 21:53:04 rpi /usr/bin/netbird[614]: 2024-07-19T21:53:04+02:00 INFO %!s(): connected to the Signal Service stream - Jul 19 22:24:10 rpi /usr/bin/netbird[614]: 2024-07-19T22:24:10+02:00 WARN [error: read udp 192.168.1.11:48398->9.9.9.9:53: i/o timeout, upstream: 9.9.9.9:53] %!s(): got an error while connecting to upstream + Jul 19 14:41:01 rpi /usr/bin/netbird[614]: error while handling message of Peer [key: REDACTED] error: [wrongly addressed message REDACTED] + Jul 19 21:53:03 rpi /usr/bin/netbird[614]: disconnected from the Signal service but will retry silently. Reason: rpc error: code = Internal desc = server closed the stream without sending trailers + Jul 19 21:53:04 rpi /usr/bin/netbird[614]: connected to the Signal Service stream + Jul 19 22:24:10 rpi /usr/bin/netbird[614]: [error: read udp 192.168.1.11:48398->9.9.9.9:53: i/o timeout, upstream: 9.9.9.9:53] got an error while connecting to upstream ``` please notice that although log level is no longer present in the syslog message it is still respected by syslog logger, so the log levels are not lost: ```console journalctl -p 3 ``` ```diff - Jul 19 14:41:01 rpi /usr/bin/netbird[614]: 2024-07-19T14:41:01+02:00 ERRO %!s(): error while handling message of Peer [key: REDACTED] error: [wrongly addressed message REDACTED] + Jul 19 14:41:01 rpi /usr/bin/netbird[614]: error while handling message of Peer [key: REDACTED] error: [wrongly addressed message REDACTED] ``` --- .editorconfig | 8 ++++++++ formatter/formatter.go | 34 +++++++++++++++++++++++++++++++++- formatter/formatter_test.go | 19 ++++++++++++++++++- formatter/set.go | 6 ++++++ util/log.go | 3 +++ 5 files changed, 68 insertions(+), 2 deletions(-) create mode 100644 .editorconfig diff --git a/.editorconfig b/.editorconfig new file mode 100644 index 000000000..3dcb869d2 --- /dev/null +++ b/.editorconfig @@ -0,0 +1,8 @@ +root = true + +[*] +end_of_line = lf +insert_final_newline = true + +[*.go] +indent_style = tab diff --git a/formatter/formatter.go b/formatter/formatter.go index a37c67914..74de38603 100644 --- a/formatter/formatter.go +++ b/formatter/formatter.go @@ -14,14 +14,29 @@ type TextFormatter struct { 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: []string{"PANC", "FATL", "ERRO", "WARN", "INFO", "DEBG", "TRAC"}, + 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 @@ -49,3 +64,20 @@ func (f *TextFormatter) parseLevel(level logrus.Level) string { 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 +} diff --git a/formatter/formatter_test.go b/formatter/formatter_test.go index 54bc8a756..1ed207958 100644 --- a/formatter/formatter_test.go +++ b/formatter/formatter_test.go @@ -8,7 +8,7 @@ import ( "github.com/stretchr/testify/assert" ) -func TestLogMessageFormat(t *testing.T) { +func TestLogTextFormat(t *testing.T) { someEntry := &logrus.Entry{ Data: logrus.Fields{"att1": 1, "att2": 2, "source": "some/fancy/path.go:46"}, @@ -24,3 +24,20 @@ func TestLogMessageFormat(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+$" 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) +} diff --git a/formatter/set.go b/formatter/set.go index f9ccef601..9dfea5a7f 100644 --- a/formatter/set.go +++ b/formatter/set.go @@ -10,6 +10,12 @@ func SetTextFormatter(logger *logrus.Logger) { logger.ReportCaller = true logger.AddHook(NewContextHook()) } +// SetSyslogFormatter set the text formatter for given logger. +func SetSyslogFormatter(logger *logrus.Logger) { + logger.Formatter = NewSyslogFormatter() + logger.ReportCaller = true + logger.AddHook(NewContextHook()) +} // SetJSONFormatter set the JSON formatter for given logger. func SetJSONFormatter(logger *logrus.Logger) { diff --git a/util/log.go b/util/log.go index 74b99311e..4bce75e4a 100644 --- a/util/log.go +++ b/util/log.go @@ -35,8 +35,11 @@ func InitLog(logLevel string, logPath string) error { AddSyslogHook() } + //nolint:gocritic if os.Getenv("NB_LOG_FORMAT") == "json" { formatter.SetJSONFormatter(log.StandardLogger()) + } else if logPath == "syslog" { + formatter.SetSyslogFormatter(log.StandardLogger()) } else { formatter.SetTextFormatter(log.StandardLogger()) }