From 0ef35fc52ae149e56c4a8a193e04e4c950c7385a Mon Sep 17 00:00:00 2001 From: Andrey Antukh Date: Wed, 30 Sep 2026 07:17:02 +0200 Subject: [PATCH] :bug: Harden browser logging against invalid levels (#11693) * :bug: Stop browser logging from crashing on empty levels Stop level->int crashes from taking down the dashboard when a nil or unknown level reaches the browser logger. Invalid levels now warn and are ignored in enabled?, setup! and the console handler, which renders unknown records with a neutral fallback. Alias the schema-legal :fatal level to :error in the browser mappings and validate the JS-exported debug.set_logging, which previously threw on missing arguments and wrote unreachable keyword keys into the loggers map. Closes #11690 AI-assisted-by: muse-spark-1.3-contributor * :bug: Guard logger args and strengthen logging tests Close the residual throw paths next to the empty-level crash: guard non-string loggers in enabled? and setup!, coerce set_logging arguments safely, and validate logger keys. Strengthen the regression tests so the fatal alias cannot regress silently: enabled-logger filtering, JVM fatal and bogus cases, setup! skip proof, and invalid-logger cases. Related to #11690 AI-assisted-by: muse-spark-1.3-contributor * :bug: Address low findings from logging review Validate the logger before the level in console-log-handler, share a public valid-logger? predicate with debug/set-logging, and keep warn formatting consistent across boundaries. Document the fail-soft-FE/strict-BE split on enabled? and the valid-level? contract on set-level!. Cover safe fallbacks, bad logger keys, handler logger skips, and loggers-map isolation in common tests, and add a frontend test for debug/set-logging. Related to #11690 AI-assisted-by: muse-spark-1.3-contributor --- common/src/app/common/logging.cljc | 132 +++++++++++++----- common/test/common_tests/logging_test.cljc | 101 ++++++++++++++ common/test/common_tests/runner.cljc | 2 + frontend/src/debug.cljs | 18 ++- .../frontend_tests/debug_logging_test.cljs | 28 ++++ frontend/test/frontend_tests/runner.cljs | 2 + 6 files changed, 249 insertions(+), 34 deletions(-) create mode 100644 common/test/common_tests/logging_test.cljc create mode 100644 frontend/test/frontend_tests/debug_logging_test.cljs diff --git a/common/src/app/common/logging.cljc b/common/src/app/common/logging.cljc index 42e4f84566..70dbab6855 100644 --- a/common/src/app/common/logging.cljc +++ b/common/src/app/common/logging.cljc @@ -104,8 +104,26 @@ 100) (recur (get-parent-logger logger')))))))))) +(def valid-levels + "The set of log levels accepted on every runtime." + #{:trace :debug :info :warn :error :fatal}) + +(defn valid-level? + "True when `level` is accepted on every runtime." + [level] + (contains? valid-levels level)) + +(defn valid-logger? + "True when `logger` is a usable logger name." + [logger] + (and (string? logger) (not (str/blank? logger)))) + (defn enabled? - "Check if logger has enabled logging for given level." + "Check if logger has enabled logging for given level. + + On CLJS, invalid loggers and levels warn and return false so logging + can never crash the app; on CLJ, invalid levels still throw + IllegalArgumentException." [logger level] #?(:clj (let [logger (LoggerFactory/getLogger ^String logger)] @@ -118,13 +136,26 @@ :fatal (and (.isErrorEnabled ^Logger logger) logger) (throw (IllegalArgumentException. (str "invalid level:" level))))) :cljs - (>= (level->int level) - (get-logger-level logger)))) + (cond + (not (valid-logger? logger)) + (do + (js/console.warn "ignoring invalid logger:" (pr-str logger)) + false) + + (not (valid-level? level)) + (do + (js/console.warn "ignoring invalid log level:" (pr-str level) "logger:" (pr-str logger)) + false) + + :else + (>= (level->int level) + (get-logger-level logger))))) (defn- level->color [level] (case level :error "#c82829" + :fatal "#c82829" :warn "#f5871f" :info "#4271ae" :debug "#969896" @@ -140,6 +171,7 @@ :info "INF" :warn "WRN" :error "ERR" + :fatal "ERR" (let [hint (str "invalid level provided to `level->name` function: " (pr-str level))] (throw (ex-info hint {:level level}))))) @@ -151,9 +183,26 @@ :info 30 :warn 40 :error 50 + :fatal 50 (let [hint (str "invalid level provided to `level->int` function: " (pr-str level))] (throw (ex-info hint {:level level}))))) +#?(:cljs + (defn level->color-safe + "Like `level->color` but falls back to a neutral gray instead of throwing." + [level] + (if (valid-level? level) + (level->color level) + "#969896"))) + +#?(:cljs + (defn level->name-safe + "Like `level->name` but falls back to \"UNK\" instead of throwing." + [level] + (if (valid-level? level) + (level->name level) + "UNK"))) + (defn build-message [props] (loop [props (seq props) @@ -284,43 +333,55 @@ (defn console-log-handler {:no-doc true} [_ _ _ {:keys [::logger ::props ::level ::cause ::trace ::message]}] - (when (enabled? logger level) - (let [hstyles (str/ffmt "font-weight: 600; color: %" (level->color level)) - mstyles (str/ffmt "font-weight: 300; color: %" (level->color level)) - ts (ct/format-inst (ct/now) "kk:mm:ss.SSSS") - header (str/concat "%c" (level->name level) " " ts " [" logger "] ") - message (str/concat header "%c" @message)] + ;; Invalid levels render with a fallback style instead of being + ;; dropped, so a corrupt record stays visible; the warn below keeps + ;; it noticeable. The normal `log!` path never reaches here because + ;; `enabled?` already drops such records before `emit-log`. + (if-not (valid-logger? logger) + (js/console.warn "ignoring log record with invalid logger:" (pr-str logger)) + (when (or (not (valid-level? level)) + (enabled? logger level)) + (when-not (valid-level? level) + (js/console.warn "invalid level on log record, using fallback rendering:" (pr-str level) "logger:" (pr-str logger))) + (let [hstyles (str/ffmt "font-weight: 600; color: %" (level->color-safe level)) + mstyles (str/ffmt "font-weight: 300; color: %" (level->color-safe level)) + ts (ct/format-inst (ct/now) "kk:mm:ss.SSSS") + header (str/concat "%c" (level->name-safe level) " " ts " [" logger "] ") + message (str/concat header "%c" @message)] - (js/console.group message hstyles mstyles) - (doseq [[type n v] (get-special-props props)] - (case type - :js (js/console.log n v) - :error (if (ex/error? v) - (js/console.error n (pr-str v)) - (js/console.error n v)))) + (js/console.group message hstyles mstyles) + (doseq [[type n v] (get-special-props props)] + (case type + :js (js/console.log n v) + :error (if (ex/error? v) + (js/console.error n (pr-str v)) + (js/console.error n v)))) - (when (ex/exception? cause) - (let [data (ex-data cause) - explain (or (:explain data) - (ex/explain data))] - (when explain - (js/console.log "Explain:") - (js/console.log explain)) + (when (ex/exception? cause) + (let [data (ex-data cause) + explain (or (:explain data) + (ex/explain data))] + (when explain + (js/console.log "Explain:") + (js/console.log explain)) - (when (and data (not explain)) - (js/console.log "Data:") - (js/console.log (pp/pprint-str data))) + (when (and data (not explain)) + (js/console.log "Data:") + (js/console.log (pp/pprint-str data))) - (js/console.log @trace #_(.-stack cause)))) + (js/console.log @trace #_(.-stack cause)))) - (js/console.groupEnd message))))) + (js/console.groupEnd message)))))) #?(:clj (add-watch log-record ::default slf4j-log-handler) :cljs (add-watch log-record ::default console-log-handler)) (defmacro set-level! "A CLJS-only macro for set logging level to current (that matches the - current namespace) or user specified logger." + current namespace) or user specified logger. + + Callers passing a dynamic level must check `valid-level?` first; + `level->int` throws on anything outside `valid-levels`." ([level] (when (:ns &env) `(.set ^js/Map loggers ~(str *ns*) (level->int ~level)))) @@ -332,9 +393,16 @@ (defn setup! [{:as config}] (run! (fn [[logger level]] - (let [logger (if (keyword? logger) (name logger) logger) - level (level->int level)] - (.set ^js/Map loggers logger level))) + (let [logger (if (keyword? logger) (name logger) logger)] + (cond + (not (valid-logger? logger)) + (js/console.warn "ignoring invalid logger in setup!:" (pr-str logger)) + + (not (valid-level? level)) + (js/console.warn "ignoring invalid log level in setup!:" (pr-str level) "logger:" (pr-str logger)) + + :else + (.set ^js/Map loggers logger (level->int level))))) config))) (defmacro raw! diff --git a/common/test/common_tests/logging_test.cljc b/common/test/common_tests/logging_test.cljc new file mode 100644 index 0000000000..80cdd0be57 --- /dev/null +++ b/common/test/common_tests/logging_test.cljc @@ -0,0 +1,101 @@ +;; This Source Code Form is subject to the terms of the Mozilla Public +;; License, v. 2.0. If a copy of the MPL was not distributed with this +;; file, You can obtain one at http://mozilla.org/MPL/2.0/. +;; +;; Copyright (c) KALEIDOS INC Sucursal en España SL + +(ns common-tests.logging-test + (:require + [app.common.logging :as l] + [clojure.test :as t])) + +(defn- throws? + [thunk] + #?(:clj (try (thunk) false (catch clojure.lang.ExceptionInfo _ true)) + :cljs (try (thunk) false (catch :default _ true)))) + +(t/deftest level->int-test + (t/is (= 10 (l/level->int :trace))) + (t/is (= 20 (l/level->int :debug))) + (t/is (= 30 (l/level->int :info))) + (t/is (= 40 (l/level->int :warn))) + (t/is (= 50 (l/level->int :error))) + (t/is (= 50 (l/level->int :fatal))) + (t/is (throws? #(l/level->int nil))) + (t/is (throws? #(l/level->int :bogus)))) + +#?(:cljs + (t/use-fixtures + :each + (fn [f] + (f) + (doseq [k ["logging-test-probe-xyz" + "logging-test-fatal-xyz" + "logging-test-setup-xyz" + "logging-test-bad-xyz" + "logging-test-key-xyz"]] + (.delete l/loggers k))))) + +#?(:cljs + (t/deftest browser-boundaries-test + (t/testing "unknown levels never throw and disable logging" + (t/is (false? (l/enabled? "logging-test-probe-xyz" nil))) + (t/is (false? (l/enabled? "logging-test-probe-xyz" :bogus)))) + (t/testing "invalid loggers never throw and disable logging" + (t/is (false? (l/enabled? nil :error))) + (t/is (false? (l/enabled? "" :error))) + (t/is (false? (l/enabled? 123 :error)))) + (t/testing "unknown logger defaults to disabled" + (t/is (false? (l/enabled? "logging-test-probe-xyz" :fatal))) + (t/is (false? (l/enabled? "logging-test-probe-xyz" :error)))) + (t/testing "fatal filters exactly like error when enabled" + (l/setup! {"logging-test-fatal-xyz" :debug}) + (t/is (true? (l/enabled? "logging-test-fatal-xyz" :fatal))) + (t/is (= (l/enabled? "logging-test-fatal-xyz" :fatal) + (l/enabled? "logging-test-fatal-xyz" :error))) + (l/setup! {"logging-test-fatal-xyz" :error}) + (t/is (true? (l/enabled? "logging-test-fatal-xyz" :fatal))) + (t/is (false? (l/enabled? "logging-test-fatal-xyz" :debug))) + (t/is (false? (l/enabled? "logging-test-fatal-xyz" :trace)))) + (t/testing "setup! skips invalid entries and installs valid ones" + (t/is (do (l/setup! {"logging-test-setup-xyz" :error + "logging-test-bad-xyz" nil}) + true)) + (t/is (true? (l/enabled? "logging-test-setup-xyz" :error))) + (t/is (false? (l/enabled? "logging-test-setup-xyz" :bogus))) + (t/is (false? (l/enabled? "logging-test-bad-xyz" :error)))) + (t/testing "setup! skips invalid logger keys and installs valid ones" + (t/is (do (l/setup! {"logging-test-key-xyz" :error + "" :error + nil :error}) + true)) + (t/is (true? (l/enabled? "logging-test-key-xyz" :error)))) + (t/testing "safe fallbacks never throw" + (t/is (= "#969896" (l/level->color-safe nil))) + (t/is (= "UNK" (l/level->name-safe nil))) + (t/is (= "#c82829" (l/level->color-safe :fatal))) + (t/is (= "ERR" (l/level->name-safe :fatal)))) + (t/testing "console handler survives a nil-level record" + (t/is (nil? (l/console-log-handler + nil nil nil + {::l/logger "logging-test-probe-xyz" + ::l/level nil + ::l/message (delay "hi") + ::l/props {}})))) + (t/testing "console handler skips invalid-logger records" + (t/is (nil? (l/console-log-handler + nil nil nil + {::l/logger nil + ::l/level nil + ::l/message (delay "hi") + ::l/props {}})))))) + +#?(:clj + (t/deftest backend-strict-test + (t/testing "fatal does not throw" + (t/is (do (l/enabled? "app" :fatal) true))) + (t/testing "JVM branch still rejects invalid levels loudly" + (t/is (try (l/enabled? "app" nil) false + (catch IllegalArgumentException _ true))) + (t/is (try (l/enabled? "app" :bogus) false + (catch IllegalArgumentException _ true)))))) diff --git a/common/test/common_tests/runner.cljc b/common/test/common_tests/runner.cljc index 68e47e824e..73e4e48f9c 100644 --- a/common/test/common_tests/runner.cljc +++ b/common/test/common_tests/runner.cljc @@ -47,6 +47,7 @@ [common-tests.geom-shapes-tree-seq-test] [common-tests.geom-snap-test] [common-tests.geom-test] + [common-tests.logging-test] [common-tests.logic.chained-propagation-test] [common-tests.logic.comp-creation-test] [common-tests.logic.comp-detach-with-nested-test] @@ -128,6 +129,7 @@ 'common-tests.geom-shapes-tree-seq-test 'common-tests.geom-snap-test 'common-tests.geom-test + 'common-tests.logging-test 'common-tests.logic.chained-propagation-test 'common-tests.logic.comp-creation-test 'common-tests.logic.comp-detach-with-nested-test diff --git a/frontend/src/debug.cljs b/frontend/src/debug.cljs index f9ddc8d9d7..7d71812c19 100644 --- a/frontend/src/debug.cljs +++ b/frontend/src/debug.cljs @@ -50,11 +50,25 @@ (l/set-level! :debug) +(defn- coerce-keyword + "Coerce `v` to a keyword when it is a string or keyword, nil otherwise." + [v] + (when (or (keyword? v) (string? v)) + (keyword v))) + (defn ^:export set-logging ([level] - (l/set-level! :app (keyword level))) + (let [level (coerce-keyword level)] + (if (l/valid-level? level) + (l/set-level! "app" level) + (js/console.warn "ignoring invalid log level:" (pr-str level))))) ([ns level] - (l/set-level! (keyword ns) (keyword level)))) + (let [ns (coerce-keyword ns) + level (coerce-keyword level)] + (if (and (l/valid-logger? (some-> ns name)) + (l/valid-level? level)) + (l/set-level! (name ns) level) + (js/console.warn "ignoring invalid logging config:" (pr-str ns) (pr-str level)))))) ;; These events are excluded when we activate the :events flag (def debug-exclude-events diff --git a/frontend/test/frontend_tests/debug_logging_test.cljs b/frontend/test/frontend_tests/debug_logging_test.cljs new file mode 100644 index 0000000000..4f07956bbb --- /dev/null +++ b/frontend/test/frontend_tests/debug_logging_test.cljs @@ -0,0 +1,28 @@ +;; This Source Code Form is subject to the terms of the Mozilla Public +;; License, v. 2.0. If a copy of the MPL was not distributed with this +;; file, You can obtain one at http://mozilla.org/MPL/2.0/. +;; +;; Copyright (c) KALEIDOS INC Sucursal en España SL + +(ns frontend-tests.debug-logging-test + (:require + [app.common.logging :as l] + [cljs.test :as t :include-macros true] + [debug :as dbg])) + +(t/deftest set-logging-test + (t/testing "invalid inputs warn and do not throw" + (t/is (nil? (dbg/set-logging nil))) + (t/is (nil? (dbg/set-logging "bogus"))) + (t/is (nil? (dbg/set-logging 123))) + (t/is (nil? (dbg/set-logging nil nil))) + (t/is (nil? (dbg/set-logging "app" "bogus"))) + (t/is (nil? (dbg/set-logging "app" nil))) + (t/is (nil? (dbg/set-logging "" "debug")))) + (t/testing "valid inputs install a string logger key" + (dbg/set-logging "app" "debug") + (t/is (true? (l/enabled? "app" :debug))) + (dbg/set-logging "app" "error") + (t/is (true? (l/enabled? "app" :error))) + (t/is (false? (l/enabled? "app" :debug))) + (.delete l/loggers "app"))) diff --git a/frontend/test/frontend_tests/runner.cljs b/frontend/test/frontend_tests/runner.cljs index dfc62d5f1a..b3764d977b 100644 --- a/frontend/test/frontend_tests/runner.cljs +++ b/frontend/test/frontend_tests/runner.cljs @@ -35,6 +35,7 @@ [frontend-tests.data.workspace-texts-test] [frontend-tests.data.workspace-thumbnails-test] [frontend-tests.data.workspace-versions-test] + [frontend-tests.debug-logging-test] [frontend-tests.errors-governor-test] [frontend-tests.errors-test] [frontend-tests.fonts-test] @@ -169,6 +170,7 @@ 'frontend-tests.data.workspace-texts-test 'frontend-tests.data.workspace-thumbnails-test 'frontend-tests.data.workspace-versions-test + 'frontend-tests.debug-logging-test 'frontend-tests.errors-governor-test 'frontend-tests.errors-test 'frontend-tests.fonts-test