events: skip dispatch setup when nothing is subscribed (#7997)

App.Emit does a fair amount of work before it can discover that no handler
is bound: it derives three loggers, one of which formats the event's UUID
even when debug logging is off, and registers a replacer callback. Only
then does it reach "shortcut if event not bound at all".

Some events are emitted on every TLS handshake -- CertMagic emits
tls_get_certificate as the first statement of GetCertificateWithContext --
so on a server with no events configuration that work runs per handshake
and is discarded every time.

Return early when neither the event's name nor the catch-all is bound and
debug logging is off, which are exactly the conditions under which nothing
can observe the event. caddy.NewEvent still runs, so the returned Event is
unchanged for callers.

Benchmarks are included; measurements are in the pull request.

modules/caddyevents/app.go

@@ -22,6 +22,7 @@ import (
 	"strings"
 
 	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 
 	"github.com/caddyserver/caddy/v2"
 )
@@ -205,13 +206,25 @@ func (app *App) On(eventName string, handler Handler) error {
 // Note that the data map is not copied, for efficiency. After Emit() is called, the
 // data passed in should not be changed in other goroutines.
 func (app *App) Emit(ctx caddy.Context, eventName string, data map[string]any) caddy.Event {
-	logger := app.logger.With(zap.String("name", eventName))
-
 	e, err := caddy.NewEvent(ctx, eventName, data)
 	if err != nil {
-		logger.Error("failed to create event", zap.Error(err))
+		app.logger.Error("failed to create event",
+			zap.String("name", eventName), zap.Error(err))
 	}
 
+	// A handler can only be reached through subscriptions to this event by
+	// name or to all events, so if neither is bound, nothing can observe
+	// this event and the only remaining output is the debug log below.
+	// Bail out before deriving loggers and registering replacer values:
+	// some events, such as tls_get_certificate, are emitted on every TLS
+	// handshake, where that work is significant and always wasted.
+	if app.subscriptions[eventName] == nil && app.subscriptions[""] == nil &&
+		!app.logger.Core().Enabled(zapcore.DebugLevel) {
+		return e
+	}
+
+	logger := app.logger.With(zap.String("name", eventName))
+
 	var originModule caddy.ModuleInfo
 	var originModuleID caddy.ModuleID
 	var originModuleName string

modules/caddyevents/app_test.go

@@ -0,0 +1,139 @@
+// Copyright 2015 Matthew Holt and The Caddy 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 caddyevents
+
+import (
+	"context"
+	"io"
+	"testing"
+
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+
+	"github.com/caddyserver/caddy/v2"
+)
+
+// discardLogger stands in for a production logger: a real core at info level,
+// so debug output is filtered but everything else behaves normally.
+func discardLogger() *zap.Logger {
+	return zap.New(zapcore.NewCore(
+		zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()),
+		zapcore.AddSync(io.Discard),
+		zapcore.InfoLevel,
+	))
+}
+
+func testApp(tb testing.TB) (*App, caddy.Context, context.CancelFunc) {
+	tb.Helper()
+	app := &App{
+		logger:        discardLogger(),
+		subscriptions: make(map[string]map[caddy.ModuleID][]Handler),
+	}
+	ctx, cancel := caddy.NewContext(caddy.Context{Context: context.Background()})
+	return app, ctx, cancel
+}
+
+type countingHandler struct{ count int }
+
+func (h *countingHandler) Handle(context.Context, caddy.Event) error {
+	h.count++
+	return nil
+}
+
+// Emit takes a shortcut when nothing is subscribed; a handler bound to the
+// event by name must still be invoked.
+func TestEmitDispatchesToNamedSubscriber(t *testing.T) {
+	app, ctx, cancel := testApp(t)
+	defer cancel()
+
+	h := new(countingHandler)
+	if err := app.On("cert_obtained", h); err != nil {
+		t.Fatal(err)
+	}
+
+	app.Emit(ctx, "cert_obtained", nil)
+	if h.count != 1 {
+		t.Errorf("handler invoked %d times, want 1", h.count)
+	}
+
+	// an event nobody subscribed to must not reach it
+	app.Emit(ctx, "cert_failed", nil)
+	if h.count != 1 {
+		t.Errorf("handler invoked %d times after unrelated event, want 1", h.count)
+	}
+}
+
+// Subscribing without naming an event binds to every event, which is stored
+// under the empty event name; the shortcut has to account for that.
+func TestEmitDispatchesToCatchAllSubscriber(t *testing.T) {
+	app, ctx, cancel := testApp(t)
+	defer cancel()
+
+	h := new(countingHandler)
+	if err := app.Subscribe(&Subscription{Handlers: []Handler{h}}); err != nil {
+		t.Fatal(err)
+	}
+
+	app.Emit(ctx, "tls_get_certificate", nil)
+	if h.count != 1 {
+		t.Errorf("handler invoked %d times, want 1", h.count)
+	}
+}
+
+// Some events, such as tls_get_certificate, are emitted on every TLS
+// handshake, whether or not anything is subscribed to them.
+func BenchmarkEmitNoSubscribers(b *testing.B) {
+	app, ctx, cancel := testApp(b)
+	defer cancel()
+
+	data := map[string]any{"client_hello": "example.com"}
+
+	b.ReportAllocs()
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		app.Emit(ctx, "tls_get_certificate", data)
+	}
+}
+
+func BenchmarkEmitNoSubscribersParallel(b *testing.B) {
+	app, ctx, cancel := testApp(b)
+	defer cancel()
+
+	data := map[string]any{"client_hello": "example.com"}
+
+	b.ReportAllocs()
+	b.ResetTimer()
+	b.RunParallel(func(pb *testing.PB) {
+		for pb.Next() {
+			app.Emit(ctx, "tls_get_certificate", data)
+		}
+	})
+}
+
+func BenchmarkEmitWithSubscriber(b *testing.B) {
+	app, ctx, cancel := testApp(b)
+	defer cancel()
+
+	if err := app.On("tls_get_certificate", new(countingHandler)); err != nil {
+		b.Fatal(err)
+	}
+	data := map[string]any{"client_hello": "example.com"}
+
+	b.ReportAllocs()
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		app.Emit(ctx, "tls_get_certificate", data)
+	}
+}

modules/caddyevents/handshake_bench_test.go

@@ -0,0 +1,111 @@
+// Copyright 2015 Matthew Holt and The Caddy 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 caddyevents
+
+import (
+	"context"
+	"crypto/ecdsa"
+	"crypto/elliptic"
+	"crypto/rand"
+	"crypto/tls"
+	"crypto/x509"
+	"crypto/x509/pkix"
+	"math/big"
+	"testing"
+	"time"
+
+	"github.com/caddyserver/certmagic"
+	"go.uber.org/zap"
+)
+
+func benchCert(tb testing.TB) tls.Certificate {
+	tb.Helper()
+	key, err := ecdsa.GenerateKey(elliptic.P256(), rand.Reader)
+	if err != nil {
+		tb.Fatal(err)
+	}
+	tmpl := &x509.Certificate{
+		SerialNumber: big.NewInt(1),
+		Subject:      pkix.Name{CommonName: "example.com"},
+		DNSNames:     []string{"example.com"},
+		NotBefore:    time.Now().Add(-time.Hour),
+		NotAfter:     time.Now().Add(24 * time.Hour),
+	}
+	der, err := x509.CreateCertificate(rand.Reader, tmpl, tmpl, &key.PublicKey, key)
+	if err != nil {
+		tb.Fatal(err)
+	}
+	leaf, err := x509.ParseCertificate(der)
+	if err != nil {
+		tb.Fatal(err)
+	}
+	return tls.Certificate{Certificate: [][]byte{der}, PrivateKey: key, Leaf: leaf}
+}
+
+// benchmarkCertLookup measures CertMagic's GetCertificate, which Caddy calls
+// once per TLS handshake. CertMagic emits "tls_get_certificate" there, so this
+// shows what the events app costs a handshake when nothing is subscribed.
+func benchmarkCertLookup(b *testing.B, onEvent func(context.Context, string, map[string]any) error) {
+	b.Helper()
+
+	var cfg *certmagic.Config
+	cache := certmagic.NewCache(certmagic.CacheOptions{
+		GetConfigForCert: func(certmagic.Certificate) (*certmagic.Config, error) { return cfg, nil },
+		Logger:           zap.NewNop(),
+	})
+	b.Cleanup(cache.Stop)
+
+	cfg = certmagic.New(cache, certmagic.Config{
+		Storage: &certmagic.FileStorage{Path: b.TempDir()},
+		Logger:  zap.NewNop(),
+		OnEvent: onEvent,
+	})
+	if _, err := cfg.CacheUnmanagedTLSCertificate(context.Background(), benchCert(b), nil); err != nil {
+		b.Fatal(err)
+	}
+
+	hello := &tls.ClientHelloInfo{
+		ServerName:        "example.com",
+		CipherSuites:      []uint16{tls.TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256},
+		SupportedCurves:   []tls.CurveID{tls.CurveP256},
+		SupportedPoints:   []uint8{0},
+		SupportedVersions: []uint16{tls.VersionTLS13, tls.VersionTLS12},
+		SignatureSchemes:  []tls.SignatureScheme{tls.ECDSAWithP256AndSHA256},
+	}
+	if _, err := cfg.GetCertificate(hello); err != nil {
+		b.Fatal(err)
+	}
+
+	b.ReportAllocs()
+	b.ResetTimer()
+	for i := 0; i < b.N; i++ {
+		if _, err := cfg.GetCertificate(hello); err != nil {
+			b.Fatal(err)
+		}
+	}
+}
+
+// Caddy always binds the TLS app to the events app, so this is what a
+// handshake pays for the tls_get_certificate event in a config that has no
+// subscriptions at all -- which is every config that does not use the events
+// app. The hook body is what (*caddytls.TLS).onEvent does.
+func BenchmarkCertLookupWithEventsApp(b *testing.B) {
+	app, ctx, cancel := testApp(b)
+	defer cancel()
+
+	benchmarkCertLookup(b, func(_ context.Context, name string, data map[string]any) error {
+		return app.Emit(ctx, name, data).Aborted
+	})
+}