added handling of OpenTracing LogFields in the same way as Jaeger by JSON encoding them

Author: basvanbeek

events/event_nettrace.go

@@ -1,21 +1,21 @@
 package events
 
 import (
-	"github.com/opentracing/basictracer-go"
+	"github.com/openzipkin/zipkin-go-opentracing"
 	"golang.org/x/net/trace"
 )
 
-// NetTraceIntegrator can be passed into a basictracer as NewSpanEventListener
+// NetTraceIntegrator can be passed into a zipkintracer as NewSpanEventListener
 // and causes all traces to be registered with the net/trace endpoint.
-var NetTraceIntegrator = func() func(basictracer.SpanEvent) {
+var NetTraceIntegrator = func() func(zipkintracer.SpanEvent) {
 	var tr trace.Trace
-	return func(e basictracer.SpanEvent) {
+	return func(e zipkintracer.SpanEvent) {
 		switch t := e.(type) {
-		case basictracer.EventCreate:
+		case zipkintracer.EventCreate:
 			tr = trace.New("tracing", t.OperationName)
-		case basictracer.EventFinish:
+		case zipkintracer.EventFinish:
 			tr.Finish()
-		case basictracer.EventLog:
+		case zipkintracer.EventLog:
 			if t.Payload != nil {
 				tr.LazyPrintf("%s (payload %v)", t.Event, t.Payload)
 			} else {

json.go

@@ -0,0 +1,92 @@
+// Copyright (c) 2016 Uber Technologies, Inc.
+// Copyright (c) 2016 Bas van Beek
+
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
+package zipkintracer
+
+import (
+	"encoding/json"
+	"fmt"
+
+	"github.com/opentracing/opentracing-go/log"
+)
+
+type fieldsAsMap map[string]string
+
+// MaterializeWithJSON converts log Fields into JSON string
+func MaterializeWithJSON(logFields []log.Field) ([]byte, error) {
+	fields := fieldsAsMap(make(map[string]string, len(logFields)))
+	for _, field := range logFields {
+		field.Marshal(fields)
+	}
+	// if we only have an event log Field we do not create a json serialization of
+	// the key-value pairs contained within the log Fields, but simply return the
+	// payload of the event log Field.
+	if len(fields) == 1 {
+		if event, ok := fields["event"]; ok {
+			return []byte(event), nil
+		}
+	}
+	return json.Marshal(fields)
+}
+
+func (ml fieldsAsMap) EmitString(key, value string) {
+	ml[key] = value
+}
+
+func (ml fieldsAsMap) EmitBool(key string, value bool) {
+	ml[key] = fmt.Sprintf("%t", value)
+}
+
+func (ml fieldsAsMap) EmitInt(key string, value int) {
+	ml[key] = fmt.Sprintf("%d", value)
+}
+
+func (ml fieldsAsMap) EmitInt32(key string, value int32) {
+	ml[key] = fmt.Sprintf("%d", value)
+}
+
+func (ml fieldsAsMap) EmitInt64(key string, value int64) {
+	ml[key] = fmt.Sprintf("%d", value)
+}
+
+func (ml fieldsAsMap) EmitUint32(key string, value uint32) {
+	ml[key] = fmt.Sprintf("%d", value)
+}
+
+func (ml fieldsAsMap) EmitUint64(key string, value uint64) {
+	ml[key] = fmt.Sprintf("%d", value)
+}
+
+func (ml fieldsAsMap) EmitFloat32(key string, value float32) {
+	ml[key] = fmt.Sprintf("%f", value)
+}
+
+func (ml fieldsAsMap) EmitFloat64(key string, value float64) {
+	ml[key] = fmt.Sprintf("%f", value)
+}
+
+func (ml fieldsAsMap) EmitObject(key string, value interface{}) {
+	ml[key] = fmt.Sprintf("%+v", value)
+}
+
+func (ml fieldsAsMap) EmitLazyLogger(value log.LazyLogger) {
+	value(ml)
+}

span_test.go

@@ -1,10 +1,12 @@
 package zipkintracer
 
 import (
+	"reflect"
 	"testing"
 
 	"github.com/opentracing/opentracing-go"
 	"github.com/opentracing/opentracing-go/ext"
+	"github.com/opentracing/opentracing-go/log"
 	"github.com/stretchr/testify/assert"
 )
 
@@ -101,16 +103,25 @@ func TestSpan_SingleLoggedTaggedSpan(t *testing.T) {
 
 	span := tracer.StartSpan("x")
 	span.LogEventWithPayload("event", "payload")
+	span.LogFields(log.String("key_str", "value"), log.Uint32("32bit", 4294967295))
 	span.SetTag("tag", "value")
 	span.Finish()
 	spans := recorder.GetSpans()
 	assert.Equal(t, 1, len(spans))
 	assert.Equal(t, "x", spans[0].Operation)
-	assert.Equal(t, 1, len(spans[0].Logs))
+	assert.Equal(t, 2, len(spans[0].Logs))
 	// XXX: broken tests
 	//   assert.Equal(t, "event", spans[0].Logs[0].Event)
 	//   assert.Equal(t, "payload", spans[0].Logs[0].Payload)
 	assert.Equal(t, opentracing.Tags{"tag": "value"}, spans[0].Tags)
+	fv := NewLogFieldValidator(t, spans[0].Logs[0].Fields)
+	fv.
+		ExpectNextFieldEquals("event", reflect.String, "event").
+		ExpectNextFieldEquals("payload", reflect.Interface, "payload")
+	fv = NewLogFieldValidator(t, spans[0].Logs[1].Fields)
+	fv.
+		ExpectNextFieldEquals("key_str", reflect.String, "value").
+		ExpectNextFieldEquals("32bit", reflect.Uint32, "4294967295")
 }
 
 func TestSpan_TrimUnsampledSpans(t *testing.T) {
@@ -126,16 +137,17 @@ func TestSpan_TrimUnsampledSpans(t *testing.T) {
 	}
 
 	span := tracer.StartSpan("x")
-	span.LogEventWithPayload("event", "payload")
+	span.LogFields(log.String("key_str", "value"), log.Uint32("32bit", 4294967295))
 	span.SetTag("tag", "value")
 	span.Finish()
 	spans := recorder.GetSpans()
 	assert.Equal(t, 1, len(spans))
 	assert.Equal(t, 1, len(spans[0].Logs))
-	// XXX: broken tests
-	//   assert.Equal(t, "event", spans[0].Logs[0].Event)
-	//   assert.Equal(t, "payload", spans[0].Logs[0].Payload)
 	assert.Equal(t, opentracing.Tags{"tag": "value"}, spans[0].Tags)
+	fv := NewLogFieldValidator(t, spans[0].Logs[0].Fields)
+	fv.
+		ExpectNextFieldEquals("key_str", reflect.String, "value").
+		ExpectNextFieldEquals("32bit", reflect.Uint32, "4294967295")
 
 	recorder.Reset()
 	// Tracer that trims only unsampled and never samples
@@ -149,7 +161,7 @@ func TestSpan_TrimUnsampledSpans(t *testing.T) {
 	}
 
 	span = tracer.StartSpan("x")
-	span.LogEventWithPayload("event", "payload")
+	span.LogFields(log.String("key_str", "value"), log.Uint32("32bit", 4294967295))
 	span.SetTag("tag", "value")
 	span.Finish()
 	spans = recorder.GetSpans()
@@ -171,7 +183,7 @@ func TestSpan_DropAllLogs(t *testing.T) {
 	}
 
 	span := tracer.StartSpan("x")
-	span.LogEventWithPayload("event", "payload")
+	span.LogFields(log.String("key_str", "value"), log.Uint32("32bit", 4294967295))
 	span.SetTag("tag", "value")
 	span.Finish()
 	spans := recorder.GetSpans()

testutil_test.go

@@ -0,0 +1,121 @@
+package zipkintracer
+
+import (
+	"fmt"
+	"reflect"
+	"testing"
+
+	"github.com/opentracing/opentracing-go/log"
+)
+
+// LogFieldValidator facilitates testing of Span.Log*() implementations.
+//
+// Usage:
+//
+//     fv := log.NewLogFieldValidator(t, someLogStructure.Fields)
+//     fv.
+//         ExpectNextFieldEquals("key1", reflect.String, "some string value").
+//         ExpectNextFieldEquals("key2", reflect.Uint32, "4294967295")
+//
+// 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          []log.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 []log.Field) *LogFieldValidator {
+	return &LogFieldValidator{
+		t:      t,
+		fields: fields,
+	}
+}
+
+// ExpectNextFieldEquals facilitates a fluent way of testing the contents
+// []Field slices.
+func (fv *LogFieldValidator) ExpectNextFieldEquals(key string, kind reflect.Kind, valAsString string) *LogFieldValidator {
+	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 *LogFieldValidator) EmitString(key, value string) {
+	fv.validateNextField(key, reflect.String, value)
+}
+
+// EmitBool satisfies the Encoder interface
+func (fv *LogFieldValidator) EmitBool(key string, value bool) {
+	fv.validateNextField(key, reflect.Bool, value)
+}
+
+// EmitInt satisfies the Encoder interface
+func (fv *LogFieldValidator) EmitInt(key string, value int) {
+	fv.validateNextField(key, reflect.Int, value)
+}
+
+// EmitInt32 satisfies the Encoder interface
+func (fv *LogFieldValidator) EmitInt32(key string, value int32) {
+	fv.validateNextField(key, reflect.Int32, value)
+}
+
+// EmitInt64 satisfies the Encoder interface
+func (fv *LogFieldValidator) EmitInt64(key string, value int64) {
+	fv.validateNextField(key, reflect.Int64, value)
+}
+
+// EmitUint32 satisfies the Encoder interface
+func (fv *LogFieldValidator) EmitUint32(key string, value uint32) {
+	fv.validateNextField(key, reflect.Uint32, value)
+}
+
+// EmitUint64 satisfies the Encoder interface
+func (fv *LogFieldValidator) EmitUint64(key string, value uint64) {
+	fv.validateNextField(key, reflect.Uint64, value)
+}
+
+// EmitFloat32 satisfies the Encoder interface
+func (fv *LogFieldValidator) EmitFloat32(key string, value float32) {
+	fv.validateNextField(key, reflect.Float32, value)
+}
+
+// EmitFloat64 satisfies the Encoder interface
+func (fv *LogFieldValidator) EmitFloat64(key string, value float64) {
+	fv.validateNextField(key, reflect.Float64, value)
+}
+
+// EmitObject satisfies the Encoder interface
+func (fv *LogFieldValidator) EmitObject(key string, value interface{}) {
+	fv.validateNextField(key, reflect.Interface, value)
+}
+
+// EmitLazyLogger satisfies the Encoder interface
+func (fv *LogFieldValidator) EmitLazyLogger(value log.LazyLogger) {
+	fv.t.Error("Test infrastructure does not support EmitLazyLogger yet")
+}
+
+func (fv *LogFieldValidator) 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.
+}

zipkin-recorder.go

@@ -117,9 +117,11 @@ func (r *Recorder) RecordSpan(sp RawSpan) {
 	}
 
 	for _, spLog := range sp.Logs {
-		// XXX: decide how to represent spLog.Fields as an annotation
-		var annotationValue string
-		annotate(span, spLog.Timestamp, annotationValue, r.endpoint)
+		if logs, err := MaterializeWithJSON(spLog.Fields); err != nil {
+			fmt.Printf("JSON serialization of OpenTracing LogFields failed: %+v", err)
+		} else {
+			annotate(span, spLog.Timestamp, string(logs), r.endpoint)
+		}
 	}
 	_ = r.collector.Collect(span)
 }