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

@@ -0,0 +1,3 @@
+```release-note:bug
+agent: Fixed a bug where all syslog entries were marked as notice when using JSON logging format
+```

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

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

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 }