event: Remove the builder concept We no longer need it, the optimizer now manages to a avoid allocations on ... functions. Change-Id: If6ac86cba8cabfc855b347fd597192d093c69663 Reviewed-on: https://go-review.googlesource.com/c/exp/+/329629 Trust: Ian Cottrell <iancottrell@google.com> Run-TryBot: Ian Cottrell <iancottrell@google.com> TryBot-Result: Go Bot <gobot@golang.org> Reviewed-by: Jonathan Amsterdam <jba@google.com>
diff --git a/event/adapter/gokit/gokit.go b/event/adapter/gokit/gokit.go index b51fab4..c442ed6 100644 --- a/event/adapter/gokit/gokit.go +++ b/event/adapter/gokit/gokit.go
@@ -34,7 +34,10 @@ keyvals = keyvals[1:] } } - b := event.To(ctx) + ev := event.New(ctx, event.LogKind) + if ev == nil { + return nil + } var msg string for i := 0; i < len(keyvals); i += 2 { key := keyvals[i].(string) @@ -42,9 +45,10 @@ if key == "msg" || key == "message" { msg = fmt.Sprint(value) } else { - b.With(keys.Value(key).Of(value)) + ev.Labels = append(ev.Labels, keys.Value(key).Of(value)) } } - b.Log(msg) + ev.Message = msg + ev.Deliver() return nil }
diff --git a/event/adapter/gokit/gokit_test.go b/event/adapter/gokit/gokit_test.go index f8d6cad..9c84590 100644 --- a/event/adapter/gokit/gokit_test.go +++ b/event/adapter/gokit/gokit_test.go
@@ -31,7 +31,7 @@ keys.Value("resource").Of("R"), }, }} - if diff := cmp.Diff(want, h.Got); diff != "" { + if diff := cmp.Diff(want, h.Got, eventtest.CmpOption()); diff != "" { t.Errorf("mismatch (-want, +got):\n%s", diff) } }
diff --git a/event/adapter/logfmt/logfmt.go b/event/adapter/logfmt/logfmt.go index 9735b38..cc8b297 100644 --- a/event/adapter/logfmt/logfmt.go +++ b/event/adapter/logfmt/logfmt.go
@@ -40,27 +40,11 @@ return &Handler{to: to} } -func (h *Handler) Log(ctx context.Context, ev *event.Event) { - h.Printer.Event(h.to, ev) -} - -func (h *Handler) Metric(ctx context.Context, ev *event.Event) { - h.Printer.Event(h.to, ev) -} - -func (h *Handler) Annotate(ctx context.Context, ev *event.Event) { - h.Printer.Event(h.to, ev) -} - -func (h *Handler) Start(ctx context.Context, ev *event.Event) context.Context { +func (h *Handler) Event(ctx context.Context, ev *event.Event) context.Context { h.Printer.Event(h.to, ev) return ctx } -func (h *Handler) End(ctx context.Context, ev *event.Event) { - h.Printer.Event(h.to, ev) -} - func (p *Printer) Event(w io.Writer, ev *event.Event) { p.needSep = false if !ev.At.IsZero() { @@ -94,7 +78,7 @@ p.label(w, "name", event.StringOf(ev.Name)) } - if ev.Kind == event.TraceKind && ev.TraceID == 0 { + if ev.Kind == event.EndKind { p.label(w, "end", event.Value{}) }
diff --git a/event/adapter/logfmt/logfmt_test.go b/event/adapter/logfmt/logfmt_test.go index ca764e3..be80ade 100644 --- a/event/adapter/logfmt/logfmt_test.go +++ b/event/adapter/logfmt/logfmt_test.go
@@ -57,7 +57,7 @@ expect: `err="an error"`, }, { name: "end", - event: event.Event{Kind: event.TraceKind}, + event: event.Event{Kind: event.EndKind}, expect: `end`, }, { name: "string",
diff --git a/event/adapter/logr/logr.go b/event/adapter/logr/logr.go index 2dfb62a..23bf172 100644 --- a/event/adapter/logr/logr.go +++ b/event/adapter/logr/logr.go
@@ -15,8 +15,8 @@ ) type logger struct { - exporter *event.Exporter - builder event.Builder // never delivered, only cloned + ctx context.Context + labels []event.Label nameSep string name string verbosity int @@ -26,7 +26,7 @@ func NewLogger(ctx context.Context, nameSep string) logr.Logger { return &logger{ - builder: event.To(ctx), + ctx: ctx, nameSep: nameSep, } } @@ -63,13 +63,6 @@ return true } -// addLabels adds labels for keysAndValues to b. -func addLabels(b event.Builder, keysAndValues []interface{}) { - for i := 0; i < len(keysAndValues); i += 2 { - b.With(newLabel(keysAndValues[i], keysAndValues[i+1])) - } -} - // Info logs a non-error message with the given key/value pairs as context. // // The msg argument should be used to add some constant description to @@ -77,7 +70,10 @@ // variable information. The key/value pairs should alternate string // keys and arbitrary values. func (l *logger) Info(msg string, keysAndValues ...interface{}) { - l.log(msg, l.builder.Clone(), keysAndValues) + ev := event.New(l.ctx, event.LogKind) + if ev != nil { + l.log(ev, msg, keysAndValues) + } } // Error logs an error, with the given message and key/value pairs as context. @@ -89,22 +85,35 @@ // while the err field should be used to attach the actual error that // triggered this log line, if present. func (l *logger) Error(err error, msg string, keysAndValues ...interface{}) { - l.log(msg, l.builder.Clone().Error(err), keysAndValues) + ev := event.New(l.ctx, event.LogKind) + if ev != nil { + ev.Labels = append(ev.Labels, keys.Value("error").Of(err)) + l.log(ev, msg, keysAndValues) + } } -func (l *logger) log(msg string, b event.Builder, keysAndValues []interface{}) { - b.With(convertVerbosity(l.verbosity)) - b.Name(l.name) - addLabels(b, keysAndValues) - b.Log(msg) +func (l *logger) log(ev *event.Event, msg string, keysAndValues []interface{}) { + ev.Labels = append(ev.Labels, convertVerbosity(l.verbosity).Label()) + ev.Labels = append(ev.Labels, l.labels...) + for i := 0; i < len(keysAndValues); i += 2 { + ev.Labels = append(ev.Labels, newLabel(keysAndValues[i], keysAndValues[i+1])) + } + ev.Name = l.name + ev.Message = msg + ev.Deliver() } // WithValues adds some key-value pairs of context to a logger. // See Info for documentation on how key/value pairs work. func (l *logger) WithValues(keysAndValues ...interface{}) logr.Logger { l2 := *l - l2.builder = l2.builder.Clone() - addLabels(l2.builder, keysAndValues) + if len(keysAndValues) > 0 { + l2.labels = make([]event.Label, len(l.labels), len(l.labels)+(len(keysAndValues)/2)) + copy(l2.labels, l.labels) + for i := 0; i < len(keysAndValues); i += 2 { + l2.labels = append(l2.labels, newLabel(keysAndValues[i], keysAndValues[i+1])) + } + } return &l2 } @@ -112,7 +121,7 @@ return keys.Value(key.(string)).Of(value) } -func convertVerbosity(v int) event.Label { +func convertVerbosity(v int) severity.Level { //TODO: this needs to be more complicated, v decreases with increasing severity - return severity.Of(severity.Level(v)) + return severity.Level(v) }
diff --git a/event/adapter/logr/logr_test.go b/event/adapter/logr/logr_test.go index 8b897e4..6417755 100644 --- a/event/adapter/logr/logr_test.go +++ b/event/adapter/logr/logr_test.go
@@ -19,7 +19,7 @@ func TestInfo(t *testing.T) { ctx, th := eventtest.NewCapture() - log := elogr.NewLogger(ctx, "/").WithName("n").V(int(severity.DebugLevel)) + log := elogr.NewLogger(ctx, "/").WithName("n").V(int(severity.Debug)) log = log.WithName("m") log.Info("mess", "traceID", 17, "resource", "R") want := []event.Event{{ @@ -28,12 +28,12 @@ Message: "mess", Name: "n/m", Labels: []event.Label{ - severity.Debug, + severity.Debug.Label(), keys.Value("traceID").Of(17), keys.Value("resource").Of("R"), }, }} - if diff := cmp.Diff(want, th.Got); diff != "" { + if diff := cmp.Diff(want, th.Got, eventtest.CmpOption()); diff != "" { t.Errorf("mismatch (-want, +got):\n%s", diff) } }
diff --git a/event/adapter/logrus/logrus.go b/event/adapter/logrus/logrus.go index fe21fee..af41ce4 100644 --- a/event/adapter/logrus/logrus.go +++ b/event/adapter/logrus/logrus.go
@@ -46,19 +46,24 @@ if ctx == nil { ctx = context.Background() } - b := event.To(ctx).At(e.Time) - b.With(convertLevel(e.Level)) - for k, v := range e.Data { - b.With(keys.Value(k).Of(v)) + ev := event.New(ctx, event.LogKind) + if ev == nil { + return nil, nil } - b.Log(e.Message) + ev.At = e.Time + ev.Labels = append(ev.Labels, convertLevel(e.Level).Label()) + for k, v := range e.Data { + ev.Labels = append(ev.Labels, keys.Value(k).Of(v)) + } + ev.Message = e.Message + ev.Deliver() return nil, nil } -func convertLevel(level logrus.Level) event.Label { +func convertLevel(level logrus.Level) severity.Level { switch level { case logrus.PanicLevel: - return severity.Of(severity.FatalLevel + 1) + return severity.Fatal + 1 case logrus.FatalLevel: return severity.Fatal case logrus.ErrorLevel:
diff --git a/event/adapter/logrus/logrus_test.go b/event/adapter/logrus/logrus_test.go index babc686..8b1f98a 100644 --- a/event/adapter/logrus/logrus_test.go +++ b/event/adapter/logrus/logrus_test.go
@@ -32,7 +32,7 @@ Kind: event.LogKind, Message: "mess", Labels: []event.Label{ - severity.Info, + severity.Info.Label(), keys.Value("traceID").Of(17), keys.Value("resource").Of("R"), }, @@ -40,7 +40,7 @@ // logrus fields are stored in a map, so we have to sort to overcome map // iteration indeterminacy. less := func(a, b event.Label) bool { return a.Name < b.Name } - if diff := cmp.Diff(want, th.Got, cmpopts.SortSlices(less), cmpopts.IgnoreFields(event.Event{}, "At")); diff != "" { + if diff := cmp.Diff(want, th.Got, cmpopts.SortSlices(less), eventtest.CmpOption()); diff != "" { t.Errorf("mismatch (-want, +got):\n%s", diff) } }
diff --git a/event/adapter/zap/zap.go b/event/adapter/zap/zap.go index 22304dd..e73e45d 100644 --- a/event/adapter/zap/zap.go +++ b/event/adapter/zap/zap.go
@@ -27,15 +27,14 @@ ) type core struct { - builder event.Builder // never delivered, only cloned + ctx context.Context + labels []event.Label } var _ zapcore.Core = (*core)(nil) func NewCore(ctx context.Context) zapcore.Core { - return &core{ - builder: event.To(ctx), - } + return &core{ctx: ctx} } func (c *core) Enabled(level zapcore.Level) bool { @@ -44,25 +43,37 @@ func (c *core) With(fields []zapcore.Field) zapcore.Core { c2 := *c - c2.builder = c2.builder.Clone() - addLabels(c2.builder, fields) + if len(fields) > 0 { + c2.labels = make([]event.Label, len(c.labels), len(c.labels)+len(fields)) + copy(c2.labels, c.labels) + for _, f := range fields { + c2.labels = append(c2.labels, newLabel(f)) + } + } return &c2 } func (c *core) Write(e zapcore.Entry, fs []zapcore.Field) error { - b := c.builder.Clone(). - At(e.Time). - With(convertLevel(e.Level)). - Name(e.LoggerName) + ev := event.New(c.ctx, event.LogKind) + if ev == nil { + return nil + } + ev.At = e.Time + ev.Labels = append(ev.Labels, c.labels...) + ev.Labels = append(ev.Labels, convertLevel(e.Level).Label()) + ev.Name = e.LoggerName // TODO: add these additional labels more efficiently. if e.Stack != "" { - b.With(keys.String("stack").Of(e.Stack)) + ev.Labels = append(ev.Labels, keys.String("stack").Of(e.Stack)) } if e.Caller.Defined { - b.With(keys.String("caller").Of(e.Caller.String())) + ev.Labels = append(ev.Labels, keys.String("caller").Of(e.Caller.String())) } - addLabels(b, fs) - b.Log(e.Message) + for _, f := range fs { + ev.Labels = append(ev.Labels, newLabel(f)) + } + ev.Message = e.Message + ev.Deliver() return nil } @@ -72,14 +83,6 @@ func (c *core) Sync() error { return nil } -// addLabels creates a new []event.Label with the given labels followed by the -// labels constructed from fields. -func addLabels(b event.Builder, fields []zap.Field) { - for i := 0; i < len(fields); i++ { - b.With(newLabel(fields[i])) - } -} - func newLabel(f zap.Field) event.Label { switch f.Type { case zapcore.ArrayMarshalerType, zapcore.ObjectMarshalerType, zapcore.BinaryType, zapcore.ByteStringType, @@ -149,7 +152,7 @@ return stringer.(fmt.Stringer).String() } -func convertLevel(level zapcore.Level) event.Label { +func convertLevel(level zapcore.Level) severity.Level { switch level { case zapcore.DebugLevel: return severity.Debug @@ -160,9 +163,9 @@ case zapcore.ErrorLevel: return severity.Error case zapcore.DPanicLevel: - return severity.Of(severity.FatalLevel - 1) + return severity.Fatal - 1 case zapcore.PanicLevel: - return severity.Of(severity.FatalLevel + 1) + return severity.Fatal + 1 case zapcore.FatalLevel: return severity.Fatal default:
diff --git a/event/adapter/zap/zap_test.go b/event/adapter/zap/zap_test.go index 4ae028a..870fc56 100644 --- a/event/adapter/zap/zap_test.go +++ b/event/adapter/zap/zap_test.go
@@ -10,7 +10,6 @@ "testing" "github.com/google/go-cmp/cmp" - "github.com/google/go-cmp/cmp/cmpopts" "go.uber.org/zap" "golang.org/x/exp/event" ezap "golang.org/x/exp/event/adapter/zap" @@ -31,11 +30,11 @@ Labels: []event.Label{ keys.Int64("traceID").Of(17), keys.String("resource").Of("R"), - severity.Info, + severity.Info.Label(), keys.Float64("pi").Of(3.14), }, }} - if diff := cmp.Diff(want, h.Got, cmpopts.IgnoreFields(event.Event{}, "At")); diff != "" { + if diff := cmp.Diff(want, h.Got, eventtest.CmpOption()); diff != "" { t.Errorf("mismatch (-want, +got):\n%s", diff) } }
diff --git a/event/alloc_test.go b/event/alloc_test.go index 070dfdf..80ce051 100644 --- a/event/alloc_test.go +++ b/event/alloc_test.go
@@ -23,8 +23,7 @@ e := event.NewExporter(logfmt.NewHandler(ioutil.Discard), &event.ExporterOptions{EnableNamespaces: true}) ctx := event.WithExporter(context.Background(), e) allocs := int(testing.AllocsPerRun(5, func() { - event.To(ctx).With(aString).With(anInt).Log("message1") - event.To(ctx).With(aString, anInt).Log("message2") + event.Log(ctx, "message", aString, anInt) })) if allocs != 0 { t.Errorf("Got %d allocs, expect 0", allocs)
diff --git a/event/bench_test.go b/event/bench_test.go index 0a07dea..8cc1206 100644 --- a/event/bench_test.go +++ b/event/bench_test.go
@@ -26,12 +26,12 @@ eventLog = eventtest.Hooks{ AStart: func(ctx context.Context, a int) context.Context { - event.To(ctx).With(severity.Info).With(aValue.Of(a)).Log(eventtest.A.Msg) + severity.Info.Log(ctx, eventtest.A.Msg, aValue.Of(a)) return ctx }, AEnd: func(ctx context.Context) {}, BStart: func(ctx context.Context, b string) context.Context { - event.To(ctx).With(severity.Info).With(bValue.Of(b)).Log(eventtest.B.Msg) + severity.Info.Log(ctx, eventtest.B.Msg, bValue.Of(b)) return ctx }, BEnd: func(ctx context.Context) {}, @@ -39,12 +39,12 @@ eventLogf = eventtest.Hooks{ AStart: func(ctx context.Context, a int) context.Context { - event.To(ctx).With(severity.Info).Logf(eventtest.A.Msgf, a) + severity.Info.Logf(ctx, eventtest.A.Msgf, a) return ctx }, AEnd: func(ctx context.Context) {}, BStart: func(ctx context.Context, b string) context.Context { - event.To(ctx).With(severity.Info).Logf(eventtest.B.Msgf, b) + severity.Info.Logf(ctx, eventtest.B.Msgf, b) return ctx }, BEnd: func(ctx context.Context) {}, @@ -52,33 +52,31 @@ eventTrace = eventtest.Hooks{ AStart: func(ctx context.Context, a int) context.Context { - ctx, _ = event.To(ctx).Start(eventtest.A.Msg) - event.To(ctx).With(aValue.Of(a)).Annotate() + ctx = event.Start(ctx, eventtest.A.Msg, aValue.Of(a)) return ctx }, AEnd: func(ctx context.Context) { - event.To(ctx).End() + event.End(ctx) }, BStart: func(ctx context.Context, b string) context.Context { - ctx, _ = event.To(ctx).Start(eventtest.B.Msg) - event.To(ctx).With(bValue.Of(b)).Annotate() + ctx = event.Start(ctx, eventtest.B.Msg, bValue.Of(b)) return ctx }, BEnd: func(ctx context.Context) { - event.To(ctx).End() + event.End(ctx) }, } eventMetric = eventtest.Hooks{ AStart: func(ctx context.Context, a int) context.Context { - event.To(ctx).With(aStat.Of(a)).Metric(gauge.Record(1)) - event.To(ctx).With(aCount.Of(1)).Metric(gauge.Record(1)) + gauge.Record(ctx, 1, aStat.Of(a)) + gauge.Record(ctx, 1, aCount.Of(1)) return ctx }, AEnd: func(ctx context.Context) {}, BStart: func(ctx context.Context, b string) context.Context { - event.To(ctx).With(bLength.Of(len(b))).Metric(gauge.Record(1)) - event.To(ctx).With(bCount.Of(1)).Metric(gauge.Record(1)) + gauge.Record(ctx, 1, bLength.Of(len(b))) + gauge.Record(ctx, 1, bCount.Of(1)) return ctx }, BEnd: func(ctx context.Context) {}, @@ -90,7 +88,7 @@ } func eventNoop() context.Context { - return event.WithExporter(context.Background(), event.NewExporter(event.NopHandler{}, eventtest.ExporterOptions())) + return event.WithExporter(context.Background(), event.NewExporter(nopHandler{}, eventtest.ExporterOptions())) } func eventPrint(w io.Writer) context.Context { @@ -103,6 +101,10 @@ return event.WithExporter(context.Background(), event.NewExporter(logfmt.NewHandler(w), opts)) } +type nopHandler struct{} + +func (nopHandler) Event(ctx context.Context, _ *event.Event) context.Context { return ctx } + func BenchmarkEventLogNoExporter(b *testing.B) { eventtest.RunBenchmark(b, eventNoExporter(), eventLog) }
diff --git a/event/builder.go b/event/builder.go deleted file mode 100644 index 1452dcf..0000000 --- a/event/builder.go +++ /dev/null
@@ -1,303 +0,0 @@ -// Copyright 2020 The Go Authors. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE file. - -// +build !disable_events - -package event - -import ( - "context" - "fmt" - "sync" - "sync/atomic" - "time" -) - -// Builder is a fluent builder for construction of new events. -type Builder struct { - builderCommon -} - -type builderCommon struct { - ctx context.Context - data *builder - builderID uint64 // equals data.id if all is well -} - -// preallocateLabels controls the space reserved for labels in a builder. -// Storing the first few labels directly in builders can avoid an allocation at -// all for the very common cases of simple events. The length needs to be large -// enough to cope with the majority of events but no so large as to cause undue -// stack pressure. -const preallocateLabels = 6 - -type builder struct { - exporter *Exporter - Event Event - labels [preallocateLabels]Label - id uint64 - parentStart time.Time -} - -var builderPool = sync.Pool{New: func() interface{} { return &builder{} }} - -// To initializes a builder from the values stored in a context. -func To(ctx context.Context) Builder { - b := Builder{builderCommon{ctx: ctx}} - b.data = newBuilder(ctx) - if b.data != nil { - b.builderID = b.data.id - } - return b -} - -var builderID uint64 // atomic - -func newBuilder(ctx context.Context) *builder { - exporter, parent, parentStart := FromContext(ctx) - if exporter == nil { - return nil - } - b := allocBuilder() - b.exporter = exporter - b.parentStart = parentStart - b.Event.Labels = b.labels[:0] - b.Event.Parent = parent - return b -} - -func allocBuilder() *builder { - b := builderPool.Get().(*builder) - b.id = atomic.AddUint64(&builderID, 1) - return b -} - -// Clone returns a copy of this builder. -// The two copies can be independently delivered. -func (b Builder) Clone() Builder { - return Builder{b.clone()} -} - -func (b builderCommon) clone() builderCommon { - if b.data == nil { - return b - } - bb := allocBuilder() - bbid := bb.id - clone := builderCommon{ctx: b.ctx, data: bb, builderID: bb.id} - *clone.data = *b.data - clone.data.id = bbid - if len(b.data.Event.Labels) == 0 || &b.data.labels[0] == &b.data.Event.Labels[0] { - clone.data.Event.Labels = clone.data.labels[:len(b.data.Event.Labels)] - } else { - clone.data.Event.Labels = make([]Label, len(b.data.Event.Labels)) - copy(clone.data.Event.Labels, b.data.Event.Labels) - } - return clone -} - -func (b Builder) Name(name string) Builder { - if b.data != nil { - b.data.Event.Name = name - } - return b -} - -func (b Builder) Error(err error) Builder { - if b.data != nil { - b.data.Event.Error = err - } - return b -} - -func (b builderCommon) addLabel(label Label) { - if b.data != nil { - checkValid(b.data, b.builderID) - } -} - -// With adds all the supplied labels to the event being constructed. -func (b Builder) With(labels ...Label) Builder { - if b.data == nil || len(labels) == 0 { - return b - } - checkValid(b.data, b.builderID) - b.data.Event.Labels = append(b.data.Event.Labels, labels...) - return b -} - -func (b Builder) At(t time.Time) Builder { - b.setAt(t) - return b -} - -func (b builderCommon) setAt(t time.Time) { - if b.data != nil { - checkValid(b.data, b.builderID) - b.data.Event.At = t - } -} - -func (b Builder) Namespace(ns string) Builder { - b.setNamespace(ns) - return b -} - -func (b builderCommon) setNamespace(ns string) { - if b.data != nil { - checkValid(b.data, b.builderID) - b.data.Event.Namespace = ns - } -} - -// Log is a helper that calls Deliver with LogKind. -func (b Builder) Log(message string) { - if b.data == nil { - return - } - checkValid(b.data, b.builderID) - if b.data.exporter.loggingEnabled() { - b.data.exporter.mu.Lock() - defer b.data.exporter.mu.Unlock() - b.data.Event.Kind = LogKind - b.data.Event.Message = message - b.data.exporter.prepare(&b.data.Event) - b.data.exporter.handler.Log(b.ctx, &b.data.Event) - } - b.done() -} - -// Logf is a helper that uses fmt.Sprint to build the message and then -// calls Deliver with LogKind. -func (b Builder) Logf(template string, args ...interface{}) { - if b.data == nil { - return - } - checkValid(b.data, b.builderID) - if b.data.exporter.loggingEnabled() { - message := fmt.Sprintf(template, args...) - // Duplicate code from Log so Exporter.deliver's invocation of runtime.Callers is correct. - b.data.exporter.mu.Lock() - defer b.data.exporter.mu.Unlock() - b.data.Event.Kind = LogKind - b.data.Event.Message = message - b.data.exporter.prepare(&b.data.Event) - b.data.exporter.handler.Log(b.ctx, &b.data.Event) - } - b.done() -} - -func (b Builder) Metric(mv MetricValue) { - if b.data == nil { - return - } - checkValid(b.data, b.builderID) - if b.data.exporter.metricsEnabled() { - b.data.exporter.mu.Lock() - defer b.data.exporter.mu.Unlock() - if b.data.Event.Namespace == "" { - b.data.Event.Namespace = mv.m.Descriptor().Namespace() - } - b.data.Event.Labels = append(b.data.Event.Labels, MetricVal.Of(mv.v), MetricKey.Of(mv.m)) - b.data.Event.Kind = MetricKind - b.data.exporter.prepare(&b.data.Event) - b.data.exporter.handler.Metric(b.ctx, &b.data.Event) - } - b.done() -} - -// Annotate is a helper that calls Deliver with AnnotateKind. -func (b Builder) Annotate() { - if b.data == nil { - return - } - checkValid(b.data, b.builderID) - if b.data.exporter.annotationsEnabled() { - b.data.exporter.mu.Lock() - defer b.data.exporter.mu.Unlock() - b.data.exporter.prepare(&b.data.Event) - b.data.exporter.handler.Annotate(b.ctx, &b.data.Event) - } - b.done() -} - -// End is a helper that calls Deliver with EndKind. -func (b Builder) End() { - if b.data == nil { - return - } - checkValid(b.data, b.builderID) - if b.data.exporter.tracingEnabled() { - // If there is a DurationMetric label, emit a Metric event - // with the time since Start was called. - if v, ok := DurationMetric.Find(&b.data.Event); ok { - m := v.(*Duration) - b.Clone().Metric(m.Record(time.Since(b.data.parentStart))) - } - b.data.exporter.mu.Lock() - defer b.data.exporter.mu.Unlock() - b.data.Event.Kind = TraceKind - b.data.exporter.prepare(&b.data.Event) - b.data.exporter.handler.End(b.ctx, &b.data.Event) - } - b.done() -} - -// Event returns a copy of the event currently being built. -func (b Builder) Event() *Event { - checkValid(b.data, b.builderID) - clone := b.data.Event - if len(b.data.Event.Labels) > 0 { - clone.Labels = make([]Label, len(b.data.Event.Labels)) - copy(clone.Labels, b.data.Event.Labels) - } - return &clone -} - -func (b builderCommon) done() { - *b.data = builder{} - builderPool.Put(b.data) -} - -// Start delivers a start event with the given name and labels. -// Its second return value is a Builder whose End method can be -// called to deliver the matching End event. -// (It is also fine to ignore the Builder.) -// All events created from the returned context will have this start event -// as their parent. -func (b Builder) Start(name string) (context.Context, Builder) { - if b.data == nil { - return b.ctx, Builder{} - } - checkValid(b.data, b.builderID) - ctx := b.ctx - var endBuilder Builder - if b.data.exporter.tracingEnabled() { - b.data.exporter.mu.Lock() - defer b.data.exporter.mu.Unlock() - b.data.exporter.lastEvent++ - traceID := b.data.exporter.lastEvent - // create the end builder - endBuilder = b.Clone() - endBuilder.data.Event.Parent = traceID - b.data.Event.Kind = TraceKind - b.data.Event.TraceID = traceID - b.data.exporter.prepare(&b.data.Event) - // and now deliver the start event - b.data.Event.Name = name - now := time.Now() - ctx = newContext(ctx, b.data.exporter, traceID, now) - ctx = b.data.exporter.handler.Start(ctx, &b.data.Event) - endBuilder.data.parentStart = now - endBuilder.ctx = ctx - } - b.done() - return ctx, endBuilder -} - -func checkValid(b *builder, wantID uint64) { - if b.exporter == nil || b.id != wantID { - panic("Builder already delivered an event; missing call to Clone") - } -}
diff --git a/event/builder_test.go b/event/builder_test.go deleted file mode 100644 index c467adb..0000000 --- a/event/builder_test.go +++ /dev/null
@@ -1,194 +0,0 @@ -// Copyright 2020 The Go Authors. All rights reserved. -// Use of this source code is governed by a BSD-style -// license that can be found in the LICENSE file. - -// +build !disable_events - -package event_test - -import ( - "context" - "fmt" - "strings" - "testing" - "time" - - "github.com/google/go-cmp/cmp" - "golang.org/x/exp/event" - "golang.org/x/exp/event/keys" -) - -func TestClone(t *testing.T) { - var labels []event.Label - for i := 0; i < 5; i++ { // one greater than len(Builder.labels) - labels = append(labels, keys.Int(fmt.Sprintf("l%d", i)).Of(i)) - } - - ctx := event.WithExporter(context.Background(), event.NewExporter(event.NopHandler{}, nil)) - b1 := event.To(ctx) - b1.With(labels[0]).With(labels[1]) - check(t, b1, labels[:2]) - b2 := b1.Clone() - check(t, b1, labels[:2]) - check(t, b2, labels[:2]) - - b2.With(labels[2]) - check(t, b1, labels[:2]) - check(t, b2, labels[:3]) - - // Force a new backing array for b.Event.Labels. - for i := 3; i < len(labels); i++ { - b2.With(labels[i]) - } - check(t, b1, labels[:2]) - check(t, b2, labels) - - b2.Log("") // put b2 back in the pool. - b2 = event.To(ctx) - check(t, b1, labels[:2]) - check(t, b2, []event.Label{}) - - b2.With(labels[3]).With(labels[4]) - check(t, b1, labels[:2]) - check(t, b2, labels[3:5]) -} - -func check(t *testing.T, b event.Builder, want []event.Label) { - t.Helper() - if got := b.Event().Labels; !cmp.Equal(got, want, cmp.Comparer(valueEqual)) { - t.Fatalf("got %v, want %v", got, want) - } -} - -func valueEqual(l1, l2 event.Value) bool { - return fmt.Sprint(l1) == fmt.Sprint(l2) -} - -func TestTraceBuilder(t *testing.T) { - // Verify that the context returned from the handler is also returned from Start, - // and is the context passed to End. - ctx := event.WithExporter(context.Background(), event.NewExporter(&testTraceHandler{t: t}, nil)) - ctx, eb := event.To(ctx).Start("s") - val := ctx.Value("x") - if val != 1 { - t.Fatal("context not returned from Start") - } - eb.End() -} - -type testTraceHandler struct { - event.NopHandler - t *testing.T -} - -func (*testTraceHandler) Start(ctx context.Context, _ *event.Event) context.Context { - return context.WithValue(ctx, "x", 1) -} - -func (t *testTraceHandler) End(ctx context.Context, _ *event.Event) { - val := ctx.Value("x") - if val != 1 { - t.t.Fatal("Start context not passed to End") - } -} - -func TestFailToClone(t *testing.T) { - ctx := event.WithExporter(context.Background(), event.NewExporter(event.NopHandler{}, nil)) - - catch := func(f func()) { - defer func() { - r := recover() - if r == nil { - t.Error("expected panic, did not get one") - return - } - got, ok := r.(string) - if !ok || !strings.Contains(got, "Clone") { - t.Errorf("got panic(%v), want string with 'Clone'", r) - } - }() - - f() - } - - catch(func() { - b1 := event.To(ctx) - b1.Log("msg1") - // Reuse of Builder without Clone; b1.data has been cleared. - b1.Log("msg2") - }) - - catch(func() { - b1 := event.To(ctx) - b1.Log("msg1") - _ = event.To(ctx) // re-allocate the builder - // b1.data is populated, but with the wrong information. - b1.Log("msg2") - }) -} - -func TestTraceDuration(t *testing.T) { - // Verify that a trace can can emit a latency metric. - dur := event.NewDuration("test", "") - want := 200 * time.Millisecond - - check := func(t *testing.T, h *testTraceDurationHandler) { - if !h.got.HasValue() { - t.Fatal("no metric value") - } - got := h.got.Duration().Round(50 * time.Millisecond) - if got != want { - t.Fatalf("got %s, want %s", got, want) - } - } - - t.Run("returned builder", func(t *testing.T) { - h := &testTraceDurationHandler{} - ctx := event.WithExporter(context.Background(), event.NewExporter(h, nil)) - ctx, eb := event.To(ctx).With(event.DurationMetric.Of(dur)).Start("s") - time.Sleep(want) - eb.End() - check(t, h) - }) - t.Run("separate builder", func(t *testing.T) { - h := &testTraceDurationHandler{} - ctx := event.WithExporter(context.Background(), event.NewExporter(h, nil)) - ctx, _ = event.To(ctx).Start("s") - time.Sleep(want) - event.To(ctx).With(event.DurationMetric.Of(dur)).End() - check(t, h) - }) -} - -type testTraceDurationHandler struct { - event.NopHandler - got event.Value -} - -func (t *testTraceDurationHandler) Metric(ctx context.Context, e *event.Event) { - t.got, _ = event.MetricVal.Find(e) -} - -func BenchmarkBuildContext(b *testing.B) { - // How long does it take to deliver an event from a nested context? - c := event.NewCounter("c", "") - for _, depth := range []int{1, 5, 7, 10} { - b.Run(fmt.Sprintf("depth %d", depth), func(b *testing.B) { - ctx := event.WithExporter(context.Background(), event.NewExporter(event.NopHandler{}, nil)) - for i := 0; i < depth; i++ { - ctx = context.WithValue(ctx, i, i) - } - b.Run("direct", func(b *testing.B) { - for i := 0; i < b.N; i++ { - event.To(ctx).Name("foo").Metric(c.Record(1)) - } - }) - b.Run("cloned", func(b *testing.B) { - bu := event.To(ctx) - for i := 0; i < b.N; i++ { - bu.Clone().Name("foo").Metric(c.Record(1)) - } - }) - }) - } -}
diff --git a/event/common.go b/event/common.go index 4eb9ea0..b6876e3 100644 --- a/event/common.go +++ b/event/common.go
@@ -4,6 +4,12 @@ package event +import ( + "context" + "fmt" + "sync/atomic" +) + const ( MetricKey = interfaceKey("metric") MetricVal = valueKey("metricValue") @@ -17,7 +23,8 @@ LogKind MetricKind - TraceKind + StartKind + EndKind ) type ( @@ -25,13 +32,60 @@ interfaceKey string ) -func (k valueKey) Of(v Value) Label { - return Label{Name: string(k), Value: v} +func Log(ctx context.Context, msg string, labels ...Label) { + ev := New(ctx, LogKind) + if ev != nil { + ev.Labels = append(ev.Labels, labels...) + ev.Message = msg + ev.Deliver() + } } -func (k valueKey) Matches(ev *Event) bool { - _, found := k.Find(ev) - return found +func Logf(ctx context.Context, msg string, args ...interface{}) { + ev := New(ctx, LogKind) + if ev != nil { + ev.Message = fmt.Sprintf(msg, args...) + ev.Deliver() + } +} + +func Annotate(ctx context.Context, labels ...Label) { + ev := New(ctx, 0) + if ev != nil { + ev.Labels = append(ev.Labels, labels...) + ev.Deliver() + } +} + +func Start(ctx context.Context, name string, labels ...Label) context.Context { + ev := New(ctx, StartKind) + if ev != nil { + ev.Labels = append(ev.Labels, labels...) + ev.Name = name + ev.TraceID = atomic.AddUint64(&ev.target.exporter.lastEvent, 1) + ev.target.exporter.prepare(ev) + ev.ctx = newContext(ev.ctx, ev.target.exporter, ev.TraceID, ev.At) + ctx = ev.Deliver() + } + return ctx +} + +func End(ctx context.Context, labels ...Label) { + ev := New(ctx, EndKind) + if ev != nil { + ev.Labels = append(ev.Labels, labels...) + ev.target.exporter.prepare(ev) + // this was an end event, do we need to send a duration? + if v, ok := DurationMetric.Find(ev); ok { + //TODO: do we want the rest of the values from the end event? + v.(*Duration).Record(ctx, ev.At.Sub(ev.target.startTime)) + } + ev.Deliver() + } +} + +func (k valueKey) Of(v Value) Label { + return Label{Name: string(k), Value: v} } func (k valueKey) Find(ev *Event) (Value, bool) { @@ -42,11 +96,6 @@ return Label{Name: string(k), Value: ValueOf(v)} } -func (k interfaceKey) Matches(ev *Event) bool { - _, found := k.Find(ev) - return found -} - func (k interfaceKey) Find(ev *Event) (interface{}, bool) { v, ok := lookupValue(string(k), ev.Labels) if !ok {
diff --git a/event/common_test.go b/event/common_test.go index d104024..852da43 100644 --- a/event/common_test.go +++ b/event/common_test.go
@@ -11,6 +11,7 @@ "golang.org/x/exp/event" "golang.org/x/exp/event/eventtest" + "golang.org/x/exp/event/keys" ) func TestCommon(t *testing.T) { @@ -20,27 +21,32 @@ const simple = "simple message" const trace = "a trace" - event.To(ctx).Log(simple) + event.Log(ctx, simple) checkMessage(t, h, "Log", simple) checkName(t, h, "Log", "") h.Reset() - event.To(ctx).Metric(m.Record(3)) + event.Logf(ctx, "logf %s message", "to") + checkMessage(t, h, "Logf", "logf to message") + checkName(t, h, "Logf", "") + h.Reset() + + m.Record(ctx, 3) checkMessage(t, h, "Metric", "") checkName(t, h, "Metric", "") h.Reset() - event.To(ctx).Annotate() + event.Annotate(ctx, keys.String("").Of("")) checkMessage(t, h, "Annotate", "") checkName(t, h, "Annotate", "") h.Reset() - _, eb := event.To(ctx).Start(trace) + ctx = event.Start(ctx, trace) checkMessage(t, h, "Start", "") checkName(t, h, "Start", trace) h.Reset() - eb.End() + event.End(ctx) checkMessage(t, h, "End", "") checkName(t, h, "End", "") }
diff --git a/event/disabled.go b/event/disabled.go index 77cbe75..20019ca 100644 --- a/event/disabled.go +++ b/event/disabled.go
@@ -20,8 +20,8 @@ func To(ctx context.Context) Builder { return Builder{} } func (b Builder) Clone() Builder { return b } -func (b Builder) With(label Label) Builder { return b } -func (b Builder) WithAll(labels ...Label) Builder { return b } +func (b Builder) Label(label Label) Builder { return b } +func (b Builder) Labels(labels ...Label) Builder { return b } func (b Builder) Log(message string) {} func (b Builder) Logf(template string, args ...interface{}) {} func (b Builder) Metric() {} @@ -35,6 +35,6 @@ func newContext(ctx context.Context, exporter *Exporter, parent uint64) context.Context { return ctx } -func FromContext(ctx context.Context) (*Exporter, uint64) { return nil, 0 } +func FromContext(ctx context.Context) *Target { return nil } func setDefaultExporter(e *Exporter) {}
diff --git a/event/event.go b/event/event.go index 369bcc5..b0718ee 100644 --- a/event/event.go +++ b/event/event.go
@@ -6,6 +6,7 @@ import ( "context" + "sync" "time" ) @@ -21,27 +22,26 @@ Name string Error error Labels []Label + + ctx context.Context + target *target + labels [preallocateLabels]Label } // Handler is a the type for something that handles events as they occur. type Handler interface { - // Log indicates a logging event. - Log(context.Context, *Event) - // Metric indicates a metric record event. - Metric(context.Context, *Event) - // Annotate reports label values at a point in time. - Annotate(context.Context, *Event) - // Start indicates a trace start event. - Start(context.Context, *Event) context.Context - // End indicates a trace end event. - End(context.Context, *Event) + // Event is called with each event. + Event(context.Context, *Event) context.Context } -// Matcher is the interface to something that can check if an event matches -// a condition. -type Matcher interface { - Matches(ev *Event) bool -} +// preallocateLabels controls the space reserved for labels in a builder. +// Storing the first few labels directly in builders can avoid an allocation at +// all for the very common cases of simple events. The length needs to be large +// enough to cope with the majority of events but no so large as to cause undue +// stack pressure. +const preallocateLabels = 6 + +var eventPool = sync.Pool{New: func() interface{} { return &Event{} }} // WithExporter returns a context with the exporter attached. // The exporter is called synchronously from the event call site, so it should @@ -56,23 +56,58 @@ setDefaultExporter(e) } -// Is uses the matcher to check if the event is a match. -// This is a simple helper to convert code like -// event.End.Matches(ev) -// to the more readable -// ev.Is(event.End) -func (ev *Event) Is(m Matcher) bool { - return m.Matches(ev) +// New prepares a new event. +// This is intended to avoid allocations in the steady state case, to do this +// it uses a pool of events. +// Events are returned to the pool when Deliver is called. Failure to call +// Deliver will exhaust the pool and cause allocations. +// It returns nil if there is no active exporter for this kind of event. +func New(ctx context.Context, kind Kind) *Event { + var t *target + if v, ok := ctx.Value(contextKey).(*target); ok { + t = v + } else { + t = getDefaultTarget() + } + if t == nil { + return nil + } + //TODO: we can change this to a much faster test + switch kind { + case LogKind: + if !t.exporter.loggingEnabled() { + return nil + } + case MetricKind: + if !t.exporter.metricsEnabled() { + return nil + } + case StartKind, EndKind: + if !t.exporter.tracingEnabled() { + return nil + } + } + ev := eventPool.Get().(*Event) + *ev = Event{ + ctx: ctx, + target: t, + Kind: kind, + Parent: t.parent, + } + ev.Labels = ev.labels[:0] + return ev } -// NopHandler is a handler that does nothing. It can be used for tests, or -// embedded in a struct to avoid having to implement all the Handler methods. -type NopHandler struct{} - -func (NopHandler) Log(context.Context, *Event) {} -func (NopHandler) Metric(context.Context, *Event) {} -func (NopHandler) Annotate(context.Context, *Event) {} -func (NopHandler) End(context.Context, *Event) {} -func (NopHandler) Start(ctx context.Context, _ *Event) context.Context { +// Deliver the event to the exporter that was found in New. +// This also returns the event to the pool, it is an error to do anything +// with the event after it is delivered. +func (ev *Event) Deliver() context.Context { + // get the event ready to send + ev.target.exporter.prepare(ev) + // now hold the lock while we deliver the event + ev.target.exporter.mu.Lock() + defer ev.target.exporter.mu.Unlock() + ctx := ev.target.exporter.handler.Event(ev.ctx, ev) + eventPool.Put(ev) return ctx }
diff --git a/event/event_test.go b/event/event_test.go index fe4501a..857c6c3 100644 --- a/event/event_test.go +++ b/event/event_test.go
@@ -8,6 +8,7 @@ import ( "context" + "fmt" "os" "strings" "testing" @@ -36,25 +37,25 @@ expect string }{{ name: "simple", - events: func(ctx context.Context) { event.To(ctx).Log("a message") }, + events: func(ctx context.Context) { event.Log(ctx, "a message") }, expect: `time="2020/03/05 14:27:48" msg="a message" `}, { name: "log 1", - events: func(ctx context.Context) { event.To(ctx).With(l1).Log("a message") }, + events: func(ctx context.Context) { event.Log(ctx, "a message", l1) }, expect: `time="2020/03/05 14:27:48" l1=1 msg="a message"`, }, { name: "log 2", - events: func(ctx context.Context) { event.To(ctx).With(l1).With(l2).Log("a message") }, + events: func(ctx context.Context) { event.Log(ctx, "a message", l1, l2) }, expect: `time="2020/03/05 14:27:48" l1=1 l2=2 msg="a message"`, }, { name: "log 3", - events: func(ctx context.Context) { event.To(ctx).With(l1).With(l2).With(l3).Log("a message") }, + events: func(ctx context.Context) { event.Log(ctx, "a message", l1, l2, l3) }, expect: `time="2020/03/05 14:27:48" l1=1 l2=2 l3=3 msg="a message"`, }, { name: "span", events: func(ctx context.Context) { - ctx, eb := event.To(ctx).Start("span") - eb.End() + ctx = event.Start(ctx, "span") + event.End(ctx) }, expect: ` time="2020/03/05 14:27:48" trace=1 name=span @@ -62,11 +63,11 @@ `}, { name: "span nested", events: func(ctx context.Context) { - ctx, eb := event.To(ctx).Start("parent") - defer eb.End() - child, eb2 := event.To(ctx).Start("child") - defer eb2.End() - event.To(child).Log("message") + ctx = event.Start(ctx, "parent") + defer event.End(ctx) + child := event.Start(ctx, "child") + defer event.End(child) + event.Log(child, "message") }, expect: ` time="2020/03/05 14:27:48" trace=1 name=parent @@ -76,32 +77,37 @@ time="2020/03/05 14:27:52" parent=1 end `}, { name: "counter", - events: func(ctx context.Context) { event.To(ctx).With(l1).Metric(counter.Record(2)) }, - expect: `time="2020/03/05 14:27:48" in="golang.org/x/exp/event_test" l1=1 metricValue=2 metric="Metric(\"golang.org/x/exp/event_test/hits\")"`, + events: func(ctx context.Context) { counter.Record(ctx, 2, l1) }, + expect: `time="2020/03/05 14:27:48" metricValue=2 metric="Metric(\"golang.org/x/exp/event_test/hits\")" l1=1`, }, { name: "gauge", - events: func(ctx context.Context) { event.To(ctx).With(l1).Metric(gauge.Record(98.6)) }, - expect: `time="2020/03/05 14:27:48" in="golang.org/x/exp/event_test" l1=1 metricValue=98.6 metric="Metric(\"golang.org/x/exp/event_test/temperature\")"`, + events: func(ctx context.Context) { gauge.Record(ctx, 98.6, l1) }, + expect: `time="2020/03/05 14:27:48" metricValue=98.6 metric="Metric(\"golang.org/x/exp/event_test/temperature\")" l1=1`, }, { name: "duration", events: func(ctx context.Context) { - event.To(ctx).With(l1).With(l2).Metric(latency.Record(3 * time.Second)) + latency.Record(ctx, 3*time.Second, l1, l2) }, - expect: `time="2020/03/05 14:27:48" in="golang.org/x/exp/event_test" l1=1 l2=2 metricValue=3s metric="Metric(\"golang.org/x/exp/event_test/latency\")"`, + expect: `time="2020/03/05 14:27:48" metricValue=3s metric="Metric(\"golang.org/x/exp/event_test/latency\")" l1=1 l2=2`, }, { name: "annotate", - events: func(ctx context.Context) { event.To(ctx).With(l1).Annotate() }, + events: func(ctx context.Context) { event.Annotate(ctx, l1) }, expect: `time="2020/03/05 14:27:48" l1=1`, }, { name: "annotate 2", - events: func(ctx context.Context) { event.To(ctx).With(l1).With(l2).Annotate() }, + events: func(ctx context.Context) { event.Annotate(ctx, l1, l2) }, expect: `time="2020/03/05 14:27:48" l1=1 l2=2`, }, { name: "multiple events", events: func(ctx context.Context) { - b := event.To(ctx) - b.Clone().With(keys.Int("myInt").Of(6)).Log("my event") - b.With(keys.String("myString").Of("some string value")).Log("string event") + /*TODO: this is supposed to be using a cached target + t := event.To(ctx) + p := event.Prototype{}.As(event.LogKind) + t.With(p).Int("myInt", 6).Message("my event").Send() + t.With(p).String("myString", "some string value").Message("string event").Send() + */ + event.Log(ctx, "my event", keys.Int("myInt").Of(6)) + event.Log(ctx, "string event", keys.String("myString").Of("some string value")) }, expect: ` time="2020/03/05 14:27:48" myInt=6 msg="my event" @@ -120,8 +126,8 @@ func ExampleLog() { ctx := event.WithExporter(context.Background(), event.NewExporter(logfmt.NewHandler(os.Stdout), eventtest.ExporterOptions())) - event.To(ctx).With(keys.Int("myInt").Of(6)).Log("my event") - event.To(ctx).With(keys.String("myString").Of("some string value")).Log("error event") + event.Log(ctx, "my event", keys.Int("myInt").Of(6)) + event.Log(ctx, "error event", keys.String("myString").Of("some string value")) // Output: // time="2020/03/05 14:27:48" myInt=6 msg="my event" // time="2020/03/05 14:27:49" myString="some string value" msg="error event" @@ -134,3 +140,105 @@ func TestLogEvent(t *testing.T) { eventtest.TestBenchmark(t, eventPrint, eventLog, eventtest.LogfmtOutput) } + +func TestTraceBuilder(t *testing.T) { + // Verify that the context returned from the handler is also returned from Start, + // and is the context passed to End. + ctx := event.WithExporter(context.Background(), event.NewExporter(&testTraceHandler{t: t}, eventtest.ExporterOptions())) + ctx = event.Start(ctx, "s") + val := ctx.Value("x") + if val != 1 { + t.Fatal("context not returned from Start") + } + event.End(ctx) +} + +type testTraceHandler struct { + t *testing.T +} + +func (t *testTraceHandler) Event(ctx context.Context, ev *event.Event) context.Context { + switch ev.Kind { + case event.StartKind: + return context.WithValue(ctx, "x", 1) + case event.EndKind: + val := ctx.Value("x") + if val != 1 { + t.t.Fatal("Start context not passed to End") + } + return ctx + default: + return ctx + } +} + +func TestTraceDuration(t *testing.T) { + // Verify that a trace can can emit a latency metric. + dur := event.NewDuration("test", "") + want := time.Second + + check := func(t *testing.T, h *testTraceDurationHandler) { + if !h.got.HasValue() { + t.Fatal("no metric value") + } + got := h.got.Duration() + if got != want { + t.Fatalf("got %s, want %s", got, want) + } + } + + t.Run("returned builder", func(t *testing.T) { + h := &testTraceDurationHandler{} + ctx := event.WithExporter(context.Background(), event.NewExporter(h, eventtest.ExporterOptions())) + ctx = event.Start(ctx, "s") + time.Sleep(want) + event.End(ctx, event.DurationMetric.Of(dur)) + check(t, h) + }) + //TODO: come back and fix this + t.Run("separate builder", func(t *testing.T) { + h := &testTraceDurationHandler{} + ctx := event.WithExporter(context.Background(), event.NewExporter(h, eventtest.ExporterOptions())) + ctx = event.Start(ctx, "s") + time.Sleep(want) + event.End(ctx, event.DurationMetric.Of(dur)) + check(t, h) + }) +} + +type testTraceDurationHandler struct { + got event.Value +} + +func (t *testTraceDurationHandler) Event(ctx context.Context, ev *event.Event) context.Context { + if ev.Kind == event.MetricKind { + t.got, _ = event.MetricVal.Find(ev) + } + return ctx +} + +func BenchmarkBuildContext(b *testing.B) { + // How long does it take to deliver an event from a nested context? + c := event.NewCounter("c", "") + for _, depth := range []int{1, 5, 7, 10} { + b.Run(fmt.Sprintf("depth %d", depth), func(b *testing.B) { + ctx := event.WithExporter(context.Background(), event.NewExporter(nopHandler{}, eventtest.ExporterOptions())) + for i := 0; i < depth; i++ { + ctx = context.WithValue(ctx, i, i) + } + b.Run("direct", func(b *testing.B) { + for i := 0; i < b.N; i++ { + c.Record(ctx, 1) + } + }) + /*TODO: work out how we do cached labels + b.Run("cloned", func(b *testing.B) { + bu := event.To(ctx) + for i := 0; i < b.N; i++ { + c.RecordTB(bu, 1).Name("foo").Send() + } + }) + */ + }) + } +}
diff --git a/event/eventtest/capture.go b/event/eventtest/capture.go index 12a4615..9510b3e 100644 --- a/event/eventtest/capture.go +++ b/event/eventtest/capture.go
@@ -10,40 +10,20 @@ Got []event.Event } -func (h *CaptureHandler) Log(ctx context.Context, ev *event.Event) { - h.event(ctx, ev) -} - -func (h *CaptureHandler) Metric(ctx context.Context, ev *event.Event) { - h.event(ctx, ev) -} - -func (h *CaptureHandler) Annotate(ctx context.Context, ev *event.Event) { - h.event(ctx, ev) -} - -func (h *CaptureHandler) Start(ctx context.Context, ev *event.Event) context.Context { - h.event(ctx, ev) +func (h *CaptureHandler) Event(ctx context.Context, ev *event.Event) context.Context { + h.Got = append(h.Got, *ev) + got := &h.Got[len(h.Got)-1] + got.Labels = make([]event.Label, len(ev.Labels)) + copy(got.Labels, ev.Labels) return ctx } -func (h *CaptureHandler) End(ctx context.Context, ev *event.Event) { - h.event(ctx, ev) -} - func (h *CaptureHandler) Reset() { if len(h.Got) > 0 { h.Got = h.Got[:0] } } -func (h *CaptureHandler) event(ctx context.Context, ev *event.Event) { - h.Got = append(h.Got, *ev) - got := &h.Got[len(h.Got)-1] - got.Labels = make([]event.Label, len(ev.Labels)) - copy(got.Labels, ev.Labels) -} - func NewCapture() (context.Context, *CaptureHandler) { h := &CaptureHandler{} ctx := event.WithExporter(context.Background(), event.NewExporter(h, ExporterOptions()))
diff --git a/event/eventtest/eventtest.go b/event/eventtest/eventtest.go index 8c1cdce..dd55a43 100644 --- a/event/eventtest/eventtest.go +++ b/event/eventtest/eventtest.go
@@ -15,6 +15,8 @@ "testing" "time" + "github.com/google/go-cmp/cmp" + "github.com/google/go-cmp/cmp/cmpopts" "golang.org/x/exp/event" "golang.org/x/exp/event/adapter/logfmt" ) @@ -30,31 +32,11 @@ printer logfmt.Printer } -func (h *testHandler) Log(ctx context.Context, ev *event.Event) { - h.event(ctx, ev) -} - -func (h *testHandler) Metric(ctx context.Context, ev *event.Event) { - h.event(ctx, ev) -} - -func (h *testHandler) Annotate(ctx context.Context, ev *event.Event) { - h.event(ctx, ev) -} - -func (h *testHandler) Start(ctx context.Context, ev *event.Event) context.Context { - h.event(ctx, ev) - return ctx -} - -func (h *testHandler) End(ctx context.Context, ev *event.Event) { - h.event(ctx, ev) -} - -func (h *testHandler) event(ctx context.Context, ev *event.Event) { +func (h *testHandler) Event(ctx context.Context, ev *event.Event) context.Context { //TODO: choose between stdout and stderr based on the event //TODO: decide if we should be calling h.tb.Fail() h.printer.Event(os.Stdout, ev) + return ctx } var InitialTime = func() time.Time { @@ -72,3 +54,7 @@ }, } } + +func CmpOption() cmp.Option { + return cmpopts.IgnoreFields(event.Event{}, "At", "ctx", "target", "labels") +}
diff --git a/event/export.go b/event/export.go index eee6a92..abfe673 100644 --- a/event/export.go +++ b/event/export.go
@@ -16,12 +16,20 @@ // Exporter synchronizes the delivery of events to handlers. type Exporter struct { - opts ExporterOptions + lastEvent uint64 // accessed using atomic, must be 64 bit aligned + opts ExporterOptions - mu sync.Mutex - handler Handler - lastEvent uint64 - sources sources + mu sync.Mutex + handler Handler + sources sources +} + +// target is a bound exporter. +// Normally you get a target by looking in the context using To. +type target struct { + exporter *Exporter + parent uint64 + startTime time.Time // for trace latency } type ExporterOptions struct { @@ -44,16 +52,8 @@ var contextKey interface{} = contextKeyType{} -// contextValue is stored by value in the context to track the exporter and -// current parent event. -type contextValue struct { - exporter *Exporter - parent uint64 - startTime time.Time // for trace latency -} - var ( - defaultExporter unsafe.Pointer + defaultTarget unsafe.Pointer ) // NewExporter creates an Exporter using the supplied handler and options. @@ -76,32 +76,27 @@ } func setDefaultExporter(e *Exporter) { - atomic.StorePointer(&defaultExporter, unsafe.Pointer(e)) + atomic.StorePointer(&defaultTarget, unsafe.Pointer(&target{exporter: e})) } -func getDefaultExporter() *Exporter { - return (*Exporter)(atomic.LoadPointer(&defaultExporter)) +func getDefaultTarget() *target { + return (*target)(atomic.LoadPointer(&defaultTarget)) } -func newContext(ctx context.Context, exporter *Exporter, parent uint64, t time.Time) context.Context { - return context.WithValue(ctx, contextKey, contextValue{exporter: exporter, parent: parent, startTime: t}) -} - -// FromContext returns the exporter, parentID and parent start time for the supplied context. -func FromContext(ctx context.Context) (*Exporter, uint64, time.Time) { - if v, ok := ctx.Value(contextKey).(contextValue); ok { - return v.exporter, v.parent, v.startTime +func newContext(ctx context.Context, exporter *Exporter, parent uint64, start time.Time) context.Context { + var t *target + if exporter != nil { + t = &target{exporter: exporter, parent: parent, startTime: start} } - return getDefaultExporter(), 0, time.Time{} + return context.WithValue(ctx, contextKey, t) } // prepare events before delivering to the underlying handler. -// The event will be assigned a new ID. +// it is safe to call this more than once (trace events have to call it early) // If the event does not have a timestamp, and the exporter has a Now function // then the timestamp will be updated. // If automatic namespaces are enabled and the event doesn't have a namespace, // one based on the caller's import path will be provided. -// prepare must be called with the export mutex held. func (e *Exporter) prepare(ev *Event) { if e.opts.Now != nil && ev.At.IsZero() { ev.At = e.opts.Now()
diff --git a/event/label.go b/event/label.go index 71c65fa..1593cf5 100644 --- a/event/label.go +++ b/event/label.go
@@ -166,7 +166,7 @@ hdr := (*reflect.SliceHeader)(unsafe.Pointer(&buf)) hdr.Data = uintptr(bp) hdr.Len = int(v.packed) - hdr.Cap = hdr.Len // TODO: is this safe? + hdr.Cap = hdr.Len return buf }
diff --git a/event/metric.go b/event/metric.go index a2611ac..143a5a3 100644 --- a/event/metric.go +++ b/event/metric.go
@@ -5,6 +5,7 @@ package event import ( + "context" "fmt" "time" ) @@ -37,8 +38,7 @@ panic("name cannot be empty") } return &MetricDescriptor{ - name: name, - // TODO: use the global callers, will also need a lock + name: name, namespace: scanStack().Space, description: description, } @@ -84,8 +84,13 @@ // Record converts its argument into a Value and returns a MetricValue with the // receiver and the value. It is intended to be used as an argument to // Builder.Metric. -func (c *Counter) Record(v uint64) MetricValue { - return MetricValue{c, Uint64Of(v)} +func (c *Counter) Record(ctx context.Context, v uint64, labels ...Label) { + ev := New(ctx, MetricKind) + if ev != nil { + record(ev, c, Uint64Of(v)) + ev.Labels = append(ev.Labels, labels...) + ev.Deliver() + } } // A FloatGauge records a single floating-point value that may go up or down. @@ -107,8 +112,13 @@ // Record converts its argument into a Value and returns a MetricValue with the // receiver and the value. It is intended to be used as an argument to // Builder.Metric. -func (g *FloatGauge) Record(v float64) MetricValue { - return MetricValue{g, Float64Of(v)} +func (g *FloatGauge) Record(ctx context.Context, v float64, labels ...Label) { + ev := New(ctx, MetricKind) + if ev != nil { + record(ev, g, Float64Of(v)) + ev.Labels = append(ev.Labels, labels...) + ev.Deliver() + } } // A Duration records a distribution of durations. @@ -130,8 +140,13 @@ // Record converts its argument into a Value and returns a MetricValue with the // receiver and the value. It is intended to be used as an argument to // Builder.Metric. -func (d *Duration) Record(v time.Duration) MetricValue { - return MetricValue{d, DurationOf(v)} +func (d *Duration) Record(ctx context.Context, v time.Duration, labels ...Label) { + ev := New(ctx, MetricKind) + if ev != nil { + record(ev, d, DurationOf(v)) + ev.Labels = append(ev.Labels, labels...) + ev.Deliver() + } } // An IntDistribution records a distribution of int64s. @@ -152,6 +167,15 @@ // Record converts its argument into a Value and returns a MetricValue with the // receiver and the value. It is intended to be used as an argument to // Builder.Metric. -func (d *IntDistribution) Record(v int64) MetricValue { - return MetricValue{d, Int64Of(v)} +func (d *IntDistribution) Record(ctx context.Context, v int64, labels ...Label) { + ev := New(ctx, MetricKind) + if ev != nil { + record(ev, d, Int64Of(v)) + ev.Labels = append(ev.Labels, labels...) + ev.Deliver() + } +} + +func record(ev *Event, m Metric, v Value) { + ev.Labels = append(ev.Labels, MetricVal.Of(v), MetricKey.Of(ValueOf(m))) }
diff --git a/event/namespace_test.go b/event/namespace_test.go index d3789c9..abab523 100644 --- a/event/namespace_test.go +++ b/event/namespace_test.go
@@ -17,7 +17,7 @@ func TestNamespace(t *testing.T) { var h nsHandler ctx := event.WithExporter(context.Background(), event.NewExporter(&h, &event.ExporterOptions{EnableNamespaces: true})) - event.To(ctx).Log("msg") + event.Log(ctx, "msg") if got, want := h.ns, thisImportPath; got != want { t.Errorf("got namespace %q, want, %q", got, want) } @@ -27,31 +27,11 @@ ns string } -func (h *nsHandler) Log(ctx context.Context, ev *event.Event) { - h.event(ctx, ev) -} - -func (h *nsHandler) Metric(ctx context.Context, ev *event.Event) { - h.event(ctx, ev) -} - -func (h *nsHandler) Annotate(ctx context.Context, ev *event.Event) { - h.event(ctx, ev) -} - -func (h *nsHandler) Start(ctx context.Context, ev *event.Event) context.Context { - h.event(ctx, ev) +func (h *nsHandler) Event(ctx context.Context, ev *event.Event) context.Context { + h.ns = ev.Namespace return ctx } -func (h *nsHandler) End(ctx context.Context, ev *event.Event) { - h.event(ctx, ev) -} - -func (h *nsHandler) event(event context.Context, e *event.Event) { - h.ns = e.Namespace -} - func BenchmarkRuntimeCallers(b *testing.B) { for i := 0; i < b.N; i++ { var pcs [1]uintptr
diff --git a/event/otel/trace.go b/event/otel/trace.go index 14f8533..2c43edf 100644 --- a/event/otel/trace.go +++ b/event/otel/trace.go
@@ -21,21 +21,22 @@ type spanKey struct{} -func (t *TraceHandler) Log(ctx context.Context, ev *event.Event) {} -func (t *TraceHandler) Annotate(ctx context.Context, ev *event.Event) {} -func (t *TraceHandler) Metric(ctx context.Context, ev *event.Event) {} -func (t *TraceHandler) Start(ctx context.Context, ev *event.Event) context.Context { - opts := labelsToSpanOptions(ev.Labels) - octx, span := t.tracer.Start(ctx, ev.Name, opts...) - return context.WithValue(octx, spanKey{}, span) -} - -func (t *TraceHandler) End(ctx context.Context, e *event.Event) { - span, ok := ctx.Value(spanKey{}).(trace.Span) - if !ok { - panic("End called on context with no span") +func (t *TraceHandler) Event(ctx context.Context, ev *event.Event) context.Context { + switch ev.Kind { + case event.StartKind: + opts := labelsToSpanOptions(ev.Labels) + octx, span := t.tracer.Start(ctx, ev.Name, opts...) + return context.WithValue(octx, spanKey{}, span) + case event.EndKind: + span, ok := ctx.Value(spanKey{}).(trace.Span) + if !ok { + panic("End called on context with no span") + } + span.End() + return ctx + default: + return ctx } - span.End() } func labelsToSpanOptions(ls []event.Label) []trace.SpanOption {
diff --git a/event/otel/trace_test.go b/event/otel/trace_test.go index c29f392..787b1ed 100644 --- a/event/otel/trace_test.go +++ b/event/otel/trace_test.go
@@ -95,9 +95,8 @@ ctx, span = s.tracer.Start(ctx, s.name) defer span.End() } else { - var eb event.Builder - ctx, eb = event.To(ctx).Start(s.name) - defer eb.End() + ctx = event.Start(ctx, s.name) + defer event.End(ctx) } for _, c := range s.children { c.apply(ctx)
diff --git a/event/severity/severity.go b/event/severity/severity.go index 66892b5..64e1441 100644 --- a/event/severity/severity.go +++ b/event/severity/severity.go
@@ -4,7 +4,12 @@ package severity -import "golang.org/x/exp/event" +import ( + "context" + "fmt" + + "golang.org/x/exp/event" +) // Level represents a severity level of an event. // The basic severity levels are designed to match the levels used in open telemetry. @@ -24,35 +29,20 @@ type Level uint64 const ( - TraceLevel = Level(1) - DebugLevel = Level(5) - InfoLevel = Level(9) - WarningLevel = Level(13) - ErrorLevel = Level(17) - FatalLevel = Level(21) - MaxLevel = Level(24) + Trace = Level(1) + Debug = Level(5) + Info = Level(9) + Warning = Level(13) + Error = Level(17) + Fatal = Level(21) + Max = Level(24) ) const Key = "level" -var ( - // Trace is an event.Label for trace level events. - Trace = Of(TraceLevel) - // Debug is an event.Label for debug level events. - Debug = Of(DebugLevel) - // Info is an event.Label for info level events. - Info = Of(InfoLevel) - // Warning is an event.Label for warning level events. - Warning = Of(WarningLevel) - // Error is an event.Label for error level events. - Error = Of(ErrorLevel) - // Fatal is an event.Label for fatal level events. - Fatal = Of(FatalLevel) -) - -// Of creates a new Label with this key and the supplied value. -func Of(v Level) event.Label { - return event.Label{Name: Key, Value: event.ValueOf(v)} +// Of creates a label for the level. +func (l Level) Label() event.Label { + return event.Label{Name: Key, Value: event.ValueOf(l)} } // From can be used to get a value from a Label. @@ -60,22 +50,41 @@ return t.Value.Interface().(Level) } +func (l Level) Log(ctx context.Context, msg string, labels ...event.Label) { + ev := event.New(ctx, event.LogKind) + if ev != nil { + ev.Labels = append(ev.Labels, l.Label()) + ev.Labels = append(ev.Labels, labels...) + ev.Message = msg + ev.Deliver() + } +} + +func (l Level) Logf(ctx context.Context, msg string, args ...interface{}) { + ev := event.New(ctx, event.LogKind) + if ev != nil { + ev.Labels = append(ev.Labels, l.Label()) + ev.Message = fmt.Sprintf(msg, args...) + ev.Deliver() + } +} + func (l Level) Class() Level { switch { - case l > MaxLevel: - return MaxLevel - case l > FatalLevel: - return FatalLevel - case l > ErrorLevel: - return ErrorLevel - case l > WarningLevel: - return WarningLevel - case l > DebugLevel: - return DebugLevel - case l > InfoLevel: - return InfoLevel - case l > TraceLevel: - return TraceLevel + case l > Max: + return Max + case l > Fatal: + return Fatal + case l > Error: + return Error + case l > Warning: + return Warning + case l > Debug: + return Debug + case l > Info: + return Info + case l > Trace: + return Trace default: return 0 } @@ -86,58 +95,58 @@ case 0: return "invalid" - case TraceLevel: + case Trace: return "trace" - case TraceLevel + 1: + case Trace + 1: return "trace2" - case TraceLevel + 2: + case Trace + 2: return "trace3" - case TraceLevel + 3: + case Trace + 3: return "trace4" - case DebugLevel: + case Debug: return "debug" - case DebugLevel + 1: + case Debug + 1: return "debug2" - case DebugLevel + 2: + case Debug + 2: return "debug3" - case DebugLevel + 3: + case Debug + 3: return "debug4" - case InfoLevel: + case Info: return "info" - case InfoLevel + 1: + case Info + 1: return "info2" - case InfoLevel + 2: + case Info + 2: return "info3" - case InfoLevel + 3: + case Info + 3: return "info4" - case WarningLevel: + case Warning: return "warning" - case WarningLevel + 1: + case Warning + 1: return "warning2" - case WarningLevel + 2: + case Warning + 2: return "warning3" - case WarningLevel + 3: + case Warning + 3: return "warning4" - case ErrorLevel: + case Error: return "error" - case ErrorLevel + 1: + case Error + 1: return "error2" - case ErrorLevel + 2: + case Error + 2: return "error3" - case ErrorLevel + 3: + case Error + 3: return "error4" - case FatalLevel: + case Fatal: return "fatal" - case FatalLevel + 1: + case Fatal + 1: return "fatal2" - case FatalLevel + 2: + case Fatal + 2: return "fatal3" - case FatalLevel + 3: + case Fatal + 3: return "fatal4" default: return "invalid"
diff --git a/event/severity/severity_test.go b/event/severity/severity_test.go index f115052..8825f23 100644 --- a/event/severity/severity_test.go +++ b/event/severity/severity_test.go
@@ -18,7 +18,6 @@ ) func TestPrint(t *testing.T) { - //TODO: print the textual form of severity ctx := context.Background() for _, test := range []struct { name string @@ -26,11 +25,11 @@ expect string }{{ name: "debug", - events: func(ctx context.Context) { event.To(ctx).With(severity.Debug).Log("a message") }, + events: func(ctx context.Context) { severity.Debug.Log(ctx, "a message") }, expect: `time="2020/03/05 14:27:48" level=debug msg="a message"`, }, { name: "info", - events: func(ctx context.Context) { event.To(ctx).With(severity.Info).Log("a message") }, + events: func(ctx context.Context) { severity.Info.Log(ctx, "a message") }, expect: `time="2020/03/05 14:27:48" level=info msg="a message"`}, } { buf := &strings.Builder{}
diff --git a/jsonrpc2/conn.go b/jsonrpc2/conn.go index cbc1558..1b26d3a 100644 --- a/jsonrpc2/conn.go +++ b/jsonrpc2/conn.go
@@ -12,6 +12,7 @@ "sync/atomic" "golang.org/x/exp/event" + "golang.org/x/exp/event/keys" errors "golang.org/x/xerrors" ) @@ -52,10 +53,10 @@ } type AsyncCall struct { - id ID - response chan *Response // the channel a response will be delivered on - resultBox chan asyncResult - endBuilder event.Builder // close the tracing span when all processing for the message is complete + id ID + response chan *Response // the channel a response will be delivered on + resultBox chan asyncResult + ctx context.Context } type asyncResult struct { @@ -65,11 +66,10 @@ // incoming is used to track an incoming request as it is being handled type incoming struct { - request *Request // the request being processed - baseCtx context.Context // a base context for the message processing - endBuilder event.Builder // builder's End method called when all processing for the message is complete - handleCtx context.Context // the context for handling the message, child of baseCtx - cancel func() // a function that cancels the handling context + request *Request // the request being processed + baseCtx context.Context // a base context for the message processing + handleCtx context.Context // the context for handling the message, child of baseCtx + cancel func() // a function that cancels the handling context } // Bind returns the options unmodified. @@ -124,12 +124,14 @@ if err != nil { return errors.Errorf("marshaling notify parameters: %v", err) } - b := event.To(ctx).With(Method.Of(method)) - b.Clone().Metric(Started.Record(1)) - ctx, endBuilder := b.With(RPCDirection.Of(Outbound)).Start(method) - err = c.write(ctx, notify) - event.To(ctx).With(Error.Of(err)).Metric(Finished.Record(1)) - endBuilder.End() + ctx = event.Start(ctx, method, RPCDirection.Of(Outbound)) + Started.Record(ctx, 1, Method.Of(method)) + var errLabel event.Label + if err = c.write(ctx, notify); err != nil { + errLabel = keys.Value("error").Of(err) + } + Finished.Record(ctx, 1, errLabel) + event.End(ctx) return err } @@ -150,10 +152,11 @@ result.resultBox <- asyncResult{err: errors.Errorf("marshaling call parameters: %w", err)} return result } - b := event.To(ctx).With(Method.Of(method)) - b.Clone().Metric(Started.Record(1)) - ctx, endBuilder := b.Clone().With(RPCDirection.Of(Outbound)).With(RPCID.Of(fmt.Sprintf("%q", result.id))).Start(method) - result.endBuilder = endBuilder + //TODO: rewrite this using the new target/prototype stuff + ctx = event.Start(ctx, method, + Method.Of(method), RPCDirection.Of(Outbound), RPCID.Of(fmt.Sprintf("%q", result.id))) + Started.Record(ctx, 1, Method.Of(method)) + result.ctx = ctx // We have to add ourselves to the pending map before we send, otherwise we // are racing the response. // rchan is buffered in case the response arrives without a listener. @@ -191,7 +194,7 @@ // The response will be unmarshaled from JSON into the result. func (a *AsyncCall) Await(ctx context.Context, result interface{}) error { status := "NONE" - defer a.endBuilder.With(StatusCode.Of(status)).End() + defer event.End(a.ctx, StatusCode.Of(status)) var r asyncResult select { case response := <-a.response: @@ -292,14 +295,14 @@ request: msg, } // add a span to the context for this request - b := event.To(ctx).With(Method.Of(msg.Method)).With(RPCDirection.Of(Inbound)) + var idLabel event.Label if msg.IsCall() { - b = b.With(RPCID.Of(fmt.Sprintf("%q", msg.ID))) + idLabel = RPCID.Of(fmt.Sprintf("%q", msg.ID)) } - entry.baseCtx, entry.endBuilder = b.Start(msg.Method) - b = event.To(entry.baseCtx).With(Method.Of(msg.Method)) - b.Clone().Metric(Started.Record(1)) - b.Metric(ReceivedBytes.Record(n)) + entry.baseCtx = event.Start(ctx, msg.Method, + Method.Of(msg.Method), RPCDirection.Of(Inbound), idLabel) + Started.Record(entry.baseCtx, 1, Method.Of(msg.Method)) + ReceivedBytes.Record(entry.baseCtx, n, Method.Of(msg.Method)) // in theory notifications cannot be cancelled, but we build them a cancel context anyway entry.handleCtx, entry.cancel = context.WithCancel(entry.baseCtx) // if the request is a call, add it to the incoming map so it can be @@ -412,7 +415,7 @@ if err := c.respond(entry, result, rerr); err != nil { // no way to propagate this error //TODO: should we do more than just log it? - event.To(entry.baseCtx).With(Error.Of(err)).Log("jsonrpc2 message delivery failed") + event.Log(entry.baseCtx, "jsonrpc2 message delivery failed", keys.Value("error").Of(err)) } } @@ -458,7 +461,7 @@ entry.cancel = nil } // mark the entire request processing as done - entry.endBuilder.With(StatusCode.Of(status)).End() + event.End(entry.baseCtx, StatusCode.Of(status)) return err } @@ -469,6 +472,6 @@ defer func() { c.writerBox <- writer }() n, err := writer.Write(ctx, msg) // TODO: get a method label in here somehow. - event.To(ctx).Metric(SentBytes.Record(n)) + SentBytes.Record(ctx, n) return err }
diff --git a/jsonrpc2/defs.go b/jsonrpc2/defs.go index f40800d..802a205 100644 --- a/jsonrpc2/defs.go +++ b/jsonrpc2/defs.go
@@ -13,7 +13,6 @@ Method = keys.String("method") RPCID = keys.String("id") RPCDirection = keys.String("direction") - Error = keys.Value("error") StatusCode = keys.String("status.code") )