// FinishWithOptions belongs to the Span interface
func (s *MockSpan) FinishWithOptions(opts opentracing.FinishOptions) {
s.Lock()
s.FinishTime = opts.FinishTime
s.Unlock()
// Handle any late-bound LogRecords.
for _, lr := range opts.LogRecords {
s.logFieldsWithTimestamp(lr.Timestamp, lr.Fields...)
}
// Handle (deprecated) BulkLogData.
for _, ld := range opts.BulkLogData {
if ld.Payload != nil {
s.logFieldsWithTimestamp(
ld.Timestamp,
log.String("event", ld.Event),
log.Object("payload", ld.Payload))
} else {
s.logFieldsWithTimestamp(
ld.Timestamp,
log.String("event", ld.Event))
}
}
s.tracer.recordSpan(s)
}
func TestMockSpan_LogFields(t *testing.T) {
tracer := New()
span := tracer.StartSpan("s")
span.LogFields(log.String("key0", "string0"))
span.LogFields(log.String("key1", "string1"), log.Uint32("key2", uint32(42)))
span.LogFields(log.Lazy(func(fv log.Encoder) {
fv.EmitInt("key_lazy", 12)
}))
span.FinishWithOptions(opentracing.FinishOptions{
LogRecords: []opentracing.LogRecord{
{Timestamp: time.Now(), Fields: []log.Field{log.String("key9", "finish")}},
}})
spans := tracer.FinishedSpans()
assert.Equal(t, 1, len(spans))
actual := spans[0].Logs()
zeroOutTimestamps(actual)
assert.Equal(t, []MockLogRecord{
MockLogRecord{
Fields: []MockKeyValue{
MockKeyValue{Key: "key0", ValueKind: reflect.String, ValueString: "string0"},
},
},
MockLogRecord{
Fields: []MockKeyValue{
MockKeyValue{Key: "key1", ValueKind: reflect.String, ValueString: "string1"},
MockKeyValue{Key: "key2", ValueKind: reflect.Uint32, ValueString: "42"},
},
},
MockLogRecord{
Fields: []MockKeyValue{
// Note that the LazyLogger gets to control the key as well as the value.
MockKeyValue{Key: "key_lazy", ValueKind: reflect.Int, ValueString: "12"},
},
},
MockLogRecord{
Fields: []MockKeyValue{
MockKeyValue{Key: "key9", ValueKind: reflect.String, ValueString: "finish"},
},
},
}, actual)
}
// LogKV belongs to the Span interface.
//
// This implementations coerces all "values" to strings, though that is not
// something all implementations need to do. Indeed, a motivated person can and
// probably should have this do a typed switch on the values.
func (s *MockSpan) LogKV(keyValues ...interface{}) {
if len(keyValues)%2 != 0 {
s.LogFields(log.Error(fmt.Errorf("Non-even keyValues len: %v", len(keyValues))))
return
}
fields, err := log.InterleavedKVToFields(keyValues...)
if err != nil {
s.LogFields(log.Error(err), log.String("function", "LogKV"))
return
}
s.LogFields(fields...)
}
// ToLogRecord converts a deprecated LogData to a non-deprecated LogRecord
func (ld *LogData) ToLogRecord() LogRecord {
var literalTimestamp time.Time
if ld.Timestamp.IsZero() {
literalTimestamp = time.Now()
} else {
literalTimestamp = ld.Timestamp
}
rval := LogRecord{
Timestamp: literalTimestamp,
}
if ld.Payload == nil {
rval.Fields = []log.Field{
log.String("event", ld.Event),
}
} else {
rval.Fields = []log.Field{
log.String("event", ld.Event),
log.Object("payload", ld.Payload),
}
}
return rval
}
func TestEncodeDecodeRawSpan(t *testing.T) {
s := basictracer.RawSpan{
Context: basictracer.SpanContext{
TraceID: 1,
SpanID: 2,
Sampled: true,
Baggage: make(map[string]string),
},
ParentSpanID: 13,
Operation: "testop",
Start: timeutil.Now(),
Duration: 15 * time.Millisecond,
Tags: make(map[string]interface{}),
Logs: []opentracing.LogRecord{
{
Timestamp: timeutil.Now().Add(2 * time.Millisecond),
},
{
Timestamp: timeutil.Now().Add(5 * time.Millisecond),
Fields: []otlog.Field{
otlog.Int("f1", 3),
otlog.String("f2", "f2Val"),
},
},
},
}
s.Context.Baggage["bag"] = "bagVal"
s.Tags["tag"] = 5
enc, err := EncodeRawSpan(&s, nil)
if err != nil {
t.Fatal(err)
}
var d basictracer.RawSpan
if err = DecodeRawSpan(enc, &d); err != nil {
t.Fatal(err)
}
// We cannot use DeepEqual because we encode all log fields as strings. So
// e.g. the "f1" field above is now a string, not an int. The string
// representations must match though.
sStr := fmt.Sprint(s)
dStr := fmt.Sprint(d)
if sStr != dStr {
t.Errorf("initial span: '%s', after encode/decode: '%s'", sStr, dStr)
}
}
// eventInternal is the common code for logging an event. If no args are given,
// the format is treated as a pre-formatted string.
func eventInternal(ctx context.Context, isErr, withTags bool, format string, args ...interface{}) {
if sp, el, ok := getSpanOrEventLog(ctx); ok {
var buf msgBuf
if withTags {
withTags = formatTags(ctx, &buf)
}
var msg string
if !withTags && len(args) == 0 {
// Fast path for pre-formatted messages.
msg = format
} else {
if len(args) == 0 {
buf.WriteString(format)
} else {
fmt.Fprintf(&buf, format, args...)
}
msg = buf.String()
}
if sp != nil {
// TODO(radu): pass tags directly to sp.LogKV when LightStep supports
// that.
sp.LogFields(otlog.String("event", 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)
}
}
el.Unlock()
}
}
}
// JoinOrNew creates a new Span joined to the provided DelegatingCarrier or
// creates Span from the given tracer.
func JoinOrNew(
tr opentracing.Tracer, carrier *SpanContextCarrier, opName string,
) (opentracing.Span, error) {
if carrier != nil {
wireContext, err := tr.Extract(basictracer.Delegator, carrier)
switch err {
case nil:
sp := tr.StartSpan(opName, opentracing.FollowsFrom(wireContext))
// Copy baggage items to tags so they show up in the Lightstep UI.
sp.Context().ForeachBaggageItem(func(k, v string) bool { sp.SetTag(k, v); return true })
sp.LogFields(otlog.String("event", opName))
return sp, nil
case opentracing.ErrSpanContextNotFound:
default:
return nil, err
}
}
return tr.StartSpan(opName), nil
}
// DecodeRawSpan unmarshals into the given RawSpan.
func DecodeRawSpan(enc []byte, dest *basictracer.RawSpan) error {
d := gob.NewDecoder(bytes.NewBuffer(enc))
var err error
decode := func(arg interface{}) {
if err == nil {
err = d.Decode(arg)
}
}
decode(&dest.Context)
decode(&dest.ParentSpanID)
decode(&dest.Operation)
decode(&dest.Start)
decode(&dest.Duration)
decode(&dest.Tags)
var numLogs int32
decode(&numLogs)
dest.Logs = make([]opentracing.LogRecord, numLogs)
for i := range dest.Logs {
lr := &dest.Logs[i]
decode(&lr.Timestamp)
var numFields int32
decode(&numFields)
lr.Fields = make([]otlog.Field, numFields)
for j := range lr.Fields {
var key, val string
decode(&key)
decode(&val)
lr.Fields[j] = otlog.String(key, val)
}
}
return err
}
func (n *Node) batchInternal(
ctx context.Context, args *roachpb.BatchRequest,
) (*roachpb.BatchResponse, error) {
// TODO(marc): grpc's authentication model (which gives credential access in
// the request handler) doesn't really fit with the current design of the
// security package (which assumes that TLS state is only given at connection
// time) - that should be fixed.
if peer, ok := peer.FromContext(ctx); ok {
if tlsInfo, ok := peer.AuthInfo.(credentials.TLSInfo); ok {
certUser, err := security.GetCertificateUser(&tlsInfo.State)
if err != nil {
return nil, err
}
if certUser != security.NodeUser {
return nil, errors.Errorf("user %s is not allowed", certUser)
}
}
}
var br *roachpb.BatchResponse
type snowballInfo struct {
syncutil.Mutex
collectedSpans [][]byte
done bool
}
var snowball *snowballInfo
if err := n.stopper.RunTaskWithErr(func() error {
const opName = "node.Batch"
sp, err := tracing.JoinOrNew(n.storeCfg.AmbientCtx.Tracer, args.TraceContext, opName)
if err != nil {
return err
}
// If this is a snowball span, it gets special treatment: It skips the
// regular tracing machinery, and we instead send the collected spans
// back with the response. This is more expensive, but then again,
// those are individual requests traced by users, so they can be.
if sp.BaggageItem(tracing.Snowball) != "" {
sp.LogFields(otlog.String("event", "delegating to snowball tracing"))
sp.Finish()
snowball = new(snowballInfo)
recorder := func(rawSpan basictracer.RawSpan) {
snowball.Lock()
defer snowball.Unlock()
if snowball.done {
// This is a late span that we must discard because the request was
// already completed.
return
}
encSp, err := tracing.EncodeRawSpan(&rawSpan, nil)
if err != nil {
log.Warning(ctx, err)
}
snowball.collectedSpans = append(snowball.collectedSpans, encSp)
}
if sp, err = tracing.JoinOrNewSnowball(opName, args.TraceContext, recorder); err != nil {
return err
}
}
defer sp.Finish()
traceCtx := opentracing.ContextWithSpan(ctx, sp)
log.Event(traceCtx, args.Summary())
tStart := timeutil.Now()
var pErr *roachpb.Error
br, pErr = n.stores.Send(traceCtx, *args)
if pErr != nil {
br = &roachpb.BatchResponse{}
log.ErrEventf(traceCtx, "%T", pErr.GetDetail())
}
if br.Error != nil {
panic(roachpb.ErrorUnexpectedlySet(n.stores, br))
}
n.metrics.callComplete(timeutil.Since(tStart), pErr)
br.Error = pErr
return nil
}); err != nil {
return nil, err
}
if snowball != nil {
snowball.Lock()
br.CollectedSpans = snowball.collectedSpans
snowball.done = true
snowball.Unlock()
}
return br, nil
}
// AddLogTagStr adds a string tag; see WithLogTagStr.
func (ac *AmbientContext) AddLogTagStr(name string, value string) {
ac.addTag(otlog.String(name, value))
}
// LogEventWithPayload belongs to the Span interface
func (s *MockSpan) LogEventWithPayload(event string, payload interface{}) {
s.LogFields(log.String("event", event), log.Object("payload", payload))
}
// LogEvent belongs to the Span interface
func (s *MockSpan) LogEvent(event string) {
s.LogFields(log.String("event", event))
}
// WithLogTagStr is a variant of WithLogTag that avoids the allocation
// associated with boxing the value in an interface{}.
func WithLogTagStr(ctx context.Context, name string, value string) context.Context {
return addLogTagChain(ctx, &logTag{Field: otlog.String(name, value)})
}
