log: create crdb-v2 log entry parser

The crdb-v2 log file format is not recognized by some tools like debug merge-log.
This is makes it difficult/impossible to merge log files properly.
This patch creates a new parser and integrates it into debug merge-log.

Release note (cli change): the tool debug merge-log is now integrated with a
crdb-v2 log entry parser.

pkg/cli/debug_merge_logs.go

@@ -527,6 +527,62 @@ func (s *fileLogStream) peek() (logpb.Entry, bool) {
 	}
 	return s.e, s.err == nil
 }
+func (s *fileLogStream) peekV2() (logpb.Entry, bool) {
+	for !s.read && s.err == nil {
+		justOpened := false
+		if s.d == nil {
+			if !s.open() {
+				return logpb.Entry{}, false
+			}
+			justOpened = true
+		}
+		var e logpb.Entry
+		moreLines := true
+		for ; moreLines ; {
+			var subE logpb.Entry
+			if s.err = s.d.DecodeV2(&subE); s.err != nil {
+				s.close()
+				s.e = logpb.Entry{}
+				break
+			}
+			if e.File == "" {
+				e = subE
+			} else if e.Counter == subE.Counter {
+				if string(subE.Message[0]) == "|" {
+					e.Message += subE.Message[1:]
+				}
+				if string(subE.Message[0]) == "+" {
+					e.Message += "\n" + subE.Message[1:]
+				}
+			} else {
+				moreLines = false
+			}
+		}
+		if s.err != nil {
+			break
+		}
+		// Upon re-opening the file, we'll read s.e again.
+		if justOpened && e == s.e {
+			continue
+		}
+		s.e = e
+		if s.e.Time < s.prevTime {
+			s.e.Time = s.prevTime
+		} else {
+			s.prevTime = s.e.Time
+		}
+		afterTo := !s.to.IsZero() && s.e.Time > s.to.UnixNano()
+		if afterTo {
+			s.close()
+			s.e = logpb.Entry{}
+			s.err = io.EOF
+		} else {
+			beforeFrom := !s.from.IsZero() && s.e.Time < s.from.UnixNano()
+			s.read = !beforeFrom
+		}
+	}
+	return s.e, s.err == nil
+}
 
 func (s *fileLogStream) pop() (e logpb.Entry, ok bool) {
 	if e, ok = s.peek(); !ok {

pkg/util/log/format_crdb_v2.go

@@ -11,10 +11,14 @@
 package log
 
 import (
+	"io"
+	"strconv"
 	"strings"
+	"time"
 	"unicode/utf8"
 
 	"github.com/cockroachdb/cockroach/pkg/util/log/channel"
+	"github.com/cockroachdb/cockroach/pkg/util/log/logpb"
 	"github.com/cockroachdb/cockroach/pkg/util/log/severity"
 	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
 	"github.com/cockroachdb/redact"
@@ -447,3 +451,90 @@ func (buf *buffer) maybeMultiLine(
 var startRedactionMarker = string(redact.StartMarker())
 var endRedactionMarker = string(redact.EndMarker())
 var markersStartWithMultiByteRune = startRedactionMarker[0] >= utf8.RuneSelf && endRedactionMarker[0] >= utf8.RuneSelf
+
+// DecodeV2 decodes the next log entry into the provided protobuf message.
+func (d *EntryDecoder) DecodeV2(entry *logpb.Entry) error {
+	for {
+		if !d.scanner.Scan() {
+			if err := d.scanner.Err(); err != nil {
+				return err
+			}
+			return io.EOF
+		}
+		b := d.scanner.Bytes()
+		m := d.re.FindSubmatch(b)
+		if m == nil {
+			continue
+		}
+
+		// Erase all the fields, to be sure.
+		*entry = logpb.Entry{}
+
+		// Process the severity.
+		entry.Severity = Severity(strings.IndexByte(severityChar, m[1][0]) + 1)
+
+		// Process the timestamp.
+		t, err := time.Parse(MessageTimeFormat, string(m[2]))
+		if err != nil {
+			return err
+		}
+		entry.Time = t.UnixNano()
+
+		// Process the goroutine ID.
+		if len(m[3]) > 0 {
+			goroutine, err := strconv.Atoi(string(m[3]))
+			if err != nil {
+				return err
+			}
+			entry.Goroutine = int64(goroutine)
+		}
+
+		// Process the channel/file/line details.
+		entry.File = string(m[4])
+		// Ignore the `(gostd)` prefix when present
+		if entry.File[:7] == "(gostd)" {
+			entry.File = entry.File[8:]
+		}
+		if idx := strings.IndexByte(entry.File, '@'); idx != -1 {
+			ch, err := strconv.Atoi(entry.File[:idx])
+			if err != nil {
+				return err
+			}
+			entry.Channel = Channel(ch)
+			entry.File = entry.File[idx+1:]
+		}
+
+		line, err := strconv.Atoi(string(m[5]))
+		if err != nil {
+			return err
+		}
+		entry.Line = int64(line)
+
+		// Process the context tags.
+		redactable := len(m[6]) != 0
+		r := redactablePackage{
+			msg:        m[7],
+			redactable: redactable,
+		}
+		r = d.sensitiveEditor(r)
+		entry.Tags = string(r.msg)
+
+		// Process the entry counter.
+		msg := b[len(m[0]):]
+		i := 0
+		for ; i < len(msg) && msg[i] >= '0' && msg[i] <= '9'; i++ {
+			entry.Counter = entry.Counter*10 + uint64(msg[i]-'0')
+		}
+		msg = msg[i+1:]
+
+		// Process the remainder of the log message.
+		r = redactablePackage{
+			msg:        trimFinalNewLines(msg),
+			redactable: redactable,
+		}
+		r = d.sensitiveEditor(r)
+		entry.Message = string(r.msg)
+		entry.Redactable = r.redactable
+		return nil
+	}
+}

pkg/util/log/format_crdb_v2_test.go

@@ -14,15 +14,18 @@ import (
 	"bytes"
 	"context"
 	"fmt"
+	"strconv"
 	"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/olekukonko/tablewriter"
 )
 
 func TestFormatCrdbV2(t *testing.T) {
@@ -178,3 +181,49 @@ func TestFormatCrdbV2LongLineBreaks(t *testing.T) {
 		return out
 	})
 }
+
+func TestEntryDecoderV2(t *testing.T) {
+	datadriven.RunTest(t, "testdata/parse",
+		func(t *testing.T, td *datadriven.TestData) string {
+			switch td.Cmd {
+			case "line":
+				var e logpb.Entry
+				fmt.Println("Here")
+				fmt.Println(e.File == "")
+				err := NewEntryDecoder(strings.NewReader(td.Input), 1).DecodeV2(&e)
+				if err != nil {
+					return fmt.Sprintf("error: %v\n", err)
+				}
+				var sb strings.Builder
+				sb.WriteString("# Original configuration:\n")
+				sb.WriteString("# " + td.Input + "\n")
+				sb.WriteString("#\n# Interpreted configuration:\n")
+
+				table := tablewriter.NewWriter(&sb)
+				table.SetAutoWrapText(false)
+				table.SetReflowDuringAutoWrap(false)
+				table.SetAlignment(tablewriter.ALIGN_LEFT)
+				table.SetBorder(false)
+				table.SetNoWhiteSpace(true)
+				table.SetTrimWhiteSpaceAtEOL(true)
+				table.SetTablePadding(" ")
+
+				row := []string{"# SEVERITY", "TIME", "GOROUTINE", "FILE", "LINE", "MESSAGE", "TAGS", "COUNTER", "CHANNEL"}
+				table.Append(row)
+				row[0] = e.Severity.String()
+				row[1] = strconv.FormatInt(e.Time, 10)
+				row[2] = strconv.FormatInt(e.Goroutine, 10)
+				row[3] = e.File
+				row[4] = strconv.FormatInt(e.Line, 10)
+				row[5] = e.Message
+				row[6] = e.Tags
+				row[7] = strconv.FormatUint(e.Counter, 10)
+				row[8] = e.Channel.String()
+				table.Append(row)
+				table.Render()
+				return sb.String()
+			default:
+				return fmt.Sprintf("unknown directive: %s", td.Cmd)
+			}
+		})
+}

pkg/util/log/testdata/parse

@@ -0,0 +1,39 @@
+subtest single_line_unstructured
+
+line
+I210116 21:49:17.073282 14 server/node.go:464 ⋮ [-] 23  started with engine type ‹2›
+----
+# Original configuration:
+# I210116 21:49:17.073282 14 server/node.go:464 ⋮ [-] 23  started with engine type ‹2›
+#
+# Interpreted configuration:
+# SEVERITY TIME                GOROUTINE FILE           LINE MESSAGE                     TAGS COUNTER CHANNEL
+INFO       1610833757073282000 14        server/node.go 464   started with engine type 2 -    23      DEV
+
+line
+I210116 21:49:17.073282 14 (gostd) server/node.go:464 ⋮ [-] 23  started with engine type ‹2›
+----
+# Original configuration:
+# I210116 21:49:17.073282 14 (gostd) server/node.go:464 ⋮ [-] 23  started with engine type ‹2›
+#
+# Interpreted configuration:
+# SEVERITY TIME                GOROUTINE FILE           LINE MESSAGE                     TAGS COUNTER CHANNEL
+INFO       1610833757073282000 14        server/node.go 464   started with engine type 2 -    23      DEV
+
+subtest end
+
+subtest single_line_structured
+
+line
+I210116 21:49:17.080713 14 1@util/log/event_log.go:32 ⋮ [-] 32 ={"Timestamp":1610833757080706620,"EventType":"node_restart"}
+----
+# Original configuration:
+# I210116 21:49:17.080713 14 1@util/log/event_log.go:32 ⋮ [-] 32 ={"Timestamp":1610833757080706620,"EventType":"node_restart"}
+#
+# Interpreted configuration:
+# SEVERITY TIME                GOROUTINE FILE                  LINE MESSAGE                                                       TAGS COUNTER CHANNEL
+INFO       1610833757080713000 14        util/log/event_log.go 32   ={"Timestamp":1610833757080706620,"EventType":"node_restart"} -    32      OPS
+
+subtest end
+
+