Make integration tests more enjoyable to use (#19025)

This commit brings numerous improvements to integration tests. The next step
will be to apply the same improvements to contract tests.

Fixes https://github.com/status-im/status-mobile/issues/18676

Improvements:

- Setting up the application and logged account per test is now done with an
  async test fixture, which is a very idiomatic way to solve this problem. No
  need anymore to write macros to wrap day8.re-frame.test/wait-for. The macros
  in test-helpers.integration will be removed once we apply the same
  improvements to contract tests.
- Integration test timeouts can be controlled per test, with a configurable,
  global default (60s).
- Now the integration test suite will fail-fast by default, i.e. a test failure
  short-circuits the entire suite immediately. This option can be overridden on
  a test-by-test basis. This improvement is very useful when investigating
  failures because the error will be shown on the spot, with no need to search
  backwards across lots of logs.
- Noisy messages from re-frame can be silenced with a test fixture. We can
  silence even more in the future if we remove the hardcoded printf call from
  C++ on every signal and control it with Clojure. We can disable most logs as
  well with the more direct (status-im.common.log/setup "ERROR") at the top of
  tests.integration-test.core. We can make verbosity even more convenient to
  control, but I think this should be designed outside this PR.
- Removed dependency on lib day8.re-frame/test for integration tests (see
  detailed explanation below).
- Each call to (our) wait-for can customize the timeout to process re-frame
  event IDs passed to it.
- Syntax is now flat, instead of being nested on every call to wait-for. You
  can now compose other async operations anywhere in a test.

Notes:

- promesa.core/do is essential in the integration test suite, as it makes sync &
  async operations play nice with each other without the developer having to
  promisify anything manually.
- There are lots of logs related to async storage ("unexpected token u in JSON at
  position..."). This isn't fixed yet.

Are we not going to use day8.re-frame.test?

We don't need this library in integration tests and we won't need it in contract
tests. Whether it will be useful after we remove it from integration and
contract tests is yet to be seen (probably not).

A few reasons:

- The async model of promises is well understood and battle tested. The one
  devised in the lib is poorly understood and rigid.
- There's basically no way to correctly integrate other async operations in the
  test, unless they can be fully controlled via re-frame events. For instance,
  how would you control timeouts? How would you retry in a test? How would
  forcefully delay an operation by a few seconds? These things are useful (to me
  at least) when developing integration/contract tests.
- Every call to day8.re-frame.test/wait-for forces you to nest code one more
  level. Code readability suffers from that choice.
- Have you ever looked up the implementation of wait-for? It's quite convoluted.
  One could say the source code is not that important, but many times I had to
  look it up because I couldn't understand the async model they built with their
  macro approach. The de facto primitive in JS for asynchronicity is promises,
  and we fully leverage it in this PR.
- The lib has an interesting macro run-test-sync, but we have no usage for it. I
  used it in status-mobile for a while. At one point, all event unit tests for
  the Activity Center used it (e.g. commit
  08fb0de7b0), but I replaced them with the
  simpler pure function style.

.clj-kondo/config.edn

@@ -26,6 +26,7 @@
                                                           malli.generator         malli.generator
                                                           malli.transform         malli.transform
                                                           malli.util              malli.util
+                                                          promesa.core            p
                                                           schema.core             schema
                                                           status-im.feature-flags ff
                                                           taoensso.timbre         log}}

.zprintrc

@@ -29,6 +29,8 @@
   "h/test"             :arg1-body
   "h/test-skip"        :arg1-body
   "h/test-only"        :arg1-body
+  "test/async"         :arg1-body
+  "test/use-fixtures"  :arg1-body
   "global.describe"    :arg1-body
   "global.test"        :arg1-body
   "list-comp"          :binding
@@ -39,6 +41,7 @@
   "reg-fx"             :arg1-pair
   "testing"            :arg1-body
   "deftest-sub"        :arg1-body
+  "h/integration-test" :arg1-body
   "wait-for"           :arg1-body
   "with-deps-check"    :arg1-body
   "schema/=>"          :arg1-body

src/test_helpers/integration.cljs

@@ -1,16 +1,35 @@
 (ns test-helpers.integration
   (:require-macros [test-helpers.integration])
   (:require
-    [cljs.test :refer [is]]
+    [cljs.test :refer [is] :as test]
     legacy.status-im.events
+    [legacy.status-im.multiaccounts.logout.core :as logout]
     legacy.status-im.subs.root
+    [legacy.status-im.utils.test :as legacy-test]
     [native-module.core :as native-module]
+    [promesa.core :as p]
     [re-frame.core :as rf]
+    [re-frame.interop :as rf.interop]
     status-im.events
     status-im.navigation.core
     status-im.subs.root
     [taoensso.timbre :as log]
-    [tests.integration-test.constants :as constants]))
+    [tests.integration-test.constants :as constants]
+    [utils.collection :as collection]))
+
+(def default-re-frame-wait-for-timeout-ms
+  "Controls the maximum time allowed to wait for all events to be processed by
+  re-frame on every call to `wait-for`.
+
+  Take into consideration that some endpoints/signals may take significantly
+  more time to finish/arrive."
+  (* 10 1000))
+
+(def default-integration-test-timeout-ms
+  "Use a high-enough value in milliseconds to timeout integration tests. Not too
+  small, which would cause sporadic failures, and not too high as to make you
+  sleepy."
+  (* 60 1000))
 
 (defn initialize-app!
   []
@@ -59,4 +78,148 @@
 
 (defn log-headline
   [test-name]
-  (log/info (str "========= " (name test-name) " ==================")))
+  (log/info (str "==== " test-name " ====")))
+
+(defn wait-for
+  "Returns a promise that resolves when all `event-ids` are processed by re-frame,
+  otherwise rejects after `timeout-ms`.
+
+  If an event ID that is expected in `event-ids` occurs in a different order,
+  the promise will be rejected."
+  ([event-ids]
+   (wait-for event-ids default-re-frame-wait-for-timeout-ms))
+  ([event-ids timeout-ms]
+   (let [waiting-ids (atom event-ids)]
+     (p/create
+      (fn [promise-resolve promise-reject]
+        (let [cb-id    (gensym "post-event-callback")
+              timer-id (js/setTimeout (fn []
+                                        (rf/remove-post-event-callback cb-id)
+                                        (promise-reject (ex-info
+                                                         "timed out waiting for all event-ids to run"
+                                                         {:event-ids   event-ids
+                                                          :waiting-ids @waiting-ids
+                                                          :timeout-ms  timeout-ms}
+                                                         ::timeout)))
+                                      timeout-ms)]
+          (rf/add-post-event-callback
+           cb-id
+           (fn [[event-id & _]]
+             (when-let [idx (collection/first-index #(= % event-id) @waiting-ids)]
+               ;; All `event-ids` should be processed in their original order.
+               (if (zero? idx)
+                 (do
+                   (swap! waiting-ids rest)
+                   ;; When there's nothing else to wait for, clean up resources.
+                   (when (empty? @waiting-ids)
+                     (js/clearTimeout timer-id)
+                     (rf/remove-post-event-callback cb-id)
+                     (promise-resolve)))
+                 (do
+                   (js/clearTimeout timer-id)
+                   (rf/remove-post-event-callback cb-id)
+                   (promise-reject (ex-info "event happened in unexpected order"
+                                            {:event-ids   event-ids
+                                             :waiting-for @waiting-ids}
+                                            ::out-of-order-event-id)))))))))))))
+
+(defn setup-app
+  []
+  (legacy-test/init!)
+  (if (app-initialized)
+    (p/resolved ::app-initialized)
+    (do
+      (rf/dispatch [:app-started])
+      (wait-for [:profile/get-profiles-overview-success]))))
+
+(defn setup-account
+  []
+  (if (messenger-started)
+    (p/resolved ::messenger-started)
+    (do
+      (create-multiaccount!)
+      (-> (wait-for [:messenger-started])
+          (.then #(assert-messenger-started))))))
+
+(defn integration-test
+  "Runs `f` inside `cljs.test/async` macro in a restorable re-frame checkpoint.
+
+  `f` will be called with one argument, the `done` function exposed by the
+  `cljs.test/async` macro. Normally, you don't need to use `done`, but you can
+  call it if you want to early-terminate the current test, so that the test
+  runner can execute the next one.
+
+  Option `fail-fast?`, when truthy (defaults to true), will force the test
+  runner to terminate on any test failure. Setting it to false can be useful
+  during development when you want the rest of the test suite to run due to a
+  flaky test. Prefer to fail fast in the CI to save on time & resources.
+
+  When `fail-fast?` is falsey, re-frame's state is automatically restored after
+  a test failure, so that the next integration test can run from a pristine
+  state.
+
+  Option `timeout-ms` controls the total time allowed to run `f`. The value
+  should be high enough to account for some variability, otherwise the test may
+  fail more often.
+  "
+  ([test-name f]
+   (integration-test test-name
+                     {:fail-fast? true
+                      :timeout-ms default-integration-test-timeout-ms}
+                     f))
+  ([test-name {:keys [fail-fast? timeout-ms]} f]
+   (test/async
+     done
+     (let [restore-fn (rf/make-restore-fn)]
+       (log-headline test-name)
+       (-> (p/do (f done))
+           (p/timeout timeout-ms)
+           (p/catch (fn [error]
+                      (is (nil? error))
+                      (when fail-fast?
+                        (js/process.exit 1))))
+           (p/finally (fn []
+                        (restore-fn)
+                        (done))))))))
+
+;;;; Fixtures
+
+(defn fixture-session
+  "Fixture to set up the application and a logged account before the test runs.
+  Log out after the test is done.
+
+  Usage:
+
+      (use-fixtures :each (h/fixture-logged))"
+  []
+  {:before (fn []
+             (test/async done
+               (p/do (setup-app)
+                     (setup-account)
+                     (done))))
+   :after  (fn []
+             (test/async done
+               (p/do (logout)
+                     (wait-for [::logout/logout-method])
+                     (done))))})
+
+(defn fixture-silence-reframe
+  "Fixture to disable most re-frame messages.
+
+  Avoid using this fixture for non-dev purposes because in the CI output it's
+  desirable to have more data to debug, not less.
+
+  Example messages disabled:
+
+  - Warning about subscriptions being used in non-reactive contexts.
+  - Debug message \"Handling re-frame event: XYZ\".
+
+  Usage:
+
+      (use-fixtures :once (h/fixture-silence-re-frame))
+  "
+  []
+  {:before (fn []
+             (set! rf.interop/debug-enabled? false))
+   :after  (fn []
+             (set! rf.interop/debug-enabled? true))})

src/tests/integration_test/chat_test.cljs

@@ -1,10 +1,9 @@
 (ns tests.integration-test.chat-test
   (:require
-    [cljs.test :refer [deftest is]]
+    [cljs.test :refer [deftest is use-fixtures]]
-    [day8.re-frame.test :as rf-test]
     legacy.status-im.events
-    [legacy.status-im.multiaccounts.logout.core :as logout]
     legacy.status-im.subs.root
+    [promesa.core :as p]
     [re-frame.core :as rf]
     [status-im.constants :as constants]
     status-im.events
@@ -12,85 +11,69 @@
     status-im.subs.root
     [test-helpers.integration :as h]))
 
+(use-fixtures :each (h/fixture-session))
+
 (def chat-id
   "0x0402905bed83f0bbf993cee8239012ccb1a8bc86907ead834c1e38476a0eda71414eed0e25f525f270592a2eebb01c9119a4ed6429ba114e51f5cb0a28dae1adfd")
 
 (deftest one-to-one-chat-test
-  (h/log-headline :one-to-one-chat-test)
+  (h/integration-test ::one-to-one-chat
-  (rf-test/run-test-async
+    (fn []
-   (h/with-app-initialized
+      (p/do
-    (h/with-account
+        (rf/dispatch-sync [:chat.ui/start-chat chat-id])
-     (rf/dispatch-sync [:chat.ui/start-chat chat-id]) ;; start a new chat
+        (h/wait-for [:chat/one-to-one-chat-created])
-     (rf-test/wait-for
-       [:chat/one-to-one-chat-created]
         (rf/dispatch-sync [:chat/navigate-to-chat chat-id])
-       (is (= chat-id @(rf/subscribe [:chats/current-chat-id])))
+        (is (= chat-id @(rf/subscribe [:chats/current-chat-id])))))))
-       (h/logout)
-       (rf-test/wait-for [::logout/logout-method]))))))
 
 (deftest delete-chat-test
-  (h/log-headline :delete-chat-test)
+  (h/integration-test ::delete-chat
-  (rf-test/run-test-async
+    (fn []
-   (h/with-app-initialized
+      (p/do
-    (h/with-account
+        (rf/dispatch-sync [:chat.ui/start-chat chat-id])
-     (rf/dispatch-sync [:chat.ui/start-chat chat-id]) ;; start a new chat
+        (h/wait-for [:chat/one-to-one-chat-created])
-     (rf-test/wait-for
-       [:chat/one-to-one-chat-created]
         (rf/dispatch-sync [:chat/navigate-to-chat chat-id])
         (is (= chat-id @(rf/subscribe [:chats/current-chat-id])))
         (is @(rf/subscribe [:chats/chat chat-id]))
         (rf/dispatch-sync [:chat.ui/show-remove-confirmation chat-id])
-       (rf/dispatch-sync [:chat.ui/remove-chat chat-id])
+        (rf/dispatch-sync [:chat.ui/remove-chat chat-id])))))
-       (h/logout)
-       (rf-test/wait-for [::logout/logout-method]))))))
 
 (deftest mute-chat-test
-  (h/log-headline :mute-chat-test)
+  (h/integration-test ::mute-chat
-  (rf-test/run-test-async
+    (fn []
-   (h/with-app-initialized
+      (p/do
-    (h/with-account
+        (rf/dispatch-sync [:chat.ui/start-chat chat-id])
-     (rf/dispatch-sync [:chat.ui/start-chat chat-id]) ;; start a new chat
+        (h/wait-for [:chat/one-to-one-chat-created])
-     (rf-test/wait-for
+
-       [:chat/one-to-one-chat-created]
         (rf/dispatch-sync [:chat/navigate-to-chat chat-id])
         (is (= chat-id @(rf/subscribe [:chats/current-chat-id])))
         (is @(rf/subscribe [:chats/chat chat-id]))
+
         (rf/dispatch-sync [:chat.ui/mute chat-id true constants/mute-till-unmuted])
-       (rf-test/wait-for
+        (h/wait-for [:chat/mute-successfully])
-         [:chat/mute-successfully]
         (is @(rf/subscribe [:chats/muted chat-id]))
+
         (rf/dispatch-sync [:chat.ui/mute chat-id false])
-         (rf-test/wait-for
+        (h/wait-for [:chat/mute-successfully])
-           [:chat/mute-successfully]
+        (is (not @(rf/subscribe [:chats/muted chat-id])))))))
-           (is (not @(rf/subscribe [:chats/muted chat-id])))
-           (h/logout)
-           (rf-test/wait-for [::logout/logout-method]))))))))
 
 (deftest add-contact-test
-  (h/log-headline :add-contact-test)
+  (h/integration-test ::add-contact
-  (let
+    (fn []
-    [compressed-key "zQ3shMwgSMKHVznoowceZMxWde9HUnkQEVSGvvex8UFpFNErL"
+      (let [compressed-key "zQ3shMwgSMKHVznoowceZMxWde9HUnkQEVSGvvex8UFpFNErL"
             public-key     (str "0x0407e9dc435fe366cb0b4c4f35cbd925438c0f46fe0"
                                 "ed2a86050325bc8856e26898c17e31dee2602b9429c91"
                                 "ecf65a41d62ac1f2f0823c0710dcb536e79af2763c")
             primary-name   "zQ3...pFNErL"]
-    (rf-test/run-test-async
+        (p/do
-     (h/with-app-initialized
+          ;; Search for contact using compressed key
-      (h/with-account
-       ;; search for contact using compressed key
           (rf/dispatch [:contacts/set-new-identity {:input compressed-key}])
-       (rf-test/wait-for
+          (h/wait-for [:contacts/set-new-identity-success])
-         [:contacts/set-new-identity-success]
           (let [new-identity @(rf/subscribe [:contacts/new-identity])]
             (is (= public-key (:public-key new-identity)))
             (is (= :valid (:state new-identity))))
-         ;; click 'view profile' button
+
+          ;; Click 'view profile' button
           (rf/dispatch [:chat.ui/show-profile public-key])
-         (rf-test/wait-for
+          (h/wait-for [:contacts/build-contact :contacts/build-contact-success])
-           [:contacts/build-contact]
-           (rf-test/wait-for
-             [:contacts/build-contact-success]
           (let [contact @(rf/subscribe [:contacts/current-contact])]
-               (is (= primary-name (:primary-name contact))))
+            (is (= primary-name (:primary-name contact)))))))))
-             (h/logout)
-             (rf-test/wait-for [::logout/logout-method])))))))))

src/tests/integration_test/core_test.cljs

@@ -1,11 +1,11 @@
 (ns tests.integration-test.core-test
   (:require
     [cljs.test :refer [deftest]]
-    [day8.re-frame.test :as rf-test]
     legacy.status-im.events
     [legacy.status-im.multiaccounts.logout.core :as logout]
     legacy.status-im.subs.root
     [legacy.status-im.utils.test :as utils.test]
+    [promesa.core :as p]
     [re-frame.core :as rf]
     status-im.events
     status-im.navigation.core
@@ -13,22 +13,22 @@
     [test-helpers.integration :as h]))
 
 (deftest initialize-app-test
-  (h/log-headline :initialize-app-test)
+  (h/integration-test ::initialize-app
-  (rf-test/run-test-async
+    (fn []
+      (p/do
         (utils.test/init!)
         (rf/dispatch [:app-started])
-   (rf-test/wait-for
+        ;; Use initialize-view because it has the longest avg. time and is
-     ;; use initialize-view because it has the longest avg. time and
+        ;; dispatched by initialize-multiaccounts (last non-view event).
-     ;; is dispatched by initialize-multiaccounts (last non-view event)
+        (h/wait-for [:profile/get-profiles-overview-success
-     [:profile/get-profiles-overview-success]
+                     :font/init-font-file-for-initials-avatar])
-     (rf-test/wait-for
-       [:font/init-font-file-for-initials-avatar]
         (h/assert-app-initialized)))))
 
 (deftest create-account-test
-  (h/log-headline :create-account-test)
+  (h/integration-test ::create-account
-  (rf-test/run-test-async
+    (fn []
-   (h/with-app-initialized
+      (p/do
-    (h/with-account
+        (h/setup-app)
+        (h/setup-account)
         (h/logout)
-     (rf-test/wait-for [::logout/logout-method])))))
+        (h/wait-for [::logout/logout-method])))))

src/tests/integration_test/profile_test.cljs

@@ -1,75 +1,52 @@
 (ns tests.integration-test.profile-test
   (:require
-    [cljs.test :refer [deftest is]]
+    [cljs.test :refer [deftest is use-fixtures]]
-    [day8.re-frame.test :as rf-test]
-    [legacy.status-im.multiaccounts.logout.core :as logout]
     [legacy.status-im.utils.test :as utils.test]
+    [promesa.core :as p]
     [status-im.contexts.profile.utils :as profile.utils]
     [test-helpers.integration :as h]
     [utils.re-frame :as rf]))
 
+(use-fixtures :each (h/fixture-session))
+
 (deftest edit-profile-name-test
-  (h/log-headline :edit-profile-name-test)
+  (h/integration-test ::edit-profile-name
+    (fn []
       (let [new-name "John Doe"]
-    (rf-test/run-test-async
+        (p/do
-     (h/with-app-initialized
-      (h/with-account
           (rf/dispatch [:profile/edit-name new-name])
-       (rf-test/wait-for
+          (h/wait-for [:navigate-back :toasts/upsert])
-         [:navigate-back]
-         (rf-test/wait-for
-           [:toasts/upsert]
           (let [profile      (rf/sub [:profile/profile])
                 display-name (profile.utils/displayed-name profile)]
-             (is (= new-name display-name)))
+            (is (= new-name display-name))))))))
-           (h/logout)
-           (rf-test/wait-for [::logout/logout-method]))))))))
 
 (deftest edit-profile-picture-test
-  (h/log-headline :edit-profile-picture-test)
+  (h/integration-test ::edit-profile-picture
+    (fn []
       (let [mock-image    "resources/images/mock2/monkey.png"
             absolute-path (.resolve utils.test/path mock-image)]
-    (rf-test/run-test-async
+        (p/do
-     (h/with-app-initialized
-      (h/with-account
           (rf/dispatch [:profile/edit-picture absolute-path 80 80])
-       (rf-test/wait-for
+          (h/wait-for [:profile/update-local-picture :toasts/upsert])
-         [:profile/update-local-picture]
-         (rf-test/wait-for
-           [:toasts/upsert]
           (let [profile (rf/sub [:profile/profile])]
-             (is (not (nil? (:images profile)))))
+            (is (not (nil? (:images profile))))))))))
-           (h/logout)
-           (rf-test/wait-for [::logout/logout-method]))))))))
 
 (deftest delete-profile-picture-test
-  (h/log-headline :delete-profile-picture-test)
+  (h/integration-test ::delete-profile-picture
-  (rf-test/run-test-async
+    (fn []
-   (h/with-app-initialized
+      (p/do
-    (h/with-account
         (rf/dispatch [:profile/delete-picture])
-     (rf-test/wait-for
+        (h/wait-for [:profile/update-local-picture :toasts/upsert])
-       [:profile/update-local-picture]
-       (rf-test/wait-for
-         [:toasts/upsert]
         (let [profile (rf/sub [:profile/profile])]
-           (is (nil? (:image profile))))
+          (is (nil? (:image profile))))))))
-         (h/logout)
-         (rf-test/wait-for [::logout/logout-method])))))))
 
 (deftest edit-profile-bio-test
-  (h/log-headline :edit-profile-bio-test)
+  (h/integration-test ::edit-profile-bio
+    (fn []
       (let [new-bio "New bio text"]
-    (rf-test/run-test-async
+        (p/do
-     (h/with-app-initialized
-      (h/with-account
           (rf/dispatch [:profile/edit-bio new-bio])
-       (rf-test/wait-for
+          (h/wait-for [:navigate-back :toasts/upsert])
-         [:navigate-back]
-         (rf-test/wait-for
-           [:toasts/upsert]
           (let [profile (rf/sub [:profile/profile])
                 bio     (:bio profile)]
-             (is (= new-bio bio)))
+            (is (= new-bio bio))))))))
-           (h/logout)
-           (rf-test/wait-for [::logout/logout-method]))))))))

src/utils/re_frame.cljs

@@ -3,6 +3,7 @@
   (:require
     [re-frame.core :as re-frame]
     [re-frame.interceptor :as interceptor]
+    [re-frame.interop :as rf.interop]
     [reagent.core :as reagent]
     [taoensso.timbre :as log]
     [utils.datetime :as datetime])
@@ -20,7 +21,9 @@
              [context]
              (when js/goog.DEBUG
                (reset! handler-nesting-level 0))
-             (log/debug "Handling re-frame event: " (first (interceptor/get-coeffect context :event)))
+             (when rf.interop/debug-enabled?
+               (log/debug "Handling re-frame event: "
+                          (first (interceptor/get-coeffect context :event))))
              context)))
 
 (defn- update-db