Skip to content
This repository has been archived by the owner on May 23, 2023. It is now read-only.

Introduce key-value Span logging as an RFC #108

Merged
merged 19 commits into from
Sep 26, 2016
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 4 additions & 3 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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))
...
}
```
Expand All @@ -65,7 +68,6 @@ reference.
...
sp := opentracing.StartSpan("operation_name")
defer sp.Finish()
sp.LogEvent("xyz_called")
...
}
```
Expand All @@ -79,7 +81,6 @@ reference.
"operation_name",
opentracing.ChildOf(parentSpan.Context()))
defer sp.Finish()
sp.LogEvent("xyz_called")
...
}
```
Expand Down
200 changes: 200 additions & 0 deletions log/field.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,200 @@
package log
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think the LazyLogger will be sufficient for things like Reference logging (which we may not even special-case), so I moved this back into its own package.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why not have reference field type explicitly? lazyLogger ultimately still ends up with primitive type of interface{}, but Reference is something we should support as a first class citizen imo.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@yurishkuro while I agree we should support Reference as a first-class citizen, I was hoping to add more appropriate (for logging) Reference types before exposing that feature.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

one problem with this approach is that adding a new field type breaks the visitor API by requiring an extra method to be implemented.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's true... I dunno, seems like there are reasonable arguments in either direction. I would have liked to add a comment about supporting Reference types in the N-1 other languages (which have been submitted already). How strongly do you feel about this? (I'm on the fence)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Don't feel very strongly. If we don't do it now, it will require a major version bump to add references, assuming we release the current state as 1.0

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Funny... I've been thinking of semver bumps in terms of clients of the API (rather than implementations), but I see what you mean. We'd have to resign the symbolic importance of major version numbers :-/


import "math"

type fieldType int

const (
stringType fieldType = iota
boolType
intType
int32Type
uint32Type
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(added more numeric types)

int64Type
uint64Type
float32Type
float64Type
errorType
objectType
lazyLoggerType
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

one other interesting feature in zap was nested fields, which allow logging hierarchical structured data.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was wondering if we could remove key from the Encoder interface, but I
fear that doing so ultimately requires using an interface type as the Field
type, which will hurt performance.

When you ask about nested fields, I start to wonder exactly how you'll use
it.

Another question: I don't see slices or array types in the list of
supported types. Omission or intentional?

On Tue, Aug 30, 2016 at 6:38 PM, Yuri Shkuro notifications@github.com
wrote:

In log/field.go
#108 (comment)
:

+type fieldType int
+
+const (

  • stringType fieldType = iota
  • boolType
  • intType
  • int32Type
  • uint32Type
  • int64Type
  • uint64Type
  • float32Type
  • float64Type
  • errorType
  • objectType
  • lazyLoggerType

one other interesting feature in zap was nested fields, which allow
logging hierarchical structured data.


You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/opentracing/opentracing-go/pull/108/files/64b19712cad0dd3fd4a3705aef7e7e8b727ba697#r76911015,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ADdiiSwNEJvns4ccZ1B52n-rjALQlR5Cks5qlNr7gaJpZM4JvDpj
.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nested field example:

span.LogFields(
    log.Nested("employee",
        log.String("firstName", ...),
        log.String("lastName", ...),
    ),
)

Copy link
Member

@yurishkuro yurishkuro Aug 31, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As for arrays, I would say the main reason not to include them is that it cannot be done while preserving type safety without doubling the number of types already present. Array of interface{} is fairly meaningless (might as well use log.Object()), while log.Uint32Array(), log.StringArray(), ... is (to me) unpalatable.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You could also write something like:

LogFields("employee", struct{First, Last string}{first, last})

I experimented with nested logging--I ran into trouble with the semantics. Are labels tags? Can you apply more than one tag to a value? What's the resulting structure look like? In the end I did come up with a satisfying approach, but it was significantly more complicated than anything discussed in this thread, possibly beyond the point of actually being useful. This is why I ask--what the application is for nested logging.

Do you want to find all logs that have a "firstName" property? Is there any sort of namespace to prevent matching logs from unrelated code with "firstName" properties? Can you join logs by these keys?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Personally, I see a strong enough use case for logging structs (as interface{} values, via something like the log.Object(...) in this PR), but pretty much as just a big (possibly truncated) blob for debugging purposes. Nested key-value fields at this logging layer are not indefensible, but IMO cross the complexity threshold and aren't worth the corner cases they expose.

And there's the perennial "easier to add than to remove" argument, too...

)

// 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
Copy link

@dominikh dominikh Sep 17, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Idiomatic Go documentation drops the parentheses, as we're talking about the identifier, not the function call. There are a bunch of others in this PR, like Lazy().

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's helpful as a hint that LogFields is, in fact, a func. I don't feel strongly but that's my rationale. I wish godoc were more explicit (via something like @see in Javadoc) which would allow tools to format/decorate things appropriately.

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'll give you a free pass because it's wrong in all of the ot-go documentation already, but do change your ways one day ;)

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 {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

can you clarify the intention/semantics? What is tracer expected to do (or NOT to do, like convert to String) with it? Maybe a warning to the users that this is likely more expensive to log than primitive values.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I honestly don't know what the semantics should be at the OT layer. We could at least own up to that... I can imagine impls that choose to ignore generic objects entirely; others that truncate or summarize them; and others that record everything.

Copy link
Contributor

@RaduBerinde RaduBerinde Sep 14, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This opens up an interesting case - the object could have a String() method that returns a dynamic value. It should be clarified if that is disallowed or not (and what the implications are). If we require any implementation to only convert to string once, then there is no issue (but that requirement should be documented).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this case must be left up to the implementations for now. There are many viable but mutually-incompatible ways to interpret an interface{} value in the context of logging and I'd feel better having specific OT guidance once the pros and cons of the possible interpretations are clearer (in production).

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))
}
}
54 changes: 54 additions & 0 deletions log/util.go
Original file line number Diff line number Diff line change
@@ -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))

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't know what got into me when I suggested "uneven". Obviously I meant to say "odd". 😊

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

haha :)

While I see what you are getting at (and while I recognize that this is micro-nit territory for both of us), I do like "non-even" because it is unmistakable. "Odd" has other (primary) connotations in English and would be easier to misinterpret.

}
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) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What is the value of this switch vs. just using Object() to store the value as an interface{}? As far as I understand, the field stuff is useful to avoid the allocations involved in boxing things into interface{}, but that has already happened here.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The approach taken here allows Span implementations to handle the "simple" (POD, string) cases via the EmitInt, EmitString, etc functions of the Encoder interface. If we just called everything an Object/interface{} that wouldn't work.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, right, that makes sense, I missed the fact that the Encoder is part of a specific implementation.

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
}
105 changes: 105 additions & 0 deletions mocktracer/mocklogrecord.go
Original file line number Diff line number Diff line change
@@ -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 {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The opentracing.LogRecord is not very useful for tests, so I went with this... Note that MockKeyValue coerces all values to strings but does remember the reflect.Kind.

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
}
Loading