diff --git a/glide.lock b/glide.lock index bf9501f3..5a3ee749 100644 --- a/glide.lock +++ b/glide.lock @@ -1,5 +1,5 @@ -hash: 8a19424b98ca02a54b68a116e0759a9c982576f7a02fd50935c2c41673fe7895 -updated: 2016-09-20T19:11:52.366084254-04:00 +hash: b065de05e5575b34a294793e44015224d4fdfe1c98d2e69270b8f156ecd8d94c +updated: 2016-09-27T10:25:26.753240697-04:00 imports: - name: github.com/apache/thrift version: 23d6746079d7b5fdb38214387c63f987e68a6d8f @@ -15,15 +15,16 @@ imports: subpackages: - spew - name: github.com/opentracing/opentracing-go - version: ca4c9c0010bd9155b6d067b33865d849fe533628 + version: 0c3154a3c2ce79d3271985848659870599dfb77c subpackages: - ext + - log - name: github.com/pmezard/go-difflib version: 792786c7400a136282c1664665ae0a8db921c6c2 subpackages: - difflib - name: github.com/stretchr/testify - version: f390dcf405f7b83c997eac1b06768bb9f44dec18 + version: 69483b4bd14f5845b5a1e55bca19e954e827f1d0 subpackages: - assert - require diff --git a/glide.yaml b/glide.yaml index 7da686a5..97781c1b 100644 --- a/glide.yaml +++ b/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 diff --git a/internal/spanlog/json.go b/internal/spanlog/json.go new file mode 100644 index 00000000..283deb1a --- /dev/null +++ b/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) +} diff --git a/reporter_test.go b/reporter_test.go index e7cbe1b9..d3d44409 100644 --- a/reporter_test.go +++ b/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 { diff --git a/span.go b/span.go index 2ea30591..e29bf1b2 100644 --- a/span.go +++ b/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() diff --git a/thrift_span.go b/thrift_span.go index 0a06d256..ab3f5b84 100644 --- a/thrift_span.go +++ b/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,18 +39,6 @@ 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) @@ -57,7 +46,7 @@ func buildThriftSpan(span *span) *z.Span { 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,14 +75,14 @@ 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) @@ -101,9 +90,13 @@ func buildAnnotations(span *span, endpoint *z.Endpoint) []*z.Annotation { } 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) diff --git a/thrift_span_test.go b/thrift_span_test.go index 7d2a5a07..d49f3627 100644 --- a/thrift_span_test.go +++ b/thrift_span_test.go @@ -1,14 +1,18 @@ package jaeger import ( + "errors" "fmt" "testing" + "time" "github.com/opentracing/opentracing-go" "github.com/opentracing/opentracing-go/ext" + "github.com/opentracing/opentracing-go/log" "github.com/stretchr/testify/assert" "github.com/uber/jaeger-client-go/thrift-gen/zipkincore" + "github.com/uber/jaeger-client-go/utils" ) func TestThriftFirstInProcessSpan(t *testing.T) { @@ -64,40 +68,156 @@ func TestThriftSpanLogs(t *testing.T) { NewConstSampler(true), NewNullReporter()) defer closer.Close() + root := tracer.StartSpan("s1") - sp := tracer.StartSpan("s1").(*span) - payload := "luggage" - n := len(logPayloadLabels) - m := n + 5 - for i := 0; i < m; i++ { - sp.LogEventWithPayload(fmt.Sprintf("event%d", i), payload) + someTime := time.Now().Add(-time.Minute) + someTimeInt64 := utils.TimeToMicrosecondsSinceEpochInt64(someTime) + + fields := func(fields ...log.Field) []log.Field { + return fields } - thriftSpan := buildThriftSpan(sp) - var ( - logs int - numberedPayloads int - plainPayloads int - ) - for i := 0; i < m; i++ { - for _, anno := range thriftSpan.Annotations { - if anno.Value == fmt.Sprintf("event%d", i) { - logs++ - } + tests := []struct { + fields []log.Field + logFunc func(sp opentracing.Span) + expected string + expectedTimestamp int64 + disableSampling bool + }{ + {fields: fields(log.String("event", "happened")), expected: "happened"}, + {fields: fields(log.String("something", "happened")), expected: `{"something":"happened"}`}, + {fields: fields(log.Bool("something", true)), expected: `{"something":"true"}`}, + {fields: fields(log.Int("something", 123)), expected: `{"something":"123"}`}, + {fields: fields(log.Int32("something", 123)), expected: `{"something":"123"}`}, + {fields: fields(log.Int64("something", 123)), expected: `{"something":"123"}`}, + {fields: fields(log.Uint32("something", 123)), expected: `{"something":"123"}`}, + {fields: fields(log.Uint64("something", 123)), expected: `{"something":"123"}`}, + {fields: fields(log.Float32("something", 123)), expected: `{"something":"123.000000"}`}, + {fields: fields(log.Float64("something", 123)), expected: `{"something":"123.000000"}`}, + {fields: fields(log.Error(errors.New("drugs are baaad, m-k"))), + expected: `{"error":"drugs are baaad, m-k"}`}, + {fields: fields(log.Object("something", 123)), expected: `{"something":"123"}`}, + { + fields: fields(log.Lazy(func(fv log.Encoder) { + fv.EmitBool("something", true) + })), + expected: `{"something":"true"}`, + }, + { + logFunc: func(sp opentracing.Span) { + sp.LogKV("event", "something") + }, + expected: "something", + }, + { + logFunc: func(sp opentracing.Span) { + sp.LogKV("non-even number of arguments") + }, + // this is a bit fragile, but ¯\_(ツ)_/¯ + expected: `{"error":"non-even keyValues len: 1","function":"LogKV"}`, + }, + { + logFunc: func(sp opentracing.Span) { + sp.LogEvent("something") + }, + expected: "something", + }, + { + logFunc: func(sp opentracing.Span) { + sp.LogEventWithPayload("something", "payload") + }, + expected: `{"event":"something","payload":"payload"}`, + }, + { + logFunc: func(sp opentracing.Span) { + sp.Log(opentracing.LogData{Event: "something"}) + }, + expected: "something", + }, + { + logFunc: func(sp opentracing.Span) { + sp.Log(opentracing.LogData{Event: "something", Payload: "payload"}) + }, + expected: `{"event":"something","payload":"payload"}`, + }, + { + logFunc: func(sp opentracing.Span) { + sp.FinishWithOptions(opentracing.FinishOptions{ + LogRecords: []opentracing.LogRecord{ + { + Timestamp: someTime, + Fields: fields(log.String("event", "happened")), + }, + }, + }) + }, + expected: "happened", + expectedTimestamp: someTimeInt64, + }, + { + logFunc: func(sp opentracing.Span) { + sp.FinishWithOptions(opentracing.FinishOptions{ + BulkLogData: []opentracing.LogData{ + { + Timestamp: someTime, + Event: "happened", + }, + }, + }) + }, + expected: "happened", + expectedTimestamp: someTimeInt64, + }, + { + logFunc: func(sp opentracing.Span) { + sp.FinishWithOptions(opentracing.FinishOptions{ + BulkLogData: []opentracing.LogData{ + { + Timestamp: someTime, + Event: "happened", + Payload: "payload", + }, + }, + }) + }, + expected: `{"event":"happened","payload":"payload"}`, + expectedTimestamp: someTimeInt64, + }, + { + disableSampling: true, + fields: fields(log.String("event", "happened")), + expected: "", + }, + { + disableSampling: true, + logFunc: func(sp opentracing.Span) { + sp.LogKV("event", "something") + }, + expected: "", + }, + } + + for i, test := range tests { + testName := fmt.Sprintf("test-%02d", i) + sp := tracer.StartSpan(testName, opentracing.ChildOf(root.Context())) + if test.disableSampling { + ext.SamplingPriority.Set(sp, 0) } - for _, anno := range thriftSpan.BinaryAnnotations { - if anno.Key == fmt.Sprintf("log_payload_%d", i) { - numberedPayloads++ - } + if test.logFunc != nil { + test.logFunc(sp) + } else if len(test.fields) > 0 { + sp.LogFields(test.fields...) } - } - for _, anno := range thriftSpan.BinaryAnnotations { - if anno.Key == "log_payload" { - plainPayloads++ + thriftSpan := buildThriftSpan(sp.(*span)) + if test.disableSampling { + assert.Equal(t, 0, len(thriftSpan.Annotations), testName) + continue + } + assert.Equal(t, 1, len(thriftSpan.Annotations), testName) + assert.Equal(t, test.expected, thriftSpan.Annotations[0].Value, testName) + if test.expectedTimestamp != 0 { + assert.Equal(t, test.expectedTimestamp, thriftSpan.Annotations[0].Timestamp, testName) } } - assert.Equal(t, m, logs, "Each log must create Annotation") - assert.Equal(t, n, numberedPayloads, "Each log must create numbered BinaryAnnotation") - assert.Equal(t, m-n, plainPayloads, "Each log over %d must create unnumbered BinaryAnnotation", n) } func TestThriftLocalComponentSpan(t *testing.T) { diff --git a/tracer.go b/tracer.go index dd054056..9b6fb02e 100644 --- a/tracer.go +++ b/tracer.go @@ -46,9 +46,12 @@ type tracer struct { timeNow func() time.Time randomNumber func() uint64 + options struct { + poolSpans bool + // more options to come + } // pool for Span objects - poolSpans bool - spanPool sync.Pool + spanPool sync.Pool injectors map[interface{}]Injector extractors map[interface{}]Extractor @@ -105,7 +108,9 @@ func NewTracer( if t.randomNumber == nil { rng := utils.NewRand(time.Now().UnixNano()) - t.randomNumber = func() uint64 { return uint64(rng.Int63()) } + t.randomNumber = func() uint64 { + return uint64(rng.Int63()) + } } if t.timeNow == nil { t.timeNow = time.Now @@ -256,7 +261,7 @@ func (t *tracer) Close() error { // getSpan retrieves an instance of a clean Span object. // If options.PoolSpans is true, the spans are retrieved from an object pool. func (t *tracer) newSpan() *span { - if !t.poolSpans { + if !t.options.poolSpans { return &span{} } sp := t.spanPool.Get().(*span) @@ -320,7 +325,7 @@ func (t *tracer) reportSpan(sp *span) { } t.reporter.Report(sp) } - if t.poolSpans { + if t.options.poolSpans { t.spanPool.Put(sp) } } diff --git a/tracer_options.go b/tracer_options.go index 712c3d4b..c6c84d4c 100644 --- a/tracer_options.go +++ b/tracer_options.go @@ -67,7 +67,7 @@ func (tracerOptions) RandomNumber(randomNumber func() uint64) TracerOption { // that can access parent spans after those spans have been finished. func (tracerOptions) PoolSpans(poolSpans bool) TracerOption { return func(tracer *tracer) { - tracer.poolSpans = poolSpans + tracer.options.poolSpans = poolSpans } } diff --git a/tracer_test.go b/tracer_test.go index d1ecdd47..0d21662d 100644 --- a/tracer_test.go +++ b/tracer_test.go @@ -197,7 +197,7 @@ func TestTracerOptions(t *testing.T) { assert.Equal(t, uint64(1), tracer.randomNumber()) assert.Equal(t, uint64(1), tracer.randomNumber()) assert.Equal(t, uint64(1), tracer.randomNumber()) // always 1 - assert.Equal(t, true, tracer.poolSpans) + assert.Equal(t, true, tracer.options.poolSpans) } func TestInjectorExtractorOptions(t *testing.T) { diff --git a/utils/utils.go b/utils/utils.go index 2259777b..79eaa4e2 100644 --- a/utils/utils.go +++ b/utils/utils.go @@ -26,6 +26,7 @@ import ( "net" "strconv" "strings" + "time" ) var ( @@ -79,3 +80,14 @@ func PackIPAsUint32(ip net.IP) uint32 { } return 0 } + +// TimeToMicrosecondsSinceEpochInt64 converts Go time.Time to a long +// representing time since epoch in microseconds, which is used expected +// in the Jaeger spans encoded as Thrift. +func TimeToMicrosecondsSinceEpochInt64(t time.Time) int64 { + // ^^^ Passing time.Time by value is faster than passing a pointer! + // BenchmarkTimeByValue-8 2000000000 1.37 ns/op + // BenchmarkTimeByPtr-8 2000000000 1.98 ns/op + + return t.UnixNano() / 1000 +}