event: detect failure to clone
If the user of a Builder forgets to call Clone and delivers a second
event, panic with a helpful message.
This does seem to slow down the no-op case:
> benchstat2 -C . bench.log
name old time/op new time/op delta
LogEventNoExporter-8 621ns ± 3% 613ns ± 1% -1.22% (p=0.000 n=19+18)
LogEventNoop-8 1.84µs ± 1% 2.04µs ± 2% +10.83% (p=0.000 n=17+19)
LogEventDiscard-8 10.7µs ± 3% 10.6µs ± 1% -0.86% (p=0.017 n=19+19)
LogEventfDiscard-8 16.4µs ± 3% 16.6µs ± 3% +1.12% (p=0.001 n=18+19)
TraceEventNoop-8 40.7µs ± 2% 41.0µs ± 3% ~ (p=0.119 n=18+20)
MetricEventNoop-8 18.2µs ± 2% 18.3µs ± 3% ~ (p=0.703 n=20+20)
Logrus-8 53.7µs ± 5% 53.8µs ± 3% ~ (p=0.779 n=20+20)
Logrusf-8 44.6µs ± 3% 45.2µs ± 5% +1.20% (p=0.046 n=19+20)
Baseline-8 278ns ± 2% 278ns ± 1% ~ (p=0.642 n=18+17)
LogStdlib-8 8.41µs ± 4% 8.39µs ± 2% ~ (p=0.767 n=19+19)
LogPrintf-8 13.0µs ± 2% 13.0µs ± 2% ~ (p=0.075 n=19+20)
LogZap-8 19.6µs ± 3% 19.6µs ± 3% ~ (p=0.390 n=19+19)
LogZapf-8 21.4µs ± 2% 21.5µs ± 2% ~ (p=0.208 n=19+17)
LogZerolog-8 7.46µs ± 2% 7.50µs ± 2% ~ (p=0.131 n=18+20)
LogZerologf-8 12.5µs ± 2% 12.6µs ± 3% ~ (p=0.430 n=18+19)
Change-Id: I94c571685c87681b64ce9a349b1e037ccdb4a888
Reviewed-on: https://go-review.googlesource.com/c/exp/+/323849
Trust: Jonathan Amsterdam <jba@google.com>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
Reviewed-by: Ian Cottrell <iancottrell@google.com>
diff --git a/event/builder.go b/event/builder.go
index 7a5f597..dda25f0 100644
--- a/event/builder.go
+++ b/event/builder.go
@@ -10,13 +10,15 @@
"context"
"fmt"
"sync"
+ "sync/atomic"
"time"
)
// Builder is a fluent builder for construction of new events.
type Builder struct {
- ctx context.Context
- data *builder
+ ctx context.Context
+ data *builder
+ builderID uint64 // equals data.id if all is well
}
// preallocateLabels controls the space reserved for labels in a builder.
@@ -30,24 +32,31 @@
exporter *Exporter
Event Event
labels [preallocateLabels]Label
+ id uint64
}
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 {
- return Builder{ctx: ctx, data: newBuilder(ctx)}
-}
-
-func newBuilder(ctx context.Context) *builder {
+ b := Builder{ctx: ctx}
exporter, parent := FromContext(ctx)
if exporter == nil {
- return nil
+ return b
}
+ b.data = allocBuilder()
+ b.builderID = b.data.id
+ b.data.exporter = exporter
+ b.data.Event.Labels = b.data.labels[:0]
+ b.data.Event.Parent = parent
+ return b
+}
+
+var builderID uint64 // atomic
+
+func allocBuilder() *builder {
b := builderPool.Get().(*builder)
- b.exporter = exporter
- b.Event.Labels = b.labels[:0]
- b.Event.Parent = parent
+ b.id = atomic.AddUint64(&builderID, 1)
return b
}
@@ -57,8 +66,11 @@
if b.data == nil {
return b
}
- clone := Builder{ctx: b.ctx, data: builderPool.Get().(*builder)}
+ bb := allocBuilder()
+ bbid := bb.id
+ clone := Builder{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 {
@@ -71,6 +83,7 @@
// With adds a new label to the event being constructed.
func (b Builder) With(label Label) Builder {
if b.data != nil {
+ checkValid(b.data, b.builderID)
b.data.Event.Labels = append(b.data.Event.Labels, label)
}
return b
@@ -81,6 +94,7 @@
if b.data == nil || len(labels) == 0 {
return b
}
+ checkValid(b.data, b.builderID)
if len(b.data.Event.Labels) == 0 {
b.data.Event.Labels = labels
} else {
@@ -91,6 +105,7 @@
func (b Builder) At(t time.Time) Builder {
if b.data != nil {
+ checkValid(b.data, b.builderID)
b.data.Event.At = t
}
return b
@@ -98,6 +113,7 @@
func (b Builder) Namespace(ns string) Builder {
if b.data != nil {
+ checkValid(b.data, b.builderID)
b.data.Event.Namespace = ns
}
return b
@@ -108,7 +124,8 @@
if b.data == nil {
return
}
- if b.data.exporter.handler != nil {
+ checkValid(b.data, b.builderID)
+ if b.data.exporter.loggingEnabled() {
b.data.exporter.mu.Lock()
defer b.data.exporter.mu.Unlock()
b.data.Event.Labels = append(b.data.Event.Labels, Message.Of(message))
@@ -124,6 +141,7 @@
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.
@@ -141,6 +159,7 @@
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()
@@ -156,6 +175,7 @@
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()
@@ -170,6 +190,7 @@
if b.data == nil {
return
}
+ checkValid(b.data, b.builderID)
if b.data.exporter.tracingEnabled() {
b.data.exporter.mu.Lock()
defer b.data.exporter.mu.Unlock()
@@ -182,6 +203,7 @@
// 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))
@@ -204,6 +226,7 @@
if b.data == nil {
return b.ctx, func() {}
}
+ checkValid(b.data, b.builderID)
ctx := b.ctx
end := func() {}
if b.data.exporter.tracingEnabled() {
@@ -215,7 +238,8 @@
b.data.exporter.prepare(&b.data.Event)
// create the end builder
eb := Builder{}
- eb.data = builderPool.Get().(*builder)
+ eb.data = allocBuilder()
+ eb.builderID = eb.data.id
eb.data.exporter = b.data.exporter
eb.data.Event.Parent = traceID
// and now deliver the start event
@@ -228,3 +252,9 @@
b.done()
return ctx, end
}
+
+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
index 8e01474..c7c629d 100644
--- a/event/builder_test.go
+++ b/event/builder_test.go
@@ -9,6 +9,7 @@
import (
"context"
"fmt"
+ "strings"
"testing"
"github.com/google/go-cmp/cmp"
@@ -22,7 +23,7 @@
labels = append(labels, keys.Int(fmt.Sprintf("l%d", i)).Of(i))
}
- ctx := event.WithExporter(context.Background(), event.NewExporter(nil, nil))
+ ctx := event.WithExporter(context.Background(), event.NewExporter(noopHandler{}, nil))
b1 := event.To(ctx)
b1.With(labels[0]).With(labels[1])
check(t, b1, labels[:2])
@@ -92,3 +93,48 @@
t.t.Fatal("Start context not passed to End")
}
}
+
+func TestFailToClone(t *testing.T) {
+ ctx := event.WithExporter(context.Background(), event.NewExporter(noopHandler{}, 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")
+ })
+}
+
+type noopHandler struct{}
+
+func (noopHandler) Log(ctx context.Context, ev *event.Event) {}
+func (noopHandler) Metric(ctx context.Context, ev *event.Event) {}
+func (noopHandler) Annotate(ctx context.Context, ev *event.Event) {}
+func (noopHandler) End(ctx context.Context, ev *event.Event) {}
+func (noopHandler) Start(ctx context.Context, ev *event.Event) context.Context {
+ return ctx
+}
diff --git a/event/export.go b/event/export.go
index 85e8729..e15cd2d 100644
--- a/event/export.go
+++ b/event/export.go
@@ -60,6 +60,9 @@
// NewExporter creates an Exporter using the supplied handler and options.
// Event delivery is serialized to enable safe atomic handling.
func NewExporter(handler Handler, opts *ExporterOptions) *Exporter {
+ if handler == nil {
+ panic("handler must not be nil")
+ }
e := &Exporter{handler: handler}
if opts != nil {
e.opts = *opts
