From f76b1447ee0a70969db8e17515857c8d47659133 Mon Sep 17 00:00:00 2001 From: Alonso Torres Date: Wed, 14 Oct 2026 10:20:27 +0200 Subject: [PATCH] :sparkles: Improve error report and warn on update loops (#12044) --- frontend/deps.edn | 8 +- frontend/src/app/main.cljs | 4 +- frontend/src/app/main/errors.cljs | 70 ++++++++- .../app/main/ui/workspace/viewport/hooks.cljs | 2 +- .../test/frontend_tests/main_errors_test.cljs | 142 ++++++++++++++++++ 5 files changed, 215 insertions(+), 11 deletions(-) diff --git a/frontend/deps.edn b/frontend/deps.edn index b1293a652c..c5184e43ae 100644 --- a/frontend/deps.edn +++ b/frontend/deps.edn @@ -15,8 +15,8 @@ :git/url "https://github.com/funcool/tubax.git"} funcool/potok2 - {:git/tag "v2.2" - :git/sha "0f7e15a" + {:git/tag "v2.3" + :git/sha "bdebbdb" :git/url "https://github.com/funcool/potok.git" :exclusions [funcool/beicon2]} @@ -26,8 +26,8 @@ :git/url "https://github.com/funcool/beicon.git"} funcool/rumext - {:git/tag "v2.25" - :git/sha "27e5a1a" + {:git/tag "v2.26" + :git/sha "d726717" :git/url "https://github.com/funcool/rumext.git"} instaparse/instaparse {:mvn/version "1.5.0"} diff --git a/frontend/src/app/main.cljs b/frontend/src/app/main.cljs index c7d87ba8ba..dbd3deb96c 100644 --- a/frontend/src/app/main.cljs +++ b/frontend/src/app/main.cljs @@ -16,7 +16,7 @@ [app.main.data.event :as ev] [app.main.data.profile :as dp] [app.main.data.websocket :as ws] - [app.main.errors] + [app.main.errors :as errors] [app.main.features :as feat] [app.main.rasterizer :as thr] [app.main.store :as st] @@ -134,6 +134,8 @@ (i18n/init) (cur/init-styles) + (mf/set-update-scheduler {:on-trip errors/on-update-loop}) + (init-ui) (st/emit! (plugins/initialize) (initialize))))) diff --git a/frontend/src/app/main/errors.cljs b/frontend/src/app/main/errors.cljs index 928722f889..d2c4976024 100644 --- a/frontend/src/app/main/errors.cljs +++ b/frontend/src/app/main/errors.cljs @@ -100,6 +100,40 @@ (assoc ::instance cause) (assoc ::trace (.-stack cause))))) +;; Events in flight when each exception was caught, as report lines +(defonce ^:private in-flight-by-cause (js/WeakMap.)) + +;; Events kept from each end of a long in-flight list +(def ^:private in-flight-edge-size 10) + +(defn- in-flight-lines + "Report lines for the in-flight `events`, outermost first; a long list + keeps only both ends." + [events] + (let [total (count events) + size in-flight-edge-size] + (if (<= total (* 2 size)) + (mapv ptk/repr-event events) + (-> [] + (into (map ptk/repr-event) (take size events)) + (conj (str "... " (- total (* 2 size)) " more ...")) + (into (map ptk/repr-event) (take-last size events)))))) + +(defn- record-in-flight! + "Keeps the events the store is processing for the report of `cause`. + Runs synchronously on the error path: when an event's `update`, `effect` + or synchronous `watch` throws, the last line is that event. When a + `watch` pipeline fails on a value from the store stream, the store has + already finished that value, so the lines show the events that emitted + it, not the event that owns the pipeline." + [cause] + (try + (when (ex/exception? cause) + (when-let [events (not-empty (ptk/in-flight-events st/state))] + (.set in-flight-by-cause cause (in-flight-lines events)))) + (catch :default _ + nil))) + (defn on-error "A general purpose error handler. @@ -114,6 +148,7 @@ (ex/print-throwable error)) (do (vreset! handling-error? true) + (record-in-flight! (if (map? error) (::instance error) error)) (try (if (map? error) (ptk/handle-error error) @@ -166,8 +201,9 @@ (println "HREF: " (rt/get-current-href))))) (defn- generate-full-report - "Complete report: context, formatted throwable (including `ex-data`) and the - last events." + "Complete report: context, formatted throwable (including `ex-data`), the + events in flight when the error was caught (when recorded) and the last + events." [cause] (with-out-str (print (report-context cause)) @@ -177,6 +213,12 @@ (ex/format-throwable cause)) (println) + (when-let [lines (.get in-flight-by-cause cause)] + (println "Events in flight when the error was caught (outermost first):") + (println "--------------------") + (run! println lines) + (println)) + (println "Last events:") (println "--------------------") (println (st/format-last-events)) @@ -202,9 +244,9 @@ "Build the report string for `cause`. `:format` selects the payload: `:full` (default) includes the formatted - throwable and the last events; `:compact` keeps only the context and the - error type/code/uri, for environment failures. The option is accepted both - as keyword arguments and as a trailing map." + throwable, the in-flight and the last events; `:compact` keeps only the + context and the error type/code/uri, for environment failures. The option + is accepted both as keyword arguments and as a trailing map." [cause & {:keys [format] :or {format :full}}] (try (case format @@ -392,6 +434,24 @@ hint occurrences)))) +(defonce ^:private update-loop-warned-at + (volatile! 0)) + +(defn on-update-loop + "Handler for the rumext update scheduler trips: logs the throttled + update loop with the events being processed, at most once per + `report-window-ms`. Runs inside store watchers and effect bodies, so it + never throws." + [_] + (try + (let [now (inst-ms (ct/now))] + (when (>= (- now @update-loop-warned-at) report-window-ms) + (vreset! update-loop-warned-at now) + (.warn js/console "[update-scheduler] update loop throttled; in-flight events:" + (into-array (map ptk/repr-event (ptk/in-flight-events st/state)))))) + (catch :default _ + nil))) + (defn- download-report! [report event] (dom/prevent-default event) diff --git a/frontend/src/app/main/ui/workspace/viewport/hooks.cljs b/frontend/src/app/main/ui/workspace/viewport/hooks.cljs index 6b91ba1984..ae8397383e 100644 --- a/frontend/src/app/main/ui/workspace/viewport/hooks.cljs +++ b/frontend/src/app/main/ui/workspace/viewport/hooks.cljs @@ -402,7 +402,7 @@ (defn inside-vbox [vbox objects frame-id] (let [frame (get objects frame-id)] - (and (some? frame) (gsh/overlaps? frame vbox)))) + (and (some? frame) (some? vbox) (gsh/overlaps? frame vbox)))) (defn setup-active-frames [objects hover-ids selected active-frames zoom transform vbox] diff --git a/frontend/test/frontend_tests/main_errors_test.cljs b/frontend/test/frontend_tests/main_errors_test.cljs index a964620c15..c622647f84 100644 --- a/frontend/test/frontend_tests/main_errors_test.cljs +++ b/frontend/test/frontend_tests/main_errors_test.cljs @@ -11,6 +11,10 @@ - stale-asset-error? – pure predicate - exception->error-data – pure transformer - on-error re-entrancy guard – prevents recursive invocations + - events in flight – the full report lists the events the + store was processing when it caught the exception; a failing stream + pipeline lists the emitters of the value, not its own event + - on-update-loop – never throws into the scheduler's caller - flash schedules async report and toast – neither the report nor ntf/show is emitted synchronously - organization SSO recovery – expired SSO sessions go back to the provider @@ -368,6 +372,144 @@ ;; The guard must have allowed only the first invocation through. (t/is (= 1 @reentrant-call-count)))) +;; --------------------------------------------------------------------------- +;; Events in flight +;; +;; on-error records the events the store is processing when it catches an +;; exception; the full report lists them, outermost first. +;; --------------------------------------------------------------------------- + +(def ^:private in-flight-cause (atom nil)) + +(defmethod ptk/handle-error ::test-in-flight + [err] + (reset! in-flight-cause (::errors/instance err)) + nil) + +(def ^:private in-flight-heading + "Events in flight when the error was caught (outermost first):") + +(defn- in-flight-failure + [] + (ex-info "in-flight failure" {:type ::test-in-flight :hint "in-flight failure"})) + +(defn- recursive-event + [n] + (ptk/reify ::test-in-flight-recursive + ptk/WatchEvent + (watch [_ _ _] + (if (pos? n) + (rx/of (recursive-event (dec n))) + (throw (in-flight-failure)))))) + +(t/deftest ^:async report-lists-the-events-in-flight-of-a-failing-event + (let [store (ptk/store {:state {} :on-error errors/on-error})] + (try + (await + (mock/with-mocks* + {st/state store + st/format-last-events (mock/stub (fn [& _] "(stub last events)")) + rt/get-current-href (constantly "https://penpot.example.com/#/workspace")} + (reset! in-flight-cause nil) + (st/emit! + (ptk/reify ::test-in-flight-outer + ptk/WatchEvent + (watch [_ _ _] + (rx/of (ptk/reify ::test-in-flight-inner + ptk/UpdateEvent + (update [_ _] (throw (in-flight-failure)))))))) + (await (async/wait-for #(some? @in-flight-cause) "the failure reaches the handler")) + (let [report (errors/generate-report @in-flight-cause) + outer (.indexOf report "typ:(:frontend-tests.main-errors-test/test-in-flight-outer)") + inner (.indexOf report "typ:(:frontend-tests.main-errors-test/test-in-flight-inner)")] + (t/is (str/includes? report in-flight-heading)) + (t/is (< -1 outer inner) "outer event listed before the failing one")))) + (finally + (rx/dispose! store))))) + +(t/deftest ^:async report-keeps-both-ends-of-a-long-in-flight-list + (let [store (ptk/store {:state {} :on-error errors/on-error})] + (try + (await + (mock/with-mocks* + {st/state store + st/format-last-events (mock/stub (fn [& _] "(stub last events)")) + rt/get-current-href (constantly "https://penpot.example.com/#/workspace")} + (reset! in-flight-cause nil) + ;; 25 nested events: 10 from each end are kept + (st/emit! (recursive-event 24)) + (await (async/wait-for #(some? @in-flight-cause) "the failure reaches the handler")) + (let [report (errors/generate-report @in-flight-cause)] + (t/is (str/includes? report "... 5 more ...")) + (t/is (= 20 (count (re-seq #"test-in-flight-recursive" report))))))) + (finally + (rx/dispose! store))))) + +(defn- in-flight-section + "The in-flight section of `report`, or nil when absent." + [report] + (let [start (.indexOf report in-flight-heading)] + (when (<= 0 start) + (subs report start (.indexOf report "Last events:" start))))) + +(t/deftest ^:async stream-pipeline-failure-lists-the-emitters-of-the-value + (let [store (ptk/store {:state {} :on-error errors/on-error})] + (try + (await + (mock/with-mocks* + {st/state store + st/format-last-events (mock/stub (fn [& _] "(stub last events)")) + rt/get-current-href (constantly "https://penpot.example.com/#/workspace")} + (reset! in-flight-cause nil) + ;; The listener's pipeline fails on the trigger that the emitter emits + (st/emit! + (ptk/reify ::test-in-flight-listener + ptk/WatchEvent + (watch [_ _ stream] + (->> stream + (rx/filter (ptk/type? ::test-in-flight-trigger)) + (rx/take 1) + (rx/map (fn [_] (throw (in-flight-failure))))))) + (ptk/reify ::test-in-flight-emitter + ptk/WatchEvent + (watch [_ _ _] + (rx/of (ptk/data-event ::test-in-flight-trigger {}))))) + (await (async/wait-for #(some? @in-flight-cause) "the failure reaches the handler")) + (let [section (in-flight-section (errors/generate-report @in-flight-cause))] + (t/is (str/includes? section "test-in-flight-emitter")) + (t/is (not (str/includes? section "test-in-flight-trigger"))) + (t/is (not (str/includes? section "test-in-flight-listener")))))) + (finally + (rx/dispose! store))))) + +(t/deftest ^:async delayed-watch-failure-has-no-in-flight-section + (let [store (ptk/store {:state {} :on-error errors/on-error})] + (try + (await + (mock/with-mocks* + {st/state store + st/format-last-events (mock/stub (fn [& _] "(stub last events)")) + rt/get-current-href (constantly "https://penpot.example.com/#/workspace")} + (reset! in-flight-cause nil) + (st/emit! + (ptk/reify ::test-in-flight-delayed + ptk/WatchEvent + (watch [_ _ _] + (->> (rx/timer 0) + (rx/map (fn [_] (throw (in-flight-failure)))))))) + (await (async/wait-for #(some? @in-flight-cause) "the failure reaches the handler")) + (let [report (errors/generate-report @in-flight-cause)] + (t/is (not (str/includes? report in-flight-heading))) + (t/is (str/includes? report "Last events:"))))) + (finally + (rx/dispose! store))))) + +(t/deftest ^:async update-loop-handler-never-throws + (await + (mock/with-mocks* + {ptk/in-flight-events (fn [_] (throw (js/Error. "in-flight read failure")))} + (t/is (nil? (errors/on-update-loop {:rounds 26})))))) + ;; --------------------------------------------------------------------------- ;; Expired organization SSO session ;;