From 5896b6bb240c35ce0b2d13473bf87feacf3de760 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Thu, 5 Nov 2026 23:48:00 +0100 Subject: [PATCH 1/8] test(pluginkit): pin how a hook calls its plugins --- pluginkit/features/.golangci.yml | 36 +++++++++ pluginkit/features/features_test.go | 39 ++++++++++ pluginkit/features/go.mod | 17 ++++ pluginkit/features/go.sum | 28 +++++++ pluginkit/features/hooks.feature | 115 ++++++++++++++++++++++++++++ 5 files changed, 235 insertions(+) create mode 100644 pluginkit/features/.golangci.yml create mode 100644 pluginkit/features/features_test.go create mode 100644 pluginkit/features/go.mod create mode 100644 pluginkit/features/go.sum create mode 100644 pluginkit/features/hooks.feature diff --git a/pluginkit/features/.golangci.yml b/pluginkit/features/.golangci.yml new file mode 100644 index 0000000..1b3b888 --- /dev/null +++ b/pluginkit/features/.golangci.yml @@ -0,0 +1,36 @@ +version: "2" + +linters: + default: standard + enable: + - depguard + - lll + - misspell + - revive + - unconvert + - unparam + settings: + lll: + line-length: 120 + revive: + rules: + - name: blank-imports + disabled: true + - name: exported + depguard: + rules: + dependency-purity: + list-mode: strict + allow: + - $gostd + - github.com/cucumber/godog + - github.com/gopherium/framework/pluginkit + +formatters: + enable: + - gofmt + - goimports + settings: + goimports: + local-prefixes: + - github.com/gopherium/framework diff --git a/pluginkit/features/features_test.go b/pluginkit/features/features_test.go new file mode 100644 index 0000000..d7178e6 --- /dev/null +++ b/pluginkit/features/features_test.go @@ -0,0 +1,39 @@ +// SPDX-License-Identifier: Apache-2.0 + +package features_test + +import ( + "os" + "testing" + + "github.com/cucumber/godog" +) + +// wipTag selects the scenarios no code makes pass yet. +const wipTag = "@wip" + +// runFeature runs one feature file as its own suite, refusing undefined steps. +func runFeature(t *testing.T, path string, initialize func(*godog.ScenarioContext)) { + t.Helper() + tags := "~" + wipTag + if os.Getenv("PLUGINKIT_BDD_WIP") != "" { + tags = "" + } + suite := godog.TestSuite{ + ScenarioInitializer: initialize, + Options: &godog.Options{ + Format: "pretty", + Paths: []string{path}, + Tags: tags, + Strict: true, + TestingT: t, + }, + } + if suite.Run() != 0 { + t.Error("the feature did not pass") + } +} + +func TestHooks(t *testing.T) { + runFeature(t, "hooks.feature", func(*godog.ScenarioContext) {}) +} diff --git a/pluginkit/features/go.mod b/pluginkit/features/go.mod new file mode 100644 index 0000000..c4ed7f7 --- /dev/null +++ b/pluginkit/features/go.mod @@ -0,0 +1,17 @@ +module github.com/gopherium/framework/pluginkit/features + +go 1.27.3 + +require github.com/cucumber/godog v0.16.0 + +require ( + github.com/cucumber/gherkin/go/v42 v42.0.0 // indirect + github.com/cucumber/messages/go/v34 v34.2.0 // indirect + github.com/google/uuid v1.6.0 // indirect + github.com/hashicorp/go-immutable-radix v1.3.1 // indirect + github.com/hashicorp/go-memdb v1.3.5 // indirect + github.com/hashicorp/golang-lru v0.5.4 // indirect + github.com/spf13/pflag v1.0.10 // indirect +) + +replace github.com/gopherium/framework/pluginkit => ../ diff --git a/pluginkit/features/go.sum b/pluginkit/features/go.sum new file mode 100644 index 0000000..32fc51b --- /dev/null +++ b/pluginkit/features/go.sum @@ -0,0 +1,28 @@ +github.com/cucumber/gherkin/go/v42 v42.0.0 h1:Ulh3E2awUUSSja+wonP/IOQ+ycmiZwZbgmzqk5H8JNI= +github.com/cucumber/gherkin/go/v42 v42.0.0/go.mod h1:CsaumaO2dR9XvBc6ZyiGLMhWCKtTRDxgoxqJigSjSSg= +github.com/cucumber/godog v0.16.0 h1:ezQbgItuWqZrjPUQwLJ3muwIlvzXBOfZso5QZfG7efE= +github.com/cucumber/godog v0.16.0/go.mod h1:EDUX9yCqANK+GpbftMDeu61sUDtdLuo1JJgXD2n3bbM= +github.com/cucumber/messages/go/v34 v34.2.0 h1:VCbcNOMz+f8ccjjOOx1NLBNhwvE7/X49Atc8klJa+i8= +github.com/cucumber/messages/go/v34 v34.2.0/go.mod h1:LYUPjqlTS1kS0pdkdf6sS5uirnjwiIzEGyXPezXNhL8= +github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= +github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0= +github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= +github.com/hashicorp/go-immutable-radix v1.3.1 h1:DKHmCUm2hRBK510BaiZlwvpD40f8bJFeZnpfm2KLowc= +github.com/hashicorp/go-immutable-radix v1.3.1/go.mod h1:0y9vanUI8NX6FsYoO3zeMjhV/C5i9g4Q3DwcSNZ4P60= +github.com/hashicorp/go-memdb v1.3.5 h1:b3taDMxCBCBVgyRrS1AZVHO14ubMYZB++QpNhBg+Nyo= +github.com/hashicorp/go-memdb v1.3.5/go.mod h1:8IVKKBkVe+fxFgdFOYxzQQNjz+sWCyHCdIC/+5+Vy1Y= +github.com/hashicorp/go-uuid v1.0.0/go.mod h1:6SBZvOh/SIDV7/2o3Jml5SYk/TvGqwFJ/bN7x4byOro= +github.com/hashicorp/go-uuid v1.0.2 h1:cfejS+Tpcp13yd5nYHWDI6qVCny6wyX2Mt5SGur2IGE= +github.com/hashicorp/go-uuid v1.0.2/go.mod h1:6SBZvOh/SIDV7/2o3Jml5SYk/TvGqwFJ/bN7x4byOro= +github.com/hashicorp/golang-lru v0.5.0/go.mod h1:/m3WP610KZHVQ1SGc6re/UDhFvYD7pJ4Ao+sR/qLZy8= +github.com/hashicorp/golang-lru v0.5.4 h1:YDjusn29QI/Das2iO9M0BHnIbxPeyuCHsjMW+lJfyTc= +github.com/hashicorp/golang-lru v0.5.4/go.mod h1:iADmTwqILo4mZ8BN3D2Q6+9jd8WM5uGBxy+E8yxSoD4= +github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= +github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/spf13/pflag v1.0.10 h1:4EBh2KAYBwaONj6b2Ye1GiHfwjqyROoF4RwYO+vPwFk= +github.com/spf13/pflag v1.0.10/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg= +github.com/stretchr/testify v1.11.1 h1:7s2iGBzp5EwR7/aIZr8ao5+dra3wiQyKjjFuvgVKu7U= +github.com/stretchr/testify v1.11.1/go.mod h1:wZwfW3scLgRK+23gO65QZefKpKQRnfz6sD981Nm4B6U= +gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= +gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= diff --git a/pluginkit/features/hooks.feature b/pluginkit/features/hooks.feature new file mode 100644 index 0000000..9af149d --- /dev/null +++ b/pluginkit/features/hooks.feature @@ -0,0 +1,115 @@ +Feature: Calling the plugins that implement a hook + A hook is a named moment where an application calls every plugin that + implements one interface, in the order the plugins were registered. An + action tells each plugin that something happened, and a filter passes a + value through each plugin. One firing of a hook shares one time budget + among all its plugins. A plugin that fails, panics or runs slow never + stops the plugins after it, and the counters name the plugin at fault. + + @wip + Scenario: Every plugin that implements the hook is called in order + Given the plugins "analytics", "feed" and "seo-basics" implement the hook "public.head-tags" + And the plugin "theme" is registered without implementing it + When the hook fires + Then "analytics", "feed" and "seo-basics" are called in that order + And "theme" is not called + + @wip + Scenario: A failing plugin leaves the plugins after it running + Given the plugins "analytics", "feed" and "seo-basics" implement the hook "content.changed" + And "feed" fails with "index unavailable" + When the hook fires + Then "analytics", "feed" and "seo-basics" are called in that order + And the report holds "pluginkit: feed content.changed: index unavailable" + And "feed" is counted 1 error + + @wip + Scenario: A panicking plugin leaves the plugins after it running + Given the plugins "analytics", "feed" and "seo-basics" implement the hook "content.changed" + And "feed" panics with "boom" + When the hook fires + Then "analytics", "feed" and "seo-basics" are called in that order + And the report holds "pluginkit: feed content.changed panicked: boom" with the stack of the panic + And "feed" is counted 1 panic + + @wip + Scenario: The plugins after a slow one are still called + Given the plugins "analytics", "feed" and "seo-basics" implement the hook "public.head-tags" + And the hook has a budget of 2 ms + And "analytics" takes 5 ms + When the hook fires + Then "analytics", "feed" and "seo-basics" are called in that order + And "feed" and "seo-basics" are called after the deadline passed + And the hook is counted 1 overrun + + @wip + Scenario: An error caused by the ended deadline is not the plugin's fault + Given the plugins "analytics" and "search" implement the hook "content.changed" + And the hook has a budget of 2 ms + And "analytics" takes 5 ms + And "search" fails with the error of its ended context + When the hook fires + Then "search" is counted 0 errors and 1 call whose context ended + And the report marks the failure of "search" as caused by the ended context + + @wip + Scenario: An error of its own after the deadline still counts against the plugin + Given the plugins "analytics" and "search" implement the hook "content.changed" + And the hook has a budget of 2 ms + And "analytics" takes 5 ms + And "search" fails with "index unavailable" + When the hook fires + Then "search" is counted 1 error and 0 calls whose context ended + + @wip + Scenario: A plugin that hides the context's error behind its own text is counted an error + Given the plugins "analytics" and "search" implement the hook "content.changed" + And the hook has a budget of 2 ms + And "analytics" takes 5 ms + And "search" fails with the text of its ended context but not the error itself + When the hook fires + Then "search" is counted 1 error and 0 calls whose context ended + + @wip + Scenario: The firing that runs over its budget charges no plugin + Given the plugins "analytics", "reviews" and "feed" implement the hook "public.head-tags" + And the hook has a budget of 2 ms and times each plugin for 20 firings after an overrun + And "analytics" takes 3 ms + When the hook fires + Then the hook is counted 1 overrun + And no plugin is charged an overrun + + @wip + Scenario: A timed overrun is charged to the slowest plugin + Given the plugins "analytics", "reviews" and "feed" implement the hook "public.head-tags" + And the hook has a budget of 2 ms and times each plugin for 20 firings after an overrun + And the hook has run over its budget once + When the hook fires while "analytics" takes 1.9 ms, "reviews" takes 0.7 ms and "feed" takes 0.1 ms + Then "analytics" is charged 1 overrun + And "reviews" and "feed" are charged no overrun + + @wip + Scenario: Each plugin is timed only for the firings after an overrun + Given the plugins "analytics" and "feed" implement the hook "public.head-tags" + And the hook has a budget of 2 ms and times each plugin for 3 firings after an overrun + And the hook has run over its budget once + When the hook fires 5 times within its budget + Then "analytics" and "feed" are each timed in 3 firings + + @wip + Scenario: A filter passes the value through every plugin + Given the plugins "brand" and "suffix" implement the filter hook "page.title" + And "brand" puts "Example: " before the title + And "suffix" puts " | Home" after the title + When the hook filters the title "Hello" + Then the title becomes "Example: Hello | Home" + + @wip + Scenario: A filter keeps the incoming value when a plugin fails or panics + Given the plugins "brand", "broken", "loud" and "suffix" implement the filter hook "page.title" + And "brand" puts "Example: " before the title + And "broken" fails with "no title" + And "loud" panics with "boom" + And "suffix" puts " | Home" after the title + When the hook filters the title "Hello" + Then the title becomes "Example: Hello | Home" From 1f967297372072e8b6143955acd45121c507aba1 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Thu, 5 Nov 2026 23:48:00 +0100 Subject: [PATCH 2/8] feat(ci): test, lint and scan the pluginkit features module --- .github/workflows/ci.yml | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index b88929f..705a1c8 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -14,7 +14,7 @@ jobs: strategy: fail-fast: false matrix: - module: ["dbkit", "dbkit/sqlite", "mailkit", "goncierge", "gonsole", "gonsole/auth", "gonsole/auth/sqlite", "pluginkit", "pluginkit/graphwire"] + module: ["dbkit", "dbkit/sqlite", "mailkit", "goncierge", "gonsole", "gonsole/auth", "gonsole/auth/sqlite", "pluginkit", "pluginkit/features", "pluginkit/graphwire"] defaults: run: working-directory: ${{ matrix.module }} @@ -99,7 +99,7 @@ jobs: strategy: fail-fast: false matrix: - module: ["dbkit", "dbkit/postgres", "dbkit/sqlite", "mailkit", "goncierge", "gonsole", "gonsole/auth", "gonsole/auth/postgres", "gonsole/auth/sqlite", "pluginkit", "pluginkit/graphwire", "postgresblob"] + module: ["dbkit", "dbkit/postgres", "dbkit/sqlite", "mailkit", "goncierge", "gonsole", "gonsole/auth", "gonsole/auth/postgres", "gonsole/auth/sqlite", "pluginkit", "pluginkit/features", "pluginkit/graphwire", "postgresblob"] steps: - uses: actions/checkout@9c091bb21b7c1c1d1991bb908d89e4e9dddfe3e0 # v7.0.0 with: @@ -121,7 +121,7 @@ jobs: strategy: fail-fast: false matrix: - module: ["dbkit", "dbkit/postgres", "dbkit/sqlite", "mailkit", "goncierge", "gonsole", "gonsole/auth", "gonsole/auth/postgres", "gonsole/auth/sqlite", "pluginkit", "pluginkit/graphwire", "postgresblob"] + module: ["dbkit", "dbkit/postgres", "dbkit/sqlite", "mailkit", "goncierge", "gonsole", "gonsole/auth", "gonsole/auth/postgres", "gonsole/auth/sqlite", "pluginkit", "pluginkit/features", "pluginkit/graphwire", "postgresblob"] defaults: run: working-directory: ${{ matrix.module }} From 5b1d4d6d392e7dc38e629f9fbe85a87555945280 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 6 Nov 2026 11:50:43 +0100 Subject: [PATCH 3/8] feat(pluginkit): call a hook on every plugin that implements it, with a recover and a time budget --- pluginkit/CHANGELOG.md | 6 + pluginkit/hook.go | 264 +++++++++++++++++++ pluginkit/hook_budget_test.go | 377 ++++++++++++++++++++++++++++ pluginkit/hook_test.go | 459 ++++++++++++++++++++++++++++++++++ pluginkit/pluginkit.go | 3 +- 5 files changed, 1108 insertions(+), 1 deletion(-) create mode 100644 pluginkit/hook.go create mode 100644 pluginkit/hook_budget_test.go create mode 100644 pluginkit/hook_test.go diff --git a/pluginkit/CHANGELOG.md b/pluginkit/CHANGELOG.md index 78b03e3..190aaf8 100644 --- a/pluginkit/CHANGELOG.md +++ b/pluginkit/CHANGELOG.md @@ -3,6 +3,12 @@ Releases of this module are tagged `pluginkit/vX.Y.Z`. Releases up to 0.5.1 were tagged `vX.Y.Z` in `github.com/gopherium/pluginkit`. +## Unreleased + +- `NewHook` collects the plugins that implement an interface into a `Hook`. `Hook.Fire` calls an action on each in registration order and `Filter` passes a value through each, every call inside its own recover. +- One firing shares `HookSettings.Budget` as a context deadline. The plugins after a slow one are still called, and an error that matches the ended context counts as `ContextEnded`, not as that plugin's fault. +- After a firing runs over its budget, the next `TimedFirings` firings time each plugin and charge a timed overrun to the slowest. `Stats` returns every counter, and `HookSettings.Report` receives each error and panic as a `HookFailure`. + ## 0.9.0 - 2026-11-05 - `wire.Manifest` holds one `plugin.json` as data, reading `version`, `license`, `did`, `requires`, `tested`, `engines`, `uninstall`, `hooks`, `defines`, `jobs` and `settings`, with every other key kept raw in `Extra`. diff --git a/pluginkit/hook.go b/pluginkit/hook.go new file mode 100644 index 0000000..43bd513 --- /dev/null +++ b/pluginkit/hook.go @@ -0,0 +1,264 @@ +// SPDX-License-Identifier: Apache-2.0 + +package pluginkit + +import ( + "context" + "errors" + "fmt" + "reflect" + "runtime/debug" + "sync/atomic" + "time" +) + +// HookSettings are the values a hook runs under, each one required. +type HookSettings struct { + // Budget is the time one firing gives all its plugins together. + Budget time.Duration + // TimedFirings is how many firings after an overrun time each plugin. + TimedFirings int + // Report receives every error and panic of a plugin inside the firing, from any goroutine at once. + Report func(HookFailure) +} + +// HookFailure is one error or panic of one plugin in one firing of a hook. +type HookFailure struct { + Hook string + ID string + // Panicked is true for a panic the hook recovered. + Panicked bool + // ContextEnded is true for an error that matches the firing's context after that context ended. + ContextEnded bool + Err error + // Stack is the stack of a panic, and empty for an error. + Stack string +} + +// HookStats are the counters of a hook, its plugins in registration order. +type HookStats struct { + Name string + Firings uint64 + Overruns uint64 + Plugins []PluginStats +} + +// PluginStats are the counters of one plugin in one hook. +type PluginStats struct { + ID string + Errors uint64 + Panics uint64 + ContextEnded uint64 + // Overruns counts the timed firings that ran over their budget with this plugin as the slowest. + Overruns uint64 + // TimedCalls counts the calls timed while firings were timed after an overrun. + TimedCalls uint64 + // TimedTime is the total time of those calls. + TimedTime time.Duration +} + +// pluginCounters are the live counters of one plugin in one hook. +type pluginCounters struct { + errors, panics, contextEnded, overruns, timedCalls atomic.Uint64 + timedTime atomic.Int64 +} + +// Hook calls, in registration order, the plugins that implement the interface C. +type Hook[C any] struct { + name string + settings HookSettings + ids []string + plugins []C + counters []pluginCounters + firings atomic.Uint64 + overruns atomic.Uint64 + timed atomic.Int64 +} + +// NewHook returns the hook called name over the plugins that implement C, refusing what it cannot run under. +func NewHook[C any, P interface{ ID() string }](name string, plugins []P, settings HookSettings) (*Hook[C], error) { + if err := checkHook(name, settings, reflect.TypeFor[C]()); err != nil { + return nil, err + } + hook := &Hook[C]{name: name, settings: settings} + seen := make(map[string]struct{}, len(plugins)) + for _, p := range plugins { + id := p.ID() + if _, ok := seen[id]; ok { + return nil, fmt.Errorf("pluginkit: hook %s: duplicate id %q", name, id) + } + seen[id] = struct{}{} + if plugin, ok := any(p).(C); ok { + hook.ids = append(hook.ids, id) + hook.plugins = append(hook.plugins, plugin) + } + } + hook.counters = make([]pluginCounters, len(hook.plugins)) + return hook, nil +} + +// checkHook refuses a hook name, settings or interface type a hook cannot run under. +func checkHook(name string, settings HookSettings, hookType reflect.Type) error { + if name == "" { + return errors.New("pluginkit: the hook name is empty") + } + if settings.Budget <= 0 { + return fmt.Errorf("pluginkit: hook %s: the budget must stand above zero, got %v", name, settings.Budget) + } + if settings.TimedFirings <= 0 { + return fmt.Errorf("pluginkit: hook %s: the timed firings must stand above zero, got %d", + name, settings.TimedFirings) + } + if settings.Report == nil { + return fmt.Errorf("pluginkit: hook %s: the report is nil", name) + } + if hookType.Kind() != reflect.Interface { + return fmt.Errorf("pluginkit: hook %s: %v is not an interface", name, hookType) + } + return nil +} + +// Fire calls call on every plugin of the hook in order, under one budget, past any plugin's error or panic. +func (h *Hook[C]) Fire(ctx context.Context, call func(ctx context.Context, plugin C) error) { + if len(h.plugins) == 0 { + return + } + h.fire(ctx, call) +} + +// Filter passes value through every plugin of hook in order, keeping the incoming value on an error or a panic. +func Filter[C, V any](ctx context.Context, hook *Hook[C], value V, + call func(ctx context.Context, plugin C, value V) (V, error)) V { + if len(hook.plugins) == 0 { + return value + } + hook.fire(ctx, func(ctx context.Context, plugin C) error { + next, err := call(ctx, plugin, value) + if err == nil { + value = next + } + return err + }) + return value +} + +// Stats returns the counters of the hook and of each of its plugins. +func (h *Hook[C]) Stats() HookStats { + stats := HookStats{ + Name: h.name, + Firings: h.firings.Load(), + Overruns: h.overruns.Load(), + Plugins: make([]PluginStats, len(h.ids)), + } + for i, id := range h.ids { + c := &h.counters[i] + stats.Plugins[i] = PluginStats{ + ID: id, + Errors: c.errors.Load(), + Panics: c.panics.Load(), + ContextEnded: c.contextEnded.Load(), + Overruns: c.overruns.Load(), + TimedCalls: c.timedCalls.Load(), + TimedTime: time.Duration(c.timedTime.Load()), + } + } + return stats +} + +// fire runs one firing, counting an overrun and charging it to the slowest plugin when the firing was timed. +func (h *Hook[C]) fire(ctx context.Context, call func(context.Context, C) error) { + h.firings.Add(1) + began := time.Now() + ctx, cancel := context.WithDeadline(ctx, began.Add(h.settings.Budget)) + defer cancel() + slowest := -1 + if h.takeTimedFiring() { + slowest = h.callTimed(ctx, call) + } else { + for i, plugin := range h.plugins { + h.call(ctx, i, plugin, call) + } + } + if time.Since(began) <= h.settings.Budget { + return + } + h.overruns.Add(1) + if slowest >= 0 { + h.counters[slowest].overruns.Add(1) + } + h.timed.Store(int64(h.settings.TimedFirings)) +} + +// takeTimedFiring reports whether this firing is one of those timed after an overrun, using one up. +func (h *Hook[C]) takeTimedFiring() bool { + for { + left := h.timed.Load() + if left <= 0 { + return false + } + if h.timed.CompareAndSwap(left, left-1) { + return true + } + } +} + +// callTimed calls every plugin in order, timing each, and returns the index of the slowest. +func (h *Hook[C]) callTimed(ctx context.Context, call func(context.Context, C) error) int { + slowest, longest := 0, time.Duration(0) + for i, plugin := range h.plugins { + began := time.Now() + h.call(ctx, i, plugin, call) + took := time.Since(began) + h.counters[i].timedCalls.Add(1) + h.counters[i].timedTime.Add(int64(took)) + if took > longest { + slowest, longest = i, took + } + } + return slowest +} + +// call calls one plugin, then counts and reports its error or panic. +func (h *Hook[C]) call(ctx context.Context, i int, plugin C, call func(context.Context, C) error) { + if out := run(ctx, plugin, call); out.recovered != nil || out.err != nil { + h.settings.Report(h.failureOf(ctx, i, out)) + } +} + +// failureOf counts what went wrong in a call of plugin i and returns it as the failure Report receives. +func (h *Hook[C]) failureOf(ctx context.Context, i int, out outcome) HookFailure { + failure := HookFailure{Hook: h.name, ID: h.ids[i]} + counters := &h.counters[i] + if out.recovered != nil { + failure.Panicked, failure.Stack = true, out.stack + failure.Err = panicError(fmt.Sprintf("pluginkit: %s %s panicked: %v", failure.ID, h.name, out.recovered)) + counters.panics.Add(1) + return failure + } + failure.Err = fmt.Errorf("pluginkit: %s %s: %w", failure.ID, h.name, out.err) + failure.ContextEnded = ctx.Err() != nil && errors.Is(out.err, ctx.Err()) + if failure.ContextEnded { + counters.contextEnded.Add(1) + } else { + counters.errors.Add(1) + } + return failure +} + +// outcome is what one call of a plugin did wrong, a panic with its stack or an error, if anything. +type outcome struct { + recovered any + stack string + err error +} + +// run calls one plugin inside a recover, answering what it panicked with and its stack, or its error. +func run[C any](ctx context.Context, plugin C, call func(context.Context, C) error) (out outcome) { + defer func() { + if out.recovered = recover(); out.recovered != nil { + out.stack = string(debug.Stack()) + } + }() + out.err = call(ctx, plugin) + return out +} diff --git a/pluginkit/hook_budget_test.go b/pluginkit/hook_budget_test.go new file mode 100644 index 0000000..04d8e12 --- /dev/null +++ b/pluginkit/hook_budget_test.go @@ -0,0 +1,377 @@ +// SPDX-License-Identifier: Apache-2.0 + +package pluginkit_test + +import ( + "context" + "errors" + "fmt" + "runtime" + "testing" + "testing/synctest" + "time" + + "github.com/gopherium/framework/pluginkit" +) + +// budget is the time one firing of the test hooks gives all their plugins. +const budget = 2 * time.Millisecond + +// timedHook builds a hook with budget that times each plugin for timedFirings firings after an overrun. +func timedHook(t *testing.T, timedFirings int, plugins ...identified) (*pluginkit.Hook[greeter], *reports) { + t.Helper() + r := &reports{} + return greetHook(t, settingsOf(budget, timedFirings, r), plugins...), r +} + +// overrunOnce fires hook once with a plugin that runs past the budget. +func overrunOnce(t *testing.T, hook *pluginkit.Hook[greeter]) { + t.Helper() + hook.Fire(t.Context(), func(context.Context, greeter) error { + time.Sleep(2 * budget) + return nil + }) +} + +// fireTimes fires hook n times. +func fireTimes(t *testing.T, hook *pluginkit.Hook[greeter], n int) { + t.Helper() + for range n { + hook.Fire(t.Context(), greet) + } +} + +func TestAFiringRunsUnderOneDeadlineOfItsBudget(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + var afterStart []time.Duration + hook, _ := timedHook(t, 20, &hookPlugin{id: "alpha", takes: budget / 2, log: &callLog{}}, + &hookPlugin{id: "beta", log: &callLog{}}) + began := time.Now() + + hook.Fire(t.Context(), func(ctx context.Context, g greeter) error { + deadline, ok := ctx.Deadline() + if !ok { + t.Error("a plugin got a context with no deadline") + } + afterStart = append(afterStart, deadline.Sub(began)) + return g.Greet(ctx) + }) + + wantEqual(t, "deadlines after the start", afterStart, []time.Duration{budget, budget}) + }) +} + +func TestThePluginsAfterASlowOneAreStillCalled(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + log := &callLog{} + hook, r := timedHook(t, 20, &hookPlugin{id: "analytics", takes: 5 * time.Millisecond, log: log}, + &hookPlugin{id: "feed", log: log}) + + hook.Fire(t.Context(), greet) + + wantEqual(t, "called", log.called(), []string{"analytics", "feed"}) + wantEqual(t, "called after the deadline", log.late, []bool{false, true}) + if stats := hook.Stats(); stats.Overruns != 1 { + t.Errorf("Stats().Overruns = %d, want 1", stats.Overruns) + } + if got := r.all(); len(got) != 0 { + t.Errorf("reported %+v, want nothing, since no plugin failed", got) + } + }) +} + +func TestAFiringThatRunsPastItsOwnDeadlineIsAnOverrun(t *testing.T) { + t.Parallel() + + const firings = 100 + hook := greetHook(t, settingsOf(20*time.Microsecond, 20, &reports{}), &hookPlugin{id: "alpha", log: &callLog{}}) + + for range firings { + hook.Fire(t.Context(), func(ctx context.Context, _ greeter) error { + deadline, _ := ctx.Deadline() + for !time.Now().After(deadline) { + runtime.Gosched() + } + return nil + }) + } + + if got := hook.Stats().Overruns; got != firings { + t.Errorf("Stats().Overruns = %d, want %d, one for each firing that ran past its deadline", got, firings) + } +} + +func TestACallerDeadlineBeforeTheBudgetIsNoOverrun(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + ctx, cancel := context.WithTimeout(t.Context(), 500*time.Microsecond) + defer cancel() + hook, _ := timedHook(t, 20, &hookPlugin{id: "alpha", takes: 1500 * time.Microsecond, log: &callLog{}}) + + hook.Fire(ctx, greet) + + if got := hook.Stats().Overruns; got != 0 { + t.Errorf("Stats().Overruns = %d, want 0, since the firing stayed inside its budget", got) + } + }) +} + +func TestAFiringThatTakesExactlyItsBudgetIsNoOverrun(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + hook, _ := timedHook(t, 20, &hookPlugin{id: "alpha", takes: budget, log: &callLog{}}) + + hook.Fire(t.Context(), greet) + + if stats := hook.Stats(); stats.Overruns != 0 { + t.Errorf("Stats().Overruns = %d, want 0", stats.Overruns) + } + }) +} + +func TestAnUntimedOverrunChargesNoPlugin(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + hook, _ := timedHook(t, 20, &hookPlugin{id: "analytics", takes: 3 * time.Millisecond, log: &callLog{}}) + + hook.Fire(t.Context(), greet) + + wantEqual(t, "Stats()", hook.Stats(), pluginkit.HookStats{ + Name: "content.changed", Firings: 1, Overruns: 1, Plugins: []pluginkit.PluginStats{{ID: "analytics"}}, + }) + }) +} + +func TestTheFiringsAfterAnOverrunTimeEachPlugin(t *testing.T) { + t.Parallel() + + tests := map[string]struct { + timedFirings, fires int + alpha, beta time.Duration + want []pluginkit.PluginStats + }{ + "for one firing when the setting says one": {1, 3, budget / 4, budget / 2, []pluginkit.PluginStats{ + {ID: "alpha", TimedCalls: 1, TimedTime: budget / 4}, + {ID: "beta", TimedCalls: 1, TimedTime: budget / 2}, + }}, + "for as many firings as the setting says": {3, 5, budget / 4, budget / 2, []pluginkit.PluginStats{ + {ID: "alpha", TimedCalls: 3, TimedTime: 3 * budget / 4}, + {ID: "beta", TimedCalls: 3, TimedTime: 3 * budget / 2}, + }}, + "charging an overrun between equal plugins to the first": {20, 1, budget, budget, []pluginkit.PluginStats{ + {ID: "alpha", Overruns: 1, TimedCalls: 1, TimedTime: budget}, + {ID: "beta", TimedCalls: 1, TimedTime: budget}, + }}, + } + for name, tc := range tests { + t.Run(name, func(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + hook, _ := timedHook(t, tc.timedFirings, &hookPlugin{id: "alpha", takes: tc.alpha, log: &callLog{}}, + &hookPlugin{id: "beta", takes: tc.beta, log: &callLog{}}) + overrunOnce(t, hook) + + fireTimes(t, hook, tc.fires) + + wantEqual(t, "Stats().Plugins", hook.Stats().Plugins, tc.want) + }) + }) + } +} + +func TestAnOverrunInsideTheWindowOpensItAgain(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + slow := &hookPlugin{id: "alpha", log: &callLog{}} + hook, _ := timedHook(t, 3, slow) + overrunOnce(t, hook) + fireTimes(t, hook, 1) + slow.takes = 2 * budget + fireTimes(t, hook, 1) + slow.takes = 0 + + fireTimes(t, hook, 5) + + wantEqual(t, "alpha's counters", statsByID(hook)["alpha"], pluginkit.PluginStats{ + ID: "alpha", Overruns: 1, TimedCalls: 5, TimedTime: 2 * budget, + }) + }) +} + +func TestATimedOverrunIsChargedToTheSlowestPlugin(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + hook, _ := timedHook(t, 20, + &hookPlugin{id: "reviews", takes: 500 * time.Microsecond, log: &callLog{}}, + &hookPlugin{id: "analytics", takes: 1200 * time.Microsecond, log: &callLog{}}, + &hookPlugin{id: "feed", takes: 900 * time.Microsecond, log: &callLog{}}) + overrunOnce(t, hook) + + fireTimes(t, hook, 1) + + wantEqual(t, "Stats()", hook.Stats(), pluginkit.HookStats{ + Name: "content.changed", Firings: 2, Overruns: 2, Plugins: []pluginkit.PluginStats{ + {ID: "reviews", TimedCalls: 1, TimedTime: 500 * time.Microsecond}, + {ID: "analytics", Overruns: 1, TimedCalls: 1, TimedTime: 1200 * time.Microsecond}, + {ID: "feed", TimedCalls: 1, TimedTime: 900 * time.Microsecond}, + }, + }) + }) +} + +func TestATimedOverrunIsChargedToTheSlowestOfThatFiringOnly(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + alpha := &hookPlugin{id: "alpha", takes: 1500 * time.Microsecond, log: &callLog{}} + beta := &hookPlugin{id: "beta", log: &callLog{}} + hook, _ := timedHook(t, 20, alpha, beta) + overrunOnce(t, hook) + fireTimes(t, hook, 1) + alpha.takes, beta.takes = 600*time.Microsecond, 1600*time.Microsecond + + fireTimes(t, hook, 1) + + wantEqual(t, "Stats().Plugins", hook.Stats().Plugins, []pluginkit.PluginStats{ + {ID: "alpha", TimedCalls: 2, TimedTime: 2100 * time.Microsecond}, + {ID: "beta", Overruns: 1, TimedCalls: 2, TimedTime: 1600 * time.Microsecond}, + }) + }) +} + +func TestAFiringAfterAnOverrunKeepsTheOrderTheDeadlineAndTheRecover(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + log := &callLog{} + hook, r := timedHook(t, 20, &hookPlugin{id: "analytics", takes: 3 * time.Millisecond, log: log}, + &hookPlugin{id: "search", fail: func(ctx context.Context) error { return ctx.Err() }, log: log}, + &hookPlugin{id: "feed", fail: failWith(errors.New("feed unavailable")), log: log}, + &hookPlugin{id: "seo", panics: "boom", log: log}) + overrunOnce(t, hook) + + hook.Fire(t.Context(), greet) + + wantEqual(t, "called", log.called(), []string{"analytics", "search", "feed", "seo"}) + wantEqual(t, "called after the deadline", log.late, []bool{false, true, true, true}) + wantEqual(t, "Stats().Plugins", hook.Stats().Plugins, []pluginkit.PluginStats{ + {ID: "analytics", Overruns: 1, TimedCalls: 1, TimedTime: 3 * time.Millisecond}, + {ID: "search", ContextEnded: 1, TimedCalls: 1}, + {ID: "feed", Errors: 1, TimedCalls: 1}, + {ID: "seo", Panics: 1, TimedCalls: 1}, + }) + wantEqual(t, "reported", shapesOf(r.all()), []failureShape{ + { + Hook: "content.changed", ID: "search", ContextEnded: true, + Err: "pluginkit: search content.changed: context deadline exceeded", + }, + {Hook: "content.changed", ID: "feed", Err: "pluginkit: feed content.changed: feed unavailable"}, + { + Hook: "content.changed", ID: "seo", Err: "pluginkit: seo content.changed panicked: boom", + Panicked: true, Stacked: true, + }, + }) + }) +} + +// endedErrorCase is what one plugin returns after the firing's deadline, the counters and the report that follow. +type endedErrorCase struct { + fail func(ctx context.Context) error + counters pluginkit.PluginStats + failure failureShape +} + +// endedErrorCases lists the errors a plugin can return once the deadline has passed. +func endedErrorCases() map[string]endedErrorCase { + ended := pluginkit.PluginStats{ID: "search", ContextEnded: 1} + failed := pluginkit.PluginStats{ID: "search", Errors: 1} + return map[string]endedErrorCase{ + "the context's error": { + fail: func(ctx context.Context) error { return ctx.Err() }, counters: ended, + failure: failureShape{ContextEnded: true, Err: "context deadline exceeded"}, + }, + "the context's error wrapped": { + fail: func(ctx context.Context) error { return fmt.Errorf("index write: %w", ctx.Err()) }, + counters: ended, failure: failureShape{ContextEnded: true, Err: "index write: context deadline exceeded"}, + }, + "an error of its own": { + fail: failWith(errors.New("index unavailable")), counters: failed, + failure: failureShape{Err: "index unavailable"}, + }, + "the context's text without the error": { + fail: func(ctx context.Context) error { return fmt.Errorf("index write: %v", ctx.Err()) }, + counters: failed, failure: failureShape{Err: "index write: context deadline exceeded"}, + }, + } +} + +func TestAnErrorAfterTheDeadlineCountsAsContextEndedOnlyWhenItIsTheContextsError(t *testing.T) { + t.Parallel() + + for name, tc := range endedErrorCases() { + t.Run(name, func(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + hook, r := timedHook(t, 20, &hookPlugin{id: "analytics", takes: 5 * time.Millisecond, log: &callLog{}}, + &hookPlugin{id: "search", fail: tc.fail, log: &callLog{}}) + + hook.Fire(t.Context(), greet) + + wantEqual(t, "search's counters", statsByID(hook)["search"], tc.counters) + want := tc.failure + want.Hook, want.ID, want.Err = "content.changed", "search", "pluginkit: search content.changed: "+want.Err + wantEqual(t, "reported", shapesOf(r.all()), []failureShape{want}) + }) + }) + } +} + +func TestTheContextsErrorBeforeTheDeadlineCountsAsAnError(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + hook, _ := timedHook(t, 20, &hookPlugin{id: "search", fail: failWith(context.DeadlineExceeded), log: &callLog{}}) + + hook.Fire(t.Context(), greet) + + if search := statsByID(hook)["search"]; search.Errors != 1 || search.ContextEnded != 0 { + t.Errorf("search's counters = %+v, want one error, since the context had not ended", search) + } + }) +} + +func TestTheCallersCanceledContextCountsAsContextEnded(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + ctx, cancel := context.WithCancel(t.Context()) + cancel() + hook, r := timedHook(t, 20, &hookPlugin{id: "search", fail: func(ctx context.Context) error { return ctx.Err() }, + log: &callLog{}}) + + hook.Fire(ctx, greet) + + failure := onlyFailure(t, r) + wantEqual(t, "reported", shapesOf([]pluginkit.HookFailure{failure}), []failureShape{{ + Hook: "content.changed", ID: "search", Err: "pluginkit: search content.changed: context canceled", + ContextEnded: true, + }}) + if !errors.Is(failure.Err, context.Canceled) { + t.Errorf("reported error = %v, want context.Canceled in its chain", failure.Err) + } + if hook.Stats().Overruns != 0 { + t.Errorf("Stats().Overruns = %d, want 0, since no time passed", hook.Stats().Overruns) + } + }) +} diff --git a/pluginkit/hook_test.go b/pluginkit/hook_test.go new file mode 100644 index 0000000..bd80f8f --- /dev/null +++ b/pluginkit/hook_test.go @@ -0,0 +1,459 @@ +// SPDX-License-Identifier: Apache-2.0 + +package pluginkit_test + +import ( + "context" + "errors" + "fmt" + "reflect" + "slices" + "strings" + "sync" + "testing" + "time" + + "github.com/gopherium/framework/pluginkit" +) + +// greeter is the interface the test hooks call. +type greeter interface { + Greet(ctx context.Context) error +} + +// titler is the interface the test filters call. +type titler interface { + Title(ctx context.Context, title string) (string, error) +} + +// identified is the least a plugin offers a hook. +type identified interface { + ID() string +} + +// callLog records which plugins a firing called, in order, and whether each saw its context ended. +type callLog struct { + mu sync.Mutex + ids []string + late []bool +} + +// add records a call of the plugin id under ctx. +func (l *callLog) add(ctx context.Context, id string) { + l.mu.Lock() + defer l.mu.Unlock() + l.ids = append(l.ids, id) + l.late = append(l.late, ctx.Err() != nil) +} + +// called returns the ids of every call, in order. +func (l *callLog) called() []string { + l.mu.Lock() + defer l.mu.Unlock() + return slices.Clone(l.ids) +} + +// hookPlugin is a plugin whose Greet and Title take its time, then panic or fail as its fields say. +type hookPlugin struct { + id string + takes time.Duration + panics any + fail func(ctx context.Context) error + suffix string + log *callLog +} + +// ID returns the plugin's id. +func (p *hookPlugin) ID() string { + return p.id +} + +// Greet records the call, takes the plugin's time, then panics or fails as told. +func (p *hookPlugin) Greet(ctx context.Context) error { + p.log.add(ctx, p.id) + time.Sleep(p.takes) + if p.panics != nil { + panic(p.panics) + } + if p.fail != nil { + return p.fail(ctx) + } + return nil +} + +// Title greets, then returns title with the plugin's suffix, beside any failure. +func (p *hookPlugin) Title(ctx context.Context, title string) (string, error) { + err := p.Greet(ctx) + return title + p.suffix, err +} + +// bystander is a plugin that implements no hook interface. +type bystander struct { + id string + log *callLog +} + +// ID returns the plugin's id. +func (b bystander) ID() string { + return b.id +} + +// failWith returns a failure that always answers err. +func failWith(err error) func(context.Context) error { + return func(context.Context) error { return err } +} + +// reports collects every failure a hook reports, from any goroutine. +type reports struct { + mu sync.Mutex + failures []pluginkit.HookFailure +} + +// add records one failure. +func (r *reports) add(failure pluginkit.HookFailure) { + r.mu.Lock() + defer r.mu.Unlock() + r.failures = append(r.failures, failure) +} + +// all returns every failure reported so far. +func (r *reports) all() []pluginkit.HookFailure { + r.mu.Lock() + defer r.mu.Unlock() + return slices.Clone(r.failures) +} + +// settingsOf returns hook settings with budget and timed firings, reporting into r. +func settingsOf(budget time.Duration, timedFirings int, r *reports) pluginkit.HookSettings { + return pluginkit.HookSettings{Budget: budget, TimedFirings: timedFirings, Report: r.add} +} + +// greetHook builds the hook content.changed of greeters over plugins, stopping the test when it is refused. +func greetHook(t *testing.T, settings pluginkit.HookSettings, plugins ...identified) *pluginkit.Hook[greeter] { + t.Helper() + hook, err := pluginkit.NewHook[greeter]("content.changed", plugins, settings) + if err != nil { + t.Fatalf("NewHook() error = %v, want nil", err) + } + return hook +} + +// greet calls Greet on one plugin of a hook. +func greet(ctx context.Context, g greeter) error { + return g.Greet(ctx) +} + +// retitle calls Title on one plugin of a filter. +func retitle(ctx context.Context, t titler, title string) (string, error) { + return t.Title(ctx, title) +} + +// statsByID returns the counters of every plugin of a hook, keyed by id. +func statsByID(hook *pluginkit.Hook[greeter]) map[string]pluginkit.PluginStats { + byID := make(map[string]pluginkit.PluginStats) + for _, plugin := range hook.Stats().Plugins { + byID[plugin.ID] = plugin + } + return byID +} + +// wantEqual checks that got deeply equals want, naming what was compared. +func wantEqual(t *testing.T, what string, got, want any) { + t.Helper() + if !reflect.DeepEqual(got, want) { + t.Errorf("%s = %+v, want %+v", what, got, want) + } +} + +// failureShape is a reported failure with its error as text and its stack only as present or absent. +type failureShape struct { + Hook, ID, Err string + Panicked, ContextEnded bool + Stacked bool +} + +// shapesOf returns the shape of each failure, in order. +func shapesOf(failures []pluginkit.HookFailure) []failureShape { + shapes := make([]failureShape, len(failures)) + for i, f := range failures { + shapes[i] = failureShape{ + Hook: f.Hook, ID: f.ID, Err: f.Err.Error(), Panicked: f.Panicked, ContextEnded: f.ContextEnded, + Stacked: f.Stack != "", + } + } + return shapes +} + +// onlyFailure returns the one failure r holds, stopping the test when it holds another number. +func onlyFailure(t *testing.T, r *reports) pluginkit.HookFailure { + t.Helper() + failures := r.all() + if len(failures) != 1 { + t.Fatalf("reported %d failures, want 1", len(failures)) + } + return failures[0] +} + +func TestNewHookKeepsOnlyImplementersInRegistrationOrder(t *testing.T) { + t.Parallel() + + log := &callLog{} + hook := greetHook(t, settingsOf(time.Hour, 20, &reports{}), + &hookPlugin{id: "gamma", log: log}, bystander{id: "theme", log: log}, &hookPlugin{id: "alpha", log: log}) + + hook.Fire(t.Context(), greet) + + wantEqual(t, "called", log.called(), []string{"gamma", "alpha"}) + wantEqual(t, "Stats()", hook.Stats(), pluginkit.HookStats{ + Name: "content.changed", Firings: 1, + Plugins: []pluginkit.PluginStats{{ID: "gamma"}, {ID: "alpha"}}, + }) +} + +func TestNewHookRefusesWhatItCannotRun(t *testing.T) { + t.Parallel() + + r := &reports{} + tests := map[string]struct { + name string + settings pluginkit.HookSettings + plugins []identified + want string + }{ + "an empty name": {"", settingsOf(time.Hour, 20, r), nil, "pluginkit: the hook name is empty"}, + "a zero budget": { + "content.changed", settingsOf(0, 20, r), nil, + "pluginkit: hook content.changed: the budget must stand above zero, got 0s", + }, + "a negative budget": { + "content.changed", settingsOf(-time.Millisecond, 20, r), nil, + "pluginkit: hook content.changed: the budget must stand above zero, got -1ms", + }, + "zero timed firings": { + "content.changed", settingsOf(time.Hour, 0, r), nil, + "pluginkit: hook content.changed: the timed firings must stand above zero, got 0", + }, + "negative timed firings": { + "content.changed", settingsOf(time.Hour, -1, r), nil, + "pluginkit: hook content.changed: the timed firings must stand above zero, got -1", + }, + "a nil report": { + "content.changed", pluginkit.HookSettings{Budget: time.Hour, TimedFirings: 20}, nil, + "pluginkit: hook content.changed: the report is nil", + }, + "two plugins with one id": { + "content.changed", settingsOf(time.Hour, 20, r), + []identified{bystander{id: "alpha"}, &hookPlugin{id: "beta"}, &hookPlugin{id: "alpha"}}, + `pluginkit: hook content.changed: duplicate id "alpha"`, + }, + } + for name, tc := range tests { + t.Run(name, func(t *testing.T) { + t.Parallel() + + hook, err := pluginkit.NewHook[greeter](tc.name, tc.plugins, tc.settings) + + if err == nil || err.Error() != tc.want { + t.Errorf("NewHook() error = %v, want %q", err, tc.want) + } + if hook != nil { + t.Errorf("NewHook() = %v, want nil", hook) + } + }) + } +} + +func TestNewHookRefusesATypeThatIsNotAnInterface(t *testing.T) { + t.Parallel() + + hook, err := pluginkit.NewHook[*hookPlugin]("content.changed", []identified{}, settingsOf(time.Hour, 20, &reports{})) + + want := "pluginkit: hook content.changed: *pluginkit_test.hookPlugin is not an interface" + if err == nil || err.Error() != want { + t.Errorf("NewHook() error = %v, want %q", err, want) + } + if hook != nil { + t.Errorf("NewHook() = %v, want nil", hook) + } +} + +func TestNewHookTakesAnyAsTheInterface(t *testing.T) { + t.Parallel() + + var ids []string + hook, err := pluginkit.NewHook[any]("content.changed", + []identified{&hookPlugin{id: "alpha"}, bystander{id: "theme"}}, settingsOf(time.Hour, 20, &reports{})) + if err != nil { + t.Fatalf("NewHook() error = %v, want nil", err) + } + + hook.Fire(t.Context(), func(_ context.Context, plugin any) error { + ids = append(ids, plugin.(identified).ID()) + return nil + }) + + if !slices.Equal(ids, []string{"alpha", "theme"}) { + t.Errorf("called = %q, want every plugin", ids) + } +} + +func TestNewHookTakesTheHostsPluginList(t *testing.T) { + t.Parallel() + + var calls []string + hook, err := pluginkit.NewHook[greeter]("content.changed", + []pluginkit.Plugin{&fakePlugin{id: "alpha", calls: &calls}}, settingsOf(time.Hour, 20, &reports{})) + if err != nil { + t.Fatalf("NewHook() error = %v, want nil", err) + } + + if got := hook.Stats().Plugins; len(got) != 0 { + t.Errorf("Stats().Plugins = %+v, want none, since the plugin is no greeter", got) + } +} + +func TestAFiringWithNoPluginAllocatesNothingAndCountsNothing(t *testing.T) { + r := &reports{} + hook := greetHook(t, settingsOf(time.Hour, 20, r), bystander{id: "theme"}) + filter, err := pluginkit.NewHook[titler]("page.title", []identified{bystander{id: "theme"}}, + settingsOf(time.Hour, 20, r)) + if err != nil { + t.Fatalf("NewHook() error = %v, want nil", err) + } + ctx := t.Context() + + allocs := testing.AllocsPerRun(100, func() { + hook.Fire(ctx, func(ctx context.Context, g greeter) error { return g.Greet(ctx) }) + if got := pluginkit.Filter(ctx, filter, "Hello", retitle); got != "Hello" { + t.Errorf("Filter() = %q, want the title unchanged", got) + } + }) + + if allocs != 0 { + t.Errorf("a firing with no plugin allocated %v times, want 0", allocs) + } + if got := hook.Stats().Firings + filter.Stats().Firings; got != 0 { + t.Errorf("firings counted = %d, want 0", got) + } +} + +func TestFireGoesOnPastAnErrorAndCountsIt(t *testing.T) { + t.Parallel() + + errIndex := errors.New("index unavailable") + log, r := &callLog{}, &reports{} + hook := greetHook(t, settingsOf(time.Hour, 20, r), + &hookPlugin{id: "alpha", log: log}, &hookPlugin{id: "beta", fail: failWith(errIndex), log: log}, + &hookPlugin{id: "gamma", log: log}) + + hook.Fire(t.Context(), greet) + + wantEqual(t, "called", log.called(), []string{"alpha", "beta", "gamma"}) + failure := onlyFailure(t, r) + wantEqual(t, "reported", shapesOf([]pluginkit.HookFailure{failure}), []failureShape{ + {Hook: "content.changed", ID: "beta", Err: "pluginkit: beta content.changed: index unavailable"}, + }) + if !errors.Is(failure.Err, errIndex) { + t.Errorf("reported error = %v, want the plugin's error in its chain", failure.Err) + } + wantEqual(t, "beta's counters", statsByID(hook)["beta"], pluginkit.PluginStats{ID: "beta", Errors: 1}) +} + +func TestFireRecoversAPanicCountsItAndReportsItsStack(t *testing.T) { + t.Parallel() + + log, r := &callLog{}, &reports{} + hook := greetHook(t, settingsOf(time.Hour, 20, r), + &hookPlugin{id: "alpha", log: log}, &hookPlugin{id: "beta", panics: "boom", log: log}, + &hookPlugin{id: "gamma", log: log}) + + hook.Fire(t.Context(), greet) + + wantEqual(t, "called", log.called(), []string{"alpha", "beta", "gamma"}) + failure := onlyFailure(t, r) + wantEqual(t, "reported", shapesOf([]pluginkit.HookFailure{failure}), []failureShape{{ + Hook: "content.changed", ID: "beta", Err: "pluginkit: beta content.changed panicked: boom", + Panicked: true, Stacked: true, + }}) + if !strings.Contains(failure.Stack, "(*hookPlugin).Greet") { + t.Errorf("reported stack = %q, want the stack of the panic", failure.Stack) + } + wantEqual(t, "beta's counters", statsByID(hook)["beta"], pluginkit.PluginStats{ID: "beta", Panics: 1}) +} + +func TestFilterPassesTheValueThroughEveryPluginPastOnesThatFail(t *testing.T) { + t.Parallel() + + tests := map[string]*hookPlugin{ + "no failure": {id: "middle", suffix: " and more"}, + "an error": {id: "middle", suffix: " and more", fail: failWith(errors.New("no title"))}, + "a panic": {id: "middle", suffix: " and more", panics: "boom"}, + } + wants := map[string]string{"no failure": "Hello | Example and more | Home", "an error": "Hello | Example | Home", + "a panic": "Hello | Example | Home"} + for name, middle := range tests { + t.Run(name, func(t *testing.T) { + t.Parallel() + + log := &callLog{} + middle.log = log + hook, err := pluginkit.NewHook[titler]("page.title", []identified{ + &hookPlugin{id: "brand", suffix: " | Example", log: log}, middle, + &hookPlugin{id: "suffix", suffix: " | Home", log: log}, + }, settingsOf(time.Hour, 20, &reports{})) + if err != nil { + t.Fatalf("NewHook() error = %v, want nil", err) + } + + got := pluginkit.Filter(t.Context(), hook, "Hello", retitle) + + if got != wants[name] { + t.Errorf("Filter() = %q, want %q", got, wants[name]) + } + if called := log.called(); !slices.Equal(called, []string{"brand", "middle", "suffix"}) { + t.Errorf("called = %q, want every plugin in order", called) + } + }) + } +} + +func TestConcurrentFiringsCountEveryFailure(t *testing.T) { + t.Parallel() + + const firings = 50 + r := &reports{} + hook := greetHook(t, settingsOf(time.Hour, 20, r), + &hookPlugin{id: "alpha", log: &callLog{}}, + &hookPlugin{id: "beta", fail: failWith(errors.New("index unavailable")), log: &callLog{}}, + &hookPlugin{id: "gamma", panics: "boom", log: &callLog{}}) + + var wg sync.WaitGroup + for range firings { + wg.Go(func() { hook.Fire(context.Background(), greet) }) + } + wg.Wait() + + wantEqual(t, "Stats()", hook.Stats(), pluginkit.HookStats{ + Name: "content.changed", Firings: firings, + Plugins: []pluginkit.PluginStats{{ID: "alpha"}, {ID: "beta", Errors: firings}, {ID: "gamma", Panics: firings}}, + }) + if got := len(r.all()); got != 2*firings { + t.Errorf("reported %d failures, want %d", got, 2*firings) + } +} + +func BenchmarkFireWithFiftyPlugins(b *testing.B) { + plugins := make([]identified, 50) + for i := range plugins { + plugins[i] = &hookPlugin{id: fmt.Sprintf("plugin-%02d", i), log: &callLog{}} + } + hook, err := pluginkit.NewHook[greeter]("content.changed", plugins, settingsOf(time.Hour, 20, &reports{})) + if err != nil { + b.Fatalf("NewHook() error = %v, want nil", err) + } + ctx := context.Background() + + for b.Loop() { + hook.Fire(ctx, func(context.Context, greeter) error { return nil }) + } +} diff --git a/pluginkit/pluginkit.go b/pluginkit/pluginkit.go index 16f3ec9..f97d471 100644 --- a/pluginkit/pluginkit.go +++ b/pluginkit/pluginkit.go @@ -1,7 +1,8 @@ // SPDX-License-Identifier: Apache-2.0 // Package pluginkit provides compile-time plugin infrastructure: a lifecycle -// contract, a plugin host, and route guarding for plugin namespaces. +// contract, a plugin host, hooks that call every plugin implementing an +// interface, and route guarding for plugin namespaces. package pluginkit import ( From d978521ecd65188cffc3557a2c5aac5759492c02 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 6 Nov 2026 11:50:44 +0100 Subject: [PATCH 4/8] test(pluginkit): run the hook scenarios against the hook runner --- pluginkit/features/features_test.go | 2 +- pluginkit/features/go.mod | 5 +- pluginkit/features/hooks.feature | 36 +- pluginkit/features/steps_hooks_test.go | 505 +++++++++++++++++++++++++ 4 files changed, 529 insertions(+), 19 deletions(-) create mode 100644 pluginkit/features/steps_hooks_test.go diff --git a/pluginkit/features/features_test.go b/pluginkit/features/features_test.go index d7178e6..c339027 100644 --- a/pluginkit/features/features_test.go +++ b/pluginkit/features/features_test.go @@ -35,5 +35,5 @@ func runFeature(t *testing.T, path string, initialize func(*godog.ScenarioContex } func TestHooks(t *testing.T) { - runFeature(t, "hooks.feature", func(*godog.ScenarioContext) {}) + runFeature(t, "hooks.feature", initializeHooks(t)) } diff --git a/pluginkit/features/go.mod b/pluginkit/features/go.mod index c4ed7f7..148e6cf 100644 --- a/pluginkit/features/go.mod +++ b/pluginkit/features/go.mod @@ -2,7 +2,10 @@ module github.com/gopherium/framework/pluginkit/features go 1.27.3 -require github.com/cucumber/godog v0.16.0 +require ( + github.com/cucumber/godog v0.16.0 + github.com/gopherium/framework/pluginkit v0.0.0 +) require ( github.com/cucumber/gherkin/go/v42 v42.0.0 // indirect diff --git a/pluginkit/features/hooks.feature b/pluginkit/features/hooks.feature index 9af149d..c5dd4cd 100644 --- a/pluginkit/features/hooks.feature +++ b/pluginkit/features/hooks.feature @@ -6,15 +6,13 @@ Feature: Calling the plugins that implement a hook among all its plugins. A plugin that fails, panics or runs slow never stops the plugins after it, and the counters name the plugin at fault. - @wip Scenario: Every plugin that implements the hook is called in order - Given the plugins "analytics", "feed" and "seo-basics" implement the hook "public.head-tags" + Given the plugins "seo-basics", "analytics" and "feed" implement the hook "public.head-tags" And the plugin "theme" is registered without implementing it When the hook fires - Then "analytics", "feed" and "seo-basics" are called in that order + Then "seo-basics", "analytics" and "feed" are called in that order And "theme" is not called - @wip Scenario: A failing plugin leaves the plugins after it running Given the plugins "analytics", "feed" and "seo-basics" implement the hook "content.changed" And "feed" fails with "index unavailable" @@ -23,7 +21,6 @@ Feature: Calling the plugins that implement a hook And the report holds "pluginkit: feed content.changed: index unavailable" And "feed" is counted 1 error - @wip Scenario: A panicking plugin leaves the plugins after it running Given the plugins "analytics", "feed" and "seo-basics" implement the hook "content.changed" And "feed" panics with "boom" @@ -32,7 +29,6 @@ Feature: Calling the plugins that implement a hook And the report holds "pluginkit: feed content.changed panicked: boom" with the stack of the panic And "feed" is counted 1 panic - @wip Scenario: The plugins after a slow one are still called Given the plugins "analytics", "feed" and "seo-basics" implement the hook "public.head-tags" And the hook has a budget of 2 ms @@ -42,7 +38,6 @@ Feature: Calling the plugins that implement a hook And "feed" and "seo-basics" are called after the deadline passed And the hook is counted 1 overrun - @wip Scenario: An error caused by the ended deadline is not the plugin's fault Given the plugins "analytics" and "search" implement the hook "content.changed" And the hook has a budget of 2 ms @@ -52,7 +47,6 @@ Feature: Calling the plugins that implement a hook Then "search" is counted 0 errors and 1 call whose context ended And the report marks the failure of "search" as caused by the ended context - @wip Scenario: An error of its own after the deadline still counts against the plugin Given the plugins "analytics" and "search" implement the hook "content.changed" And the hook has a budget of 2 ms @@ -61,7 +55,6 @@ Feature: Calling the plugins that implement a hook When the hook fires Then "search" is counted 1 error and 0 calls whose context ended - @wip Scenario: A plugin that hides the context's error behind its own text is counted an error Given the plugins "analytics" and "search" implement the hook "content.changed" And the hook has a budget of 2 ms @@ -70,8 +63,7 @@ Feature: Calling the plugins that implement a hook When the hook fires Then "search" is counted 1 error and 0 calls whose context ended - @wip - Scenario: The firing that runs over its budget charges no plugin + Scenario: An untimed overrun charges no plugin Given the plugins "analytics", "reviews" and "feed" implement the hook "public.head-tags" And the hook has a budget of 2 ms and times each plugin for 20 firings after an overrun And "analytics" takes 3 ms @@ -79,24 +71,35 @@ Feature: Calling the plugins that implement a hook Then the hook is counted 1 overrun And no plugin is charged an overrun - @wip Scenario: A timed overrun is charged to the slowest plugin - Given the plugins "analytics", "reviews" and "feed" implement the hook "public.head-tags" + Given the plugins "reviews", "analytics" and "feed" implement the hook "public.head-tags" And the hook has a budget of 2 ms and times each plugin for 20 firings after an overrun And the hook has run over its budget once - When the hook fires while "analytics" takes 1.9 ms, "reviews" takes 0.7 ms and "feed" takes 0.1 ms + When the hook fires while the plugins take + | plugin | ms | + | reviews | 0.5 | + | analytics | 1.2 | + | feed | 0.9 | Then "analytics" is charged 1 overrun And "reviews" and "feed" are charged no overrun - @wip Scenario: Each plugin is timed only for the firings after an overrun Given the plugins "analytics" and "feed" implement the hook "public.head-tags" And the hook has a budget of 2 ms and times each plugin for 3 firings after an overrun And the hook has run over its budget once When the hook fires 5 times within its budget Then "analytics" and "feed" are each timed in 3 firings + And no plugin is charged an overrun + + Scenario: An overrun among the timed firings starts the timing again in full + Given the plugins "analytics" and "feed" implement the hook "public.head-tags" + And the hook has a budget of 2 ms and times each plugin for 4 firings after an overrun + And the hook has run over its budget once + And the hook fires 2 times within its budget + And the hook has run over its budget once + When the hook fires 5 times within its budget + Then "analytics" and "feed" are each timed in 7 firings - @wip Scenario: A filter passes the value through every plugin Given the plugins "brand" and "suffix" implement the filter hook "page.title" And "brand" puts "Example: " before the title @@ -104,7 +107,6 @@ Feature: Calling the plugins that implement a hook When the hook filters the title "Hello" Then the title becomes "Example: Hello | Home" - @wip Scenario: A filter keeps the incoming value when a plugin fails or panics Given the plugins "brand", "broken", "loud" and "suffix" implement the filter hook "page.title" And "brand" puts "Example: " before the title diff --git a/pluginkit/features/steps_hooks_test.go b/pluginkit/features/steps_hooks_test.go new file mode 100644 index 0000000..e676be5 --- /dev/null +++ b/pluginkit/features/steps_hooks_test.go @@ -0,0 +1,505 @@ +// SPDX-License-Identifier: Apache-2.0 + +package features_test + +import ( + "context" + "errors" + "fmt" + "regexp" + "slices" + "strings" + "testing" + "testing/synctest" + "time" + + "github.com/cucumber/godog" + + "github.com/gopherium/framework/pluginkit" +) + +// handler is the interface an action hook calls. +type handler interface { + Handle(ctx context.Context) error +} + +// titler is the interface a filter hook calls. +type titler interface { + Title(ctx context.Context, title string) (string, error) +} + +// identified is the least a plugin offers a hook. +type identified interface { + ID() string +} + +// quoted finds every quoted name in a list such as "a", "b" and "c". +var quoted = regexp.MustCompile(`"([^"]*)"`) + +// names returns the quoted names of list, in order. +func names(list string) []string { + var found []string + for _, match := range quoted.FindAllStringSubmatch(list, -1) { + found = append(found, match[1]) + } + return found +} + +// scenePlugin is a plugin of a scenario, doing what the scenario's steps tell it. +type scenePlugin struct { + id string + takes time.Duration + panics string + fail func(ctx context.Context) error + before, after string + world *hookWorld +} + +// ID returns the plugin's id. +func (p *scenePlugin) ID() string { + return p.id +} + +// Handle records the call, takes the plugin's time, then panics or fails as told. +func (p *scenePlugin) Handle(ctx context.Context) error { + p.world.calls = append(p.world.calls, p.id) + p.world.late[p.id] = ctx.Err() != nil + time.Sleep(p.takes) + if p.panics != "" { + panic(p.panics) + } + if p.fail != nil { + return p.fail(ctx) + } + return nil +} + +// Title handles the call, then returns title between the plugin's words, or nothing on a failure. +func (p *scenePlugin) Title(ctx context.Context, title string) (string, error) { + if err := p.Handle(ctx); err != nil { + return "", err + } + return p.before + title + p.after, nil +} + +// bystander is a plugin that implements no hook interface. +type bystander struct { + id string +} + +// ID returns the plugin's id. +func (b bystander) ID() string { + return b.id +} + +// hookWorld is the state of one scenario. +type hookWorld struct { + t *testing.T + name string + budget time.Duration + timedFirings int + plugins []identified + byID map[string]*scenePlugin + calls []string + late map[string]bool + failures []pluginkit.HookFailure + actions *pluginkit.Hook[handler] + title string +} + +// hookWorldKey carries a scenario's world in its context. +type hookWorldKey struct{} + +// worldOf returns the world of the scenario ctx belongs to. +func worldOf(ctx context.Context) *hookWorld { + return ctx.Value(hookWorldKey{}).(*hookWorld) +} + +// plugin returns the plugin id of the scenario ctx belongs to, failing when the scenario never named it. +func plugin(ctx context.Context, id string) (*scenePlugin, error) { + if p, ok := worldOf(ctx).byID[id]; ok { + return p, nil + } + return nil, fmt.Errorf("no plugin %q in this scenario", id) +} + +// settings returns the hook settings of the scenario, reporting into its failures. +func (w *hookWorld) settings() pluginkit.HookSettings { + return pluginkit.HookSettings{ + Budget: w.budget, TimedFirings: w.timedFirings, + Report: func(failure pluginkit.HookFailure) { w.failures = append(w.failures, failure) }, + } +} + +// hook builds the action hook of the scenario once and returns it. +func (w *hookWorld) hook() (*pluginkit.Hook[handler], error) { + if w.actions != nil { + return w.actions, nil + } + hook, err := pluginkit.NewHook[handler](w.name, w.plugins, w.settings()) + w.actions = hook + return hook, err +} + +// onFakeClock runs fn on a fake clock, so the times a scenario names pass in no real time. +func (w *hookWorld) onFakeClock(fn func()) { + synctest.Test(w.t, func(*testing.T) { fn() }) +} + +// statsOf returns the counters of the plugin id in the action hook. +func (w *hookWorld) statsOf(id string) (pluginkit.PluginStats, error) { + if w.actions == nil { + return pluginkit.PluginStats{}, errors.New("the hook never fired") + } + for _, stats := range w.actions.Stats().Plugins { + if stats.ID == id { + return stats, nil + } + } + return pluginkit.PluginStats{}, fmt.Errorf("no counters for %s", id) +} + +// implement registers the plugins of list, in order, as implementing the hook name. +func implement(ctx context.Context, list, name string) { + w := worldOf(ctx) + w.name = name + for _, id := range names(list) { + p := &scenePlugin{id: id, world: w} + w.plugins = append(w.plugins, p) + w.byID[id] = p + } +} + +// registerBystander registers a plugin that implements no hook interface. +func registerBystander(ctx context.Context, id string) { + w := worldOf(ctx) + w.plugins = append(w.plugins, bystander{id: id}) +} + +// setBudget gives the hook a budget of text milliseconds, such as 1.9, read exactly. +func setBudget(ctx context.Context, text string) error { + budget, err := time.ParseDuration(text + "ms") + worldOf(ctx).budget = budget + return err +} + +// setTiming gives the hook a budget and a count of firings timed after an overrun. +func setTiming(ctx context.Context, text string, timedFirings int) error { + worldOf(ctx).timedFirings = timedFirings + return setBudget(ctx, text) +} + +// setTakes makes the plugin id take text milliseconds on each call. +func setTakes(ctx context.Context, id, text string) error { + p, err := plugin(ctx, id) + if err != nil { + return err + } + p.takes, err = time.ParseDuration(text + "ms") + return err +} + +// setFailure makes the plugin id fail with fail. +func setFailure(ctx context.Context, id string, fail func(ctx context.Context) error) error { + p, err := plugin(ctx, id) + if err == nil { + p.fail = fail + } + return err +} + +// failsWith makes the plugin id fail with its own error text. +func failsWith(ctx context.Context, id, text string) error { + return setFailure(ctx, id, func(context.Context) error { return errors.New(text) }) +} + +// failsWithEndedContext makes the plugin id fail with the error of its ended context, or with only its text. +func failsWithEndedContext(ctx context.Context, id, what string) error { + verb := "%w" + if what == "text" { + verb = "%v" + } + return setFailure(ctx, id, func(ctx context.Context) error { return fmt.Errorf("index write: "+verb, ctx.Err()) }) +} + +// panicsWith makes the plugin id panic with text. +func panicsWith(ctx context.Context, id, text string) error { + p, err := plugin(ctx, id) + if err == nil { + p.panics = text + } + return err +} + +// putsAround makes the plugin id put text before or after the title it filters. +func putsAround(ctx context.Context, id, text, where string) error { + p, err := plugin(ctx, id) + if err != nil { + return err + } + if where == "before" { + p.before = text + } else { + p.after = text + } + return nil +} + +// handle calls Handle on one plugin of the hook. +func handle(ctx context.Context, h handler) error { + return h.Handle(ctx) +} + +// fireTimes fires the action hook n times on the fake clock. +func fireTimes(ctx context.Context, n int) error { + w := worldOf(ctx) + hook, err := w.hook() + if err != nil { + return err + } + w.onFakeClock(func() { + for range n { + hook.Fire(context.Background(), handle) + } + }) + return nil +} + +// fire fires the action hook once. +func fire(ctx context.Context) error { + return fireTimes(ctx, 1) +} + +// overrunOnce fires the action hook once with every call taking twice its budget. +func overrunOnce(ctx context.Context) error { + w := worldOf(ctx) + hook, err := w.hook() + if err != nil { + return err + } + w.onFakeClock(func() { + hook.Fire(context.Background(), func(context.Context, handler) error { + time.Sleep(2 * w.budget) + return nil + }) + }) + return nil +} + +// fireWhileTaking fires the action hook once after giving each plugin of table the milliseconds beside it. +func fireWhileTaking(ctx context.Context, table *godog.Table) error { + for _, row := range table.Rows[1:] { + if err := setTakes(ctx, row.Cells[0].Value, row.Cells[1].Value); err != nil { + return err + } + } + return fire(ctx) +} + +// filterTitle passes title through the filter hook of the scenario. +func filterTitle(ctx context.Context, title string) error { + w := worldOf(ctx) + hook, err := pluginkit.NewHook[titler](w.name, w.plugins, w.settings()) + if err != nil { + return err + } + w.onFakeClock(func() { + w.title = pluginkit.Filter(context.Background(), hook, title, + func(ctx context.Context, t titler, title string) (string, error) { return t.Title(ctx, title) }) + }) + return nil +} + +// calledInOrder checks that the plugins of list, and no others, were called in that order. +func calledInOrder(ctx context.Context, list string) error { + if called, want := worldOf(ctx).calls, names(list); !slices.Equal(called, want) { + return fmt.Errorf("called %q, want %q", called, want) + } + return nil +} + +// notCalled checks that the plugin id was never called. +func notCalled(ctx context.Context, id string) error { + if slices.Contains(worldOf(ctx).calls, id) { + return fmt.Errorf("%s was called", id) + } + return nil +} + +// calledLate checks that every plugin of list was called after the firing's deadline had passed. +func calledLate(ctx context.Context, list string) error { + for _, id := range names(list) { + if !worldOf(ctx).late[id] { + return fmt.Errorf("%s was called before the deadline passed", id) + } + } + return nil +} + +// reportHolds checks that a reported failure has the text want, and the panicking plugin's stack only when named. +func reportHolds(ctx context.Context, want, stack string) error { + failures := worldOf(ctx).failures + for _, failure := range failures { + if failure.Err.Error() == want && strings.Contains(failure.Stack, "(*scenePlugin).Handle") == (stack != "") { + return nil + } + } + return fmt.Errorf("reported %+v, want %q%s", failures, want, stack) +} + +// reportMarksContextEnded checks that the failure of the plugin id is marked as caused by the ended context. +func reportMarksContextEnded(ctx context.Context, id string) error { + failures := worldOf(ctx).failures + for _, failure := range failures { + if failure.ID == id && failure.ContextEnded { + return nil + } + } + return fmt.Errorf("reported %+v, want a failure of %s marked as context ended", failures, id) +} + +// countedFailures checks the errors or panics counted for the plugin id. +func countedFailures(ctx context.Context, id string, want int, kind string) error { + stats, err := worldOf(ctx).statsOf(id) + if err != nil { + return err + } + got := stats.Errors + if kind == "panic" || kind == "panics" { + got = stats.Panics + } + if got != uint64(want) { + return fmt.Errorf("%s is counted %d %s, want %d", id, got, kind, want) + } + return nil +} + +// countedErrorsAndEnded checks the errors and the calls whose context ended counted for the plugin id. +func countedErrorsAndEnded(ctx context.Context, id string, errs, ended int) error { + stats, err := worldOf(ctx).statsOf(id) + if err != nil { + return err + } + if stats.Errors != uint64(errs) || stats.ContextEnded != uint64(ended) { + return fmt.Errorf("%s is counted %+v, want %d errors and %d calls whose context ended", id, stats, errs, ended) + } + return nil +} + +// hookOverruns checks the overruns counted on the hook. +func hookOverruns(ctx context.Context, want int) error { + w := worldOf(ctx) + if w.actions == nil { + return errors.New("the hook never fired") + } + if got := w.actions.Stats().Overruns; got != uint64(want) { + return fmt.Errorf("the hook is counted %d overruns, want %d", got, want) + } + return nil +} + +// chargedOverruns checks the overruns charged to the plugin id. +func chargedOverruns(ctx context.Context, id string, want int) error { + stats, err := worldOf(ctx).statsOf(id) + if err == nil && stats.Overruns != uint64(want) { + err = fmt.Errorf("%s is charged %d overruns, want %d", id, stats.Overruns, want) + } + return err +} + +// chargedNone checks that no plugin of list is charged an overrun. +func chargedNone(ctx context.Context, list string) error { + for _, id := range names(list) { + if err := chargedOverruns(ctx, id, 0); err != nil { + return err + } + } + return nil +} + +// noPluginCharged checks that no plugin of the hook is charged an overrun. +func noPluginCharged(ctx context.Context) error { + for id := range worldOf(ctx).byID { + if err := chargedOverruns(ctx, id, 0); err != nil { + return err + } + } + return nil +} + +// timedIn checks that every plugin of list was timed in want firings. +func timedIn(ctx context.Context, list string, want int) error { + for _, id := range names(list) { + stats, err := worldOf(ctx).statsOf(id) + if err == nil && stats.TimedCalls != uint64(want) { + err = fmt.Errorf("%s was timed in %d firings, want %d", id, stats.TimedCalls, want) + } + if err != nil { + return err + } + } + return nil +} + +// titleBecomes checks the title the filter returned. +func titleBecomes(ctx context.Context, want string) error { + if got := worldOf(ctx).title; got != want { + return fmt.Errorf("the title became %q, want %q", got, want) + } + return nil +} + +// initializeHooks returns the steps of the hooks feature, each scenario with its own world on t's fake clock. +func initializeHooks(t *testing.T) func(*godog.ScenarioContext) { + return func(sc *godog.ScenarioContext) { + sc.Before(func(ctx context.Context, _ *godog.Scenario) (context.Context, error) { + w := &hookWorld{ + t: t, budget: time.Hour, timedFirings: 20, byID: map[string]*scenePlugin{}, late: map[string]bool{}, + } + return context.WithValue(ctx, hookWorldKey{}, w), nil + }) + givenHooks(sc) + whenHooks(sc) + thenHooks(sc) + } +} + +// givenHooks registers the steps that set a scenario up. +func givenHooks(sc *godog.ScenarioContext) { + sc.Step(`^the plugins (.+) implement the (?:filter )?hook "([^"]*)"$`, implement) + sc.Step(`^the plugin "([^"]*)" is registered without implementing it$`, registerBystander) + sc.Step(`^the hook has a budget of (\S+) ms$`, setBudget) + sc.Step(`^the hook has a budget of (\S+) ms and times each plugin for (\d+) firings after an overrun$`, setTiming) + sc.Step(`^"([^"]*)" takes (\S+) ms$`, setTakes) + sc.Step(`^"([^"]*)" fails with "([^"]*)"$`, failsWith) + sc.Step(`^"([^"]*)" fails with the (error|text) of its ended context(?: but not the error itself)?$`, + failsWithEndedContext) + sc.Step(`^"([^"]*)" panics with "([^"]*)"$`, panicsWith) + sc.Step(`^"([^"]*)" puts "([^"]*)" (before|after) the title$`, putsAround) + sc.Step(`^the hook has run over its budget once$`, overrunOnce) +} + +// whenHooks registers the steps that fire a scenario's hook. +func whenHooks(sc *godog.ScenarioContext) { + sc.Step(`^the hook fires$`, fire) + sc.Step(`^the hook fires (\d+) times within its budget$`, fireTimes) + sc.Step(`^the hook fires while the plugins take$`, fireWhileTaking) + sc.Step(`^the hook filters the title "([^"]*)"$`, filterTitle) +} + +// thenHooks registers the steps that check what a scenario's firing did. +func thenHooks(sc *godog.ScenarioContext) { + sc.Step(`^(.+) are called in that order$`, calledInOrder) + sc.Step(`^"([^"]*)" is not called$`, notCalled) + sc.Step(`^(.+) are called after the deadline passed$`, calledLate) + sc.Step(`^the report holds "([^"]*)"( with the stack of the panic)?$`, reportHolds) + sc.Step(`^the report marks the failure of "([^"]*)" as caused by the ended context$`, reportMarksContextEnded) + sc.Step(`^"([^"]*)" is counted (\d+) (errors?|panics?)$`, countedFailures) + sc.Step(`^"([^"]*)" is counted (\d+) errors? and (\d+) calls? whose context ended$`, countedErrorsAndEnded) + sc.Step(`^the hook is counted (\d+) overruns?$`, hookOverruns) + sc.Step(`^"([^"]*)" is charged (\d+) overruns?$`, chargedOverruns) + sc.Step(`^(.+) are charged no overrun$`, chargedNone) + sc.Step(`^no plugin is charged an overrun$`, noPluginCharged) + sc.Step(`^(.+) are each timed in (\d+) firings$`, timedIn) + sc.Step(`^the title becomes "([^"]*)"$`, titleBecomes) +} From 49073fb26a564587dafa783d9f57cceaa41c21db Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 6 Nov 2026 13:32:06 +0100 Subject: [PATCH 5/8] fix(pluginkit): keep a plugin's error handling inside its recover and its time, and Report outside both --- pluginkit/CHANGELOG.md | 2 +- pluginkit/hook.go | 96 +++++++++++----- pluginkit/hook_budget_test.go | 200 +++++++++++++++++++++++++++++++++- pluginkit/hook_test.go | 101 +++++++++++++++-- 4 files changed, 358 insertions(+), 41 deletions(-) diff --git a/pluginkit/CHANGELOG.md b/pluginkit/CHANGELOG.md index 190aaf8..c2d3608 100644 --- a/pluginkit/CHANGELOG.md +++ b/pluginkit/CHANGELOG.md @@ -7,7 +7,7 @@ Releases of this module are tagged `pluginkit/vX.Y.Z`. Releases up to - `NewHook` collects the plugins that implement an interface into a `Hook`. `Hook.Fire` calls an action on each in registration order and `Filter` passes a value through each, every call inside its own recover. - One firing shares `HookSettings.Budget` as a context deadline. The plugins after a slow one are still called, and an error that matches the ended context counts as `ContextEnded`, not as that plugin's fault. -- After a firing runs over its budget, the next `TimedFirings` firings time each plugin and charge a timed overrun to the slowest. `Stats` returns every counter, and `HookSettings.Report` receives each error and panic as a `HookFailure`. +- After a firing runs over its budget, the next `TimedFirings` firings time each plugin, without the time of `Report`, and a timed firing whose plugins together run over is charged to the slowest. `Stats` returns every counter, and `HookSettings.Report` receives each error and panic as a `HookFailure` and must not panic. ## 0.9.0 - 2026-11-05 diff --git a/pluginkit/hook.go b/pluginkit/hook.go index 43bd513..b9f76a7 100644 --- a/pluginkit/hook.go +++ b/pluginkit/hook.go @@ -14,11 +14,11 @@ import ( // HookSettings are the values a hook runs under, each one required. type HookSettings struct { - // Budget is the time one firing gives all its plugins together. + // Budget is the time one firing gives all its plugins together, the time of Report included. Budget time.Duration // TimedFirings is how many firings after an overrun time each plugin. TimedFirings int - // Report receives every error and panic of a plugin inside the firing, from any goroutine at once. + // Report receives every error and panic of a plugin inside the firing, from any goroutine at once, and must not panic. Report func(HookFailure) } @@ -30,7 +30,8 @@ type HookFailure struct { Panicked bool // ContextEnded is true for an error that matches the firing's context after that context ended. ContextEnded bool - Err error + // Err names the plugin and the hook, and for an error wraps the plugin's error, whose methods are the plugin's code. + Err error // Stack is the stack of a panic, and empty for an error. Stack string } @@ -49,11 +50,11 @@ type PluginStats struct { Errors uint64 Panics uint64 ContextEnded uint64 - // Overruns counts the timed firings that ran over their budget with this plugin as the slowest. + // Overruns counts the timed firings whose plugins together ran over the budget, with this plugin as the slowest. Overruns uint64 // TimedCalls counts the calls timed while firings were timed after an overrun. TimedCalls uint64 - // TimedTime is the total time of those calls. + // TimedTime is the total time of those calls, without the time Report took. TimedTime time.Duration } @@ -165,7 +166,7 @@ func (h *Hook[C]) Stats() HookStats { return stats } -// fire runs one firing, counting an overrun and charging it to the slowest plugin when the firing was timed. +// fire runs one firing, counting an overrun, charged to the slowest plugin when timed plugins ran over together. func (h *Hook[C]) fire(ctx context.Context, call func(context.Context, C) error) { h.firings.Add(1) began := time.Now() @@ -176,7 +177,7 @@ func (h *Hook[C]) fire(ctx context.Context, call func(context.Context, C) error) slowest = h.callTimed(ctx, call) } else { for i, plugin := range h.plugins { - h.call(ctx, i, plugin, call) + h.report(i, run(ctx, plugin, call)) } } if time.Since(began) <= h.settings.Budget { @@ -202,41 +203,47 @@ func (h *Hook[C]) takeTimedFiring() bool { } } -// callTimed calls every plugin in order, timing each, and returns the index of the slowest. +// callTimed calls and times every plugin in order, returning the slowest, or -1 when together they kept the budget. func (h *Hook[C]) callTimed(ctx context.Context, call func(context.Context, C) error) int { - slowest, longest := 0, time.Duration(0) + slowest, longest, total := 0, time.Duration(0), time.Duration(0) for i, plugin := range h.plugins { began := time.Now() - h.call(ctx, i, plugin, call) + out := run(ctx, plugin, call) took := time.Since(began) + total += took h.counters[i].timedCalls.Add(1) h.counters[i].timedTime.Add(int64(took)) if took > longest { slowest, longest = i, took } + h.report(i, out) + } + if total <= h.settings.Budget { + return -1 } return slowest } -// call calls one plugin, then counts and reports its error or panic. -func (h *Hook[C]) call(ctx context.Context, i int, plugin C, call func(context.Context, C) error) { - if out := run(ctx, plugin, call); out.recovered != nil || out.err != nil { - h.settings.Report(h.failureOf(ctx, i, out)) +// report counts and reports what went wrong in one call of plugin i, if anything did. +func (h *Hook[C]) report(i int, out *outcome) { + if out != nil { + h.settings.Report(h.failureOf(i, out)) } } // failureOf counts what went wrong in a call of plugin i and returns it as the failure Report receives. -func (h *Hook[C]) failureOf(ctx context.Context, i int, out outcome) HookFailure { +func (h *Hook[C]) failureOf(i int, out *outcome) HookFailure { failure := HookFailure{Hook: h.name, ID: h.ids[i]} counters := &h.counters[i] - if out.recovered != nil { + named := "pluginkit: " + failure.ID + " " + h.name + if out.panicked { failure.Panicked, failure.Stack = true, out.stack - failure.Err = panicError(fmt.Sprintf("pluginkit: %s %s panicked: %v", failure.ID, h.name, out.recovered)) + failure.Err = panicError(named + " panicked: " + out.text) counters.panics.Add(1) return failure } - failure.Err = fmt.Errorf("pluginkit: %s %s: %w", failure.ID, h.name, out.err) - failure.ContextEnded = ctx.Err() != nil && errors.Is(out.err, ctx.Err()) + failure.Err = &pluginError{text: named + ": " + out.text, err: out.err} + failure.ContextEnded = out.ended if failure.ContextEnded { counters.contextEnded.Add(1) } else { @@ -245,20 +252,51 @@ func (h *Hook[C]) failureOf(ctx context.Context, i int, out outcome) HookFailure return failure } -// outcome is what one call of a plugin did wrong, a panic with its stack or an error, if anything. +// outcome is what went wrong in one call of a plugin, a panic with its stack or an error, with its text. type outcome struct { - recovered any - stack string - err error + panicked bool + stack string + text string + err error + // ended is true for an error that matches the firing's context after that context ended. + ended bool +} + +// run calls one plugin inside a recover, answering nil when the call succeeded, else what went wrong. +func run[C any](ctx context.Context, plugin C, call func(context.Context, C) error) (out *outcome) { + defer func() { + if recovered := recover(); recovered != nil { + out = &outcome{panicked: true, stack: string(debug.Stack()), text: describe(recovered)} + } + }() + if err := call(ctx, plugin); err != nil { + return &outcome{err: err, text: describe(err), ended: ctx.Err() != nil && errors.Is(err, ctx.Err())} + } + return nil } -// run calls one plugin inside a recover, answering what it panicked with and its stack, or its error. -func run[C any](ctx context.Context, plugin C, call func(context.Context, C) error) (out outcome) { +// describe returns v as fmt prints it, or its type when printing it panics. +func describe(v any) (text string) { defer func() { - if out.recovered = recover(); out.recovered != nil { - out.stack = string(debug.Stack()) + if recover() != nil { + text = fmt.Sprintf("%T whose text panicked", v) } }() - out.err = call(ctx, plugin) - return out + return fmt.Sprint(v) +} + +// pluginError is a plugin's error with the plugin and the hook named before its text. +type pluginError struct { + text string + err error +} + +// Error returns the error's text. +func (e *pluginError) Error() string { + return e.text +} + +// Unwrap returns the plugin's own error. +func (e *pluginError) Unwrap() error { + return e.err } diff --git a/pluginkit/hook_budget_test.go b/pluginkit/hook_budget_test.go index 04d8e12..3a82bed 100644 --- a/pluginkit/hook_budget_test.go +++ b/pluginkit/hook_budget_test.go @@ -7,6 +7,7 @@ import ( "errors" "fmt" "runtime" + "strings" "testing" "testing/synctest" "time" @@ -24,7 +25,7 @@ func timedHook(t *testing.T, timedFirings int, plugins ...identified) (*pluginki return greetHook(t, settingsOf(budget, timedFirings, r), plugins...), r } -// overrunOnce fires hook once with a plugin that runs past the budget. +// overrunOnce fires hook once with every call taking twice the budget. func overrunOnce(t *testing.T, hook *pluginkit.Hook[greeter]) { t.Helper() hook.Fire(t.Context(), func(context.Context, greeter) error { @@ -249,6 +250,164 @@ func TestATimedOverrunIsChargedToTheSlowestOfThatFiringOnly(t *testing.T) { }) } +// slowText is an error whose text takes 3 ms to build. +type slowText struct{} + +// Error returns the error's text after 3 ms. +func (slowText) Error() string { + time.Sleep(3 * time.Millisecond) + return "rating unavailable" +} + +func TestTheTimeOfReportIsLeftOutOfThePluginsTime(t *testing.T) { + t.Parallel() + + tests := map[string]struct { + err error + panics any + reviews, analytics time.Duration + want []pluginkit.PluginStats + }{ + "so a firing that only Report runs over charges no plugin": { + errors.New("rating unavailable"), nil, 0, 500 * time.Microsecond, []pluginkit.PluginStats{ + {ID: "reviews", Errors: 1, TimedCalls: 1}, + {ID: "analytics", TimedCalls: 1, TimedTime: 500 * time.Microsecond}, + }, + }, + "so plugins that together take exactly the budget charge none": { + errors.New("rating unavailable"), nil, budget, 0, []pluginkit.PluginStats{ + {ID: "reviews", Errors: 1, TimedCalls: 1, TimedTime: budget}, + {ID: "analytics", TimedCalls: 1}, + }, + }, + "so plugins that together run over charge the slowest of their own times": { + errors.New("rating unavailable"), nil, 200 * time.Microsecond, 1900 * time.Microsecond, + []pluginkit.PluginStats{ + {ID: "reviews", Errors: 1, TimedCalls: 1, TimedTime: 200 * time.Microsecond}, + {ID: "analytics", Overruns: 1, TimedCalls: 1, TimedTime: 1900 * time.Microsecond}, + }, + }, + "but the time of the plugin's own error text stays the plugin's": { + slowText{}, nil, 0, 500 * time.Microsecond, []pluginkit.PluginStats{ + {ID: "reviews", Errors: 1, Overruns: 1, TimedCalls: 1, TimedTime: 3 * time.Millisecond}, + {ID: "analytics", TimedCalls: 1, TimedTime: 500 * time.Microsecond}, + }, + }, + "and so does the time of the text of its panic": { + nil, slowText{}, 0, 500 * time.Microsecond, []pluginkit.PluginStats{ + {ID: "reviews", Panics: 1, Overruns: 1, TimedCalls: 1, TimedTime: 3 * time.Millisecond}, + {ID: "analytics", TimedCalls: 1, TimedTime: 500 * time.Microsecond}, + }, + }, + } + for name, tc := range tests { + t.Run(name, func(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + settings := pluginkit.HookSettings{Budget: budget, TimedFirings: 20, Report: func(pluginkit.HookFailure) { + time.Sleep(3 * time.Millisecond) + }} + hook := greetHook(t, settings, + &hookPlugin{id: "reviews", takes: tc.reviews, fail: failWith(tc.err), panics: tc.panics, log: &callLog{}}, + &hookPlugin{id: "analytics", takes: tc.analytics, log: &callLog{}}) + overrunOnce(t, hook) + + fireTimes(t, hook, 1) + + wantEqual(t, "Stats()", hook.Stats(), pluginkit.HookStats{ + Name: "content.changed", Firings: 2, Overruns: 2, Plugins: tc.want, + }) + }) + }) + } +} + +func TestAFiringThatOnlyReportRunsOverTimesTheFiringsAfterIt(t *testing.T) { + t.Parallel() + + tests := map[string]struct { + timed bool + overruns uint64 + want pluginkit.PluginStats + }{ + "from an untimed firing": {false, 1, pluginkit.PluginStats{ID: "alpha", Errors: 6, TimedCalls: 3}}, + "from a timed firing, in full again": { + true, 2, pluginkit.PluginStats{ID: "alpha", Errors: 6, TimedCalls: 4}, + }, + } + for name, tc := range tests { + t.Run(name, func(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + reportTakes := 3 * time.Millisecond + settings := pluginkit.HookSettings{Budget: budget, TimedFirings: 3, Report: func(pluginkit.HookFailure) { + time.Sleep(reportTakes) + }} + hook := greetHook(t, settings, + &hookPlugin{id: "alpha", fail: failWith(errors.New("index unavailable")), log: &callLog{}}) + if tc.timed { + overrunOnce(t, hook) + } + fireTimes(t, hook, 1) + reportTakes = 0 + + fireTimes(t, hook, 5) + + wantEqual(t, "Stats().Overruns", hook.Stats().Overruns, tc.overruns) + wantEqual(t, "alpha's counters", statsByID(hook)["alpha"], tc.want) + }) + }) + } +} + +func TestAPanicInReportLeavesFire(t *testing.T) { + t.Parallel() + + for name, timed := range map[string]bool{"an untimed firing": false, "a timed firing": true} { + t.Run(name, func(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + log := &callLog{} + settings := pluginkit.HookSettings{Budget: budget, TimedFirings: 20, Report: func(pluginkit.HookFailure) { + panic("report broken") + }} + hook := greetHook(t, settings, + &hookPlugin{id: "alpha", fail: failWith(errors.New("index unavailable")), log: log}, + &hookPlugin{id: "beta", log: log}) + if timed { + overrunOnce(t, hook) + } + + defer func() { + if got := recover(); got != "report broken" { + t.Errorf("Fire() panicked with %v, want the panic of Report", got) + } + wantEqual(t, "called", log.called(), []string{"alpha"}) + }() + hook.Fire(t.Context(), greet) + }) + }) + } +} + +func TestAPluginThatRunsIntoTheDeadlineAndReturnsItsErrorCountsAsContextEnded(t *testing.T) { + t.Parallel() + + synctest.Test(t, func(t *testing.T) { + hook, _ := timedHook(t, 20, &hookPlugin{ + id: "search", takes: 3 * time.Millisecond, fail: func(ctx context.Context) error { return ctx.Err() }, + log: &callLog{}, + }) + + hook.Fire(t.Context(), greet) + + wantEqual(t, "search's counters", statsByID(hook)["search"], pluginkit.PluginStats{ID: "search", ContextEnded: 1}) + }) +} + func TestAFiringAfterAnOverrunKeepsTheOrderTheDeadlineAndTheRecover(t *testing.T) { t.Parallel() @@ -312,6 +471,9 @@ func endedErrorCases() map[string]endedErrorCase { fail: func(ctx context.Context) error { return fmt.Errorf("index write: %v", ctx.Err()) }, counters: failed, failure: failureShape{Err: "index write: context deadline exceeded"}, }, + "another context's error": { + fail: failWith(context.Canceled), counters: failed, failure: failureShape{Err: "context canceled"}, + }, } } @@ -375,3 +537,39 @@ func TestTheCallersCanceledContextCountsAsContextEnded(t *testing.T) { } }) } + +// unwrapPanics is an error whose Unwrap panics. +type unwrapPanics struct{} + +// Error returns the error's text. +func (unwrapPanics) Error() string { + return "index write failed" +} + +// Unwrap panics with the text unwrapped. +func (unwrapPanics) Unwrap() error { + panic("unwrapped") +} + +func TestAnErrorWhoseUnwrapPanicsCountsAsAPanicOfItsPlugin(t *testing.T) { + t.Parallel() + + ctx, cancel := context.WithCancel(t.Context()) + cancel() + log, r := &callLog{}, &reports{} + hook := greetHook(t, settingsOf(time.Hour, 20, r), + &hookPlugin{id: "search", fail: failWith(unwrapPanics{}), log: log}, &hookPlugin{id: "feed", log: log}) + + hook.Fire(ctx, greet) + + wantEqual(t, "called", log.called(), []string{"search", "feed"}) + failure := onlyFailure(t, r) + wantEqual(t, "reported", shapesOf([]pluginkit.HookFailure{failure}), []failureShape{{ + Hook: "content.changed", ID: "search", Err: "pluginkit: search content.changed panicked: unwrapped", + Panicked: true, Stacked: true, + }}) + if !strings.Contains(failure.Stack, "unwrapPanics.Unwrap") { + t.Errorf("reported stack = %q, want the stack of the panic in Unwrap", failure.Stack) + } + wantEqual(t, "search's counters", statsByID(hook)["search"], pluginkit.PluginStats{ID: "search", Panics: 1}) +} diff --git a/pluginkit/hook_test.go b/pluginkit/hook_test.go index bd80f8f..6a29b19 100644 --- a/pluginkit/hook_test.go +++ b/pluginkit/hook_test.go @@ -381,6 +381,55 @@ func TestFireRecoversAPanicCountsItAndReportsItsStack(t *testing.T) { wantEqual(t, "beta's counters", statsByID(hook)["beta"], pluginkit.PluginStats{ID: "beta", Panics: 1}) } +// selfPanicking is an error and a panic value whose text panics with itself, a panic fmt does not catch. +type selfPanicking struct{} + +// Error panics with the error itself. +func (selfPanicking) Error() string { + panic(selfPanicking{}) +} + +func TestAPluginValueWhoseTextPanicsIsReportedByItsType(t *testing.T) { + t.Parallel() + + tests := map[string]struct { + plugin *hookPlugin + failure failureShape + counters pluginkit.PluginStats + }{ + "a returned error": { + &hookPlugin{id: "alpha", fail: failWith(selfPanicking{})}, + failureShape{Err: "pluginkit: alpha content.changed: pluginkit_test.selfPanicking whose text panicked"}, + pluginkit.PluginStats{ID: "alpha", Errors: 1}, + }, + "a panic value": { + &hookPlugin{id: "alpha", panics: selfPanicking{}}, + failureShape{ + Err: "pluginkit: alpha content.changed panicked: pluginkit_test.selfPanicking whose text panicked", + Panicked: true, Stacked: true, + }, + pluginkit.PluginStats{ID: "alpha", Panics: 1}, + }, + } + for name, tc := range tests { + t.Run(name, func(t *testing.T) { + t.Parallel() + + log, r := &callLog{}, &reports{} + tc.plugin.log = log + hook := greetHook(t, settingsOf(time.Hour, 20, r), tc.plugin, &hookPlugin{id: "beta", log: log}) + + hook.Fire(t.Context(), greet) + + wantEqual(t, "called", log.called(), []string{"alpha", "beta"}) + want := tc.failure + want.Hook, want.ID = "content.changed", "alpha" + wantEqual(t, "reported", shapesOf(r.all()), []failureShape{want}) + wantEqual(t, "alpha's counters", statsByID(hook)["alpha"], tc.counters) + }) + } +} + func TestFilterPassesTheValueThroughEveryPluginPastOnesThatFail(t *testing.T) { t.Parallel() @@ -442,18 +491,50 @@ func TestConcurrentFiringsCountEveryFailure(t *testing.T) { } } -func BenchmarkFireWithFiftyPlugins(b *testing.B) { - plugins := make([]identified, 50) - for i := range plugins { - plugins[i] = &hookPlugin{id: fmt.Sprintf("plugin-%02d", i), log: &callLog{}} +func TestConcurrentTimedFiringsCountEveryTimedCallAndCharge(t *testing.T) { + t.Parallel() + + const firings = 50 + hook := greetHook(t, settingsOf(time.Nanosecond, firings+1, &reports{}), + &hookPlugin{id: "alpha", takes: time.Microsecond, log: &callLog{}}, + &hookPlugin{id: "beta", takes: time.Microsecond, log: &callLog{}}) + hook.Fire(t.Context(), greet) + + var wg sync.WaitGroup + for range firings { + wg.Go(func() { hook.Fire(context.Background(), greet) }) } - hook, err := pluginkit.NewHook[greeter]("content.changed", plugins, settingsOf(time.Hour, 20, &reports{})) - if err != nil { - b.Fatalf("NewHook() error = %v, want nil", err) + wg.Wait() + + stats := hook.Stats() + charged := stats.Plugins[0].Overruns + stats.Plugins[1].Overruns + if stats.Overruns != firings+1 || charged != firings { + t.Errorf("Stats() = %+v, want %d overruns and %d charged to a plugin", stats, firings+1, firings) } - ctx := context.Background() + for _, plugin := range stats.Plugins { + if plugin.TimedCalls != firings { + t.Errorf("%s was timed in %d firings, want %d", plugin.ID, plugin.TimedCalls, firings) + } + } +} + +func BenchmarkFireWithTwoHundredPlugins(b *testing.B) { + plugins := make([]identified, 200) + for i := range plugins { + plugins[i] = &hookPlugin{id: fmt.Sprintf("plugin-%03d", i), log: &callLog{}} + } + for name, limit := range map[string]time.Duration{"untimed": time.Hour, "timed": time.Nanosecond} { + b.Run(name, func(b *testing.B) { + hook, err := pluginkit.NewHook[greeter]("content.changed", plugins, settingsOf(limit, 1<<30, &reports{})) + if err != nil { + b.Fatalf("NewHook() error = %v, want nil", err) + } + ctx := context.Background() + hook.Fire(ctx, func(context.Context, greeter) error { return nil }) - for b.Loop() { - hook.Fire(ctx, func(context.Context, greeter) error { return nil }) + for b.Loop() { + hook.Fire(ctx, func(context.Context, greeter) error { return nil }) + } + }) } } From 5ca4e5175b8e6c4abfcd3e5fc668c2ac27721680 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 6 Nov 2026 13:32:06 +0100 Subject: [PATCH 6/8] test(pluginkit): add the report scenarios and sharpen the hook scenarios --- pluginkit/features/hooks.feature | 53 +++++++++++++++- pluginkit/features/steps_hooks_test.go | 83 +++++++++++++++++++++++--- 2 files changed, 126 insertions(+), 10 deletions(-) diff --git a/pluginkit/features/hooks.feature b/pluginkit/features/hooks.feature index c5dd4cd..6fc7ffe 100644 --- a/pluginkit/features/hooks.feature +++ b/pluginkit/features/hooks.feature @@ -4,14 +4,17 @@ Feature: Calling the plugins that implement a hook action tells each plugin that something happened, and a filter passes a value through each plugin. One firing of a hook shares one time budget among all its plugins. A plugin that fails, panics or runs slow never - stops the plugins after it, and the counters name the plugin at fault. + stops the plugins after it. The counters name the plugin that failed or + panicked, and the slowest one once the firings after an overrun are + timed. The report is the application's own function that receives each + error and panic of a plugin. Scenario: Every plugin that implements the hook is called in order - Given the plugins "seo-basics", "analytics" and "feed" implement the hook "public.head-tags" + Given the plugins "seo-basics" and "analytics" implement the hook "public.head-tags" And the plugin "theme" is registered without implementing it + And the plugin "feed" implements the hook "public.head-tags" When the hook fires Then "seo-basics", "analytics" and "feed" are called in that order - And "theme" is not called Scenario: A failing plugin leaves the plugins after it running Given the plugins "analytics", "feed" and "seo-basics" implement the hook "content.changed" @@ -63,6 +66,23 @@ Feature: Calling the plugins that implement a hook When the hook fires Then "search" is counted 1 error and 0 calls whose context ended + Scenario: After the deadline, an error that panics when the hook unwraps it counts as a panic of its plugin + Given the plugins "analytics", "search" and "feed" implement the hook "content.changed" + And the hook has a budget of 2 ms + And "analytics" takes 5 ms + And "search" fails with an error that panics when it is unwrapped + When the hook fires + Then "analytics", "search" and "feed" are called in that order + And "search" is counted 1 panic + + Scenario: A panic in the report reaches the code that fired the hook + Given the plugins "analytics" and "feed" implement the hook "content.changed" + And "analytics" fails with "index unavailable" + And the report panics with "report broken" + When the hook fires + Then the firing panics with "report broken" + And "feed" is not called + Scenario: An untimed overrun charges no plugin Given the plugins "analytics", "reviews" and "feed" implement the hook "public.head-tags" And the hook has a budget of 2 ms and times each plugin for 20 firings after an overrun @@ -83,6 +103,33 @@ Feature: Calling the plugins that implement a hook Then "analytics" is charged 1 overrun And "reviews" and "feed" are charged no overrun + Scenario: The time the report takes is not charged to the failing plugin + Given the plugins "reviews", "analytics" and "feed" implement the hook "public.head-tags" + And the hook has a budget of 2 ms and times each plugin for 20 firings after an overrun + And the report takes 1.5 ms + And "reviews" fails with "rating unavailable" + And the hook has run over its budget once + When the hook fires while the plugins take + | plugin | ms | + | reviews | 0.1 | + | analytics | 1.2 | + | feed | 0.9 | + Then "analytics" is charged 1 overrun + And "reviews" and "feed" are charged no overrun + + Scenario: A firing that only the report runs over its budget charges no plugin + Given the plugins "reviews" and "analytics" implement the hook "public.head-tags" + And the hook has a budget of 2 ms and times each plugin for 20 firings after an overrun + And the report takes 3 ms + And "reviews" fails with "rating unavailable" + And the hook has run over its budget once + When the hook fires while the plugins take + | plugin | ms | + | reviews | 0.1 | + | analytics | 0.5 | + Then the hook is counted 2 overruns + And no plugin is charged an overrun + Scenario: Each plugin is timed only for the firings after an overrun Given the plugins "analytics" and "feed" implement the hook "public.head-tags" And the hook has a budget of 2 ms and times each plugin for 3 firings after an overrun diff --git a/pluginkit/features/steps_hooks_test.go b/pluginkit/features/steps_hooks_test.go index e676be5..79c55d3 100644 --- a/pluginkit/features/steps_hooks_test.go +++ b/pluginkit/features/steps_hooks_test.go @@ -92,6 +92,19 @@ func (b bystander) ID() string { return b.id } +// unwrapPanics is an error whose Unwrap panics. +type unwrapPanics struct{} + +// Error returns the error's text. +func (unwrapPanics) Error() string { + return "index write failed" +} + +// Unwrap panics with the text unwrapped. +func (unwrapPanics) Unwrap() error { + panic("unwrapped") +} + // hookWorld is the state of one scenario. type hookWorld struct { t *testing.T @@ -103,6 +116,9 @@ type hookWorld struct { calls []string late map[string]bool failures []pluginkit.HookFailure + reportTakes time.Duration + reportPanics string + escaped any actions *pluginkit.Hook[handler] title string } @@ -125,9 +141,15 @@ func plugin(ctx context.Context, id string) (*scenePlugin, error) { // settings returns the hook settings of the scenario, reporting into its failures. func (w *hookWorld) settings() pluginkit.HookSettings { - return pluginkit.HookSettings{ - Budget: w.budget, TimedFirings: w.timedFirings, - Report: func(failure pluginkit.HookFailure) { w.failures = append(w.failures, failure) }, + return pluginkit.HookSettings{Budget: w.budget, TimedFirings: w.timedFirings, Report: w.report} +} + +// report records failure, takes the scenario's report time, then panics when the scenario says so. +func (w *hookWorld) report(failure pluginkit.HookFailure) { + w.failures = append(w.failures, failure) + time.Sleep(w.reportTakes) + if w.reportPanics != "" { + panic(w.reportPanics) } } @@ -141,9 +163,16 @@ func (w *hookWorld) hook() (*pluginkit.Hook[handler], error) { return hook, err } -// onFakeClock runs fn on a fake clock, so the times a scenario names pass in no real time. +// onFakeClock runs fn on a fake clock, so a scenario's times pass in no real time, keeping a panic that leaves fn. func (w *hookWorld) onFakeClock(fn func()) { - synctest.Test(w.t, func(*testing.T) { fn() }) + synctest.Test(w.t, func(*testing.T) { + defer func() { + if escaped := recover(); escaped != nil { + w.escaped = escaped + } + }() + fn() + }) } // statsOf returns the counters of the plugin id in the action hook. @@ -159,7 +188,7 @@ func (w *hookWorld) statsOf(id string) (pluginkit.PluginStats, error) { return pluginkit.PluginStats{}, fmt.Errorf("no counters for %s", id) } -// implement registers the plugins of list, in order, as implementing the hook name. +// implement registers the plugins of list, in order after any registered before, as implementing the hook name. func implement(ctx context.Context, list, name string) { w := worldOf(ctx) w.name = name @@ -222,6 +251,23 @@ func failsWithEndedContext(ctx context.Context, id, what string) error { return setFailure(ctx, id, func(ctx context.Context) error { return fmt.Errorf("index write: "+verb, ctx.Err()) }) } +// failsWithPanickyUnwrap makes the plugin id fail with an error whose Unwrap panics. +func failsWithPanickyUnwrap(ctx context.Context, id string) error { + return setFailure(ctx, id, func(context.Context) error { return unwrapPanics{} }) +} + +// setReportTakes makes the report take text milliseconds on each failure. +func setReportTakes(ctx context.Context, text string) error { + takes, err := time.ParseDuration(text + "ms") + worldOf(ctx).reportTakes = takes + return err +} + +// reportPanicsWith makes the report panic with text on each failure. +func reportPanicsWith(ctx context.Context, text string) { + worldOf(ctx).reportPanics = text +} + // panicsWith makes the plugin id panic with text. func panicsWith(ctx context.Context, id, text string) error { p, err := plugin(ctx, id) @@ -441,6 +487,24 @@ func timedIn(ctx context.Context, list string, want int) error { return nil } +// firingPanicked checks that a firing panicked with want, and takes that panic as expected. +func firingPanicked(ctx context.Context, want string) error { + w := worldOf(ctx) + if w.escaped != want { + return fmt.Errorf("the firing panicked with %v, want %q", w.escaped, want) + } + w.escaped = nil + return nil +} + +// noPanicLeft fails a scenario whose firing panicked when no step expected it. +func noPanicLeft(ctx context.Context, _ *godog.Scenario, _ error) (context.Context, error) { + if escaped := worldOf(ctx).escaped; escaped != nil { + return ctx, fmt.Errorf("a firing panicked with %v", escaped) + } + return ctx, nil +} + // titleBecomes checks the title the filter returned. func titleBecomes(ctx context.Context, want string) error { if got := worldOf(ctx).title; got != want { @@ -458,6 +522,7 @@ func initializeHooks(t *testing.T) func(*godog.ScenarioContext) { } return context.WithValue(ctx, hookWorldKey{}, w), nil }) + sc.After(noPanicLeft) givenHooks(sc) whenHooks(sc) thenHooks(sc) @@ -466,7 +531,7 @@ func initializeHooks(t *testing.T) func(*godog.ScenarioContext) { // givenHooks registers the steps that set a scenario up. func givenHooks(sc *godog.ScenarioContext) { - sc.Step(`^the plugins (.+) implement the (?:filter )?hook "([^"]*)"$`, implement) + sc.Step(`^the plugins? (.+) implements? the (?:filter )?hook "([^"]*)"$`, implement) sc.Step(`^the plugin "([^"]*)" is registered without implementing it$`, registerBystander) sc.Step(`^the hook has a budget of (\S+) ms$`, setBudget) sc.Step(`^the hook has a budget of (\S+) ms and times each plugin for (\d+) firings after an overrun$`, setTiming) @@ -474,6 +539,9 @@ func givenHooks(sc *godog.ScenarioContext) { sc.Step(`^"([^"]*)" fails with "([^"]*)"$`, failsWith) sc.Step(`^"([^"]*)" fails with the (error|text) of its ended context(?: but not the error itself)?$`, failsWithEndedContext) + sc.Step(`^"([^"]*)" fails with an error that panics when it is unwrapped$`, failsWithPanickyUnwrap) + sc.Step(`^the report takes (\S+) ms$`, setReportTakes) + sc.Step(`^the report panics with "([^"]*)"$`, reportPanicsWith) sc.Step(`^"([^"]*)" panics with "([^"]*)"$`, panicsWith) sc.Step(`^"([^"]*)" puts "([^"]*)" (before|after) the title$`, putsAround) sc.Step(`^the hook has run over its budget once$`, overrunOnce) @@ -501,5 +569,6 @@ func thenHooks(sc *godog.ScenarioContext) { sc.Step(`^(.+) are charged no overrun$`, chargedNone) sc.Step(`^no plugin is charged an overrun$`, noPluginCharged) sc.Step(`^(.+) are each timed in (\d+) firings$`, timedIn) + sc.Step(`^the firing panics with "([^"]*)"$`, firingPanicked) sc.Step(`^the title becomes "([^"]*)"$`, titleBecomes) } From 34a548562a94c770a1178116a4dd144c53ed0627 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 6 Nov 2026 17:25:35 +0100 Subject: [PATCH 7/8] feat(pluginkit): count the timed overruns no plugin caused and the time Report takes --- pluginkit/CHANGELOG.md | 1 + pluginkit/hook.go | 39 ++++++++++++++++++++++++----------- pluginkit/hook_budget_test.go | 34 ++++++++++++++++-------------- pluginkit/hook_test.go | 5 ++--- 4 files changed, 49 insertions(+), 30 deletions(-) diff --git a/pluginkit/CHANGELOG.md b/pluginkit/CHANGELOG.md index c2d3608..9526be8 100644 --- a/pluginkit/CHANGELOG.md +++ b/pluginkit/CHANGELOG.md @@ -8,6 +8,7 @@ Releases of this module are tagged `pluginkit/vX.Y.Z`. Releases up to - `NewHook` collects the plugins that implement an interface into a `Hook`. `Hook.Fire` calls an action on each in registration order and `Filter` passes a value through each, every call inside its own recover. - One firing shares `HookSettings.Budget` as a context deadline. The plugins after a slow one are still called, and an error that matches the ended context counts as `ContextEnded`, not as that plugin's fault. - After a firing runs over its budget, the next `TimedFirings` firings time each plugin, without the time of `Report`, and a timed firing whose plugins together run over is charged to the slowest. `Stats` returns every counter, and `HookSettings.Report` receives each error and panic as a `HookFailure` and must not panic. +- `HookStats.UnchargedOverruns` counts the timed firings that ran over while their plugins together kept the budget, and `HookStats.TimedReportTime` the time `Report` took in timed firings. ## 0.9.0 - 2026-11-05 diff --git a/pluginkit/hook.go b/pluginkit/hook.go index b9f76a7..134bfe5 100644 --- a/pluginkit/hook.go +++ b/pluginkit/hook.go @@ -41,7 +41,11 @@ type HookStats struct { Name string Firings uint64 Overruns uint64 - Plugins []PluginStats + // UnchargedOverruns counts the timed firings that ran over their budget while their plugins together kept it. + UnchargedOverruns uint64 + // TimedReportTime is the total time Report took in the timed firings. + TimedReportTime time.Duration + Plugins []PluginStats } // PluginStats are the counters of one plugin in one hook. @@ -74,6 +78,9 @@ type Hook[C any] struct { firings atomic.Uint64 overruns atomic.Uint64 timed atomic.Int64 + + uncharged atomic.Uint64 + reportTime atomic.Int64 } // NewHook returns the hook called name over the plugins that implement C, refusing what it cannot run under. @@ -146,10 +153,12 @@ func Filter[C, V any](ctx context.Context, hook *Hook[C], value V, // Stats returns the counters of the hook and of each of its plugins. func (h *Hook[C]) Stats() HookStats { stats := HookStats{ - Name: h.name, - Firings: h.firings.Load(), - Overruns: h.overruns.Load(), - Plugins: make([]PluginStats, len(h.ids)), + Name: h.name, + Firings: h.firings.Load(), + Overruns: h.overruns.Load(), + UnchargedOverruns: h.uncharged.Load(), + TimedReportTime: time.Duration(h.reportTime.Load()), + Plugins: make([]PluginStats, len(h.ids)), } for i, id := range h.ids { c := &h.counters[i] @@ -172,8 +181,8 @@ func (h *Hook[C]) fire(ctx context.Context, call func(context.Context, C) error) began := time.Now() ctx, cancel := context.WithDeadline(ctx, began.Add(h.settings.Budget)) defer cancel() - slowest := -1 - if h.takeTimedFiring() { + timed, slowest := h.takeTimedFiring(), -1 + if timed { slowest = h.callTimed(ctx, call) } else { for i, plugin := range h.plugins { @@ -186,6 +195,8 @@ func (h *Hook[C]) fire(ctx context.Context, call func(context.Context, C) error) h.overruns.Add(1) if slowest >= 0 { h.counters[slowest].overruns.Add(1) + } else if timed { + h.uncharged.Add(1) } h.timed.Store(int64(h.settings.TimedFirings)) } @@ -216,7 +227,7 @@ func (h *Hook[C]) callTimed(ctx context.Context, call func(context.Context, C) e if took > longest { slowest, longest = i, took } - h.report(i, out) + h.reportTime.Add(int64(h.report(i, out))) } if total <= h.settings.Budget { return -1 @@ -224,11 +235,15 @@ func (h *Hook[C]) callTimed(ctx context.Context, call func(context.Context, C) e return slowest } -// report counts and reports what went wrong in one call of plugin i, if anything did. -func (h *Hook[C]) report(i int, out *outcome) { - if out != nil { - h.settings.Report(h.failureOf(i, out)) +// report counts and reports what went wrong in one call of plugin i, if anything did, returning the time Report took. +func (h *Hook[C]) report(i int, out *outcome) time.Duration { + if out == nil { + return 0 } + failure := h.failureOf(i, out) + began := time.Now() + h.settings.Report(failure) + return time.Since(began) } // failureOf counts what went wrong in a call of plugin i and returns it as the failure Report receives. diff --git a/pluginkit/hook_budget_test.go b/pluginkit/hook_budget_test.go index 3a82bed..1eb8e86 100644 --- a/pluginkit/hook_budget_test.go +++ b/pluginkit/hook_budget_test.go @@ -266,35 +266,36 @@ func TestTheTimeOfReportIsLeftOutOfThePluginsTime(t *testing.T) { err error panics any reviews, analytics time.Duration + uncharged uint64 want []pluginkit.PluginStats }{ "so a firing that only Report runs over charges no plugin": { - errors.New("rating unavailable"), nil, 0, 500 * time.Microsecond, []pluginkit.PluginStats{ + errors.New("rating unavailable"), nil, 0, 500 * time.Microsecond, 1, []pluginkit.PluginStats{ {ID: "reviews", Errors: 1, TimedCalls: 1}, {ID: "analytics", TimedCalls: 1, TimedTime: 500 * time.Microsecond}, }, }, "so plugins that together take exactly the budget charge none": { - errors.New("rating unavailable"), nil, budget, 0, []pluginkit.PluginStats{ + errors.New("rating unavailable"), nil, budget, 0, 1, []pluginkit.PluginStats{ {ID: "reviews", Errors: 1, TimedCalls: 1, TimedTime: budget}, {ID: "analytics", TimedCalls: 1}, }, }, "so plugins that together run over charge the slowest of their own times": { - errors.New("rating unavailable"), nil, 200 * time.Microsecond, 1900 * time.Microsecond, + errors.New("rating unavailable"), nil, 200 * time.Microsecond, 1900 * time.Microsecond, 0, []pluginkit.PluginStats{ {ID: "reviews", Errors: 1, TimedCalls: 1, TimedTime: 200 * time.Microsecond}, {ID: "analytics", Overruns: 1, TimedCalls: 1, TimedTime: 1900 * time.Microsecond}, }, }, "but the time of the plugin's own error text stays the plugin's": { - slowText{}, nil, 0, 500 * time.Microsecond, []pluginkit.PluginStats{ + slowText{}, nil, 0, 500 * time.Microsecond, 0, []pluginkit.PluginStats{ {ID: "reviews", Errors: 1, Overruns: 1, TimedCalls: 1, TimedTime: 3 * time.Millisecond}, {ID: "analytics", TimedCalls: 1, TimedTime: 500 * time.Microsecond}, }, }, "and so does the time of the text of its panic": { - nil, slowText{}, 0, 500 * time.Microsecond, []pluginkit.PluginStats{ + nil, slowText{}, 0, 500 * time.Microsecond, 0, []pluginkit.PluginStats{ {ID: "reviews", Panics: 1, Overruns: 1, TimedCalls: 1, TimedTime: 3 * time.Millisecond}, {ID: "analytics", TimedCalls: 1, TimedTime: 500 * time.Microsecond}, }, @@ -316,7 +317,8 @@ func TestTheTimeOfReportIsLeftOutOfThePluginsTime(t *testing.T) { fireTimes(t, hook, 1) wantEqual(t, "Stats()", hook.Stats(), pluginkit.HookStats{ - Name: "content.changed", Firings: 2, Overruns: 2, Plugins: tc.want, + Name: "content.changed", Firings: 2, Overruns: 2, UnchargedOverruns: tc.uncharged, + TimedReportTime: 3 * time.Millisecond, Plugins: tc.want, }) }) }) @@ -327,14 +329,17 @@ func TestAFiringThatOnlyReportRunsOverTimesTheFiringsAfterIt(t *testing.T) { t.Parallel() tests := map[string]struct { - timed bool - overruns uint64 - want pluginkit.PluginStats + timed bool + want pluginkit.HookStats }{ - "from an untimed firing": {false, 1, pluginkit.PluginStats{ID: "alpha", Errors: 6, TimedCalls: 3}}, - "from a timed firing, in full again": { - true, 2, pluginkit.PluginStats{ID: "alpha", Errors: 6, TimedCalls: 4}, - }, + "from an untimed firing, counting no timed overrun or report time": {false, pluginkit.HookStats{ + Name: "content.changed", Firings: 6, Overruns: 1, + Plugins: []pluginkit.PluginStats{{ID: "alpha", Errors: 6, TimedCalls: 3}}, + }}, + "from a timed firing, in full again": {true, pluginkit.HookStats{ + Name: "content.changed", Firings: 7, Overruns: 2, UnchargedOverruns: 1, TimedReportTime: 3 * time.Millisecond, + Plugins: []pluginkit.PluginStats{{ID: "alpha", Errors: 6, TimedCalls: 4}}, + }}, } for name, tc := range tests { t.Run(name, func(t *testing.T) { @@ -355,8 +360,7 @@ func TestAFiringThatOnlyReportRunsOverTimesTheFiringsAfterIt(t *testing.T) { fireTimes(t, hook, 5) - wantEqual(t, "Stats().Overruns", hook.Stats().Overruns, tc.overruns) - wantEqual(t, "alpha's counters", statsByID(hook)["alpha"], tc.want) + wantEqual(t, "Stats()", hook.Stats(), tc.want) }) }) } diff --git a/pluginkit/hook_test.go b/pluginkit/hook_test.go index 6a29b19..5a51be2 100644 --- a/pluginkit/hook_test.go +++ b/pluginkit/hook_test.go @@ -508,9 +508,8 @@ func TestConcurrentTimedFiringsCountEveryTimedCallAndCharge(t *testing.T) { stats := hook.Stats() charged := stats.Plugins[0].Overruns + stats.Plugins[1].Overruns - if stats.Overruns != firings+1 || charged != firings { - t.Errorf("Stats() = %+v, want %d overruns and %d charged to a plugin", stats, firings+1, firings) - } + wantEqual(t, "overruns, charged and uncharged", []uint64{stats.Overruns, charged, stats.UnchargedOverruns}, + []uint64{firings + 1, firings, 0}) for _, plugin := range stats.Plugins { if plugin.TimedCalls != firings { t.Errorf("%s was timed in %d firings, want %d", plugin.ID, plugin.TimedCalls, firings) From c5ee9cd730de53c45bc9950ed03e98af70ed4ea0 Mon Sep 17 00:00:00 2001 From: SirLouen Date: Fri, 6 Nov 2026 17:25:35 +0100 Subject: [PATCH 8/8] test(pluginkit): check the uncharged overruns and the report time in the hook scenarios --- pluginkit/features/hooks.feature | 5 +++ pluginkit/features/steps_hooks_test.go | 42 ++++++++++++++++++++++---- 2 files changed, 41 insertions(+), 6 deletions(-) diff --git a/pluginkit/features/hooks.feature b/pluginkit/features/hooks.feature index 6fc7ffe..5a9331e 100644 --- a/pluginkit/features/hooks.feature +++ b/pluginkit/features/hooks.feature @@ -90,6 +90,7 @@ Feature: Calling the plugins that implement a hook When the hook fires Then the hook is counted 1 overrun And no plugin is charged an overrun + And the hook is counted 0 timed overruns that no plugin is charged for Scenario: A timed overrun is charged to the slowest plugin Given the plugins "reviews", "analytics" and "feed" implement the hook "public.head-tags" @@ -116,6 +117,8 @@ Feature: Calling the plugins that implement a hook | feed | 0.9 | Then "analytics" is charged 1 overrun And "reviews" and "feed" are charged no overrun + And the hook is counted 0 timed overruns that no plugin is charged for + And the report is counted 1.5 ms in the timed firings Scenario: A firing that only the report runs over its budget charges no plugin Given the plugins "reviews" and "analytics" implement the hook "public.head-tags" @@ -129,6 +132,8 @@ Feature: Calling the plugins that implement a hook | analytics | 0.5 | Then the hook is counted 2 overruns And no plugin is charged an overrun + And the hook is counted 1 timed overrun that no plugin is charged for + And the report is counted 3 ms in the timed firings Scenario: Each plugin is timed only for the firings after an overrun Given the plugins "analytics" and "feed" implement the hook "public.head-tags" diff --git a/pluginkit/features/steps_hooks_test.go b/pluginkit/features/steps_hooks_test.go index 79c55d3..530f2df 100644 --- a/pluginkit/features/steps_hooks_test.go +++ b/pluginkit/features/steps_hooks_test.go @@ -175,6 +175,14 @@ func (w *hookWorld) onFakeClock(fn func()) { }) } +// hookStats returns the counters of the action hook, failing when it never fired. +func (w *hookWorld) hookStats() (pluginkit.HookStats, error) { + if w.actions == nil { + return pluginkit.HookStats{}, errors.New("the hook never fired") + } + return w.actions.Stats(), nil +} + // statsOf returns the counters of the plugin id in the action hook. func (w *hookWorld) statsOf(id string) (pluginkit.PluginStats, error) { if w.actions == nil { @@ -434,14 +442,34 @@ func countedErrorsAndEnded(ctx context.Context, id string, errs, ended int) erro // hookOverruns checks the overruns counted on the hook. func hookOverruns(ctx context.Context, want int) error { - w := worldOf(ctx) - if w.actions == nil { - return errors.New("the hook never fired") + stats, err := worldOf(ctx).hookStats() + if err == nil && stats.Overruns != uint64(want) { + err = fmt.Errorf("the hook is counted %d overruns, want %d", stats.Overruns, want) } - if got := w.actions.Stats().Overruns; got != uint64(want) { - return fmt.Errorf("the hook is counted %d overruns, want %d", got, want) + return err +} + +// unchargedOverruns checks the timed overruns the hook counted with no plugin charged. +func unchargedOverruns(ctx context.Context, want int) error { + stats, err := worldOf(ctx).hookStats() + if err == nil && stats.UnchargedOverruns != uint64(want) { + err = fmt.Errorf("the hook is counted %d timed overruns that no plugin is charged for, want %d", + stats.UnchargedOverruns, want) } - return nil + return err +} + +// reportTimed checks the time the report took in the timed firings, text milliseconds such as 1.5. +func reportTimed(ctx context.Context, text string) error { + stats, err := worldOf(ctx).hookStats() + if err != nil { + return err + } + want, err := time.ParseDuration(text + "ms") + if err == nil && stats.TimedReportTime != want { + err = fmt.Errorf("the report is counted %v in the timed firings, want %v", stats.TimedReportTime, want) + } + return err } // chargedOverruns checks the overruns charged to the plugin id. @@ -568,6 +596,8 @@ func thenHooks(sc *godog.ScenarioContext) { sc.Step(`^"([^"]*)" is charged (\d+) overruns?$`, chargedOverruns) sc.Step(`^(.+) are charged no overrun$`, chargedNone) sc.Step(`^no plugin is charged an overrun$`, noPluginCharged) + sc.Step(`^the hook is counted (\d+) timed overruns? that no plugin is charged for$`, unchargedOverruns) + sc.Step(`^the report is counted (\S+) ms in the timed firings$`, reportTimed) sc.Step(`^(.+) are each timed in (\d+) firings$`, timedIn) sc.Step(`^the firing panics with "([^"]*)"$`, firingPanicked) sc.Step(`^the title becomes "([^"]*)"$`, titleBecomes)