From a776e95c6132bc448131e3d76bfe51d4b08e02e3 Mon Sep 17 00:00:00 2001 From: Krzesimir Nowak Date: Tue, 3 Sep 2019 20:03:51 +0200 Subject: [PATCH] Consolidate AddEvent and Event methods, add FinishOptions (#99) * Merge two event methods in span API There was an agreement to get rid of the Event interface and consolidate the two methods for adding events into one. See #57. * Eliminate the use of the Event interface There is no need for the SDK to provide the implementation of the Event interface - it is used nowhere. * Drop the Event interface It's dead code now. * Make it possible to override a finish timestamp through options Opentracing to opentelemetry bridge will certainly use this feature. * Obey the start time option * Add tests for events and custom start/end times --- api/event/event.go | 29 ---- api/trace/api.go | 19 ++- api/trace/current_test.go | 9 +- api/trace/noop_span.go | 9 +- example/basic/main.go | 4 +- example/http/server/server.go | 2 +- .../streaming/exporter/observer/observer.go | 1 - .../streaming/sdk/internal/test_observer.go | 60 +++++++ experimental/streaming/sdk/span.go | 21 +-- experimental/streaming/sdk/span_test.go | 151 ++++++++++++++++++ experimental/streaming/sdk/trace.go | 2 +- plugin/httptrace/clienttrace.go | 6 +- sdk/trace/basetypes.go | 11 -- sdk/trace/span.go | 35 ++-- sdk/trace/trace_test.go | 36 ++++- 15 files changed, 297 insertions(+), 98 deletions(-) delete mode 100644 api/event/event.go create mode 100644 experimental/streaming/sdk/internal/test_observer.go create mode 100644 experimental/streaming/sdk/span_test.go diff --git a/api/event/event.go b/api/event/event.go deleted file mode 100644 index 67d1c661fd2e..000000000000 --- a/api/event/event.go +++ /dev/null @@ -1,29 +0,0 @@ -// Copyright 2019, OpenTelemetry Authors -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -package event - -import ( - "go.opentelemetry.io/api/core" -) - -// Event interface provides methods to retrieve Event properties. -type Event interface { - - // Message interface retrieves message string of the Event. - Message() string - - // Attributes interface returns a copy of attributes associated with the Event. - Attributes() []core.KeyValue -} diff --git a/api/trace/api.go b/api/trace/api.go index f6edb5823e97..587bd6d7571d 100644 --- a/api/trace/api.go +++ b/api/trace/api.go @@ -21,7 +21,6 @@ import ( "google.golang.org/grpc/codes" "go.opentelemetry.io/api/core" - "go.opentelemetry.io/api/event" "go.opentelemetry.io/api/tag" ) @@ -50,18 +49,28 @@ type Tracer interface { Inject(context.Context, Span, Injector) } +type FinishOptions struct { + FinishTime time.Time +} + +type FinishOption func(*FinishOptions) + +func WithFinishTime(finishTime time.Time) FinishOption { + return func(opts *FinishOptions) { + opts.FinishTime = finishTime + } +} + type Span interface { // Tracer returns tracer used to create this span. Tracer cannot be nil. Tracer() Tracer // Finish completes the span. No updates are allowed to span after it // finishes. The only exception is setting status of the span. - Finish() + Finish(options ...FinishOption) // AddEvent adds an event to the span. - AddEvent(ctx context.Context, event event.Event) - // AddEvent records an event to the span. - Event(ctx context.Context, msg string, attrs ...core.KeyValue) + AddEvent(ctx context.Context, msg string, attrs ...core.KeyValue) // IsRecordingEvents returns true if the span is active and recording events is enabled. IsRecordingEvents() bool diff --git a/api/trace/current_test.go b/api/trace/current_test.go index c8937e8581f4..796384afd7ae 100644 --- a/api/trace/current_test.go +++ b/api/trace/current_test.go @@ -7,7 +7,6 @@ import ( "google.golang.org/grpc/codes" "go.opentelemetry.io/api/core" - "go.opentelemetry.io/api/event" "go.opentelemetry.io/api/tag" "go.opentelemetry.io/api/trace" ) @@ -97,7 +96,7 @@ func (mockSpan) ModifyAttributes(mutators ...tag.Mutator) { } // Finish does nothing. -func (mockSpan) Finish() { +func (mockSpan) Finish(options ...trace.FinishOption) { } // Tracer returns noop implementation of Tracer. @@ -105,10 +104,6 @@ func (mockSpan) Tracer() trace.Tracer { return trace.NoopTracer{} } -// AddEvent does nothing. -func (mockSpan) AddEvent(ctx context.Context, event event.Event) { -} - // Event does nothing. -func (mockSpan) Event(ctx context.Context, msg string, attrs ...core.KeyValue) { +func (mockSpan) AddEvent(ctx context.Context, msg string, attrs ...core.KeyValue) { } diff --git a/api/trace/noop_span.go b/api/trace/noop_span.go index 233ca600642a..e3399767c504 100644 --- a/api/trace/noop_span.go +++ b/api/trace/noop_span.go @@ -20,7 +20,6 @@ import ( "google.golang.org/grpc/codes" "go.opentelemetry.io/api/core" - "go.opentelemetry.io/api/event" "go.opentelemetry.io/api/tag" ) @@ -64,7 +63,7 @@ func (NoopSpan) ModifyAttributes(mutators ...tag.Mutator) { } // Finish does nothing. -func (NoopSpan) Finish() { +func (NoopSpan) Finish(options ...FinishOption) { } // Tracer returns noop implementation of Tracer. @@ -73,11 +72,7 @@ func (NoopSpan) Tracer() Tracer { } // AddEvent does nothing. -func (NoopSpan) AddEvent(ctx context.Context, event event.Event) { -} - -// Event does nothing. -func (NoopSpan) Event(ctx context.Context, msg string, attrs ...core.KeyValue) { +func (NoopSpan) AddEvent(ctx context.Context, msg string, attrs ...core.KeyValue) { } // SetName does nothing. diff --git a/example/basic/main.go b/example/basic/main.go index 9a3421b40bfb..54bfa6d2f512 100644 --- a/example/basic/main.go +++ b/example/basic/main.go @@ -63,7 +63,7 @@ func main() { err := tracer.WithSpan(ctx, "operation", func(ctx context.Context) error { - trace.CurrentSpan(ctx).Event(ctx, "Nice operation!", key.New("bogons").Int(100)) + trace.CurrentSpan(ctx).AddEvent(ctx, "Nice operation!", key.New("bogons").Int(100)) trace.CurrentSpan(ctx).SetAttributes(anotherKey.String("yes")) @@ -75,7 +75,7 @@ func main() { func(ctx context.Context) error { trace.CurrentSpan(ctx).SetAttribute(lemonsKey.String("five")) - trace.CurrentSpan(ctx).Event(ctx, "Sub span event") + trace.CurrentSpan(ctx).AddEvent(ctx, "Sub span event") stats.Record(ctx, measureTwo.M(1.3)) diff --git a/example/http/server/server.go b/example/http/server/server.go index 9b534ee9414b..dbab3b101132 100644 --- a/example/http/server/server.go +++ b/example/http/server/server.go @@ -49,7 +49,7 @@ func main() { ) defer span.Finish() - span.Event(ctx, "handling this...") + span.AddEvent(ctx, "handling this...") _, _ = io.WriteString(w, "Hello, world!\n") } diff --git a/experimental/streaming/exporter/observer/observer.go b/experimental/streaming/exporter/observer/observer.go index e56fc935d07d..4326961d32bd 100644 --- a/experimental/streaming/exporter/observer/observer.go +++ b/experimental/streaming/exporter/observer/observer.go @@ -36,7 +36,6 @@ type ScopeID struct { core.SpanContext } -// TODO: this Event is confusing with event.Event. type Event struct { // Automatic fields Sequence EventID // Auto-filled diff --git a/experimental/streaming/sdk/internal/test_observer.go b/experimental/streaming/sdk/internal/test_observer.go new file mode 100644 index 000000000000..37eaf6dd139e --- /dev/null +++ b/experimental/streaming/sdk/internal/test_observer.go @@ -0,0 +1,60 @@ +// Copyright 2019, OpenTelemetry Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package internal // import "go.opentelemetry.io/experimental/streaming/sdk/internal" + +import ( + "go.opentelemetry.io/experimental/streaming/exporter/observer" +) + +type eventsMap map[observer.EventType][]observer.Event + +type TestObserver struct { + events eventsMap +} + +var _ observer.Observer = &TestObserver{} + +func NewRegisteredObserver() *TestObserver { + o := &TestObserver{} + observer.RegisterObserver(o) + return o +} + +func (o *TestObserver) Unregister() { + observer.UnregisterObserver(o) +} + +func (o *TestObserver) Observe(e observer.Event) { + if o.events == nil { + o.events = make(eventsMap) + } + o.events[e.Type] = append(o.events[e.Type], e) +} + +func (o *TestObserver) Clear() { + o.events = nil +} + +func (o *TestObserver) ClearAndUnregister() { + o.Clear() + o.Unregister() +} + +func (o *TestObserver) Events(eType observer.EventType) []observer.Event { + if o.events == nil { + return nil + } + return o.events[eType] +} diff --git a/experimental/streaming/sdk/span.go b/experimental/streaming/sdk/span.go index 89c91f7e3c5a..153ff140e35e 100644 --- a/experimental/streaming/sdk/span.go +++ b/experimental/streaming/sdk/span.go @@ -16,11 +16,11 @@ package sdk import ( "context" + "time" "google.golang.org/grpc/codes" "go.opentelemetry.io/api/core" - "go.opentelemetry.io/api/event" "go.opentelemetry.io/api/tag" apitrace "go.opentelemetry.io/api/trace" "go.opentelemetry.io/experimental/streaming/exporter/observer" @@ -87,9 +87,14 @@ func (sp *span) ModifyAttributes(mutators ...tag.Mutator) { }) } -func (sp *span) Finish() { +func (sp *span) Finish(options ...apitrace.FinishOption) { recovered := recover() + opts := apitrace.FinishOptions{} + for _, opt := range options { + opt(&opts) + } observer.Record(observer.Event{ + Time: opts.FinishTime, Type: observer.FINISH_SPAN, Scope: sp.ScopeID(), Recovered: recovered, @@ -103,17 +108,13 @@ func (sp *span) Tracer() apitrace.Tracer { return sp.tracer } -func (sp *span) AddEvent(ctx context.Context, event event.Event) { - observer.Record(observer.Event{ - Type: observer.ADD_EVENT, - String: event.Message(), - Attributes: event.Attributes(), - Context: ctx, - }) +func (sp *span) AddEvent(ctx context.Context, msg string, attrs ...core.KeyValue) { + sp.addEventWithTime(ctx, time.Time{}, msg, attrs...) } -func (sp *span) Event(ctx context.Context, msg string, attrs ...core.KeyValue) { +func (sp *span) addEventWithTime(ctx context.Context, timestamp time.Time, msg string, attrs ...core.KeyValue) { observer.Record(observer.Event{ + Time: timestamp, Type: observer.ADD_EVENT, String: msg, Attributes: attrs, diff --git a/experimental/streaming/sdk/span_test.go b/experimental/streaming/sdk/span_test.go new file mode 100644 index 000000000000..3b02cc51d97e --- /dev/null +++ b/experimental/streaming/sdk/span_test.go @@ -0,0 +1,151 @@ +// Copyright 2019, OpenTelemetry Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package sdk + +import ( + "context" + "reflect" + "testing" + "time" + + "github.com/google/go-cmp/cmp" + + "go.opentelemetry.io/api/core" + "go.opentelemetry.io/api/key" + "go.opentelemetry.io/api/trace" + + "go.opentelemetry.io/experimental/streaming/exporter/observer" + "go.opentelemetry.io/experimental/streaming/sdk/internal" +) + +func TestEvents(t *testing.T) { + _ = New().WithSpan(context.Background(), "test", func(ctx context.Context) error { + type test1Type struct{} + type test2Type struct{} + span := trace.CurrentSpan(ctx) + obs := internal.NewRegisteredObserver() + defer obs.ClearAndUnregister() + k1v1 := key.New("k1").String("v1") + k2v2 := key.New("k2").String("v2") + k3v3 := key.New("k3").String("v3") + ctx1 := context.WithValue(ctx, test1Type{}, 42) + span.AddEvent(ctx1, "one two three", k1v1) + ctx2 := context.WithValue(ctx1, test2Type{}, "foo") + span.AddEvent(ctx2, "testing", k2v2, k3v3) + + got := obs.Events(observer.ADD_EVENT) + for idx := range got { + if got[idx].Time.IsZero() { + t.Errorf("Event %d has zero timestamp", idx) + } + got[idx].Time = time.Time{} + } + if len(got) != 2 { + t.Errorf("Expected two events, got %d", len(got)) + } + want := []observer.Event{ + { + Type: observer.ADD_EVENT, + String: "one two three", + Attributes: []core.KeyValue{k1v1}, + }, + { + Type: observer.ADD_EVENT, + String: "testing", + Attributes: []core.KeyValue{k2v2, k3v3}, + }, + } + if diffEvents(t, got, want) { + checkContext(t, got[0].Context, test1Type{}, 42) + checkContextMissing(t, got[0].Context, test2Type{}) + checkContext(t, got[1].Context, test1Type{}, 42) + checkContext(t, got[1].Context, test2Type{}, "foo") + } + return nil + }) +} + +func TestCustomStartEndTime(t *testing.T) { + startTime := time.Date(2019, time.August, 27, 14, 42, 0, 0, time.UTC) + endTime := startTime.Add(time.Second * 20) + tracer := New() + obs := internal.NewRegisteredObserver() + defer obs.ClearAndUnregister() + _, span := tracer.Start( + context.Background(), + "testspan", + trace.WithStartTime(startTime), + ) + span.Finish(trace.WithFinishTime(endTime)) + want := []observer.Event{ + { + Type: observer.START_SPAN, + Time: startTime, + String: "testspan", + }, + { + Type: observer.FINISH_SPAN, + Time: endTime, + }, + } + got := append(obs.Events(observer.START_SPAN), obs.Events(observer.FINISH_SPAN)...) + diffEvents(t, got, want, "Scope") +} + +func checkContextMissing(t *testing.T, ctx context.Context, key interface{}) bool { + gotValue := ctx.Value(key) + if gotValue != nil { + keyType := reflect.TypeOf(key) + t.Errorf("Expected %s to be missing in context", keyType) + return false + } + return true +} + +func checkContext(t *testing.T, ctx context.Context, key, wantValue interface{}) bool { + gotValue := ctx.Value(key) + if gotValue == nil { + keyType := reflect.TypeOf(key) + t.Errorf("Expected %s to exist in context", keyType) + return false + } + if diff := cmp.Diff(gotValue, wantValue); diff != "" { + keyType := reflect.TypeOf(key) + t.Errorf("Context value for key %s: -got +want %s", keyType, diff) + return false + } + return true +} + +func diffEvents(t *testing.T, got, want []observer.Event, extraIgnoredFields ...string) bool { + ignoredPaths := map[string]struct{}{ + "Sequence": struct{}{}, + "Context": struct{}{}, + } + for _, field := range extraIgnoredFields { + ignoredPaths[field] = struct{}{} + } + opts := []cmp.Option{ + cmp.FilterPath(func(path cmp.Path) bool { + _, found := ignoredPaths[path.String()] + return found + }, cmp.Ignore()), + } + if diff := cmp.Diff(got, want, opts...); diff != "" { + t.Errorf("Events: -got +want %s", diff) + return false + } + return true +} diff --git a/experimental/streaming/sdk/trace.go b/experimental/streaming/sdk/trace.go index c765e7c2f937..04183ef02d60 100644 --- a/experimental/streaming/sdk/trace.go +++ b/experimental/streaming/sdk/trace.go @@ -71,7 +71,7 @@ func (t *tracer) WithSpan(ctx context.Context, name string, body func(context.Co if err := body(ctx); err != nil { span.SetAttribute(ErrorKey.Bool(true)) - span.Event(ctx, "span error", MessageKey.String(err.Error())) + span.AddEvent(ctx, "span error", MessageKey.String(err.Error())) return err } return nil diff --git a/plugin/httptrace/clienttrace.go b/plugin/httptrace/clienttrace.go index a2419bc8ad1d..0a14187cb387 100644 --- a/plugin/httptrace/clienttrace.go +++ b/plugin/httptrace/clienttrace.go @@ -153,15 +153,15 @@ func (ct *clientTracer) wroteRequest(info httptrace.WroteRequestInfo) { } func (ct *clientTracer) got100Continue() { - ct.current().Event(ct.Context, "GOT 100 - Continue") + ct.current().AddEvent(ct.Context, "GOT 100 - Continue") } func (ct *clientTracer) wait100Continue() { - ct.current().Event(ct.Context, "GOT 100 - Wait") + ct.current().AddEvent(ct.Context, "GOT 100 - Wait") } func (ct *clientTracer) got1xxResponse(code int, header textproto.MIMEHeader) error { - ct.current().Event(ct.Context, "GOT 1xx", + ct.current().AddEvent(ct.Context, "GOT 1xx", HTTPStatus.Int(code), HTTPHeaderMIME.String(sm2s(header)), ) diff --git a/sdk/trace/basetypes.go b/sdk/trace/basetypes.go index 118ccd69312b..ff6edf9b1836 100644 --- a/sdk/trace/basetypes.go +++ b/sdk/trace/basetypes.go @@ -18,7 +18,6 @@ import ( "time" "go.opentelemetry.io/api/core" - apievent "go.opentelemetry.io/api/event" ) // event is used to describe an event with a message string and set of @@ -28,13 +27,3 @@ type event struct { attributes []core.KeyValue time time.Time } - -var _ apievent.Event = &event{} - -func (me *event) Message() string { - return me.msg -} - -func (me *event) Attributes() []core.KeyValue { - return me.attributes -} diff --git a/sdk/trace/span.go b/sdk/trace/span.go index f3ae8d6214ff..d9347bac4c0e 100644 --- a/sdk/trace/span.go +++ b/sdk/trace/span.go @@ -22,7 +22,6 @@ import ( "google.golang.org/grpc/codes" "go.opentelemetry.io/api/core" - apievent "go.opentelemetry.io/api/event" apitag "go.opentelemetry.io/api/tag" apitrace "go.opentelemetry.io/api/trace" "go.opentelemetry.io/sdk/internal" @@ -107,7 +106,7 @@ func (s *span) ModifyAttribute(mutator apitag.Mutator) { func (s *span) ModifyAttributes(mutators ...apitag.Mutator) { } -func (s *span) Finish() { +func (s *span) Finish(options ...apitrace.FinishOption) { if s == nil { return } @@ -118,13 +117,21 @@ func (s *span) Finish() { if !s.IsRecordingEvents() { return } + opts := apitrace.FinishOptions{} + for _, opt := range options { + opt(&opts) + } s.endOnce.Do(func() { exp, _ := exporters.Load().(exportersMap) mustExport := s.spanContext.IsSampled() && len(exp) > 0 //if s.spanStore != nil || mustExport { if mustExport { sd := s.makeSpanData() - sd.EndTime = internal.MonotonicEndTime(sd.StartTime) + if opts.FinishTime.IsZero() { + sd.EndTime = internal.MonotonicEndTime(sd.StartTime) + } else { + sd.EndTime = opts.FinishTime + } //if s.spanStore != nil { // s.spanStore.finished(s, sd) //} @@ -141,27 +148,21 @@ func (s *span) Tracer() apitrace.Tracer { return s.tracer } -func (s *span) AddEvent(ctx context.Context, event apievent.Event) { +func (s *span) AddEvent(ctx context.Context, msg string, attrs ...core.KeyValue) { if !s.IsRecordingEvents() { return } - s.mu.Lock() - defer s.mu.Unlock() - s.messageEvents.add(event) + s.addEventWithTimestamp(time.Now(), msg, attrs...) } -func (s *span) Event(ctx context.Context, msg string, attrs ...core.KeyValue) { - if !s.IsRecordingEvents() { - return - } - now := time.Now() +func (s *span) addEventWithTimestamp(timestamp time.Time, msg string, attrs ...core.KeyValue) { s.mu.Lock() + defer s.mu.Unlock() s.messageEvents.add(event{ msg: msg, attributes: attrs, - time: now, + time: timestamp, }) - s.mu.Unlock() } func (s *span) SetName(name string) { @@ -274,9 +275,13 @@ func startSpanInternal(name string, parent core.SpanContext, remoteParent bool, return span } + startTime := o.StartTime + if startTime.IsZero() { + startTime = time.Now() + } span.data = &SpanData{ SpanContext: span.spanContext, - StartTime: time.Now(), + StartTime: startTime, // TODO;[rghetia] : fix spanKind //SpanKind: o.SpanKind, Name: name, diff --git a/sdk/trace/trace_test.go b/sdk/trace/trace_test.go index e06a57033013..a05456281f86 100644 --- a/sdk/trace/trace_test.go +++ b/sdk/trace/trace_test.go @@ -234,8 +234,8 @@ func TestEvents(t *testing.T) { k2v2 := key.New("key2").String("value2") k3v3 := key.New("key3").String("value3") - span.Event(context.Background(), "foo", key.New("key1").String("value1")) - span.Event(context.Background(), "bar", + span.AddEvent(context.Background(), "foo", key.New("key1").String("value1")) + span.AddEvent(context.Background(), "bar", key.New("key2").String("value2"), key.New("key3").String("value3"), ) @@ -276,13 +276,13 @@ func TestEventsOverLimit(t *testing.T) { k2v2 := key.New("key2").String("value2") k3v3 := key.New("key3").String("value3") - span.Event(context.Background(), "fooDrop", key.New("key1").String("value1")) - span.Event(context.Background(), "barDrop", + span.AddEvent(context.Background(), "fooDrop", key.New("key1").String("value1")) + span.AddEvent(context.Background(), "barDrop", key.New("key2").String("value2"), key.New("key3").String("value3"), ) - span.Event(context.Background(), "foo", key.New("key1").String("value1")) - span.Event(context.Background(), "bar", + span.AddEvent(context.Background(), "foo", key.New("key1").String("value1")) + span.AddEvent(context.Background(), "bar", key.New("key2").String("value2"), key.New("key3").String("value3"), ) @@ -596,3 +596,27 @@ func TestExecutionTracerTaskEnd(t *testing.T) { t.Fatalf("Execution tracer task ended for %v spans; want %v", got, want) } } + +func TestCustomStartEndTime(t *testing.T) { + startTime := time.Date(2019, time.August, 27, 14, 42, 0, 0, time.UTC) + endTime := startTime.Add(time.Second * 20) + _, span := apitrace.Start( + context.Background(), + "testspan", + apitrace.WithStartTime(startTime), + ) + var te testExporter + RegisterExporter(&te) + span.Finish(apitrace.WithFinishTime(endTime)) + UnregisterExporter(&te) + if len(te.spans) != 1 { + t.Fatalf("got exported spans %#v, want one span", te.spans) + } + got := te.spans[0] + if got.StartTime != startTime { + t.Errorf("expected start time to be %s, got %s", startTime, got.StartTime) + } + if got.EndTime != endTime { + t.Errorf("expected end time to be %s, got %s", endTime, got.EndTime) + } +}