Skip to content

Commit

Permalink
Merge #103225
Browse files Browse the repository at this point in the history 
103225: tracing: assorted tracing fixes r=dhartunian,RaduBerinde a=knz

Fixes #103052.
Fixes #103227.
Epic: CRDB-27642

Prior to this patch, structured items added to verbose traces were
improperly converted to an unsafe string prior to recording.
This was making the entire structured payload redactable in the
recording representation.

This patch fixes the situation by delegating the representation
to the structured item itself, which may implement a SafeFormat
method.

This patch also ensures that the JSON copy of structured events
is properly marked as redactable.

Co-authored-by: Raphael 'kena' Poss <[email protected]>
  • Loading branch information
@knz
craig[bot] and knz committed May 24, 2023
2 parents aaaae95 + 89a2012 commit bd6f8f5
Show file tree
Hide file tree
Showing 11 changed files with 131 additions and 101 deletions.
6 changes: 3 additions & 3 deletions DEPS.bzl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1575,10 +1575,10 @@ def go_deps():
name = "com_github_cockroachdb_redact",
build_file_proto_mode = "disable_global",
importpath = "github.com/cockroachdb/redact",
sha256 = "7778b1e4485e4f17f35e5e592d87eb99c29e173ac9507801d000ad76dd0c261e",
strip_prefix = "github.com/cockroachdb/[email protected].3",
sha256 = "9a723dfbb1627ae2f2b5d1374a59d6188ae9796e6dfb9a4622a4eb94321a4fac",
strip_prefix = "github.com/cockroachdb/[email protected].4",
urls = [
"https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/redact/com_github_cockroachdb_redact-v1.1.3.zip",
"https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/redact/com_github_cockroachdb_redact-v1.1.4.zip",
],
)
go_repository(
Expand Down
2 changes: 1 addition & 1 deletion build/bazelutil/distdir_files.bzl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -314,7 +314,7 @@ DISTDIR_FILES = {
"https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/gostdlib/com_github_cockroachdb_gostdlib-v1.19.0.zip": "c4d516bcfe8c07b6fc09b8a9a07a95065b36c2855627cb3514e40c98f872b69e",
"https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/logtags/com_github_cockroachdb_logtags-v0.0.0-20230118201751-21c54148d20b.zip": "ca7776f47e5fecb4c495490a679036bfc29d95bd7625290cfdb9abb0baf97476",
"https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/pebble/com_github_cockroachdb_pebble-v0.0.0-20230517184044-6f2788660198.zip": "bf4b7fff13bdd7c44d08910a8645621e2261236650c2ee8b68c97d0233ef9c84",
"https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/redact/com_github_cockroachdb_redact-v1.1.3.zip": "7778b1e4485e4f17f35e5e592d87eb99c29e173ac9507801d000ad76dd0c261e",
"https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/redact/com_github_cockroachdb_redact-v1.1.4.zip": "9a723dfbb1627ae2f2b5d1374a59d6188ae9796e6dfb9a4622a4eb94321a4fac",
"https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/returncheck/com_github_cockroachdb_returncheck-v0.0.0-20200612231554-92cdbca611dd.zip": "ce92ba4352deec995b1f2eecf16eba7f5d51f5aa245a1c362dfe24c83d31f82b",
"https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/sentry-go/com_github_cockroachdb_sentry_go-v0.6.1-cockroachdb.2.zip": "fbb2207d02aecfdd411b1357efe1192dbb827959e36b7cab7491731ac55935c9",
"https://storage.googleapis.com/cockroach-godeps/gomod/github.com/cockroachdb/stress/com_github_cockroachdb_stress-v0.0.0-20220803192808-1806698b1b7b.zip": "3fda531795c600daf25532a4f98be2a1335cd1e5e182c72789bca79f5f69fcc1",
Expand Down
2 changes: 1 addition & 1 deletion go.mod
View file
Original file line number Diff line number Diff line change
Expand Up @@ -117,7 +117,7 @@ require (
github.com/cockroachdb/gostdlib v1.19.0
github.com/cockroachdb/logtags v0.0.0-20230118201751-21c54148d20b
github.com/cockroachdb/pebble v0.0.0-20230517184044-6f2788660198
github.com/cockroachdb/redact v1.1.3
github.com/cockroachdb/redact v1.1.4
github.com/cockroachdb/returncheck v0.0.0-20200612231554-92cdbca611dd
github.com/cockroachdb/stress v0.0.0-20220803192808-1806698b1b7b
github.com/cockroachdb/tools v0.0.0-20211112185054-642e51449b40
Expand Down
3 changes: 2 additions & 1 deletion go.sum
View file
Original file line number Diff line number Diff line change
Expand Up @@ -488,8 +488,9 @@ github.com/cockroachdb/logtags v0.0.0-20230118201751-21c54148d20b h1:r6VH0faHjZe
github.com/cockroachdb/logtags v0.0.0-20230118201751-21c54148d20b/go.mod h1:Vz9DsVWQQhf3vs21MhPMZpMGSht7O/2vFW2xusFUVOs=
github.com/cockroachdb/pebble v0.0.0-20230517184044-6f2788660198 h1:N3vfWZcO7kckliXwwStettsidjAt67wJ5RbZaBW1bzs=
github.com/cockroachdb/pebble v0.0.0-20230517184044-6f2788660198/go.mod h1:TkdVsGYRqtULUppt2RbC+YaKtTHnHoWa2apfFrSKABw=
github.com/cockroachdb/redact v1.1.3 h1:AKZds10rFSIj7qADf0g46UixK8NNLwWTNdCIGS5wfSQ=
github.com/cockroachdb/redact v1.1.3/go.mod h1:BVNblN9mBWFyMyqK1k3AAiSxhvhfK2oOZZ2lK+dpvRg=
github.com/cockroachdb/redact v1.1.4 h1:Y0XrVI2FAyofNyGveodTN//qdpPtFKcKTeCBsK3AHAQ=
github.com/cockroachdb/redact v1.1.4/go.mod h1:BVNblN9mBWFyMyqK1k3AAiSxhvhfK2oOZZ2lK+dpvRg=
github.com/cockroachdb/returncheck v0.0.0-20200612231554-92cdbca611dd h1:KFOt5I9nEKZgCnOSmy8r4Oykh8BYQO8bFOTgHDS8YZA=
github.com/cockroachdb/returncheck v0.0.0-20200612231554-92cdbca611dd/go.mod h1:AN708GD2FFeLgUHMbD58YPe4Nw8GG//3rwgyG4L9gR0=
github.com/cockroachdb/stress v0.0.0-20220803192808-1806698b1b7b h1:JbkTu68NpiczWOaciC2QSy33RFEnnq6H2pz7viQp0rc=
Expand Down
2 changes: 1 addition & 1 deletion pkg/storage/mvcc_history_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -550,7 +550,7 @@ func TestMVCCHistories(t *testing.T) {
for i := range d.CmdArgs {
buf.Printf(" %s", &d.CmdArgs[i])
}
_ = buf.WriteByte('\n')
buf.Printf("\n")
}

// Record the engine and evaluated stats before the command, so
Expand Down
18 changes: 12 additions & 6 deletions pkg/util/tracing/span_inner.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,6 @@ package tracing

import (
"fmt"
"strings"

"github.com/cockroachdb/cockroach/pkg/util/timeutil"
"github.com/cockroachdb/cockroach/pkg/util/tracing/tracingpb"
Expand Down Expand Up @@ -266,9 +265,10 @@ func (s *spanInner) RecordStructured(item Structured) {
}
s.crdb.recordStructured(item)
if s.hasVerboseSink() {
// NB: TrimSpace avoids the trailing whitespace generated by the
// protobuf stringers.
s.Record(strings.TrimSpace(item.String()))
// Do not call .String() on the item, so that non-redactable bits
// in its representation are properly preserved by Recordf() in
// verbose recordings.
s.Recordf("%v", item)
}
}

Expand All @@ -286,10 +286,16 @@ func (s *spanInner) Recordf(format string, args ...interface{}) {
} else {
// `fmt.Sprintf` when called on a logEntry will use the faster
// `logEntry.String` method instead of `logEntry.SafeFormat`.
// The additional use of `redact.Sprintf("%s",...)` is necessary
// The additional use of `redact.Sprint(...)` is necessary
// to wrap the result in redaction markers.
str = redact.Sprintf("%s", fmt.Sprintf(format, args...))
str = redact.Sprint(fmt.Sprintf(format, args...))
}
s.recordRedactable(format, args, str)
}

func (s *spanInner) recordRedactable(
format string, args []interface{}, str redact.RedactableString,
) {
if s.otelSpan != nil {
// TODO(obs-inf): depending on the situation it may be more appropriate to
// redact the string here.
Expand Down
117 changes: 70 additions & 47 deletions pkg/util/tracing/span_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -104,23 +104,21 @@ func TestRecordingString(t *testing.T) {
event: remote child 1
span: local child
tags: _verbose=1
event: local child 1
`))
event: local child 1`))

require.NoError(t, CheckRecording(rec, `
=== operation:root _verbose:1
checkRecording(t, rec, `
=== operation:root _verbose:‹1›
[remote child]
[local child]
event:root 1
=== operation:remote child _verbose:1
event:remote child 1
event:root 2
event:root 3
=== operation:local child _verbose:1
event:local child 1
event:root 4
event:root 5
`))
event:‹root 1›
=== operation:remote child _verbose:‹1›
event:‹remote child 1›
event:‹root 2›
event:‹root 3›
=== operation:local child _verbose:‹1›
event:‹local child 1›
event:‹root 4›
event:‹root 5›`)
// Check the timing info on the first two lines.
lines := strings.Split(rec.String(), "\n")
l, err := parseLine(lines[0])
Expand Down Expand Up @@ -174,8 +172,7 @@ func TestRecordingInRecording(t *testing.T) {
span: child
tags: _verbose=1
span: grandchild
tags: _verbose=1
`))
tags: _verbose=1`))

rootRec := root.FinishAndGetRecording(tracingpb.RecordingVerbose)
require.NoError(t, CheckRecordedSpans(rootRec, `
Expand All @@ -184,14 +181,12 @@ func TestRecordingInRecording(t *testing.T) {
span: child
tags: _verbose=1
span: grandchild
tags: _verbose=1
`))
tags: _verbose=1`))

require.NoError(t, CheckRecording(childRec, `
=== operation:child _verbose:1
checkRecording(t, childRec, `
=== operation:child _verbose:‹1›
[grandchild]
=== operation:grandchild _verbose:1
`))
=== operation:grandchild _verbose:‹1›`)
}

// Verify that GetRecording propagates the structured events even when the
Expand All @@ -210,23 +205,25 @@ func TestImportRemoteRecording(t *testing.T) {
ch := tr.StartSpan("child", WithParent(sp), WithDetachedRecording())
ch.RecordStructured(&types.Int32Value{Value: 4})
ch.Record("foo")
ch.Recordf("safe %s", "unsafe")
sp.ImportRemoteRecording(ch.FinishAndGetRecording(tracingpb.RecordingVerbose))

if verbose {
require.NoError(t, CheckRecording(sp.FinishAndGetRecording(tracingpb.RecordingVerbose), `
=== operation:root _verbose:1
// Note: all the events are marked unsafe because the tracer
// was not configured to be redactable.
checkRecording(t, sp.FinishAndGetRecording(tracingpb.RecordingVerbose), `
=== operation:root _verbose:‹1›
[child]
=== operation:child _verbose:1
event:&Int32Value{Value:4,XXX_unrecognized:[],}
event:foo
structured:{"@type":"type.googleapis.com/google.protobuf.Int32Value","value":4}
`))
=== operation:child _verbose:‹1›
event:‹&Int32Value{Value:4,XXX_unrecognized:[],}›
event:‹foo›
event:‹safe unsafe›
structured:‹{"@type":"type.googleapis.com/google.protobuf.Int32Value","value":4}›`)
} else {
require.NoError(t, CheckRecording(sp.FinishAndGetRecording(tracingpb.RecordingStructured), `
checkRecording(t, sp.FinishAndGetRecording(tracingpb.RecordingStructured), `
=== operation:root
[child]
structured:{"@type":"type.googleapis.com/google.protobuf.Int32Value","value":4}
`))
structured:‹{"@type":"type.googleapis.com/google.protobuf.Int32Value","value":4}›`)
}
})
}
Expand All @@ -250,27 +247,55 @@ func TestImportRemoteRecordingMaintainsRightByteSize(t *testing.T) {
rootTrace.check(t)
}

func TestSpanRecordStructuredRedactable(t *testing.T) {
tr := NewTracer()
tr.SetRedactable(true)
sp := tr.StartSpan("root", WithRecording(tracingpb.RecordingVerbose))
defer sp.Finish()

payload := &tracingpb.OperationMetadata{Count: 123}
sp.RecordStructured(payload)
rec := sp.GetRecording(tracingpb.RecordingStructured)

// The following check fails if RecordStructured incorrectly
// serializes the event to a string.
checkRecordingWithRedact(t, rec, `
=== operation:root
event:{count: 123, duration 0µs}
structured:‹×›`, true)
}

func TestSpanRecordStructured(t *testing.T) {
tr := NewTracer()
sp := tr.StartSpan("root", WithRecording(tracingpb.RecordingStructured))
defer sp.Finish()

sp.RecordStructured(&types.Int32Value{Value: 4})
// Use a complex struct as payload -- the particular type doesn't
// matter, we just care to use a type for which a pretty-printer was
// generated by gogoproto.
payload1 := &tracingpb.OperationMetadata{Duration: 3 * time.Second}
payload2 := &types.Int32Value{Value: 4}
sp.RecordStructured(payload1)
sp.RecordStructured(payload2)
rec := sp.GetRecording(tracingpb.RecordingStructured)
require.Len(t, rec, 1)
require.Len(t, rec[0].StructuredRecords, 1)
require.Len(t, rec[0].StructuredRecords, 2)
item := rec[0].StructuredRecords[0]
var d1 types.DynamicAny
require.NoError(t, types.UnmarshalAny(item.Payload, &d1))
require.IsType(t, (*types.Int32Value)(nil), d1.Message)
require.IsType(t, (*tracingpb.OperationMetadata)(nil), d1.Message)
item2 := rec[0].StructuredRecords[1]
var d2 types.DynamicAny
require.NoError(t, types.UnmarshalAny(item2.Payload, &d2))
require.IsType(t, (*types.Int32Value)(nil), d2.Message)

require.NoError(t, CheckRecordedSpans(rec, `
span: root
`))
require.NoError(t, CheckRecording(rec, `
checkRecording(t, rec, `
=== operation:root
structured:{"@type":"type.googleapis.com/google.protobuf.Int32Value","value":4}
`))
structured:‹{"@type":"type.googleapis.com/cockroach.util.tracing.tracingpb.OperationMetadata","duration":"3s","count":"0","containsUnfinished":false}›
structured:‹{"@type":"type.googleapis.com/google.protobuf.Int32Value","value":4}›`)
}

// TestSpanRecordStructuredLimit tests recording behavior when the size of
Expand Down Expand Up @@ -1334,11 +1359,10 @@ func TestOpenChildIncludedRecording(t *testing.T) {
parent := tr.StartSpan("parent", WithRecording(tracingpb.RecordingVerbose))
child := tr.StartSpan("child", WithParent(parent))
rec := parent.FinishAndGetRecording(tracingpb.RecordingVerbose)
require.NoError(t, CheckRecording(rec, `
=== operation:parent _verbose:1
checkRecording(t, rec, `
=== operation:parent _verbose:‹1›
[child]
=== operation:child _unfinished:1 _verbose:1
`))
=== operation:child _unfinished:‹1› _verbose:‹1›`)
child.Finish()
}

Expand Down Expand Up @@ -1576,10 +1600,9 @@ func TestWithEventListenersAndVerboseParent(t *testing.T) {
_, child := EnsureChildSpan(context.Background(), tr, "child", WithParent(parent), WithEventListeners())
defer child.Finish()
child.Record("foo")
require.NoError(t, CheckRecording(parent.GetConfiguredRecording(), `
=== operation:parent _unfinished:1 _verbose:1
checkRecording(t, parent.GetConfiguredRecording(), `
=== operation:parent _unfinished:‹1› _verbose:‹1›
[child]
=== operation:child _unfinished:1 _verbose:1
event:foo
`))
=== operation:child _unfinished:‹1› _verbose:‹1›
event:‹foo›`)
}
35 changes: 23 additions & 12 deletions pkg/util/tracing/test_utils.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@ import (

"github.com/cockroachdb/cockroach/pkg/util/tracing/tracingpb"
"github.com/cockroachdb/errors"
"github.com/cockroachdb/redact"
"github.com/pmezard/go-difflib/difflib"
)

Expand Down Expand Up @@ -160,27 +161,34 @@ func CheckRecordedSpans(rec tracingpb.Recording, expected string) error {
return nil
}

// CheckRecording checks whether a recording looks like the expected
// T is a subset of testing.TB.
type T interface {
Fatalf(format string, args ...interface{})
}

// checkRecording checks whether a recording looks like the expected
// one. The expected string is allowed to elide timing information, and the
// outer-most indentation level is adjusted for when comparing.
//
// if err := CheckRecording(sp.GetRecording(), `
// checkRecording(t, sp.GetRecording(), `
// === operation:root
// [childrenMetadata]
// event:root 1
// === operation:remote child
// event:remote child 1
// `); err != nil {
// t.Fatal(err)
// }
func CheckRecording(rec tracingpb.Recording, expected string) error {
// `)
func checkRecording(t T, rec tracingpb.Recording, expected string) {
checkRecordingWithRedact(t, rec, expected, false)
}

func checkRecordingWithRedact(t T, rec tracingpb.Recording, expected string, redactValues bool) {
normalize := func(rec string) string {
// normalize the string form of a recording for ease of comparison.
//
// 1. Strip out any leading new lines.
rec = strings.TrimLeft(rec, "\n")
// 2. Strip out trailing space.
rec = strings.TrimRight(rec, "\n\t ")
// 2. Strip out trailing newlines.
rec = strings.TrimRight(rec, "\n")
// 3. Strip out all timing information from the recordings.
//
// Before | "0.007ms 0.007ms event:root 1"
Expand All @@ -191,7 +199,7 @@ func CheckRecording(rec tracingpb.Recording, expected string) error {
//
// Before | [operation: {Count:<count>, Duration:<duration>}]
// After | [operation]
re = regexp.MustCompile(`:.*]`)
re = regexp.MustCompile(`: .*]`)
rec = string(re.ReplaceAll([]byte(rec), []byte("]")))
// 5. Change all tabs to four spaces.
rec = strings.ReplaceAll(rec, "\t", " ")
Expand Down Expand Up @@ -231,8 +239,12 @@ func CheckRecording(rec tracingpb.Recording, expected string) error {
sortChildrenMetadataByName(rec[i].ChildrenMetadata)
}

actual := redact.Sprint(rec)
if redactValues {
actual = actual.Redact()
}
exp := normalize(expected)
got := normalize(rec.String())
got := normalize(string(actual))
if got != exp {
diff := difflib.UnifiedDiff{
A: difflib.SplitLines(exp),
Expand All @@ -242,7 +254,6 @@ func CheckRecording(rec tracingpb.Recording, expected string) error {
Context: 4,
}
diffText, _ := difflib.GetUnifiedDiffString(diff)
return errors.Newf("unexpected diff:\n%s", diffText)
t.Fatalf("unexpected diff:\n%s", redact.RedactableString(diffText))
}
return nil
}
Loading

0 comments on commit bd6f8f5

Please sign in to comment.