Skip to content

Commit b32bdc4

Browse files
oxzioxzi
committed
logging: Include error field in journald message
Our journald zapcore.Core logs every zap field as a journald field. This has the disadvantage that these fields do not shown up in the default journalctl output, effectively hiding errors. While this is documented, it is not the expected behavior for most users, resulting in incomplete bug reports. This change introduces a new set of zap fields to be also included in the journald message. Currently, only the "error" field gets this special treatment, allowing errors to be displayed. An exemplary Icinga DB log message would change as follows while still containing the ICINGADB_ERROR field. > database: Can't connect to database. Retrying > database: Can't connect to database. Retrying error="dial tcp [::1]:5432: connect: connection refused" As a drive-by change, the package-global variable "priorities" was renamed to "journaldPriorities" to make it more obvious. Fixes Icinga/icingadb#793.
1 parent d262a5e commit b32bdc4

File tree

2 files changed

+184
-4
lines changed

2 files changed

+184
-4
lines changed

‎logging/journald_core.go‎

Lines changed: 70 additions & 4 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,7 +61,7 @@ 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
}
@@ -64,7 +72,7 @@ func (c *journaldCore) Write(ent zapcore.Entry, fields []zapcore.Field) error {
6472
c.addFields(enc, c.context)
6573
enc.Fields["SYSLOG_IDENTIFIER"] = c.identifier
6674

67-
message := ent.Message
75+
message := ent.Message + visibleFieldsMsg(journaldVisibleFields, append(fields, c.context...))
6876
if ent.LoggerName != c.identifier {
6977
message = ent.LoggerName + ": " + message
7078
}
@@ -124,3 +132,61 @@ func encodeJournaldFieldKey(key string) string {
124132

125133
return key
126134
}
135+
136+
// visibleFieldsMsg creates a string to be appended to the log message including fields to be explicitly printed.
137+
//
138+
// When logging against journald, the zapcore.Fields are used as journald fields, resulting in not being shown in the
139+
// default journalctl output (short). While this is documented in our docs, missing error messages are usually confusing
140+
// for end users.
141+
//
142+
// This method takes an allow list (set, map of keys to empty struct) of key to be displayed - there is the global
143+
// variable journaldVisibleFields; parameter for testing - and a slice of zapcore.Fields, creating an output string of
144+
// the allowed fields prefixed by a whitespace separator. If there are no fields to be logged, the returned string is
145+
// empty. So the function output can be appended to the output message without further checks.
146+
func visibleFieldsMsg(visibleFieldKeys map[string]struct{}, fields []zapcore.Field) string {
147+
if visibleFieldKeys == nil || fields == nil {
148+
return ""
149+
}
150+
151+
enc := zapcore.NewMapObjectEncoder()
152+
153+
for _, field := range fields {
154+
if _, shouldLog := visibleFieldKeys[field.Key]; shouldLog {
155+
field.AddTo(enc)
156+
}
157+
}
158+
159+
// The internal zapcore.encodeError function[^0] can result in multiple fields. For example, an error type
160+
// implementing fmt.Formatter results in another "errorVerbose" field, containing the stack trace if the error was
161+
// created by github.com/pkg/errors including a stack[^1].
162+
//
163+
// Therefore, the keys are checked again in the following loop before being inserted in the final array, having a
164+
// capacity of twice the fields length to minimize the chance of a resize.
165+
//
166+
// [^0]: https://github.com/uber-go/zap/blob/v1.27.0/zapcore/error.go#L47
167+
// [^1]: https://pkg.go.dev/github.com/pkg/[email protected]#WithStack
168+
visibleFields := make([]string, 0, 2*len(enc.Fields))
169+
for k, v := range utils.IterateOrderedMap(enc.Fields) {
170+
if _, shouldLog := visibleFieldKeys[k]; !shouldLog {
171+
continue
172+
}
173+
174+
var fieldVerb, fieldEnclosure string
175+
switch v.(type) {
176+
case rune, string, []byte, error:
177+
fieldVerb = "%q"
178+
// %q already enclosures the value
179+
default:
180+
fieldVerb = "%v"
181+
fieldEnclosure = `"`
182+
}
183+
184+
visibleFields = append(visibleFields, fmt.Sprintf("%s=%s"+fieldVerb+"%s", k, fieldEnclosure, v, fieldEnclosure))
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: 114 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,113 @@ 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+
"int": {},
132+
"rune": {},
133+
"float": {},
134+
"complex": {},
135+
"byte-string": {},
136+
},
137+
fields: []zapcore.Field{
138+
zap.Bool("bool", true),
139+
zap.ByteString("byte-string", []byte{0xC0, 0xFF, 0xEE}),
140+
zap.Complex64("complex", -1i),
141+
zap.Float64("float", 1.0/3.0),
142+
zap.Int("int", 42),
143+
zap.Any("rune", 'A'),
144+
},
145+
output: "\t" + `bool="true", byte-string="\xc0\xff\xee", complex="(0-1i)", float="0.3333333333333333", int="42", rune='A'`,
146+
},
147+
}
148+
149+
for _, test := range tests {
150+
t.Run(test.name, func(t *testing.T) {
151+
out := visibleFieldsMsg(test.visibleFieldKeys, test.fields)
152+
require.Equal(t, test.output, out)
153+
})
154+
}
155+
}

0 commit comments

Comments
 (0)