diff --git a/pkg/cli/debug.go b/pkg/cli/debug.go index 699cd498d329..17a0e56ae6d0 100644 --- a/pkg/cli/debug.go +++ b/pkg/cli/debug.go @@ -1239,7 +1239,7 @@ func removeDeadReplicas( return batch, nil } -var debugMergeLogsCommand = &cobra.Command{ +var debugMergeLogsCmd = &cobra.Command{ Use: "merge-logs ", Short: "merge multiple log files from different machines into a single stream", Long: ` @@ -1314,7 +1314,7 @@ var debugCmds = append(DebugCmdsForRocksDB, debugUnsafeRemoveDeadReplicasCmd, debugEnvCmd, debugZipCmd, - debugMergeLogsCommand, + debugMergeLogsCmd, debugListFilesCmd, debugResetQuorumCmd, ) @@ -1410,7 +1410,7 @@ func init() { f.IntSliceVar(&removeDeadReplicasOpts.deadStoreIDs, "dead-store-ids", nil, "list of dead store IDs") - f = debugMergeLogsCommand.Flags() + f = debugMergeLogsCmd.Flags() f.Var(flagutil.Time(&debugMergeLogsOpts.from), "from", "time before which messages should be filtered") // TODO(knz): the "to" should be named "until" - it's a time boundary, not a space boundary. diff --git a/pkg/cli/debug_merge_logs_test.go b/pkg/cli/debug_merge_logs_test.go index 0b75f653407c..d1d0b940238c 100644 --- a/pkg/cli/debug_merge_logs_test.go +++ b/pkg/cli/debug_merge_logs_test.go @@ -156,16 +156,16 @@ var cases = []testCase{ func (c testCase) run(t *testing.T) { outBuf := bytes.Buffer{} - debugMergeLogsCommand.Flags().Visit(func(f *pflag.Flag) { + debugMergeLogsCmd.Flags().Visit(func(f *pflag.Flag) { if err := f.Value.Set(f.DefValue); err != nil { t.Fatalf("Failed to set flag to default: %v", err) } }) - debugMergeLogsCommand.SetOutput(&outBuf) - if err := debugMergeLogsCommand.ParseFlags(c.flags); err != nil { + debugMergeLogsCmd.SetOutput(&outBuf) + if err := debugMergeLogsCmd.ParseFlags(c.flags); err != nil { t.Fatalf("Failed to set flags: %v", err) } - if err := debugMergeLogsCommand.RunE(debugMergeLogsCommand, c.args); err != nil { + if err := debugMergeLogsCmd.RunE(debugMergeLogsCmd, c.args); err != nil { t.Fatalf("Failed to run command: %v", err) } // The expected output lives in filepath.Join(testdataPath, "results", testCase.name) diff --git a/pkg/util/log/format_crdb_v2.go b/pkg/util/log/format_crdb_v2.go index af4833c4dba0..c46e3781c1a2 100644 --- a/pkg/util/log/format_crdb_v2.go +++ b/pkg/util/log/format_crdb_v2.go @@ -11,10 +11,16 @@ package log import ( + "fmt" + "io" + "regexp" + "strconv" "strings" + "time" "unicode/utf8" "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/cockroachdb/redact" @@ -447,3 +453,133 @@ func (buf *buffer) maybeMultiLine( var startRedactionMarker = string(redact.StartMarker()) var endRedactionMarker = string(redact.EndMarker()) var markersStartWithMultiByteRune = startRedactionMarker[0] >= utf8.RuneSelf && endRedactionMarker[0] >= utf8.RuneSelf + +// We don't include a capture group for the log message here, just for the +// preamble, because a capture group that handles multiline messages is very +// slow when running on the large buffers passed to EntryDecoder.split. +var entryREV2 = regexp.MustCompile( + `(?m)^` + + /* Severity */ `([IWEF])` + + /* Date and time */ `(\d{6} \d{2}:\d{2}:\d{2}.\d{6}) ` + + /* Goroutine ID */ `(?:(\d+) )` + + /* Go standard library flag */ `(\(gostd\) )?` + + /* Channel */ `(\d+@)?` + + /* File */ `([^:]+):` + + /* Line */ `(?:(\d+) )` + + /* Redactable flag */ `((?:` + redactableIndicator + `)?) ` + + /* Context tags */ `(?:\[((?:[^]]|\][^ ])+)\] )` + + /* Counter */ `((?:\d+)?) ` + + /* Continuation marker */ `([ =!+|])` + + /* Message */ `(.*)$`, +) + +// EntryDecoderV2 reads successive encoded log entries from the data. +type EntryDecoderV2 struct { + re *regexp.Regexp + data []byte +} + +// NewEntryDecoderV2 creates a new instance of EntryDecoderV2. +func NewEntryDecoderV2(data []byte) *EntryDecoderV2 { + return &EntryDecoderV2{ + re: entryREV2, + data: data, + } +} + +// DecodeV2 decodes the next log entry into the provided protobuf message. +func (d *EntryDecoderV2) DecodeV2(entry *logpb.Entry) error { + m := d.re.FindSubmatch(d.data) + if m == nil { + return io.EOF + } + + // Erase all the fields, to be sure. + *entry = logpb.Entry{} + + // Process the severity. + entry.Severity = Severity(strings.IndexByte(severityChar, m[1][0]) + 1) + + // Process the timestamp. + t, err := time.Parse(MessageTimeFormat, string(m[2])) + if err != nil { + return err + } + entry.Time = t.UnixNano() + + // Process the goroutine ID. + goroutine, err := strconv.Atoi(string(m[3])) + if err != nil { + return err + } + entry.Goroutine = int64(goroutine) + + // Process the channel. + if len(string(m[5])) != 0 { + ch, err := strconv.Atoi(string(m[5])[:len(string(m[5]))-1]) + if err != nil { + return err + } + entry.Channel = Channel(ch) + } + + // Process the file. + entry.File = string(m[6]) + + // Process the line. + line, err := strconv.Atoi(string(m[7])) + if err != nil { + return err + } + entry.Line = int64(line) + + // Process the redactable marker. + entry.Redactable = len(m[8]) != 0 + + // Process the context tags. + entry.Tags = string(m[9]) + + // Process the counter. + if len(m[10]) != 0 { + counter, err := strconv.Atoi(string(m[10])) + if err != nil { + return err + } + entry.Counter = uint64(counter) + } + + // Process the log message. + // While the entry has additional lines, collect the full message. + var entryMsg strings.Builder + + fmt.Fprintf(&entryMsg, string(trimFinalNewLines(m[12]))) + + linesLoop:for { + // Remove the top line from the log data. + d.data = d.data[len(m[0]):] + + // Match the next line in the log data. + m = d.re.FindSubmatch(d.data) + if m == nil { + break + } + + // Determine whether this line is a continuation of the entry and append the message accordingly. + cont := string(m[11]) + msg := string(m[12]) + switch cont { + case "+": + fmt.Fprintf(&entryMsg, "\n"+msg) + case "|": + fmt.Fprintf(&entryMsg, msg) + case "!": + fmt.Fprintf(&entryMsg, "\nstack trace:\n"+msg) + default: + break linesLoop + } + } + + entry.Message = entryMsg.String() + + return nil +} diff --git a/pkg/util/log/format_crdb_v2_test.go b/pkg/util/log/format_crdb_v2_test.go index 2846a62852b9..8bcc9a221a34 100644 --- a/pkg/util/log/format_crdb_v2_test.go +++ b/pkg/util/log/format_crdb_v2_test.go @@ -14,15 +14,18 @@ import ( "bytes" "context" "fmt" + "io" "strings" "testing" "time" "github.com/cockroachdb/cockroach/pkg/util/log/channel" "github.com/cockroachdb/cockroach/pkg/util/log/eventpb" + "github.com/cockroachdb/cockroach/pkg/util/log/logpb" "github.com/cockroachdb/cockroach/pkg/util/log/severity" "github.com/cockroachdb/datadriven" "github.com/cockroachdb/logtags" + "github.com/kr/pretty" ) func TestFormatCrdbV2(t *testing.T) { @@ -178,3 +181,29 @@ func TestFormatCrdbV2LongLineBreaks(t *testing.T) { return out }) } + +func TestFormatCrdbV2Decode(t *testing.T) { + datadriven.RunTest(t, "testdata/parse", + func(t *testing.T, td *datadriven.TestData) string { + switch td.Cmd { + case "log": + var out strings.Builder + d := NewEntryDecoderV2([]byte(td.Input)) + for { + var e logpb.Entry + if err := d.DecodeV2(&e); err != nil { + if err == io.EOF { + break + } + td.Fatalf(t, "error while decoding: %v", err) + } + fmt.Fprintf(&out, "%# v \n", pretty.Formatter(e)) + } + return out.String() + default: + t.Fatalf("unknown directive: %q", td.Cmd) + } + // unreachable + return "" + }) +} diff --git a/pkg/util/log/testdata/parse b/pkg/util/log/testdata/parse new file mode 100644 index 000000000000..9cbde665d9e0 --- /dev/null +++ b/pkg/util/log/testdata/parse @@ -0,0 +1,218 @@ +subtest single_line_unstructured_entry + +log +I210116 21:49:17.073282 14 server/node.go:464 ⋮ [-] 23 started with engine type ‹2› +---- +logpb.Entry{Severity:1, Time:1610833757073282000, Goroutine:14, File:"server/node.go", Line:464, Message:"started with engine type ‹2›", Tags:"-", Counter:0x17, Redactable:true, Channel:0} + +log +I210116 21:49:17.073282 14 (gostd) server/node.go:464 ⋮ [-] 23 started with engine type ‹2› +---- +logpb.Entry{Severity:1, Time:1610833757073282000, Goroutine:14, File:"server/node.go", Line:464, Message:"started with engine type ‹2›", Tags:"-", Counter:0x17, Redactable:true, Channel:0} + +subtest end + +subtest multiline_unstructured_entry + +log +I210116 21:49:17.083093 14 1@cli/start.go:690 ⋮ [-] 40 node startup completed: +I210116 21:49:17.083093 14 1@cli/start.go:690 ⋮ [-] 40 +CockroachDB node starting at 2021-01-16 21:49 (took 0.0s) +---- +logpb.Entry{Severity:1, Time:1610833757083093000, Goroutine:14, File:"cli/start.go", Line:690, Message:"node startup completed:\nCockroachDB node starting at 2021-01-16 21:49 (took 0.0s)", Tags:"-", Counter:0x28, Redactable:true, Channel:1} + +log +I210116 21:49:17.083093 14 1@cli/start.go:690 ⋮ [-] 40 node startup completed: +I210116 21:49:17.083093 14 1@cli/start.go:690 ⋮ [-] 40 +CockroachDB node starting at 2021-01-16 21:49 (took 0.0s) +I210116 21:49:17.083093 14 1@cli/start.go:690 ⋮ [-] 40 +build: CCL v21.1.1 @ 2021/5/24 11:00:26 (go1.15.5) (go1.12.6) +---- +logpb.Entry{Severity:1, Time:1610833757083093000, Goroutine:14, File:"cli/start.go", Line:690, Message:"node startup completed:\nCockroachDB node starting at 2021-01-16 21:49 (took 0.0s)\nbuild: CCL v21.1.1 @ 2021/5/24 11:00:26 (go1.15.5) (go1.12.6)", Tags:"-", Counter:0x28, Redactable:true, Channel:1} + +subtest end + +subtest structured_entry + +log +I210116 21:49:17.080713 14 1@util/log/event_log.go:32 ⋮ [-] 32 ={"Timestamp":1610833757080706620,"EventType":"node_restart"} +---- +logpb.Entry{Severity:1, Time:1610833757080713000, Goroutine:14, File:"util/log/event_log.go", Line:32, Message:"{\"Timestamp\":1610833757080706620,\"EventType\":\"node_restart\"}", Tags:"-", Counter:0x20, Redactable:true, Channel:1} + +subtest end + +subtest large_entry + +log +I210116 21:49:17.073282 14 server/node.go:464 ⋮ [-] 23 aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa +I210116 21:49:17.073282 14 server/node.go:464 ⋮ [-] 23 |aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa +---- +logpb.Entry{Severity:1, Time:1610833757073282000, Goroutine:14, File:"server/node.go", Line:464, Message:"aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", Tags:"-", Counter:0x17, Redactable:true, Channel:0} + +log +I210116 21:49:17.073282 14 server/node.go:464 ⋮ [-] 23 aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa +I210116 21:49:17.073282 14 server/node.go:464 ⋮ [-] 23 |aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa +I210116 21:49:17.073282 14 server/node.go:464 ⋮ [-] 23 |aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa +---- +logpb.Entry{Severity:1, Time:1610833757073282000, Goroutine:14, File:"server/node.go", Line:464, Message:"aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", Tags:"-", Counter:0x17, Redactable:true, Channel:0} + +log +I210116 21:49:17.083093 14 1@cli/start.go:690 ⋮ [-] 40 node startup +I210116 21:49:17.083093 14 1@cli/start.go:690 ⋮ [-] 40 | completed: +I210116 21:49:17.083093 14 1@cli/start.go:690 ⋮ [-] 40 +CockroachDB node starting at +I210116 21:49:17.083093 14 1@cli/start.go:690 ⋮ [-] 40 | 2021-01-16 21:49 (took 0.0s) +---- +logpb.Entry{Severity:1, Time:1610833757083093000, Goroutine:14, File:"cli/start.go", Line:690, Message:"node startup completed:\nCockroachDB node starting at 2021-01-16 21:49 (took 0.0s)", Tags:"-", Counter:0x28, Redactable:true, Channel:1} + +log +I210116 21:49:17.080713 14 1@util/log/event_log.go:32 ⋮ [-] 32 ={"Timestamp":1610833757080706620,"EventTy +I210116 21:49:17.080713 14 1@util/log/event_log.go:32 ⋮ [-] 32 |pe":"node_restart"} +---- +logpb.Entry{Severity:1, Time:1610833757080713000, Goroutine:14, File:"util/log/event_log.go", Line:32, Message:"{\"Timestamp\":1610833757080706620,\"EventType\":\"node_restart\"}", Tags:"-", Counter:0x20, Redactable:true, Channel:1} + +subtest end + +subtest stack_trace + +log +E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 hello ‹stack› +E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 !this is a fake stack +---- +logpb.Entry{Severity:3, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"hello ‹stack›\nstack trace: this is a fake stack", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:2} + +log +I210116 21:49:17.080713 14 1@util/log/event_log.go:32 ⋮ [-] 32 ={"Timestamp":1610833757080706620,"EventType":"node_restart"} +I210116 21:49:17.080713 14 1@util/log/event_log.go:32 ⋮ [-] 32 !this is a fake stack +---- +logpb.Entry{Severity:1, Time:1610833757080713000, Goroutine:14, File:"util/log/event_log.go", Line:32, Message:"{\"Timestamp\":1610833757080706620,\"EventType\":\"node_restart\"}\nstack trace: this is a fake stack", Tags:"-", Counter:0x20, Redactable:true, Channel:1} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 maybe ‹multi› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 +‹line with stack› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 !this is a fake stack +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"maybe ‹multi›\n‹line with stack›\nstack trace: this is a fake stack", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:0} + +log +E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 hello ‹stack› +E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 !this is aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa +E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 |aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa fake stack +---- +logpb.Entry{Severity:3, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"hello ‹stack›\nstack trace: this is aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa fake stack", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:2} + +subtest end + +subtest empty_fields + +log +E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] hello ‹world› +---- +logpb.Entry{Severity:3, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"hello ‹world›", Tags:"noval,s‹1›,long=‹2›", Counter:0x0, Redactable:true, Channel:2} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] hello ‹world› +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"hello ‹world›", Tags:"noval,s‹1›,long=‹2›", Counter:0x0, Redactable:true, Channel:0} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] maybe ‹multi› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] +‹line› +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"maybe ‹multi›\n‹line›", Tags:"noval,s‹1›,long=‹2›", Counter:0x0, Redactable:true, Channel:0} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] ={"Timestamp":123,"EventType":"rename_database","DatabaseName":"‹hello›","NewDatabaseName":"‹world›"} +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"{\"Timestamp\":123,\"EventType\":\"rename_database\",\"DatabaseName\":\"‹hello›\",\"NewDatabaseName\":\"‹world›\"}", Tags:"noval,s‹1›,long=‹2›", Counter:0x0, Redactable:true, Channel:0} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] ={"Timestamp":123,"EventType":"rename_database","DatabaseName":"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] |‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›"} +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"{\"Timestamp\":123,\"EventType\":\"rename_database\",\"DatabaseName\":\"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›\"}", Tags:"noval,s‹1›,long=‹2›", Counter:0x0, Redactable:true, Channel:0} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] ={"Timestamp":123,"EventType":"rename_database","DatabaseName":"‹hello›","NewDatabaseName":"‹world›"} +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] !this is a fake stack +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"{\"Timestamp\":123,\"EventType\":\"rename_database\",\"DatabaseName\":\"‹hello›\",\"NewDatabaseName\":\"‹world›\"}\nstack trace: this is a fake stack", Tags:"noval,s‹1›,long=‹2›", Counter:0x0, Redactable:true, Channel:0} + +log +W060102 15:04:05.654321 11 1@util/log/format_crdb_v2_test.go:123 [noval,s1,long=2] hello world +---- +logpb.Entry{Severity:2, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"hello world", Tags:"noval,s1,long=2", Counter:0x0, Redactable:false, Channel:1} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 [noval,s1,long=2] maybe multi +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 [noval,s1,long=2] +line +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"maybe multi\nline", Tags:"noval,s1,long=2", Counter:0x0, Redactable:false, Channel:0} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 [noval,s1,long=2] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 [noval,s1,long=2] |aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa", Tags:"noval,s1,long=2", Counter:0x0, Redactable:false, Channel:0} + +subtest end + +subtest multiple_entries + +log +E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 hello ‹world› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 24 ={"Timestamp":123,"EventType":"rename_database","DatabaseName":"‹hello›","NewDatabaseName":"‹world›"} +---- +logpb.Entry{Severity:3, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"hello ‹world›", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:2} +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"{\"Timestamp\":123,\"EventType\":\"rename_database\",\"DatabaseName\":\"‹hello›\",\"NewDatabaseName\":\"‹world›\"}", Tags:"noval,s‹1›,long=‹2›", Counter:0x18, Redactable:true, Channel:0} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 maybe ‹multi› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 +‹line› +E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 24 hello ‹world› +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"maybe ‹multi›\n‹line›", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:0} +logpb.Entry{Severity:3, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"hello ‹world›", Tags:"noval,s‹1›,long=‹2›", Counter:0x18, Redactable:true, Channel:2} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 maybe ‹multi› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 +‹line› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 24 ={"Timestamp":123,"EventType":"rename_database","DatabaseName":"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 24 |‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›"} +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"maybe ‹multi›\n‹line›", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"{\"Timestamp\":123,\"EventType\":\"rename_database\",\"DatabaseName\":\"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›\"}", Tags:"noval,s‹1›,long=‹2›", Counter:0x18, Redactable:true, Channel:0} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 ={"Timestamp":123,"EventType":"rename_database","DatabaseName":"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 |‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›"} +E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 24 hello ‹world› +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"{\"Timestamp\":123,\"EventType\":\"rename_database\",\"DatabaseName\":\"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›\"}", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:0} +logpb.Entry{Severity:3, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"hello ‹world›", Tags:"noval,s‹1›,long=‹2›", Counter:0x18, Redactable:true, Channel:2} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 ={"Timestamp":123,"EventType":"rename_database","DatabaseName":"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 |‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›"} +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 24 maybe ‹multi› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 24 +‹line› +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"{\"Timestamp\":123,\"EventType\":\"rename_database\",\"DatabaseName\":\"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›\"}", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"maybe ‹multi›\n‹line›", Tags:"noval,s‹1›,long=‹2›", Counter:0x18, Redactable:true, Channel:0} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 ={"Timestamp":123,"EventType":"rename_database","DatabaseName":"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 |‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›"} +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 !this is a fake stack +E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 24 hello ‹world› +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"{\"Timestamp\":123,\"EventType\":\"rename_database\",\"DatabaseName\":\"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›\"}\nstack trace: this is a fake stack", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:0} +logpb.Entry{Severity:3, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"hello ‹world›", Tags:"noval,s‹1›,long=‹2›", Counter:0x18, Redactable:true, Channel:2} + +log +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 ={"Timestamp":123,"EventType":"rename_database","DatabaseName":"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 |‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›"} +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 !this is a fake stack +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 24 maybe ‹multi› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 24 +‹line› +---- +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"{\"Timestamp\":123,\"EventType\":\"rename_database\",\"DatabaseName\":\"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›\"}\nstack trace: this is a fake stack", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:0} +logpb.Entry{Severity:1, Time:1136214245654321000, Goroutine:11, File:"util/log/format_crdb_v2_test.go", Line:123, Message:"maybe ‹multi›\n‹line›", Tags:"noval,s‹1›,long=‹2›", Counter:0x18, Redactable:true, Channel:0} + +subtest end