Merge pull request #26 from basvanbeek/master

Handle OpenTracing key-value logging, finished work in PR #25

event.go

@@ -19,7 +19,12 @@ type EventBaggage struct {
 	Key, Value string
 }
 
+// EventLogFields is received when LogFields or LogKV is called.
+type EventLogFields opentracing.LogRecord
+
 // EventLog is received when Log (or one of its derivatives) is called.
+//
+// Deprecated: superseded by EventLogFields
 type EventLog opentracing.LogData
 
 // EventFinish is received when Finish is called.
@@ -40,6 +45,11 @@ func (s *spanImpl) onLog(ld opentracing.LogData) {
 		s.event(EventLog(ld))
 	}
 }
+func (s *spanImpl) onLogFields(lr opentracing.LogRecord) {
+	if s.event != nil {
+		s.event(EventLogFields(lr))
+	}
+}
 func (s *spanImpl) onBaggage(key, value string) {
 	if s.event != nil {
 		s.event(EventBaggage{Key: key, Value: value})

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)
+}

raw.go

@@ -26,5 +26,5 @@ type RawSpan struct {
 	Tags opentracing.Tags
 
 	// The span's "microlog".
-	Logs []opentracing.LogData
+	Logs []opentracing.LogRecord
 }

span.go

@@ -6,6 +6,7 @@ import (
 
 	opentracing "github.com/opentracing/opentracing-go"
 	"github.com/opentracing/opentracing-go/ext"
+	"github.com/opentracing/opentracing-go/log"
 
 	"github.com/openzipkin/zipkin-go-opentracing/_thrift/gen-go/zipkincore"
 )
@@ -91,6 +92,31 @@ func (s *spanImpl) SetTag(key string, value interface{}) opentracing.Span {
 	return s
 }
 
+func (s *spanImpl) LogKV(keyValues ...interface{}) {
+	fields, err := log.InterleavedKVToFields(keyValues...)
+	if err != nil {
+		s.LogFields(log.Error(err), log.String("function", "LogKV"))
+		return
+	}
+	s.LogFields(fields...)
+}
+
+func (s *spanImpl) LogFields(fields ...log.Field) {
+	lr := opentracing.LogRecord{
+		Fields: fields,
+	}
+	defer s.onLogFields(lr)
+	s.Lock()
+	defer s.Unlock()
+	if s.trim() || s.tracer.options.dropAllLogs {
+		return
+	}
+	if lr.Timestamp.IsZero() {
+		lr.Timestamp = time.Now()
+	}
+	s.raw.Logs = append(s.raw.Logs, lr)
+}
+
 func (s *spanImpl) LogEvent(event string) {
 	s.Log(opentracing.LogData{
 		Event: event,
@@ -116,7 +142,7 @@ func (s *spanImpl) Log(ld opentracing.LogData) {
 		ld.Timestamp = time.Now()
 	}
 
-	s.raw.Logs = append(s.raw.Logs, ld)
+	s.raw.Logs = append(s.raw.Logs, ld.ToLogRecord())
 }
 
 func (s *spanImpl) Finish() {
@@ -132,8 +158,11 @@ func (s *spanImpl) FinishWithOptions(opts opentracing.FinishOptions) {
 
 	s.Lock()
 	defer s.Unlock()
-	if opts.BulkLogData != nil {
-		s.raw.Logs = append(s.raw.Logs, opts.BulkLogData...)
+	if opts.LogRecords != nil {
+		s.raw.Logs = append(s.raw.Logs, opts.LogRecords...)
+	}
+	for _, ld := range opts.BulkLogData {
+		s.raw.Logs = append(s.raw.Logs, ld.ToLogRecord())
 	}
 	s.raw.Duration = duration
 

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,15 +103,22 @@ 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, "event", spans[0].Logs[0].Event)
-	assert.Equal(t, "payload", spans[0].Logs[0].Payload)
+	assert.Equal(t, 2, len(spans[0].Logs))
 	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) {
@@ -125,15 +134,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))
-	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
@@ -147,7 +158,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()
@@ -169,7 +180,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()