log,tracing: make traces redactable

This commit makes traces redactable, meaning that redaction markers are
included in their verbose messages. The traces are not redacted
anywhere, so the only change is the inclusion of redaction markers in
the output.

Release note: None

pkg/kv/bulk/sst_batcher_test.go

@@ -227,7 +227,7 @@ func runTestImport(t *testing.T, batchSizeValue int64) {
  for _, rec := range getRec() {
  for _, l := range rec.Logs {
  for _, line := range l.Fields {
- if strings.Contains(line.Value, "SSTable cannot be added spanning range bounds") {
+ if strings.Contains(line.Value.StripMarkers(), "SSTable cannot be added spanning range bounds") {
  splitRetries++
  }
  }

pkg/kv/kvserver/concurrency/concurrency_manager_test.go

@@ -1024,7 +1024,7 @@ func (m *monitor) collectRecordings() string {
  continue
  }
  logs = append(logs, logRecord{
- g: g, value: field.Value,
+ g: g, value: field.Value.StripMarkers(),
  })
  g.prevEvents++
  }

pkg/server/status.go

@@ -666,7 +666,7 @@ func recordedSpansToTraceEvents(spans []tracingpb.RecordedSpan) []*serverpb.Trac
  Time: entry.Time,
  }
  if len(entry.Fields) == 1 {
- event.Message = entry.Fields[0].Value
+ event.Message = entry.Fields[0].Value.StripMarkers()
  } else {
  buf.Reset()
  for i, f := range entry.Fields {

pkg/sql/rowexec/tablereader_test.go

@@ -454,7 +454,7 @@ func TestLimitScans(t *testing.T) {
  }
  for _, l := range span.Logs {
  for _, f := range l.Fields {
- match := re.FindStringSubmatch(f.Value)
+ match := re.FindStringSubmatch(f.Value.StripMarkers())
  if match == nil {
  continue
  }

pkg/util/log/BUILD.bazel

@@ -70,6 +70,7 @@ go_library(
  "@com_github_cockroachdb_errors//oserror",
  "@com_github_cockroachdb_logtags//:logtags",
  "@com_github_cockroachdb_redact//:redact",
+ "@com_github_cockroachdb_redact//interfaces",
  "@com_github_cockroachdb_ttycolor//:ttycolor",
  "@com_github_petermattis_goid//:goid",
  "@org_golang_x_net//trace",

pkg/util/log/channels.go

@@ -53,7 +53,9 @@ func logfDepth(
  ctx, sev, ch,
  depth+1, true /* redactable */, format, args...)
  if sp, el, ok := getSpanOrEventLog(ctx); ok {
- eventInternal(sp, el, (sev >= severity.ERROR), entry.convertToLegacy())
+ // Prevent `entry` from moving to the heap if this branch isn't taken.
+ heapEntry := entry
+ eventInternal(sp, el, sev >= severity.ERROR, &heapEntry)
  }
  logger.outputLogEntry(entry)
 }

pkg/util/log/event_log.go

@@ -39,7 +39,9 @@ func StructuredEvent(ctx context.Context, event eventpb.EventPayload) {
  event)
 
  if sp, el, ok := getSpanOrEventLog(ctx); ok {
- eventInternal(sp, el, (entry.sev >= severity.ERROR), entry.convertToLegacy())
+ // Prevent `entry` from moving to the heap when this branch is not taken.
+ heapEntry := entry
+ eventInternal(sp, el, entry.sev >= severity.ERROR, &heapEntry)
  }
 
  logger := logging.getLogger(entry.ch)

pkg/util/log/log_entry.go

@@ -12,6 +12,7 @@ package log
 
 import (
  "context"
+ "fmt"
  "os"
  "strings"
  "time"
@@ -24,6 +25,7 @@ import (
  "github.com/cockroachdb/cockroach/pkg/util/timeutil"
  "github.com/cockroachdb/logtags"
  "github.com/cockroachdb/redact"
+ "github.com/cockroachdb/redact/interfaces"
  "github.com/petermattis/goid"
 )
 
@@ -83,6 +85,49 @@ type logEntry struct {
  payload entryPayload
 }
 
+var _ redact.SafeFormatter = (*logEntry)(nil)
+var _ fmt.Stringer = (*logEntry)(nil)
+
+func (e *logEntry) SafeFormat(w interfaces.SafePrinter, _ rune) {
+ if len(e.file) != 0 {
+ // TODO(knz): The "canonical" way to represent a file/line prefix
+ // is: <file>:<line>: msg
+ // with a colon between the line number and the message.
+ // However, some location filter deep inside SQL doesn't
+ // understand a colon after the line number.
+ w.Printf("%s:%d ", redact.Safe(e.file), redact.Safe(e.line))
+ }
+ if e.tags != nil {
+ w.SafeString("[")
+ for i, tag := range e.tags.Get() {
+ if i > 0 {
+ w.SafeString(",")
+ }
+ // TODO(obs-inf/server): this assumes that log tag keys are safe, but this
+ // is not enforced. We could lint that it is true similar to how we lint
+ // that the format strings for `log.Infof` etc are const strings.
+ k := redact.SafeString(tag.Key())
+ v := tag.Value()
+ if v != nil {
+ w.Printf("%s=%v", k, tag.Value())
+ } else {
+ w.Printf("%s", k)
+ }
+ }
+ w.SafeString("] ")
+ }
+
+ if !e.payload.redactable {
+ w.Print(e.payload.message)
+ } else {
+ w.Print(redact.RedactableString(e.payload.message))
+ }
+}
+
+func (e *logEntry) String() string {
+ return redact.StringWithoutMarkers(e)
+}
+
 type entryPayload struct {
  // Whether the payload is redactable or not.
  redactable bool

pkg/util/log/trace.go

@@ -12,16 +12,13 @@ package log
 
 import (
  "context"
- "strconv"
  "strings"
 
  "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/syncutil"
  "github.com/cockroachdb/cockroach/pkg/util/tracing"
  "github.com/cockroachdb/logtags"
- "github.com/cockroachdb/redact"
  "golang.org/x/net/trace"
 )
 
@@ -103,66 +100,33 @@ func getSpanOrEventLog(ctx context.Context) (*tracing.Span, *ctxEventLog, bool)
  return nil, nil, false
 }
 
-// eventInternal is the common code for logging an event. If no args are given,
-// the format is treated as a pre-formatted string.
-//
-// Note that when called from a logging function, this is taking the log
-// message as input after introduction of redaction markers. This
-// means the message may or may not contain markers already depending
-// of the configuration of --redactable-logs.
-func eventInternal(sp *tracing.Span, el *ctxEventLog, isErr bool, entry logpb.Entry) {
- var msg string
- if len(entry.Tags) == 0 && len(entry.File) == 0 && !entry.Redactable {
- // Shortcut.
- msg = entry.Message
- } else {
- var buf strings.Builder
- if len(entry.File) != 0 {
- buf.WriteString(entry.File)
- buf.WriteByte(':')
- // TODO(knz): The "canonical" way to represent a file/line prefix
- // is: <file>:<line>: msg
- // with a colon between the line number and the message.
- // However, some location filter deep inside SQL doesn't
- // understand a colon after the line number.
- buf.WriteString(strconv.FormatInt(entry.Line, 10))
- buf.WriteByte(' ')
- }
- if len(entry.Tags) > 0 {
- buf.WriteByte('[')
- buf.WriteString(entry.Tags)
- buf.WriteString("] ")
- }
- buf.WriteString(entry.Message)
- msg = buf.String()
-
- if entry.Redactable {
- // This is true when eventInternal is called from logfDepth(),
- // ie. a regular log call. In this case, the tags and message may contain
- // redaction markers. We remove them here.
- msg = redact.RedactableString(msg).StripMarkers()
- }
+// eventInternal is the common code for logging an event to trace and/or event
+// logs. All entries passed to this method should be redactable.
+func eventInternal(sp *tracing.Span, el *ctxEventLog, isErr bool, entry *logEntry) {
+ if sp != nil {
+ sp.Recordf("%s", entry)
+ // TODO(obs-inf): figure out a way to signal that this is an error. We could
+ // use a different "error" key (provided it shows up in LightStep). Things
+ // like NetTraceIntegrator would need to be modified to understand the
+ // difference. We could also set a special Tag or Baggage on the span. See
+ // #8827 for more discussion.
+ _ = isErr
+ return
  }
 
- if sp != nil {
- sp.Record(msg)
- // if isErr {
- // // TODO(radu): figure out a way to signal that this is an error. We
- // // could use a different "error" key (provided it shows up in
- // // LightStep). Things like NetTraceIntegrator would need to be modified
- // // to understand the difference. We could also set a special Tag or
- // // Baggage on the span. See #8827 for more discussion.
- // }
- } else {
- el.Lock()
- if el.eventLog != nil {
- if isErr {
- el.eventLog.Errorf("%s", msg)
- } else {
- el.eventLog.Printf("%s", msg)
- }
+ // No span, record to event log instead.
+ //
+ // TODO(obs-inf): making this either/or doesn't seem useful, but it
+ // is the status quo, and the callers only pass one of the two even
+ // if they have both.
+ el.Lock()
+ defer el.Unlock()
+ if el.eventLog != nil {
+ if isErr {
+ el.eventLog.Errorf("%s", entry)
+ } else {
+ el.eventLog.Printf("%s", entry)
  }
- el.Unlock()
  }
 }
 
@@ -194,16 +158,13 @@ func Event(ctx context.Context, msg string) {
  }
 
  // Format the tracing event and add it to the trace.
- entry := MakeLegacyEntry(ctx,
+ entry := makeUnstructuredEntry(ctx,
  severity.INFO, /* unused for trace events */
  channel.DEV, /* unused for trace events */
  1, /* depth */
- // redactable is false because we want to flatten the data in traces
- // -- we don't have infrastructure yet for trace redaction.
- false, /* redactable */
- "")
- entry.Message = msg
- eventInternal(sp, el, false /* isErr */, entry)
+ true, /* redactable */
+ msg)
+ eventInternal(sp, el, false /* isErr */, &entry)
 }
 
 // Eventf looks for an opentracing.Trace in the context and formats and logs
@@ -217,15 +178,13 @@ func Eventf(ctx context.Context, format string, args ...interface{}) {
  }
 
  // Format the tracing event and add it to the trace.
- entry := MakeLegacyEntry(ctx,
+ entry := makeUnstructuredEntry(ctx,
  severity.INFO, /* unused for trace events */
  channel.DEV, /* unused for trace events */
  1, /* depth */
- // redactable is false because we want to flatten the data in traces
- // -- we don't have infrastructure yet for trace redaction.
- false, /* redactable */
+ true, /* redactable */
  format, args...)
- eventInternal(sp, el, false /* isErr */, entry)
+ eventInternal(sp, el, false /* isErr */, &entry)
 }
 
 func vEventf(
@@ -244,15 +203,13 @@ func vEventf(
  // Nothing to log. Skip the work.
  return
  }
- entry := MakeLegacyEntry(ctx,
+ entry := makeUnstructuredEntry(ctx,
  severity.INFO, /* unused for trace events */
  channel.DEV, /* unused for trace events */
  depth+1,
- // redactable is false because we want to flatten the data in traces
- // -- we don't have infrastructure yet for trace redaction.
- false, /* redactable */
+ true, /* redactable */
  format, args...)
- eventInternal(sp, el, isErr, entry)
+ eventInternal(sp, el, isErr, &entry)
  }
 }
 

pkg/util/tracing/crdbspan.go

@@ -22,6 +22,7 @@ import (
  "github.com/cockroachdb/cockroach/pkg/util/timeutil"
  "github.com/cockroachdb/cockroach/pkg/util/tracing/tracingpb"
  "github.com/cockroachdb/logtags"
+ "github.com/cockroachdb/redact"
  "github.com/gogo/protobuf/types"
  "github.com/opentracing/opentracing-go"
 )
@@ -290,7 +291,7 @@ func (s *crdbSpan) setTagLocked(key string, value interface{}) {
  s.mu.tags[key] = value
 }
 
-func (s *crdbSpan) record(msg string) {
+func (s *crdbSpan) record(msg redact.RedactableString) {
  if s.recordingType() != RecordingVerbose {
  return
  }
@@ -397,13 +398,14 @@ func (s *crdbSpan) setBaggageItemLocked(restrictedKey, value string) {
 // optimization as stringifying the tag values can be expensive.
 func (s *crdbSpan) getRecordingLocked(wantTags bool) tracingpb.RecordedSpan {
  rs := tracingpb.RecordedSpan{
- TraceID: s.traceID,
- SpanID: s.spanID,
- ParentSpanID: s.parentSpanID,
- GoroutineID: s.goroutineID,
- Operation: s.mu.operation,
- StartTime: s.startTime,
- Duration: s.mu.duration,
+ TraceID: s.traceID,
+ SpanID: s.spanID,
+ ParentSpanID: s.parentSpanID,
+ GoroutineID: s.goroutineID,
+ Operation: s.mu.operation,
+ StartTime: s.startTime,
+ Duration: s.mu.duration,
+ RedactableLogs: true,
  }
 
  if rs.Duration == -1 {

pkg/util/tracing/recording.go

@@ -208,7 +208,10 @@ func (r Recording) visitSpan(sp tracingpb.RecordedSpan, depth int) []traceLogDat
  Fields: make([]otlog.Field, len(l.Fields)),
  }
  for i, f := range l.Fields {
- lr.Fields[i] = otlog.String(f.Key, f.Value)
+ // TODO(obs-inf): the use of opentracing data structures here seems
+ // like detritus and prevents good redactability of the result.
+ // It looks like this is only used for Recording.String() though.
+ lr.Fields[i] = otlog.String(f.Key, f.Value.StripMarkers())
  }
  lastLog := ownLogs[len(ownLogs)-1]
  ownLogs = append(ownLogs, conv(lr, lastLog.Timestamp))
@@ -507,7 +510,7 @@ func TestingCheckRecordedSpans(rec Recording, expected string) error {
  for _, l := range rs.Logs {
  var msg string
  for _, f := range l.Fields {
- msg = msg + fmt.Sprintf(" %s: %v", f.Key, f.Value)
+ msg = msg + fmt.Sprintf(" %s: %v", f.Key, f.Value.StripMarkers())
  }
  row(d, "%s", msg)
  }

pkg/util/tracing/span.go

@@ -160,9 +160,7 @@ func (sp *Span) IsVerbose() bool {
 // Record provides a way to record free-form text into verbose spans. Recordings
 // may be dropped due to sizing constraints.
 //
-// TODO(irfansharif): We don't currently have redactability with trace
-// recordings (both here, and using RecordStructured above). We'll want to do this
-// soon.
+// TODO(tbg): make sure `msg` is lint-forced to be const.
 func (sp *Span) Record(msg string) {
  if sp.done() {
  return