server, tracing: force redactability on tenant spans

Prior commits added the ability to set a flag on the Tracer to determine
whether Span's should be marked redactable or not. This commit adds
logic to selectively force redactability enabled on Spans for requests
that come from a non-system tenant.

The desired outcome is to preserve redactability for tenant traces while
preserving a non-redactable code path for requests using the system
tenant. This preserves existing functionality in production while
keeping the current performance hit of fine grained redaction from
propagating to non-tenant deployments.

Benchmarking this against master results in the following improvements.
Verbose redaction is enabled in the test via SET tracing = on.

* verbose-redaction-always.txt refers to master @ a64af2c
which has redaction turned on always
* verbose-redaction-conditional-off.txt refers to the top of this PR @
51a8c72 which implements conditional redaction and turns it off for the
test

We gain back a significant portion of the performance hit.

```
10:39:06 ❯ benchstat verbose-redaction-always.txt  verbose-redaction-conditional-off.txt
name                                                        old time/op    new time/op    delta
Tracing/1node/scan/trace=100%/redactable=on/verbose=on-8       890µs ± 8%     795µs ±10%  -10.68%  (p=0.000 n=10+10)
Tracing/1node/insert/trace=100%/redactable=on/verbose=on-8    1.05ms ± 4%    0.95ms ± 1%   -9.17%  (p=0.000 n=9+8)
Tracing/3node/scan/trace=100%/redactable=on/verbose=on-8       921µs ± 4%     875µs ± 9%   -5.09%  (p=0.006 n=9+9)
Tracing/3node/insert/trace=100%/redactable=on/verbose=on-8    1.12ms ±21%    1.02ms ± 5%   -9.35%  (p=0.010 n=10+9)

name                                                        old alloc/op   new alloc/op   delta
Tracing/1node/scan/trace=100%/redactable=on/verbose=on-8       133kB ± 0%     135kB ± 0%   +1.76%  (p=0.000 n=9+9)
Tracing/1node/insert/trace=100%/redactable=on/verbose=on-8     165kB ± 0%     164kB ± 0%   -0.47%  (p=0.000 n=10+9)
Tracing/3node/scan/trace=100%/redactable=on/verbose=on-8       170kB ± 0%     170kB ± 1%     ~     (p=0.796 n=10+10)
Tracing/3node/insert/trace=100%/redactable=on/verbose=on-8     154kB ± 2%     155kB ± 1%     ~     (p=0.796 n=10+10)

name                                                        old allocs/op  new allocs/op  delta
Tracing/1node/scan/trace=100%/redactable=on/verbose=on-8       2.00k ± 0%     1.76k ± 0%  -12.02%  (p=0.000 n=9+8)
Tracing/1node/insert/trace=100%/redactable=on/verbose=on-8     2.36k ± 0%     2.01k ± 0%  -14.64%  (p=0.000 n=10+10)
Tracing/3node/scan/trace=100%/redactable=on/verbose=on-8       1.92k ± 0%     1.81k ± 1%   -5.69%  (p=0.000 n=10+10)
Tracing/3node/insert/trace=100%/redactable=on/verbose=on-8     1.68k ± 1%     1.56k ± 1%   -7.45%  (p=0.000 n=10+10)
```

Resolves #71694

Release note: None

pkg/ccl/kvccl/kvtenantccl/tenant_trace_test.go

@@ -19,25 +19,18 @@ import (
  "github.com/cockroachdb/cockroach/pkg/kv/kvserver/kvserverbase"
  "github.com/cockroachdb/cockroach/pkg/roachpb"
  "github.com/cockroachdb/cockroach/pkg/security"
- "github.com/cockroachdb/cockroach/pkg/testutils"
+ "github.com/cockroachdb/cockroach/pkg/server"
  "github.com/cockroachdb/cockroach/pkg/testutils/serverutils"
  "github.com/cockroachdb/cockroach/pkg/testutils/sqlutils"
  "github.com/cockroachdb/cockroach/pkg/util/leaktest"
  "github.com/cockroachdb/cockroach/pkg/util/log"
- "github.com/cockroachdb/cockroach/pkg/util/tracing"
  "github.com/stretchr/testify/require"
 )
 
 // TestTenantTracesAreRedacted is an end-to-end version of
 // `kvserver.TestMaybeRedactRecording`.
 func TestTenantTracesAreRedacted(t *testing.T) {
  defer leaktest.AfterTest(t)()
- testutils.RunTrueAndFalse(t, "redactable", func(t *testing.T, redactable bool) {
- testTenantTracesAreRedactedImpl(t, redactable)
- })
-}
-
-func testTenantTracesAreRedactedImpl(t *testing.T, redactable bool) {
  defer log.Scope(t).Close(t)
  ctx := context.Background()
 
@@ -69,9 +62,10 @@ SET tracing = off;
  var args base.TestClusterArgs
  args.ServerArgs.Knobs.Store = knobs
  tc := serverutils.StartNewTestCluster(t, 1, args)
- tc.Server(0).Tracer().(*tracing.Tracer).SetRedactable(redactable)
  defer tc.Stopper().Stop(ctx)
 
+ // Queries from the system tenant will receive unredacted traces
+ // since the tracer will not have the redactable flag set.
  t.Run("system-tenant", func(t *testing.T) {
  db := tc.ServerConn(0)
  defer db.Close()
@@ -97,7 +91,6 @@ SET tracing = off;
  defer tenDB.Close()
  results := getTrace(t, tenDB)
 
- const redactedMarkerString = "verbose trace message redacted"
  var found bool
  var foundRedactedMarker bool
  for _, sl := range results {
@@ -111,26 +104,16 @@ SET tracing = off;
  if strings.Contains(s, visibleString) {
  found = true
  }
- if strings.Contains(s, redactedMarkerString) {
+ if strings.Contains(s, string(server.TraceRedactedMarker)) {
  foundRedactedMarker = true
  }
  }
  }
 
- if redactable {
- // If redaction was on, we expect the tenant to see safe information in its
- // trace.
- require.True(t, found, "did not see expected trace message '%q':\n%s",
- visibleString, sqlutils.MatrixToStr(results))
- require.False(t, foundRedactedMarker, "unexpectedly found '%q':\n%s",
- redactedMarkerString, sqlutils.MatrixToStr(results))
- } else {
- // Otherwise, expect the opposite: not even safe information makes it through,
- // because it gets replaced with foundRedactedMarker.
- require.False(t, found, "unexpectedly saw message '%q':\n%s",
- visibleString, sqlutils.MatrixToStr(results))
- require.True(t, foundRedactedMarker, "not not find expected message '%q':\n%s",
- redactedMarkerString, sqlutils.MatrixToStr(results))
- }
+ // Redactability is always enabled for tenants
+ require.True(t, found, "did not see expected trace message '%q':\n%s",
+ visibleString, sqlutils.MatrixToStr(results))
+ require.False(t, foundRedactedMarker, "unexpectedly found '%q':\n%s",
+ string(server.TraceRedactedMarker), sqlutils.MatrixToStr(results))
  })
 }

pkg/kv/txn.go

@@ -965,7 +965,7 @@ func (txn *Txn) exec(ctx context.Context, fn func(context.Context, *Txn) error)
  if err == nil {
  if !txn.IsCommitted() {
  err = txn.Commit(ctx)
- log.Eventf(ctx, "client.Txn did AutoCommit. err: %v\n", err)
+ log.Eventf(ctx, "client.Txn did AutoCommit. err: %v", err)
  if err != nil {
  if !errors.HasType(err, (*roachpb.TransactionRetryWithProtoRefreshError)(nil)) {
  // We can't retry, so let the caller know we tried to

pkg/kv/txn_test.go

@@ -68,7 +68,6 @@ func TestTxnVerboseTrace(t *testing.T) {
  `(?s)`+
  `.*event:[^:]*:\d+ inside txn\n`+
  `.*event:[^:]*:\d+ client\.Txn did AutoCommit\. err: <nil>\n`+
- `.*\n`+
  `.*event:[^:]*:\d+ txn complete.*`,
  dump)
  if err != nil {

pkg/server/node.go

@@ -1050,6 +1050,15 @@ func (n *Node) setupSpanForIncomingRPC(
  // remoteTrace case below.
  const opName = "/cockroach.roachpb.Internal/Batch"
  tr := n.storeCfg.AmbientCtx.Tracer
+
+ // We require redactability enabled on tenant requests.
+ // TODO(davidh): Once performance issues around redaction are
+ // resolved via #58610, this code can be removed so that all traces
+ // have redactability enabled.
+ if !tr.Redactable() && tenID != roachpb.SystemTenantID {
+ tr.SetRedactable(true)
+ }
+
  // newSpan is set if we end up creating a new span.
  var newSpan *tracing.Span
  parentSpan := tracing.SpanFromContext(ctx)

pkg/server/node_tenant.go

@@ -18,7 +18,7 @@ import (
  "github.com/cockroachdb/redact"
 )
 
-const sRedactedMarker = redact.RedactableString("verbose trace message redacted")
+const TraceRedactedMarker = redact.RedactableString("verbose trace message redacted")
 
 // redactRecordingForTenant redacts the sensitive parts of log messages in the
 // recording if the tenant to which this recording is intended is not the system
@@ -49,7 +49,7 @@ func redactRecordingForTenant(tenID roachpb.TenantID, rec tracing.Recording) err
  if field.Key != tracingpb.LogMessageField {
  // We don't have any of these fields, but let's not take any
  // chances (our dependencies might slip them in).
- field.Value = sRedactedMarker
+ field.Value = TraceRedactedMarker
  continue
  }
  if !sp.RedactableLogs {
@@ -58,7 +58,7 @@ func redactRecordingForTenant(tenID roachpb.TenantID, rec tracing.Recording) err
  // stripped. Note that this is not the common path here, as most
  // information in the trace will be from the local node, which
  // always creates redactable logs.
- field.Value = sRedactedMarker
+ field.Value = TraceRedactedMarker
  continue
  }
  field.Value = field.Value.Redact()

pkg/server/node_tenant_test.go

@@ -45,7 +45,10 @@ func TestRedactRecordingForTenant(t *testing.T) {
  Add("tag_sensitive", tagSensitive).
  Add("tag_not_sensitive", log.Safe(tagNotSensitive))
  ctx := logtags.WithTags(context.Background(), tags)
- ctx, sp := tracing.NewTracer().StartSpanCtx(ctx, "foo", tracing.WithRecording(tracing.RecordingVerbose))
+ tracer := tracing.NewTracer()
+ tracer.SetRedactable(true)
+ ctx, sp := tracer.StartSpanCtx(ctx, "foo", tracing.WithRecording(tracing.RecordingVerbose))
+ sp.SetVerbose(true)
 
  log.Eventf(ctx, "%s %s", msgSensitive, log.Safe(msgNotSensitive))
  sp.SetTag("all_span_tags_are_stripped", attribute.StringValue("because_no_redactability"))