From 3b8ef13d323eb44a7a083649f876e0f754b96a3a Mon Sep 17 00:00:00 2001 From: Ryan Laurie Date: Thu, 11 Jun 2026 15:54:53 -0600 Subject: [PATCH] add after-each hook --- README.md | 36 ++++++ src/mb/hawk/core.clj | 94 +++++++++++++- src/mb/hawk/hooks.clj | 56 +++++++++ test/mb/hawk/hooks_test.clj | 239 ++++++++++++++++++++++++++++++++++++ 4 files changed, 422 insertions(+), 3 deletions(-) create mode 100644 test/mb/hawk/hooks_test.clj diff --git a/README.md b/README.md index ca20340..2230b82 100644 --- a/README.md +++ b/README.md @@ -246,6 +246,42 @@ they live in is loaded; this may be affected by `:only` options passed to the te Return values of methods are ignored; they are done purely for side effects. +## Per-Test Hooks + +You can run arbitrary code after each individual test finishes with an `after-each` hook: + +```clj +(methodical/defmethod mb.hawk.hooks/after-each ::my-hook + [options context] + (record-test-info! context)) +``` + +`options` are the same options passed to the test runner as a whole, just like for `before-run`/`after-run`. +`context` is a map describing the test that just ran: + +| Key | Description | +| --- | --- | +| `:var` | the test var that just ran | +| `:ns` | the namespace of the test var | +| `:report-events` | all `clojure.test` report event maps emitted during the test (`:pass`, `:fail`, `:error`, `:begin-test-var`, `:end-test-var`, ...), in order. Each event additionally has `:testing-contexts` assoc'ed onto it: the value of `clojure.test/*testing-contexts*` (innermost first) at the moment the event was emitted | +| `:output` | everything the test wrote to `*out*` or `*err*`, as a string. Output is captured with a tee, so it still shows up in the normal test output too | +| `:summary` | map of `:pass`/`:fail`/`:error` counts for this test var | +| `:duration-ms` | wall-clock time the test var took, in milliseconds | +| `:parallel?` | whether the test is a `^:parallel` test (and so may run concurrently with other tests) | + +Hooks run after the test var itself completes but before its `:each` fixtures finish, and run on the same thread as +the test, so for `^:parallel` tests hooks may run concurrently. If a hook throws (or a `clojure.test` assertion inside +it fails), it is reported as a test error/failure attributed to that test var -- it will fail the test suite and show +up in the JUnit output. Hooks only run for test vars that actually run: a var skipped because its `:each` fixture threw, +or because an earlier failure tripped `:fail-fast?`, does not fire after-each hooks. + +Capturing test output and report events is skipped entirely when no `after-each` hooks are registered -- whether any +hooks are registered is checked once at the start of each test run -- so test runs without hooks pay no overhead. + +The same caveats as for whole-suite hooks apply: dispatch values just need to be unique, hook order is indeterminate, +hooks only run if the namespace they live in gets loaded, and return values are ignored. There is no default +`after-each` method (it would run once per test); register at least one hook to enable the feature. + ## Partitioning tests You can divide a test suite into multiple partitions using the `:partition/total` and `:partition/index` keys. This is diff --git a/src/mb/hawk/core.clj b/src/mb/hawk/core.clj index fa79fa6..1800bc2 100644 --- a/src/mb/hawk/core.clj +++ b/src/mb/hawk/core.clj @@ -19,7 +19,9 @@ [mb.hawk.parallel :as hawk.parallel] [mb.hawk.partition :as hawk.partition] [mb.hawk.speak :as hawk.speak] - [mb.hawk.util :as u])) + [mb.hawk.util :as u]) + (:import + (java.io StringWriter Writer))) (set! *warn-on-reflection* true) @@ -152,6 +154,86 @@ (def ^:private ^:dynamic *parallel-test-counter* nil) +(def ^:private ^:dynamic *after-each-options* + "Bound to the test run options when at least one [[mb.hawk.hooks/after-each]] hook is registered, and `nil` + otherwise. Capturing per-test output and report events only happens when this is non-nil, so runs without after-each + hooks pay no overhead." + nil) + +(defn- tee-writer + "Returns a Writer that forwards everything written to it to both `primary` and `copy`. Closing it flushes both but + closes neither." + ^Writer [^Writer primary ^Writer copy] + (proxy [Writer] [] + (write + ([x] + (cond + (integer? x) (do (.write primary (int x)) + (.write copy (int x))) + (string? x) (do (.write primary ^String x) + (.write copy ^String x)) + :else (do (.write primary ^chars x) + (.write copy ^chars x)))) + ([x off len] + (if (string? x) + (do (.write primary ^String x (int off) (int len)) + (.write copy ^String x (int off) (int len))) + (do (.write primary ^chars x (int off) (int len)) + (.write copy ^chars x (int off) (int len)))))) + (flush [] + (.flush primary) + (.flush copy)) + (close [] + (.flush primary) + (.flush copy)))) + +(defn- run-test-with-after-each-hooks + "Run `test-var`, capturing its [[clojure.test]] report events and `*out*`/`*err*` output, then invoke + any [[hawk.hooks/after-each]] hooks with the run `options` and a context map describing the test that just ran. + + The hooks are run as the test var's reporting window closes -- right before its `:end-test-var` event reaches the + real reporter -- rather than after [[orig-test-var]] returns. This matters: a hook exception (or a `clojure.test` + assertion inside a hook) is reported as a `clojure.test` error while `test-var` is still the var being reported on, + so it is counted and attributed to `test-var` everywhere, including in the JUnit output (which finalizes a test + var's results when it sees `:end-test-var`)." + [options test-var] + (let [events (atom []) + buf (StringWriter.) + orig-report t/report + start-ns (System/nanoTime) + run-hooks! (fn [] + (let [duration-ms (/ (- (System/nanoTime) start-ns) 1e6) + summary (merge {:pass 0, :fail 0, :error 0} + (select-keys (frequencies (map :type @events)) + [:pass :fail :error]))] + ;; bind t/report back to the real reporter so anything the hook reports (including the + ;; hook-error event below) goes straight through instead of being recaptured into `events` + (binding [t/report orig-report] + (try + (hawk.hooks/after-each options {:var test-var + :ns (:ns (meta test-var)) + :report-events @events + :output (str buf) + :summary summary + :duration-ms duration-ms + :parallel? hawk.parallel/*parallel?*}) + (catch Throwable e + (orig-report {:type :error + :var test-var + :message (format "Error in after-each hook for %s" test-var) + :expected nil + :actual e}))))))] + (binding [t/report (fn [event] + (swap! events conj (assoc event :testing-contexts t/*testing-contexts*)) + ;; run hooks while the var's reporting window is still open (before :end-test-var is + ;; forwarded), so hook errors are attributed to this var + (when (= (:type event) :end-test-var) + (run-hooks!)) + (orig-report event)) + *out* (tee-writer *out* buf) + *err* (tee-writer *err* buf)] + (orig-test-var test-var)))) + (defn run-test "Run a single test `test-var`. Wraps/replaces [[clojure.test/test-var]]." [test-var] @@ -161,7 +243,9 @@ :parallel :single-threaded) (fnil inc 0))) - (orig-test-var test-var))) + (if-let [options *after-each-options*] + (run-test-with-after-each-hooks options test-var) + (orig-test-var test-var)))) (alter-var-root #'t/test-var (constantly run-test)) @@ -203,7 +287,11 @@ options)] (when-not (every? var? test-vars) (throw (ex-info "Invalid test vars" {:test-vars test-vars, :options options}))) - (binding [*parallel-test-counter* (atom {})] + (binding [*parallel-test-counter* (atom {}) + ;; check for after-each hooks once per run rather than once per test; eftest conveys these bindings + ;; to its worker threads + *after-each-options* (when (hawk.hooks/after-each-hooks-registered?) + options)] (merge (mb.eftest.runner/run-tests test-vars diff --git a/src/mb/hawk/hooks.clj b/src/mb/hawk/hooks.clj index 72e9433..70d79bd 100644 --- a/src/mb/hawk/hooks.clj +++ b/src/mb/hawk/hooks.clj @@ -56,3 +56,59 @@ "Default hook for [[after-run]]; log a message about running after-run hooks." [_options] (println "Running after-run hooks...")) + +(methodical/defmulti after-each + "Hooks to run after each individual test var finishes (after the test itself, but before `:each` fixture teardown). + Add a new hook like this: + + (methodical/defmethod mb.hawk.hooks/after-each ::my-hook + [_options context] + ...) + + `options` are the same options passed to the test runner as a whole, i.e. a combination of those specified in your + `deps.edn` aliases as well as additional command-line options. + + `context` is a map describing the test that just ran: + + | Key | Description | + |------------------|--------------------------------------------------------------------------------------------| + | `:var` | the test var that just ran | + | `:ns` | the namespace of the test var | + | `:report-events` | all `clojure.test` report event maps emitted during the test (`:pass`, `:fail`, `:error`, `:begin-test-var`, `:end-test-var`, ...), in order. Each event has `:testing-contexts` assoc'ed onto it: the value of `clojure.test/*testing-contexts*` (innermost first) when the event was emitted | + | `:output` | everything the test wrote to `*out*` or `*err*`, as a string | + | `:summary` | map of `:pass`/`:fail`/`:error` counts for this test var | + | `:duration-ms` | wall-clock time the test var took, in milliseconds | + | `:parallel?` | whether the test is a `^:parallel` test (and so may run concurrently with other tests) | + + If a hook throws (or a `clojure.test` assertion inside it fails), it is reported as a test error/failure attributed + to the test var -- it will fail the test suite and show up in the JUnit output -- and other after-each hooks for that + test may not run. Hooks run on the same thread as the test, so for `^:parallel` tests they may run concurrently. + + Hooks run only for test vars that actually run: a var skipped because its `:each` fixture threw, or because an + earlier failure tripped `:fail-fast?`, does not fire after-each hooks. + + Capturing test output and report events is skipped entirely when no after-each hooks are registered, so test runs + without any hooks pay no overhead. Whether any hooks are registered is checked once at the start of each test run. + + Unlike [[before-run]] and [[after-run]] there is no default method (one would run once per test); register at least + one hook to enable the machinery. The dispatch value is not particularly important -- one hook will run for each + dispatch value -- but you should probably make it a namespaced keyword to avoid conflicts, and give it a docstring so + people know why it's there. The orders the hooks are run in is indeterminate. The docstring for [[after-each]] is + updated automatically as new hooks are added; you can check it to see which hooks are in use. Note that hooks will + not be ran unless the namespace they live in is loaded; this may be affected by `:only` options passed to the test + runner. + + Return values of methods are ignored; they are done purely for side effects." + {:arglists '([options context]), :defmethod-arities #{2}} + :none + :combo (methodical/do-method-combination) + :dispatcher (methodical/everything-dispatcher)) + +(defn after-each-hooks-registered? + "Whether any [[after-each]] hooks are currently registered. When this is false the test runner skips per-test + output/event capture entirely. There is intentionally no default [[after-each]] method, so any registered method + (including one on the `:default` dispatch value) counts as a hook." + [] + (boolean + (or (seq (methodical/primary-methods after-each)) + (seq (methodical/aux-methods after-each))))) diff --git a/test/mb/hawk/hooks_test.clj b/test/mb/hawk/hooks_test.clj new file mode 100644 index 0000000..77d1894 --- /dev/null +++ b/test/mb/hawk/hooks_test.clj @@ -0,0 +1,239 @@ +(ns mb.hawk.hooks-test + (:require + [clojure.string :as str] + [clojure.test :refer :all] + [mb.hawk.core :as hawk] + [mb.hawk.hooks :as hawk.hooks] + [methodical.core :as methodical]) + (:import + (java.io StringWriter) + (java.util.concurrent BrokenBarrierException CyclicBarrier TimeUnit))) + +(set! *warn-on-reflection* true) + +(defn- silent-reporter [_event] nil) + +(defn- counting-reporter + "A reporter that records every event into `events-atom` and also increments the `clojure.test` report counters (the + way the real eftest reporters do), so that the summary returned by [[hawk/run-tests]] reflects pass/fail/error + counts." + [events-atom] + (fn [event] + (swap! events-atom conj event) + (when (#{:pass :fail :error} (:type event)) + (inc-report-counter (:type event))))) + +(defn- make-test-var + "Intern `test-fn` as a test var (as if defined with `deftest`) in scratch namespace `ns-symb`." + [ns-symb var-symb test-fn & {:as extra-meta}] + (let [v (intern (create-ns ns-symb) var-symb test-fn)] + (alter-meta! v merge {:test test-fn} extra-meta) + v)) + +(defn- do-with-after-each-hook + "Run `thunk` with `hook-fn` registered as an [[mb.hawk.hooks/after-each]] hook on `dispatch-val` (default `::hook`)." + ([hook-fn thunk] + (do-with-after-each-hook ::hook hook-fn thunk)) + ([dispatch-val hook-fn thunk] + (methodical/add-primary-method! #'hawk.hooks/after-each dispatch-val hook-fn) + (try + (thunk) + (finally + (methodical/remove-primary-method! #'hawk.hooks/after-each dispatch-val))))) + +(deftest after-each-hooks-registered?-test + (is (false? (hawk.hooks/after-each-hooks-registered?))) + (do-with-after-each-hook + (fn [_options _context] nil) + (fn [] + (is (true? (hawk.hooks/after-each-hooks-registered?))))) + (is (false? (hawk.hooks/after-each-hooks-registered?))) + (testing "a hook registered on the :default dispatch value still counts (there is no built-in :default method)" + (do-with-after-each-hook + :default + (fn [_options _context] nil) + (fn [] + (is (true? (hawk.hooks/after-each-hooks-registered?))))) + (is (false? (hawk.hooks/after-each-hooks-registered?))))) + +(deftest after-each-context-test + (let [scratch-ns 'mb.hawk.hooks-test.context-scratch + v (make-test-var scratch-ns 'passing-test + (fn [] + (testing "context" + (println "hello from out") + (binding [*out* *err*] + (println "hello from err")) + (is (= 1 1)) + (is (= 2 2))))) + hook-calls (atom []) + err-buf (StringWriter.)] + (try + (let [out-str (with-out-str + (binding [*err* err-buf] + (do-with-after-each-hook + (fn [options context] + (swap! hook-calls conj {:options options, :context context})) + (fn [] + (hawk/run-tests [v] {:report silent-reporter, ::custom-option 42})))))] + (testing "captured test output should still make it to the original *out*/*err*" + (is (str/includes? out-str "hello from out")) + (is (str/includes? (str err-buf) "hello from err")))) + (is (= 1 (count @hook-calls))) + (let [{:keys [options context]} (first @hook-calls)] + (testing "options" + (is (= 42 (::custom-option options))) + (is (= :repl (:mode options)))) + (testing "context" + (is (= v (:var context))) + (is (= (find-ns scratch-ns) (:ns context))) + (is (= [:begin-test-var :pass :pass :end-test-var] + (map :type (:report-events context)))) + (testing "report events should include the testing context they were emitted in" + (is (every? #(= ["context"] (:testing-contexts %)) + (filter #(= :pass (:type %)) (:report-events context))))) + (is (str/includes? (:output context) "hello from out")) + (is (str/includes? (:output context) "hello from err")) + (is (= {:pass 2, :fail 0, :error 0} (:summary context))) + (is (number? (:duration-ms context))) + (is (not (:parallel? context))))) + (finally + (remove-ns scratch-ns))))) + +(deftest after-each-failing-and-erroring-tests-test + (let [scratch-ns 'mb.hawk.hooks-test.failing-scratch + failing (make-test-var scratch-ns 'failing-test + (fn [] (is (= 1 2) "numbers should be equal"))) + erroring (make-test-var scratch-ns 'erroring-test + (fn [] (throw (ex-info "boom" {})))) + contexts (atom {})] + (try + (do-with-after-each-hook + (fn [_options context] + (swap! contexts assoc (:name (meta (:var context))) context)) + (fn [] + (hawk/run-tests [failing erroring] {:report silent-reporter}))) + (testing "failing test" + (let [context (get @contexts 'failing-test)] + (is (= {:pass 0, :fail 1, :error 0} (:summary context))) + (let [fail-event (first (filter #(= :fail (:type %)) (:report-events context)))] + (is (= "numbers should be equal" (:message fail-event))) + (is (contains? fail-event :expected)) + (is (contains? fail-event :actual))))) + (testing "erroring test" + (let [context (get @contexts 'erroring-test)] + (is (= {:pass 0, :fail 0, :error 1} (:summary context))) + (let [error-event (first (filter #(= :error (:type %)) (:report-events context)))] + (is (= "boom" (ex-message (:actual error-event))))))) + (finally + (remove-ns scratch-ns))))) + +(deftest after-each-hook-error-test + (let [scratch-ns 'mb.hawk.hooks-test.hook-error-scratch + v1 (make-test-var scratch-ns 'test-1 (fn [] (is (= 1 1)))) + v2 (make-test-var scratch-ns 'test-2 (fn [] (is (= 1 1)))) + seen-events (atom []) + ran (atom []) + summary (do-with-after-each-hook + (fn [_options context] + (swap! ran conj (:name (meta (:var context)))) + (throw (ex-info "hook boom" {}))) + (fn [] + (try + (hawk/run-tests [v1 v2] {:report (counting-reporter seen-events)}) + (finally + (remove-ns scratch-ns)))))] + (testing "an exception in an after-each hook should be reported as a test error" + (let [error-events (filter #(= :error (:type %)) @seen-events)] + (is (= 2 (count error-events))) + (is (every? #(re-find #"after-each hook" (str (:message %))) error-events)) + (is (= "hook boom" (ex-message (:actual (first error-events))))))) + (testing "the hook error should fail the suite (be counted in the summary)" + (is (= 2 (:error summary)))) + (testing "the hook error :error event should be reported before the var's :end-test-var, so it is attributed to + the var (e.g. in JUnit output) instead of landing after the var's reporting window has closed" + (doseq [v [v1 v2]] + (let [types (->> @seen-events + (filter #(= v (:var %))) + (map :type) + (filter #{:error :end-test-var}))] + (is (= [:error :end-test-var] types) + (format "hook :error should precede :end-test-var for %s" v))))) + (testing "a hook error for one test should not prevent later tests from running" + (is (= '[test-1 test-2] @ran))))) + +(deftest after-each-hook-assertion-attributed-test + (testing "a hook runs while the test var is still the one being reported on, so a clojure.test assertion (or error) + inside the hook is attributed to that var -- this is what keeps var-aware reporters like JUnit from + mis-attributing or crashing on a hook failure" + (let [scratch-ns 'mb.hawk.hooks-test.hook-assertion-scratch + v (make-test-var scratch-ns 'the-test (fn [] (is (= 1 1)))) + testing-vars (atom ::unset) + seen-events (atom [])] + (try + (do-with-after-each-hook + (fn [_options _context] + ;; clojure.test attributes a report event to the var in (last *testing-vars*); verify it is still set + (reset! testing-vars (vec *testing-vars*)) + (is (= :a :b) "assertion inside hook")) + (fn [] + (hawk/run-tests [v] {:report (counting-reporter seen-events)}))) + (testing "the test var is the current (innermost) var in *testing-vars* while the hook runs" + ;; NOTE: because this test runs `hawk/run-tests` nested inside a test that is itself run by hawk, + ;; *testing-vars* also contains the outer test var; in a normal (non-nested) run it is exactly `[v]`. + ;; `clojure.test`/JUnit attribute to the innermost var, which is what we assert here. + (is (= v (first @testing-vars)))) + (testing "the hook's failing assertion is reported (and the run did not crash)" + (let [fail-events (filter #(= :fail (:type %)) @seen-events)] + (is (= 1 (count fail-events))) + (is (= "assertion inside hook" (:message (first fail-events)))))) + (finally + (remove-ns scratch-ns)))))) + +(deftest no-hooks-fast-path-test + (let [scratch-ns 'mb.hawk.hooks-test.fast-path-scratch + outer-out *out* + seen-out (atom nil) + v (make-test-var scratch-ns 'out-test + (fn [] + (reset! seen-out *out*) + (is (= 1 1))))] + (try + (is (false? (hawk.hooks/after-each-hooks-registered?))) + (hawk/run-tests [v] {:report silent-reporter}) + (testing "*out* should not get wrapped when no after-each hooks are registered" + (is (identical? outer-out @seen-out))) + (finally + (remove-ns scratch-ns))))) + +(deftest after-each-parallel-test + (let [scratch-ns 'mb.hawk.hooks-test.parallel-scratch + ;; a barrier forces both ^:parallel tests to be in-flight at the same time, so the test fails loudly if they + ;; are not actually run concurrently, and proves the per-test output buffers stay isolated under concurrency + ^CyclicBarrier barrier (CyclicBarrier. 2) + await! (fn [] (try + (.await barrier 10 TimeUnit/SECONDS) + (catch BrokenBarrierException _ nil))) + body (fn [c] (fn [] + (await!) + (dotimes [_ 100] (print c)) + (is (= 1 1)))) + v1 (make-test-var scratch-ns 'parallel-test-1 (body "1") :parallel true) + v2 (make-test-var scratch-ns 'parallel-test-2 (body "2") :parallel true) + contexts (atom {})] + (try + (with-out-str + (do-with-after-each-hook + (fn [_options context] + (swap! contexts assoc (:name (meta (:var context))) context)) + (fn [] + (hawk/run-tests [v1 v2] {:report silent-reporter})))) + (let [context-1 (get @contexts 'parallel-test-1) + context-2 (get @contexts 'parallel-test-2)] + (is (true? (:parallel? context-1))) + (is (true? (:parallel? context-2))) + (testing "each test's captured output should be isolated from the other parallel test's output" + (is (= (apply str (repeat 100 "1")) (:output context-1))) + (is (= (apply str (repeat 100 "2")) (:output context-2))))) + (finally + (remove-ns scratch-ns)))))