Skip to content

Commit 33bda3e

Browse files
oxzioxzi
authored
Merge pull request #126 from Icinga/logging-journald-include-error-field
logging: Include error field in journald message, Fix key encoding of all fields for journaldCore
2 parents 0b95298 + ca887af commit 33bda3e

File tree

3 files changed

+222
-9
lines changed

3 files changed

+222
-9
lines changed

‎logging/error.go‎

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,35 @@
1+
package logging
2+
3+
import (
4+
"github.com/pkg/errors"
5+
"go.uber.org/zap"
6+
)
7+
8+
// stackTracer is an interface used to identify errors that include a stack trace.
9+
// This interface specifically targets errors created using the github.com/pkg/errors library,
10+
// which can add stack traces to errors with functions like errors.Wrap().
11+
type stackTracer interface {
12+
StackTrace() errors.StackTrace
13+
}
14+
15+
// errNoStackTrace is a wrapper for errors that implements the error interface without exposing a stack trace.
16+
type errNoStackTrace struct {
17+
e error
18+
}
19+
20+
// Error returns the error message of the wrapped error.
21+
func (e errNoStackTrace) Error() string {
22+
return e.e.Error()
23+
}
24+
25+
// Error returns a zap.Field for logging the provided error.
26+
// This function checks if the error includes a stack trace from the pkg/errors library.
27+
// If a stack trace is present, it is suppressed in the log output because
28+
// logging a stack trace is not necessary. Otherwise, the error is logged normally.
29+
func Error(e error) zap.Field {
30+
if _, ok := e.(stackTracer); ok {
31+
return zap.Error(errNoStackTrace{e})
32+
}
33+
34+
return zap.Error(e)
35+
}

‎logging/journald_core.go‎

Lines changed: 75 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1,14 +1,17 @@
11
package logging
22

33
import (
4+
"fmt"
45
"github.com/icinga/icinga-go-library/strcase"
6+
"github.com/icinga/icinga-go-library/utils"
57
"github.com/pkg/errors"
68
"github.com/ssgreg/journald"
79
"go.uber.org/zap/zapcore"
10+
"strings"
811
)
912

10-
// priorities maps zapcore.Level to journal.Priority.
11-
var priorities = map[zapcore.Level]journald.Priority{
13+
// journaldPriorities maps zapcore.Level to journal.Priority.
14+
var journaldPriorities = map[zapcore.Level]journald.Priority{
1215
zapcore.DebugLevel: journald.PriorityDebug,
1316
zapcore.InfoLevel: journald.PriorityInfo,
1417
zapcore.WarnLevel: journald.PriorityWarning,
@@ -18,6 +21,11 @@ var priorities = map[zapcore.Level]journald.Priority{
1821
zapcore.DPanicLevel: journald.PriorityCrit,
1922
}
2023

24+
// journaldVisibleFields is a set (map to struct{}) of field keys being logged within the message for journald.
25+
var journaldVisibleFields = map[string]struct{}{
26+
"error": {},
27+
}
28+
2129
// NewJournaldCore returns a zapcore.Core that sends log entries to systemd-journald and
2230
// uses the given identifier as a prefix for structured logging context that is sent as journal fields.
2331
func NewJournaldCore(identifier string, enab zapcore.LevelEnabler) zapcore.Core {
@@ -53,30 +61,35 @@ func (c *journaldCore) With(fields []zapcore.Field) zapcore.Core {
5361
}
5462

5563
func (c *journaldCore) Write(ent zapcore.Entry, fields []zapcore.Field) error {
56-
pri, ok := priorities[ent.Level]
64+
pri, ok := journaldPriorities[ent.Level]
5765
if !ok {
5866
return errors.Errorf("unknown log level %q", ent.Level)
5967
}
6068

6169
enc := zapcore.NewMapObjectEncoder()
62-
// Ensure that all field keys are valid journald field keys. If in doubt, use encodeJournaldFieldKey.
6370
c.addFields(enc, fields)
6471
c.addFields(enc, c.context)
6572
enc.Fields["SYSLOG_IDENTIFIER"] = c.identifier
6673

67-
message := ent.Message
74+
// Re-encode keys before passing them to journald. Unfortunately, this cannot be done within addFields or at another
75+
// earlier position since zapcore's Field.AddTo may create multiple entries, some with non-compliant names.
76+
encFields := make(map[string]interface{})
77+
for k, v := range enc.Fields {
78+
encFields[encodeJournaldFieldKey(k)] = v
79+
}
80+
81+
message := ent.Message + visibleFieldsMsg(journaldVisibleFields, append(fields, c.context...))
6882
if ent.LoggerName != c.identifier {
6983
message = ent.LoggerName + ": " + message
7084
}
7185

72-
return journald.Send(message, pri, enc.Fields)
86+
return journald.Send(message, pri, encFields)
7387
}
7488

75-
// addFields adds all given fields to enc with an altered key, prefixed with the journaldCore.identifier and sanitized
76-
// via encodeJournaldFieldKey.
89+
// addFields adds all given fields to enc with an altered key, prefixed with the journaldCore.identifier.
7790
func (c *journaldCore) addFields(enc zapcore.ObjectEncoder, fields []zapcore.Field) {
7891
for _, field := range fields {
79-
field.Key = encodeJournaldFieldKey(c.identifier + "_" + field.Key)
92+
field.Key = c.identifier + "_" + field.Key
8093
field.AddTo(enc)
8194
}
8295
}
@@ -124,3 +137,56 @@ func encodeJournaldFieldKey(key string) string {
124137

125138
return key
126139
}
140+
141+
// visibleFieldsMsg creates a string to be appended to the log message including fields to be explicitly printed.
142+
//
143+
// When logging against journald, the zapcore.Fields are used as journald fields, resulting in not being shown in the
144+
// default journalctl output (short). While this is documented in our docs, missing error messages are usually confusing
145+
// for end users.
146+
//
147+
// This method takes an allow list (set, map of keys to empty struct) of key to be displayed - there is the global
148+
// variable journaldVisibleFields; parameter for testing - and a slice of zapcore.Fields, creating an output string of
149+
// the allowed fields prefixed by a whitespace separator. If there are no fields to be logged, the returned string is
150+
// empty. So the function output can be appended to the output message without further checks.
151+
func visibleFieldsMsg(visibleFieldKeys map[string]struct{}, fields []zapcore.Field) string {
152+
if visibleFieldKeys == nil || fields == nil {
153+
return ""
154+
}
155+
156+
enc := zapcore.NewMapObjectEncoder()
157+
158+
for _, field := range fields {
159+
if _, shouldLog := visibleFieldKeys[field.Key]; shouldLog {
160+
field.AddTo(enc)
161+
}
162+
}
163+
164+
// The internal zapcore.encodeError function[^0] can result in multiple fields. For example, an error type
165+
// implementing fmt.Formatter results in another "errorVerbose" field, containing the stack trace if the error was
166+
// created by github.com/pkg/errors including a stack[^1]. So the keys are checked again in the following loop.
167+
//
168+
// [^0]: https://github.com/uber-go/zap/blob/v1.27.0/zapcore/error.go#L47
169+
// [^1]: https://pkg.go.dev/github.com/pkg/[email protected]#WithStack
170+
visibleFields := make([]string, 0, len(visibleFieldKeys))
171+
for k, v := range utils.IterateOrderedMap(enc.Fields) {
172+
if _, shouldLog := visibleFieldKeys[k]; !shouldLog {
173+
continue
174+
}
175+
176+
var encodedField string
177+
switch v.(type) {
178+
case string, []byte, error:
179+
encodedField = fmt.Sprintf("%s=%q", k, v)
180+
default:
181+
encodedField = fmt.Sprintf(`%s="%v"`, k, v)
182+
}
183+
184+
visibleFields = append(visibleFields, encodedField)
185+
}
186+
187+
if len(visibleFields) == 0 {
188+
return ""
189+
}
190+
191+
return "\t" + strings.Join(visibleFields, ", ")
192+
}

‎logging/journald_core_test.go‎

Lines changed: 112 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,11 @@
11
package logging
22

33
import (
4+
"fmt"
5+
"github.com/pkg/errors"
46
"github.com/stretchr/testify/require"
7+
"go.uber.org/zap"
8+
"go.uber.org/zap/zapcore"
59
"regexp"
610
"testing"
711
)
@@ -39,3 +43,111 @@ func Test_journaldFieldEncode(t *testing.T) {
3943
})
4044
}
4145
}
46+
47+
// testingStackError is an error mimicking the stack behavior from github.com/pkg/errors in a deterministic way.
48+
type testingStackError string
49+
50+
func (err testingStackError) Error() string {
51+
return string(err)
52+
}
53+
54+
func (err testingStackError) Format(s fmt.State, verb rune) {
55+
if verb == 'v' && s.Flag('+') {
56+
_, _ = fmt.Fprintf(s, "%s: look, I am a stack trace", string(err))
57+
} else {
58+
_, _ = fmt.Fprintf(s, "%s", string(err))
59+
}
60+
}
61+
62+
func Test_visibleFieldsMsg(t *testing.T) {
63+
tests := []struct {
64+
name string
65+
visibleFieldKeys map[string]struct{}
66+
fields []zapcore.Field
67+
output string
68+
}{
69+
{
70+
name: "empty-all-nil",
71+
visibleFieldKeys: nil,
72+
fields: nil,
73+
output: "",
74+
},
75+
{
76+
name: "empty-all",
77+
visibleFieldKeys: map[string]struct{}{},
78+
fields: nil,
79+
output: "",
80+
},
81+
{
82+
name: "empty-visibleFiledKeys",
83+
visibleFieldKeys: map[string]struct{}{},
84+
fields: []zapcore.Field{zap.String("foo", "bar")},
85+
output: "",
86+
},
87+
{
88+
name: "no-field-match",
89+
visibleFieldKeys: map[string]struct{}{"bar": {}},
90+
fields: []zapcore.Field{zap.String("foo", "bar")},
91+
output: "",
92+
},
93+
{
94+
name: "expected-string",
95+
visibleFieldKeys: map[string]struct{}{"foo": {}},
96+
fields: []zapcore.Field{zap.String("foo", "bar")},
97+
output: "\t" + `foo="bar"`,
98+
},
99+
{
100+
name: "expected-multiple-strings-with-excluded",
101+
visibleFieldKeys: map[string]struct{}{"foo": {}, "bar": {}},
102+
fields: []zapcore.Field{
103+
zap.String("foo", "bar"),
104+
zap.String("bar", "baz"),
105+
zap.String("baz", "qux"), // not in allow list
106+
},
107+
output: "\t" + `bar="baz", foo="bar"`,
108+
},
109+
{
110+
name: "expected-error-simple",
111+
visibleFieldKeys: map[string]struct{}{"error": {}},
112+
fields: []zapcore.Field{zap.Error(fmt.Errorf("oops"))},
113+
output: "\t" + `error="oops"`,
114+
},
115+
{
116+
name: "expected-error-without-stack",
117+
visibleFieldKeys: map[string]struct{}{"error": {}},
118+
fields: []zapcore.Field{zap.Error(errors.WithStack(fmt.Errorf("oops")))},
119+
output: "\t" + `error="oops"`,
120+
},
121+
{
122+
name: "expected-error-with-stack",
123+
visibleFieldKeys: map[string]struct{}{"error": {}, "errorVerbose": {}},
124+
fields: []zapcore.Field{zap.Error(testingStackError("oops"))},
125+
output: "\t" + `error="oops", errorVerbose="oops: look, I am a stack trace"`,
126+
},
127+
{
128+
name: "expected-multiple-basic-types",
129+
visibleFieldKeys: map[string]struct{}{
130+
"bool": {},
131+
"byte-string": {},
132+
"complex": {},
133+
"float": {},
134+
"int": {},
135+
},
136+
fields: []zapcore.Field{
137+
zap.Bool("bool", true),
138+
zap.ByteString("byte-string", []byte{0xC0, 0xFF, 0xEE}),
139+
zap.Complex64("complex", -1i),
140+
zap.Float64("float", 1.0/3.0),
141+
zap.Int("int", 42),
142+
},
143+
output: "\t" + `bool="true", byte-string="\xc0\xff\xee", complex="(0-1i)", float="0.3333333333333333", int="42"`,
144+
},
145+
}
146+
147+
for _, test := range tests {
148+
t.Run(test.name, func(t *testing.T) {
149+
out := visibleFieldsMsg(test.visibleFieldKeys, test.fields)
150+
require.Equal(t, test.output, out)
151+
})
152+
}
153+
}

0 commit comments

Comments
 (0)