Merge pull request #108 from opentracing/bhs/spanlog

Introduce key-value Span logging as an RFC

Author: bensigelman

README.md

@@ -50,7 +50,10 @@ happily rely on it for `Span` propagation. To start a new (blocking child)
         ...
         span, ctx := opentracing.StartSpanFromContext(ctx, "operation_name")
         defer span.Finish()
-        span.LogEvent("xyz_called")
+        span.LogFields(
+            log.String("event", "soft error"),
+            log.String("type", "cache timeout"),
+            log.Int("waited.millis", 1500))
         ...
     }
 ```
@@ -65,7 +68,6 @@ reference.
         ...
         sp := opentracing.StartSpan("operation_name")
         defer sp.Finish()
-        sp.LogEvent("xyz_called")
         ...
     }
 ```
@@ -79,7 +81,6 @@ reference.
             "operation_name",
             opentracing.ChildOf(parentSpan.Context()))
         defer sp.Finish()
-        sp.LogEvent("xyz_called")
         ...
     }
 ```

log/field.go

@@ -0,0 +1,200 @@
+package log
+
+import "math"
+
+type fieldType int
+
+const (
+	stringType fieldType = iota
+	boolType
+	intType
+	int32Type
+	uint32Type
+	int64Type
+	uint64Type
+	float32Type
+	float64Type
+	errorType
+	objectType
+	lazyLoggerType
+)
+
+// Field instances are constructed via LogBool, LogString, and so on.
+// Tracing implementations may then handle them via the Field.Process
+// method.
+//
+// "heavily influenced by" (i.e., partially stolen from)
+// https://github.com/uber-go/zap
+type Field struct {
+	key          string
+	fieldType    fieldType
+	numericVal   int64
+	stringVal    string
+	interfaceVal interface{}
+}
+
+// String adds a string-valued key:value pair to a Span.LogFields() record
+func String(key, val string) Field {
+	return Field{
+		key:       key,
+		fieldType: stringType,
+		stringVal: val,
+	}
+}
+
+// Bool adds a bool-valued key:value pair to a Span.LogFields() record
+func Bool(key string, val bool) Field {
+	var numericVal int64
+	if val {
+		numericVal = 1
+	}
+	return Field{
+		key:        key,
+		fieldType:  boolType,
+		numericVal: numericVal,
+	}
+}
+
+// Int adds an int-valued key:value pair to a Span.LogFields() record
+func Int(key string, val int) Field {
+	return Field{
+		key:        key,
+		fieldType:  intType,
+		numericVal: int64(val),
+	}
+}
+
+// Int32 adds an int32-valued key:value pair to a Span.LogFields() record
+func Int32(key string, val int32) Field {
+	return Field{
+		key:        key,
+		fieldType:  int32Type,
+		numericVal: int64(val),
+	}
+}
+
+// Int64 adds an int64-valued key:value pair to a Span.LogFields() record
+func Int64(key string, val int64) Field {
+	return Field{
+		key:        key,
+		fieldType:  int64Type,
+		numericVal: val,
+	}
+}
+
+// Uint32 adds a uint32-valued key:value pair to a Span.LogFields() record
+func Uint32(key string, val uint32) Field {
+	return Field{
+		key:        key,
+		fieldType:  uint32Type,
+		numericVal: int64(val),
+	}
+}
+
+// Uint64 adds a uint64-valued key:value pair to a Span.LogFields() record
+func Uint64(key string, val uint64) Field {
+	return Field{
+		key:        key,
+		fieldType:  uint64Type,
+		numericVal: int64(val),
+	}
+}
+
+// Float32 adds a float32-valued key:value pair to a Span.LogFields() record
+func Float32(key string, val float32) Field {
+	return Field{
+		key:        key,
+		fieldType:  float32Type,
+		numericVal: int64(math.Float32bits(val)),
+	}
+}
+
+// Float64 adds a float64-valued key:value pair to a Span.LogFields() record
+func Float64(key string, val float64) Field {
+	return Field{
+		key:        key,
+		fieldType:  float64Type,
+		numericVal: int64(math.Float64bits(val)),
+	}
+}
+
+// Error adds an error with the key "error" to a Span.LogFields() record
+func Error(err error) Field {
+	return Field{
+		key:          "error",
+		fieldType:    errorType,
+		interfaceVal: err,
+	}
+}
+
+// Object adds an object-valued key:value pair to a Span.LogFields() record
+func Object(key string, obj interface{}) Field {
+	return Field{
+		key:          key,
+		fieldType:    objectType,
+		interfaceVal: obj,
+	}
+}
+
+// LazyLogger allows for user-defined, late-bound logging of arbitrary data
+type LazyLogger func(fv Encoder)
+
+// Lazy adds a LazyLogger to a Span.LogFields() record; the tracing
+// implementation will call the LazyLogger function at an indefinite time in
+// the future (after Lazy() returns).
+func Lazy(ll LazyLogger) Field {
+	return Field{
+		fieldType:    lazyLoggerType,
+		interfaceVal: ll,
+	}
+}
+
+// Encoder allows access to the contents of a Field (via a call to
+// Field.Marshal).
+//
+// Tracer implementations typically provide an implementation of Encoder;
+// OpenTracing callers typically do not need to concern themselves with it.
+type Encoder interface {
+	EmitString(key, value string)
+	EmitBool(key string, value bool)
+	EmitInt(key string, value int)
+	EmitInt32(key string, value int32)
+	EmitInt64(key string, value int64)
+	EmitUint32(key string, value uint32)
+	EmitUint64(key string, value uint64)
+	EmitFloat32(key string, value float32)
+	EmitFloat64(key string, value float64)
+	EmitObject(key string, value interface{})
+	EmitLazyLogger(value LazyLogger)
+}
+
+// Marshal passes a Field instance through to the appropriate
+// field-type-specific method of an Encoder.
+func (lf Field) Marshal(visitor Encoder) {
+	switch lf.fieldType {
+	case stringType:
+		visitor.EmitString(lf.key, lf.stringVal)
+	case boolType:
+		visitor.EmitBool(lf.key, lf.numericVal != 0)
+	case intType:
+		visitor.EmitInt(lf.key, int(lf.numericVal))
+	case int32Type:
+		visitor.EmitInt32(lf.key, int32(lf.numericVal))
+	case int64Type:
+		visitor.EmitInt64(lf.key, int64(lf.numericVal))
+	case uint32Type:
+		visitor.EmitUint32(lf.key, uint32(lf.numericVal))
+	case uint64Type:
+		visitor.EmitUint64(lf.key, uint64(lf.numericVal))
+	case float32Type:
+		visitor.EmitFloat32(lf.key, math.Float32frombits(uint32(lf.numericVal)))
+	case float64Type:
+		visitor.EmitFloat64(lf.key, math.Float64frombits(uint64(lf.numericVal)))
+	case errorType:
+		visitor.EmitString(lf.key, lf.interfaceVal.(error).Error())
+	case objectType:
+		visitor.EmitObject(lf.key, lf.interfaceVal)
+	case lazyLoggerType:
+		visitor.EmitLazyLogger(lf.interfaceVal.(LazyLogger))
+	}
+}

log/util.go

@@ -0,0 +1,54 @@
+package log
+
+import "fmt"
+
+// InterleavedKVToFields converts keyValues a la Span.LogKV() to a Field slice
+// a la Span.LogFields().
+func InterleavedKVToFields(keyValues ...interface{}) ([]Field, error) {
+	if len(keyValues)%2 != 0 {
+		return nil, fmt.Errorf("non-even keyValues len: %d", len(keyValues))
+	}
+	fields := make([]Field, len(keyValues)/2)
+	for i := 0; i*2 < len(keyValues); i++ {
+		key, ok := keyValues[i*2].(string)
+		if !ok {
+			return nil, fmt.Errorf(
+				"non-string key (pair #%d): %T",
+				i, keyValues[i*2])
+		}
+		switch typedVal := keyValues[i*2+1].(type) {
+		case bool:
+			fields[i] = Bool(key, typedVal)
+		case string:
+			fields[i] = String(key, typedVal)
+		case int:
+			fields[i] = Int(key, typedVal)
+		case int8:
+			fields[i] = Int32(key, int32(typedVal))
+		case int16:
+			fields[i] = Int32(key, int32(typedVal))
+		case int32:
+			fields[i] = Int32(key, typedVal)
+		case int64:
+			fields[i] = Int64(key, typedVal)
+		case uint:
+			fields[i] = Uint64(key, uint64(typedVal))
+		case uint64:
+			fields[i] = Uint64(key, typedVal)
+		case uint8:
+			fields[i] = Uint32(key, uint32(typedVal))
+		case uint16:
+			fields[i] = Uint32(key, uint32(typedVal))
+		case uint32:
+			fields[i] = Uint32(key, typedVal)
+		case float32:
+			fields[i] = Float32(key, typedVal)
+		case float64:
+			fields[i] = Float64(key, typedVal)
+		default:
+			// When in doubt, coerce to a string
+			fields[i] = String(key, fmt.Sprint(typedVal))
+		}
+	}
+	return fields, nil
+}

mocktracer/mocklogrecord.go

@@ -0,0 +1,105 @@
+package mocktracer
+
+import (
+	"fmt"
+	"reflect"
+	"time"
+
+	"github.com/opentracing/opentracing-go/log"
+)
+
+// MockLogRecord represents data logged to a Span via Span.LogFields or
+// Span.LogKV.
+type MockLogRecord struct {
+	Timestamp time.Time
+	Fields    []MockKeyValue
+}
+
+// MockKeyValue represents a single key:value pair.
+type MockKeyValue struct {
+	Key string
+
+	// All MockLogRecord values are coerced to strings via fmt.Sprint(), though
+	// we retain their type separately.
+	ValueKind   reflect.Kind
+	ValueString string
+}
+
+// EmitString belongs to the log.Encoder interface
+func (m *MockKeyValue) EmitString(key, value string) {
+	m.Key = key
+	m.ValueKind = reflect.TypeOf(value).Kind()
+	m.ValueString = fmt.Sprint(value)
+}
+
+// EmitBool belongs to the log.Encoder interface
+func (m *MockKeyValue) EmitBool(key string, value bool) {
+	m.Key = key
+	m.ValueKind = reflect.TypeOf(value).Kind()
+	m.ValueString = fmt.Sprint(value)
+}
+
+// EmitInt belongs to the log.Encoder interface
+func (m *MockKeyValue) EmitInt(key string, value int) {
+	m.Key = key
+	m.ValueKind = reflect.TypeOf(value).Kind()
+	m.ValueString = fmt.Sprint(value)
+}
+
+// EmitInt32 belongs to the log.Encoder interface
+func (m *MockKeyValue) EmitInt32(key string, value int32) {
+	m.Key = key
+	m.ValueKind = reflect.TypeOf(value).Kind()
+	m.ValueString = fmt.Sprint(value)
+}
+
+// EmitInt64 belongs to the log.Encoder interface
+func (m *MockKeyValue) EmitInt64(key string, value int64) {
+	m.Key = key
+	m.ValueKind = reflect.TypeOf(value).Kind()
+	m.ValueString = fmt.Sprint(value)
+}
+
+// EmitUint32 belongs to the log.Encoder interface
+func (m *MockKeyValue) EmitUint32(key string, value uint32) {
+	m.Key = key
+	m.ValueKind = reflect.TypeOf(value).Kind()
+	m.ValueString = fmt.Sprint(value)
+}
+
+// EmitUint64 belongs to the log.Encoder interface
+func (m *MockKeyValue) EmitUint64(key string, value uint64) {
+	m.Key = key
+	m.ValueKind = reflect.TypeOf(value).Kind()
+	m.ValueString = fmt.Sprint(value)
+}
+
+// EmitFloat32 belongs to the log.Encoder interface
+func (m *MockKeyValue) EmitFloat32(key string, value float32) {
+	m.Key = key
+	m.ValueKind = reflect.TypeOf(value).Kind()
+	m.ValueString = fmt.Sprint(value)
+}
+
+// EmitFloat64 belongs to the log.Encoder interface
+func (m *MockKeyValue) EmitFloat64(key string, value float64) {
+	m.Key = key
+	m.ValueKind = reflect.TypeOf(value).Kind()
+	m.ValueString = fmt.Sprint(value)
+}
+
+// EmitObject belongs to the log.Encoder interface
+func (m *MockKeyValue) EmitObject(key string, value interface{}) {
+	m.Key = key
+	m.ValueKind = reflect.TypeOf(value).Kind()
+	m.ValueString = fmt.Sprint(value)
+}
+
+// EmitLazyLogger belongs to the log.Encoder interface
+func (m *MockKeyValue) EmitLazyLogger(value log.LazyLogger) {
+	var meta MockKeyValue
+	value(&meta)
+	m.Key = meta.Key
+	m.ValueKind = meta.ValueKind
+	m.ValueString = meta.ValueString
+}