✨ Count update-file validation refusals by error code

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 <alvorithm@teje.ro>

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"

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)))))))
 

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" [] [])))))