Upgrade to the new K/V Span logging API

glide.yaml

@@ -5,7 +5,7 @@ import:
   subpackages:
   - lib/go/thrift
 - package: github.com/opentracing/opentracing-go
-  version: ">=0.10.0,<1.0.0"
+  version: ~1.0
   subpackages:
   - ext
 - package: golang.org/x/net

internal/spanlog/json.go

@@ -0,0 +1,87 @@
+// Copyright (c) 2016 Uber Technologies, Inc.
+
+// 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 spanlog
+
+import (
+	"encoding/json"
+	"fmt"
+
+	"github.com/opentracing/opentracing-go/log"
+)
+
+type fieldsAsMap map[string]string
+
+// MaterializeWithJSON converts log Fields into JSON string
+// TODO refactor into pluggable materializer
+func MaterializeWithJSON(logFields []log.Field) ([]byte, error) {
+	fields := fieldsAsMap(make(map[string]string, len(logFields)))
+	for _, field := range logFields {
+		field.Marshal(fields)
+	}
+	if event, ok := fields["event"]; ok && len(fields) == 1 {
+		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)
+}

reporter_test.go

@@ -129,7 +129,7 @@ func (s *reporterSuite) TestClientSpanAnnotations() {
 func (s *reporterSuite) TestTagsAndEvents() {
 	sp := s.tracer.StartSpan("get_name")
 	sp.LogEvent("hello")
-	sp.LogEvent(strings.Repeat("long event", 30))
+	sp.LogEvent(strings.Repeat("long event ", 30))
 	expected := []string{"long", "ping", "awake", "awake", "one", "two", "three", "bite me",
 		JaegerClientVersionTagKey, TracerHostnameTagKey,
 		SamplerParamTagKey, SamplerTypeTagKey,
@@ -158,7 +158,7 @@ func (s *reporterSuite) TestTagsAndEvents() {
 	sort.Strings(binAnnos)
 	s.Equal(expected, binAnnos, "expecting %d binary annotations", len(expected))
 
-	s.NotNil(findAnnotation(zSpan, "hello"), "expecting 'hello' annotation")
+	s.NotNil(findAnnotation(zSpan, "hello"), "expecting 'hello' annotation: %+v", zSpan.Annotations)
 
 	longEvent := false
 	for _, a := range zSpan.Annotations {

span.go

@@ -27,6 +27,7 @@ import (
 
 	"github.com/opentracing/opentracing-go"
 	"github.com/opentracing/opentracing-go/ext"
+	"github.com/opentracing/opentracing-go/log"
 
 	"github.com/uber/jaeger-client-go/utils"
 )
@@ -70,7 +71,7 @@ type span struct {
 	tags []tag
 
 	// The span's "micro-log"
-	logs []opentracing.LogData
+	logs []opentracing.LogRecord
 }
 
 type tag struct {
@@ -119,6 +120,34 @@ func (s *span) setTracerTags(tags []tag) {
 	s.Unlock()
 }
 
+func (s *span) LogFields(fields ...log.Field) {
+	s.Lock()
+	defer s.Unlock()
+	if !s.context.IsSampled() {
+		return
+	}
+	lr := opentracing.LogRecord{
+		Fields:    fields,
+		Timestamp: time.Now(),
+	}
+	s.appendLog(lr)
+}
+
+func (s *span) LogKV(alternatingKeyValues ...interface{}) {
+	s.RLock()
+	sampled := s.context.IsSampled()
+	s.RUnlock()
+	if !sampled {
+		return
+	}
+	fields, err := log.InterleavedKVToFields(alternatingKeyValues...)
+	if err != nil {
+		s.LogFields(log.Error(err), log.String("function", "LogKV"))
+		return
+	}
+	s.LogFields(fields...)
+}
+
 func (s *span) LogEvent(event string) {
 	s.Log(opentracing.LogData{Event: event})
 }
@@ -134,10 +163,16 @@ func (s *span) Log(ld opentracing.LogData) {
 		if ld.Timestamp.IsZero() {
 			ld.Timestamp = s.tracer.timeNow()
 		}
-		s.logs = append(s.logs, ld)
+		s.appendLog(ld.ToLogRecord())
 	}
 }
 
+// this function should only be called while holding a Write lock
+func (s *span) appendLog(lr opentracing.LogRecord) {
+	// TODO add logic to limit number of logs per span (issue #46)
+	s.logs = append(s.logs, lr)
+}
+
 // SetBaggageItem implements SetBaggageItem() of opentracing.SpanContext
 func (s *span) SetBaggageItem(key, value string) opentracing.Span {
 	key = normalizeBaggageKey(key)
@@ -167,8 +202,12 @@ func (s *span) FinishWithOptions(options opentracing.FinishOptions) {
 			finishTime = s.tracer.timeNow()
 		}
 		s.duration = finishTime.Sub(s.startTime)
-		if options.BulkLogData != nil {
-			s.logs = append(s.logs, options.BulkLogData...)
+		// Note: bulk logs are not subject to maxLogsPerSpan limit
+		if options.LogRecords != nil {
+			s.logs = append(s.logs, options.LogRecords...)
+		}
+		for _, ld := range options.BulkLogData {
+			s.logs = append(s.logs, ld.ToLogRecord())
 		}
 	}
 	s.Unlock()

thrift_span.go

@@ -26,8 +26,9 @@ import (
 	"time"
 
 	"github.com/opentracing/opentracing-go/ext"
-
+	"github.com/uber/jaeger-client-go/internal/spanlog"
 	z "github.com/uber/jaeger-client-go/thrift-gen/zipkincore"
+	"github.com/uber/jaeger-client-go/utils"
 )
 
 const (
@@ -38,26 +39,14 @@ const (
 	allowPackedNumbers = false
 )
 
-var (
-	logPayloadLabels = makeLogPayloadLabels(100)
-)
-
-func makeLogPayloadLabels(size int) []string {
-	labels := make([]string, size)
-	for i := 0; i < size; i++ {
-		labels[i] = fmt.Sprintf("log_payload_%d", i)
-	}
-	return labels
-}
-
 // buildThriftSpan builds thrift span based on internal span.
 func buildThriftSpan(span *span) *z.Span {
 	parentID := int64(span.context.parentID)
 	var ptrParentID *int64
 	if parentID != 0 {
 		ptrParentID = &parentID
 	}
-	timestamp := timeToMicrosecondsSinceEpochInt64(span.startTime)
+	timestamp := utils.TimeToMicrosecondsSinceEpochInt64(span.startTime)
 	duration := span.duration.Nanoseconds() / int64(time.Microsecond)
 	endpoint := &z.Endpoint{
 		ServiceName: span.tracer.serviceName,
@@ -86,24 +75,28 @@ func buildAnnotations(span *span, endpoint *z.Endpoint) []*z.Annotation {
 	}
 	if !span.startTime.IsZero() && startLabel != "" {
 		start := &z.Annotation{
-			Timestamp: timeToMicrosecondsSinceEpochInt64(span.startTime),
+			Timestamp: utils.TimeToMicrosecondsSinceEpochInt64(span.startTime),
 			Value:     startLabel,
 			Host:      endpoint}
 		annotations = append(annotations, start)
 		if span.duration != 0 {
 			endTs := span.startTime.Add(span.duration)
 			end := &z.Annotation{
-				Timestamp: timeToMicrosecondsSinceEpochInt64(endTs),
+				Timestamp: utils.TimeToMicrosecondsSinceEpochInt64(endTs),
 				Value:     endLabel,
 				Host:      endpoint}
 			annotations = append(annotations, end)
 		}
 	}
 	for _, log := range span.logs {
 		anno := &z.Annotation{
-			Timestamp: timeToMicrosecondsSinceEpochInt64(log.Timestamp),
-			Value:     truncateString(log.Event),
+			Timestamp: utils.TimeToMicrosecondsSinceEpochInt64(log.Timestamp),
 			Host:      endpoint}
+		if content, err := spanlog.MaterializeWithJSON(log.Fields); err == nil {
+			anno.Value = truncateString(string(content))
+		} else {
+			anno.Value = err.Error()
+		}
 		annotations = append(annotations, anno)
 	}
 	return annotations
@@ -149,17 +142,6 @@ func buildBinaryAnnotations(span *span, endpoint *z.Endpoint) []*z.BinaryAnnotat
 			annotations = append(annotations, anno)
 		}
 	}
-	for i, log := range span.logs {
-		if log.Payload != nil {
-			label := "log_payload"
-			if i < len(logPayloadLabels) {
-				label = logPayloadLabels[i]
-			}
-			if anno := buildBinaryAnnotation(label, log.Payload, nil); anno != nil {
-				annotations = append(annotations, anno)
-			}
-		}
-	}
 	return annotations
 }
 
@@ -218,13 +200,6 @@ func boolToByte(b bool) byte {
 	return 0
 }
 
-// Passing time by value is faster than passing a pointer!
-// BenchmarkTimeByValue-8	2000000000	         1.37 ns/op
-// BenchmarkTimeByPtr-8  	2000000000	         1.98 ns/op
-func timeToMicrosecondsSinceEpochInt64(t time.Time) int64 {
-	return t.UnixNano() / 1000
-}
-
 // int32ToBytes converts int32 to bytes.
 func int32ToBytes(i int32) []byte {
 	buf := make([]byte, 4)