logging: Include error field in journald message, Fix key encoding of all fields for journaldCore

logging/error.go

@@ -0,0 +1,35 @@
+package logging
+
+import (
+	"github.com/pkg/errors"
+	"go.uber.org/zap"
+)
+
+// stackTracer is an interface used to identify errors that include a stack trace.
+// This interface specifically targets errors created using the github.com/pkg/errors library,
+// which can add stack traces to errors with functions like errors.Wrap().
+type stackTracer interface {
+	StackTrace() errors.StackTrace
+}
+
+// errNoStackTrace is a wrapper for errors that implements the error interface without exposing a stack trace.
+type errNoStackTrace struct {
+	e error
+}
+
+// Error returns the error message of the wrapped error.
+func (e errNoStackTrace) Error() string {
+	return e.e.Error()
+}
+
+// Error returns a zap.Field for logging the provided error.
+// This function checks if the error includes a stack trace from the pkg/errors library.
+// If a stack trace is present, it is suppressed in the log output because
+// logging a stack trace is not necessary. Otherwise, the error is logged normally.
+func Error(e error) zap.Field {
+	if _, ok := e.(stackTracer); ok {
+		return zap.Error(errNoStackTrace{e})
+	}
+
+	return zap.Error(e)
+}

logging/journald_core.go

@@ -1,14 +1,17 @@
 package logging
 
 import (
+	"fmt"
 	"github.com/icinga/icinga-go-library/strcase"
+	"github.com/icinga/icinga-go-library/utils"
 	"github.com/pkg/errors"
 	"github.com/ssgreg/journald"
 	"go.uber.org/zap/zapcore"
+	"strings"
 )
 
-// priorities maps zapcore.Level to journal.Priority.
-var priorities = map[zapcore.Level]journald.Priority{
+// journaldPriorities maps zapcore.Level to journal.Priority.
+var journaldPriorities = map[zapcore.Level]journald.Priority{
 	zapcore.DebugLevel:  journald.PriorityDebug,
 	zapcore.InfoLevel:   journald.PriorityInfo,
 	zapcore.WarnLevel:   journald.PriorityWarning,
@@ -18,6 +21,11 @@ var priorities = map[zapcore.Level]journald.Priority{
 	zapcore.DPanicLevel: journald.PriorityCrit,
 }
 
+// journaldVisibleFields is a set (map to struct{}) of field keys being logged within the message for journald.
+var journaldVisibleFields = map[string]struct{}{
+	"error": {},
+}
+
 // NewJournaldCore returns a zapcore.Core that sends log entries to systemd-journald and
 // uses the given identifier as a prefix for structured logging context that is sent as journal fields.
 func NewJournaldCore(identifier string, enab zapcore.LevelEnabler) zapcore.Core {
@@ -53,30 +61,35 @@ func (c *journaldCore) With(fields []zapcore.Field) zapcore.Core {
 }
 
 func (c *journaldCore) Write(ent zapcore.Entry, fields []zapcore.Field) error {
-	pri, ok := priorities[ent.Level]
+	pri, ok := journaldPriorities[ent.Level]
 	if !ok {
 		return errors.Errorf("unknown log level %q", ent.Level)
 	}
 
 	enc := zapcore.NewMapObjectEncoder()
-	// Ensure that all field keys are valid journald field keys. If in doubt, use encodeJournaldFieldKey.
 	c.addFields(enc, fields)
 	c.addFields(enc, c.context)
 	enc.Fields["SYSLOG_IDENTIFIER"] = c.identifier
 
-	message := ent.Message
+	// Re-encode keys before passing them to journald. Unfortunately, this cannot be done within addFields or at another
+	// earlier position since zapcore's Field.AddTo may create multiple entries, some with non-compliant names.
+	encFields := make(map[string]interface{})
+	for k, v := range enc.Fields {
+		encFields[encodeJournaldFieldKey(k)] = v
+	}
+
+	message := ent.Message + visibleFieldsMsg(journaldVisibleFields, append(fields, c.context...))
 	if ent.LoggerName != c.identifier {
 		message = ent.LoggerName + ": " + message
 	}
 
-	return journald.Send(message, pri, enc.Fields)
+	return journald.Send(message, pri, encFields)
 }
 
-// addFields adds all given fields to enc with an altered key, prefixed with the journaldCore.identifier and sanitized
-// via encodeJournaldFieldKey.
+// addFields adds all given fields to enc with an altered key, prefixed with the journaldCore.identifier.
 func (c *journaldCore) addFields(enc zapcore.ObjectEncoder, fields []zapcore.Field) {
 	for _, field := range fields {
-		field.Key = encodeJournaldFieldKey(c.identifier + "_" + field.Key)
+		field.Key = c.identifier + "_" + field.Key
 		field.AddTo(enc)
 	}
 }
@@ -124,3 +137,56 @@ func encodeJournaldFieldKey(key string) string {
 
 	return key
 }
+
+// visibleFieldsMsg creates a string to be appended to the log message including fields to be explicitly printed.
+//
+// When logging against journald, the zapcore.Fields are used as journald fields, resulting in not being shown in the
+// default journalctl output (short). While this is documented in our docs, missing error messages are usually confusing
+// for end users.
+//
+// This method takes an allow list (set, map of keys to empty struct) of key to be displayed - there is the global
+// variable journaldVisibleFields; parameter for testing - and a slice of zapcore.Fields, creating an output string of
+// the allowed fields prefixed by a whitespace separator. If there are no fields to be logged, the returned string is
+// empty. So the function output can be appended to the output message without further checks.
+func visibleFieldsMsg(visibleFieldKeys map[string]struct{}, fields []zapcore.Field) string {
+	if visibleFieldKeys == nil || fields == nil {
+		return ""
+	}
+
+	enc := zapcore.NewMapObjectEncoder()
+
+	for _, field := range fields {
+		if _, shouldLog := visibleFieldKeys[field.Key]; shouldLog {
+			field.AddTo(enc)
+		}
+	}
+
+	// The internal zapcore.encodeError function[^0] can result in multiple fields. For example, an error type
+	// implementing fmt.Formatter results in another "errorVerbose" field, containing the stack trace if the error was
+	// created by github.com/pkg/errors including a stack[^1]. So the keys are checked again in the following loop.
+	//
+	// [^0]: https://github.com/uber-go/zap/blob/v1.27.0/zapcore/error.go#L47
+	// [^1]: https://pkg.go.dev/github.com/pkg/[email protected]#WithStack
+	visibleFields := make([]string, 0, len(visibleFieldKeys))
+	for k, v := range utils.IterateOrderedMap(enc.Fields) {
+		if _, shouldLog := visibleFieldKeys[k]; !shouldLog {
+			continue
+		}
+
+		var encodedField string
+		switch v.(type) {
+		case string, []byte, error:
+			encodedField = fmt.Sprintf("%s=%q", k, v)
+		default:
+			encodedField = fmt.Sprintf(`%s="%v"`, k, v)
+		}
+
+		visibleFields = append(visibleFields, encodedField)
+	}
+
+	if len(visibleFields) == 0 {
+		return ""
+	}
+
+	return "\t" + strings.Join(visibleFields, ", ")
+}

logging/journald_core_test.go

@@ -1,7 +1,11 @@
 package logging
 
 import (
+	"fmt"
+	"github.com/pkg/errors"
 	"github.com/stretchr/testify/require"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 	"regexp"
 	"testing"
 )
@@ -39,3 +43,111 @@ func Test_journaldFieldEncode(t *testing.T) {
 		})
 	}
 }
+
+// testingStackError is an error mimicking the stack behavior from github.com/pkg/errors in a deterministic way.
+type testingStackError string
+
+func (err testingStackError) Error() string {
+	return string(err)
+}
+
+func (err testingStackError) Format(s fmt.State, verb rune) {
+	if verb == 'v' && s.Flag('+') {
+		_, _ = fmt.Fprintf(s, "%s: look, I am a stack trace", string(err))
+	} else {
+		_, _ = fmt.Fprintf(s, "%s", string(err))
+	}
+}
+
+func Test_visibleFieldsMsg(t *testing.T) {
+	tests := []struct {
+		name             string
+		visibleFieldKeys map[string]struct{}
+		fields           []zapcore.Field
+		output           string
+	}{
+		{
+			name:             "empty-all-nil",
+			visibleFieldKeys: nil,
+			fields:           nil,
+			output:           "",
+		},
+		{
+			name:             "empty-all",
+			visibleFieldKeys: map[string]struct{}{},
+			fields:           nil,
+			output:           "",
+		},
+		{
+			name:             "empty-visibleFiledKeys",
+			visibleFieldKeys: map[string]struct{}{},
+			fields:           []zapcore.Field{zap.String("foo", "bar")},
+			output:           "",
+		},
+		{
+			name:             "no-field-match",
+			visibleFieldKeys: map[string]struct{}{"bar": {}},
+			fields:           []zapcore.Field{zap.String("foo", "bar")},
+			output:           "",
+		},
+		{
+			name:             "expected-string",
+			visibleFieldKeys: map[string]struct{}{"foo": {}},
+			fields:           []zapcore.Field{zap.String("foo", "bar")},
+			output:           "\t" + `foo="bar"`,
+		},
+		{
+			name:             "expected-multiple-strings-with-excluded",
+			visibleFieldKeys: map[string]struct{}{"foo": {}, "bar": {}},
+			fields: []zapcore.Field{
+				zap.String("foo", "bar"),
+				zap.String("bar", "baz"),
+				zap.String("baz", "qux"), // not in allow list
+			},
+			output: "\t" + `bar="baz", foo="bar"`,
+		},
+		{
+			name:             "expected-error-simple",
+			visibleFieldKeys: map[string]struct{}{"error": {}},
+			fields:           []zapcore.Field{zap.Error(fmt.Errorf("oops"))},
+			output:           "\t" + `error="oops"`,
+		},
+		{
+			name:             "expected-error-without-stack",
+			visibleFieldKeys: map[string]struct{}{"error": {}},
+			fields:           []zapcore.Field{zap.Error(errors.WithStack(fmt.Errorf("oops")))},
+			output:           "\t" + `error="oops"`,
+		},
+		{
+			name:             "expected-error-with-stack",
+			visibleFieldKeys: map[string]struct{}{"error": {}, "errorVerbose": {}},
+			fields:           []zapcore.Field{zap.Error(testingStackError("oops"))},
+			output:           "\t" + `error="oops", errorVerbose="oops: look, I am a stack trace"`,
+		},
+		{
+			name: "expected-multiple-basic-types",
+			visibleFieldKeys: map[string]struct{}{
+				"bool":        {},
+				"byte-string": {},
+				"complex":     {},
+				"float":       {},
+				"int":         {},
+			},
+			fields: []zapcore.Field{
+				zap.Bool("bool", true),
+				zap.ByteString("byte-string", []byte{0xC0, 0xFF, 0xEE}),
+				zap.Complex64("complex", -1i),
+				zap.Float64("float", 1.0/3.0),
+				zap.Int("int", 42),
+			},
+			output: "\t" + `bool="true", byte-string="\xc0\xff\xee", complex="(0-1i)", float="0.3333333333333333", int="42"`,
+		},
+	}
+
+	for _, test := range tests {
+		t.Run(test.name, func(t *testing.T) {
+			out := visibleFieldsMsg(test.visibleFieldKeys, test.fields)
+			require.Equal(t, test.output, out)
+		})
+	}
+}