From 114a8940acf65b699c827fa9b51a80b4757ea6aa Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Fri, 4 Jun 2021 19:43:45 +0200 Subject: [PATCH 1/6] util/log: move the crdb-v1 test code to a separate file Release note: None --- pkg/util/log/BUILD.bazel | 1 + pkg/util/log/clog_test.go | 227 ------------------------- pkg/util/log/format_crdb_v1_test.go | 250 ++++++++++++++++++++++++++++ 3 files changed, 251 insertions(+), 227 deletions(-) create mode 100644 pkg/util/log/format_crdb_v1_test.go diff --git a/pkg/util/log/BUILD.bazel b/pkg/util/log/BUILD.bazel index daee6abee62e..613d29611751 100644 --- a/pkg/util/log/BUILD.bazel +++ b/pkg/util/log/BUILD.bazel @@ -127,6 +127,7 @@ go_test( "file_test.go", "flags_test.go", "fluent_client_test.go", + "format_crdb_v1_test.go", "format_crdb_v2_test.go", "format_json_test.go", "helpers_test.go", diff --git a/pkg/util/log/clog_test.go b/pkg/util/log/clog_test.go index 4db42a79d6b2..e3e0e70a8a6a 100644 --- a/pkg/util/log/clog_test.go +++ b/pkg/util/log/clog_test.go @@ -18,17 +18,14 @@ import ( "bytes" "context" "fmt" - "io" "io/ioutil" stdLog "log" "os" "path/filepath" - "reflect" "regexp" "strings" "sync" "testing" - "time" "github.com/cockroachdb/cockroach/pkg/cli/exit" "github.com/cockroachdb/cockroach/pkg/util/leaktest" @@ -37,7 +34,6 @@ import ( "github.com/cockroachdb/cockroach/pkg/util/log/logpb" "github.com/cockroachdb/cockroach/pkg/util/log/severity" "github.com/cockroachdb/cockroach/pkg/util/timeutil" - "github.com/kr/pretty" ) // Test that shortHostname works as advertised. @@ -144,229 +140,6 @@ func TestStandardLog(t *testing.T) { } } -func TestEntryDecoder(t *testing.T) { - entryIdx := 1 - formatEntry := func(s Severity, c Channel, now time.Time, gid int, file string, line int, tags, msg string) string { - entry := logpb.Entry{ - Severity: s, - Channel: c, - Time: now.UnixNano(), - Goroutine: int64(gid), - File: file, - Line: int64(line), - Tags: tags, - Message: msg, - Counter: uint64(entryIdx), - } - entryIdx++ - var buf bytes.Buffer - _ = FormatLegacyEntry(entry, &buf) - return buf.String() - } - - t1 := timeutil.Now().Round(time.Microsecond) - t2 := t1.Add(time.Microsecond) - t3 := t2.Add(time.Microsecond) - t4 := t3.Add(time.Microsecond) - t5 := t4.Add(time.Microsecond) - t6 := t5.Add(time.Microsecond) - t7 := t6.Add(time.Microsecond) - t8 := t7.Add(time.Microsecond) - t9 := t8.Add(time.Microsecond) - t10 := t9.Add(time.Microsecond) - t11 := t10.Add(time.Microsecond) - - // Verify the truncation logic for reading logs that are longer than the - // default scanner can handle. - preambleLength := len(formatEntry(severity.INFO, channel.DEV, t1, 0, "clog_test.go", 136, ``, "")) - maxMessageLength := bufio.MaxScanTokenSize - preambleLength - 1 - reallyLongEntry := string(bytes.Repeat([]byte("a"), maxMessageLength)) - tooLongEntry := reallyLongEntry + "a" - - contents := formatEntry(severity.INFO, channel.DEV, t1, 0, "clog_test.go", 136, ``, "info") - contents += formatEntry(severity.INFO, channel.DEV, t2, 1, "clog_test.go", 137, ``, "multi-\nline") - contents += formatEntry(severity.INFO, channel.DEV, t3, 2, "clog_test.go", 138, ``, reallyLongEntry) - contents += formatEntry(severity.INFO, channel.DEV, t4, 3, "clog_test.go", 139, ``, tooLongEntry) - contents += formatEntry(severity.WARNING, channel.DEV, t5, 4, "clog_test.go", 140, ``, "warning") - contents += formatEntry(severity.ERROR, channel.DEV, t6, 5, "clog_test.go", 141, ``, "error") - contents += formatEntry(severity.FATAL, channel.DEV, t7, 6, "clog_test.go", 142, ``, "fatal\nstack\ntrace") - contents += formatEntry(severity.INFO, channel.DEV, t8, 7, "clog_test.go", 143, ``, tooLongEntry) - - // Regression test for #56873. - contents += formatEntry(severity.INFO, channel.DEV, t8, 8, "clog_test.go", 144, `sometags`, "foo") - contents += formatEntry(severity.INFO, channel.DEV, t8, 9, "clog_test.go", 145, ``, "bar" /* no tags */) - // Different channel. - contents += formatEntry(severity.INFO, channel.SESSIONS, t9, 10, "clog_test.go", 146, ``, "info") - // Ensure that IPv6 addresses in tags get parsed properly. - contents += formatEntry(severity.INFO, channel.DEV, t10, 11, "clog_test.go", 147, `client=[1::]:2`, "foo") - // Ensure that empty messages don't wreak havoc. - contents += formatEntry(severity.INFO, channel.DEV, t11, 12, "clog_test.go", 148, "", "") - - readAllEntries := func(contents string) []logpb.Entry { - decoder := NewEntryDecoder(strings.NewReader(contents), WithFlattenedSensitiveData) - var entries []logpb.Entry - var entry logpb.Entry - for { - if err := decoder.Decode(&entry); err != nil { - if err == io.EOF { - break - } - t.Fatal(err) - } - entries = append(entries, entry) - } - return entries - } - - entries := readAllEntries(contents) - expected := []logpb.Entry{ - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t1.UnixNano(), - Goroutine: 0, - File: `clog_test.go`, - Line: 136, - Message: `info`, - Counter: 2, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t2.UnixNano(), - Goroutine: 1, - File: `clog_test.go`, - Line: 137, - Message: `multi- -line`, - Counter: 3, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t3.UnixNano(), - Goroutine: 2, - File: `clog_test.go`, - Line: 138, - Message: reallyLongEntry, - Counter: 4, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t4.UnixNano(), - Goroutine: 3, - File: `clog_test.go`, - Line: 139, - Message: tooLongEntry[:maxMessageLength], - Counter: 5, - }, - { - Severity: severity.WARNING, - Channel: channel.DEV, - Time: t5.UnixNano(), - Goroutine: 4, - File: `clog_test.go`, - Line: 140, - Message: `warning`, - Counter: 6, - }, - { - Severity: severity.ERROR, - Channel: channel.DEV, - Time: t6.UnixNano(), - Goroutine: 5, - File: `clog_test.go`, - Line: 141, - Message: `error`, - Counter: 7, - }, - { - Severity: severity.FATAL, - Channel: channel.DEV, - Time: t7.UnixNano(), - Goroutine: 6, - File: `clog_test.go`, - Line: 142, - Message: `fatal -stack -trace`, - Counter: 8, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t8.UnixNano(), - Goroutine: 7, - File: `clog_test.go`, - Line: 143, - Message: tooLongEntry[:maxMessageLength], - Counter: 9, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t8.UnixNano(), - Goroutine: 8, - File: `clog_test.go`, - Line: 144, - Tags: `sometags`, - Message: `foo`, - Counter: 10, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t8.UnixNano(), - Goroutine: 9, - File: `clog_test.go`, - Line: 145, - Message: `bar`, - Counter: 11, - }, - { - Severity: severity.INFO, - Channel: channel.SESSIONS, - Time: t9.UnixNano(), - Goroutine: 10, - File: `clog_test.go`, - Line: 146, - Message: `info`, - Counter: 12, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t10.UnixNano(), - Goroutine: 11, - File: `clog_test.go`, - Line: 147, - Tags: `client=[1::]:2`, - Message: `foo`, - Counter: 13, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t11.UnixNano(), - Goroutine: 12, - File: `clog_test.go`, - Line: 148, - Tags: ``, - Message: ``, - Counter: 14, - }, - } - if !reflect.DeepEqual(expected, entries) { - t.Fatalf("%s\n", strings.Join(pretty.Diff(expected, entries), "\n")) - } - - entries = readAllEntries("file header\n\n\n" + contents) - if !reflect.DeepEqual(expected, entries) { - t.Fatalf("%s\n", strings.Join(pretty.Diff(expected, entries), "\n")) - } -} - // Test that an Error log goes to Warning and Info. // Even in the Info log, the source character will be E, so the data should // all be identical. diff --git a/pkg/util/log/format_crdb_v1_test.go b/pkg/util/log/format_crdb_v1_test.go new file mode 100644 index 000000000000..3f2100c1aef7 --- /dev/null +++ b/pkg/util/log/format_crdb_v1_test.go @@ -0,0 +1,250 @@ +// Copyright 2021 The Cockroach Authors. +// +// Use of this software is governed by the Business Source License +// included in the file licenses/BSL.txt. +// +// As of the Change Date specified in that file, in accordance with +// the Business Source License, use of this software will be governed +// by the Apache License, Version 2.0, included in the file +// licenses/APL.txt. + +package log + +import ( + "bufio" + "bytes" + "io" + "reflect" + "strings" + "testing" + "time" + + "github.com/cockroachdb/cockroach/pkg/util/log/channel" + "github.com/cockroachdb/cockroach/pkg/util/log/logpb" + "github.com/cockroachdb/cockroach/pkg/util/log/severity" + "github.com/cockroachdb/cockroach/pkg/util/timeutil" + "github.com/kr/pretty" +) + +func TestEntryDecoder(t *testing.T) { + entryIdx := 1 + formatEntry := func(s Severity, c Channel, now time.Time, gid int, file string, line int, tags, msg string) string { + entry := logpb.Entry{ + Severity: s, + Channel: c, + Time: now.UnixNano(), + Goroutine: int64(gid), + File: file, + Line: int64(line), + Tags: tags, + Message: msg, + Counter: uint64(entryIdx), + } + entryIdx++ + var buf bytes.Buffer + _ = FormatLegacyEntry(entry, &buf) + return buf.String() + } + + t1 := timeutil.Now().Round(time.Microsecond) + t2 := t1.Add(time.Microsecond) + t3 := t2.Add(time.Microsecond) + t4 := t3.Add(time.Microsecond) + t5 := t4.Add(time.Microsecond) + t6 := t5.Add(time.Microsecond) + t7 := t6.Add(time.Microsecond) + t8 := t7.Add(time.Microsecond) + t9 := t8.Add(time.Microsecond) + t10 := t9.Add(time.Microsecond) + t11 := t10.Add(time.Microsecond) + + // Verify the truncation logic for reading logs that are longer than the + // default scanner can handle. + preambleLength := len(formatEntry(severity.INFO, channel.DEV, t1, 0, "clog_test.go", 136, ``, "")) + maxMessageLength := bufio.MaxScanTokenSize - preambleLength - 1 + reallyLongEntry := string(bytes.Repeat([]byte("a"), maxMessageLength)) + tooLongEntry := reallyLongEntry + "a" + + contents := formatEntry(severity.INFO, channel.DEV, t1, 0, "clog_test.go", 136, ``, "info") + contents += formatEntry(severity.INFO, channel.DEV, t2, 1, "clog_test.go", 137, ``, "multi-\nline") + contents += formatEntry(severity.INFO, channel.DEV, t3, 2, "clog_test.go", 138, ``, reallyLongEntry) + contents += formatEntry(severity.INFO, channel.DEV, t4, 3, "clog_test.go", 139, ``, tooLongEntry) + contents += formatEntry(severity.WARNING, channel.DEV, t5, 4, "clog_test.go", 140, ``, "warning") + contents += formatEntry(severity.ERROR, channel.DEV, t6, 5, "clog_test.go", 141, ``, "error") + contents += formatEntry(severity.FATAL, channel.DEV, t7, 6, "clog_test.go", 142, ``, "fatal\nstack\ntrace") + contents += formatEntry(severity.INFO, channel.DEV, t8, 7, "clog_test.go", 143, ``, tooLongEntry) + + // Regression test for #56873. + contents += formatEntry(severity.INFO, channel.DEV, t8, 8, "clog_test.go", 144, `sometags`, "foo") + contents += formatEntry(severity.INFO, channel.DEV, t8, 9, "clog_test.go", 145, ``, "bar" /* no tags */) + // Different channel. + contents += formatEntry(severity.INFO, channel.SESSIONS, t9, 10, "clog_test.go", 146, ``, "info") + // Ensure that IPv6 addresses in tags get parsed properly. + contents += formatEntry(severity.INFO, channel.DEV, t10, 11, "clog_test.go", 147, `client=[1::]:2`, "foo") + // Ensure that empty messages don't wreak havoc. + contents += formatEntry(severity.INFO, channel.DEV, t11, 12, "clog_test.go", 148, "", "") + + readAllEntries := func(contents string) []logpb.Entry { + decoder := NewEntryDecoder(strings.NewReader(contents), WithFlattenedSensitiveData) + var entries []logpb.Entry + var entry logpb.Entry + for { + if err := decoder.Decode(&entry); err != nil { + if err == io.EOF { + break + } + t.Fatal(err) + } + entries = append(entries, entry) + } + return entries + } + + entries := readAllEntries(contents) + expected := []logpb.Entry{ + { + Severity: severity.INFO, + Channel: channel.DEV, + Time: t1.UnixNano(), + Goroutine: 0, + File: `clog_test.go`, + Line: 136, + Message: `info`, + Counter: 2, + }, + { + Severity: severity.INFO, + Channel: channel.DEV, + Time: t2.UnixNano(), + Goroutine: 1, + File: `clog_test.go`, + Line: 137, + Message: `multi- +line`, + Counter: 3, + }, + { + Severity: severity.INFO, + Channel: channel.DEV, + Time: t3.UnixNano(), + Goroutine: 2, + File: `clog_test.go`, + Line: 138, + Message: reallyLongEntry, + Counter: 4, + }, + { + Severity: severity.INFO, + Channel: channel.DEV, + Time: t4.UnixNano(), + Goroutine: 3, + File: `clog_test.go`, + Line: 139, + Message: tooLongEntry[:maxMessageLength], + Counter: 5, + }, + { + Severity: severity.WARNING, + Channel: channel.DEV, + Time: t5.UnixNano(), + Goroutine: 4, + File: `clog_test.go`, + Line: 140, + Message: `warning`, + Counter: 6, + }, + { + Severity: severity.ERROR, + Channel: channel.DEV, + Time: t6.UnixNano(), + Goroutine: 5, + File: `clog_test.go`, + Line: 141, + Message: `error`, + Counter: 7, + }, + { + Severity: severity.FATAL, + Channel: channel.DEV, + Time: t7.UnixNano(), + Goroutine: 6, + File: `clog_test.go`, + Line: 142, + Message: `fatal +stack +trace`, + Counter: 8, + }, + { + Severity: severity.INFO, + Channel: channel.DEV, + Time: t8.UnixNano(), + Goroutine: 7, + File: `clog_test.go`, + Line: 143, + Message: tooLongEntry[:maxMessageLength], + Counter: 9, + }, + { + Severity: severity.INFO, + Channel: channel.DEV, + Time: t8.UnixNano(), + Goroutine: 8, + File: `clog_test.go`, + Line: 144, + Tags: `sometags`, + Message: `foo`, + Counter: 10, + }, + { + Severity: severity.INFO, + Channel: channel.DEV, + Time: t8.UnixNano(), + Goroutine: 9, + File: `clog_test.go`, + Line: 145, + Message: `bar`, + Counter: 11, + }, + { + Severity: severity.INFO, + Channel: channel.SESSIONS, + Time: t9.UnixNano(), + Goroutine: 10, + File: `clog_test.go`, + Line: 146, + Message: `info`, + Counter: 12, + }, + { + Severity: severity.INFO, + Channel: channel.DEV, + Time: t10.UnixNano(), + Goroutine: 11, + File: `clog_test.go`, + Line: 147, + Tags: `client=[1::]:2`, + Message: `foo`, + Counter: 13, + }, + { + Severity: severity.INFO, + Channel: channel.DEV, + Time: t11.UnixNano(), + Goroutine: 12, + File: `clog_test.go`, + Line: 148, + Tags: ``, + Message: ``, + Counter: 14, + }, + } + if !reflect.DeepEqual(expected, entries) { + t.Fatalf("%s\n", strings.Join(pretty.Diff(expected, entries), "\n")) + } + + entries = readAllEntries("file header\n\n\n" + contents) + if !reflect.DeepEqual(expected, entries) { + t.Fatalf("%s\n", strings.Join(pretty.Diff(expected, entries), "\n")) + } +} From 4bddc1d328cffd674e82c8bdcb45144312f94bfc Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Fri, 4 Jun 2021 20:21:11 +0200 Subject: [PATCH 2/6] util/log: use a datadriven test for the crdb-v1 format/parse test This simplifies the test and makes it more extensible. Release note: None --- pkg/util/log/format_crdb_v1_test.go | 214 +++++++++------------------- pkg/util/log/testdata/crdb_v1 | 97 +++++++++++++ 2 files changed, 164 insertions(+), 147 deletions(-) create mode 100644 pkg/util/log/testdata/crdb_v1 diff --git a/pkg/util/log/format_crdb_v1_test.go b/pkg/util/log/format_crdb_v1_test.go index 3f2100c1aef7..3fe3bd8bacc6 100644 --- a/pkg/util/log/format_crdb_v1_test.go +++ b/pkg/util/log/format_crdb_v1_test.go @@ -13,6 +13,8 @@ package log import ( "bufio" "bytes" + "encoding/json" + "fmt" "io" "reflect" "strings" @@ -23,10 +25,69 @@ import ( "github.com/cockroachdb/cockroach/pkg/util/log/logpb" "github.com/cockroachdb/cockroach/pkg/util/log/severity" "github.com/cockroachdb/cockroach/pkg/util/timeutil" + "github.com/cockroachdb/datadriven" "github.com/kr/pretty" ) -func TestEntryDecoder(t *testing.T) { +func TestCrdbV1EncodeDecode(t *testing.T) { + var templateEntry logpb.Entry + // We only use the datadriven framework for the ability to rewrite the output. + datadriven.RunTest(t, "testdata/crdb_v1", func(t *testing.T, td *datadriven.TestData) string { + switch td.Cmd { + case "common": + templateEntry = logpb.Entry{} + if err := json.Unmarshal([]byte(td.Input), &templateEntry); err != nil { + td.Fatalf(t, "invalid input syntax: %v", err) + } + + case "entries": + var inputEntries []logpb.Entry + for _, line := range strings.Split(td.Input, "\n") { + entry := templateEntry + if err := json.Unmarshal([]byte(line), &entry); err != nil { + td.Fatalf(t, "invalid input syntax: %v", err) + } + inputEntries = append(inputEntries, entry) + } + + var buf bytes.Buffer + // Encode. + for _, entry := range inputEntries { + _ = FormatLegacyEntry(entry, &buf) + } + // Decode. + entryStr := buf.String() + decoder := NewEntryDecoder(strings.NewReader(entryStr), WithMarkedSensitiveData) + var outputEntries []logpb.Entry + for { + var entry logpb.Entry + if err := decoder.Decode(&entry); err != nil { + if err == io.EOF { + break + } + td.Fatalf(t, "error while decoding: %v", err) + } + outputEntries = append(outputEntries, entry) + } + if len(outputEntries) != len(inputEntries) { + td.Fatalf(t, "parse results in %d entries, expected %d. Input:\n%s", len(outputEntries), len(inputEntries), entryStr) + } + // Show what has been decoded. + buf.WriteString("# after parse:\n") + for _, entry := range outputEntries { + fmt.Fprintf(&buf, "%# v\n", pretty.Formatter(entry)) + } + return buf.String() + + default: + t.Fatalf("unsupported command: %q", td.Cmd) + } + return "" + // unreachable + }) +} + +func TestCrdbV1EntryDecoderForVeryLargeEntries(t *testing.T) { entryIdx := 1 formatEntry := func(s Severity, c Channel, now time.Time, gid int, file string, line int, tags, msg string) string { entry := logpb.Entry{ @@ -48,15 +109,6 @@ func TestEntryDecoder(t *testing.T) { t1 := timeutil.Now().Round(time.Microsecond) t2 := t1.Add(time.Microsecond) - t3 := t2.Add(time.Microsecond) - t4 := t3.Add(time.Microsecond) - t5 := t4.Add(time.Microsecond) - t6 := t5.Add(time.Microsecond) - t7 := t6.Add(time.Microsecond) - t8 := t7.Add(time.Microsecond) - t9 := t8.Add(time.Microsecond) - t10 := t9.Add(time.Microsecond) - t11 := t10.Add(time.Microsecond) // Verify the truncation logic for reading logs that are longer than the // default scanner can handle. @@ -65,24 +117,8 @@ func TestEntryDecoder(t *testing.T) { reallyLongEntry := string(bytes.Repeat([]byte("a"), maxMessageLength)) tooLongEntry := reallyLongEntry + "a" - contents := formatEntry(severity.INFO, channel.DEV, t1, 0, "clog_test.go", 136, ``, "info") - contents += formatEntry(severity.INFO, channel.DEV, t2, 1, "clog_test.go", 137, ``, "multi-\nline") - contents += formatEntry(severity.INFO, channel.DEV, t3, 2, "clog_test.go", 138, ``, reallyLongEntry) - contents += formatEntry(severity.INFO, channel.DEV, t4, 3, "clog_test.go", 139, ``, tooLongEntry) - contents += formatEntry(severity.WARNING, channel.DEV, t5, 4, "clog_test.go", 140, ``, "warning") - contents += formatEntry(severity.ERROR, channel.DEV, t6, 5, "clog_test.go", 141, ``, "error") - contents += formatEntry(severity.FATAL, channel.DEV, t7, 6, "clog_test.go", 142, ``, "fatal\nstack\ntrace") - contents += formatEntry(severity.INFO, channel.DEV, t8, 7, "clog_test.go", 143, ``, tooLongEntry) - - // Regression test for #56873. - contents += formatEntry(severity.INFO, channel.DEV, t8, 8, "clog_test.go", 144, `sometags`, "foo") - contents += formatEntry(severity.INFO, channel.DEV, t8, 9, "clog_test.go", 145, ``, "bar" /* no tags */) - // Different channel. - contents += formatEntry(severity.INFO, channel.SESSIONS, t9, 10, "clog_test.go", 146, ``, "info") - // Ensure that IPv6 addresses in tags get parsed properly. - contents += formatEntry(severity.INFO, channel.DEV, t10, 11, "clog_test.go", 147, `client=[1::]:2`, "foo") - // Ensure that empty messages don't wreak havoc. - contents += formatEntry(severity.INFO, channel.DEV, t11, 12, "clog_test.go", 148, "", "") + contents := formatEntry(severity.INFO, channel.DEV, t1, 2, "clog_test.go", 138, ``, reallyLongEntry) + contents += formatEntry(severity.INFO, channel.DEV, t2, 3, "clog_test.go", 139, ``, tooLongEntry) readAllEntries := func(contents string) []logpb.Entry { decoder := NewEntryDecoder(strings.NewReader(contents), WithFlattenedSensitiveData) @@ -106,137 +142,21 @@ func TestEntryDecoder(t *testing.T) { Severity: severity.INFO, Channel: channel.DEV, Time: t1.UnixNano(), - Goroutine: 0, - File: `clog_test.go`, - Line: 136, - Message: `info`, - Counter: 2, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t2.UnixNano(), - Goroutine: 1, - File: `clog_test.go`, - Line: 137, - Message: `multi- -line`, - Counter: 3, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t3.UnixNano(), Goroutine: 2, File: `clog_test.go`, Line: 138, Message: reallyLongEntry, - Counter: 4, + Counter: 2, }, { Severity: severity.INFO, Channel: channel.DEV, - Time: t4.UnixNano(), + Time: t2.UnixNano(), Goroutine: 3, File: `clog_test.go`, Line: 139, Message: tooLongEntry[:maxMessageLength], - Counter: 5, - }, - { - Severity: severity.WARNING, - Channel: channel.DEV, - Time: t5.UnixNano(), - Goroutine: 4, - File: `clog_test.go`, - Line: 140, - Message: `warning`, - Counter: 6, - }, - { - Severity: severity.ERROR, - Channel: channel.DEV, - Time: t6.UnixNano(), - Goroutine: 5, - File: `clog_test.go`, - Line: 141, - Message: `error`, - Counter: 7, - }, - { - Severity: severity.FATAL, - Channel: channel.DEV, - Time: t7.UnixNano(), - Goroutine: 6, - File: `clog_test.go`, - Line: 142, - Message: `fatal -stack -trace`, - Counter: 8, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t8.UnixNano(), - Goroutine: 7, - File: `clog_test.go`, - Line: 143, - Message: tooLongEntry[:maxMessageLength], - Counter: 9, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t8.UnixNano(), - Goroutine: 8, - File: `clog_test.go`, - Line: 144, - Tags: `sometags`, - Message: `foo`, - Counter: 10, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t8.UnixNano(), - Goroutine: 9, - File: `clog_test.go`, - Line: 145, - Message: `bar`, - Counter: 11, - }, - { - Severity: severity.INFO, - Channel: channel.SESSIONS, - Time: t9.UnixNano(), - Goroutine: 10, - File: `clog_test.go`, - Line: 146, - Message: `info`, - Counter: 12, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t10.UnixNano(), - Goroutine: 11, - File: `clog_test.go`, - Line: 147, - Tags: `client=[1::]:2`, - Message: `foo`, - Counter: 13, - }, - { - Severity: severity.INFO, - Channel: channel.DEV, - Time: t11.UnixNano(), - Goroutine: 12, - File: `clog_test.go`, - Line: 148, - Tags: ``, - Message: ``, - Counter: 14, + Counter: 3, }, } if !reflect.DeepEqual(expected, entries) { diff --git a/pkg/util/log/testdata/crdb_v1 b/pkg/util/log/testdata/crdb_v1 new file mode 100644 index 000000000000..5a98967466c1 --- /dev/null +++ b/pkg/util/log/testdata/crdb_v1 @@ -0,0 +1,97 @@ +common +{"severity": 1, "time": 12300000000, "goroutine": 456, "file": "somefile.go", "line": 136} +---- + +entries +{"counter": 2, "message": ""} +{"counter": 3, "message": "info"} +---- +I000101 00:00:12.300000 456 somefile.go:136 2 +I000101 00:00:12.300000 456 somefile.go:136 3 info +# after parse: +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹›", Tags:"", Counter:0x2, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹info›", Tags:"", Counter:0x3, Redactable:true, Channel:0} + +entries +{"counter": 2, "message": "hello ‹world›"} +{"counter": 3, "message": "hello ‹world›", "redactable": true} +---- +I000101 00:00:12.300000 456 somefile.go:136 2 hello ‹world› +I000101 00:00:12.300000 456 somefile.go:136 ⋮ 3 hello ‹world› +# after parse: +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹hello ?world?›", Tags:"", Counter:0x2, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"hello ‹world›", Tags:"", Counter:0x3, Redactable:true, Channel:0} + + +entries +{"counter": 2, "message": "multi-\nline"} +{"counter": 3, "message": "multi-\nline", "redactable": true} +---- +I000101 00:00:12.300000 456 somefile.go:136 2 multi- +line +I000101 00:00:12.300000 456 somefile.go:136 ⋮ 3 multi- +line +# after parse: +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹multi-›\n‹line›", Tags:"", Counter:0x2, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"multi-\nline", Tags:"", Counter:0x3, Redactable:true, Channel:0} + + +entries +{"counter": 2, "severity": 2, "message": "warning"} +{"counter": 3, "severity": 3, "message": "error"} +{"counter": 4, "severity": 4, "message": "fatal"} +---- +W000101 00:00:12.300000 456 somefile.go:136 2 warning +E000101 00:00:12.300000 456 somefile.go:136 3 error +F000101 00:00:12.300000 456 somefile.go:136 4 fatal +# after parse: +logpb.Entry{Severity:2, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹warning›", Tags:"", Counter:0x2, Redactable:true, Channel:0} +logpb.Entry{Severity:3, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹error›", Tags:"", Counter:0x3, Redactable:true, Channel:0} +logpb.Entry{Severity:4, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹fatal›", Tags:"", Counter:0x4, Redactable:true, Channel:0} + +subtest regression_56873 + +entries +{"counter": 2, "tags": "sometags", "message": "foo"} +{"counter": 3, "tags": "", "message": "foo"} +---- +I000101 00:00:12.300000 456 somefile.go:136 [sometags] 2 foo +I000101 00:00:12.300000 456 somefile.go:136 3 foo +# after parse: +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"‹sometags›", Counter:0x2, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"", Counter:0x3, Redactable:true, Channel:0} + +subtest end + +subtest different_channel + +entries +{"counter": 2, "channel": 2, "message": "foo"} +---- +I000101 00:00:12.300000 456 2@somefile.go:136 2 foo +# after parse: +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"", Counter:0x2, Redactable:true, Channel:2} + +subtest end + +subtest ipv6_in_tags + +entries +{"counter": 2, "tags": "client=[1::]:2", "message": "foo"} +---- +I000101 00:00:12.300000 456 somefile.go:136 [client=[1::]:2] 2 foo +# after parse: +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"‹client=[1::]:2›", Counter:0x2, Redactable:true, Channel:0} + +subtest end + +subtest structured_entry + +entries +{"counter": 2, "message": "Structured entry: {'hello':123}", "redactable": true} +---- +I000101 00:00:12.300000 456 somefile.go:136 ⋮ 2 Structured entry: {'hello':123} +# after parse: +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"Structured entry: {'hello':123}", Tags:"", Counter:0x2, Redactable:true, Channel:0} + +subtest end From 8ed51c60bdee1098b6dc56c87ff330ac48cc9d63 Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Fri, 4 Jun 2021 20:43:30 +0200 Subject: [PATCH 3/6] util/log: make `logpb.Entry` slightly more able to represent crdb-v2 entries Prior to this change, we did not have a public data structure able to represent the various fields available in a `crdb-v2` log entry: the existing `logpb.Entry` was not able to distinguish structured and non-structured entries, and did not have the ability to delimit the message and the stack trace. This patch extends `logpb.Entry` to make it more able to represent `crdb-v2` entries, at least for the purpose of extending `debug merge-log` towards conversion between logging formats. Additionally, the patch adds a *best effort* attempt at populating the new fields in the `crdb-v1` entry parser. This is best effort because the crdb-v1 parser is lossy so we cannot faithfully parse its entries reliably. Release note: None --- docs/generated/logformats.md | 2 +- pkg/util/log/format_crdb_v1.go | 19 +++ pkg/util/log/format_crdb_v1_test.go | 7 + pkg/util/log/format_crdb_v2.go | 2 +- pkg/util/log/log_entry.go | 7 +- pkg/util/log/logpb/log.pb.go | 193 +++++++++++++++++++++------- pkg/util/log/logpb/log.proto | 22 ++++ pkg/util/log/testdata/crdb_v1 | 52 +++++--- 8 files changed, 241 insertions(+), 63 deletions(-) diff --git a/docs/generated/logformats.md b/docs/generated/logformats.md index 1ebca1bd927b..1f07098d5a4a 100644 --- a/docs/generated/logformats.md +++ b/docs/generated/logformats.md @@ -291,7 +291,7 @@ to indicate whether the remainder of the line is a structured entry, or a continuation of a previous entry. Finally, in the previous format, structured entries -were prefixed with the string `Structured entry:`. In +were prefixed with the string `Structured entry: `. In the new format, they are prefixed by the `=` continuation indicator. diff --git a/pkg/util/log/format_crdb_v1.go b/pkg/util/log/format_crdb_v1.go index 3a368868a887..c93b4e443508 100644 --- a/pkg/util/log/format_crdb_v1.go +++ b/pkg/util/log/format_crdb_v1.go @@ -471,6 +471,25 @@ func (d *EntryDecoder) Decode(entry *logpb.Entry) error { r = d.sensitiveEditor(r) entry.Message = string(r.msg) entry.Redactable = r.redactable + + if strings.HasPrefix(entry.Message, structuredEntryPrefix+"{") /* crdb-v1 prefix */ { + // Note: we do not recognize the v2 marker here (" ={") because + // v2 entries can be split across multiple lines. + entry.StructuredStart = uint32(len(structuredEntryPrefix)) + + if nl := strings.IndexByte(entry.Message, '\n'); nl != -1 { + entry.StructuredEnd = uint32(nl) + entry.StackTraceStart = uint32(nl + 1) + } else { + entry.StructuredEnd = uint32(len(entry.Message)) + } + } + // Note: we only know how to populate entry.StackTraceStart upon + // parse if the entry was structured (see above). If it is not + // structured, we cannot distinguish where the message ends and + // where the stack trace starts. This is another reason why the + // crdb-v1 format is lossy. + return nil } } diff --git a/pkg/util/log/format_crdb_v1_test.go b/pkg/util/log/format_crdb_v1_test.go index 3fe3bd8bacc6..6d80dfc59599 100644 --- a/pkg/util/log/format_crdb_v1_test.go +++ b/pkg/util/log/format_crdb_v1_test.go @@ -76,6 +76,13 @@ func TestCrdbV1EncodeDecode(t *testing.T) { buf.WriteString("# after parse:\n") for _, entry := range outputEntries { fmt.Fprintf(&buf, "%# v\n", pretty.Formatter(entry)) + if entry.StructuredEnd != 0 { + var payload interface{} + if err := json.Unmarshal([]byte(entry.Message[entry.StructuredStart:entry.StructuredEnd]), &payload); err != nil { + td.Fatalf(t, "JSON entry not parsable: %v", err) + } + fmt.Fprintf(&buf, "JSON payload in previous entry: %+v\n", payload) + } } return buf.String() diff --git a/pkg/util/log/format_crdb_v2.go b/pkg/util/log/format_crdb_v2.go index af4833c4dba0..38266391f261 100644 --- a/pkg/util/log/format_crdb_v2.go +++ b/pkg/util/log/format_crdb_v2.go @@ -143,7 +143,7 @@ to indicate whether the remainder of the line is a structured entry, or a continuation of a previous entry. Finally, in the previous format, structured entries -were prefixed with the string ` + "`Structured entry:`" + `. In +were prefixed with the string ` + "`" + structuredEntryPrefix + "`" + `. In the new format, they are prefixed by the ` + "`=`" + ` continuation indicator. `) diff --git a/pkg/util/log/log_entry.go b/pkg/util/log/log_entry.go index 2f83e9b393f0..7ccb555aaef3 100644 --- a/pkg/util/log/log_entry.go +++ b/pkg/util/log/log_entry.go @@ -248,16 +248,21 @@ func (e logEntry) convertToLegacy() (res logpb.Entry) { // At this point, the message only contains the JSON fields of the // payload. Add the decoration suitable for our legacy file // format. - res.Message = "Structured entry: {" + res.Message + "}" + res.Message = structuredEntryPrefix + "{" + res.Message + "}" + res.StructuredStart = uint32(len(structuredEntryPrefix)) + res.StructuredEnd = uint32(len(res.Message)) } if e.stacks != nil { + res.StackTraceStart = uint32(len(res.Message)) + 1 res.Message += "\n" + string(e.stacks) } return res } +const structuredEntryPrefix = "Structured entry: " + func renderTagsAsString(tags *logtags.Buffer, redactable bool) string { if redactable { return string(renderTagsAsRedactable(tags)) diff --git a/pkg/util/log/logpb/log.pb.go b/pkg/util/log/logpb/log.pb.go index 6bcded72d9a0..6517e133b68c 100644 --- a/pkg/util/log/logpb/log.pb.go +++ b/pkg/util/log/logpb/log.pb.go @@ -290,6 +290,25 @@ type Entry struct { Redactable bool `protobuf:"varint,9,opt,name=redactable,proto3" json:"redactable,omitempty"` // Channel is the channel on which the message was sent. Channel Channel `protobuf:"varint,10,opt,name=channel,proto3,enum=cockroach.util.log.Channel" json:"channel,omitempty"` + // StructuredEnd, if non-zero, indicates that the entry + // is structured; it is also the index + // inside the Message field where the JSON payload ends (exclusive). + StructuredEnd uint32 `protobuf:"varint,11,opt,name=structured_end,json=structuredEnd,proto3" json:"structured_end,omitempty"` + // StructuredStart, when StructuredEnd is non-zero, is the index + // inside the Message field where the JSON payload starts (inclusive). + StructuredStart uint32 `protobuf:"varint,12,opt,name=structured_start,json=structuredStart,proto3" json:"structured_start,omitempty"` + // StackTraceStart is the index inside Message where a detailed + // stack trace starts. If zero, no stack trace is present. Stack + // traces are always separated from the message using a newline + // character. If a stack trace is included, StackTracePosition is + // the index of the character immediately after the newline + // character. + // + // We use an index-in-string field in the protobuf, instead of two + // separate string fields, because previous-version consumers of + // Entry are still expecting the message and the stack trace in the + // same field. + StackTraceStart uint32 `protobuf:"varint,13,opt,name=stack_trace_start,json=stackTraceStart,proto3" json:"stack_trace_start,omitempty"` } func (m *Entry) Reset() { *m = Entry{} } @@ -407,50 +426,55 @@ func init() { func init() { proto.RegisterFile("util/log/logpb/log.proto", fileDescriptor_84e824ab4ae60f77) } var fileDescriptor_84e824ab4ae60f77 = []byte{ - // 683 bytes of a gzipped FileDescriptorProto - 0x1f, 0x8b, 0x08, 0x00, 0x00, 0x00, 0x00, 0x00, 0x02, 0xff, 0x6c, 0x53, 0xc1, 0x6a, 0xeb, 0x46, - 0x14, 0xb5, 0x2c, 0xc9, 0x92, 0xae, 0x1f, 0x61, 0x3a, 0xbc, 0x82, 0xda, 0x97, 0x2a, 0x26, 0x14, - 0x6a, 0xb2, 0x70, 0x20, 0xa5, 0xd0, 0x5d, 0x91, 0xed, 0x71, 0xa2, 0xd6, 0x91, 0x9d, 0x91, 0x93, - 0x94, 0x76, 0x21, 0x64, 0x7b, 0xa2, 0x88, 0x4a, 0x1a, 0x23, 0xc9, 0x85, 0xf4, 0x1f, 0x0a, 0xfd, - 0x88, 0x7e, 0x45, 0xfb, 0x03, 0x59, 0x66, 0x99, 0x55, 0x68, 0x9d, 0x1f, 0x29, 0x33, 0xb6, 0xd2, - 0xc0, 0xcb, 0xc2, 0xe6, 0x9c, 0x33, 0x67, 0xee, 0xdc, 0x39, 0x57, 0x03, 0xf6, 0xba, 0x4a, 0xd2, - 0xe3, 0x94, 0xc7, 0xe2, 0xb7, 0x9a, 0x8b, 0xff, 0xde, 0xaa, 0xe0, 0x15, 0xc7, 0x78, 0xc1, 0x17, - 0xbf, 0x14, 0x3c, 0x5a, 0xdc, 0xf6, 0x84, 0xa7, 0x97, 0xf2, 0xf8, 0xf3, 0xf7, 0x31, 0x8f, 0xb9, - 0x5c, 0x3e, 0x16, 0x68, 0xeb, 0x3c, 0xfc, 0xab, 0x09, 0x3a, 0xc9, 0xab, 0xe2, 0x0e, 0x7f, 0x0b, - 0x66, 0xc9, 0x7e, 0x65, 0x45, 0x52, 0xdd, 0xd9, 0x4a, 0x47, 0xe9, 0xee, 0x9d, 0xec, 0xf7, 0x3e, - 0x2e, 0xd3, 0x0b, 0x76, 0x1e, 0xfa, 0xe2, 0xc6, 0x18, 0xb4, 0x2a, 0xc9, 0x98, 0xdd, 0xec, 0x28, - 0x5d, 0x95, 0x4a, 0x8c, 0xf7, 0xc1, 0x8a, 0x79, 0xc1, 0xd7, 0x55, 0x92, 0x33, 0xbb, 0x25, 0x17, - 0xfe, 0x17, 0xc4, 0x8e, 0x9b, 0x24, 0x65, 0xb6, 0xda, 0x51, 0xba, 0x16, 0x95, 0x58, 0x68, 0xa9, - 0x30, 0x6b, 0xdb, 0x2a, 0x02, 0x63, 0x1b, 0x8c, 0x8c, 0x95, 0x65, 0x14, 0x33, 0x5b, 0x97, 0xd6, - 0x9a, 0xca, 0x33, 0xa3, 0xb8, 0xb4, 0x8d, 0x6d, 0x05, 0x81, 0x85, 0x7b, 0xc1, 0xd7, 0x79, 0xc5, - 0x0a, 0xdb, 0xec, 0x28, 0x5d, 0x8d, 0xd6, 0x14, 0x3b, 0x00, 0x05, 0x5b, 0x46, 0x8b, 0x2a, 0x9a, - 0xa7, 0xcc, 0xb6, 0x3a, 0x4a, 0xd7, 0xa4, 0xaf, 0x14, 0xfc, 0x0d, 0x18, 0x8b, 0xdb, 0x28, 0xcf, - 0x59, 0x6a, 0x83, 0xbc, 0xfa, 0x87, 0xb7, 0xae, 0x3e, 0xd8, 0x5a, 0x68, 0xed, 0x3d, 0xfc, 0x5d, - 0x81, 0xf6, 0x28, 0x49, 0xd9, 0x90, 0x55, 0x51, 0x92, 0xca, 0x06, 0x56, 0x05, 0x8f, 0x8b, 0x28, - 0x93, 0x09, 0x5a, 0xb4, 0xa6, 0xa2, 0xdd, 0x5b, 0x5e, 0x56, 0x32, 0x22, 0x8b, 0x4a, 0x8c, 0x3f, - 0x80, 0xb5, 0x2e, 0x59, 0x11, 0xe6, 0x51, 0x56, 0x27, 0x61, 0x0a, 0xc1, 0x8f, 0x32, 0xf6, 0x92, - 0xa9, 0xfe, 0x2a, 0xd3, 0xcf, 0x40, 0x5d, 0x25, 0xcb, 0x6d, 0x9a, 0x7d, 0x63, 0xf3, 0x74, 0xa0, - 0x4e, 0xbd, 0x21, 0x15, 0xda, 0xf7, 0x9a, 0xa9, 0x21, 0xfd, 0xf0, 0x4f, 0x05, 0x4c, 0xd1, 0x8f, - 0x97, 0xdf, 0x70, 0x51, 0x41, 0x56, 0xde, 0x76, 0x22, 0x31, 0xfe, 0x02, 0xa0, 0x4c, 0x7e, 0x63, - 0xe1, 0xfc, 0xae, 0x62, 0xe5, 0x6e, 0x5e, 0x96, 0x50, 0xfa, 0x42, 0xc0, 0x5f, 0xc2, 0x5e, 0xc6, - 0x97, 0xa1, 0x38, 0x2c, 0xcc, 0xa3, 0x9c, 0x97, 0xb2, 0x2d, 0x95, 0xbe, 0xcb, 0xf8, 0x72, 0x96, - 0x64, 0xcc, 0x17, 0x1a, 0xfe, 0x0e, 0x8c, 0xe5, 0xf6, 0xc2, 0x72, 0x56, 0xed, 0x93, 0x83, 0xb7, - 0xc2, 0x7a, 0x95, 0x4b, 0x5f, 0xbb, 0x7f, 0x3a, 0x68, 0xd0, 0x7a, 0xd7, 0xd1, 0xcf, 0x60, 0xd6, - 0x5f, 0x11, 0x6e, 0x83, 0x71, 0xe9, 0xff, 0xe0, 0x4f, 0xae, 0x7d, 0xd4, 0xc0, 0x26, 0x68, 0x9e, - 0x3f, 0x9a, 0x20, 0x45, 0xc8, 0xd7, 0x2e, 0xf5, 0x3d, 0xff, 0x14, 0x35, 0xb1, 0x05, 0x3a, 0xa1, - 0x74, 0x42, 0x91, 0x2a, 0xe0, 0xc8, 0x9d, 0xb9, 0x63, 0xa4, 0x09, 0xb3, 0x3f, 0xf1, 0x09, 0xd2, - 0x85, 0x79, 0x48, 0x46, 0xee, 0xe5, 0x78, 0x86, 0x5a, 0x47, 0x7f, 0x2b, 0x60, 0xec, 0x06, 0x85, - 0x0d, 0x50, 0x87, 0xe4, 0x0a, 0x35, 0x04, 0x98, 0x4c, 0x03, 0xa4, 0x60, 0x80, 0xd6, 0x19, 0x71, - 0xc7, 0xb3, 0x33, 0xd4, 0x14, 0xdb, 0x82, 0xd9, 0x84, 0xba, 0xa7, 0x04, 0xa9, 0xf8, 0x1d, 0x98, - 0x01, 0x09, 0x02, 0x6f, 0xe2, 0x07, 0x48, 0xc3, 0x7b, 0x00, 0xc1, 0xc5, 0x38, 0x0c, 0x06, 0x67, - 0xe4, 0xdc, 0x45, 0xba, 0xe0, 0x97, 0x01, 0xa1, 0xa1, 0x3b, 0x3c, 0xf7, 0x7c, 0xd4, 0x12, 0x7c, - 0x4a, 0xbd, 0x2b, 0x6f, 0x4c, 0x4e, 0x49, 0x80, 0x0c, 0xfc, 0x1e, 0x50, 0x40, 0xfc, 0xc0, 0x9b, - 0x79, 0x57, 0x24, 0x74, 0x07, 0x03, 0x12, 0x04, 0xc8, 0x94, 0x35, 0x2f, 0xc6, 0x21, 0xf9, 0x91, - 0x0c, 0x90, 0x55, 0xb3, 0x29, 0xa1, 0x23, 0x04, 0xf8, 0x53, 0xf8, 0x44, 0x30, 0xcf, 0x9f, 0x11, - 0xea, 0xbb, 0x3b, 0xb9, 0xdd, 0xff, 0xea, 0xfe, 0x5f, 0xa7, 0x71, 0xbf, 0x71, 0x94, 0x87, 0x8d, - 0xa3, 0x3c, 0x6e, 0x1c, 0xe5, 0x9f, 0x8d, 0xa3, 0xfc, 0xf1, 0xec, 0x34, 0x1e, 0x9e, 0x9d, 0xc6, - 0xe3, 0xb3, 0xd3, 0xf8, 0x49, 0x97, 0x6f, 0x7d, 0xde, 0x92, 0xcf, 0xf7, 0xeb, 0xff, 0x02, 0x00, - 0x00, 0xff, 0xff, 0x14, 0x81, 0x8f, 0xee, 0x04, 0x04, 0x00, 0x00, + // 753 bytes of a gzipped FileDescriptorProto + 0x1f, 0x8b, 0x08, 0x00, 0x00, 0x00, 0x00, 0x00, 0x02, 0xff, 0x6c, 0x94, 0xd1, 0x6e, 0xdb, 0x36, + 0x14, 0x86, 0xad, 0x48, 0xb6, 0xa4, 0xe3, 0x24, 0x63, 0x89, 0x0e, 0xd0, 0xd6, 0x4e, 0x31, 0x82, + 0x0d, 0xf3, 0x72, 0xe1, 0x02, 0x1d, 0x06, 0xec, 0x6e, 0x50, 0x6c, 0x3a, 0xd1, 0xe6, 0xca, 0x29, + 0xe9, 0xa4, 0xc3, 0x76, 0x21, 0x28, 0x32, 0xeb, 0x08, 0x91, 0xc4, 0x40, 0xa2, 0x07, 0x64, 0xef, + 0x30, 0x60, 0x0f, 0xb1, 0x87, 0x18, 0xb0, 0x17, 0xc8, 0x65, 0x2f, 0x7b, 0x55, 0x6c, 0xce, 0x8b, + 0x0c, 0xa4, 0xad, 0xc6, 0x40, 0x7b, 0x61, 0xe3, 0x3f, 0xbf, 0x3e, 0x1e, 0xf2, 0xf0, 0x1c, 0x10, + 0xbc, 0xa5, 0xcc, 0xf2, 0x67, 0xb9, 0x58, 0xa8, 0xdf, 0xcd, 0xa5, 0xfa, 0x1f, 0xdc, 0x54, 0x42, + 0x0a, 0x8c, 0x53, 0x91, 0x5e, 0x57, 0x22, 0x49, 0xaf, 0x06, 0x8a, 0x19, 0xe4, 0x62, 0xf1, 0xf9, + 0xe3, 0x85, 0x58, 0x08, 0xfd, 0xf9, 0x99, 0x52, 0x6b, 0xf2, 0xf0, 0x6f, 0x13, 0xda, 0xa4, 0x94, + 0xd5, 0x2d, 0xfe, 0x1e, 0x9c, 0x9a, 0xff, 0xc6, 0xab, 0x4c, 0xde, 0x7a, 0x46, 0xcf, 0xe8, 0xef, + 0x3f, 0x7f, 0x3a, 0xf8, 0x30, 0xcd, 0x80, 0x6d, 0x18, 0xfa, 0x9e, 0xc6, 0x18, 0x2c, 0x99, 0x15, + 0xdc, 0xdb, 0xe9, 0x19, 0x7d, 0x93, 0x6a, 0x8d, 0x9f, 0x82, 0xbb, 0x10, 0x95, 0x58, 0xca, 0xac, + 0xe4, 0x5e, 0x47, 0x7f, 0x78, 0x30, 0xd4, 0x8a, 0xd7, 0x59, 0xce, 0x3d, 0xb3, 0x67, 0xf4, 0x5d, + 0xaa, 0xb5, 0xf2, 0x72, 0x05, 0x5b, 0xeb, 0x2c, 0x4a, 0x63, 0x0f, 0xec, 0x82, 0xd7, 0x75, 0xb2, + 0xe0, 0x5e, 0x5b, 0xa3, 0x4d, 0xa8, 0xf7, 0x4c, 0x16, 0xb5, 0x67, 0xaf, 0x33, 0x28, 0xad, 0xe8, + 0x54, 0x2c, 0x4b, 0xc9, 0x2b, 0xcf, 0xe9, 0x19, 0x7d, 0x8b, 0x36, 0x21, 0xf6, 0x01, 0x2a, 0x3e, + 0x4f, 0x52, 0x99, 0x5c, 0xe6, 0xdc, 0x73, 0x7b, 0x46, 0xdf, 0xa1, 0x5b, 0x0e, 0xfe, 0x0e, 0xec, + 0xf4, 0x2a, 0x29, 0x4b, 0x9e, 0x7b, 0xa0, 0x4b, 0x7f, 0xf2, 0xb1, 0xd2, 0x87, 0x6b, 0x84, 0x36, + 0x2c, 0xfe, 0x0a, 0xf6, 0x6b, 0x59, 0x2d, 0x53, 0xb9, 0xac, 0xf8, 0x3c, 0xe6, 0xe5, 0xdc, 0xeb, + 0xf6, 0x8c, 0xfe, 0x1e, 0xdd, 0x7b, 0x70, 0x49, 0x39, 0xc7, 0xdf, 0x00, 0xda, 0xc2, 0x6a, 0x99, + 0x54, 0xd2, 0xdb, 0xd5, 0xe0, 0x27, 0x0f, 0x3e, 0x53, 0x36, 0x3e, 0x82, 0x47, 0xb5, 0x4c, 0xd2, + 0xeb, 0x58, 0x56, 0x49, 0xca, 0x37, 0xec, 0x5e, 0xc3, 0x26, 0xe9, 0xf5, 0x4c, 0xf9, 0x9a, 0x3d, + 0xfc, 0xc3, 0x80, 0xee, 0x38, 0xcb, 0xf9, 0x88, 0xcb, 0x24, 0xcb, 0x75, 0xf9, 0x37, 0x95, 0x58, + 0x54, 0x49, 0xa1, 0xfb, 0xe7, 0xd2, 0x26, 0x54, 0x97, 0x75, 0x25, 0x6a, 0xa9, 0x1b, 0xe4, 0x52, + 0xad, 0xf1, 0x13, 0x70, 0x97, 0x35, 0xaf, 0xe2, 0x32, 0x29, 0x9a, 0x3e, 0x38, 0xca, 0x88, 0x92, + 0x82, 0xbf, 0xef, 0x68, 0x7b, 0xab, 0xa3, 0x9f, 0x81, 0x79, 0x93, 0xcd, 0xd7, 0xbd, 0x3c, 0xb6, + 0x57, 0xef, 0x0e, 0xcc, 0xb3, 0x70, 0x44, 0x95, 0xf7, 0xa3, 0xe5, 0x58, 0xa8, 0x7d, 0xf8, 0x97, + 0x01, 0x8e, 0x3a, 0x4f, 0x58, 0xbe, 0x16, 0x2a, 0x83, 0xce, 0xbc, 0x3e, 0x89, 0xd6, 0xf8, 0x0b, + 0x80, 0x3a, 0xfb, 0x9d, 0xc7, 0x97, 0xb7, 0x92, 0xd7, 0x9b, 0x69, 0x71, 0x95, 0x73, 0xac, 0x0c, + 0xfc, 0x25, 0xec, 0x17, 0x62, 0x1e, 0xab, 0xcd, 0xe2, 0x32, 0x29, 0x45, 0xad, 0x8f, 0x65, 0xd2, + 0xdd, 0x42, 0xcc, 0x67, 0x59, 0xc1, 0x23, 0xe5, 0xe1, 0x1f, 0xc0, 0x9e, 0xaf, 0x0b, 0xd6, 0x93, + 0xd2, 0x7d, 0x7e, 0xf0, 0xb1, 0x56, 0x6d, 0xdd, 0xcb, 0xb1, 0x75, 0xf7, 0xee, 0xa0, 0x45, 0x9b, + 0x55, 0x47, 0xbf, 0x82, 0xd3, 0xcc, 0x30, 0xee, 0x82, 0x7d, 0x1e, 0xfd, 0x14, 0x4d, 0x5f, 0x45, + 0xa8, 0x85, 0x1d, 0xb0, 0xc2, 0x68, 0x3c, 0x45, 0x86, 0xb2, 0x5f, 0x05, 0x34, 0x0a, 0xa3, 0x13, + 0xb4, 0x83, 0x5d, 0x68, 0x13, 0x4a, 0xa7, 0x14, 0x99, 0x4a, 0x8e, 0x83, 0x59, 0x30, 0x41, 0x96, + 0x82, 0xa3, 0x69, 0x44, 0x50, 0x5b, 0xc1, 0x23, 0x32, 0x0e, 0xce, 0x27, 0x33, 0xd4, 0x39, 0xfa, + 0xc7, 0x00, 0x7b, 0x33, 0x26, 0xd8, 0x06, 0x73, 0x44, 0x2e, 0x50, 0x4b, 0x89, 0xe9, 0x19, 0x43, + 0x06, 0x06, 0xe8, 0x9c, 0x92, 0x60, 0x32, 0x3b, 0x45, 0x3b, 0x6a, 0x19, 0x9b, 0x4d, 0x69, 0x70, + 0x42, 0x90, 0x89, 0x77, 0xc1, 0x61, 0x84, 0xb1, 0x70, 0x1a, 0x31, 0x64, 0xe1, 0x7d, 0x00, 0xf6, + 0x72, 0x12, 0xb3, 0xe1, 0x29, 0x79, 0x11, 0xa0, 0xb6, 0x8a, 0xcf, 0x19, 0xa1, 0x71, 0x30, 0x7a, + 0x11, 0x46, 0xa8, 0xa3, 0xe2, 0x33, 0x1a, 0x5e, 0x84, 0x13, 0x72, 0x42, 0x18, 0xb2, 0xf1, 0x63, + 0x40, 0x8c, 0x44, 0x2c, 0x9c, 0x85, 0x17, 0x24, 0x0e, 0x86, 0x43, 0xc2, 0x18, 0x72, 0x74, 0xce, + 0x97, 0x93, 0x98, 0xfc, 0x4c, 0x86, 0xc8, 0x6d, 0xa2, 0x33, 0x42, 0xc7, 0x08, 0xf0, 0xa7, 0xf0, + 0x48, 0x45, 0x61, 0x34, 0x23, 0x34, 0x0a, 0x36, 0x76, 0xf7, 0xf8, 0xeb, 0xbb, 0xff, 0xfc, 0xd6, + 0xdd, 0xca, 0x37, 0xde, 0xac, 0x7c, 0xe3, 0xed, 0xca, 0x37, 0xfe, 0x5d, 0xf9, 0xc6, 0x9f, 0xf7, + 0x7e, 0xeb, 0xcd, 0xbd, 0xdf, 0x7a, 0x7b, 0xef, 0xb7, 0x7e, 0x69, 0xeb, 0x97, 0xe6, 0xb2, 0xa3, + 0x1f, 0x8f, 0x6f, 0xff, 0x0f, 0x00, 0x00, 0xff, 0xff, 0xc5, 0x77, 0x0c, 0x15, 0x82, 0x04, 0x00, + 0x00, } func (m *Entry) Marshal() (dAtA []byte, err error) { @@ -473,6 +497,21 @@ func (m *Entry) MarshalToSizedBuffer(dAtA []byte) (int, error) { _ = i var l int _ = l + if m.StackTraceStart != 0 { + i = encodeVarintLog(dAtA, i, uint64(m.StackTraceStart)) + i-- + dAtA[i] = 0x68 + } + if m.StructuredStart != 0 { + i = encodeVarintLog(dAtA, i, uint64(m.StructuredStart)) + i-- + dAtA[i] = 0x60 + } + if m.StructuredEnd != 0 { + i = encodeVarintLog(dAtA, i, uint64(m.StructuredEnd)) + i-- + dAtA[i] = 0x58 + } if m.Channel != 0 { i = encodeVarintLog(dAtA, i, uint64(m.Channel)) i-- @@ -691,6 +730,15 @@ func (m *Entry) Size() (n int) { if m.Channel != 0 { n += 1 + sovLog(uint64(m.Channel)) } + if m.StructuredEnd != 0 { + n += 1 + sovLog(uint64(m.StructuredEnd)) + } + if m.StructuredStart != 0 { + n += 1 + sovLog(uint64(m.StructuredStart)) + } + if m.StackTraceStart != 0 { + n += 1 + sovLog(uint64(m.StackTraceStart)) + } return n } @@ -1007,6 +1055,63 @@ func (m *Entry) Unmarshal(dAtA []byte) error { break } } + case 11: + if wireType != 0 { + return fmt.Errorf("proto: wrong wireType = %d for field StructuredEnd", wireType) + } + m.StructuredEnd = 0 + for shift := uint(0); ; shift += 7 { + if shift >= 64 { + return ErrIntOverflowLog + } + if iNdEx >= l { + return io.ErrUnexpectedEOF + } + b := dAtA[iNdEx] + iNdEx++ + m.StructuredEnd |= uint32(b&0x7F) << shift + if b < 0x80 { + break + } + } + case 12: + if wireType != 0 { + return fmt.Errorf("proto: wrong wireType = %d for field StructuredStart", wireType) + } + m.StructuredStart = 0 + for shift := uint(0); ; shift += 7 { + if shift >= 64 { + return ErrIntOverflowLog + } + if iNdEx >= l { + return io.ErrUnexpectedEOF + } + b := dAtA[iNdEx] + iNdEx++ + m.StructuredStart |= uint32(b&0x7F) << shift + if b < 0x80 { + break + } + } + case 13: + if wireType != 0 { + return fmt.Errorf("proto: wrong wireType = %d for field StackTraceStart", wireType) + } + m.StackTraceStart = 0 + for shift := uint(0); ; shift += 7 { + if shift >= 64 { + return ErrIntOverflowLog + } + if iNdEx >= l { + return io.ErrUnexpectedEOF + } + b := dAtA[iNdEx] + iNdEx++ + m.StackTraceStart |= uint32(b&0x7F) << shift + if b < 0x80 { + break + } + } default: iNdEx = preIndex skippy, err := skipLog(dAtA[iNdEx:]) diff --git a/pkg/util/log/logpb/log.proto b/pkg/util/log/logpb/log.proto index bf3f99ff3d9e..0099e3f21515 100644 --- a/pkg/util/log/logpb/log.proto +++ b/pkg/util/log/logpb/log.proto @@ -226,6 +226,28 @@ message Entry { // Channel is the channel on which the message was sent. Channel channel = 10; + + // StructuredEnd, if non-zero, indicates that the entry + // is structured; it is also the index + // inside the Message field where the JSON payload ends (exclusive). + uint32 structured_end = 11; + + // StructuredStart, when StructuredEnd is non-zero, is the index + // inside the Message field where the JSON payload starts (inclusive). + uint32 structured_start = 12; + + // StackTraceStart is the index inside Message where a detailed + // stack trace starts. If zero, no stack trace is present. Stack + // traces are always separated from the message using a newline + // character. If a stack trace is included, StackTracePosition is + // the index of the character immediately after the newline + // character. + // + // We use an index-in-string field in the protobuf, instead of two + // separate string fields, because previous-version consumers of + // Entry are still expecting the message and the stack trace in the + // same field. + uint32 stack_trace_start = 13; } // A FileDetails holds all of the particulars that can be parsed by the name of diff --git a/pkg/util/log/testdata/crdb_v1 b/pkg/util/log/testdata/crdb_v1 index 5a98967466c1..728ef03a5d1e 100644 --- a/pkg/util/log/testdata/crdb_v1 +++ b/pkg/util/log/testdata/crdb_v1 @@ -9,8 +9,8 @@ entries I000101 00:00:12.300000 456 somefile.go:136 2 I000101 00:00:12.300000 456 somefile.go:136 3 info # after parse: -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹›", Tags:"", Counter:0x2, Redactable:true, Channel:0} -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹info›", Tags:"", Counter:0x3, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹›", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹info›", Tags:"", Counter:0x3, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} entries {"counter": 2, "message": "hello ‹world›"} @@ -19,8 +19,8 @@ entries I000101 00:00:12.300000 456 somefile.go:136 2 hello ‹world› I000101 00:00:12.300000 456 somefile.go:136 ⋮ 3 hello ‹world› # after parse: -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹hello ?world?›", Tags:"", Counter:0x2, Redactable:true, Channel:0} -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"hello ‹world›", Tags:"", Counter:0x3, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹hello ?world?›", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"hello ‹world›", Tags:"", Counter:0x3, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} entries @@ -32,8 +32,8 @@ line I000101 00:00:12.300000 456 somefile.go:136 ⋮ 3 multi- line # after parse: -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹multi-›\n‹line›", Tags:"", Counter:0x2, Redactable:true, Channel:0} -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"multi-\nline", Tags:"", Counter:0x3, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹multi-›\n‹line›", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"multi-\nline", Tags:"", Counter:0x3, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} entries @@ -45,9 +45,9 @@ W000101 00:00:12.300000 456 somefile.go:136 2 warning E000101 00:00:12.300000 456 somefile.go:136 3 error F000101 00:00:12.300000 456 somefile.go:136 4 fatal # after parse: -logpb.Entry{Severity:2, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹warning›", Tags:"", Counter:0x2, Redactable:true, Channel:0} -logpb.Entry{Severity:3, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹error›", Tags:"", Counter:0x3, Redactable:true, Channel:0} -logpb.Entry{Severity:4, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹fatal›", Tags:"", Counter:0x4, Redactable:true, Channel:0} +logpb.Entry{Severity:2, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹warning›", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +logpb.Entry{Severity:3, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹error›", Tags:"", Counter:0x3, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +logpb.Entry{Severity:4, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹fatal›", Tags:"", Counter:0x4, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} subtest regression_56873 @@ -58,8 +58,8 @@ entries I000101 00:00:12.300000 456 somefile.go:136 [sometags] 2 foo I000101 00:00:12.300000 456 somefile.go:136 3 foo # after parse: -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"‹sometags›", Counter:0x2, Redactable:true, Channel:0} -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"", Counter:0x3, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"‹sometags›", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"", Counter:0x3, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} subtest end @@ -70,7 +70,7 @@ entries ---- I000101 00:00:12.300000 456 2@somefile.go:136 2 foo # after parse: -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"", Counter:0x2, Redactable:true, Channel:2} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"", Counter:0x2, Redactable:true, Channel:2, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} subtest end @@ -81,17 +81,37 @@ entries ---- I000101 00:00:12.300000 456 somefile.go:136 [client=[1::]:2] 2 foo # after parse: -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"‹client=[1::]:2›", Counter:0x2, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"‹foo›", Tags:"‹client=[1::]:2›", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} subtest end subtest structured_entry entries -{"counter": 2, "message": "Structured entry: {'hello':123}", "redactable": true} +{"counter": 2, "message": "Structured entry: {\"hello\":123}", "redactable": true} +{"counter": 2, "message": "Structured entry: {\"hello\":123}\nstack trace:\nfoo", "redactable": true} ---- -I000101 00:00:12.300000 456 somefile.go:136 ⋮ 2 Structured entry: {'hello':123} +I000101 00:00:12.300000 456 somefile.go:136 ⋮ 2 Structured entry: {"hello":123} +I000101 00:00:12.300000 456 somefile.go:136 ⋮ 2 Structured entry: {"hello":123} +stack trace: +foo # after parse: -logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"Structured entry: {'hello':123}", Tags:"", Counter:0x2, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"Structured entry: {\"hello\":123}", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x1f, StructuredStart:0x12, StackTraceStart:0x0} +JSON payload in previous entry: map[hello:123] +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:"Structured entry: {\"hello\":123}\nstack trace:\nfoo", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x1f, StructuredStart:0x12, StackTraceStart:0x20} +JSON payload in previous entry: map[hello:123] + +# v2 entries are not treated specially in the v1 parser. +entries +{"counter": 2, "message": " ={\"hello\":123}", "redactable": true} +{"counter": 2, "message": " ={\"hello\":123}\nstack trace:\nfoo", "redactable": true} +---- +I000101 00:00:12.300000 456 somefile.go:136 ⋮ 2 ={"hello":123} +I000101 00:00:12.300000 456 somefile.go:136 ⋮ 2 ={"hello":123} +stack trace: +foo +# after parse: +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:" ={\"hello\":123}", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +logpb.Entry{Severity:1, Time:946684812300000000, Goroutine:456, File:"somefile.go", Line:136, Message:" ={\"hello\":123}\nstack trace:\nfoo", Tags:"", Counter:0x2, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} subtest end From c07e44089a47e5e695d66b6bce50dfeec863dc5e Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Mon, 7 Jun 2021 13:41:32 +0200 Subject: [PATCH 4/6] util/log: report the logging format at the start of new files Release note (cli change): When log entries are written to disk, the first few header lines written at the start of every new file now report the configured logging format. --- pkg/util/log/log_entry.go | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/pkg/util/log/log_entry.go b/pkg/util/log/log_entry.go index 7ccb555aaef3..2067ee97752a 100644 --- a/pkg/util/log/log_entry.go +++ b/pkg/util/log/log_entry.go @@ -221,8 +221,13 @@ func (l *sinkInfo) getStartLines(now time.Time) []*buffer { // Including a non-ascii character in the first 1024 bytes of the log helps // viewers that attempt to guess the character encoding. - messages = append(messages, - makeStartLine(f, "line format: [IWEF]yymmdd hh:mm:ss.uuuuuu goid file:line msg utf8=\u2713")) + messages = append(messages, makeStartLine(f, "log format (utf8=\u2713): %s", Safe(f.formatterName()))) + + if strings.HasPrefix(f.formatterName(), "crdb-") { + // For the crdb file formats, suggest the structure of each log line. + messages = append(messages, + makeStartLine(f, `line format: [IWEF]yymmdd hh:mm:ss.uuuuuu goid [chan@]file:line redactionmark \[tags\] [counter] msg`)) + } return messages } From 4840a4a6a799d9f471b7348e3b65ecd44d0494bc Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Mon, 7 Jun 2021 13:48:16 +0200 Subject: [PATCH 5/6] logconfig: fix the handling of crdb-v1 explicit config Release note (bug fix): Previously, `--log='file-defaults: {format: crdb-v1}'` was not handled properly. This has been fixed. This bug existed since v21.1.0. --- pkg/util/log/logconfig/validate.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkg/util/log/logconfig/validate.go b/pkg/util/log/logconfig/validate.go index 3acdc4866b40..4c09005c71b9 100644 --- a/pkg/util/log/logconfig/validate.go +++ b/pkg/util/log/logconfig/validate.go @@ -326,7 +326,7 @@ func (c *Config) validateFileSinkConfig(fc *FileSinkConfig, defaultLogDir *strin fc.BufferedWrites = &bf fc.Criticality = &bt if *fc.Format == "crdb-v1" { - s := "`crdb-v1-count" + s := "crdb-v1-count" fc.Format = &s } } From 1456c73c76100a465642578ac3c0b94a6190f7ec Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Mon, 7 Jun 2021 13:49:30 +0200 Subject: [PATCH 6/6] cli: report explicit log config in logs This increases troubleshootability. Release note: None --- pkg/cli/log_flags.go | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/pkg/cli/log_flags.go b/pkg/cli/log_flags.go index ff0a0a80fc57..daefbad548e3 100644 --- a/pkg/cli/log_flags.go +++ b/pkg/cli/log_flags.go @@ -179,6 +179,11 @@ func setupLogging(ctx context.Context, cmd *cobra.Command, isServerCmd, applyCon return err } + // If using a custom config, report the configuration at the start of the logging stream. + if cliCtx.logConfigInput.isSet { + log.Ops.Infof(ctx, "using explicit logging configuration:\n%s", cliCtx.logConfigInput.s) + } + if cliCtx.ambiguousLogDir { // Note that we can't report this message earlier, because the log directory // may not have been ready before the call to MkdirAll() above.