From 1ae9785f9b8625683432d8e47ba66d5759ccde5b Mon Sep 17 00:00:00 2001 From: James Rasell Date: Thu, 16 Jan 2025 08:23:08 +0100 Subject: [PATCH] agent: Fix a bug where all syslog lines are notice when using JSON (#24865) The agent syslog write handler was unable to handle JSON log lines correctly, meaning all syslog entries when using JSON log format showed as NOTICE level. This change adds a new handler to the Nomad agent which can parse JSON log lines and correctly understand the expected log level entry. The change also removes the use of a filter from the default log format handler. This is not needed as the logs are fed into the syslog handler via hclog, which is responsible for level filtering. --- .changelog/24865.txt | 3 + command/agent/command.go | 2 +- command/agent/syslog.go | 70 +++++++++++-- command/agent/syslog_test.go | 187 ++++++++++++++++++++++++++++++++--- 4 files changed, 235 insertions(+), 27 deletions(-) create mode 100644 .changelog/24865.txt diff --git a/.changelog/24865.txt b/.changelog/24865.txt new file mode 100644 index 000000000..b0568b05d --- /dev/null +++ b/.changelog/24865.txt @@ -0,0 +1,3 @@ +```release-note:bug +agent: Fixed a bug where all syslog entries were marked as notice when using JSON logging format +``` diff --git a/command/agent/command.go b/command/agent/command.go index 8077b4ea8..28dd0ebd3 100644 --- a/command/agent/command.go +++ b/command/agent/command.go @@ -585,7 +585,7 @@ func SetupLoggers(ui cli.Ui, config *Config) (*logutils.LevelFilter, *gatedwrite ui.Error(fmt.Sprintf("Syslog setup failed: %v", err)) return nil, nil, nil } - writers = append(writers, &SyslogWrapper{l, logFilter}) + writers = append(writers, newSyslogWriter(l, config.LogJson)) } // Check if file logging is enabled diff --git a/command/agent/syslog.go b/command/agent/syslog.go index 81900dca7..7f2c28ab4 100644 --- a/command/agent/syslog.go +++ b/command/agent/syslog.go @@ -5,9 +5,11 @@ package agent import ( "bytes" + "io" + "regexp" + "strings" gsyslog "github.com/hashicorp/go-syslog" - "github.com/hashicorp/logutils" ) // levelPriority is used to map a log level to a syslog priority level. The @@ -32,20 +34,28 @@ func getSysLogPriority(level string) gsyslog.Priority { return priority } +// newSyslogWriter generates a new syslog wrapper depending on whether the +// agent is logging in JSON format. +func newSyslogWriter(sysLogger gsyslog.Syslogger, json bool) io.Writer { + if json { + return &syslogJSONWrapper{logger: sysLogger} + } else { + return &syslogWrapper{l: sysLogger} + } +} + // SyslogWrapper is used to cleanup log messages before // writing them to a Syslogger. Implements the io.Writer // interface. -type SyslogWrapper struct { - l gsyslog.Syslogger - filt *logutils.LevelFilter +type syslogWrapper struct { + l gsyslog.Syslogger } -// Write is used to implement io.Writer -func (s *SyslogWrapper) Write(p []byte) (int, error) { - // Skip syslog if the log level doesn't apply - if !s.filt.Check(p) { - return 0, nil - } +// Write is used to implement io.Writer. +// +// Nomad's syslog is fed by go-hclog which is responsible for performing the +// log level filtering. It is not needed here. +func (s *syslogWrapper) Write(p []byte) (int, error) { // Extract log level var level string @@ -63,3 +73,43 @@ func (s *SyslogWrapper) Write(p []byte) (int, error) { err := s.l.WriteLevel(getSysLogPriority(level), afterLevel) return len(p), err } + +var ( + // jsonLogLineLevelRegex is used to find the log level key/value entry + // within a JSON log line. It will match string entries such as + // `"@level":"debug",`, so we can pull these out for syslog capabilities. + jsonLogLineLevelRegex = regexp.MustCompile(`"@level":"\w+",`) +) + +// syslogJSONWrapper is a syslog writer for Nomad logs when the operator has +// enabled the JSON logging format. +type syslogJSONWrapper struct { + logger gsyslog.Syslogger +} + +// Write is used to implement io.Writer. It dissects the passed JSON log line, +// identifying the log level and removing the contextual entry, before +// performing the syslog write. +// +// Nomad's syslog is fed by go-hclog which is responsible for performing the +// log level filtering. It is not needed here. +func (s *syslogJSONWrapper) Write(logBytes []byte) (int, error) { + + // Find the start and finish index of the regex match, so we know where in + // the byte array the level contextual entry is. + indexes := jsonLogLineLevelRegex.FindAllIndex(logBytes, 1) + + // If the indexes are not what we expected, write the log line with the + // notice level. It's better to have a log line at the incorrect level + // than have a log line saying we couldn't write a log line. + if len(indexes) != 1 || len(indexes[0]) != 2 { + return len(logBytes), s.logger.WriteLevel(gsyslog.LOG_NOTICE, logBytes) + } + + // Pull the log level from the message using the identified indexes and + // knowledge of the JSON formatting from go-hclog. + level := strings.ToTitle(string(logBytes[indexes[0][0]+10 : indexes[0][1]-2])) + + // Attempt to write using the converted syslog priority. + return len(logBytes), s.logger.WriteLevel(getSysLogPriority(level), logBytes) +} diff --git a/command/agent/syslog_test.go b/command/agent/syslog_test.go index ae63e6328..37345bc17 100644 --- a/command/agent/syslog_test.go +++ b/command/agent/syslog_test.go @@ -64,26 +64,181 @@ func Test_getSysLogPriority(t *testing.T) { } } -func TestSyslogFilter(t *testing.T) { +func Test_newSyslogWriter(t *testing.T) { ci.Parallel(t) + if runtime.GOOS == "windows" { t.Skip("Syslog not supported on Windows") } - l, err := gsyslog.NewLogger(gsyslog.LOG_NOTICE, "LOCAL0", "nomad") - must.NoError(t, err) + // Test the non-json syslog write handler generation. + expectedSyslogWriter := newSyslogWriter(nil, false) + _, ok := expectedSyslogWriter.(*syslogWrapper) + must.True(t, ok) - filt := LevelFilter() - filt.MinLevel = "INFO" - - s := &SyslogWrapper{l, filt} - n, err := s.Write([]byte("[INFO] test")) - if err != nil { - t.Fatalf("err: %s", err) - } - must.NonZero(t, n) - - n, err = s.Write([]byte("[DEBUG] test")) - must.NoError(t, err) - must.Zero(t, n) + // Test the json syslog write handler generation. + expectedJSONSyslogWriter := newSyslogWriter(nil, true) + _, ok = expectedJSONSyslogWriter.(*syslogJSONWrapper) + must.True(t, ok) } + +func Test_syslogWrapper(t *testing.T) { + ci.Parallel(t) + + if runtime.GOOS == "windows" { + t.Skip("Syslog not supported on Windows") + } + + testCases := []struct { + name string + inputLogLine string + expectedWrittenLogLine string + expectedBytesWritten int + expectedPriority gsyslog.Priority + }{ + { + name: "trace", + inputLogLine: `2025-01-14T09:29:56.747Z [TRACE] agent: i am a trace message`, + expectedWrittenLogLine: `agent: i am a trace message`, + expectedBytesWritten: 60, + expectedPriority: gsyslog.LOG_DEBUG, + }, + { + name: "debug", + inputLogLine: `2025-01-14T09:29:56.747Z [DEBUG] agent: i am a debug message`, + expectedWrittenLogLine: `agent: i am a debug message`, + expectedBytesWritten: 60, + expectedPriority: gsyslog.LOG_INFO, + }, + { + name: "info", + inputLogLine: `2025-01-14T09:29:56.747Z [INFO] agent: i am an info message`, + expectedWrittenLogLine: `agent: i am an info message`, + expectedBytesWritten: 59, + expectedPriority: gsyslog.LOG_NOTICE, + }, + { + name: "warn", + inputLogLine: `2025-01-14T09:29:56.747Z [WARN] agent: i am a warn message`, + expectedWrittenLogLine: `agent: i am a warn message`, + expectedBytesWritten: 58, + expectedPriority: gsyslog.LOG_WARNING, + }, + { + name: "error", + inputLogLine: `2025-01-14T09:29:56.747Z [ERROR] agent: i am an error message`, + expectedWrittenLogLine: `agent: i am an error message`, + expectedBytesWritten: 61, + expectedPriority: gsyslog.LOG_ERR, + }, + { + name: "no level", + inputLogLine: `2025-01-14T09:29:56.747Z agent: i am a message without a level`, + expectedWrittenLogLine: `2025-01-14T09:29:56.747Z agent: i am a message without a level`, + expectedBytesWritten: 62, + expectedPriority: gsyslog.LOG_NOTICE, + }, + } + + // Generate our test backend, so we can easily read written log messages + // back out. + testSyslogBackend := testSysLogger{} + syslogWriter := newSyslogWriter(&testSyslogBackend, false) + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + bytesWritten, err := syslogWriter.Write([]byte(tc.inputLogLine)) + must.NoError(t, err) + must.Eq(t, tc.expectedBytesWritten, bytesWritten) + must.Eq(t, tc.expectedWrittenLogLine, testSyslogBackend.msg) + must.Eq(t, tc.expectedPriority, testSyslogBackend.pri) + }) + } +} + +func Test_syslogJSONWrapper(t *testing.T) { + ci.Parallel(t) + + if runtime.GOOS == "windows" { + t.Skip("Syslog not supported on Windows") + } + + testCases := []struct { + name string + inputLogLine string + expectedBytesWritten int + expectedPriority gsyslog.Priority + }{ + { + name: "trace", + inputLogLine: `{"@level":"trace","@message":"i am a trace message","@module":"agent","@timestamp":"2025-01-14T08:54:26.245072Z"}`, + expectedBytesWritten: 113, + expectedPriority: gsyslog.LOG_DEBUG, + }, + { + name: "debug", + inputLogLine: `{"@level":"debug","@message":"i am a debug message","@module":"agent","@timestamp":"2025-01-14T08:54:26.245072Z"}`, + expectedBytesWritten: 113, + expectedPriority: gsyslog.LOG_INFO, + }, + { + name: "info", + inputLogLine: `{"@level":"info","@message":"i am an info message","@module":"agent","@timestamp":"2025-01-14T08:54:26.245072Z"}`, + expectedBytesWritten: 112, + expectedPriority: gsyslog.LOG_NOTICE, + }, + { + name: "warn", + inputLogLine: `{"@level":"warn","@message":"i am a warn message","@module":"agent","@timestamp":"2025-01-14T08:54:26.245072Z"}`, + expectedBytesWritten: 111, + expectedPriority: gsyslog.LOG_WARNING, + }, + { + name: "error", + inputLogLine: `{"@level":"error","@message":"i am an error message","@module":"agent","@timestamp":"2025-01-14T08:54:26.245072Z"}`, + expectedBytesWritten: 114, + expectedPriority: gsyslog.LOG_ERR, + }, + { + name: "no level", + inputLogLine: `{"@message":"i am a message without a level","@module":"agent","@timestamp":"2025-01-14T08:54:26.245072Z"}`, + expectedBytesWritten: 106, + expectedPriority: gsyslog.LOG_NOTICE, + }, + } + + // Generate our test backend, so we can easily read written log messages + // back out. + testSyslogBackend := testSysLogger{} + syslogWriter := newSyslogWriter(&testSyslogBackend, true) + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + bytesWritten, err := syslogWriter.Write([]byte(tc.inputLogLine)) + must.NoError(t, err) + must.Eq(t, tc.expectedBytesWritten, bytesWritten) + must.Eq(t, tc.inputLogLine, testSyslogBackend.msg) + must.Eq(t, tc.expectedPriority, testSyslogBackend.pri) + }) + } +} + +// testSysLogger implements the gsyslog.Syslogger interface. It allows the +// tests to check written log lines. +type testSysLogger struct { + msg string + pri gsyslog.Priority +} + +func (t *testSysLogger) WriteLevel(pri gsyslog.Priority, log []byte) error { + _, err := t.Write(log) + t.pri = pri + return err +} + +func (t *testSysLogger) Write(log []byte) (int, error) { + t.msg = string(log) + return len(log), nil +} + +func (t *testSysLogger) Close() error { return nil }