From 72522ead9175e20e8060ed23276464d60227a8c7 Mon Sep 17 00:00:00 2001 From: Moritz Heidkamp Date: Wed, 17 Sep 2025 22:10:10 +0200 Subject: [PATCH] Detect accidentally dropped errors in tests Manifold has a debug mechanism which instruments deferreds so that a warning is logged when they are in an error state with no error handler attached at garbage collection time. Such errors are referred to as "dropped errors" and the instrumented deferreds are called "leak-aware". The dropped error logging feature is enabled by default but for performance reasons, only every 1024th deferred is made leak-aware (see `manifold.deferred/deferred`). However, deferreds constructed via `manifold.deferred/error-deferred` are always leak-aware. This patch introduces a new option `manifold.debug/*leak-aware-deferred-rate*` which allows changing the rate of leak-aware deferreds being instantiated, with default still being 1024. When this option is set to to 1 (= every deferred will be leak-aware), dropped errors can be detected more reliably e.g. during testing. To that end, the patch also includes a test util for instrumenting all tests in a namespace so that they fail when a dropped error was detected. All test namespaces are now instrumented like this (except for `:benchmark` and `:stress` tests), which already uncovered a few latent dropped errors. These will be fixed in separate patches. --- src/manifold/debug.clj | 30 +++++++++++++++- src/manifold/deferred.clj | 13 ++++--- test/manifold/bus_test.clj | 2 ++ test/manifold/deferred_stage_test.clj | 3 ++ test/manifold/deferred_test.clj | 31 +++++++++------- test/manifold/executor_test.clj | 5 ++- test/manifold/go_off_test.clj | 4 ++- test/manifold/stream_test.clj | 12 ++++--- test/manifold/test_utils.clj | 52 ++++++++++++++++++++++++++- test/manifold/time_test.clj | 2 ++ 10 files changed, 128 insertions(+), 26 deletions(-) diff --git a/src/manifold/debug.clj b/src/manifold/debug.clj index 47732966..a5b24cca 100644 --- a/src/manifold/debug.clj +++ b/src/manifold/debug.clj @@ -1,5 +1,6 @@ (ns manifold.debug - {:no-doc true}) + {:no-doc true} + (:require [clojure.tools.logging :as log])) (def ^:dynamic *dropped-error-logging-enabled?* true) @@ -8,3 +9,30 @@ (defn disable-dropped-error-logging! [] (.bindRoot #'*dropped-error-logging-enabled?* false)) + +(def ^:dynamic *leak-aware-deferred-rate* 1024) + +(defn set-leak-aware-deferred-rate! [n] + (.bindRoot #'*leak-aware-deferred-rate* n)) + +(def dropped-errors nil) + +(defn log-dropped-error! [error] + (some-> dropped-errors (swap! inc)) + (log/warn error "unconsumed deferred in error state, make sure you're using `catch`.")) + +(defn with-dropped-error-detection + "Calls f, then attempts to trigger dropped errors to be detected and finally calls + handle-dropped-errors with the number of detected dropped errors. Details about these are logged + as warnings." + [f handle-dropped-errors] + (assert (nil? dropped-errors) "with-dropped-error-detection may not be nested") + ;; Flush out any pending dropped errors from before + (System/gc) + (System/runFinalization) + (with-redefs [dropped-errors (atom 0)] + (f) + ;; Flush out any errors which were dropped during f + (System/gc) + (System/runFinalization) + (handle-dropped-errors @dropped-errors))) diff --git a/src/manifold/deferred.clj b/src/manifold/deferred.clj index 18efe072..46854694 100644 --- a/src/manifold/deferred.clj +++ b/src/manifold/deferred.clj @@ -481,8 +481,10 @@ [Object (finalize [_] (utils/with-lock lock - (when (and (identical? ::error state) (not consumed?)) - (log/warn val "unconsumed deferred in error state, make sure you're using `catch`."))))] + (when (and (identical? ::error state) + (not consumed?) + debug/*dropped-error-logging-enabled?*) + (debug/log-dropped-error! val))))] nil) clojure.lang.IReference @@ -631,7 +633,7 @@ (when (and (not consumed?) debug/*dropped-error-logging-enabled?*) - (log/warn error "unconsumed deferred in error state, make sure you're using `catch`."))) + (debug/log-dropped-error! error))) clojure.lang.IReference (meta [_] mta) @@ -690,8 +692,9 @@ ([] (deferred (ex/executor))) ([executor] - (if (and (p/zero? (rem (.incrementAndGet created) 1024)) - debug/*dropped-error-logging-enabled?*) + (if (and debug/*dropped-error-logging-enabled?* + (p/zero? (rem (.incrementAndGet created) + ^long debug/*leak-aware-deferred-rate*))) (LeakAwareDeferred. nil ::unset nil (utils/mutex) (LinkedList.) nil false executor) (Deferred. nil ::unset nil (utils/mutex) (LinkedList.) nil false executor))))) diff --git a/test/manifold/bus_test.clj b/test/manifold/bus_test.clj index 01a167ec..44db63dd 100644 --- a/test/manifold/bus_test.clj +++ b/test/manifold/bus_test.clj @@ -23,3 +23,5 @@ d (b/publish! b (long 1) 42)] (is (= 42 @(s/take! s))) (is (= true @d)))) + +(instrument-tests-with-dropped-error-detection!) diff --git a/test/manifold/deferred_stage_test.clj b/test/manifold/deferred_stage_test.clj index f8e62d4c..c63b86a6 100644 --- a/test/manifold/deferred_stage_test.clj +++ b/test/manifold/deferred_stage_test.clj @@ -1,5 +1,6 @@ (ns manifold.deferred-stage-test (:require [manifold.deferred :as d] + [manifold.test-utils :refer :all] [manifold.utils :refer [fn->Function fn->Consumer fn->BiFunction fn->BiConsumer]] [clojure.test :refer [deftest is testing]]) @@ -598,3 +599,5 @@ (d/success-deferred (d/success-deferred x)))))] (is (d/deferred? @d2))))) + +(instrument-tests-with-dropped-error-detection!) diff --git a/test/manifold/deferred_test.clj b/test/manifold/deferred_test.clj index aab00dd8..9475afaa 100644 --- a/test/manifold/deferred_test.clj +++ b/test/manifold/deferred_test.clj @@ -3,12 +3,14 @@ (:require [clojure.test :refer :all] [manifold.test-utils :refer :all] + [manifold.debug :as debug] [manifold.deferred :as d] [manifold.executor :as ex]) (:import (java.util.concurrent CompletableFuture - CompletionStage) + CompletionStage + TimeoutException) (manifold.deferred IDeferred))) (defmacro future' [& body] @@ -314,7 +316,7 @@ ;;; -(deftest ^:benchmark benchmark-chain +(deftest ^:ignore-dropped-errors ^:benchmark benchmark-chain (bench "invoke comp x1" ((comp inc) 0)) (bench "chain x1" @@ -334,7 +336,7 @@ (bench "chain' x5" @(d/chain' 0 inc inc inc inc inc))) -(deftest ^:benchmark benchmark-deferred +(deftest ^:ignore-dropped-errors ^:benchmark benchmark-deferred (bench "create deferred" (d/deferred)) (bench "add-listener and success" @@ -381,16 +383,19 @@ (deliver d 1) @d))) -(deftest ^:stress test-error-leak-detection +(deftest ^:ignore-dropped-errors ^:stress test-error-leak-detection + (testing "error-deferred always detects dropped errors" + (expect-dropped-errors 1 + (d/error-deferred (Throwable.)))) - (d/error-deferred (Throwable.)) - (System/gc) + (testing "regular deferreds detect errors on every debug/*leak-aware-deferred-rate*'th instance (1024 by default)" + (expect-dropped-errors 2 + ;; Explicitly restating the (current) default here for clarity + (binding [debug/*leak-aware-deferred-rate* 1024] + (dotimes [_ 2048] + (d/error! (d/deferred) (Throwable.))))))) - (dotimes [_ 2e3] - (d/error! (d/deferred) (Throwable.))) - (System/gc)) - -(deftest ^:stress test-deferred-chain +(deftest ^:ignore-dropped-errors ^:stress test-deferred-chain (dotimes [_ 1e4] (let [d (d/deferred) result (d/future @@ -401,7 +406,7 @@ (d/connect % d') d') d))))] - (Thread/sleep (rand-int 10)) + (Thread/sleep ^long (rand-int 10)) (d/success! d 1) (is (= 1 @@result))))) @@ -431,3 +436,5 @@ (finally (remove-method print-method CompletionStage)))) + +(instrument-tests-with-dropped-error-detection!) diff --git a/test/manifold/executor_test.clj b/test/manifold/executor_test.clj index 7ed20bd2..dbe026e8 100644 --- a/test/manifold/executor_test.clj +++ b/test/manifold/executor_test.clj @@ -1,7 +1,8 @@ (ns manifold.executor-test (:require [clojure.test :refer :all] - [manifold.executor :as e]) + [manifold.executor :as e] + [manifold.test-utils :refer :all]) (:import [io.aleph.dirigiste Executor @@ -68,3 +69,5 @@ 500) thread (.newThread tf (constantly nil))] (is (= "custom-name" (.getName thread))))) + +(instrument-tests-with-dropped-error-detection!) diff --git a/test/manifold/go_off_test.clj b/test/manifold/go_off_test.clj index 98677dc9..cafc8ed0 100644 --- a/test/manifold/go_off_test.clj +++ b/test/manifold/go_off_test.clj @@ -149,7 +149,7 @@ (s/close! test-stream) (is (= @test-d [0 1 2 nil nil])))) -(deftest ^:benchmark benchmark-go-off +(deftest ^:ignore-dropped-errors ^:benchmark benchmark-go-off (bench "invoke comp x1" ((comp inc) 0)) (bench "go-off x1" @@ -174,3 +174,5 @@ @(go-off (inc (! c 1)) (async/! c 1)) (async/> (ns-interns *ns*) + vals + (filter (comp :test meta)) + (run! (fn [tv] + (when-not (:ignore-dropped-errors (meta tv)) + (alter-meta! tv update :test instrument-test-fn-with-dropped-error-detection)))))) + +(defmacro expect-dropped-errors + "Expect n number of dropped errors after executing body in the form of a test assertion. + + Add `:ignore-dropped-errors` to the a test's metadata to be able to use this macro in an + instrumented namespace (see `instrument-tests-with-dropped-error-detection!`)." + [n & body] + `(debug/with-dropped-error-detection + (fn [] ~@body) + (fn [n#] + (test/is (= ~n n#) "Expected number of dropped errors doesn't match detected number of dropped errors.")))) diff --git a/test/manifold/time_test.clj b/test/manifold/time_test.clj index eb773bc5..13cdaa19 100644 --- a/test/manifold/time_test.clj +++ b/test/manifold/time_test.clj @@ -81,3 +81,5 @@ (is (= 1 @counter)) (t/advance c 1) (is (= 1 @counter)))) + +(instrument-tests-with-dropped-error-detection!)