From fff50b3ef84478f6fdcf3383ecb8ae9cf33cfc26 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=81lvaro=20Tejero=20Cantero?= Date: Wed, 28 Oct 2026 08:46:39 +0100 Subject: [PATCH] :sparkles: Count update-file validation refusals by error code MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Record three counters on the update-file path, and add the ids that operators need to the lines the soft validations write: - penpot_rpc_update_file_refused_total, labelled by the furthest validation step the save reached and by the error code; - penpot_rpc_update_file_soft_failure_total, labelled by the soft check that failed and a bounded reason: the deepest schema key of the explain path, or the code of the first reported referential error; - penpot_rpc_update_file_lagged_total, for saves whose incoming revn is behind the stored one and that the server folds on top of changes the client has not received. The soft-failure lines now carry the file id, the incoming and stored revn, the error code, and the failing path (ids only). Metrics stay no-ops when the cfg carries no metrics instance. Closes #12665 AI-assisted-by: claude-opus-5-5, deepseek-v4.1-flash Signed-off-by: Álvaro Tejero Cantero --- backend/src/app/main.clj | 17 ++ backend/src/app/rpc/commands/files_update.clj | 130 ++++++++-- .../files_update_refusal_test.clj | 227 ++++++++++++++++++ 3 files changed, 359 insertions(+), 15 deletions(-) create mode 100644 backend/test/backend_tests/files_update_refusal_test.clj diff --git a/backend/src/app/main.clj b/backend/src/app/main.clj index 2f119a769f..a532d825f2 100644 --- a/backend/src/app/main.clj +++ b/backend/src/app/main.clj @@ -77,6 +77,23 @@ ::mdef/buckets mtx/default-request-histogram-buckets ::mdef/type :histogram} + :update-file-refused + {::mdef/name "penpot_rpc_update_file_refused_total" + ::mdef/help "Saves that raised out of update-file, by the furthest validation step reached and the error code." + ::mdef/labels ["stage" "code"] + ::mdef/type :counter} + + :update-file-soft-failure + {::mdef/name "penpot_rpc_update_file_soft_failure_total" + ::mdef/help "Soft file validation failures, by the check that failed and a bounded reason." + ::mdef/labels ["check" "reason"] + ::mdef/type :counter} + + :update-file-lagged + {::mdef/name "penpot_rpc_update_file_lagged_total" + ::mdef/help "Saves that passed the revision check with a revn behind the stored head." + ::mdef/type :counter} + :rpc-main-timing {::mdef/name "penpot_rpc_main_timing" ::mdef/help "RPC command method call timing for main" diff --git a/backend/src/app/rpc/commands/files_update.clj b/backend/src/app/rpc/commands/files_update.clj index 85a0a58b1f..4fd4d94815 100644 --- a/backend/src/app/rpc/commands/files_update.clj +++ b/backend/src/app/rpc/commands/files_update.clj @@ -124,6 +124,46 @@ (contains? token-change-types type) (contains? file-change-types type))) +;; --- METRICS + +(defn- record-metric! + "Record a metric on the cfg's metrics instance. A cfg without one + records nothing, so callers outside the service (scripts, tests) + work unchanged." + [cfg params] + (when-let [metrics (::mtx/metrics cfg)] + (when (mtx/metrics? metrics) + (mtx/run! metrics params)))) + +(defn- refusal-code + "Bounded label for the error that refused a save: the `:code` of its + ex-data, the `:type` when it carries no code, or `unknown`. + + Both are keywords written in this codebase, so the label set stays + bounded by the source." + [cause] + (let [data (ex-data cause) + code (or (:code data) (:type data))] + (if (keyword? code) (name code) "unknown"))) + +(defn- refusal-stage + "Bounded label for the stage a refused save had reached, read from the + step timings that `process-changes-and-validate` records in `finally` + forms: a step's timing is present whether it completed or raised, so + the furthest step present is the one that raised, or the last one + before the failing step. + + `changes` covers the whole change-application step, the version and + change schema checks included. The hard referential gate is the last + step before the write whenever `:file-schema-validation` is off, so a + write failure reports `referential`." + [timings] + (cond + (nil? (:process-changes-ms timings)) "pre-changes" + (nil? (:validate-affected-ms timings)) "changes" + (nil? (:validate-schema-ms timings)) "referential" + :else "schema")) + ;; If features are specified from params and the final feature ;; set is different than the persisted one, update it on the ;; database. @@ -142,7 +182,7 @@ ::doc/module :files ::doc/added "1.17" ::db/transaction true} - [{:keys [::mtx/metrics ::db/conn] :as cfg} + [{:keys [::db/conn] :as cfg} {:keys [::rpc/profile-id id changes changes-with-metadata] :as params}] (files/check-edition-permissions! conn profile-id id) @@ -169,7 +209,9 @@ (assoc :changes changes)) cfg (assoc cfg ::timestamp (ct/now) - ::validation-timings (atom {})) + ::validation-timings (atom {}) + ::incoming-revn (:revn params) + ::stored-revn (:revn file)) tpoint (ct/tpoint)] @@ -189,6 +231,13 @@ :context {:incoming-revn (:revn params) :stored-revn (:revn file)})) + ;; The save passed the revision check with a revn behind the stored + ;; head: the server accepts it and folds it on top of changes its + ;; client had not received. + (when (< (::incoming-revn cfg) + (::stored-revn cfg)) + (record-metric! cfg {:id :update-file-lagged :inc 1})) + ;; When newly computed features does not match exactly with the ;; features defined on team row, we update it (when-let [features (-> features @@ -205,7 +254,7 @@ {::db/return-keys false}))) - (mtx/run! metrics {:id :update-file-changes :inc (count changes)}) + (record-metric! cfg {:id :update-file-changes :inc (count changes)}) (binding [l/*context* (some-> (meta params) (get :app.http/request) @@ -231,6 +280,10 @@ ;; (`handle-response`), so timings collected before a hard ;; validation failure would be lost without this inline log. (let [timings @(::validation-timings cfg)] + (record-metric! cfg {:id :update-file-refused + :labels [(refusal-stage timings) + (refusal-code cause)] + :inc 1}) (l/dbg :hint "update-file" :file-id (str (:id file)) :project-id (str (:project-id file)) @@ -409,30 +462,77 @@ (apply update-fn cfg file args))) +(defn- deepest-explain-error + "The entry of a malli explain whose `:path` is the longest, or nil." + [cause] + (->> (-> cause ex-data ::sm/explain :errors) + (filter #(seq (:path %))) + (sort-by #(count (:path %))) + last)) + +(defn- schema-failure-reason + "Bounded label for a soft schema failure: the deepest keyword of the + `:path` of the deepest explain entry, which is the schema key that + failed (`type` for a shape whose type is invalid, `objects` for a nil + object map). Indices and other non-keyword path elements are skipped + so the label set stays small." + [error] + (let [key (->> (:path error) (filter keyword?) last)] + (if (keyword? key) (name key) "unknown"))) + +(defn- referential-failure-code + "The code of the first error `validate-file-affected!` reported, kept + within its closed `error-codes` set, or `:unknown`." + [cause] + (let [code (-> cause ex-data :details first :code)] + (if (contains? val/error-codes code) code :unknown))) + (defn- soft-validate-file-schema! - [file] + [cfg file] (try (val/validate-file-schema! file) (catch Throwable cause - (l/error :hint "file schema validation error" :cause cause)))) + (let [error (deepest-explain-error cause)] + (record-metric! cfg {:id :update-file-soft-failure + :labels ["schema" (schema-failure-reason error)] + :inc 1}) + (l/error :hint "file schema validation error" + :file-id (str (:id file)) + :incoming-revn (::incoming-revn cfg) + :stored-revn (::stored-revn cfg) + :code (refusal-code cause) + ;; Schema path and instance path of the deepest explain + ;; entry: keywords, ids, and indices only. + :path (some-> error :path vec) + :in (some-> error :in vec) + :cause cause))))) (defn- record-validation-timing [cfg step-key step-label elapsed-ms] - (when-let [metrics (::mtx/metrics cfg)] - (when (mtx/metrics? metrics) - (mtx/run! metrics {:id :update-file-validation-timing - :labels [step-label] - :val (double elapsed-ms)}))) + (record-metric! cfg {:id :update-file-validation-timing + :labels [step-label] + :val (double elapsed-ms)}) (when-let [timings (::validation-timings cfg)] (swap! timings assoc step-key elapsed-ms))) (defn- soft-validate-file! - [file libs changes] + [cfg file libs changes] (try (val/validate-file-affected! file libs changes) (catch Throwable cause - (l/error :hint "file validation error" - :cause cause)))) + (let [code (referential-failure-code cause) + error (-> cause ex-data :details first)] + (record-metric! cfg {:id :update-file-soft-failure + :labels ["affected" (name code)] + :inc 1}) + (l/error :hint "file validation error" + :file-id (str (:id file)) + :incoming-revn (::incoming-revn cfg) + :stored-revn (::stored-revn cfg) + :code (name code) + :page-id (some-> error :page-id str) + :shape-id (some-> error :shape-id str) + :cause cause))))) (defn- process-changes-and-validate [cfg file changes skip-validate] @@ -484,14 +584,14 @@ (when (contains? cf/flags :soft-file-validation) (let [t (ct/tpoint)] (try - (soft-validate-file! file libs changes) + (soft-validate-file! cfg file libs changes) (finally (record-validation-timing cfg :soft-validate-affected-ms "soft-validate-affected" (inst-ms (t))))))) (when (contains? cf/flags :soft-file-schema-validation) (let [t (ct/tpoint)] (try - (soft-validate-file-schema! file) + (soft-validate-file-schema! cfg file) (finally (record-validation-timing cfg :soft-validate-schema-ms "soft-validate-schema" (inst-ms (t))))))) diff --git a/backend/test/backend_tests/files_update_refusal_test.clj b/backend/test/backend_tests/files_update_refusal_test.clj new file mode 100644 index 0000000000..dbccf697a4 --- /dev/null +++ b/backend/test/backend_tests/files_update_refusal_test.clj @@ -0,0 +1,227 @@ +;; 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 SUBSIDIARY SL + +(ns backend-tests.files-update-refusal-test + "Counters that update-file records for refused saves, soft validation + failures, and lagged saves, and the bounded labels they carry." + (:require + [app.binfile.common :as bfc] + [app.common.features :as cfeat] + [app.common.types.shape :as cts] + [app.common.uuid :as uuid] + [app.config :as cf] + [app.main :as main] + [app.metrics :as mtx] + [app.metrics.definition :as-alias mdef] + [app.rpc :as-alias rpc] + [app.rpc.commands.files-update :as files-update] + [backend-tests.helpers :as th] + [clojure.test :as t] + [integrant.core :as ig]) + (:import + io.prometheus.client.CollectorRegistry)) + +(t/use-fixtures :once th/state-init) +(t/use-fixtures :each th/database-reset) + +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +;; Helpers +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; + +(defn- metrics + [] + (ig/init-key :app.metrics/metrics {:default main/default-metrics})) + +(defn- counter + "Value of a counter series, or 0 when the series does not exist yet." + [metrics name label-names label-values] + (or (.getSampleValue ^CollectorRegistry (mtx/get-registry metrics) + ^String name + (into-array String label-names) + (into-array String label-values)) + 0.0)) + +(defn- validation-cfg + [metrics] + {::mtx/metrics metrics + ::files-update/validation-timings (atom {}) + ::files-update/incoming-revn 0 + ::files-update/stored-revn 0}) + +(defn- broken-schema-file + "A file whose only defect is a shape with an invalid `:type`." + [] + (let [page-id (uuid/next) + shape (-> (cts/setup-shape {:id (uuid/next) + :type :rect + :name "rect" + :x 0 :y 0 :width 10 :height 10 + :parent-id uuid/zero + :frame-id uuid/zero}) + (assoc :type :not-a-shape))] + {:id (uuid/next) + :revn 0 + :version 0 + :data {:pages [page-id] + :pages-index {page-id {:id page-id + :name "Page 1" + :objects {(:id shape) shape}}}}})) + +(defn- broken-referential-file + "A file whose root lists a child that does not exist." + [] + (let [page-id (uuid/next) + root (-> (cts/setup-shape {:id uuid/zero + :type :frame + :name "Root" + :x 0 :y 0 :width 100 :height 100 + :parent-id uuid/zero + :frame-id uuid/zero}) + (update :shapes (fnil conj []) (uuid/next)))] + {:id (uuid/next) + :revn 0 + :version 0 + :features #{"components/v2"} + :data {:pages [page-id] + :pages-index {page-id {:id page-id + :name "Page 1" + :objects {uuid/zero root}}}}})) + +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +;; Tests +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; + +(t/deftest refusal-metrics-are-declared-with-the-labels-they-receive + ;; A counter whose declared labels differ from the ones the recorder + ;; passes fails inside `run!`, which swallows the error: every sample + ;; would be dropped silently. + (t/is (= ["stage" "code"] + (get-in main/default-metrics [:update-file-refused ::mdef/labels]))) + (t/is (= :counter + (get-in main/default-metrics [:update-file-refused ::mdef/type]))) + + (t/is (= ["check" "reason"] + (get-in main/default-metrics [:update-file-soft-failure ::mdef/labels]))) + (t/is (= :counter + (get-in main/default-metrics [:update-file-soft-failure ::mdef/type]))) + + (t/is (nil? (get-in main/default-metrics [:update-file-lagged ::mdef/labels]))) + (t/is (= :counter + (get-in main/default-metrics [:update-file-lagged ::mdef/type])))) + +(t/deftest soft-schema-failure-is-counted-with-the-failing-schema-key + (let [metrics (metrics) + cfg (validation-cfg metrics) + before (counter metrics "penpot_rpc_update_file_soft_failure_total" + ["check" "reason"] ["schema" "type"])] + (binding [cf/flags #{:soft-file-schema-validation}] + (@#'files-update/process-changes-and-validate + cfg (broken-schema-file) [] nil)) + + (t/is (= (inc before) + (counter metrics "penpot_rpc_update_file_soft_failure_total" + ["check" "reason"] ["schema" "type"]))))) + +(t/deftest soft-referential-failure-is-counted-with-the-reported-code + (let [metrics (metrics) + cfg (validation-cfg metrics) + file (broken-referential-file) + page-id (first (:pages (:data file))) + before (counter metrics "penpot_rpc_update_file_soft_failure_total" + ["check" "reason"] ["affected" "child-not-found"])] + (binding [cf/flags #{:soft-file-validation}] + (with-redefs [bfc/get-resolved-file-libraries (fn [_ _] {})] + (@#'files-update/process-changes-and-validate + cfg file + [{:type :mod-obj :page-id page-id :id uuid/zero :operations []}] + nil))) + + (t/is (= (inc before) + (counter metrics "penpot_rpc_update_file_soft_failure_total" + ["check" "reason"] ["affected" "child-not-found"]))))) + +(t/deftest referential-refusal-reports-the-gate-stage-and-code + (let [cfg (validation-cfg (metrics)) + file (broken-referential-file) + page-id (first (:pages (:data file))) + changes [{:type :mod-obj :page-id page-id :id uuid/zero :operations []}] + cause (binding [cf/flags #{:file-validation}] + (with-redefs [bfc/get-resolved-file-libraries (fn [_ _] {})] + (try + (@#'files-update/process-changes-and-validate cfg file changes nil) + nil + (catch Throwable cause + cause))))] + (t/is (some? cause)) + (t/is (= "referential" + (@#'files-update/refusal-stage + @(::files-update/validation-timings cfg)))) + (t/is (= "referential-integrity" + (@#'files-update/refusal-code cause))))) + +(t/deftest soft-failure-records-nothing-without-a-metrics-instance + ;; `mtx/run!` fails on a missing instance, so an unguarded recording + ;; would turn a soft check into a refusal for callers without metrics. + (let [cfg {::files-update/validation-timings (atom {}) + ::files-update/incoming-revn 0 + ::files-update/stored-revn 0}] + (binding [cf/flags #{:soft-file-schema-validation}] + (t/is (map? (@#'files-update/process-changes-and-validate + cfg (broken-schema-file) [] nil)))))) + +(t/deftest refused-update-file-is-counted-with-stage-and-code + (let [profile (th/create-profile* 1 {:is-active true}) + file (th/create-file* 1 {:profile-id (:id profile) + :project-id (:default-project-id profile)}) + page-id (first (:pages (:data file))) + metrics (:app.metrics/metrics th/*system*) + before (counter metrics "penpot_rpc_update_file_refused_total" + ["stage" "code"] ["changes" "data-validation"]) + ;; The operation passes the params schema (`:val` is untyped) and + ;; leaves the shape invalid, so the fold itself refuses it. + out (th/command! {::th/type :update-file + ::rpc/profile-id (:id profile) + :id (:id file) + :session-id (uuid/next) + :revn 0 + :vern 0 + :features (cfeat/get-enabled-features cf/flags) + :changes [{:type :mod-obj + :page-id page-id + :id uuid/zero + :operations [{:type :set + :attr :type + :val :not-a-shape}]}]})] + (t/is (some? (:error out))) + (t/is (= (inc before) + (counter metrics "penpot_rpc_update_file_refused_total" + ["stage" "code"] ["changes" "data-validation"]))))) + +(t/deftest lagged-save-is-counted + (let [profile (th/create-profile* 1 {:is-active true}) + file (th/create-file* 1 {:profile-id (:id profile) + :project-id (:default-project-id profile)}) + page-id (first (:pages (:data file))) + changes [{:type :mod-obj :page-id page-id :id uuid/zero :operations []}] + metrics (:app.metrics/metrics th/*system*) + before (counter metrics "penpot_rpc_update_file_lagged_total" [] [])] + + ;; The first save moves the stored revn to 1; it arrives at the head. + (th/update-file! :profile-id (:id profile) + :file-id (:id file) + :revn 0 + :changes changes) + (t/is (= before + (counter metrics "penpot_rpc_update_file_lagged_total" [] []))) + + ;; The second one keeps the stale revn and the server accepts it, + ;; applying it on top of the change its client has not received. + (th/update-file! :profile-id (:id profile) + :file-id (:id file) + :revn 0 + :changes changes) + (t/is (= (inc before) + (counter metrics "penpot_rpc_update_file_lagged_total" [] [])))))