Skip to content

Commit a74b36a

Browse files
knzknz
committed
util/log: delay the formatting of log entries
Prior to this patch, the logging events were converted to a `logpb.Entry` very early in the logging pipeline. This was forcing the conversion of the logging tags to a flat string too early, and making it hard for (e.g.) a JSON formatter to preserve the structure of logging tags. This patch averts this by introducing a new `logEntry` type which has more-or-less the same structure as `logpb.Entry` but keep the logging tags structured until the point the entry is formatted. Release note: None
1 parent f41f07c commit a74b36a

21 files changed

Lines changed: 330 additions & 209 deletions

‎pkg/cli/debug_merge_logs.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -64,7 +64,7 @@ func writeLogStream(
6464
if _, err = w.Write(prefixBytes); err != nil {
6565
return err
6666
}
67-
return log.FormatEntry(ei.Entry, w)
67+
return log.FormatLegacyEntry(ei.Entry, w)
6868
}
6969

7070
g, ctx := errgroup.WithContext(context.Background())

‎pkg/cli/zip.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -676,7 +676,7 @@ func runDebugZip(cmd *cobra.Command, args []string) (retErr error) {
676676
// We're also going to print a warning at the end.
677677
warnRedactLeak = true
678678
}
679-
if err := log.FormatEntry(e, logOut); err != nil {
679+
if err := log.FormatLegacyEntry(e, logOut); err != nil {
680680
return err
681681
}
682682
}

‎pkg/server/debug/logspy.go‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -160,11 +160,11 @@ func (spy *logSpy) run(ctx context.Context, w io.Writer, opts logSpyOptions) (er
160160
defer func() {
161161
if err == nil {
162162
if dropped := atomic.LoadInt32(&countDropped); dropped > 0 {
163-
entry := log.MakeEntry(
163+
entry := log.MakeLegacyEntry(
164164
ctx, severity.WARNING, channel.DEV,
165-
0 /* depth */, false, /* redactable */
165+
0 /* depth */, true, /* redactable */
166166
"%d messages were dropped", log.Safe(dropped))
167-
err = log.FormatEntry(entry, w) // modify return value
167+
err = log.FormatLegacyEntry(entry, w) // modify return value
168168
}
169169
}
170170
}()
@@ -176,9 +176,9 @@ func (spy *logSpy) run(ctx context.Context, w io.Writer, opts logSpyOptions) (er
176176
entries := make(chan logpb.Entry, logSpyChanCap)
177177

178178
{
179-
entry := log.MakeEntry(
179+
entry := log.MakeLegacyEntry(
180180
ctx, severity.INFO, channel.DEV,
181-
0 /* depth */, false, /* redactable */
181+
0 /* depth */, true, /* redactable */
182182
"intercepting logs with options %+v", opts)
183183
entries <- entry
184184
}
@@ -218,7 +218,7 @@ func (spy *logSpy) run(ctx context.Context, w io.Writer, opts logSpyOptions) (er
218218
return
219219

220220
case entry := <-entries:
221-
if err := log.FormatEntry(entry, w); err != nil {
221+
if err := log.FormatLegacyEntry(entry, w); err != nil {
222222
return errors.Wrapf(err, "while writing entry %v", entry)
223223
}
224224
count++

‎pkg/testutils/lint/passes/fmtsafe/functions.go‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -74,7 +74,8 @@ var requireConstFmt = map[string]bool{
7474
// Note: More of the logging functions are populated here via the
7575
// init() function below.
7676

77-
"github.com/cockroachdb/cockroach/pkg/util/log.MakeEntry": true,
77+
"github.com/cockroachdb/cockroach/pkg/util/log.MakeLegacyEntry": true,
78+
"github.com/cockroachdb/cockroach/pkg/util/log.makeUnstructuredEntry": true,
7879
"github.com/cockroachdb/cockroach/pkg/util/log.FormatWithContextTags": true,
7980
"github.com/cockroachdb/cockroach/pkg/util/log.renderArgsAsRedactable": true,
8081
"github.com/cockroachdb/cockroach/pkg/util/log.formatArgs": true,

‎pkg/util/log/channels.go‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -49,11 +49,11 @@ func logfDepth(
4949
}
5050

5151
logger := logging.getLogger(ch)
52-
entry := MakeEntry(
52+
entry := makeUnstructuredEntry(
5353
ctx, sev, ch,
5454
depth+1, true /* redactable */, format, args...)
5555
if sp, el, ok := getSpanOrEventLog(ctx); ok {
56-
eventInternal(sp, el, (sev >= severity.ERROR), entry)
56+
eventInternal(sp, el, (sev >= severity.ERROR), entry.convertToLegacy())
5757
}
5858
logger.outputLogEntry(entry)
5959
}

‎pkg/util/log/clog.go‎

Lines changed: 17 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -22,7 +22,6 @@ import (
2222

2323
"github.com/cockroachdb/cockroach/pkg/cli/exit"
2424
"github.com/cockroachdb/cockroach/pkg/util/log/channel"
25-
"github.com/cockroachdb/cockroach/pkg/util/log/logpb"
2625
"github.com/cockroachdb/cockroach/pkg/util/log/severity"
2726
"github.com/cockroachdb/cockroach/pkg/util/syncutil"
2827
"github.com/cockroachdb/errors"
@@ -248,36 +247,35 @@ func SetTenantIDs(tenantID string, sqlInstanceID int32) {
248247
// outputLogEntry marshals a log entry proto into bytes, and writes
249248
// the data to the log files. If a trace location is set, stack traces
250249
// are added to the entry before marshaling.
251-
func (l *loggerT) outputLogEntry(entry logpb.Entry) {
250+
func (l *loggerT) outputLogEntry(entry logEntry) {
252251
if f, ok := logging.interceptor.Load().(InterceptorFn); ok && f != nil {
253-
f(entry)
252+
f(entry.convertToLegacy())
254253
return
255254
}
256255

257256
// Mark the logger as active, so that further configuration changes
258257
// are disabled. See IsActive() and its callers for details.
259258
setActive()
260-
var stacks []byte
261259
var fatalTrigger chan struct{}
262260
extraSync := false
263261

264-
if entry.Severity == severity.FATAL {
262+
if entry.sev == severity.FATAL {
265263
extraSync = true
266264
logging.signalFatalCh()
267265

268266
switch traceback {
269267
case tracebackSingle:
270-
stacks = getStacks(false)
268+
entry.stacks = getStacks(false)
271269
case tracebackAll:
272-
stacks = getStacks(true)
270+
entry.stacks = getStacks(true)
273271
}
274272

275273
for _, s := range l.sinkInfos {
276-
stacks = s.sink.attachHints(stacks)
274+
entry.stacks = s.sink.attachHints(entry.stacks)
277275
}
278276

279277
// Explain to the (human) user that we would like to hear from them.
280-
stacks = append(stacks, []byte(fatalErrorPostamble)...)
278+
entry.stacks = append(entry.stacks, []byte(fatalErrorPostamble)...)
281279

282280
// We don't want to hang forever writing our final log message. If
283281
// things are broken (for example, if the disk fills up and there
@@ -296,7 +294,7 @@ func (l *loggerT) outputLogEntry(entry logpb.Entry) {
296294
logging.mu.Lock()
297295
if logging.mu.exitOverride.f != nil {
298296
if logging.mu.exitOverride.hideStack {
299-
stacks = []byte("stack trace omitted via SetExitFunc()\n")
297+
entry.stacks = []byte("stack trace omitted via SetExitFunc()\n")
300298
}
301299
exitFunc = logging.mu.exitOverride.f
302300
}
@@ -337,17 +335,21 @@ func (l *loggerT) outputLogEntry(entry logpb.Entry) {
337335
// Stopper's Stop() call (e.g. the pgwire async processing
338336
// goroutine). These asynchronous log calls are concurrent with
339337
// the stderrSinkInfo update in (*TestLogScope).Close().
340-
if entry.Severity < s.threshold.Get() || !s.sink.active() {
338+
if entry.sev < s.threshold.Get() || !s.sink.active() {
341339
continue
342340
}
343-
editedEntry := maybeRedactEntry(entry, s.editor)
341+
editedEntry := entry
344342

345343
// Add a counter. This is important for e.g. the SQL audit logs.
346344
// Note: whether the counter is displayed or not depends on
347345
// the formatter.
348-
editedEntry.Counter = atomic.AddUint64(&s.msgCount, 1)
346+
editedEntry.counter = atomic.AddUint64(&s.msgCount, 1)
349347

350-
bufs.b[i] = s.formatter.formatEntry(editedEntry, stacks)
348+
// Process the redation spec.
349+
editedEntry.payload = maybeRedactEntry(editedEntry.payload, s.editor)
350+
351+
// Format the entry for this sink.
352+
bufs.b[i] = s.formatter.formatEntry(editedEntry)
351353
someSinkActive = true
352354
}
353355

@@ -398,7 +400,7 @@ func (l *loggerT) outputLogEntry(entry logpb.Entry) {
398400
}
399401

400402
// Flush and exit on fatal logging.
401-
if entry.Severity == severity.FATAL {
403+
if entry.sev == severity.FATAL {
402404
close(fatalTrigger)
403405
// Note: although it seems like the function is allowed to return
404406
// below when s == severity.FATAL, this is not so, because the

‎pkg/util/log/clog_test.go‎

Lines changed: 31 additions & 30 deletions
Original file line numberDiff line numberDiff line change
@@ -156,9 +156,8 @@ func TestEntryDecoder(t *testing.T) {
156156
Tags: tags,
157157
Message: msg,
158158
}
159-
var f formatCrdbV1
160-
buf := f.formatEntry(entry, nil /* stacks */)
161-
defer putBuffer(buf)
159+
var buf bytes.Buffer
160+
_ = FormatLegacyEntry(entry, &buf)
162161
return buf.String()
163162
}
164163

@@ -635,36 +634,39 @@ func TestRollover(t *testing.T) {
635634
// right now clog writes straight to os.StdErr.
636635
func TestFatalStacktraceStderr(t *testing.T) {
637636
defer leaktest.AfterTest(t)()
638-
defer ScopeWithoutShowLogs(t).Close(t)
639637

640-
SetExitFunc(false /* hideStack */, func(exit.Code) {})
638+
for _, level := range []int{tracebackNone, tracebackSingle, tracebackAll} {
639+
t.Run(fmt.Sprintf("%d", level), func(t *testing.T) {
640+
defer ScopeWithoutShowLogs(t).Close(t)
641641

642-
defer capture()()
642+
SetExitFunc(false /* hideStack */, func(exit.Code) {})
643643

644-
for _, level := range []int{tracebackNone, tracebackSingle, tracebackAll} {
645-
traceback = level
646-
Fatalf(context.Background(), "cinap")
647-
cont := contents()
648-
if !strings.Contains(cont, " cinap") {
649-
t.Fatalf("panic output does not contain cinap:\n%s", cont)
650-
}
651-
if !strings.Contains(cont, "clog_test") {
652-
t.Fatalf("stack trace does not contain file name: %s", cont)
653-
}
654-
switch traceback {
655-
case tracebackNone:
656-
if strings.Count(cont, "goroutine ") > 0 {
657-
t.Fatalf("unexpected stack trace:\n%s", cont)
644+
defer capture()()
645+
646+
traceback = level
647+
Fatalf(context.Background(), "cinap")
648+
cont := contents()
649+
if !strings.Contains(cont, " cinap") {
650+
t.Fatalf("panic output does not contain cinap:\n%s", cont)
658651
}
659-
case tracebackSingle:
660-
if strings.Count(cont, "goroutine ") != 1 {
661-
t.Fatalf("stack trace contains too many goroutines: %s", cont)
652+
if !strings.Contains(cont, "clog_test") {
653+
t.Fatalf("stack trace does not contain file name: %s", cont)
662654
}
663-
case tracebackAll:
664-
if strings.Count(cont, "goroutine ") < 2 {
665-
t.Fatalf("stack trace contains less than two goroutines: %s", cont)
655+
switch traceback {
656+
case tracebackNone:
657+
if strings.Count(cont, "goroutine ") > 0 {
658+
t.Fatalf("unexpected stack trace:\n%s", cont)
659+
}
660+
case tracebackSingle:
661+
if strings.Count(cont, "goroutine ") != 1 {
662+
t.Fatalf("stack trace contains too many goroutines: %s", cont)
663+
}
664+
case tracebackAll:
665+
if strings.Count(cont, "goroutine ") < 2 {
666+
t.Fatalf("stack trace contains less than two goroutines: %s", cont)
667+
}
666668
}
667-
}
669+
})
668670
}
669671
}
670672

@@ -773,10 +775,9 @@ func BenchmarkHeader(b *testing.B) {
773775
File: "file.go",
774776
Line: 100,
775777
}
776-
var f formatCrdbV1
777778
for i := 0; i < b.N; i++ {
778-
buf := f.formatEntry(entry, nil /* stacks */)
779-
putBuffer(buf)
779+
var w bytes.Buffer
780+
_ = FormatLegacyEntry(entry, &w)
780781
}
781782
}
782783

‎pkg/util/log/event_log.go‎

Lines changed: 14 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,6 @@ package log
1212

1313
import (
1414
"context"
15-
"encoding/json"
1615

1716
"github.com/cockroachdb/cockroach/pkg/util/log/eventpb"
1817
"github.com/cockroachdb/cockroach/pkg/util/log/severity"
@@ -29,19 +28,20 @@ func StructuredEvent(ctx context.Context, event eventpb.EventPayload) {
2928
if len(common.EventType) == 0 {
3029
common.EventType = eventpb.GetEventTypeName(event)
3130
}
32-
// TODO(knz): Avoid marking all the JSON payload as redactable. Do
33-
// redaction per-field.
34-
b, err := json.Marshal(event)
35-
if err != nil {
36-
Fatalf(ctx, "unexpected JSON encoding error: %+v", err)
37-
}
3831

39-
// TODO(knz): Avoid escaping the JSON format when emitting the payload
40-
// to an external sink.
32+
entry := makeStructuredEntry(ctx,
33+
severity.INFO,
34+
event.LoggingChannel(),
35+
// Note: we use depth 0 intentionally here, so that structured
36+
// events can be reliably detected (their source filename will
37+
// always be log/event_log.go).
38+
0, /* depth */
39+
event)
40+
41+
if sp, el, ok := getSpanOrEventLog(ctx); ok {
42+
eventInternal(sp, el, (entry.sev >= severity.ERROR), entry.convertToLegacy())
43+
}
4144

42-
// Note: we use depth 0 intentionally here, so that structured
43-
// events can be reliably detected (their source filename will
44-
// always be log/event_log.go).
45-
// TODO(knz): Consider another way to mark structured events.
46-
logfDepth(ctx, 0, severity.INFO, event.LoggingChannel(), "Structured event: %s", string(b))
45+
logger := logging.getLogger(entry.ch)
46+
logger.outputLogEntry(entry)
4747
}

‎pkg/util/log/exit_override.go‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -77,9 +77,10 @@ func (l *loggerT) exitLocked(err error, code exit.Code) {
7777
// This assumes l.outputMu is held, but l.fileSink.mu is not held.
7878
func (l *loggerT) reportErrorEverywhereLocked(ctx context.Context, err error) {
7979
// Make a valid log entry for this error.
80-
entry := MakeEntry(
80+
entry := makeUnstructuredEntry(
8181
ctx, severity.ERROR, channel.OPS,
82-
2 /* depth */, true, /* redactable */
82+
2, /* depth */
83+
true, /* redactable */
8384
"logging error: %v", err)
8485

8586
// Either stderr or our log file is broken. Try writing the error to both
@@ -96,7 +97,7 @@ func (l *loggerT) reportErrorEverywhereLocked(ctx context.Context, err error) {
9697
for _, s := range l.sinkInfos {
9798
sink := s.sink
9899
if logpb.Severity_ERROR >= s.threshold && sink.active() {
99-
buf := s.formatter.formatEntry(entry, nil /*stack*/)
100+
buf := s.formatter.formatEntry(entry)
100101
sink.emergencyOutput(buf.Bytes())
101102
putBuffer(buf)
102103
}

‎pkg/util/log/file_log_gc_test.go‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -67,7 +67,8 @@ func TestSecondaryGC(t *testing.T) {
6767

6868
testLogGC(t, logger,
6969
func(ctx context.Context, format string, args ...interface{}) {
70-
entry := MakeEntry(ctx, severity.INFO, channel.DEV, 1, si.redactable,
70+
entry := makeUnstructuredEntry(ctx, severity.INFO, channel.DEV, 1,
71+
true, /* redactable */
7172
format, /* nolint:fmtsafe */
7273
args...)
7374
logger.outputLogEntry(entry)

0 commit comments

Comments
 (0)