From 386d87c7f29dcad81693c914a0efb34746342d40 Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Fri, 7 May 2021 23:29:37 +0200 Subject: [PATCH 1/3] util/log: default the line split size to 16K instead of 1K Release note (cli change): Long lines in the `crdb-v2` output logging format are now split when they exceed 16K, instead of 1K as previously. --- pkg/util/log/format_crdb_v2.go | 12 +++++++++--- pkg/util/log/format_crdb_v2_test.go | 3 +++ 2 files changed, 12 insertions(+), 3 deletions(-) diff --git a/pkg/util/log/format_crdb_v2.go b/pkg/util/log/format_crdb_v2.go index 73cee973b175..1874819d9d25 100644 --- a/pkg/util/log/format_crdb_v2.go +++ b/pkg/util/log/format_crdb_v2.go @@ -319,10 +319,16 @@ 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 line, in bytes, before +// it gets broken up into multiple lines. // -// 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 = 16 * 1000 func (buf *buffer) maybeMultiLine(prefixLen int, contMark byte, msg string, cp ttycolor.Profile) { var i int diff --git a/pkg/util/log/format_crdb_v2_test.go b/pkg/util/log/format_crdb_v2_test.go index d1f96073e4c9..3735b8ed1c5e 100644 --- a/pkg/util/log/format_crdb_v2_test.go +++ b/pkg/util/log/format_crdb_v2_test.go @@ -35,6 +35,9 @@ func TestFormatCrdbV2(t *testing.T) { ctx = logtags.AddTag(ctx, "s", "1") ctx = logtags.AddTag(ctx, "long", "2") + defer func(prev int) { crdbV2LongLineLen = prev }(crdbV2LongLineLen) + crdbV2LongLineLen = 1024 + longLine := string(bytes.Repeat([]byte("a"), 1030)) withStack := func(e logEntry) logEntry { From 3b2828e857024142be70c845ad40e6e73db07e17 Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Sat, 8 May 2021 00:29:08 +0200 Subject: [PATCH 2/3] util/log: fix line splitting behavior Release note (bug fix): The automatic long line splitting behavior of the new `crdb-v2` logging format now avoids splitting lines in the middle of UTF-8 sequences, and avoids unbalanced redaction markers. --- pkg/util/log/format_crdb_v2.go | 56 ++++++- pkg/util/log/format_crdb_v2_test.go | 26 ++++ pkg/util/log/testdata/crdb_v2 | 4 +- pkg/util/log/testdata/crdb_v2_break_lines | 179 ++++++++++++++++++++++ 4 files changed, 258 insertions(+), 7 deletions(-) create mode 100644 pkg/util/log/testdata/crdb_v2_break_lines diff --git a/pkg/util/log/format_crdb_v2.go b/pkg/util/log/format_crdb_v2.go index 1874819d9d25..6616e599e4ac 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. @@ -330,7 +331,9 @@ func formatLogEntryInternalV2(entry logEntry, cp ttycolor.Profile) *buffer { // documentation above. Keep them in sync if necessary. var crdbV2LongLineLen = 16 * 1000 -func (buf *buffer) maybeMultiLine(prefixLen int, contMark byte, msg string, cp ttycolor.Profile) { +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] @@ -339,6 +342,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]) @@ -352,15 +356,57 @@ func (buf *buffer) maybeMultiLine(prefixLen int, contMark byte, msg string, cp t } if lastLen >= crdbV2LongLineLen { 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]) buf.WriteByte('|') buf.Write(cp[ttycolor.Reset]) + if betweenRedactionMarkers { + // See above: if we are splitting in-between redaction + // markers, continue the sensitive item on the new line. + buf.WriteString(startRedactionMarker) + } k = i lastLen = 0 } - lastLen++ + // 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 + } + 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 3735b8ed1c5e..e59918022efb 100644 --- a/pkg/util/log/format_crdb_v2_test.go +++ b/pkg/util/log/format_crdb_v2_test.go @@ -128,3 +128,29 @@ 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 = prev }(crdbV2LongLineLen) + crdbV2LongLineLen = maxLen + + entry := logEntry{ + payload: entryPayload{ + redactable: redactable, + message: td.Input, + }, + } + b := f.formatEntry(entry) + defer putBuffer(b) + return b.String() + }) +} diff --git a/pkg/util/log/testdata/crdb_v2 b/pkg/util/log/testdata/crdb_v2 index b97b7d95409c..012c688d1be2 100644 --- a/pkg/util/log/testdata/crdb_v2 +++ b/pkg/util/log/testdata/crdb_v2 @@ -32,8 +32,8 @@ 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,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,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":"‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa› +I060102 15:04:05.654321 11 util/log/format_crdb_v2_test.go:123 ⋮ [noval,s‹1›,long=‹2›] |‹aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa›"} # 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 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..50938e48de24 --- /dev/null +++ b/pkg/util/log/testdata/crdb_v2_break_lines @@ -0,0 +1,179 @@ +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=10 redactable=false +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 [-] hello ‹w +I000101 00:00:00.000000 0 :0 [-] |orld› an +I000101 00:00:00.000000 0 :0 [-] |d universe + +# Ensure that multi-byte sequences do not get broken +# up in the middle. +run maxlen=20 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=21 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=14 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 universe,› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹ this is a lar› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹ge sentence› +I000101 00:00:00.000000 0 :0 ⋮ [-] | to the end. + +# Ensure that multi-byte sequences do not get broken +# up in the middle. +run maxlen=20 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=21 redactable=true +☃☃☃☃☃☃☃☃☃☃☃ +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] ☃☃☃☃☃☃☃ +I000101 00:00:00.000000 0 :0 ⋮ [-] |☃☃☃☃ + +# Ditto, between redaction markers. +run maxlen=20 redactable=true +‹☃☃☃☃☃☃☃☃☃☃› +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] ‹☃☃☃☃☃☃› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹☃☃☃☃› + +run maxlen=21 redactable=true +‹☃☃☃☃☃☃☃☃☃☃› +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] ‹☃☃☃☃☃☃› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹☃☃☃☃› + +# First split outside of redaction markers. +run maxlen=6 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹wor› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹ld› +I000101 00:00:00.000000 0 :0 ⋮ [-] |and un +I000101 00:00:00.000000 0 :0 ⋮ [-] |iverse + +# First split exactly at start of opening redaction marker. +run maxlen=7 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 un +I000101 00:00:00.000000 0 :0 ⋮ [-] |iverse + +# First split inside the UTF-8 sequence of redaction markers. +run maxlen=8 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 uni +I000101 00:00:00.000000 0 :0 ⋮ [-] |verse + +# Ditto, a bit further. +run maxlen=9 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 unive +I000101 00:00:00.000000 0 :0 ⋮ [-] |rse + +# Split in-between redaction markers. +run maxlen=10 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹w› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹orld› an +I000101 00:00:00.000000 0 :0 ⋮ [-] |d universe + +# Ditto. +run maxlen=13 redactable=true +hello ‹world› and universe +---- +I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹worl› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹d› and univ +I000101 00:00:00.000000 0 :0 ⋮ [-] |erse + +# Split just before closing redaction marker. +run maxlen=14 redactable=true +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 + +# Split in the middle of the UTF-8 sequence of the closing redaction marker. +run maxlen=15 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=16 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=17 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=18 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=19 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 From 35fea82e5f2ff2fa26384d3ca10a198093943587 Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Mon, 10 May 2021 12:00:27 +0200 Subject: [PATCH 3/3] util/log: better honor the maximum line length This way if/when we ever make it configurable and document it, there won't be any surprises. Release note: None --- pkg/util/log/format_crdb_v2.go | 45 +++++++- pkg/util/log/format_crdb_v2_test.go | 36 +++++-- pkg/util/log/testdata/crdb_v2 | 12 +-- pkg/util/log/testdata/crdb_v2_break_lines | 121 ++++++++++++---------- 4 files changed, 140 insertions(+), 74 deletions(-) diff --git a/pkg/util/log/format_crdb_v2.go b/pkg/util/log/format_crdb_v2.go index 6616e599e4ac..9c946dd6b131 100644 --- a/pkg/util/log/format_crdb_v2.go +++ b/pkg/util/log/format_crdb_v2.go @@ -320,8 +320,13 @@ func formatLogEntryInternalV2(entry logEntry, cp ttycolor.Profile) *buffer { return buf } -// crdbV2LongLineLen is the max length of a log line, in bytes, before +// 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. // // This is implemented as a variable so it can be modified // in unit tests. @@ -329,7 +334,36 @@ func formatLogEntryInternalV2(entry logEntry, cp ttycolor.Profile) *buffer { // // NB: the value of this variable might be mentioned in the format's // documentation above. Keep them in sync if necessary. -var crdbV2LongLineLen = 16 * 1000 +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 (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, @@ -354,7 +388,7 @@ func (buf *buffer) maybeMultiLine( 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 @@ -367,13 +401,14 @@ func (buf *buffer) maybeMultiLine( buf.Write(cp[ttycolor.Green]) buf.WriteByte('|') 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) } - k = i - lastLen = 0 } // Common case: single-byte runes and redaction marker known to // start with a multi-byte sequence. Take a shortcut. diff --git a/pkg/util/log/format_crdb_v2_test.go b/pkg/util/log/format_crdb_v2_test.go index e59918022efb..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,8 +36,8 @@ func TestFormatCrdbV2(t *testing.T) { ctx = logtags.AddTag(ctx, "s", "1") ctx = logtags.AddTag(ctx, "long", "2") - defer func(prev int) { crdbV2LongLineLen = prev }(crdbV2LongLineLen) - crdbV2LongLineLen = 1024 + defer func(prev int) { crdbV2LongLineLen.set(prev) }(int(crdbV2LongLineLen)) + crdbV2LongLineLen.set(1024) longLine := string(bytes.Repeat([]byte("a"), 1030)) @@ -140,8 +141,8 @@ func TestFormatCrdbV2LongLineBreaks(t *testing.T) { td.ScanArgs(t, "maxlen", &maxLen) td.ScanArgs(t, "redactable", &redactable) - defer func(prev int) { crdbV2LongLineLen = prev }(crdbV2LongLineLen) - crdbV2LongLineLen = maxLen + defer func(prev int) { crdbV2LongLineLen.set(prev) }(int(crdbV2LongLineLen)) + crdbV2LongLineLen.set(maxLen) entry := logEntry{ payload: entryPayload{ @@ -150,7 +151,30 @@ func TestFormatCrdbV2LongLineBreaks(t *testing.T) { }, } b := f.formatEntry(entry) - defer putBuffer(b) - return b.String() + 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 012c688d1be2..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 index 50938e48de24..79fbe3eda849 100644 --- a/pkg/util/log/testdata/crdb_v2_break_lines +++ b/pkg/util/log/testdata/crdb_v2_break_lines @@ -7,28 +7,28 @@ I000101 00:00:00.000000 0 :0 [-] hello ‹world› and universe # 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=10 redactable=false +run maxlen=20 redactable=false hello ‹world› and universe ---- -I000101 00:00:00.000000 0 :0 [-] hello ‹w -I000101 00:00:00.000000 0 :0 [-] |orld› an -I000101 00:00:00.000000 0 :0 [-] |d 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=20 redactable=false +run maxlen=30 redactable=false ☃☃☃☃☃☃☃☃☃☃☃☃ ---- -I000101 00:00:00.000000 0 :0 [-] ☃☃☃☃☃☃☃ -I000101 00:00:00.000000 0 :0 [-] |☃☃☃☃☃ +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=21 redactable=false +run maxlen=31 redactable=false ☃☃☃☃☃☃☃☃☃☃☃ ---- -I000101 00:00:00.000000 0 :0 [-] ☃☃☃☃☃☃☃ -I000101 00:00:00.000000 0 :0 [-] |☃☃☃☃ +I000101 00:00:00.000000 0 :0 [-] ☃☃☃☃☃☃☃☃☃ +I000101 00:00:00.000000 0 :0 [-] |☃☃ @@ -44,135 +44,142 @@ 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=14 redactable=true +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 universe,› -I000101 00:00:00.000000 0 :0 ⋮ [-] |‹ this is a lar› -I000101 00:00:00.000000 0 :0 ⋮ [-] |‹ge sentence› -I000101 00:00:00.000000 0 :0 ⋮ [-] | to the end. +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=20 redactable=true +run maxlen=30 redactable=true ☃☃☃☃☃☃☃☃☃☃☃☃ ---- -I000101 00:00:00.000000 0 :0 ⋮ [-] ☃☃☃☃☃☃☃ -I000101 00:00:00.000000 0 :0 ⋮ [-] |☃☃☃☃☃ +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=21 redactable=true +run maxlen=31 redactable=true ☃☃☃☃☃☃☃☃☃☃☃ ---- -I000101 00:00:00.000000 0 :0 ⋮ [-] ☃☃☃☃☃☃☃ -I000101 00:00:00.000000 0 :0 ⋮ [-] |☃☃☃☃ +I000101 00:00:00.000000 0 :0 ⋮ [-] ☃☃☃☃☃☃☃☃☃ +I000101 00:00:00.000000 0 :0 ⋮ [-] |☃☃ # Ditto, between redaction markers. -run maxlen=20 redactable=true +run maxlen=30 redactable=true ‹☃☃☃☃☃☃☃☃☃☃› ---- -I000101 00:00:00.000000 0 :0 ⋮ [-] ‹☃☃☃☃☃☃› -I000101 00:00:00.000000 0 :0 ⋮ [-] |‹☃☃☃☃› +I000101 00:00:00.000000 0 :0 ⋮ [-] ‹☃☃☃☃☃☃☃› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹☃☃☃› -run maxlen=21 redactable=true +run maxlen=31 redactable=true ‹☃☃☃☃☃☃☃☃☃☃› ---- -I000101 00:00:00.000000 0 :0 ⋮ [-] ‹☃☃☃☃☃☃› -I000101 00:00:00.000000 0 :0 ⋮ [-] |‹☃☃☃☃› +I000101 00:00:00.000000 0 :0 ⋮ [-] ‹☃☃☃☃☃☃☃☃› +I000101 00:00:00.000000 0 :0 ⋮ [-] |‹☃☃› # First split outside of redaction markers. -run maxlen=6 redactable=true +run maxlen=11 redactable=true hello ‹world› and universe ---- -I000101 00:00:00.000000 0 :0 ⋮ [-] hello -I000101 00:00:00.000000 0 :0 ⋮ [-] |‹wor› -I000101 00:00:00.000000 0 :0 ⋮ [-] |‹ld› -I000101 00:00:00.000000 0 :0 ⋮ [-] |and un -I000101 00:00:00.000000 0 :0 ⋮ [-] |iverse +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=7 redactable=true +run maxlen=13 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 ⋮ [-] |‹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=8 redactable=true +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 ⋮ [-] | and uni -I000101 00:00:00.000000 0 :0 ⋮ [-] |verse +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=9 redactable=true +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 unive -I000101 00:00:00.000000 0 :0 ⋮ [-] |rse +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=10 redactable=true +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› an -I000101 00:00:00.000000 0 :0 ⋮ [-] |d universe +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=13 redactable=true +run maxlen=17 redactable=true hello ‹world› and universe ---- -I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹worl› -I000101 00:00:00.000000 0 :0 ⋮ [-] |‹d› and univ -I000101 00:00:00.000000 0 :0 ⋮ [-] |erse +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=14 redactable=true +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 univer -I000101 00:00:00.000000 0 :0 ⋮ [-] |se +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=15 redactable=true +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=16 redactable=true +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=17 redactable=true +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=18 redactable=true +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=19 redactable=true +run maxlen=25 redactable=true hello ‹world› and universe ---- I000101 00:00:00.000000 0 :0 ⋮ [-] hello ‹world› a