diff --git a/test/metabase/test/util_test.clj b/test/metabase/test/util_test.clj index ca1b9f15e4c71dc539ba98d669a9dd8b2e0a533e..8fd89f271e8065234e9d3e1e8542bbcf8e0543ba 100644 --- a/test/metabase/test/util_test.clj +++ b/test/metabase/test/util_test.clj @@ -7,8 +7,11 @@ [metabase.test :as mt] [metabase.test.data :as data] [metabase.util :as u] + [metabase.util.log :as log] [toucan2.core :as t2]) - (:import (java.util.concurrent CountDownLatch TimeUnit))) + (:import + (clojure.lang Agent) + (java.util.concurrent CountDownLatch ThreadPoolExecutor TimeUnit))) (set! *warn-on-reflection* true) @@ -50,24 +53,35 @@ (deftest ^:parallel with-dynamic-redefs-test (testing "Three threads can independently redefine a regular var" - (let [n-threads 3 - latch (CountDownLatch. (inc n-threads)) - take-latch #(do - (.countDown latch) - (when-not (.await latch 100 TimeUnit/MILLISECONDS) - (throw (ex-info "Timeout waiting on all threads to pull their latch" {:latch latch}))))] + (let [n-threads 3 + ;; Note that .getId is deprecated in favor of .threadId, but that method is only introduced in Java 19 + thread-id #(.getId (Thread/currentThread)) + latch (CountDownLatch. (inc n-threads)) + take-latch #(do + (.countDown latch) + ;; We give a generous timeout here in case there is heavy contention for the thread pool in CI + (when-not (.await latch 30 TimeUnit/SECONDS) + (throw (ex-info "Timeout waiting on all threads to pull their latch" + {:latch latch + :thread-id (thread-id) + :agent-pool (let [^ThreadPoolExecutor executor Agent/pooledExecutor] + {:active-count (.getActiveCount executor) + :pool-size (.getPoolSize executor) + :task-count (.getTaskCount executor)})}))))] (testing "The original definition" (is (= "original" (clump "o" "riginal")))) (future - (testing "A thread that minds its own business" + (testing "A thread that minds its own business" + (log/debug "Starting no-op thread, thread-id:" (thread-id)) (is (= "123" (clump 12 3))) (take-latch) (is (= "321" (clump 3 21))))) (future (testing "A thread that redefines it in reverse" + (log/debug "Starting reverse thread, thread-id:" (thread-id)) (mt/with-dynamic-redefs [clump #(str %2 %1)] (is (= "ok" (clump "k" "o"))) (take-latch) @@ -75,7 +89,8 @@ (future (testing "A thread that redefines it twice" - (mt/with-dynamic-redefs [clump #(str %2 %2)] + (log/debug "Starting double-redefining thread, thread-id:" (thread-id)) + (mt/with-dynamic-redefs [clump (fn [_ y] (str y y))] (is (= "zz" (clump "a" "z"))) (mt/with-dynamic-redefs [clump (fn [x _] (str x x))] (is (= "aa" (clump "a" "z"))) @@ -83,6 +98,7 @@ (is (= "mm" (clump "m" "l")))) (is (= "bb" (clump "a" "b")))))) + (log/debug "Taking latch on main thread, thread-id:" (thread-id)) (take-latch) (testing "The original definition survives" (is (= "original" (clump "orig" "inal"))))))) diff --git a/test_config/log4j2-test.xml b/test_config/log4j2-test.xml index aa899da4e81491fb8b9673bce9b1e3a6ea7a84fe..99d3b8741bfcc551af5f0e3998fdea1b8638e09a 100644 --- a/test_config/log4j2-test.xml +++ b/test_config/log4j2-test.xml @@ -10,6 +10,7 @@ <Logger name="metabase-enterprise" level="FATAL"/> <Logger name="liquibase" level="FATAL"/> <Logger name="metabase.test.data.interface" level="INFO"/> + <Logger name="metabase.test.util-test" level="DEBUG" /> <Root level="FATAL"> <AppenderRef ref="Console"/>