Increase timeout for with-dynamic-redefs test (metabase#41516)

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,39 +53,52 @@
 
 (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)
             (is (= "ko" (clump "o" "k"))))))
 
       (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")))
               (take-latch)
               (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")))))))

test_config/log4j2-test.xml

@@ -11,6 +11,7 @@
     <Logger name="liquibase" level="FATAL"/>
     <Logger name="metabase.test.data.interface" level="INFO"/>
     <Logger name="metabase.sync.fetch-metadata" level="ERROR"/>
+    <Logger name="metabase.test.util-test" level="DEBUG" />
 
     <Root level="FATAL">
       <AppenderRef ref="Console"/>