From 7ece034b28fbd73723c257276cbe152fc7ec7eb5 Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Sun, 28 Aug 2016 17:09:47 -0700 Subject: [PATCH 01/19] Introduce key-value Span logging as an RFC --- logfield.go | 136 ++++++++++++++++++++++++++++++++++++++++++++++++++++ span.go | 73 +++++++++++++--------------- 2 files changed, 169 insertions(+), 40 deletions(-) create mode 100644 logfield.go diff --git a/logfield.go b/logfield.go new file mode 100644 index 0000000..9bdde5e --- /dev/null +++ b/logfield.go @@ -0,0 +1,136 @@ +package opentracing + +import "math" + +const ( + stringType fieldType = iota + boolType + intType + int64Type + float64Type + errorType + objectType + deferredObjectType +) + +// LogField instances are constructed via LogBool, LogString, and so on. +// Tracing implementations may then handle them via the LogField.Process +// method. +type LogField struct { + key string + valType valType + numericVal int64 + stringVal string + interfaceVal interface{} +} + +func LogString(key, val string) LogField { + return LogField{ + key: key, + valType: stringType, + stringVal: val, + } +} + +func LogBool(key string, val bool) LogField { + var numericVal int64 + if val { + numericVal = 1 + } + return LogField{ + key: key, + valType: boolType, + numericVal: numericVal, + } +} + +func LogInt(key string, val int) LogField { + var numericVal int64 = int64(val) + return LogField{ + key: key, + valType: intType, + numericVal: numericVal, + } +} + +func LogInt64(key string, val int64) LogField { + return LogField{ + key: key, + valType: int64Type, + numericVal: val, + } +} + +func LogFloat64(key string, val float64) LogField { + return LogField{ + key: key, + valType: float64Type, + numericVal: int64(math.Float64bits(val)), + } +} + +// REVIEWERS: etc etc for other numeric types if we like this direction + +func LogError(err error) LogField { + return LogField{ + key: "error", + valType: errorType, + interfaceVal: err, + } +} + +func LogObject(key string, obj interface{}) LogField { + return LogField{ + key: key, + valType: objectType, + interfaceVal: obj, + } +} + +type DeferredObjectGenerator func() interface{} + +func LogDeferredObject(key string, generator DeferredObjectGenerator) LogField { + return LogField{ + key: key, + valType: deferredObjectType, + interfaceVal: generator, + } +} + +// LogFieldProcessor allows access to the contents of a LogField (via a call to +// LogField.Process). +// +// Tracer implementations typically provide an implementation of +// LogFieldProcessor; OpenTracing callers should not need to concern themselves +// with it. +type LogFieldProcessor interface { + AddString(key, value string) + AddBool(key string, value bool) + AddInt(key string, value int) + AddInt64(key string, value int64) + AddFloat64(key string, value float64) + AddObject(key string, value interface{}) +} + +// Process passes a LogField instance through to the appropriate type-specific +// method of a LogFieldProcessor. +func (lf LogField) Process(processor LogFieldProcessor) { + switch lf.valType { + case stringType: + processor.AddString(lf.key, lf.stringVal) + case boolType: + processor.AddBool(lf.key, lf.numericVal != 0) + case intType: + processor.AddInt(lf.key, int(lf.numericVal)) + case int64Type: + processor.AddInt64(lf.key, lf.numericVal) + case float64Type: + processor.AddFloat64(lf.key, math.Float64frombits(uint64(lf.numericVal))) + case errorType: + processor.AddString(lf.key, lf.obj.(error).Error()) + case objectType: + processor.AddObject(lf.key, lf.interfaceVal) + case deferredObjectType: + processor.AddObject(lf.key, lf.interfaceVal.(DeferredObjectGenerator)()) + } +} diff --git a/span.go b/span.go index cc5579d..a393ca5 100644 --- a/span.go +++ b/span.go @@ -1,6 +1,8 @@ package opentracing -import "time" +import ( + "time" +) // SpanContext represents Span state that must propagate to descendant Spans and across process // boundaries (e.g., a tuple). @@ -49,22 +51,36 @@ type Span interface { // may ignore the tag, but shall not panic. SetTag(key string, value interface{}) Span - // LogEvent() is equivalent to + // LogFields and LogKV are two ways to record logging data about a Span. + // Both allow for timestamped key-value logging of arbitrary data. Neither + // intrinsically supports message formatting; in fact, formatted log + // messages are discouraged (though not disallowed) in OpenTracing. // - // Log(LogData{Event: event}) + // LogFields is designed to be type-checked, efficient, yet a little + // cumbersome from the caller's perspective. // - LogEvent(event string) - - // LogEventWithPayload() is equivalent to + // LogKV is designed to minimize boilerplate and leads to concise, readable + // calling code; unfortunately this also makes it less efficient and less + // type-safe. // - // Log(LogData{Event: event, Payload: payload0}) + // For example, the following are equivalent: // - LogEventWithPayload(event string, payload interface{}) - - // Log() records `data` to this Span. + // span.LogFields( + // opentracing.LogString("request_path", request.Path()), + // opentracing.LogInt("request_size", request.Size())) // - // See LogData for semantic details. - Log(data LogData) + // span.LogKV( + // "request_path", request.Path(), + // "request_size", request.Size()) + // + // Also see Span.FinishWithOptions() and FinishOptions.BulkLogData. + LogFields(fields ...LogField) + // For LogKV (as opposed to LogFields()), every even parameter must be a + // string. Odd parameters may be strings, numeric types, bools, Go error + // instances, or arbitrary structs. If an odd parameter is a + // DeferredObjectGenerator, the the generator will be invoked lazily (in + // the future) and its return value substituted for itself. + LogKV(alternatingKeyValues ...interface{}) // SetBaggageItem sets a key:value pair on this Span and its SpanContext // that also propagates to descendants of this Span. @@ -92,37 +108,14 @@ type Span interface { Tracer() Tracer } -// LogData is data associated with a Span. Every LogData instance should -// specify at least one of Event and/or Payload. +// LogData is data associated with a single Span log. Every LogData instance +// must specify at least one LogField. type LogData struct { - // The timestamp of the log record; if set to the default value (the unix - // epoch), implementations should use time.Now() implicitly. + // The timestamp of the LogField(s) Timestamp time.Time - // Event (if non-empty) should be the stable name of some notable moment in - // the lifetime of a Span. For instance, a Span representing a browser page - // load might add an Event for each of the Performance.timing moments - // here: https://developer.mozilla.org/en-US/docs/Web/API/PerformanceTiming - // - // While it is not a formal requirement, Event strings will be most useful - // if they are *not* unique; rather, tracing systems should be able to use - // them to understand how two similar Spans relate from an internal timing - // perspective. - Event string - - // Payload is a free-form potentially structured object which Tracer - // implementations may retain and record all, none, or part of. - // - // If included, `Payload` should be restricted to data derived from the - // instrumented application; in particular, it should not be used to pass - // semantic flags to a Log() implementation. - // - // For example, an RPC system could log the wire contents in both - // directions, or a SQL library could log the query (with or without - // parameter bindings); tracing implementations may truncate or otherwise - // record only a snippet of these payloads (or may strip out PII, etc, - // etc). - Payload interface{} + // One or more LogField instances that describe this LogData + Fields []LogField } // FinishOptions allows Span.FinishWithOptions callers to override the finish From 150080a7b0209d987748416fdabefbab0b08dad9 Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Sun, 28 Aug 2016 21:30:06 -0700 Subject: [PATCH 02/19] Give credit where credit is due --- logfield.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/logfield.go b/logfield.go index 9bdde5e..758f88b 100644 --- a/logfield.go +++ b/logfield.go @@ -16,6 +16,9 @@ const ( // LogField instances are constructed via LogBool, LogString, and so on. // Tracing implementations may then handle them via the LogField.Process // method. +// +// "heavily influenced by" (i.e., partially stolen from) +// https://github.com/uber-go/zap type LogField struct { key string valType valType From 5ffc1aa8681737c027bbf1a4aefb5420f6629341 Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Mon, 29 Aug 2016 21:41:08 -0700 Subject: [PATCH 03/19] Adjust per the review comments --- log/field.go | 185 +++++++++++++++++++++++++++++++++++++++++++++++++++ logfield.go | 139 -------------------------------------- span.go | 60 ++++++++--------- 3 files changed, 212 insertions(+), 172 deletions(-) create mode 100644 log/field.go delete mode 100644 logfield.go diff --git a/log/field.go b/log/field.go new file mode 100644 index 0000000..de0a737 --- /dev/null +++ b/log/field.go @@ -0,0 +1,185 @@ +package opentracing + +import "math" + +const ( + stringType fieldType = iota + boolType + intType + int32Type + uint32Type + int64Type + uint64Type + float324Type + 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 + valType valType + numericVal int64 + stringVal string + interfaceVal interface{} +} + +func String(key, val string) Field { + return Field{ + key: key, + valType: stringType, + stringVal: val, + } +} + +func Bool(key string, val bool) Field { + var numericVal int64 + if val { + numericVal = 1 + } + return Field{ + key: key, + valType: boolType, + numericVal: numericVal, + } +} + +func Int(key string, val int) Field { + return Field{ + key: key, + valType: intType, + numericVal: int64(val), + } +} + +func Int32(key string, val int32) Field { + return Field{ + key: key, + valType: int32Type, + numericVal: int64(val), + } +} + +func Int64(key string, val int64) Field { + return Field{ + key: key, + valType: int64Type, + numericVal: val, + } +} + +func Uint32(key string, val uint32) Field { + return Field{ + key: key, + valType: uint32Type, + numericVal: int64(val), + } +} + +func Uint64(key string, val uint64) Field { + return Field{ + key: key, + valType: int64Type, + numericVal: int64(val), + } +} + +func Float32(key string, val float32) Field { + return Field{ + key: key, + valType: float32Type, + numericVal: int64(math.Float32bits(val)), + } +} + +func Float64(key string, val float64) Field { + return Field{ + key: key, + valType: float64Type, + numericVal: int64(math.Float64bits(val)), + } +} + +func Error(err error) Field { + return Field{ + key: "error", + valType: errorType, + interfaceVal: err, + } +} + +func Object(key string, obj interface{}) Field { + return Field{ + key: key, + valType: objectType, + interfaceVal: obj, + } +} + +type LazyLogger func(fv FieldVisitor) + +func Lazy(key string, ll LazyLogger) Field { + return Field{ + key: key, + valType: lazyLoggerType, + interfaceVal: ll, + } +} + +// FieldVisitor allows access to the contents of a Field (via a call to +// Field.Visit). +// +// Tracer implementations typically provide an implementation of +// FieldVisitor; OpenTracing callers should not need to concern themselves +// with it. +type FieldVisitor interface { + AddString(key, value string) + AddBool(key string, value bool) + AddInt(key string, value int) + AddInt32(key string, value int32) + AddInt64(key string, value int64) + AddUint32(key string, value uint32) + AddUint64(key string, value uint64) + AddFloat32(key string, value float32) + AddFloat64(key string, value float64) + AddObject(key string, value interface{}) + AddLazyLogger(key string, value LazyLogger) +} + +// Visit passes a Field instance through to the appropriate field-type-specific +// method of a FieldVisitor. +func (lf Field) Visit(visitor FieldVisitor) { + switch lf.valType { + case stringType: + visitor.AddString(lf.key, lf.stringVal) + case boolType: + visitor.AddBool(lf.key, lf.numericVal != 0) + case intType: + visitor.AddInt(lf.key, int(lf.numericVal)) + case int32Type: + visitor.AddInt32(lf.key, int32(lf.numericVal)) + case int64Type: + visitor.AddInt64(lf.key, int64(lf.numericVal)) + case uint32Type: + visitor.AddUint32(lf.key, uint32(lf.numericVal)) + case uint64Type: + visitor.AddUint64(lf.key, uint64(lf.numericVal)) + case float32Type: + visitor.AddFloat32(lf.key, math.Float32frombits(uint64(lf.numericVal))) + case float64Type: + visitor.AddFloat64(lf.key, math.Float64frombits(uint64(lf.numericVal))) + case errorType: + visitor.AddString(lf.key, lf.obj.(error).Error()) + case objectType: + visitor.AddObject(lf.key, lf.interfaceVal) + case lazyLoggerType: + visitor.AddLazyLogger(lf.key, lf.interfaceVal.(LazyLogger)) + } +} diff --git a/logfield.go b/logfield.go deleted file mode 100644 index 758f88b..0000000 --- a/logfield.go +++ /dev/null @@ -1,139 +0,0 @@ -package opentracing - -import "math" - -const ( - stringType fieldType = iota - boolType - intType - int64Type - float64Type - errorType - objectType - deferredObjectType -) - -// LogField instances are constructed via LogBool, LogString, and so on. -// Tracing implementations may then handle them via the LogField.Process -// method. -// -// "heavily influenced by" (i.e., partially stolen from) -// https://github.com/uber-go/zap -type LogField struct { - key string - valType valType - numericVal int64 - stringVal string - interfaceVal interface{} -} - -func LogString(key, val string) LogField { - return LogField{ - key: key, - valType: stringType, - stringVal: val, - } -} - -func LogBool(key string, val bool) LogField { - var numericVal int64 - if val { - numericVal = 1 - } - return LogField{ - key: key, - valType: boolType, - numericVal: numericVal, - } -} - -func LogInt(key string, val int) LogField { - var numericVal int64 = int64(val) - return LogField{ - key: key, - valType: intType, - numericVal: numericVal, - } -} - -func LogInt64(key string, val int64) LogField { - return LogField{ - key: key, - valType: int64Type, - numericVal: val, - } -} - -func LogFloat64(key string, val float64) LogField { - return LogField{ - key: key, - valType: float64Type, - numericVal: int64(math.Float64bits(val)), - } -} - -// REVIEWERS: etc etc for other numeric types if we like this direction - -func LogError(err error) LogField { - return LogField{ - key: "error", - valType: errorType, - interfaceVal: err, - } -} - -func LogObject(key string, obj interface{}) LogField { - return LogField{ - key: key, - valType: objectType, - interfaceVal: obj, - } -} - -type DeferredObjectGenerator func() interface{} - -func LogDeferredObject(key string, generator DeferredObjectGenerator) LogField { - return LogField{ - key: key, - valType: deferredObjectType, - interfaceVal: generator, - } -} - -// LogFieldProcessor allows access to the contents of a LogField (via a call to -// LogField.Process). -// -// Tracer implementations typically provide an implementation of -// LogFieldProcessor; OpenTracing callers should not need to concern themselves -// with it. -type LogFieldProcessor interface { - AddString(key, value string) - AddBool(key string, value bool) - AddInt(key string, value int) - AddInt64(key string, value int64) - AddFloat64(key string, value float64) - AddObject(key string, value interface{}) -} - -// Process passes a LogField instance through to the appropriate type-specific -// method of a LogFieldProcessor. -func (lf LogField) Process(processor LogFieldProcessor) { - switch lf.valType { - case stringType: - processor.AddString(lf.key, lf.stringVal) - case boolType: - processor.AddBool(lf.key, lf.numericVal != 0) - case intType: - processor.AddInt(lf.key, int(lf.numericVal)) - case int64Type: - processor.AddInt64(lf.key, lf.numericVal) - case float64Type: - processor.AddFloat64(lf.key, math.Float64frombits(uint64(lf.numericVal))) - case errorType: - processor.AddString(lf.key, lf.obj.(error).Error()) - case objectType: - processor.AddObject(lf.key, lf.interfaceVal) - case deferredObjectType: - processor.AddObject(lf.key, lf.interfaceVal.(DeferredObjectGenerator)()) - } -} diff --git a/span.go b/span.go index a393ca5..454d5fd 100644 --- a/span.go +++ b/span.go @@ -51,35 +51,32 @@ type Span interface { // may ignore the tag, but shall not panic. SetTag(key string, value interface{}) Span - // LogFields and LogKV are two ways to record logging data about a Span. - // Both allow for timestamped key-value logging of arbitrary data. Neither - // intrinsically supports message formatting; in fact, formatted log - // messages are discouraged (though not disallowed) in OpenTracing. - // - // LogFields is designed to be type-checked, efficient, yet a little - // cumbersome from the caller's perspective. - // - // LogKV is designed to minimize boilerplate and leads to concise, readable - // calling code; unfortunately this also makes it less efficient and less - // type-safe. - // - // For example, the following are equivalent: + // LogFields is an efficient and type-checked way to record key:value + // logging data about a Span, though the programming interface is a little + // more verbose than LogKV(). Here's an example: // // span.LogFields( - // opentracing.LogString("request_path", request.Path()), - // opentracing.LogInt("request_size", request.Size())) + // log.String("request_path", request.Path()), + // log.Uint32("request_size", request.Size())) + // + // Also see Span.FinishWithOptions() and FinishOptions.BulkLogData. + LogFields(fields ...LogField) + + // LogKV is a concise, readable way to record key:value logging data about + // a Span, though unfortunately this also makes it less efficient and less + // type-safe than LogFields(). Here's an example: // // span.LogKV( // "request_path", request.Path(), // "request_size", request.Size()) // - // Also see Span.FinishWithOptions() and FinishOptions.BulkLogData. - LogFields(fields ...LogField) - // For LogKV (as opposed to LogFields()), every even parameter must be a - // string. Odd parameters may be strings, numeric types, bools, Go error - // instances, or arbitrary structs. If an odd parameter is a - // DeferredObjectGenerator, the the generator will be invoked lazily (in - // the future) and its return value substituted for itself. + // For LogKV (as opposed to LogFields()), the parameters must appear as + // key-value pairs, like + // + // span.LogKV(key1, val1, key2, val2, key3, val3, ...) + // + // The keys must all be strings. The values may be strings, numeric types, + // bools, Go error instances, or arbitrary structs. LogKV(alternatingKeyValues ...interface{}) // SetBaggageItem sets a key:value pair on this Span and its SpanContext @@ -108,14 +105,11 @@ type Span interface { Tracer() Tracer } -// LogData is data associated with a single Span log. Every LogData instance -// must specify at least one LogField. -type LogData struct { - // The timestamp of the LogField(s) +// LogRecord is data associated with a single Span log. Every LogRecord +// instance must specify at least one Field. +type LogRecord struct { Timestamp time.Time - - // One or more LogField instances that describe this LogData - Fields []LogField + Fields []log.Field } // FinishOptions allows Span.FinishWithOptions callers to override the finish @@ -128,15 +122,15 @@ type FinishOptions struct { // (per StartSpanOptions). FinishTime time.Time - // BulkLogData allows the caller to specify the contents of many Log() + // LogRecords allows the caller to specify the contents of many Log() // calls with a single slice. May be nil. // - // None of the LogData.Timestamp values may be .IsZero() (i.e., they must + // None of the LogRecord.Timestamp values may be .IsZero() (i.e., they must // be set explicitly). Also, they must be >= the Span's start timestamp and // <= the FinishTime (or time.Now() if FinishTime.IsZero()). Otherwise the // behavior of FinishWithOptions() is undefined. // - // If specified, the caller hands off ownership of BulkLogData at + // If specified, the caller hands off ownership of LogRecords at // FinishWithOptions() invocation time. - BulkLogData []LogData + LogRecords []LogRecord } From 44d840f4fbf65723100efa6fe0fff2e5162101f5 Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Tue, 30 Aug 2016 14:32:51 -0700 Subject: [PATCH 04/19] Flesh out the LogFields and LogKV changes --- log/field.go | 38 ++++++++-------- mocktracer/mocklogrecord.go | 84 ++++++++++++++++++++++++++++++++++ mocktracer/mockspan.go | 68 +++++++++++++++++++++------ mocktracer/mocktracer_test.go | 86 +++++++++++++++++++++++++++++++---- noop.go | 8 +++- span.go | 23 +++++++++- testtracer_test.go | 10 ++-- 7 files changed, 270 insertions(+), 47 deletions(-) create mode 100644 mocktracer/mocklogrecord.go diff --git a/log/field.go b/log/field.go index de0a737..554db3d 100644 --- a/log/field.go +++ b/log/field.go @@ -1,7 +1,9 @@ -package opentracing +package log import "math" +type fieldType int + const ( stringType fieldType = iota boolType @@ -10,7 +12,7 @@ const ( uint32Type int64Type uint64Type - float324Type + float32Type float64Type errorType objectType @@ -25,7 +27,7 @@ const ( // https://github.com/uber-go/zap type Field struct { key string - valType valType + fieldType fieldType numericVal int64 stringVal string interfaceVal interface{} @@ -34,7 +36,7 @@ type Field struct { func String(key, val string) Field { return Field{ key: key, - valType: stringType, + fieldType: stringType, stringVal: val, } } @@ -46,7 +48,7 @@ func Bool(key string, val bool) Field { } return Field{ key: key, - valType: boolType, + fieldType: boolType, numericVal: numericVal, } } @@ -54,7 +56,7 @@ func Bool(key string, val bool) Field { func Int(key string, val int) Field { return Field{ key: key, - valType: intType, + fieldType: intType, numericVal: int64(val), } } @@ -62,7 +64,7 @@ func Int(key string, val int) Field { func Int32(key string, val int32) Field { return Field{ key: key, - valType: int32Type, + fieldType: int32Type, numericVal: int64(val), } } @@ -70,7 +72,7 @@ func Int32(key string, val int32) Field { func Int64(key string, val int64) Field { return Field{ key: key, - valType: int64Type, + fieldType: int64Type, numericVal: val, } } @@ -78,7 +80,7 @@ func Int64(key string, val int64) Field { func Uint32(key string, val uint32) Field { return Field{ key: key, - valType: uint32Type, + fieldType: uint32Type, numericVal: int64(val), } } @@ -86,7 +88,7 @@ func Uint32(key string, val uint32) Field { func Uint64(key string, val uint64) Field { return Field{ key: key, - valType: int64Type, + fieldType: int64Type, numericVal: int64(val), } } @@ -94,7 +96,7 @@ func Uint64(key string, val uint64) Field { func Float32(key string, val float32) Field { return Field{ key: key, - valType: float32Type, + fieldType: float32Type, numericVal: int64(math.Float32bits(val)), } } @@ -102,7 +104,7 @@ func Float32(key string, val float32) Field { func Float64(key string, val float64) Field { return Field{ key: key, - valType: float64Type, + fieldType: float64Type, numericVal: int64(math.Float64bits(val)), } } @@ -110,7 +112,7 @@ func Float64(key string, val float64) Field { func Error(err error) Field { return Field{ key: "error", - valType: errorType, + fieldType: errorType, interfaceVal: err, } } @@ -118,7 +120,7 @@ func Error(err error) Field { func Object(key string, obj interface{}) Field { return Field{ key: key, - valType: objectType, + fieldType: objectType, interfaceVal: obj, } } @@ -128,7 +130,7 @@ type LazyLogger func(fv FieldVisitor) func Lazy(key string, ll LazyLogger) Field { return Field{ key: key, - valType: lazyLoggerType, + fieldType: lazyLoggerType, interfaceVal: ll, } } @@ -156,7 +158,7 @@ type FieldVisitor interface { // Visit passes a Field instance through to the appropriate field-type-specific // method of a FieldVisitor. func (lf Field) Visit(visitor FieldVisitor) { - switch lf.valType { + switch lf.fieldType { case stringType: visitor.AddString(lf.key, lf.stringVal) case boolType: @@ -172,11 +174,11 @@ func (lf Field) Visit(visitor FieldVisitor) { case uint64Type: visitor.AddUint64(lf.key, uint64(lf.numericVal)) case float32Type: - visitor.AddFloat32(lf.key, math.Float32frombits(uint64(lf.numericVal))) + visitor.AddFloat32(lf.key, math.Float32frombits(uint32(lf.numericVal))) case float64Type: visitor.AddFloat64(lf.key, math.Float64frombits(uint64(lf.numericVal))) case errorType: - visitor.AddString(lf.key, lf.obj.(error).Error()) + visitor.AddString(lf.key, lf.interfaceVal.(error).Error()) case objectType: visitor.AddObject(lf.key, lf.interfaceVal) case lazyLoggerType: diff --git a/mocktracer/mocklogrecord.go b/mocktracer/mocklogrecord.go new file mode 100644 index 0000000..9524ee9 --- /dev/null +++ b/mocktracer/mocklogrecord.go @@ -0,0 +1,84 @@ +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 +} + +func (m *MockKeyValue) AddString(key, value string) { + m.Key = key + m.ValueKind = reflect.TypeOf(value).Kind() + m.ValueString = fmt.Sprint(value) +} +func (m *MockKeyValue) AddBool(key string, value bool) { + m.Key = key + m.ValueKind = reflect.TypeOf(value).Kind() + m.ValueString = fmt.Sprint(value) +} +func (m *MockKeyValue) AddInt(key string, value int) { + m.Key = key + m.ValueKind = reflect.TypeOf(value).Kind() + m.ValueString = fmt.Sprint(value) +} +func (m *MockKeyValue) AddInt32(key string, value int32) { + m.Key = key + m.ValueKind = reflect.TypeOf(value).Kind() + m.ValueString = fmt.Sprint(value) +} +func (m *MockKeyValue) AddInt64(key string, value int64) { + m.Key = key + m.ValueKind = reflect.TypeOf(value).Kind() + m.ValueString = fmt.Sprint(value) +} +func (m *MockKeyValue) AddUint32(key string, value uint32) { + m.Key = key + m.ValueKind = reflect.TypeOf(value).Kind() + m.ValueString = fmt.Sprint(value) +} +func (m *MockKeyValue) AddUint64(key string, value uint64) { + m.Key = key + m.ValueKind = reflect.TypeOf(value).Kind() + m.ValueString = fmt.Sprint(value) +} +func (m *MockKeyValue) AddFloat32(key string, value float32) { + m.Key = key + m.ValueKind = reflect.TypeOf(value).Kind() + m.ValueString = fmt.Sprint(value) +} +func (m *MockKeyValue) AddFloat64(key string, value float64) { + m.Key = key + m.ValueKind = reflect.TypeOf(value).Kind() + m.ValueString = fmt.Sprint(value) +} +func (m *MockKeyValue) AddObject(key string, value interface{}) { + m.Key = key + m.ValueKind = reflect.TypeOf(value).Kind() + m.ValueString = fmt.Sprint(value) +} +func (m *MockKeyValue) AddLazyLogger(key string, value log.LazyLogger) { + var meta MockKeyValue + value(&meta) + m.Key = meta.Key + m.ValueKind = meta.ValueKind + m.ValueString = meta.ValueString +} diff --git a/mocktracer/mockspan.go b/mocktracer/mockspan.go index b22dff8..5349f95 100644 --- a/mocktracer/mockspan.go +++ b/mocktracer/mockspan.go @@ -8,6 +8,7 @@ import ( "github.com/opentracing/opentracing-go" "github.com/opentracing/opentracing-go/ext" + "github.com/opentracing/opentracing-go/log" ) // MockSpanContext is an opentracing.SpanContext implementation. @@ -70,7 +71,7 @@ type MockSpan struct { // All of the below are protected by the embedded RWMutex. SpanContext MockSpanContext tags map[string]interface{} - logs []opentracing.LogData + logs []MockLogRecord tracer *MockTracer } @@ -99,7 +100,7 @@ func newMockSpan(t *MockTracer, name string, opts opentracing.StartSpanOptions) OperationName: name, StartTime: startTime, tags: tags, - logs: []opentracing.LogData{}, + logs: []MockLogRecord{}, SpanContext: spanContext, tracer: t, @@ -125,10 +126,10 @@ func (s *MockSpan) Tag(k string) interface{} { } // Logs returns a copy of logs accumulated in the span so far -func (s *MockSpan) Logs() []opentracing.LogData { +func (s *MockSpan) Logs() []MockLogRecord { s.RLock() defer s.RUnlock() - logs := make([]opentracing.LogData, len(s.logs)) + logs := make([]MockLogRecord, len(s.logs)) copy(logs, s.logs) return logs } @@ -183,8 +184,26 @@ func (s *MockSpan) Finish() { func (s *MockSpan) FinishWithOptions(opts opentracing.FinishOptions) { s.Lock() s.FinishTime = opts.FinishTime - s.logs = append(s.logs, opts.BulkLogData...) 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) } @@ -196,26 +215,45 @@ func (s *MockSpan) String() string { s.SpanContext.Sampled, s.OperationName) } +// LogFields belongs to the Span interface +func (s *MockSpan) LogFields(fields ...log.Field) { + s.logFieldsWithTimestamp(time.Now(), fields...) +} + +// The caller MUST NOT hold s.Lock +func (s *MockSpan) logFieldsWithTimestamp(ts time.Time, fields ...log.Field) { + lr := MockLogRecord{ + Timestamp: ts, + Fields: make([]MockKeyValue, len(fields)), + } + for i, f := range fields { + outField := &(lr.Fields[i]) + f.Visit(outField) + } + + s.Lock() + defer s.Unlock() + s.logs = append(s.logs, lr) +} + +// LogKV belongs to the Span interface +func (s *MockSpan) LogKV(keyValues ...interface{}) { + // XXX +} + // LogEvent belongs to the Span interface func (s *MockSpan) LogEvent(event string) { - s.Log(opentracing.LogData{ - Event: event, - }) + s.LogFields(log.String("event", event)) } // LogEventWithPayload belongs to the Span interface func (s *MockSpan) LogEventWithPayload(event string, payload interface{}) { - s.Log(opentracing.LogData{ - Event: event, - Payload: payload, - }) + s.LogFields(log.String("event", event), log.Object("payload", payload)) } // Log belongs to the Span interface func (s *MockSpan) Log(data opentracing.LogData) { - s.Lock() - defer s.Unlock() - s.logs = append(s.logs, data) + panic("MockSpan.Log() no longer supported") } // SetOperationName belongs to the Span interface diff --git a/mocktracer/mocktracer_test.go b/mocktracer/mocktracer_test.go index 90a7439..0ca8fa3 100644 --- a/mocktracer/mocktracer_test.go +++ b/mocktracer/mocktracer_test.go @@ -2,13 +2,16 @@ package mocktracer import ( "net/http" + "reflect" "testing" + "time" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "github.com/opentracing/opentracing-go" "github.com/opentracing/opentracing-go/ext" + "github.com/opentracing/opentracing-go/log" ) func TestMockTracer_StartSpan(t *testing.T) { @@ -89,22 +92,89 @@ func TestMockTracer_FinishedSpans_and_Reset(t *testing.T) { assert.Equal(t, 0, len(spans)) } -func TestMockSpan_Logs(t *testing.T) { +func zeroOutTimestamps(recs []MockLogRecord) { + for i := range recs { + recs[i].Timestamp = time.Time{} + } +} + +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("SHOULD_BE_IGNORED", func(fv log.FieldVisitor) { + fv.AddInt("key_lazy", 12) + })) + span.FinishWithOptions(opentracing.FinishOptions{ + LogRecords: []opentracing.LogRecord{ + {time.Now(), []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) +} + +func TestMockSpan_DeprecatedLogs(t *testing.T) { tracer := New() span := tracer.StartSpan("x") span.LogEvent("x") span.LogEventWithPayload("y", "z") - span.Log(opentracing.LogData{Event: "a"}) + span.LogEvent("a") span.FinishWithOptions(opentracing.FinishOptions{ BulkLogData: []opentracing.LogData{{Event: "f"}}}) spans := tracer.FinishedSpans() assert.Equal(t, 1, len(spans)) - assert.Equal(t, []opentracing.LogData{ - {Event: "x"}, - {Event: "y", Payload: "z"}, - {Event: "a"}, - {Event: "f"}, - }, spans[0].Logs()) + actual := spans[0].Logs() + zeroOutTimestamps(actual) + assert.Equal(t, []MockLogRecord{ + MockLogRecord{ + Fields: []MockKeyValue{ + MockKeyValue{Key: "event", ValueKind: reflect.String, ValueString: "x"}, + }, + }, + MockLogRecord{ + Fields: []MockKeyValue{ + MockKeyValue{Key: "event", ValueKind: reflect.String, ValueString: "y"}, + MockKeyValue{Key: "payload", ValueKind: reflect.String, ValueString: "z"}, + }, + }, + MockLogRecord{ + Fields: []MockKeyValue{ + MockKeyValue{Key: "event", ValueKind: reflect.String, ValueString: "a"}, + }, + }, + MockLogRecord{ + Fields: []MockKeyValue{ + MockKeyValue{Key: "event", ValueKind: reflect.String, ValueString: "f"}, + }, + }, + }, actual) } func TestMockTracer_Propagation(t *testing.T) { diff --git a/noop.go b/noop.go index 270824e..bd559dc 100644 --- a/noop.go +++ b/noop.go @@ -1,5 +1,7 @@ package opentracing +import "github.com/opentracing/opentracing-go/log" + // A NoopTracer is a trivial implementation of Tracer for which all operations // are no-ops. type NoopTracer struct{} @@ -25,13 +27,15 @@ func (n noopSpan) Context() SpanContext { retur func (n noopSpan) SetBaggageItem(key, val string) Span { return defaultNoopSpan } func (n noopSpan) BaggageItem(key string) string { return emptyString } func (n noopSpan) SetTag(key string, value interface{}) Span { return n } +func (n noopSpan) LogFields(fields ...log.Field) {} +func (n noopSpan) LogKV(keyVals ...interface{}) {} func (n noopSpan) Finish() {} func (n noopSpan) FinishWithOptions(opts FinishOptions) {} +func (n noopSpan) SetOperationName(operationName string) Span { return n } +func (n noopSpan) Tracer() Tracer { return defaultNoopTracer } func (n noopSpan) LogEvent(event string) {} func (n noopSpan) LogEventWithPayload(event string, payload interface{}) {} func (n noopSpan) Log(data LogData) {} -func (n noopSpan) SetOperationName(operationName string) Span { return n } -func (n noopSpan) Tracer() Tracer { return defaultNoopTracer } // StartSpan belongs to the Tracer interface. func (n NoopTracer) StartSpan(operationName string, opts ...StartSpanOption) Span { diff --git a/span.go b/span.go index 454d5fd..ef2a378 100644 --- a/span.go +++ b/span.go @@ -2,6 +2,8 @@ package opentracing import ( "time" + + "github.com/opentracing/opentracing-go/log" ) // SpanContext represents Span state that must propagate to descendant Spans and across process @@ -60,7 +62,7 @@ type Span interface { // log.Uint32("request_size", request.Size())) // // Also see Span.FinishWithOptions() and FinishOptions.BulkLogData. - LogFields(fields ...LogField) + LogFields(fields ...log.Field) // LogKV is a concise, readable way to record key:value logging data about // a Span, though unfortunately this also makes it less efficient and less @@ -103,6 +105,13 @@ type Span interface { // Provides access to the Tracer that created this Span. Tracer() Tracer + + // DEPRECATED + LogEvent(event string) + // DEPRECATED + LogEventWithPayload(event string, payload interface{}) + // DEPRECATED + Log(data LogData) } // LogRecord is data associated with a single Span log. Every LogRecord @@ -132,5 +141,17 @@ type FinishOptions struct { // // If specified, the caller hands off ownership of LogRecords at // FinishWithOptions() invocation time. + // + // If specified, the (deprecated) BulkLogData must be nil or empty. LogRecords []LogRecord + + // BulkLogData is DEPRECATED. + BulkLogData []LogData +} + +// LogData is DEPRECATED +type LogData struct { + Timestamp time.Time + Event string + Payload interface{} } diff --git a/testtracer_test.go b/testtracer_test.go index 7d9106e..dd13788 100644 --- a/testtracer_test.go +++ b/testtracer_test.go @@ -4,6 +4,8 @@ import ( "strconv" "strings" "time" + + "github.com/opentracing/opentracing-go/log" ) const testHTTPHeaderPrefix = "testprefix-" @@ -65,13 +67,15 @@ func (n testSpan) Context() SpanContext { retur func (n testSpan) SetTag(key string, value interface{}) Span { return n } func (n testSpan) Finish() {} func (n testSpan) FinishWithOptions(opts FinishOptions) {} -func (n testSpan) LogEvent(event string) {} -func (n testSpan) LogEventWithPayload(event string, payload interface{}) {} -func (n testSpan) Log(data LogData) {} +func (n testSpan) LogFields(fields ...log.Field) {} +func (n testSpan) LogKV(kvs ...interface{}) {} func (n testSpan) SetOperationName(operationName string) Span { return n } func (n testSpan) Tracer() Tracer { return testTracer{} } func (n testSpan) SetBaggageItem(key, val string) Span { return n } func (n testSpan) BaggageItem(key string) string { return "" } +func (n testSpan) LogEvent(event string) {} +func (n testSpan) LogEventWithPayload(event string, payload interface{}) {} +func (n testSpan) Log(data LogData) {} // StartSpan belongs to the Tracer interface. func (n testTracer) StartSpan(operationName string, opts ...StartSpanOption) Span { From 6d1271234a346cecabc22ded6d408f22603f5d66 Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Tue, 30 Aug 2016 14:48:14 -0700 Subject: [PATCH 05/19] Add LogKV --- mocktracer/mockspan.go | 26 ++++++++++++++++++++++++-- mocktracer/mocktracer_test.go | 26 ++++++++++++++++++++++++++ 2 files changed, 50 insertions(+), 2 deletions(-) diff --git a/mocktracer/mockspan.go b/mocktracer/mockspan.go index 5349f95..456123b 100644 --- a/mocktracer/mockspan.go +++ b/mocktracer/mockspan.go @@ -2,6 +2,7 @@ package mocktracer import ( "fmt" + "reflect" "sync" "sync/atomic" "time" @@ -236,9 +237,30 @@ func (s *MockSpan) logFieldsWithTimestamp(ts time.Time, fields ...log.Field) { s.logs = append(s.logs, lr) } -// LogKV belongs to the Span interface +// 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{}) { - // XXX + if len(keyValues)%2 != 0 { + s.LogFields(log.Error(fmt.Errorf("Non-even keyValues len: %v", len(keyValues)))) + return + } + fields := make([]log.Field, len(keyValues)/2) + for i := 0; i*2 < len(keyValues); i++ { + key, ok := keyValues[i*2].(string) + if !ok { + s.LogFields(log.Error( + fmt.Errorf( + "Non-string key (pair=%v): %v", + i, reflect.TypeOf(keyValues[i*2])))) + return + } + valStr := fmt.Sprint(keyValues[i*2+1]) + fields[i] = log.String(key, valStr) + } + s.LogFields(fields...) } // LogEvent belongs to the Span interface diff --git a/mocktracer/mocktracer_test.go b/mocktracer/mocktracer_test.go index 0ca8fa3..427b57b 100644 --- a/mocktracer/mocktracer_test.go +++ b/mocktracer/mocktracer_test.go @@ -98,6 +98,32 @@ func zeroOutTimestamps(recs []MockLogRecord) { } } +func TestMockSpan_LogKV(t *testing.T) { + tracer := New() + span := tracer.StartSpan("s") + span.LogKV("key0", "string0") + span.LogKV("key1", "string1", "key2", uint32(42)) + span.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"}, + // Note that the type is a String, not a Uint32, since we're using LogKV. + MockKeyValue{Key: "key2", ValueKind: reflect.String, ValueString: "42"}, + }, + }, + }, actual) +} + func TestMockSpan_LogFields(t *testing.T) { tracer := New() span := tracer.StartSpan("s") From 802a5497d78056a66699f3315804677e2aa4449a Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Tue, 30 Aug 2016 14:55:34 -0700 Subject: [PATCH 06/19] Delint --- log/field.go | 19 ++++++++++++++++++- mocktracer/mocklogrecord.go | 21 +++++++++++++++++++++ 2 files changed, 39 insertions(+), 1 deletion(-) diff --git a/log/field.go b/log/field.go index 554db3d..bc8b4c7 100644 --- a/log/field.go +++ b/log/field.go @@ -33,6 +33,7 @@ type Field struct { 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, @@ -41,6 +42,7 @@ func String(key, val string) Field { } } +// 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 { @@ -53,6 +55,7 @@ func Bool(key string, val bool) Field { } } +// Int adds an int-valued key:value pair to a Span.LogFields() record func Int(key string, val int) Field { return Field{ key: key, @@ -61,6 +64,7 @@ func Int(key string, val int) Field { } } +// Int32 adds an int32-valued key:value pair to a Span.LogFields() record func Int32(key string, val int32) Field { return Field{ key: key, @@ -69,6 +73,7 @@ func Int32(key string, val int32) Field { } } +// Int64 adds an int64-valued key:value pair to a Span.LogFields() record func Int64(key string, val int64) Field { return Field{ key: key, @@ -77,6 +82,7 @@ func Int64(key string, val int64) Field { } } +// Uint32 adds a uint32-valued key:value pair to a Span.LogFields() record func Uint32(key string, val uint32) Field { return Field{ key: key, @@ -85,6 +91,7 @@ func Uint32(key string, val uint32) Field { } } +// Uint64 adds a uint64-valued key:value pair to a Span.LogFields() record func Uint64(key string, val uint64) Field { return Field{ key: key, @@ -93,6 +100,7 @@ func Uint64(key string, val uint64) Field { } } +// Float32 adds a float32-valued key:value pair to a Span.LogFields() record func Float32(key string, val float32) Field { return Field{ key: key, @@ -101,6 +109,7 @@ func Float32(key string, val float32) Field { } } +// Float64 adds a float64-valued key:value pair to a Span.LogFields() record func Float64(key string, val float64) Field { return Field{ key: key, @@ -109,6 +118,7 @@ func Float64(key string, val float64) Field { } } +// Error adds an error with the key "error" to a Span.LogFields() record func Error(err error) Field { return Field{ key: "error", @@ -117,6 +127,7 @@ func Error(err error) Field { } } +// Object adds an object-valued key:value pair to a Span.LogFields() record func Object(key string, obj interface{}) Field { return Field{ key: key, @@ -125,9 +136,15 @@ func Object(key string, obj interface{}) Field { } } +// LazyLogger allows for user-defined, late-bound logging of arbitrary data type LazyLogger func(fv FieldVisitor) -func Lazy(key string, ll LazyLogger) Field { +// 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). +// +// Note that `ignoredKey` is ignored (as the LazyLogger can control the key). +func Lazy(ignoredKey string, ll LazyLogger) Field { return Field{ key: key, fieldType: lazyLoggerType, diff --git a/mocktracer/mocklogrecord.go b/mocktracer/mocklogrecord.go index 9524ee9..a8ec706 100644 --- a/mocktracer/mocklogrecord.go +++ b/mocktracer/mocklogrecord.go @@ -25,56 +25,77 @@ type MockKeyValue struct { ValueString string } +// AddString belongs to the log.FieldVisitor interface func (m *MockKeyValue) AddString(key, value string) { m.Key = key m.ValueKind = reflect.TypeOf(value).Kind() m.ValueString = fmt.Sprint(value) } + +// AddBool belongs to the log.FieldVisitor interface func (m *MockKeyValue) AddBool(key string, value bool) { m.Key = key m.ValueKind = reflect.TypeOf(value).Kind() m.ValueString = fmt.Sprint(value) } + +// AddInt belongs to the log.FieldVisitor interface func (m *MockKeyValue) AddInt(key string, value int) { m.Key = key m.ValueKind = reflect.TypeOf(value).Kind() m.ValueString = fmt.Sprint(value) } + +// AddInt32 belongs to the log.FieldVisitor interface func (m *MockKeyValue) AddInt32(key string, value int32) { m.Key = key m.ValueKind = reflect.TypeOf(value).Kind() m.ValueString = fmt.Sprint(value) } + +// AddInt64 belongs to the log.FieldVisitor interface func (m *MockKeyValue) AddInt64(key string, value int64) { m.Key = key m.ValueKind = reflect.TypeOf(value).Kind() m.ValueString = fmt.Sprint(value) } + +// AddUint32 belongs to the log.FieldVisitor interface func (m *MockKeyValue) AddUint32(key string, value uint32) { m.Key = key m.ValueKind = reflect.TypeOf(value).Kind() m.ValueString = fmt.Sprint(value) } + +// AddUint64 belongs to the log.FieldVisitor interface func (m *MockKeyValue) AddUint64(key string, value uint64) { m.Key = key m.ValueKind = reflect.TypeOf(value).Kind() m.ValueString = fmt.Sprint(value) } + +// AddFloat32 belongs to the log.FieldVisitor interface func (m *MockKeyValue) AddFloat32(key string, value float32) { m.Key = key m.ValueKind = reflect.TypeOf(value).Kind() m.ValueString = fmt.Sprint(value) } + +// AddFloat64 belongs to the log.FieldVisitor interface func (m *MockKeyValue) AddFloat64(key string, value float64) { m.Key = key m.ValueKind = reflect.TypeOf(value).Kind() m.ValueString = fmt.Sprint(value) } + +// AddObject belongs to the log.FieldVisitor interface func (m *MockKeyValue) AddObject(key string, value interface{}) { m.Key = key m.ValueKind = reflect.TypeOf(value).Kind() m.ValueString = fmt.Sprint(value) } + +// AddLazyLogger belongs to the log.FieldVisitor interface func (m *MockKeyValue) AddLazyLogger(key string, value log.LazyLogger) { var meta MockKeyValue value(&meta) From a92f3514a88102005a0c80bbc2a0304f4000d9e5 Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Tue, 30 Aug 2016 15:25:30 -0700 Subject: [PATCH 07/19] Don't ask for a key we throw out --- log/field.go | 6 ++---- mocktracer/mocktracer_test.go | 2 +- 2 files changed, 3 insertions(+), 5 deletions(-) diff --git a/log/field.go b/log/field.go index bc8b4c7..b8f5a7b 100644 --- a/log/field.go +++ b/log/field.go @@ -142,11 +142,9 @@ type LazyLogger func(fv FieldVisitor) // 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). -// -// Note that `ignoredKey` is ignored (as the LazyLogger can control the key). -func Lazy(ignoredKey string, ll LazyLogger) Field { +func Lazy(ll LazyLogger) Field { return Field{ - key: key, + key: "Lazy", // will be overwritten fieldType: lazyLoggerType, interfaceVal: ll, } diff --git a/mocktracer/mocktracer_test.go b/mocktracer/mocktracer_test.go index 427b57b..c83fae7 100644 --- a/mocktracer/mocktracer_test.go +++ b/mocktracer/mocktracer_test.go @@ -129,7 +129,7 @@ func TestMockSpan_LogFields(t *testing.T) { 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("SHOULD_BE_IGNORED", func(fv log.FieldVisitor) { + span.LogFields(log.Lazy(func(fv log.FieldVisitor) { fv.AddInt("key_lazy", 12) })) span.FinishWithOptions(opentracing.FinishOptions{ From cb1bd725c30791a0d2f9129e975be22b3ea6585b Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Tue, 30 Aug 2016 16:48:06 -0700 Subject: [PATCH 08/19] Adjust naming per @jmacd --- log/field.go | 63 +++++++++++++++++------------------ mocktracer/mocklogrecord.go | 44 ++++++++++++------------ mocktracer/mockspan.go | 2 +- mocktracer/mocktracer_test.go | 4 +-- 4 files changed, 56 insertions(+), 57 deletions(-) diff --git a/log/field.go b/log/field.go index b8f5a7b..c1967de 100644 --- a/log/field.go +++ b/log/field.go @@ -137,7 +137,7 @@ func Object(key string, obj interface{}) Field { } // LazyLogger allows for user-defined, late-bound logging of arbitrary data -type LazyLogger func(fv FieldVisitor) +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 @@ -150,53 +150,52 @@ func Lazy(ll LazyLogger) Field { } } -// FieldVisitor allows access to the contents of a Field (via a call to +// Encoder allows access to the contents of a Field (via a call to // Field.Visit). // -// Tracer implementations typically provide an implementation of -// FieldVisitor; OpenTracing callers should not need to concern themselves -// with it. -type FieldVisitor interface { - AddString(key, value string) - AddBool(key string, value bool) - AddInt(key string, value int) - AddInt32(key string, value int32) - AddInt64(key string, value int64) - AddUint32(key string, value uint32) - AddUint64(key string, value uint64) - AddFloat32(key string, value float32) - AddFloat64(key string, value float64) - AddObject(key string, value interface{}) - AddLazyLogger(key string, value LazyLogger) +// 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(key string, value LazyLogger) } -// Visit passes a Field instance through to the appropriate field-type-specific -// method of a FieldVisitor. -func (lf Field) Visit(visitor FieldVisitor) { +// 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.AddString(lf.key, lf.stringVal) + visitor.EmitString(lf.key, lf.stringVal) case boolType: - visitor.AddBool(lf.key, lf.numericVal != 0) + visitor.EmitBool(lf.key, lf.numericVal != 0) case intType: - visitor.AddInt(lf.key, int(lf.numericVal)) + visitor.EmitInt(lf.key, int(lf.numericVal)) case int32Type: - visitor.AddInt32(lf.key, int32(lf.numericVal)) + visitor.EmitInt32(lf.key, int32(lf.numericVal)) case int64Type: - visitor.AddInt64(lf.key, int64(lf.numericVal)) + visitor.EmitInt64(lf.key, int64(lf.numericVal)) case uint32Type: - visitor.AddUint32(lf.key, uint32(lf.numericVal)) + visitor.EmitUint32(lf.key, uint32(lf.numericVal)) case uint64Type: - visitor.AddUint64(lf.key, uint64(lf.numericVal)) + visitor.EmitUint64(lf.key, uint64(lf.numericVal)) case float32Type: - visitor.AddFloat32(lf.key, math.Float32frombits(uint32(lf.numericVal))) + visitor.EmitFloat32(lf.key, math.Float32frombits(uint32(lf.numericVal))) case float64Type: - visitor.AddFloat64(lf.key, math.Float64frombits(uint64(lf.numericVal))) + visitor.EmitFloat64(lf.key, math.Float64frombits(uint64(lf.numericVal))) case errorType: - visitor.AddString(lf.key, lf.interfaceVal.(error).Error()) + visitor.EmitString(lf.key, lf.interfaceVal.(error).Error()) case objectType: - visitor.AddObject(lf.key, lf.interfaceVal) + visitor.EmitObject(lf.key, lf.interfaceVal) case lazyLoggerType: - visitor.AddLazyLogger(lf.key, lf.interfaceVal.(LazyLogger)) + visitor.EmitLazyLogger(lf.key, lf.interfaceVal.(LazyLogger)) } } diff --git a/mocktracer/mocklogrecord.go b/mocktracer/mocklogrecord.go index a8ec706..4816ab8 100644 --- a/mocktracer/mocklogrecord.go +++ b/mocktracer/mocklogrecord.go @@ -25,78 +25,78 @@ type MockKeyValue struct { ValueString string } -// AddString belongs to the log.FieldVisitor interface -func (m *MockKeyValue) AddString(key, value 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) } -// AddBool belongs to the log.FieldVisitor interface -func (m *MockKeyValue) AddBool(key string, value bool) { +// 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) } -// AddInt belongs to the log.FieldVisitor interface -func (m *MockKeyValue) AddInt(key string, value int) { +// 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) } -// AddInt32 belongs to the log.FieldVisitor interface -func (m *MockKeyValue) AddInt32(key string, value int32) { +// 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) } -// AddInt64 belongs to the log.FieldVisitor interface -func (m *MockKeyValue) AddInt64(key string, value int64) { +// 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) } -// AddUint32 belongs to the log.FieldVisitor interface -func (m *MockKeyValue) AddUint32(key string, value uint32) { +// 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) } -// AddUint64 belongs to the log.FieldVisitor interface -func (m *MockKeyValue) AddUint64(key string, value uint64) { +// 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) } -// AddFloat32 belongs to the log.FieldVisitor interface -func (m *MockKeyValue) AddFloat32(key string, value float32) { +// 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) } -// AddFloat64 belongs to the log.FieldVisitor interface -func (m *MockKeyValue) AddFloat64(key string, value float64) { +// 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) } -// AddObject belongs to the log.FieldVisitor interface -func (m *MockKeyValue) AddObject(key string, value interface{}) { +// 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) } -// AddLazyLogger belongs to the log.FieldVisitor interface -func (m *MockKeyValue) AddLazyLogger(key string, value log.LazyLogger) { +// EmitLazyLogger belongs to the log.Encoder interface +func (m *MockKeyValue) EmitLazyLogger(key string, value log.LazyLogger) { var meta MockKeyValue value(&meta) m.Key = meta.Key diff --git a/mocktracer/mockspan.go b/mocktracer/mockspan.go index 456123b..a9c4fe5 100644 --- a/mocktracer/mockspan.go +++ b/mocktracer/mockspan.go @@ -229,7 +229,7 @@ func (s *MockSpan) logFieldsWithTimestamp(ts time.Time, fields ...log.Field) { } for i, f := range fields { outField := &(lr.Fields[i]) - f.Visit(outField) + f.Marshal(outField) } s.Lock() diff --git a/mocktracer/mocktracer_test.go b/mocktracer/mocktracer_test.go index c83fae7..ed04494 100644 --- a/mocktracer/mocktracer_test.go +++ b/mocktracer/mocktracer_test.go @@ -129,8 +129,8 @@ func TestMockSpan_LogFields(t *testing.T) { 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.FieldVisitor) { - fv.AddInt("key_lazy", 12) + span.LogFields(log.Lazy(func(fv log.Encoder) { + fv.EmitInt("key_lazy", 12) })) span.FinishWithOptions(opentracing.FinishOptions{ LogRecords: []opentracing.LogRecord{ From 6decba5a23ba944750455aead91608ff748cbb20 Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Mon, 12 Sep 2016 17:16:45 -0700 Subject: [PATCH 09/19] Update README and comments --- README.md | 12 +++++++++--- span.go | 2 +- 2 files changed, 10 insertions(+), 4 deletions(-) diff --git a/README.md b/README.md index e262efa..f0a9411 100644 --- a/README.md +++ b/README.md @@ -50,7 +50,9 @@ 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", "xyz called"), + log.Int("request.size", request.Size())) ... } ``` @@ -65,7 +67,9 @@ reference. ... sp := opentracing.StartSpan("operation_name") defer sp.Finish() - sp.LogEvent("xyz_called") + span.LogFields( + log.String("event", "xyz called"), + log.Int("request.size", request.Size())) ... } ``` @@ -79,7 +83,9 @@ reference. "operation_name", opentracing.ChildOf(parentSpan.Context())) defer sp.Finish() - sp.LogEvent("xyz_called") + span.LogFields( + log.String("event", "xyz called"), + log.Int("request.size", request.Size())) ... } ``` diff --git a/span.go b/span.go index ef2a378..4d4de2d 100644 --- a/span.go +++ b/span.go @@ -131,7 +131,7 @@ type FinishOptions struct { // (per StartSpanOptions). FinishTime time.Time - // LogRecords allows the caller to specify the contents of many Log() + // LogRecords allows the caller to specify the contents of many LogFields() // calls with a single slice. May be nil. // // None of the LogRecord.Timestamp values may be .IsZero() (i.e., they must From 0004729124e053de945e2ee8ec0af4c208ce36b6 Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Mon, 12 Sep 2016 22:22:21 -0700 Subject: [PATCH 10/19] Create an InterleavedKVToFields helper It will help anyone trying to implement LogKV(). Use it in MockSpan. --- log/util.go | 57 +++++++++++++++++++++++++++++++++++ mocktracer/mockspan.go | 17 +++-------- mocktracer/mocktracer_test.go | 3 +- 3 files changed, 62 insertions(+), 15 deletions(-) create mode 100644 log/util.go diff --git a/log/util.go b/log/util.go new file mode 100644 index 0000000..2f3c30f --- /dev/null +++ b/log/util.go @@ -0,0 +1,57 @@ +package log + +import ( + "fmt" + "reflect" +) + +// 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: %v", 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=%v): %v", + i, reflect.TypeOf(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 +} diff --git a/mocktracer/mockspan.go b/mocktracer/mockspan.go index a9c4fe5..5ca7114 100644 --- a/mocktracer/mockspan.go +++ b/mocktracer/mockspan.go @@ -2,7 +2,6 @@ package mocktracer import ( "fmt" - "reflect" "sync" "sync/atomic" "time" @@ -247,18 +246,10 @@ func (s *MockSpan) LogKV(keyValues ...interface{}) { s.LogFields(log.Error(fmt.Errorf("Non-even keyValues len: %v", len(keyValues)))) return } - fields := make([]log.Field, len(keyValues)/2) - for i := 0; i*2 < len(keyValues); i++ { - key, ok := keyValues[i*2].(string) - if !ok { - s.LogFields(log.Error( - fmt.Errorf( - "Non-string key (pair=%v): %v", - i, reflect.TypeOf(keyValues[i*2])))) - return - } - valStr := fmt.Sprint(keyValues[i*2+1]) - fields[i] = log.String(key, valStr) + fields, err := log.InterleavedKVToFields(keyValues...) + if err != nil { + s.LogFields(log.Error(err), log.String("function", "LogKV")) + return } s.LogFields(fields...) } diff --git a/mocktracer/mocktracer_test.go b/mocktracer/mocktracer_test.go index ed04494..1754cf5 100644 --- a/mocktracer/mocktracer_test.go +++ b/mocktracer/mocktracer_test.go @@ -117,8 +117,7 @@ func TestMockSpan_LogKV(t *testing.T) { MockLogRecord{ Fields: []MockKeyValue{ MockKeyValue{Key: "key1", ValueKind: reflect.String, ValueString: "string1"}, - // Note that the type is a String, not a Uint32, since we're using LogKV. - MockKeyValue{Key: "key2", ValueKind: reflect.String, ValueString: "42"}, + MockKeyValue{Key: "key2", ValueKind: reflect.Uint32, ValueString: "42"}, }, }, }, actual) From c4d24cd69a4d487907025ae274286ce67b64c0dd Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Mon, 12 Sep 2016 22:37:43 -0700 Subject: [PATCH 11/19] Add a LogData->LogRecord converter --- span.go | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/span.go b/span.go index 4d4de2d..f5b3d8e 100644 --- a/span.go +++ b/span.go @@ -79,6 +79,8 @@ type Span interface { // // The keys must all be strings. The values may be strings, numeric types, // bools, Go error instances, or arbitrary structs. + // + // (Note to implementors: consider the log.InterleavedKVToFields() helper) LogKV(alternatingKeyValues ...interface{}) // SetBaggageItem sets a key:value pair on this Span and its SpanContext @@ -155,3 +157,14 @@ type LogData struct { Event string Payload interface{} } + +// ToLogRecord converts a deprecated LogData to a non-deprecated LogRecord +func (ld *LogData) ToLogRecord() LogRecord { + return LogRecord{ + Timestamp: ld.Timestamp, + Fields: []log.Field{ + log.String("event", ld.Event), + log.Object("payload", ld.Payload), + }, + } +} From 6de9a960249ee9ca1ca09142e3a228ef17e7d777 Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Tue, 13 Sep 2016 11:30:43 -0700 Subject: [PATCH 12/19] Add a LogFieldValidator for tests of OT impls --- log/field.go | 2 +- log/testutil.go | 122 ++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 123 insertions(+), 1 deletion(-) create mode 100644 log/testutil.go diff --git a/log/field.go b/log/field.go index c1967de..dec4b8e 100644 --- a/log/field.go +++ b/log/field.go @@ -151,7 +151,7 @@ func Lazy(ll LazyLogger) Field { } // Encoder allows access to the contents of a Field (via a call to -// Field.Visit). +// Field.Marshal). // // Tracer implementations typically provide an implementation of Encoder; // OpenTracing callers typically do not need to concern themselves with it. diff --git a/log/testutil.go b/log/testutil.go new file mode 100644 index 0000000..f3170d3 --- /dev/null +++ b/log/testutil.go @@ -0,0 +1,122 @@ +package log + +import ( + "fmt" + "reflect" + "testing" +) + +// LogFieldValidator facilitates testing of Span.Log*() implementations. +// +// LogFieldValidator SHOULD ONLY BE USED FOR TESTS. It is not intended for +// production code. +// +// Usage: +// +// lfv := log.NewLogFieldValidator(t, someLogStructure.Fields) +// lfv. +// ExpectNextFieldEquals("key1", reflect.String, "some string value"). +// ExpectNextFieldEquals("key2", reflect.Uint8, "255") +// +// LogFieldValidator satisfies the log.Encoder interface and thus is able to +// marshal log.Field instances (which it takes advantage of internally). +type LogFieldValidator struct { + t *testing.T + fieldIdx int + fields []Field + nextKey string + nextKind reflect.Kind + nextValAsString string +} + +// NewLogFieldValidator returns a new validator that will test the contents of +// `fields`. +func NewLogFieldValidator(t *testing.T, fields []Field) *LogFieldValidator { + return &LogFieldValidator{ + t: t, + fields: fields, + } +} + +// ExpectNextFieldEquals facilitates a fluent way of testing the contents +// []Field slices. +func (lfv *LogFieldValidator) ExpectNextFieldEquals(key string, kind reflect.Kind, valAsString string) *LogFieldValidator { + if len(lfv.fields) < lfv.fieldIdx { + lfv.t.Errorf("Expecting more than the %v Fields we have", len(lfv.fields)) + } + lfv.nextKey = key + lfv.nextKind = kind + lfv.nextValAsString = valAsString + lfv.fields[lfv.fieldIdx].Marshal(lfv) + lfv.fieldIdx++ + return lfv +} + +// EmitString satisfies the Encoder interface +func (lfv *LogFieldValidator) EmitString(key, value string) { + lfv.validateNextField(key, reflect.String, value) +} + +// EmitBool satisfies the Encoder interface +func (lfv *LogFieldValidator) EmitBool(key string, value bool) { + lfv.validateNextField(key, reflect.Bool, value) +} + +// EmitInt satisfies the Encoder interface +func (lfv *LogFieldValidator) EmitInt(key string, value int) { + lfv.validateNextField(key, reflect.Int, value) +} + +// EmitInt32 satisfies the Encoder interface +func (lfv *LogFieldValidator) EmitInt32(key string, value int32) { + lfv.validateNextField(key, reflect.Int32, value) +} + +// EmitInt64 satisfies the Encoder interface +func (lfv *LogFieldValidator) EmitInt64(key string, value int64) { + lfv.validateNextField(key, reflect.Int64, value) +} + +// EmitUint32 satisfies the Encoder interface +func (lfv *LogFieldValidator) EmitUint32(key string, value uint32) { + lfv.validateNextField(key, reflect.Uint32, value) +} + +// EmitUint64 satisfies the Encoder interface +func (lfv *LogFieldValidator) EmitUint64(key string, value uint64) { + lfv.validateNextField(key, reflect.Uint64, value) +} + +// EmitFloat32 satisfies the Encoder interface +func (lfv *LogFieldValidator) EmitFloat32(key string, value float32) { + lfv.validateNextField(key, reflect.Float32, value) +} + +// EmitFloat64 satisfies the Encoder interface +func (lfv *LogFieldValidator) EmitFloat64(key string, value float64) { + lfv.validateNextField(key, reflect.Float64, value) +} + +// EmitObject satisfies the Encoder interface +func (lfv *LogFieldValidator) EmitObject(key string, value interface{}) { + lfv.validateNextField(key, reflect.Interface, value) +} + +// EmitLazyLogger satisfies the Encoder interface +func (lfv *LogFieldValidator) EmitLazyLogger(key string, value LazyLogger) { + lfv.t.Error("Test infrastructure does not support EmitLazyLogger yet") +} + +func (lfv *LogFieldValidator) validateNextField(key string, actualKind reflect.Kind, value interface{}) { + if lfv.nextKey != key { + lfv.t.Errorf("Bad key: expected %q, found %q", lfv.nextKey, key) + } + if lfv.nextKind != actualKind { + lfv.t.Errorf("Bad reflect.Kind: expected %v, found %v", lfv.nextKind, actualKind) + return + } + if lfv.nextValAsString != fmt.Sprint(value) { + lfv.t.Errorf("Bad value: expected %q, found %q", lfv.nextValAsString, fmt.Sprint(value)) + } + // All good. +} From 5c9aebf9adbec5936a5d3bc433648eed55de9be0 Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Tue, 13 Sep 2016 11:47:39 -0700 Subject: [PATCH 13/19] Fix lint stuttering --- log/testutil.go | 96 ++++++++++++++++++++++++------------------------- 1 file changed, 48 insertions(+), 48 deletions(-) diff --git a/log/testutil.go b/log/testutil.go index f3170d3..906a275 100644 --- a/log/testutil.go +++ b/log/testutil.go @@ -6,21 +6,21 @@ import ( "testing" ) -// LogFieldValidator facilitates testing of Span.Log*() implementations. +// FieldValidator facilitates testing of Span.Log*() implementations. // -// LogFieldValidator SHOULD ONLY BE USED FOR TESTS. It is not intended for +// FieldValidator SHOULD ONLY BE USED FOR TESTS. It is not intended for // production code. // // Usage: // -// lfv := log.NewLogFieldValidator(t, someLogStructure.Fields) -// lfv. +// fv := log.NewFieldValidator(t, someLogStructure.Fields) +// fv. // ExpectNextFieldEquals("key1", reflect.String, "some string value"). -// ExpectNextFieldEquals("key2", reflect.Uint8, "255") +// ExpectNextFieldEquals("key2", reflect.Uint32, "4294967295") // -// LogFieldValidator satisfies the log.Encoder interface and thus is able to +// FieldValidator satisfies the log.Encoder interface and thus is able to // marshal log.Field instances (which it takes advantage of internally). -type LogFieldValidator struct { +type FieldValidator struct { t *testing.T fieldIdx int fields []Field @@ -29,10 +29,10 @@ type LogFieldValidator struct { nextValAsString string } -// NewLogFieldValidator returns a new validator that will test the contents of +// NewFieldValidator returns a new validator that will test the contents of // `fields`. -func NewLogFieldValidator(t *testing.T, fields []Field) *LogFieldValidator { - return &LogFieldValidator{ +func NewFieldValidator(t *testing.T, fields []Field) *FieldValidator { + return &FieldValidator{ t: t, fields: fields, } @@ -40,83 +40,83 @@ func NewLogFieldValidator(t *testing.T, fields []Field) *LogFieldValidator { // ExpectNextFieldEquals facilitates a fluent way of testing the contents // []Field slices. -func (lfv *LogFieldValidator) ExpectNextFieldEquals(key string, kind reflect.Kind, valAsString string) *LogFieldValidator { - if len(lfv.fields) < lfv.fieldIdx { - lfv.t.Errorf("Expecting more than the %v Fields we have", len(lfv.fields)) +func (fv *FieldValidator) ExpectNextFieldEquals(key string, kind reflect.Kind, valAsString string) *FieldValidator { + if len(fv.fields) < fv.fieldIdx { + fv.t.Errorf("Expecting more than the %v Fields we have", len(fv.fields)) } - lfv.nextKey = key - lfv.nextKind = kind - lfv.nextValAsString = valAsString - lfv.fields[lfv.fieldIdx].Marshal(lfv) - lfv.fieldIdx++ - return lfv + fv.nextKey = key + fv.nextKind = kind + fv.nextValAsString = valAsString + fv.fields[fv.fieldIdx].Marshal(fv) + fv.fieldIdx++ + return fv } // EmitString satisfies the Encoder interface -func (lfv *LogFieldValidator) EmitString(key, value string) { - lfv.validateNextField(key, reflect.String, value) +func (fv *FieldValidator) EmitString(key, value string) { + fv.validateNextField(key, reflect.String, value) } // EmitBool satisfies the Encoder interface -func (lfv *LogFieldValidator) EmitBool(key string, value bool) { - lfv.validateNextField(key, reflect.Bool, value) +func (fv *FieldValidator) EmitBool(key string, value bool) { + fv.validateNextField(key, reflect.Bool, value) } // EmitInt satisfies the Encoder interface -func (lfv *LogFieldValidator) EmitInt(key string, value int) { - lfv.validateNextField(key, reflect.Int, value) +func (fv *FieldValidator) EmitInt(key string, value int) { + fv.validateNextField(key, reflect.Int, value) } // EmitInt32 satisfies the Encoder interface -func (lfv *LogFieldValidator) EmitInt32(key string, value int32) { - lfv.validateNextField(key, reflect.Int32, value) +func (fv *FieldValidator) EmitInt32(key string, value int32) { + fv.validateNextField(key, reflect.Int32, value) } // EmitInt64 satisfies the Encoder interface -func (lfv *LogFieldValidator) EmitInt64(key string, value int64) { - lfv.validateNextField(key, reflect.Int64, value) +func (fv *FieldValidator) EmitInt64(key string, value int64) { + fv.validateNextField(key, reflect.Int64, value) } // EmitUint32 satisfies the Encoder interface -func (lfv *LogFieldValidator) EmitUint32(key string, value uint32) { - lfv.validateNextField(key, reflect.Uint32, value) +func (fv *FieldValidator) EmitUint32(key string, value uint32) { + fv.validateNextField(key, reflect.Uint32, value) } // EmitUint64 satisfies the Encoder interface -func (lfv *LogFieldValidator) EmitUint64(key string, value uint64) { - lfv.validateNextField(key, reflect.Uint64, value) +func (fv *FieldValidator) EmitUint64(key string, value uint64) { + fv.validateNextField(key, reflect.Uint64, value) } // EmitFloat32 satisfies the Encoder interface -func (lfv *LogFieldValidator) EmitFloat32(key string, value float32) { - lfv.validateNextField(key, reflect.Float32, value) +func (fv *FieldValidator) EmitFloat32(key string, value float32) { + fv.validateNextField(key, reflect.Float32, value) } // EmitFloat64 satisfies the Encoder interface -func (lfv *LogFieldValidator) EmitFloat64(key string, value float64) { - lfv.validateNextField(key, reflect.Float64, value) +func (fv *FieldValidator) EmitFloat64(key string, value float64) { + fv.validateNextField(key, reflect.Float64, value) } // EmitObject satisfies the Encoder interface -func (lfv *LogFieldValidator) EmitObject(key string, value interface{}) { - lfv.validateNextField(key, reflect.Interface, value) +func (fv *FieldValidator) EmitObject(key string, value interface{}) { + fv.validateNextField(key, reflect.Interface, value) } // EmitLazyLogger satisfies the Encoder interface -func (lfv *LogFieldValidator) EmitLazyLogger(key string, value LazyLogger) { - lfv.t.Error("Test infrastructure does not support EmitLazyLogger yet") +func (fv *FieldValidator) EmitLazyLogger(key string, value LazyLogger) { + fv.t.Error("Test infrastructure does not support EmitLazyLogger yet") } -func (lfv *LogFieldValidator) validateNextField(key string, actualKind reflect.Kind, value interface{}) { - if lfv.nextKey != key { - lfv.t.Errorf("Bad key: expected %q, found %q", lfv.nextKey, key) +func (fv *FieldValidator) validateNextField(key string, actualKind reflect.Kind, value interface{}) { + if fv.nextKey != key { + fv.t.Errorf("Bad key: expected %q, found %q", fv.nextKey, key) } - if lfv.nextKind != actualKind { - lfv.t.Errorf("Bad reflect.Kind: expected %v, found %v", lfv.nextKind, actualKind) + if fv.nextKind != actualKind { + fv.t.Errorf("Bad reflect.Kind: expected %v, found %v", fv.nextKind, actualKind) return } - if lfv.nextValAsString != fmt.Sprint(value) { - lfv.t.Errorf("Bad value: expected %q, found %q", lfv.nextValAsString, fmt.Sprint(value)) + if fv.nextValAsString != fmt.Sprint(value) { + fv.t.Errorf("Bad value: expected %q, found %q", fv.nextValAsString, fmt.Sprint(value)) } // All good. } From e4a87f008480ad02516d2e87ab67531350907d18 Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Tue, 13 Sep 2016 17:03:09 -0700 Subject: [PATCH 14/19] Respond to review comments --- log/field.go | 5 +- log/testutil.go | 122 ------------------------------------ mocktracer/mocklogrecord.go | 2 +- 3 files changed, 3 insertions(+), 126 deletions(-) delete mode 100644 log/testutil.go diff --git a/log/field.go b/log/field.go index dec4b8e..03e3325 100644 --- a/log/field.go +++ b/log/field.go @@ -144,7 +144,6 @@ type LazyLogger func(fv Encoder) // the future (after Lazy() returns). func Lazy(ll LazyLogger) Field { return Field{ - key: "Lazy", // will be overwritten fieldType: lazyLoggerType, interfaceVal: ll, } @@ -166,7 +165,7 @@ type Encoder interface { EmitFloat32(key string, value float32) EmitFloat64(key string, value float64) EmitObject(key string, value interface{}) - EmitLazyLogger(key string, value LazyLogger) + EmitLazyLogger(value LazyLogger) } // Marshal passes a Field instance through to the appropriate @@ -196,6 +195,6 @@ func (lf Field) Marshal(visitor Encoder) { case objectType: visitor.EmitObject(lf.key, lf.interfaceVal) case lazyLoggerType: - visitor.EmitLazyLogger(lf.key, lf.interfaceVal.(LazyLogger)) + visitor.EmitLazyLogger(lf.interfaceVal.(LazyLogger)) } } diff --git a/log/testutil.go b/log/testutil.go deleted file mode 100644 index 906a275..0000000 --- a/log/testutil.go +++ /dev/null @@ -1,122 +0,0 @@ -package log - -import ( - "fmt" - "reflect" - "testing" -) - -// FieldValidator facilitates testing of Span.Log*() implementations. -// -// FieldValidator SHOULD ONLY BE USED FOR TESTS. It is not intended for -// production code. -// -// Usage: -// -// fv := log.NewFieldValidator(t, someLogStructure.Fields) -// fv. -// ExpectNextFieldEquals("key1", reflect.String, "some string value"). -// ExpectNextFieldEquals("key2", reflect.Uint32, "4294967295") -// -// FieldValidator satisfies the log.Encoder interface and thus is able to -// marshal log.Field instances (which it takes advantage of internally). -type FieldValidator struct { - t *testing.T - fieldIdx int - fields []Field - nextKey string - nextKind reflect.Kind - nextValAsString string -} - -// NewFieldValidator returns a new validator that will test the contents of -// `fields`. -func NewFieldValidator(t *testing.T, fields []Field) *FieldValidator { - return &FieldValidator{ - t: t, - fields: fields, - } -} - -// ExpectNextFieldEquals facilitates a fluent way of testing the contents -// []Field slices. -func (fv *FieldValidator) ExpectNextFieldEquals(key string, kind reflect.Kind, valAsString string) *FieldValidator { - if len(fv.fields) < fv.fieldIdx { - fv.t.Errorf("Expecting more than the %v Fields we have", len(fv.fields)) - } - fv.nextKey = key - fv.nextKind = kind - fv.nextValAsString = valAsString - fv.fields[fv.fieldIdx].Marshal(fv) - fv.fieldIdx++ - return fv -} - -// EmitString satisfies the Encoder interface -func (fv *FieldValidator) EmitString(key, value string) { - fv.validateNextField(key, reflect.String, value) -} - -// EmitBool satisfies the Encoder interface -func (fv *FieldValidator) EmitBool(key string, value bool) { - fv.validateNextField(key, reflect.Bool, value) -} - -// EmitInt satisfies the Encoder interface -func (fv *FieldValidator) EmitInt(key string, value int) { - fv.validateNextField(key, reflect.Int, value) -} - -// EmitInt32 satisfies the Encoder interface -func (fv *FieldValidator) EmitInt32(key string, value int32) { - fv.validateNextField(key, reflect.Int32, value) -} - -// EmitInt64 satisfies the Encoder interface -func (fv *FieldValidator) EmitInt64(key string, value int64) { - fv.validateNextField(key, reflect.Int64, value) -} - -// EmitUint32 satisfies the Encoder interface -func (fv *FieldValidator) EmitUint32(key string, value uint32) { - fv.validateNextField(key, reflect.Uint32, value) -} - -// EmitUint64 satisfies the Encoder interface -func (fv *FieldValidator) EmitUint64(key string, value uint64) { - fv.validateNextField(key, reflect.Uint64, value) -} - -// EmitFloat32 satisfies the Encoder interface -func (fv *FieldValidator) EmitFloat32(key string, value float32) { - fv.validateNextField(key, reflect.Float32, value) -} - -// EmitFloat64 satisfies the Encoder interface -func (fv *FieldValidator) EmitFloat64(key string, value float64) { - fv.validateNextField(key, reflect.Float64, value) -} - -// EmitObject satisfies the Encoder interface -func (fv *FieldValidator) EmitObject(key string, value interface{}) { - fv.validateNextField(key, reflect.Interface, value) -} - -// EmitLazyLogger satisfies the Encoder interface -func (fv *FieldValidator) EmitLazyLogger(key string, value LazyLogger) { - fv.t.Error("Test infrastructure does not support EmitLazyLogger yet") -} - -func (fv *FieldValidator) validateNextField(key string, actualKind reflect.Kind, value interface{}) { - if fv.nextKey != key { - fv.t.Errorf("Bad key: expected %q, found %q", fv.nextKey, key) - } - if fv.nextKind != actualKind { - fv.t.Errorf("Bad reflect.Kind: expected %v, found %v", fv.nextKind, actualKind) - return - } - if fv.nextValAsString != fmt.Sprint(value) { - fv.t.Errorf("Bad value: expected %q, found %q", fv.nextValAsString, fmt.Sprint(value)) - } - // All good. -} diff --git a/mocktracer/mocklogrecord.go b/mocktracer/mocklogrecord.go index 4816ab8..2ce96d9 100644 --- a/mocktracer/mocklogrecord.go +++ b/mocktracer/mocklogrecord.go @@ -96,7 +96,7 @@ func (m *MockKeyValue) EmitObject(key string, value interface{}) { } // EmitLazyLogger belongs to the log.Encoder interface -func (m *MockKeyValue) EmitLazyLogger(key string, value log.LazyLogger) { +func (m *MockKeyValue) EmitLazyLogger(value log.LazyLogger) { var meta MockKeyValue value(&meta) m.Key = meta.Key From fefab0430b34f0af784190e047eae4b4b40bcff4 Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Fri, 16 Sep 2016 15:42:57 -0700 Subject: [PATCH 15/19] Adjust deprecation path logic --- span.go | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/span.go b/span.go index f5b3d8e..2ded84d 100644 --- a/span.go +++ b/span.go @@ -160,11 +160,18 @@ type LogData struct { // ToLogRecord converts a deprecated LogData to a non-deprecated LogRecord func (ld *LogData) ToLogRecord() LogRecord { - return LogRecord{ + rval := LogRecord{ Timestamp: ld.Timestamp, - Fields: []log.Field{ + } + 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 } From 1937e3c1e99aa701c8dcb88cfb07656bf8c8399c Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Sat, 17 Sep 2016 15:59:28 -0700 Subject: [PATCH 16/19] Respond to review comments --- log/field.go | 2 +- log/util.go | 11 ++++------- 2 files changed, 5 insertions(+), 8 deletions(-) diff --git a/log/field.go b/log/field.go index 03e3325..a340aed 100644 --- a/log/field.go +++ b/log/field.go @@ -95,7 +95,7 @@ func Uint32(key string, val uint32) Field { func Uint64(key string, val uint64) Field { return Field{ key: key, - fieldType: int64Type, + fieldType: uint64Type, numericVal: int64(val), } } diff --git a/log/util.go b/log/util.go index 2f3c30f..3832feb 100644 --- a/log/util.go +++ b/log/util.go @@ -1,23 +1,20 @@ package log -import ( - "fmt" - "reflect" -) +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: %v", len(keyValues)) + 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=%v): %v", - i, reflect.TypeOf(keyValues[i*2])) + "non-string key (pair #%d): %T", + i, keyValues[i*2]) } switch typedVal := keyValues[i*2+1].(type) { case bool: From 7e94f4a23d6db01c5236bbb88481597474924bcd Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Sat, 17 Sep 2016 16:05:14 -0700 Subject: [PATCH 17/19] Use a different example for LogFields and LogKV --- README.md | 11 +++-------- span.go | 10 ++++++---- 2 files changed, 9 insertions(+), 12 deletions(-) diff --git a/README.md b/README.md index f0a9411..1af252a 100644 --- a/README.md +++ b/README.md @@ -51,8 +51,9 @@ happily rely on it for `Span` propagation. To start a new (blocking child) span, ctx := opentracing.StartSpanFromContext(ctx, "operation_name") defer span.Finish() span.LogFields( - log.String("event", "xyz called"), - log.Int("request.size", request.Size())) + log.String("event", "soft error"), + log.String("type", "cache timeout"), + log.Int("waited.millis", 1500)) ... } ``` @@ -67,9 +68,6 @@ reference. ... sp := opentracing.StartSpan("operation_name") defer sp.Finish() - span.LogFields( - log.String("event", "xyz called"), - log.Int("request.size", request.Size())) ... } ``` @@ -83,9 +81,6 @@ reference. "operation_name", opentracing.ChildOf(parentSpan.Context())) defer sp.Finish() - span.LogFields( - log.String("event", "xyz called"), - log.Int("request.size", request.Size())) ... } ``` diff --git a/span.go b/span.go index 2ded84d..591da8b 100644 --- a/span.go +++ b/span.go @@ -58,8 +58,9 @@ type Span interface { // more verbose than LogKV(). Here's an example: // // span.LogFields( - // log.String("request_path", request.Path()), - // log.Uint32("request_size", request.Size())) + // log.String("event", "soft error"), + // log.String("type", "cache timeout"), + // log.Int("waited.millis", 1500)) // // Also see Span.FinishWithOptions() and FinishOptions.BulkLogData. LogFields(fields ...log.Field) @@ -69,8 +70,9 @@ type Span interface { // type-safe than LogFields(). Here's an example: // // span.LogKV( - // "request_path", request.Path(), - // "request_size", request.Size()) + // "event", "soft error", + // "type", "cache timeout", + // "waited.millis", 1500) // // For LogKV (as opposed to LogFields()), the parameters must appear as // key-value pairs, like From ea0e30140cf6184e207d44220f354b9b06e1be0f Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Sat, 17 Sep 2016 16:10:22 -0700 Subject: [PATCH 18/19] Improve deprecation message with pointers --- span.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/span.go b/span.go index 591da8b..903412c 100644 --- a/span.go +++ b/span.go @@ -110,11 +110,11 @@ type Span interface { // Provides access to the Tracer that created this Span. Tracer() Tracer - // DEPRECATED + // Deprecated: use LogFields or LogKV LogEvent(event string) - // DEPRECATED + // Deprecated: use LogFields or LogKV LogEventWithPayload(event string, payload interface{}) - // DEPRECATED + // Deprecated: use LogFields or LogKV Log(data LogData) } From d3768c5f5693fd5ea0ec1aa58c897d86c3a89995 Mon Sep 17 00:00:00 2001 From: Ben Sigelman Date: Mon, 19 Sep 2016 14:57:55 -0700 Subject: [PATCH 19/19] Handle the IsZero timestamp case --- span.go | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/span.go b/span.go index 903412c..f6c3234 100644 --- a/span.go +++ b/span.go @@ -162,8 +162,14 @@ type LogData struct { // 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: ld.Timestamp, + Timestamp: literalTimestamp, } if ld.Payload == nil { rval.Fields = []log.Field{