diff --git a/pkg/util/log/format_crdb_v2.go b/pkg/util/log/format_crdb_v2.go index 73cee973b175..9c946dd6b131 100644 --- a/pkg/util/log/format_crdb_v2.go +++ b/pkg/util/log/format_crdb_v2.go @@ -12,6 +12,7 @@ package log import ( "strings" + "unicode/utf8" "github.com/cockroachdb/cockroach/pkg/util/log/channel" "github.com/cockroachdb/cockroach/pkg/util/log/severity" @@ -298,11 +299,11 @@ func formatLogEntryInternalV2(entry logEntry, cp ttycolor.Profile) *buffer { buf.Write(cp[ttycolor.Reset]) // Structured entries are guaranteed to fit on a single line already. buf.WriteByte('{') - buf.maybeMultiLine(commonPrefixLen, '+', entry.payload.message, cp) + buf.maybeMultiLine(commonPrefixLen, '+', entry.payload.redactable, entry.payload.message, cp) buf.WriteByte('}') } else { buf.WriteByte(' ') - buf.maybeMultiLine(commonPrefixLen, '+', entry.payload.message, cp) + buf.maybeMultiLine(commonPrefixLen, '+', entry.payload.redactable, entry.payload.message, cp) } if entry.stacks != nil { buf.WriteByte('\n') @@ -310,7 +311,7 @@ func formatLogEntryInternalV2(entry logEntry, cp ttycolor.Profile) *buffer { buf.Write(cp[ttycolor.Green]) buf.WriteByte('!') buf.Write(cp[ttycolor.Reset]) - buf.maybeMultiLine(commonPrefixLen, '!', string(entry.stacks), cp) + buf.maybeMultiLine(commonPrefixLen, '!', false /* redactable */, string(entry.stacks), cp) } // Ensure there is a final newline. @@ -319,12 +320,54 @@ func formatLogEntryInternalV2(entry logEntry, cp ttycolor.Profile) *buffer { return buf } -// crdbV2LongLineLen is the max length of a log line before it gets broken up into multiple lines. +// crdbV2LongLineLen is the max length of a log entry, in bytes, before +// it gets broken up into multiple lines. +// This maximum is applied to the size of the entry without considering +// the prefix (timestamp, location etc). +// The value is approximate: lines can be effectively shorter than +// this maximum. This margin exists so as to accommodate lines that +// end with a multi-byte UTF-8 sequence, as these cannot be broken up. // -// NB: the value of 1KiB is mentioned in the format's documentation above. Keep them in sync. -const crdbV2LongLineLen = 1024 +// This is implemented as a variable so it can be modified +// in unit tests. +// TODO(knz): This could also be made configurable by the user. +// +// NB: the value of this variable might be mentioned in the format's +// documentation above. Keep them in sync if necessary. +var crdbV2LongLineLen longLineLen + +func init() { + crdbV2LongLineLen.set(16 * 1000) +} + +type longLineLen int + +func (l *longLineLen) set(v int) { + // We refuse to break a long entry in the middle of a UTF-8 + // sequence, so the effective max length needs to be reduced by the + // maximum size of an UTF-8 sequence. + suffixLen := utf8.UTFMax + // We also refuse to break a long entry in the middle of a redaction + // marker. Additionally, if we observe a start redaction marker, + // we are going to insert a closing redaction marker after it + // before we break up the line. + if len(startRedactionMarker)+len(endRedactionMarker) > suffixLen { + suffixLen = len(startRedactionMarker) + len(endRedactionMarker) + } + newMax := v - suffixLen + if newMax < 1 { + panic("max line length cannot be zero or negative") + } + *l = longLineLen(newMax) +} -func (buf *buffer) maybeMultiLine(prefixLen int, contMark byte, msg string, cp ttycolor.Profile) { +func (l longLineLen) shouldBreak(lastLen int) bool { + return lastLen >= int(l) +} + +func (buf *buffer) maybeMultiLine( + prefixLen int, contMark byte, redactable bool, msg string, cp ttycolor.Profile, +) { var i int for i = len(msg) - 1; i > 0 && msg[i] == '\n'; i-- { msg = msg[:i] @@ -333,6 +376,7 @@ func (buf *buffer) maybeMultiLine(prefixLen int, contMark byte, msg string, cp t // which we've already copied into buf. k := 0 lastLen := 0 + betweenRedactionMarkers := false for i := 0; i < len(msg); i++ { if msg[i] == '\n' { buf.WriteString(msg[k : i+1]) @@ -344,8 +388,14 @@ func (buf *buffer) maybeMultiLine(prefixLen int, contMark byte, msg string, cp t lastLen = 0 continue } - if lastLen >= crdbV2LongLineLen { + if crdbV2LongLineLen.shouldBreak(lastLen) { buf.WriteString(msg[k:i]) + if betweenRedactionMarkers { + // We are breaking a long line in-between redaction + // markers. Ensures that the opening and closing markers do + // not straddle log entries. + buf.WriteString(endRedactionMarker) + } buf.WriteByte('\n') buf.Write(buf.Bytes()[0:prefixLen]) buf.Write(cp[ttycolor.Green]) @@ -353,8 +403,45 @@ func (buf *buffer) maybeMultiLine(prefixLen int, contMark byte, msg string, cp t buf.Write(cp[ttycolor.Reset]) k = i lastLen = 0 + if betweenRedactionMarkers { + // See above: if we are splitting in-between redaction + // markers, continue the sensitive item on the new line. + buf.WriteString(startRedactionMarker) + lastLen += len(startRedactionMarker) + } + } + // Common case: single-byte runes and redaction marker known to + // start with a multi-byte sequence. Take a shortcut. + if markersStartWithMultiByteRune && msg[i] < utf8.RuneSelf { + lastLen++ + continue } - lastLen++ + if redactable { + // If we see an opening redaction marker, remember this fact + // so that we close/open it properly. + if strings.HasPrefix(msg[i:], startRedactionMarker) { + betweenRedactionMarkers = true + lm := len(startRedactionMarker) + i += lm - 1 + lastLen += lm + continue + } else if strings.HasPrefix(msg[i:], endRedactionMarker) { + betweenRedactionMarkers = false + le := len(endRedactionMarker) + i += le - 1 + lastLen += le + continue + } + } + + // Avoid breaking in the middle of UTF-8 sequences. + _, width := utf8.DecodeRuneInString(msg[i:]) + i += width - 1 + lastLen += width } buf.WriteString(msg[k:]) } + +var startRedactionMarker = string(redact.StartMarker()) +var endRedactionMarker = string(redact.EndMarker()) +var markersStartWithMultiByteRune = startRedactionMarker[0] >= utf8.RuneSelf && endRedactionMarker[0] >= utf8.RuneSelf diff --git a/pkg/util/log/format_crdb_v2_test.go b/pkg/util/log/format_crdb_v2_test.go index d1f96073e4c9..2846a62852b9 100644 --- a/pkg/util/log/format_crdb_v2_test.go +++ b/pkg/util/log/format_crdb_v2_test.go @@ -14,6 +14,7 @@ import ( "bytes" "context" "fmt" + "strings" "testing" "time" @@ -35,6 +36,9 @@ func TestFormatCrdbV2(t *testing.T) { ctx = logtags.AddTag(ctx, "s", "1") ctx = logtags.AddTag(ctx, "long", "2") + defer func(prev int) { crdbV2LongLineLen.set(prev) }(int(crdbV2LongLineLen)) + crdbV2LongLineLen.set(1024) + longLine := string(bytes.Repeat([]byte("a"), 1030)) withStack := func(e logEntry) logEntry { @@ -125,3 +129,52 @@ func TestFormatCrdbV2(t *testing.T) { }) } + +func TestFormatCrdbV2LongLineBreaks(t *testing.T) { + f := formatCrdbV2{} + datadriven.RunTest(t, "testdata/crdb_v2_break_lines", func(t *testing.T, td *datadriven.TestData) string { + if td.Cmd != "run" { + t.Fatalf("unknown command: %s", td.Cmd) + } + var maxLen int + var redactable bool + td.ScanArgs(t, "maxlen", &maxLen) + td.ScanArgs(t, "redactable", &redactable) + + defer func(prev int) { crdbV2LongLineLen.set(prev) }(int(crdbV2LongLineLen)) + crdbV2LongLineLen.set(maxLen) + + entry := logEntry{ + payload: entryPayload{ + redactable: redactable, + message: td.Input, + }, + } + b := f.formatEntry(entry) + out := b.String() + putBuffer(b) + + // Sanity check: verify that no payload is longer (in bytes) than the configured max length. + const prefix1 = "I000101 00:00:00.000000 0 :0 [-] " + const prefix2 = "I000101 00:00:00.000000 0 :0 ⋮ [-] " + lines := strings.Split(out, "\n") + for i, l := range lines { + l = strings.TrimSuffix(l, "\n") + if len(l) == 0 { + continue + } + l = strings.TrimPrefix(l, prefix1) + l = strings.TrimPrefix(l, prefix2) + // Remove the start or continutation marker + if l[0] != ' ' && l[0] != '|' { + t.Fatalf("unexpected continuation marker on line %d: %q", i+1, l) + } + l = l[1:] + if len(l) > maxLen { + t.Fatalf("line too large: %d bytes, expected max %d - %q", len(l), maxLen, l) + } + } + + return out + }) +} diff --git a/pkg/util/log/testdata/crdb_v2 b/pkg/util/log/testdata/crdb_v2 index b97b7d95409c..4fe0cd6c8978 100644 --- a/pkg/util/log/testdata/crdb_v2 +++ b/pkg/util/log/testdata/crdb_v2 @@ -29,12 +29,12 @@ I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1 I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] +‹line with stack› I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] !this is a fake stack # -I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 [noval,s1,long=2] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa -I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 [noval,s1,long=2] |aaaaaa +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 [noval,s1,long=2] aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 [noval,s1,long=2] |aaaaaaaaaaaa # -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":"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa -I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] |aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›"} +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":"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] |‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›"} # E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] hello ‹stack› -E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] !this is aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa -E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] |aaaaaaaaaaaaaa fake stack +E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] !this is aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa +E060102 15:04:05.654321 11 2@util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] |aaaaaaaaaaaaaaaaaaaa fake stack diff --git a/pkg/util/log/testdata/crdb_v2_break_lines b/pkg/util/log/testdata/crdb_v2_break_lines new file mode 100644 index 000000000000..79fbe3eda849 --- /dev/null +++ b/pkg/util/log/testdata/crdb_v2_break_lines @@ -0,0 +1,186 @@ +run maxlen=100 redactable=false +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 [-] hello ‹world› and universe + +# Although the entry *seems* to contain redaction markers, +# it really does not - the redactability bit is not set. +# in that case, the redaction markers are meant to be interpreted +# as-is. +run maxlen=20 redactable=false +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 [-] hello ‹world +I000101 00:00:00.000000 0 :0 [-] |› and univer +I000101 00:00:00.000000 0 :0 [-] |se + +# Ensure that multi-byte sequences do not get broken +# up in the middle. +run maxlen=30 redactable=false +☃☃☃☃☃☃☃☃☃☃☃☃ +---- +I000101 00:00:00.000000 0 :0 [-] ☃☃☃☃☃☃☃☃ +I000101 00:00:00.000000 0 :0 [-] |☃☃☃☃ + +# Same test offset by 1, in case the previous test +# accidentally set maxlen to land exactly in-between two runes. +run maxlen=31 redactable=false +☃☃☃☃☃☃☃☃☃☃☃ +---- +I000101 00:00:00.000000 0 :0 [-] ☃☃☃☃☃☃☃☃☃ +I000101 00:00:00.000000 0 :0 [-] |☃☃ + + + +## Entries with redactability follow. These +## guarantees that redaction markers do not get +## unbalanced during splitting. + + +run maxlen=100 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹world› and universe + +# Split a long redactable string so that its "middle" spans multiple +# lines. +run maxlen=20 redactable=true +hello ‹world and universe, this is a large sentence› to the end. +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹world› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹ and univer› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹se, this is› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹ a large se› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹ntence› t +I000101 00:00:00.000000 0 :0 ⋮ [-] |o the end. + +# Ensure that multi-byte sequences do not get broken +# up in the middle. +run maxlen=30 redactable=true +☃☃☃☃☃☃☃☃☃☃☃☃ +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] ☃☃☃☃☃☃☃☃ +I000101 00:00:00.000000 0 :0 ⋮ [-] |☃☃☃☃ + +# Same test offset by 1, in case the previous test +# accidentally set maxlen to land exactly in-between two runes. +run maxlen=31 redactable=true +☃☃☃☃☃☃☃☃☃☃☃ +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] ☃☃☃☃☃☃☃☃☃ +I000101 00:00:00.000000 0 :0 ⋮ [-] |☃☃ + +# Ditto, between redaction markers. +run maxlen=30 redactable=true +‹☃☃☃☃☃☃☃☃☃☃› +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] ‹☃☃☃☃☃☃☃› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹☃☃☃› + +run maxlen=31 redactable=true +‹☃☃☃☃☃☃☃☃☃☃› +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] ‹☃☃☃☃☃☃☃☃› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹☃☃› + +# First split outside of redaction markers. +run maxlen=11 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello +I000101 00:00:00.000000 0 :0 ⋮ [-] | ‹w› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹or› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹ld› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹› +I000101 00:00:00.000000 0 :0 ⋮ [-] | and +I000101 00:00:00.000000 0 :0 ⋮ [-] |unive +I000101 00:00:00.000000 0 :0 ⋮ [-] |rse + +# First split exactly at start of opening redaction marker. +run maxlen=13 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹worl› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹d› +I000101 00:00:00.000000 0 :0 ⋮ [-] | and un +I000101 00:00:00.000000 0 :0 ⋮ [-] |iverse + +# First split inside the UTF-8 sequence of redaction markers. +run maxlen=14 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹world› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹› a +I000101 00:00:00.000000 0 :0 ⋮ [-] |nd unive +I000101 00:00:00.000000 0 :0 ⋮ [-] |rse + +# Ditto, a bit further. +run maxlen=15 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹world› +I000101 00:00:00.000000 0 :0 ⋮ [-] | and univ +I000101 00:00:00.000000 0 :0 ⋮ [-] |erse + +# Split in-between redaction markers. +run maxlen=16 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹w› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹orld› +I000101 00:00:00.000000 0 :0 ⋮ [-] | and unive +I000101 00:00:00.000000 0 :0 ⋮ [-] |rse + +# Ditto. +run maxlen=17 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹wo› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹rld› a +I000101 00:00:00.000000 0 :0 ⋮ [-] |nd universe + +# Split just before closing redaction marker. +run maxlen=20 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹world› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹› and uni +I000101 00:00:00.000000 0 :0 ⋮ [-] |verse + +# Split in the middle of the UTF-8 sequence of the closing redaction marker. +run maxlen=21 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹world› +I000101 00:00:00.000000 0 :0 ⋮ [-] | and universe + +# Ditto. +run maxlen=22 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹world› +I000101 00:00:00.000000 0 :0 ⋮ [-] | and universe + +# Split at the end of the closing redaction marker. +run maxlen=23 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹world› +I000101 00:00:00.000000 0 :0 ⋮ [-] | and universe + +# Split just after the closing redaction marker. +run maxlen=24 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹world› +I000101 00:00:00.000000 0 :0 ⋮ [-] |and universe + +# Split after a redaction pair. +run maxlen=25 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹world› a +I000101 00:00:00.000000 0 :0 ⋮ [-] |nd universe