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(<nil>): 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(<nil>): 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(<nil>): 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(<nil>): 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(<nil>): 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]
```
This commit is contained in:
Jakub Kołodziejczak 2024-08-01 18:22:02 +02:00 committed by GitHub
parent df8b8db068
commit 24e031ab74
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
5 changed files with 68 additions and 2 deletions

8
.editorconfig Normal file
View File

@ -0,0 +1,8 @@
root = true
[*]
end_of_line = lf
insert_final_newline = true
[*.go]
indent_style = tab

View File

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

View File

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

View File

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

View File

@ -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())
}