diff --git a/pkg/cli/debug.go b/pkg/cli/debug.go index 1842b50aaa32..1bfd2ca80dab 100644 --- a/pkg/cli/debug.go +++ b/pkg/cli/debug.go @@ -1266,7 +1266,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: ` @@ -1294,6 +1294,7 @@ var debugMergeLogsOpts = struct { prefix string keepRedactable bool redactInput bool + format string }{ program: nil, // match everything file: regexp.MustCompile(log.FilePattern), @@ -1307,7 +1308,7 @@ func runDebugMergeLogs(cmd *cobra.Command, args []string) error { inputEditMode := log.SelectEditMode(o.redactInput, o.keepRedactable) s, err := newMergedStreamFromPatterns(context.Background(), - args, o.file, o.program, o.from, o.to, inputEditMode) + args, o.file, o.program, o.from, o.to, inputEditMode, o.format) if err != nil { return err } @@ -1341,7 +1342,7 @@ var debugCmds = append(DebugCmdsForRocksDB, debugUnsafeRemoveDeadReplicasCmd, debugEnvCmd, debugZipCmd, - debugMergeLogsCommand, + debugMergeLogsCmd, debugListFilesCmd, debugResetQuorumCmd, ) @@ -1439,7 +1440,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. @@ -1458,6 +1459,8 @@ func init() { "keep the output log file redactable") f.BoolVar(&debugMergeLogsOpts.redactInput, "redact", debugMergeLogsOpts.redactInput, "redact the input files to remove sensitive information") + f.StringVar(&debugMergeLogsOpts.format, "format", "", + "log format of the input files") f = debugDecodeProtoCmd.Flags() f.StringVar(&debugDecodeProtoName, "schema", "cockroach.sql.sqlbase.Descriptor", diff --git a/pkg/cli/debug_merge_logs.go b/pkg/cli/debug_merge_logs.go index 590fcc370e85..f08ed54bb8bf 100644 --- a/pkg/cli/debug_merge_logs.go +++ b/pkg/cli/debug_merge_logs.go @@ -170,6 +170,7 @@ func newMergedStreamFromPatterns( filePattern, programFilter *regexp.Regexp, from, to time.Time, editMode log.EditSensitiveData, + format string, ) (logStream, error) { paths, err := expandPatterns(patterns) if err != nil { @@ -180,7 +181,7 @@ func newMergedStreamFromPatterns( if err != nil { return nil, err } - return newMergedStream(ctx, files, from, to, editMode) + return newMergedStream(ctx, files, from, to, editMode, format) } func groupIndex(re *regexp.Regexp, groupName string) int { @@ -193,7 +194,11 @@ func groupIndex(re *regexp.Regexp, groupName string) int { } func newMergedStream( - ctx context.Context, files []fileInfo, from, to time.Time, editMode log.EditSensitiveData, + ctx context.Context, + files []fileInfo, + from, to time.Time, + editMode log.EditSensitiveData, + format string, ) (*mergedStream, error) { // TODO(ajwerner): think about clock movement and PID const maxConcurrentFiles = 256 // should be far less than the FD limit @@ -204,7 +209,7 @@ func newMergedStream( return func() error { sem <- struct{}{} defer func() { <-sem }() - s, err := newFileLogStream(files[i], from, to, editMode) + s, err := newFileLogStream(files[i], from, to, editMode, format) if s != nil { res[i] = s } @@ -439,9 +444,10 @@ type fileLogStream struct { prevTime int64 fi fileInfo f *os.File - d *log.EntryDecoder + d log.EntryDecoder read bool editMode log.EditSensitiveData + format string e logpb.Entry err error @@ -454,13 +460,14 @@ type fileLogStream struct { // file is always closed before returning from this constructor so the initial // peek does not consume resources. func newFileLogStream( - fi fileInfo, from, to time.Time, editMode log.EditSensitiveData, + fi fileInfo, from, to time.Time, editMode log.EditSensitiveData, format string, ) (logStream, error) { s := &fileLogStream{ fi: fi, from: from, to: to, editMode: editMode, + format: format, } if _, ok := s.peek(); !ok { if err := s.error(); err != io.EOF { @@ -483,10 +490,13 @@ func (s *fileLogStream) open() bool { if s.f, s.err = os.Open(s.fi.path); s.err != nil { return false } - if s.err = seekToFirstAfterFrom(s.f, s.from, s.editMode); s.err != nil { + if s.err = seekToFirstAfterFrom(s.f, s.from, s.editMode, s.format); s.err != nil { return false } - s.d = log.NewEntryDecoder(bufio.NewReaderSize(s.f, readBufSize), s.editMode) + var err error + if s.d, err = log.NewEntryDecoderWithFormat(bufio.NewReaderSize(s.f, readBufSize), s.editMode, s.format); err != nil { + panic(err) + } return true } @@ -541,7 +551,9 @@ func (s *fileLogStream) error() error { return s.err } // seekToFirstAfterFrom uses binary search to seek to an offset after all // entries which occur before from. -func seekToFirstAfterFrom(f *os.File, from time.Time, editMode log.EditSensitiveData) (err error) { +func seekToFirstAfterFrom( + f *os.File, from time.Time, editMode log.EditSensitiveData, format string, +) (err error) { if from.IsZero() { return nil } @@ -560,8 +572,11 @@ func seekToFirstAfterFrom(f *os.File, from time.Time, editMode log.EditSensitive panic(err) } var e logpb.Entry - err := log.NewEntryDecoder(f, editMode).Decode(&e) + d, err := log.NewEntryDecoderWithFormat(f, editMode, format) if err != nil { + panic(err) + } + if err := d.Decode(&e); err != nil { if err == io.EOF { return true } @@ -573,7 +588,11 @@ func seekToFirstAfterFrom(f *os.File, from time.Time, editMode log.EditSensitive return err } var e logpb.Entry - if err := log.NewEntryDecoder(f, editMode).Decode(&e); err != nil { + d, err := log.NewEntryDecoderWithFormat(f, editMode, format) + if err != nil { + return err + } + if err := d.Decode(&e); err != nil { return err } _, err = f.Seek(int64(offset), io.SeekStart) diff --git a/pkg/cli/debug_merge_logs_test.go b/pkg/cli/debug_merge_logs_test.go index 0b75f653407c..a26b68ac1b0d 100644 --- a/pkg/cli/debug_merge_logs_test.go +++ b/pkg/cli/debug_merge_logs_test.go @@ -21,155 +21,191 @@ import ( "github.com/spf13/pflag" ) -const testdataPath = "testdata/merge_logs" +const crdbV2testdataPath = "testdata/merge_logs_v2" +const crdbV1testdataPath = "testdata/merge_logs_v1" type testCase struct { - name string - flags []string - args []string + name string + format string + flags []string + args []string } -var cases = []testCase{ - { - name: "1.all", - args: []string{"testdata/merge_logs/1/*/*"}, - flags: []string{"--redact=false", "--redactable-output=false"}, - }, - { - name: "1.filter-program", - args: []string{"testdata/merge_logs/1/*/*"}, - flags: []string{"--redact=false", "--redactable-output=false", "--program-filter", "not-cockroach"}, - }, - { - name: "1.seek-past-end-of-file", - args: []string{"testdata/merge_logs/1/*/*"}, - flags: []string{"--redact=false", "--redactable-output=false", "--from", "181130 22:15:07.525317"}, - }, - { - name: "1.filter-message", - args: []string{"testdata/merge_logs/1/*/*"}, - flags: []string{"--redact=false", "--redactable-output=false", "--filter", "gossip"}, - }, - { - name: "2.multiple-files-from-node", - args: []string{"testdata/merge_logs/2/*/*"}, - flags: []string{"--redact=false", "--redactable-output=false"}, - }, - { - // NB: the output here matches 2.multiple-files-from-node. - name: "2.walk-directory", - args: []string{"testdata/merge_logs/2"}, - flags: []string{"--redact=false", "--redactable-output=false"}, - }, - { - name: "2.skip-file", - args: []string{"testdata/merge_logs/2/*/*"}, - flags: []string{"--redact=false", "--redactable-output=false", "--from", "181130 22:15:07.525316"}, - }, - { - name: "2.remove-duplicates", - args: []string{ - "testdata/merge_logs/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log", - "testdata/merge_logs/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_14_47Z.004130.log", - "testdata/merge_logs/2/2.logs/cockroach.stderr", - "testdata/merge_logs/2/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log", - "testdata/merge_logs/2/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log", - "testdata/merge_logs/2/2.logs/roachprod.log", - }, - flags: []string{"--redact=false", "--redactable-output=false", "--from", "181130 22:15:07.525316"}, - }, - { - name: "3.non-standard", - args: []string{"testdata/merge_logs/3/*/*"}, - flags: []string{"--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--prefix", ""}, - }, - { - // Prints only lines that match the filter (if no submatches). - name: "4.filter", - args: []string{"testdata/merge_logs/4/*"}, - flags: []string{"--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--filter", "3:0"}, - }, - { - // Prints only the submatch. - name: "4.filter-submatch", - args: []string{"testdata/merge_logs/4/*"}, - flags: []string{"--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--filter", "(3:)0"}, - }, - { - // Prints only the submatches. - name: "4.filter-submatch-double", - args: []string{"testdata/merge_logs/4/*"}, - flags: []string{"--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--filter", "(3):(0)"}, - }, - { - // Simple grep for a panic line only. - name: "4.filter-npe", - args: []string{"testdata/merge_logs/4/npe.log"}, - flags: []string{"--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--filter", `(panic: .*)`}, - }, - { - // Grep for a panic and a few lines more. This is often not so useful - // because there's lots of recover() and re-panic happening; the real - // source of the panic is harder to find. - name: "4.filter-npe-with-context", - args: []string{"testdata/merge_logs/4/npe.log"}, - flags: []string{"--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--filter", `(?m)(panic:.(?:.*\n){0,5})`}, - }, - { - // This regexp attempts to find the source of the panic, essentially by - // matching on: - // - // panic(... - // stack - // anything - // stack - // not-a-panic - // stack - // - // This will skip past the recover-panic extra stacks at the top which - // usually alternate with panic(). - name: "4.filter-npe-origin-stack-only", - args: []string{"testdata/merge_logs/4/npe-repanic.log"}, // (?:panic\(.*)* - flags: []string{"--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--filter", `(?m)^(panic\(.*\n.*\n.*\n.*\n[^p].*)`}, - }, - { - name: "5.redact-off-redactable-off", - args: []string{"testdata/merge_logs/5/redactable.log"}, - flags: []string{"--redact=false", "--redactable-output=false", "--file-pattern", ".*"}, - }, - { - name: "5.redact-off-redactable-on", - args: []string{"testdata/merge_logs/5/redactable.log"}, - flags: []string{"--redact=false", "--redactable-output=true", "--file-pattern", ".*"}, - }, - { - name: "5.redact-on-redactable-off", - args: []string{"testdata/merge_logs/5/redactable.log"}, - flags: []string{"--redact=true", "--redactable-output=false", "--file-pattern", ".*"}, - }, - { - name: "5.redact-on-redactable-on", - args: []string{"testdata/merge_logs/5/redactable.log"}, - flags: []string{"--redact=true", "--redactable-output=true", "--file-pattern", ".*"}, - }, +func getCases(format string) []testCase { + var testdataPath string + switch format { + case "crdb-v2": + testdataPath = crdbV2testdataPath + case "crdb-v1": + testdataPath = crdbV1testdataPath + } + return []testCase{ + { + name: "1.all", + format: format, + args: []string{testdataPath + "/1/*/*"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false"}, + }, + { + name: "1.filter-program", + format: format, + args: []string{testdataPath + "/1/*/*"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false", "--program-filter", "not-cockroach"}, + }, + { + name: "1.seek-past-end-of-file", + format: format, + args: []string{testdataPath + "/1/*/*"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false", "--from", "181130 22:15:07.525317"}, + }, + { + name: "1.filter-message", + format: format, + args: []string{testdataPath + "/1/*/*"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false", "--filter", "gossip"}, + }, + { + name: "2.multiple-files-from-node", + format: format, + args: []string{testdataPath + "/2/*/*"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false"}, + }, + { + // NB: the output here matches 2.multiple-files-from-node. + name: "2.walk-directory", + format: format, + args: []string{testdataPath + "/2"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false"}, + }, + { + name: "2.skip-file", + format: format, + args: []string{testdataPath + "/2/*/*"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false", "--from", "181130 22:15:07.525316"}, + }, + { + name: "2.remove-duplicates", + format: format, + args: []string{ + testdataPath + "/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log", + testdataPath + "/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_14_47Z.004130.log", + testdataPath + "/2/2.logs/cockroach.stderr", + testdataPath + "/2/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log", + testdataPath + "/2/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log", + testdataPath + "/2/2.logs/roachprod.log", + }, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false", "--from", "181130 22:15:07.525316"}, + }, + { + name: "3.non-standard", + format: format, + args: []string{testdataPath + "/3/*/*"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--prefix", ""}, + }, + { + // Prints only lines that match the filter (if no submatches). + name: "4.filter", + format: format, + args: []string{testdataPath + "/4/*"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--filter", "3:0"}, + }, + { + // Prints only the submatch. + name: "4.filter-submatch", + format: format, + args: []string{testdataPath + "/4/*"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--filter", "(3:)0"}, + }, + { + // Prints only the submatches. + name: "4.filter-submatch-double", + format: format, + args: []string{testdataPath + "/4/*"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--filter", "(3):(0)"}, + }, + { + // Simple grep for a panic line only. + name: "4.filter-npe", + format: format, + args: []string{testdataPath + "/4/npe.log"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--filter", `(panic: .*)`}, + }, + { + // Grep for a panic and a few lines more. This is often not so useful + // because there's lots of recover() and re-panic happening; the real + // source of the panic is harder to find. + name: "4.filter-npe-with-context", + format: format, + args: []string{testdataPath + "/4/npe.log"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--filter", `(?m)(panic:.(?:.*\n){0,5})`}, + }, + { + // This regexp attempts to find the source of the panic, essentially by + // matching on: + // + // panic(... + // stack + // anything + // stack + // not-a-panic + // stack + // + // This will skip past the recover-panic extra stacks at the top which + // usually alternate with panic(). + name: "4.filter-npe-origin-stack-only", + format: format, + args: []string{testdataPath + "/4/npe-repanic.log"}, // (?:panic\(.*)* + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false", "--file-pattern", ".*", "--filter", `(?m)^(panic\(.*\n.*\n.*\n.*\n[^p].*)`}, + }, + { + name: "5.redact-off-redactable-off", + format: format, + args: []string{testdataPath + "/5/redactable.log"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=false", "--file-pattern", ".*"}, + }, + { + name: "5.redact-off-redactable-on", + format: format, + args: []string{testdataPath + "/5/redactable.log"}, + flags: []string{"--format=" + format, "--redact=false", "--redactable-output=true", "--file-pattern", ".*"}, + }, + { + name: "5.redact-on-redactable-off", + format: format, + args: []string{testdataPath + "/5/redactable.log"}, + flags: []string{"--format=" + format, "--redact=true", "--redactable-output=false", "--file-pattern", ".*"}, + }, + { + name: "5.redact-on-redactable-on", + format: format, + args: []string{testdataPath + "/5/redactable.log"}, + flags: []string{"--format=" + format, "--redact=true", "--redactable-output=true", "--file-pattern", ".*"}, + }, + } } 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.SetOut(&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) - resultFile := filepath.Join(testdataPath, "results", c.name) + var resultFile string + switch c.format { + case "crdb-v2": + resultFile = filepath.Join(crdbV2testdataPath, "results", c.name) + case "crdb-v1": + resultFile = filepath.Join(crdbV1testdataPath, "results", c.name) + } expected, err := ioutil.ReadFile(resultFile) if err != nil { t.Errorf("Failed to read expected result from %v: %v", resultFile, err) @@ -180,9 +216,21 @@ func (c testCase) run(t *testing.T) { } } -func TestDebugMergeLogs(t *testing.T) { +func TestCrdbV2DebugMergeLogs(t *testing.T) { defer leaktest.AfterTest(t)() defer log.Scope(t).Close(t) + + var cases = getCases("crdb-v2") + for _, c := range cases { + t.Run(c.name, c.run) + } +} + +func TestCrdbV1DebugMergeLogs(t *testing.T) { + defer leaktest.AfterTest(t)() + defer log.Scope(t).Close(t) + + var cases = getCases("crdb-v1") for _, c := range cases { t.Run(c.name, c.run) } diff --git a/pkg/cli/testdata/merge_logs/1/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log b/pkg/cli/testdata/merge_logs_v1/1/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log similarity index 100% rename from pkg/cli/testdata/merge_logs/1/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log rename to pkg/cli/testdata/merge_logs_v1/1/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log diff --git a/pkg/cli/testdata/merge_logs/1/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log b/pkg/cli/testdata/merge_logs_v1/1/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log similarity index 100% rename from pkg/cli/testdata/merge_logs/1/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log rename to pkg/cli/testdata/merge_logs_v1/1/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log diff --git a/pkg/cli/testdata/merge_logs/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log b/pkg/cli/testdata/merge_logs_v1/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log similarity index 100% rename from pkg/cli/testdata/merge_logs/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log rename to pkg/cli/testdata/merge_logs_v1/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log diff --git a/pkg/cli/testdata/merge_logs/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_14_47Z.004130.log b/pkg/cli/testdata/merge_logs_v1/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_14_47Z.004130.log similarity index 100% rename from pkg/cli/testdata/merge_logs/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_14_47Z.004130.log rename to pkg/cli/testdata/merge_logs_v1/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_14_47Z.004130.log diff --git a/pkg/cli/testdata/merge_logs/2/2.logs/cockroach.stderr b/pkg/cli/testdata/merge_logs_v1/2/2.logs/cockroach.stderr similarity index 100% rename from pkg/cli/testdata/merge_logs/2/2.logs/cockroach.stderr rename to pkg/cli/testdata/merge_logs_v1/2/2.logs/cockroach.stderr diff --git a/pkg/cli/testdata/merge_logs/2/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log b/pkg/cli/testdata/merge_logs_v1/2/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log similarity index 100% rename from pkg/cli/testdata/merge_logs/2/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log rename to pkg/cli/testdata/merge_logs_v1/2/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log diff --git a/pkg/cli/testdata/merge_logs/2/2.logs/roachprod.log b/pkg/cli/testdata/merge_logs_v1/2/2.logs/roachprod.log similarity index 100% rename from pkg/cli/testdata/merge_logs/2/2.logs/roachprod.log rename to pkg/cli/testdata/merge_logs_v1/2/2.logs/roachprod.log diff --git a/pkg/cli/testdata/merge_logs/3/1/not_standard.log b/pkg/cli/testdata/merge_logs_v1/3/1/not_standard.log similarity index 100% rename from pkg/cli/testdata/merge_logs/3/1/not_standard.log rename to pkg/cli/testdata/merge_logs_v1/3/1/not_standard.log diff --git a/pkg/cli/testdata/merge_logs/3/2/also_not_standard.log b/pkg/cli/testdata/merge_logs_v1/3/2/also_not_standard.log similarity index 100% rename from pkg/cli/testdata/merge_logs/3/2/also_not_standard.log rename to pkg/cli/testdata/merge_logs_v1/3/2/also_not_standard.log diff --git a/pkg/cli/testdata/merge_logs/4/npe-repanic.log b/pkg/cli/testdata/merge_logs_v1/4/npe-repanic.log similarity index 100% rename from pkg/cli/testdata/merge_logs/4/npe-repanic.log rename to pkg/cli/testdata/merge_logs_v1/4/npe-repanic.log diff --git a/pkg/cli/testdata/merge_logs/4/npe.log b/pkg/cli/testdata/merge_logs_v1/4/npe.log similarity index 100% rename from pkg/cli/testdata/merge_logs/4/npe.log rename to pkg/cli/testdata/merge_logs_v1/4/npe.log diff --git a/pkg/cli/testdata/merge_logs/5/redactable.log b/pkg/cli/testdata/merge_logs_v1/5/redactable.log similarity index 100% rename from pkg/cli/testdata/merge_logs/5/redactable.log rename to pkg/cli/testdata/merge_logs_v1/5/redactable.log diff --git a/pkg/cli/testdata/merge_logs/results/1.all b/pkg/cli/testdata/merge_logs_v1/results/1.all similarity index 100% rename from pkg/cli/testdata/merge_logs/results/1.all rename to pkg/cli/testdata/merge_logs_v1/results/1.all diff --git a/pkg/cli/testdata/merge_logs/results/1.filter-message b/pkg/cli/testdata/merge_logs_v1/results/1.filter-message similarity index 100% rename from pkg/cli/testdata/merge_logs/results/1.filter-message rename to pkg/cli/testdata/merge_logs_v1/results/1.filter-message diff --git a/pkg/cli/testdata/merge_logs/results/1.filter-program b/pkg/cli/testdata/merge_logs_v1/results/1.filter-program similarity index 100% rename from pkg/cli/testdata/merge_logs/results/1.filter-program rename to pkg/cli/testdata/merge_logs_v1/results/1.filter-program diff --git a/pkg/cli/testdata/merge_logs/results/1.seek-past-end-of-file b/pkg/cli/testdata/merge_logs_v1/results/1.seek-past-end-of-file similarity index 100% rename from pkg/cli/testdata/merge_logs/results/1.seek-past-end-of-file rename to pkg/cli/testdata/merge_logs_v1/results/1.seek-past-end-of-file diff --git a/pkg/cli/testdata/merge_logs/results/2.multiple-files-from-node b/pkg/cli/testdata/merge_logs_v1/results/2.multiple-files-from-node similarity index 100% rename from pkg/cli/testdata/merge_logs/results/2.multiple-files-from-node rename to pkg/cli/testdata/merge_logs_v1/results/2.multiple-files-from-node diff --git a/pkg/cli/testdata/merge_logs/results/2.remove-duplicates b/pkg/cli/testdata/merge_logs_v1/results/2.remove-duplicates similarity index 100% rename from pkg/cli/testdata/merge_logs/results/2.remove-duplicates rename to pkg/cli/testdata/merge_logs_v1/results/2.remove-duplicates diff --git a/pkg/cli/testdata/merge_logs/results/2.skip-file b/pkg/cli/testdata/merge_logs_v1/results/2.skip-file similarity index 100% rename from pkg/cli/testdata/merge_logs/results/2.skip-file rename to pkg/cli/testdata/merge_logs_v1/results/2.skip-file diff --git a/pkg/cli/testdata/merge_logs/results/2.walk-directory b/pkg/cli/testdata/merge_logs_v1/results/2.walk-directory similarity index 100% rename from pkg/cli/testdata/merge_logs/results/2.walk-directory rename to pkg/cli/testdata/merge_logs_v1/results/2.walk-directory diff --git a/pkg/cli/testdata/merge_logs/results/3.non-standard b/pkg/cli/testdata/merge_logs_v1/results/3.non-standard similarity index 100% rename from pkg/cli/testdata/merge_logs/results/3.non-standard rename to pkg/cli/testdata/merge_logs_v1/results/3.non-standard diff --git a/pkg/cli/testdata/merge_logs/results/4.filter b/pkg/cli/testdata/merge_logs_v1/results/4.filter similarity index 100% rename from pkg/cli/testdata/merge_logs/results/4.filter rename to pkg/cli/testdata/merge_logs_v1/results/4.filter diff --git a/pkg/cli/testdata/merge_logs/results/4.filter-npe b/pkg/cli/testdata/merge_logs_v1/results/4.filter-npe similarity index 100% rename from pkg/cli/testdata/merge_logs/results/4.filter-npe rename to pkg/cli/testdata/merge_logs_v1/results/4.filter-npe diff --git a/pkg/cli/testdata/merge_logs/results/4.filter-npe-origin-stack-only b/pkg/cli/testdata/merge_logs_v1/results/4.filter-npe-origin-stack-only similarity index 100% rename from pkg/cli/testdata/merge_logs/results/4.filter-npe-origin-stack-only rename to pkg/cli/testdata/merge_logs_v1/results/4.filter-npe-origin-stack-only diff --git a/pkg/cli/testdata/merge_logs/results/4.filter-npe-with-context b/pkg/cli/testdata/merge_logs_v1/results/4.filter-npe-with-context similarity index 100% rename from pkg/cli/testdata/merge_logs/results/4.filter-npe-with-context rename to pkg/cli/testdata/merge_logs_v1/results/4.filter-npe-with-context diff --git a/pkg/cli/testdata/merge_logs/results/4.filter-submatch b/pkg/cli/testdata/merge_logs_v1/results/4.filter-submatch similarity index 100% rename from pkg/cli/testdata/merge_logs/results/4.filter-submatch rename to pkg/cli/testdata/merge_logs_v1/results/4.filter-submatch diff --git a/pkg/cli/testdata/merge_logs/results/4.filter-submatch-double b/pkg/cli/testdata/merge_logs_v1/results/4.filter-submatch-double similarity index 100% rename from pkg/cli/testdata/merge_logs/results/4.filter-submatch-double rename to pkg/cli/testdata/merge_logs_v1/results/4.filter-submatch-double diff --git a/pkg/cli/testdata/merge_logs/results/5.redact-off-redactable-off b/pkg/cli/testdata/merge_logs_v1/results/5.redact-off-redactable-off similarity index 100% rename from pkg/cli/testdata/merge_logs/results/5.redact-off-redactable-off rename to pkg/cli/testdata/merge_logs_v1/results/5.redact-off-redactable-off diff --git a/pkg/cli/testdata/merge_logs/results/5.redact-off-redactable-on b/pkg/cli/testdata/merge_logs_v1/results/5.redact-off-redactable-on similarity index 100% rename from pkg/cli/testdata/merge_logs/results/5.redact-off-redactable-on rename to pkg/cli/testdata/merge_logs_v1/results/5.redact-off-redactable-on diff --git a/pkg/cli/testdata/merge_logs/results/5.redact-on-redactable-off b/pkg/cli/testdata/merge_logs_v1/results/5.redact-on-redactable-off similarity index 100% rename from pkg/cli/testdata/merge_logs/results/5.redact-on-redactable-off rename to pkg/cli/testdata/merge_logs_v1/results/5.redact-on-redactable-off diff --git a/pkg/cli/testdata/merge_logs/results/5.redact-on-redactable-on b/pkg/cli/testdata/merge_logs_v1/results/5.redact-on-redactable-on similarity index 100% rename from pkg/cli/testdata/merge_logs/results/5.redact-on-redactable-on rename to pkg/cli/testdata/merge_logs_v1/results/5.redact-on-redactable-on diff --git a/pkg/cli/testdata/merge_logs_v2/1/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log b/pkg/cli/testdata/merge_logs_v2/1/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log new file mode 100644 index 000000000000..11213a6a0d3a --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/1/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log @@ -0,0 +1,10 @@ +I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] +gossip client (0/3 cur/max conns) +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] +gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] + 2: ajwerner-test-0002:26257 (8m0s) +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] + 3: ajwerner-test-0003:26257 (8m0s) +I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_v2/1/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log b/pkg/cli/testdata/merge_logs_v2/1/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log new file mode 100644 index 000000000000..4869977cd987 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/1/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log @@ -0,0 +1,10 @@ +I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_v2/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log b/pkg/cli/testdata/merge_logs_v2/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log new file mode 100644 index 000000000000..5879e11fd644 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_06_47Z.004130.log @@ -0,0 +1,7 @@ +I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] +gossip client (0/3 cur/max conns) +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] +gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] + 2: ajwerner-test-0002:26257 (8m0s) +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] + 3: ajwerner-test-0003:26257 (8m0s) diff --git a/pkg/cli/testdata/merge_logs_v2/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_14_47Z.004130.log b/pkg/cli/testdata/merge_logs_v2/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_14_47Z.004130.log new file mode 100644 index 000000000000..6bbc0a563feb --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/2/1.logs/cockroach.test-0001.ubuntu.2018-11-30T22_14_47Z.004130.log @@ -0,0 +1,3 @@ +I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_v2/2/2.logs/cockroach.stderr b/pkg/cli/testdata/merge_logs_v2/2/2.logs/cockroach.stderr new file mode 100644 index 000000000000..e69de29bb2d1 diff --git a/pkg/cli/testdata/merge_logs_v2/2/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log b/pkg/cli/testdata/merge_logs_v2/2/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log new file mode 100644 index 000000000000..4869977cd987 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/2/2.logs/cockroach.test-0002.ubuntu.2018-11-30T22_06_47Z.003959.log @@ -0,0 +1,10 @@ +I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_v2/2/2.logs/roachprod.log b/pkg/cli/testdata/merge_logs_v2/2/2.logs/roachprod.log new file mode 100644 index 000000000000..e69de29bb2d1 diff --git a/pkg/cli/testdata/merge_logs_v2/3/1/not_standard.log b/pkg/cli/testdata/merge_logs_v2/3/1/not_standard.log new file mode 100644 index 000000000000..11213a6a0d3a --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/3/1/not_standard.log @@ -0,0 +1,10 @@ +I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] +gossip client (0/3 cur/max conns) +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] +gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] + 2: ajwerner-test-0002:26257 (8m0s) +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] + 3: ajwerner-test-0003:26257 (8m0s) +I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_v2/3/2/also_not_standard.log b/pkg/cli/testdata/merge_logs_v2/3/2/also_not_standard.log new file mode 100644 index 000000000000..4869977cd987 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/3/2/also_not_standard.log @@ -0,0 +1,10 @@ +I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_v2/4/npe-repanic.log b/pkg/cli/testdata/merge_logs_v2/4/npe-repanic.log new file mode 100644 index 000000000000..4e5a3428cabf --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/4/npe-repanic.log @@ -0,0 +1,69 @@ +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] i was created via the following code: +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !func main() { +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! defer cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! defer cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! defer cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! defer cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! defer cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! defer cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! defer cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! func() { func() { func() { func() { func() { +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! func() { func() { panic("boom") +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! }()}()}()}()}()}()}() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !} +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !and here we go: +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! panic: boom [recovered] +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! panic: boom [recovered] +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! panic: boom [recovered] +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! panic: boom [recovered] +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! panic: boom [recovered] +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! panic: boom [recovered] +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! panic: boom +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !goroutine 1 [running]: +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:20 +0x60 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !panic(0x122540, 0x16aa50) +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /usr/local/go/src/runtime/panic.go:522 +0x240 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:20 +0x60 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !panic(0x122540, 0x16aa50) +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /usr/local/go/src/runtime/panic.go:522 +0x240 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:20 +0x60 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !panic(0x122540, 0x16aa50) +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /usr/local/go/src/runtime/panic.go:522 +0x240 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:20 +0x60 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !panic(0x122540, 0x16aa50) +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /usr/local/go/src/runtime/panic.go:522 +0x240 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:20 +0x60 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !panic(0x122540, 0x16aa50) +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /usr/local/go/src/runtime/panic.go:522 +0x240 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:20 +0x60 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !panic(0x122540, 0x16aa50) +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /usr/local/go/src/runtime/panic.go:522 +0x240 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.cleanup() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:20 +0x60 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !panic(0x122540, 0x16aa50) +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /usr/local/go/src/runtime/panic.go:522 +0x240 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.main.func1.1.1.1.1.1.1(...) +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:42 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.main.func1.1.1.1.1.1() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:43 +0x40 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.main.func1.1.1.1.1() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:44 +0x20 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.main.func1.1.1.1() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:45 +0x20 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.main.func1.1.1() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:46 +0x20 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.main.func1.1() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:47 +0x20 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.main.func1() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:48 +0x20 +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] !main.main() +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] ! /tmp/sandbox881972553/main.go:49 +0x200 diff --git a/pkg/cli/testdata/merge_logs_v2/4/npe.log b/pkg/cli/testdata/merge_logs_v2/4/npe.log new file mode 100644 index 000000000000..5bae5bea342c --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/4/npe.log @@ -0,0 +1,26 @@ +I190412 10:06:00.490104 183717 ccl/partitionccl/partition_test.go:204 [-] query: SELECT count(*) FROM "multi col range partitioning - MAXVALUE MAXVALUE" WHERE a >= 4 AND (a, b) < (5, 6) +E190412 10:06:00.645112 195432 storage/queue.go:866 [n1,replicate,s1,r161/2:/Table/84/{1/5/7-2}] no removable replicas from range that needs a removal: [2*:27, 3:0] +E190412 10:06:00.681552 195558 storage/queue.go:866 [n1,replicate,s1,r158/3:/Table/84/1/3{-/4}] no removable replicas from range that needs a removal: [2:0, 3*:34] +E190412 10:06:00.780922 195831 storage/queue.go:866 [n3,replicate,s3,r49/1:/Table/84/1/{3/4-4}] no removable replicas from range that needs a removal: [1*:16, 2:0] +E190412 10:06:00.818605 195938 storage/queue.go:866 [n1,replicate,s1,r159/2:/Table/84/1/{4-5/6}] no removable replicas from range that needs a removal: [2*:27, 3:0] +E190412 10:06:01.015534 196474 storage/queue.go:866 [n2,replicate,s2,r161/3:/Table/84/{1/5/7-2}] no removable replicas from range that needs a removal: [2:0, 3*:29] +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] query: SELECT count(*) FROM "multi col range partitioning - MAXVALUE MAXVALUE" WHERE (a, b) < (3, 4) +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] !panic: runtime error: invalid memory address or nil pointer dereference [recovered] +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] ! panic: runtime error: invalid memory address or nil pointer dereference +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] ![signal SIGSEGV: segmentation violation code=0x1 addr=0x10 pc=0x20efbad] +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] ! +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] !goroutine 76680 [running]: +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] !github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).Recover(0xc000c467e0, 0x379a020, 0xc0029cb650) +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] ! /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:185 +0x11f +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] !panic(0x2ccb620, 0x527ac20) +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] ! /usr/local/go/src/runtime/panic.go:513 +0x1b9 +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] !github.com/cockroachdb/cockroach/pkg/storage.(*replicaItem).setProcessing(...) +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] ! /go/src/github.com/cockroachdb/cockroach/pkg/storage/queue.go:80 +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] !github.com/cockroachdb/cockroach/pkg/storage.(*baseQueue).addToPurgatoryLocked.func2.1(0xc000473340, 0x379a020, 0xc0029cb650, 0xc000c467e0) +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] ! /go/src/github.com/cockroachdb/cockroach/pkg/storage/queue.go:928 +0x1dd +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] !github.com/cockroachdb/cockroach/pkg/storage.(*baseQueue).addToPurgatoryLocked.func2(0x379a020, 0xc0029cb650) +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] ! /go/src/github.com/cockroachdb/cockroach/pkg/storage/queue.go:949 +0x462 +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] !github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker.func1(0xc001480a10, 0xc000c467e0, 0xc0002f37c0) +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] ! /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:200 +0xe1 +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] !created by github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunWorker +I190412 10:06:01.029478 183717 ccl/partitionccl/partition_test.go:204 [-] ! /go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:193 +0xa8 diff --git a/pkg/cli/testdata/merge_logs_v2/5/redactable.log b/pkg/cli/testdata/merge_logs_v2/5/redactable.log new file mode 100644 index 000000000000..50c18fed7ea7 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/5/redactable.log @@ -0,0 +1,2 @@ +I190412 10:06:00.490104 183717 server/server.go:1423 ⋮ [-] safe ‹unsafe› +I190412 10:06:00.490104 183717 server/server.go:1424 [-] unknownsafe diff --git a/pkg/cli/testdata/merge_logs_v2/results/1.all b/pkg/cli/testdata/merge_logs_v2/results/1.all new file mode 100644 index 000000000000..586d6b74b71f --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/1.all @@ -0,0 +1,20 @@ +test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +gossip client (0/3 cur/max conns) +gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) + 2: ajwerner-test-0002:26257 (8m0s) + 3: ajwerner-test-0003:26257 (8m0s) +test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_v2/results/1.filter-message b/pkg/cli/testdata/merge_logs_v2/results/1.filter-message new file mode 100644 index 000000000000..401ace269349 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/1.filter-message @@ -0,0 +1,5 @@ +test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +gossip client (0/3 cur/max conns) +gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) + 2: ajwerner-test-0002:26257 (8m0s) + 3: ajwerner-test-0003:26257 (8m0s) diff --git a/pkg/cli/testdata/merge_logs_v2/results/1.filter-program b/pkg/cli/testdata/merge_logs_v2/results/1.filter-program new file mode 100644 index 000000000000..e69de29bb2d1 diff --git a/pkg/cli/testdata/merge_logs_v2/results/1.seek-past-end-of-file b/pkg/cli/testdata/merge_logs_v2/results/1.seek-past-end-of-file new file mode 100644 index 000000000000..b367d19e2f19 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/1.seek-past-end-of-file @@ -0,0 +1 @@ +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_v2/results/2.multiple-files-from-node b/pkg/cli/testdata/merge_logs_v2/results/2.multiple-files-from-node new file mode 100644 index 000000000000..586d6b74b71f --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/2.multiple-files-from-node @@ -0,0 +1,20 @@ +test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +gossip client (0/3 cur/max conns) +gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) + 2: ajwerner-test-0002:26257 (8m0s) + 3: ajwerner-test-0003:26257 (8m0s) +test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_v2/results/2.remove-duplicates b/pkg/cli/testdata/merge_logs_v2/results/2.remove-duplicates new file mode 100644 index 000000000000..f8c19a121b58 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/2.remove-duplicates @@ -0,0 +1,2 @@ +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_v2/results/2.skip-file b/pkg/cli/testdata/merge_logs_v2/results/2.skip-file new file mode 100644 index 000000000000..f8c19a121b58 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/2.skip-file @@ -0,0 +1,2 @@ +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_v2/results/2.walk-directory b/pkg/cli/testdata/merge_logs_v2/results/2.walk-directory new file mode 100644 index 000000000000..586d6b74b71f --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/2.walk-directory @@ -0,0 +1,20 @@ +test-0001> I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +test-0001> I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +test-0001> I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +gossip client (0/3 cur/max conns) +gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) + 2: ajwerner-test-0002:26257 (8m0s) + 3: ajwerner-test-0003:26257 (8m0s) +test-0001> I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +test-0002> I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +test-0002> I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +test-0002> I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +test-0002> I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +test-0002> I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +test-0002> I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +test-0001> I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +test-0002> I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +test-0002> I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +test-0002> I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +test-0001> I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +test-0002> I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_v2/results/3.non-standard b/pkg/cli/testdata/merge_logs_v2/results/3.non-standard new file mode 100644 index 000000000000..a1005a6d8dca --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/3.non-standard @@ -0,0 +1,20 @@ +I181130 22:14:34.828612 740 storage/store_rebalancer.go:277 [n1,s1,store-rebalancer] load-based lease transfers successfully brought s1 down to 37128.65 qps (mean=29834.62, upperThreshold=37293.27) +I181130 22:14:37.516378 441 server/status/runtime.go:465 [n1] runtime stats: 900 MiB RSS, 1509 goroutines, 421 MiB/144 MiB/777 MiB GO alloc/idle/total, 96 MiB/144 MiB CGO alloc/total, 154632.4 CGO/sec, 2206.9/216.0 %(u/s)time, 0.4 %gc (43x), 182 MiB/204 MiB (r/w)net +I181130 22:14:47.400515 437 gossip/gossip.go:555 [n1] gossip status (ok, 3 nodes) +gossip client (0/3 cur/max conns) +gossip server (2/3 cur/max conns, infos 4077/2242 sent/received, bytes 1275332B/555352B sent/received) + 2: ajwerner-test-0002:26257 (8m0s) + 3: ajwerner-test-0003:26257 (8m0s) +I181130 22:14:47.519324 441 server/status/runtime.go:465 [n1] runtime stats: 957 MiB RSS, 1690 goroutines, 420 MiB/173 MiB/777 MiB GO alloc/idle/total, 124 MiB/174 MiB CGO alloc/total, 143837.6 CGO/sec, 2245.9/218.3 %(u/s)time, 0.5 %gc (47x), 199 MiB/210 MiB (r/w)net +I181130 22:14:49.706516 6152567 storage/split_queue.go:213 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split based on load at key /Table/53/1/-3661595080111255049 +I181130 22:14:49.706563 6152567 storage/replica_command.go:342 [n2,split,s2,r163/3:/Table/53/1/-36{84178…-35915…}] initiating a split of this range at key /Table/53/1/-3661595080111255049 [r586] +I181130 22:14:49.732930 6153357 storage/split_queue.go:213 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split based on load at key /Table/53/1/-8134885765915906309 +I181130 22:14:49.732976 6153357 storage/replica_command.go:342 [n2,split,s2,r269/3:/Table/53/1/-81{56147…-10716…}] initiating a split of this range at key /Table/53/1/-8134885765915906309 [r587] +I181130 22:14:50.203263 6163815 storage/split_queue.go:213 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split based on load at key /Table/53/1/-8768249731886885702 +I181130 22:14:50.203299 6163815 storage/replica_command.go:342 [n2,split,s2,r171/3:/Table/53/1/-87{94402…-45781…}] initiating a split of this range at key /Table/53/1/-8768249731886885702 [r588] +I181130 22:14:57.522236 441 server/status/runtime.go:465 [n1] runtime stats: 986 MiB RSS, 1332 goroutines, 438 MiB/140 MiB/777 MiB GO alloc/idle/total, 151 MiB/203 MiB CGO alloc/total, 137663.6 CGO/sec, 2168.3/222.8 %(u/s)time, 0.4 %gc (45x), 192 MiB/203 MiB (r/w)net +I181130 22:14:57.650774 499 server/status/runtime.go:465 [n2] runtime stats: 729 MiB RSS, 1127 goroutines, 416 MiB/91 MiB/584 MiB GO alloc/idle/total, 75 MiB/128 MiB CGO alloc/total, 111534.7 CGO/sec, 2013.0/232.3 %(u/s)time, 0.4 %gc (56x), 189 MiB/189 MiB (r/w)net +I181130 22:15:05.892547 6507691 storage/split_queue.go:213 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split based on load at key /Table/53/1/-698671514117501959 +I181130 22:15:05.892592 6507691 storage/replica_command.go:342 [n2,split,s2,r129/3:/Table/53/1/-{722633…-673989…}] initiating a split of this range at key /Table/53/1/-698671514117501959 [r589] +I181130 22:15:07.525316 441 server/status/runtime.go:465 [n1] runtime stats: 952 MiB RSS, 1422 goroutines, 397 MiB/165 MiB/777 MiB GO alloc/idle/total, 112 MiB/164 MiB CGO alloc/total, 133359.9 CGO/sec, 2137.8/225.1 %(u/s)time, 0.4 %gc (43x), 187 MiB/198 MiB (r/w)net +I181130 22:15:07.653821 499 server/status/runtime.go:465 [n2] runtime stats: 756 MiB RSS, 1127 goroutines, 338 MiB/113 MiB/584 MiB GO alloc/idle/total, 94 MiB/149 MiB CGO alloc/total, 108469.2 CGO/sec, 1964.7/227.0 %(u/s)time, 0.4 %gc (54x), 185 MiB/184 MiB (r/w)net diff --git a/pkg/cli/testdata/merge_logs_v2/results/4.filter b/pkg/cli/testdata/merge_logs_v2/results/4.filter new file mode 100644 index 000000000000..acd2c58d4b4f --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/4.filter @@ -0,0 +1,2 @@ +> E190412 10:06:00.645112 195432 storage/queue.go:866 [n1,replicate,s1,r161/2:/Table/84/{1/5/7-2}] no removable replicas from range that needs a removal: [2*:27, 3:0] +> E190412 10:06:00.818605 195938 storage/queue.go:866 [n1,replicate,s1,r159/2:/Table/84/1/{4-5/6}] no removable replicas from range that needs a removal: [2*:27, 3:0] diff --git a/pkg/cli/testdata/merge_logs_v2/results/4.filter-npe b/pkg/cli/testdata/merge_logs_v2/results/4.filter-npe new file mode 100644 index 000000000000..1a13cca8bfb0 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/4.filter-npe @@ -0,0 +1 @@ +panic: runtime error: invalid memory address or nil pointer dereference [recovered] diff --git a/pkg/cli/testdata/merge_logs_v2/results/4.filter-npe-origin-stack-only b/pkg/cli/testdata/merge_logs_v2/results/4.filter-npe-origin-stack-only new file mode 100644 index 000000000000..5357b36f81bf --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/4.filter-npe-origin-stack-only @@ -0,0 +1,5 @@ +panic(0x122540, 0x16aa50) + /usr/local/go/src/runtime/panic.go:522 +0x240 +main.main.func1.1.1.1.1.1.1(...) + /tmp/sandbox881972553/main.go:42 +main.main.func1.1.1.1.1.1() diff --git a/pkg/cli/testdata/merge_logs_v2/results/4.filter-npe-with-context b/pkg/cli/testdata/merge_logs_v2/results/4.filter-npe-with-context new file mode 100644 index 000000000000..a42b8dd6bed8 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/4.filter-npe-with-context @@ -0,0 +1,6 @@ +panic: runtime error: invalid memory address or nil pointer dereference [recovered] + panic: runtime error: invalid memory address or nil pointer dereference +[signal SIGSEGV: segmentation violation code=0x1 addr=0x10 pc=0x20efbad] + +goroutine 76680 [running]: + diff --git a/pkg/cli/testdata/merge_logs_v2/results/4.filter-submatch b/pkg/cli/testdata/merge_logs_v2/results/4.filter-submatch new file mode 100644 index 000000000000..1ee1d5586086 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/4.filter-submatch @@ -0,0 +1,2 @@ +3: +3: diff --git a/pkg/cli/testdata/merge_logs_v2/results/4.filter-submatch-double b/pkg/cli/testdata/merge_logs_v2/results/4.filter-submatch-double new file mode 100644 index 000000000000..285b16f691a6 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/4.filter-submatch-double @@ -0,0 +1,2 @@ +30 +30 diff --git a/pkg/cli/testdata/merge_logs_v2/results/5.redact-off-redactable-off b/pkg/cli/testdata/merge_logs_v2/results/5.redact-off-redactable-off new file mode 100644 index 000000000000..d24297ff394a --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/5.redact-off-redactable-off @@ -0,0 +1,2 @@ +> I190412 10:06:00.490104 183717 server/server.go:1423 [-] safe unsafe +> I190412 10:06:00.490104 183717 server/server.go:1424 [-] unknownsafe diff --git a/pkg/cli/testdata/merge_logs_v2/results/5.redact-off-redactable-on b/pkg/cli/testdata/merge_logs_v2/results/5.redact-off-redactable-on new file mode 100644 index 000000000000..e9b765d63575 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/5.redact-off-redactable-on @@ -0,0 +1,2 @@ +> I190412 10:06:00.490104 183717 server/server.go:1423 ⋮ [-] safe ‹unsafe› +> I190412 10:06:00.490104 183717 server/server.go:1424 ⋮ [-] ‹unknownsafe› diff --git a/pkg/cli/testdata/merge_logs_v2/results/5.redact-on-redactable-off b/pkg/cli/testdata/merge_logs_v2/results/5.redact-on-redactable-off new file mode 100644 index 000000000000..5dd1937c09a8 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/5.redact-on-redactable-off @@ -0,0 +1,2 @@ +> I190412 10:06:00.490104 183717 server/server.go:1423 [-] safe × +> I190412 10:06:00.490104 183717 server/server.go:1424 [-] × diff --git a/pkg/cli/testdata/merge_logs_v2/results/5.redact-on-redactable-on b/pkg/cli/testdata/merge_logs_v2/results/5.redact-on-redactable-on new file mode 100644 index 000000000000..b0a69a9466b7 --- /dev/null +++ b/pkg/cli/testdata/merge_logs_v2/results/5.redact-on-redactable-on @@ -0,0 +1,2 @@ +> I190412 10:06:00.490104 183717 server/server.go:1423 ⋮ [-] safe ‹×› +> I190412 10:06:00.490104 183717 server/server.go:1424 ⋮ [-] ‹×› diff --git a/pkg/server/status.go b/pkg/server/status.go index e937cf61adcc..947479585dbc 100644 --- a/pkg/server/status.go +++ b/pkg/server/status.go @@ -1058,13 +1058,16 @@ func (s *statusServer) LogFile( // Read the logs. reader, err := log.GetLogReader(req.File, true /* restricted */) - if reader == nil || err != nil { - return nil, fmt.Errorf("log file %s could not be opened: %s", req.File, err) + if err != nil { + return nil, errors.Wrapf(err, "log file %q could not be opened", req.File) } defer reader.Close() var resp serverpb.LogEntriesResponse - decoder := log.NewEntryDecoder(reader, inputEditMode) + decoder, err := log.NewEntryDecoder(reader, inputEditMode) + if err != nil { + return nil, err + } for { var entry logpb.Entry if err := decoder.Decode(&entry); err != nil { diff --git a/pkg/server/status_test.go b/pkg/server/status_test.go index 967a5be18ad0..f304a3d9cdb7 100644 --- a/pkg/server/status_test.go +++ b/pkg/server/status_test.go @@ -675,16 +675,16 @@ func TestStatusLogRedaction(t *testing.T) { // If there were no markers to start with (redactableLogs=false), we // introduce markers around the entire message to indicate it's not known to // be safe. - {false, false, `‹ THISISSAFE THISISUNSAFE›`, true}, + {false, false, `‹THISISSAFE THISISUNSAFE›`, true}, // redact=true must be conservative and redact everything out if // there were no markers to start with (redactableLogs=false). {false, true, `‹×›`, false}, // redact=false keeps whatever was in the log file. - {true, false, ` THISISSAFE ‹THISISUNSAFE›`, true}, + {true, false, `THISISSAFE ‹THISISUNSAFE›`, true}, // Whether or not to keep the redactable markers has no influence // on the output of redaction, just on the presence of the // "redactable" marker. In any case no information is leaked. - {true, true, ` THISISSAFE ‹×›`, true}, + {true, true, `THISISSAFE ‹×›`, true}, } testutils.RunTrueAndFalse(t, "redactableLogs", diff --git a/pkg/sql/pgwire/auth_test.go b/pkg/sql/pgwire/auth_test.go index 57555b73dfa4..a0ced6beec9b 100644 --- a/pkg/sql/pgwire/auth_test.go +++ b/pkg/sql/pgwire/auth_test.go @@ -314,13 +314,13 @@ func hbaRunTest(t *testing.T, insecure bool) { entry := &entries[i] // t.Logf("found log entry: %+v", *entry) - if !strings.HasPrefix(entry.Message, "={") { + if entry.StructuredEnd == 0 { // TODO(knz): Enhance this when the log file // contains proper markers for structured entries. t.Errorf("malformed structured message: %q", entry.Message) } - jsonPayload := []byte(entry.Message[1:]) + jsonPayload := []byte(entry.Message) if entry.Redactable { jsonPayload = redact.RedactableBytes(jsonPayload).StripMarkers() } diff --git a/pkg/util/log/BUILD.bazel b/pkg/util/log/BUILD.bazel index de4d76d6763d..cf3c7a156dd0 100644 --- a/pkg/util/log/BUILD.bazel +++ b/pkg/util/log/BUILD.bazel @@ -16,6 +16,7 @@ go_library( "file_sync_buffer.go", "flags.go", "fluent_client.go", + "format_crdb.go", "format_crdb_v1.go", "format_crdb_v2.go", "format_json.go", @@ -25,6 +26,7 @@ go_library( "log.go", "log_bridge.go", "log_buffer.go", + "log_decoder.go", "log_entry.go", "log_flush.go", "redact.go", @@ -51,6 +53,7 @@ go_library( "//pkg/util/caller", "//pkg/util/encoding/encodingtype", "//pkg/util/envutil", + "//pkg/util/errorutil/unimplemented", "//pkg/util/fileutil", "//pkg/util/jsonbytes", "//pkg/util/log/channel", diff --git a/pkg/util/log/file_api.go b/pkg/util/log/file_api.go index a665e5849a0c..a92f66b0e926 100644 --- a/pkg/util/log/file_api.go +++ b/pkg/util/log/file_api.go @@ -286,6 +286,17 @@ func FetchEntriesFromFiles( maxEntries int, pattern *regexp.Regexp, editMode EditSensitiveData, +) ([]logpb.Entry, error) { + return FetchEntriesFromFilesWithFormat(startTimestamp, endTimestamp, maxEntries, pattern, editMode, "" /*format*/) +} + +// FetchEntriesFromFilesWithFormat is like FetchEntriesFromFiles but the caller can specify the format of the log file. +func FetchEntriesFromFilesWithFormat( + startTimestamp, endTimestamp int64, + maxEntries int, + pattern *regexp.Regexp, + editMode EditSensitiveData, + format string, ) ([]logpb.Entry, error) { logGroups, err := listLogGroups() if err != nil { @@ -305,7 +316,8 @@ func FetchEntriesFromFiles( endTimestamp, maxEntries-len(entries), pattern, - editMode) + editMode, + format) if err != nil { return nil, err } @@ -358,14 +370,18 @@ func readAllEntriesFromFile( maxEntries int, pattern *regexp.Regexp, editMode EditSensitiveData, + format string, ) ([]logpb.Entry, bool, error) { reader, err := GetLogReader(file.Name, true /* restricted */) - if reader == nil || err != nil { + if err != nil { return nil, false, err } defer reader.Close() entries := []logpb.Entry{} - decoder := NewEntryDecoder(reader, editMode) + decoder, err := NewEntryDecoderWithFormat(reader, editMode, format) + if err != nil { + return nil, false, err + } entryBeforeStart := false for { entry := logpb.Entry{} diff --git a/pkg/util/log/format_crdb.go b/pkg/util/log/format_crdb.go new file mode 100644 index 000000000000..f3e1294fe46b --- /dev/null +++ b/pkg/util/log/format_crdb.go @@ -0,0 +1,31 @@ +// 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 ( + "io" + + "github.com/cockroachdb/cockroach/pkg/util/log/logpb" +) + +const severityChar = "IWEF" + +// MessageTimeFormat is the format of the timestamp in log message headers of crdb formatted logs. +// as used in time.Parse and time.Format. +const MessageTimeFormat = "060102 15:04:05.999999" + +// FormatLegacyEntry writes the contents of the legacy log entry struct to the specified writer. +func FormatLegacyEntry(e logpb.Entry, w io.Writer) error { + buf := formatLogEntryInternalV1(e, false /* isHeader */, true /* showCounter */, nil) + defer putBuffer(buf) + _, err := w.Write(buf.Bytes()) + return err +} diff --git a/pkg/util/log/format_crdb_v1.go b/pkg/util/log/format_crdb_v1.go index c93b4e443508..a3b627b6e00e 100644 --- a/pkg/util/log/format_crdb_v1.go +++ b/pkg/util/log/format_crdb_v1.go @@ -25,14 +25,6 @@ import ( "github.com/cockroachdb/ttycolor" ) -// FormatLegacyEntry writes the legacy log entry to the specified writer. -func FormatLegacyEntry(e logpb.Entry, w io.Writer) error { - buf := formatLogEntryInternalV1(e, false /* isHeader */, true /* showCounter */, nil) - defer putBuffer(buf) - _, err := w.Write(buf.Bytes()) - return err -} - // formatCrdbV1 is the pre-v21.1 canonical log format, without a // counter column. type formatCrdbV1 struct{} @@ -219,8 +211,6 @@ func (formatCrdbV1TTYWithCounter) doc() string { return "Same textual format as `" + formatCrdbV1WithCounter{}.formatterName() + "`." + ttyFormatDoc } -const severityChar = "IWEF" - // formatEntryInternalV1 renders a log entry. // Log lines are colorized depending on severity. // It uses a newly allocated *buffer. The caller is responsible @@ -348,9 +338,9 @@ func formatLogEntryInternalV1( // 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 entryRE = regexp.MustCompile( +var entryREV1 = regexp.MustCompile( `(?m)^` + - /* Severity */ `([IWEF])` + + /* Severity */ `([` + severityChar + `])` + /* Date and time */ `(\d{6} \d{2}:\d{2}:\d{2}.\d{6}) ` + /* Goroutine ID */ `(?:(\d+) )?` + /* Channel/File/Line*/ `([^:]+):(\d+) ` + @@ -358,33 +348,14 @@ var entryRE = regexp.MustCompile( /* Context tags */ `(?:\[((?:[^]]|\][^ ])+)\] )?`, ) -// EntryDecoder reads successive encoded log entries from the input -// buffer. Each entry is preceded by a single big-ending uint32 -// describing the next entry's length. -type EntryDecoder struct { - re *regexp.Regexp +type entryDecoderV1 struct { scanner *bufio.Scanner sensitiveEditor redactEditor truncatedLastEntry bool } -// NewEntryDecoder creates a new instance of EntryDecoder. -func NewEntryDecoder(in io.Reader, editMode EditSensitiveData) *EntryDecoder { - d := &EntryDecoder{ - re: entryRE, - scanner: bufio.NewScanner(in), - sensitiveEditor: getEditor(editMode), - } - d.scanner.Split(d.split) - return d -} - -// MessageTimeFormat is the format of the timestamp in log message headers as -// used in time.Parse and time.Format. -const MessageTimeFormat = "060102 15:04:05.999999" - // Decode decodes the next log entry into the provided protobuf message. -func (d *EntryDecoder) Decode(entry *logpb.Entry) error { +func (d *entryDecoderV1) Decode(entry *logpb.Entry) error { for { if !d.scanner.Scan() { if err := d.scanner.Err(); err != nil { @@ -393,7 +364,7 @@ func (d *EntryDecoder) Decode(entry *logpb.Entry) error { return io.EOF } b := d.scanner.Bytes() - m := d.re.FindSubmatch(b) + m := entryREV1.FindSubmatch(b) if m == nil { continue } @@ -494,23 +465,13 @@ func (d *EntryDecoder) Decode(entry *logpb.Entry) error { } } -func trimFinalNewLines(s []byte) []byte { - for i := len(s) - 1; i >= 0; i-- { - if s[i] == '\n' { - s = s[:i] - } else { - break - } - } - return s -} - -func (d *EntryDecoder) split(data []byte, atEOF bool) (advance int, token []byte, err error) { +// split function for the crdb-v1 entry decoder scanner. +func (d *entryDecoderV1) split(data []byte, atEOF bool) (advance int, token []byte, err error) { if atEOF && len(data) == 0 { return 0, nil, nil } if d.truncatedLastEntry { - i := d.re.FindIndex(data) + i := entryREV1.FindIndex(data) if i == nil { // If there's no entry that starts in this chunk, advance past it, since // we've truncated the entry it was originally part of. @@ -528,7 +489,7 @@ func (d *EntryDecoder) split(data []byte, atEOF bool) (advance int, token []byte } // From this point on, we assume we're currently positioned at a log entry. // We want to find the next one so we start our search at data[1]. - i := d.re.FindIndex(data[1:]) + i := entryREV1.FindIndex(data[1:]) if i == nil { if atEOF { return len(data), data, nil @@ -548,3 +509,14 @@ func (d *EntryDecoder) split(data []byte, atEOF bool) (advance int, token []byte i[0]++ return i[0], data[:i[0]], nil } + +func trimFinalNewLines(s []byte) []byte { + for i := len(s) - 1; i >= 0; i-- { + if s[i] == '\n' { + s = s[:i] + } else { + break + } + } + return s +} diff --git a/pkg/util/log/format_crdb_v1_test.go b/pkg/util/log/format_crdb_v1_test.go index 6d80dfc59599..4d074a1ed6ad 100644 --- a/pkg/util/log/format_crdb_v1_test.go +++ b/pkg/util/log/format_crdb_v1_test.go @@ -57,7 +57,10 @@ func TestCrdbV1EncodeDecode(t *testing.T) { } // Decode. entryStr := buf.String() - decoder := NewEntryDecoder(strings.NewReader(entryStr), WithMarkedSensitiveData) + decoder, err := NewEntryDecoderWithFormat(strings.NewReader(entryStr), WithMarkedSensitiveData, "crdb-v1") + if err != nil { + td.Fatalf(t, "error while constructing decoder: %v", err) + } var outputEntries []logpb.Entry for { var entry logpb.Entry @@ -119,16 +122,19 @@ func TestCrdbV1EntryDecoderForVeryLargeEntries(t *testing.T) { // 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, ``, "")) + preambleLength := len(formatEntry(severity.INFO, channel.DEV, t1, 0, "somefile.go", 136, ``, "")) maxMessageLength := bufio.MaxScanTokenSize - preambleLength - 1 reallyLongEntry := string(bytes.Repeat([]byte("a"), maxMessageLength)) tooLongEntry := reallyLongEntry + "a" - 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) + contents := formatEntry(severity.INFO, channel.DEV, t1, 2, "somefile.go", 138, ``, reallyLongEntry) + contents += formatEntry(severity.INFO, channel.DEV, t2, 3, "somefile.go", 139, ``, tooLongEntry) readAllEntries := func(contents string) []logpb.Entry { - decoder := NewEntryDecoder(strings.NewReader(contents), WithFlattenedSensitiveData) + decoder, err := NewEntryDecoderWithFormat(strings.NewReader(contents), WithFlattenedSensitiveData, "crdb-v1") + if err != nil { + t.Fatal(err) + } var entries []logpb.Entry var entry logpb.Entry for { @@ -150,7 +156,7 @@ func TestCrdbV1EntryDecoderForVeryLargeEntries(t *testing.T) { Channel: channel.DEV, Time: t1.UnixNano(), Goroutine: 2, - File: `clog_test.go`, + File: `somefile.go`, Line: 138, Message: reallyLongEntry, Counter: 2, @@ -160,7 +166,7 @@ func TestCrdbV1EntryDecoderForVeryLargeEntries(t *testing.T) { Channel: channel.DEV, Time: t2.UnixNano(), Goroutine: 3, - File: `clog_test.go`, + File: `somefile.go`, Line: 139, Message: tooLongEntry[:maxMessageLength], Counter: 3, diff --git a/pkg/util/log/format_crdb_v2.go b/pkg/util/log/format_crdb_v2.go index 38266391f261..acc39bee9b5b 100644 --- a/pkg/util/log/format_crdb_v2.go +++ b/pkg/util/log/format_crdb_v2.go @@ -11,12 +11,20 @@ package log import ( + "bufio" + "bytes" + "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/errors" "github.com/cockroachdb/redact" "github.com/cockroachdb/ttycolor" ) @@ -447,3 +455,256 @@ func (buf *buffer) maybeMultiLine( var startRedactionMarker = string(redact.StartMarker()) var endRedactionMarker = string(redact.EndMarker()) var markersStartWithMultiByteRune = startRedactionMarker[0] >= utf8.RuneSelf && endRedactionMarker[0] >= utf8.RuneSelf + +var ( + entryREV2 = regexp.MustCompile( + `(?m)^` + + /* Severity */ `(?P[` + severityChar + `])` + + /* Date and time */ `(?P\d{6} \d{2}:\d{2}:\d{2}.\d{6}) ` + + /* Goroutine ID */ `(?:(?P\d+) )` + + /* Go standard library flag */ `(\(gostd\) )?` + + /* Channel */ `(?:(?P\d+)@)?` + + /* File */ `(?P[^:]+):` + + /* Line */ `(?:(?P\d+) )` + + /* Redactable flag */ `(?P(?:` + redactableIndicator + `)?) ` + + /* Context tags */ `\[(?P(?:[^]]|\][^ ])+)\] ` + + /* Counter */ `(?P(?:\d+)?) ` + + /* Continuation marker */ `(?P[ =!+|])` + + /* Message */ `(?P.*)$`, + ) + v2SeverityIdx = entryREV2.SubexpIndex("severity") + v2DateTimeIdx = entryREV2.SubexpIndex("datetime") + v2GoroutineIdx = entryREV2.SubexpIndex("goroutine") + v2ChannelIdx = entryREV2.SubexpIndex("channel") + v2FileIdx = entryREV2.SubexpIndex("file") + v2LineIdx = entryREV2.SubexpIndex("line") + v2RedactableIdx = entryREV2.SubexpIndex("redactable") + v2TagsIdx = entryREV2.SubexpIndex("tags") + v2CounterIdx = entryREV2.SubexpIndex("counter") + v2ContinuationIdx = entryREV2.SubexpIndex("continuation") + v2MsgIdx = entryREV2.SubexpIndex("msg") +) + +type entryDecoderV2 struct { + lines int // number of lines read from reader + reader *bufio.Reader + nextFragment entryDecoderV2Fragment + sensitiveEditor redactEditor +} + +// Decode decodes the next log entry into the provided protobuf message. +func (d *entryDecoderV2) Decode(entry *logpb.Entry) (err error) { + defer func() { + switch r := recover().(type) { + case nil: // do nothing + case error: + err = errors.Wrapf(r, "decoding on line %d", d.lines) + default: + panic(r) + } + }() + frag, atEOF := d.peekNextFragment() + if atEOF { + return io.EOF + } + d.popFragment() + if err := d.initEntryFromFirstLine(entry, frag); err != nil { + return err + } + + // Process the message. + var entryMsg bytes.Buffer + entryMsg.Write(frag.getMsg()) + + // While the entry has additional lines, collect the full message. + for { + frag, atEOF := d.peekNextFragment() + if atEOF || !frag.isContinuation() { + break + } + d.popFragment() + d.addContinuationFragmentToEntry(entry, &entryMsg, frag) + } + + r := redactablePackage{ + msg: entryMsg.Bytes(), + redactable: entry.Redactable, + } + r = d.sensitiveEditor(r) + entry.Message = string(r.msg) + entry.Redactable = r.redactable + + return nil +} + +func (d *entryDecoderV2) addContinuationFragmentToEntry( + entry *logpb.Entry, entryMsg *bytes.Buffer, frag entryDecoderV2Fragment, +) { + switch frag.getContinuation() { + case '+': + entryMsg.WriteByte('\n') + entryMsg.Write(frag.getMsg()) + case '|': + entryMsg.Write(frag.getMsg()) + if entry.StructuredEnd != 0 { + entry.StructuredEnd = uint32(entryMsg.Len()) + } + case '!': + if entry.StackTraceStart == 0 { + entry.StackTraceStart = uint32(entryMsg.Len()) + 1 + entryMsg.WriteString("\nstack trace:\n") + entryMsg.Write(frag.getMsg()) + } else { + entryMsg.WriteString("\n") + entryMsg.Write(frag.getMsg()) + } + default: + panic(errors.Errorf("unexpected continuation character %c", frag.getContinuation())) + } +} + +// peekNextFragment populates the nextFragment buffer by reading from the +// underlying reader a line at a time until a valid line is reached. +// It will panic if a malformed log line is discovered. It permits the first +// line in the decoder to be malformed and it will skip that line. Upon EOF, +// if there is no text left to consume, the atEOF return value will be true. +func (d *entryDecoderV2) peekNextFragment() (_ entryDecoderV2Fragment, atEOF bool) { + for d.nextFragment == nil { + d.lines++ + nextLine, err := d.reader.ReadBytes('\n') + if isEOF := errors.Is(err, io.EOF); isEOF { + if len(nextLine) == 0 { + return nil, true + } + } else if err != nil { + panic(err) + } + nextLine = bytes.TrimSuffix(nextLine, []byte{'\n'}) + m := entryREV2.FindSubmatch(nextLine) + if m == nil { + if d.lines == 1 { // allow non-matching lines if we've never seen a line + continue + } + panic(errors.New("malformed log entry")) + } + d.nextFragment = m + } + return d.nextFragment, false +} + +func (d *entryDecoderV2) popFragment() { + if d.nextFragment == nil { + panic(errors.AssertionFailedf("cannot pop unpopulated fragment")) + } + d.nextFragment = nil +} + +func (d *entryDecoderV2) initEntryFromFirstLine( + entry *logpb.Entry, m entryDecoderV2Fragment, +) (err error) { + // Erase all the fields, to be sure. + *entry = logpb.Entry{ + Severity: m.getSeverity(), + Time: m.getTimestamp(), + Goroutine: m.getGoroutine(), + Channel: m.getChannel(), + File: m.getFile(), + Line: m.getLine(), + Redactable: m.isRedactable(), + Tags: m.getTags(d.sensitiveEditor), + Counter: m.getCounter(), + } + if m.isStructured() { + entry.StructuredStart = 0 + entry.StructuredEnd = uint32(len(m.getMsg())) + } + return nil +} + +// entryDecoderV2Fragment is a line which is part of a v2 log entry. +// It is the output of entryV2RE.FindSubmatch. +type entryDecoderV2Fragment [][]byte + +func (f entryDecoderV2Fragment) getSeverity() logpb.Severity { + return Severity(strings.IndexByte(severityChar, f[v2SeverityIdx][0]) + 1) +} + +func (f entryDecoderV2Fragment) getMsg() []byte { + return f[v2MsgIdx] +} + +func (f entryDecoderV2Fragment) getContinuation() byte { + return f[v2ContinuationIdx][0] +} + +func (f entryDecoderV2Fragment) isContinuation() bool { + switch f.getContinuation() { + case '|', '+', '!': + return true + default: + return false + } +} + +func (f entryDecoderV2Fragment) getGoroutine() int64 { + return parseInt(f[v2GoroutineIdx], "goroutine") +} + +func (f entryDecoderV2Fragment) getTimestamp() (unixNano int64) { + t, err := time.Parse(MessageTimeFormat, string(f[v2DateTimeIdx])) + if err != nil { + panic(err) + } + return t.UnixNano() +} + +func (f entryDecoderV2Fragment) getChannel() logpb.Channel { + if len(f[v2ChannelIdx]) == 0 { + return Channel(0) + } + return Channel(parseInt(f[v2ChannelIdx], "channel")) +} + +func (f entryDecoderV2Fragment) getFile() string { + return string(f[v2FileIdx]) +} + +func (f entryDecoderV2Fragment) getLine() int64 { + return parseInt(f[v2LineIdx], "line") +} + +func (f entryDecoderV2Fragment) isRedactable() bool { + return len(f[v2RedactableIdx]) > 0 +} + +func (f entryDecoderV2Fragment) getTags(editor redactEditor) string { + switch tagsStr := string(f[v2TagsIdx]); tagsStr { + case "-": + return tagsStr + default: + r := editor(redactablePackage{ + msg: f[v2TagsIdx], + redactable: f.isRedactable(), + }) + return string(r.msg) + } +} + +func (f entryDecoderV2Fragment) getCounter() uint64 { + if len(f[v2CounterIdx]) == 0 { + return 0 + } + return uint64(parseInt(f[v2CounterIdx], "counter")) +} + +func (f entryDecoderV2Fragment) isStructured() bool { + return f.getContinuation() == '=' +} + +func parseInt(data []byte, name string) int64 { + i, err := strconv.ParseInt(string(data), 10, 64) + if err != nil { + panic(errors.Wrapf(err, "parsing %s", name)) + } + return i +} diff --git a/pkg/util/log/format_crdb_v2_test.go b/pkg/util/log/format_crdb_v2_test.go index 2846a62852b9..20f725b7da6f 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,34 @@ func TestFormatCrdbV2LongLineBreaks(t *testing.T) { return out }) } + +func TestCrdbV2Decode(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, err := NewEntryDecoderWithFormat(strings.NewReader(td.Input), WithMarkedSensitiveData, "crdb-v2") + if err != nil { + td.Fatalf(t, "error while constructing decoder: %v", err) + } + + for { + var e logpb.Entry + if err := d.Decode(&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/formats.go b/pkg/util/log/formats.go index 07077cdc08ab..1324898e2665 100644 --- a/pkg/util/log/formats.go +++ b/pkg/util/log/formats.go @@ -19,6 +19,19 @@ type logFormatter interface { formatEntry(entry logEntry) *buffer } +var formats = map[string]string{ + "crdb-v1": "v1", + "crdb-v1-count": "v1", + "crdb-v1-tty": "v1", + "crdb-v1-tty-count": "v1", + "crdb-v2": "v2", + "crdb-v2-tty": "v2", + "json": "json", + "json-compact": "json", + "json-fluent": "json", + "json-fluent-compact": "json", +} + var formatters = func() map[string]logFormatter { m := make(map[string]logFormatter) r := func(f logFormatter) { diff --git a/pkg/util/log/log_decoder.go b/pkg/util/log/log_decoder.go new file mode 100644 index 000000000000..26f4948dd154 --- /dev/null +++ b/pkg/util/log/log_decoder.go @@ -0,0 +1,102 @@ +// 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" + "regexp" + + "github.com/cockroachdb/cockroach/pkg/util/errorutil/unimplemented" + "github.com/cockroachdb/cockroach/pkg/util/log/logpb" + "github.com/cockroachdb/errors" +) + +// EntryDecoder is used to decode log entries. +type EntryDecoder interface { + Decode(entry *logpb.Entry) error +} + +// NewEntryDecoder creates a new instance of EntryDecoder. +// The format of the log file determines how the decoder is constructed. +func NewEntryDecoder(in io.Reader, editMode EditSensitiveData) (EntryDecoder, error) { + return NewEntryDecoderWithFormat(in, editMode, "" /*format*/) +} + +// NewEntryDecoderWithFormat is like NewEntryDecoder but the caller can specify the format of the log file. +// The header lines do not need to be searched for the log entry format when 'logFormat' is non-empty. +func NewEntryDecoderWithFormat( + in io.Reader, editMode EditSensitiveData, logFormat string, +) (EntryDecoder, error) { + var d EntryDecoder + var format string + + // If the log format has not been specified, get the format from the first few header lines of the log file. + if logFormat == "" { + var buf bytes.Buffer + rest := bufio.NewReader(in) + r := io.TeeReader(rest, &buf) + { + const headerBytes = 8096 + header := make([]byte, headerBytes) + n, err := r.Read(header) + if err != nil { + return nil, err + } + header = header[:n] + logFormat, err = getLogFormat(header) + if err != nil { + return nil, errors.Wrap(err, "decoding format") + } + } + in = io.MultiReader(&buf, rest) + } + f, ok := formats[logFormat] + if !ok { + return nil, errors.Newf("unknown log file format: %s", logFormat) + } + format = f + + switch format { + case "v2": + d = &entryDecoderV2{ + reader: bufio.NewReader(in), + sensitiveEditor: getEditor(editMode), + } + case "v1": + decoder := &entryDecoderV1{ + scanner: bufio.NewScanner(in), + sensitiveEditor: getEditor(editMode), + } + decoder.scanner.Split(decoder.split) + d = decoder + default: + return nil, unimplemented.NewWithIssue(66684, "unable to decode this log file format") + } + return d, nil +} + +// getLogFormat retrieves the log format recorded at the top of a log. +func getLogFormat(data []byte) (string, error) { + var re = regexp.MustCompile( + `(?m)^` + + /* Prefix */ `(?:.*\[config\] log format \(utf8=.+\): )` + + /* Format */ `(.*)$`, + ) + + m := re.FindSubmatch(data) + if m == nil { + return "", errors.New("failed to extract log file format from the log") + } + + return string(m[1]), nil +} diff --git a/pkg/util/log/redact_test.go b/pkg/util/log/redact_test.go index 455d7c2ddb55..5d32529919d4 100644 --- a/pkg/util/log/redact_test.go +++ b/pkg/util/log/redact_test.go @@ -170,7 +170,10 @@ func TestRedactedDecodeFile(t *testing.T) { t.Fatal(err) } defer reader.Close() - decoder := NewEntryDecoder(reader, tc.redactMode) + decoder, err := NewEntryDecoder(reader, tc.redactMode) + if err != nil { + t.Fatal(err) + } // Now verify we have what we want in the file. foundMessage := false diff --git a/pkg/util/log/testdata/parse b/pkg/util/log/testdata/parse new file mode 100644 index 000000000000..b0275df37578 --- /dev/null +++ b/pkg/util/log/testdata/parse @@ -0,0 +1,225 @@ +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +subtest end + +subtest multiline_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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x3c, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x3c, StructuredStart:0x0, StackTraceStart:0x0} + +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:\nthis is a fake stack", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:2, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x12} + +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 longer +E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] 23 !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:\nthis is a longer\nfake stack", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:2, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x12} + +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:\nthis is a fake stack", Tags:"-", Counter:0x20, Redactable:true, Channel:1, StructuredEnd:0x3c, StructuredStart:0x0, StackTraceStart:0x3d} + +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:\nthis is a fake stack", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x28} + +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:\nthis is aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa fake stack", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:2, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x12} + +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x6c, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x91, StructuredStart:0x0, StackTraceStart:0x0} + +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:\nthis is a fake stack", Tags:"noval,s‹1›,long=‹2›", Counter:0x0, Redactable:true, Channel:0, StructuredEnd:0x6c, StructuredStart:0x0, StackTraceStart:0x6d} + +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:true, Channel:1, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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›\n‹line›", Tags:"‹noval,s1,long=2›", Counter:0x0, Redactable:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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:true, Channel:0, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +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, StructuredEnd:0x6c, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} +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, StructuredEnd:0x91, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x91, StructuredStart:0x0, StackTraceStart:0x0} +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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, StructuredEnd:0x91, StructuredStart:0x0, StackTraceStart:0x0} +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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:\nthis is a fake stack", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:0, StructuredEnd:0x91, StructuredStart:0x0, StackTraceStart:0x92} +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +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:\nthis is a fake stack", Tags:"noval,s‹1›,long=‹2›", Counter:0x17, Redactable:true, Channel:0, StructuredEnd:0x91, StructuredStart:0x0, StackTraceStart:0x92} +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, StructuredEnd:0x0, StructuredStart:0x0, StackTraceStart:0x0} + +subtest end