🐛 Answer 400 on a request body the parser cannot read

A body declared as JSON that clojure.data.json cannot read ended as a 500
:unexpected with the whole stack trace in the log: wrap-parse-request
classified the failure by exception class, and the library signals its
syntax errors with a bare java.lang.Exception.

Classify it where it happens instead: read-body-params reads the body and
raises :validation :malformed-json (400) for anything it cannot parse,
keeps RequestTooBigException at 413 and re-raises a structured error from
deeper untouched. The body is read outside the handler try, so the error
goes out as a throw like the other specific-exception branches.

The failure is now one log line (path, peer address, content-type, parser
message) without the stack trace, and it is counted: the middleware takes
the metrics instance as a middleware argument, so the backend exports
penpot_http_malformed_requests_total and nexus declares its own
nexus_http_malformed_requests_total.

Tests: parse-request-malformed-json-body reproduces the production body
and asserts the 400 and the counter; the existing parse-request tests now
pass a metrics stub.

AI-assisted-by: deepseek-v4.1-flash

.serena/memories/audit-log.md

@@ -269,7 +269,7 @@ Nexus dispatches on `:type`: `"telemetry-events"` batches are coerced and insert
 
 - **Anonymization happens in Penpot, before sending.** By the time events leave, times are day-truncated, IPs are already `0.0.0.0`, props/context are filtered (see above), and emails are gone (only derived `email-domain` survives). Nexus additionally forces the outcome: it prefixes any non-`telemetry:` source, sets `received-at = tracked-at` (already truncated), pins IP to `0.0.0.0`, and stamps the sending `instance-id` into every event context.
 - **No personal data is expected.** Profile ids are random UUIDs with no PII, so the telemetry consumer needs no login guard; grouping is by `instance`, not by person (see posthog-telemetry below).
-- **The endpoint always answers 200.** Failures are swallowed and only counted (`nexus_telemetry_errors_total`), so a bad batch never breaks the sending instance; successes are counted (`nexus_telemetry_events_total`, `nexus_telemetry_reports_total`). Old instances may send a fressian+zstd base64 blob instead of a plain vector; Nexus decodes both (50 MiB cap against decompression bombs).
+- **The endpoint always answers 200.** Failures are swallowed and only counted (`nexus_telemetry_errors_total`), so a bad batch never breaks the sending instance; successes are counted (`nexus_telemetry_events_total`, `nexus_telemetry_reports_total`). A body the parser cannot read never reaches the handler: it answers 400 and counts in `nexus_http_malformed_requests_total`. Old instances may send a fressian+zstd base64 blob instead of a plain vector; Nexus decodes both (50 MiB cap against decompression bombs).
 
 ## 12. Archive to Nexus (today) and to Nitrate (future)
 

.serena/memories/backend/subtleties.md

@@ -42,7 +42,7 @@
 - `app.config/config` and `flags` are dynamic `defonce` vars populated from `PENPOT_*` env vars through the shared schema string transformer. Tests and tooling can bind them.
 - `parse-flags` automatically adds `:disable-secure-session-cookies` when `public-uri` is plain HTTP and not localhost. This changes cookie defaults without an explicit env flag.
 - The backend sets Clojure `*assert*` globally from the `:backend-asserts` feature flag. Assertion-dependent checks can therefore differ by runtime flags.
-- Request body parsing is mostly POST-oriented and supports Transit JSON plus plain JSON. Plain JSON request keys are kebab-decoded before being merged into `:params`.
+- Request body parsing is mostly POST-oriented and supports Transit JSON plus plain JSON. Plain JSON request keys are kebab-decoded before being merged into `:params`. A body the parser cannot read is a client error, classified at the parse site and never by exception class (`clojure.data.json` signals its syntax errors with a bare `java.lang.Exception`): 400 `:validation`/`:malformed-json`, one `warn` line (`malformed request body`) carrying path, peer address and content-type instead of a stack trace, and `penpot_http_malformed_requests_total`. `RequestTooBigException` keeps its 413.
 - Response formatting negotiates with `Accept` or `_fmt=json`. Transit is the default for collection/boolean bodies; JSON encoding has special pointer-map handling.
 - Auth prefers the session cookie token before the `Authorization` header. Headers may be `Token` or `Bearer`. Only `kid=1`/`ver=1` tokens are decoded as session tokens; anything else is left unauthenticated (legacy v1 tokens were removed).
 - Shared-key auth requires `x-shared-key` as `<key-id> <key>` and stores the lowercased key id on the request. If no shared keys are configured it always rejects.
@@ -60,6 +60,7 @@
 ## Metrics recording
 
 - `app.metrics/run!` is safe by default: a recording failure never throws (a metrics bug must not change the behavior of the measured operation). The first failure per metric id logs at `warn`, later ones at `debug`. The `instance` precondition is a plain assert (the backend enables `:backend-asserts`), and the collector lookup sits outside the recording guard, so a missing instance fails hard even when asserts are disabled. `::mtx/metrics` is required by the storage, s3-backend, and db-pool schemas; `app.db` wires the prometheus `MetricsTrackerFactory` unconditionally. Storage-specific metric contracts: `mem:backend/storage`.
+- `penpot_http_malformed_requests_total` (counter, no labels) counts requests whose body the parser could not read. `app.http.middleware/wrap-parse-request` emits it where it classifies the error, so the instance travels as a middleware argument (`[mw/parse-request (::mtx/metrics cfg)]`) and each service declares the definition with its own prefix (nexus: `nexus_http_malformed_requests_total`). The per-endpoint request counters of nexus do not count these requests: they sit inside the parse middleware, so the failure happens before them.
 
 ## Log-derived metrics
 

backend/src/app/http.clj

@@ -244,6 +244,7 @@
    [::mgmt/routes schema:routes]
    ::session/manager
    ::setup/props
+   ::mtx/metrics
    ::db/pool])
 
 (defmethod ig/assert-key ::router
@@ -260,7 +261,7 @@
                       [mw/auth {:bearer (partial session/decode-token cfg)
                                 :cookie (partial session/decode-token cfg)
                                 :token  (partial actoken/decode-token cfg)}]
-                      [mw/parse-request]
+                      [mw/parse-request (::mtx/metrics cfg)]
                       [mw/errors errors/handle]
                       [mw/restrict-methods]]}
 

backend/src/app/http/middleware.clj

@@ -14,7 +14,9 @@
    [app.config :as cf]
    [app.http :as-alias http]
    [app.http.errors :as errors]
+   [app.metrics :as mtx]
    [app.tokens :as tokens]
+   [app.util.inet :as inet]
    [app.util.pointer-map :as pmap]
    [cuerdas.core :as str]
    [yetti.adapter :as yt]
@@ -44,27 +46,81 @@
     (java.io.BufferedReader.
      (java.io.InputStreamReader. body))))
 
+(def ^:private not-a-body
+  "Marker returned by `read-body-params` when the `content-type` header names
+  neither transit nor json; the request is left untouched.
+
+  A fresh object and not a keyword: a keyword is a legal value for a decoded
+  body, so identity is the only safe comparison."
+  (Object.))
+
+(defn- raise-malformed-body
+  "Signals a body that the parser could not read.
+
+  A failure while reading the body means the body does not match what the
+  client declared, so it is a client error: the exception class says nothing
+  here, because `clojure.data.json` signals its syntax errors with a bare
+  `java.lang.Exception`."
+  [request metrics content-type cause]
+  ;; A single line, without the stack trace: the trace of a parse failure
+  ;; hides the fields (path, peer address, content-type) that identify the
+  ;; client sending the broken body.
+  (l/wrn :hint "malformed request body"
+         :path (yreq/path request)
+         :remote-addr (inet/parse-request request)
+         :content-type content-type
+         :error (ex/get-hint cause))
+
+  (mtx/run! metrics
+            :id :http-malformed-requests-total
+            :inc 1)
+
+  (ex/raise :type :validation
+            :code :malformed-json
+            :hint "invalid JSON in request body"
+            :cause cause))
+
+(defn- read-body-params
+  "Reads the request body according to the `content-type` header.
+
+  `RequestTooBigException` keeps its own code (413) and a structured error
+  raised from deeper (an `ex-info`) travels untouched; anything else is a
+  malformed body."
+  [request metrics content-type]
+  (try
+    (cond
+      (str/starts-with? content-type "application/transit+json")
+      (with-open [^InputStream is (yreq/body request)]
+        (t/read! (t/reader is)))
+
+      (str/starts-with? content-type "application/json")
+      (with-open [reader (get-reader request)]
+        (json/read reader :key-fn json/read-kebab-key))
+
+      :else
+      not-a-body)
+
+    (catch RequestTooBigException cause
+      (ex/raise :type :validation
+                :code :request-body-too-large
+                :hint "request body exceeds size limit"
+                :cause cause))
+
+    (catch Throwable cause
+      (if (ex/error? cause)
+        (throw cause)
+        (raise-malformed-body request metrics content-type cause)))))
+
 (defn wrap-parse-request
-  [handler]
+  [handler metrics]
   (letfn [(process-request [request]
-            (let [header (yreq/get-header request "content-type")]
-              (cond
-                (str/starts-with? header "application/transit+json")
-                (with-open [^InputStream is (yreq/body request)]
-                  (let [params (t/read! (t/reader is))]
-                    (-> request
-                        (assoc :body-params params)
-                        (update :params merge params))))
-
-                (str/starts-with? header "application/json")
-                (with-open [reader (get-reader request)]
-                  (let [params (json/read reader :key-fn json/read-kebab-key)]
-                    (-> request
-                        (assoc :body-params params)
-                        (update :params merge params))))
-
-                :else
-                request)))
+            (let [header (yreq/get-header request "content-type")
+                  params (read-body-params request metrics header)]
+              (if (identical? params not-a-body)
+                request
+                (-> request
+                    (assoc :body-params params)
+                    (update :params merge params)))))
 
           ;; The specific-exception branches below (IAE,
           ;; RequestTooBigException, EOFException) raise with
@@ -107,10 +163,14 @@
 
     (fn [request]
       (if (= (yreq/method request) :post)
-        (try
-          (-> request process-request handler)
-          (catch Throwable cause
-            (handle-error cause request)))
+        ;; The body is read outside the `try`: a failure there is always
+        ;; raised already classified by `read-body-params`, and goes out as a
+        ;; throw like the rest of the specific-exception branches above.
+        (let [request (process-request request)]
+          (try
+            (handler request)
+            (catch Throwable cause
+              (handle-error cause request))))
         (handler request)))))
 
 (def parse-request

backend/src/app/main.clj

@@ -226,6 +226,11 @@
    :http-connector-errors-total
    {::mdef/name "penpot_http_connector_errors_total"
     ::mdef/help "Total number of handler errors in the http listener."
+    ::mdef/type :counter}
+
+   :http-malformed-requests-total
+   {::mdef/name "penpot_http_malformed_requests_total"
+    ::mdef/help "Total number of requests whose body the parser could not read."
     ::mdef/type :counter}})
 
 (def system-config
@@ -360,6 +365,7 @@
     ::rpc/routes         (ig/ref ::rpc/routes)
     ::setup/props        (ig/ref ::setup/props)
     ::mtx/routes         (ig/ref ::mtx/routes)
+    ::mtx/metrics        (ig/ref ::mtx/metrics)
     ::oidc/routes        (ig/ref ::oidc/routes)
     ::mgmt/routes        (ig/ref ::mgmt/routes)
     ::http.debug/routes  (ig/ref ::http.debug/routes)

backend/test/backend_tests/http_middleware_test.clj

@@ -16,7 +16,8 @@
    [app.http.errors :as http-errors]
    [app.http.middleware :as mw]
    [app.http.session :as session]
-   [app.main :as-alias main]
+   [app.main :as main]
+   [app.metrics :as mtx]
    [app.rpc :as-alias rpc]
    [app.rpc.commands.access-token]
    [app.tokens :as tokens]
@@ -28,6 +29,7 @@
    [yetti.request :as yreq]
    [yetti.response :as yres])
   (:import
+   io.prometheus.client.CollectorRegistry
    io.undertow.server.RequestTooBigException))
 
 (t/use-fixtures :once th/state-init)
@@ -515,7 +517,8 @@
   ;; handler in app.http/router-handler), this test asserts on
   ;; the ex-info thrown by wrap-parse-request directly.
   (let [handler (#'app.http.middleware/wrap-parse-request
-                 (fn [_] {::yres/status 200 ::yres/body :ok}))
+                 (fn [_] {::yres/status 200 ::yres/body :ok})
+                 (th/metrics-stub))
         ;; Body contains the bytes for: {"x": "\}"}  -- a string
         ;; value with a backslash followed by '}', which
         ;; clojure.data.json v0.5.x cannot handle.
@@ -532,13 +535,44 @@
     (t/is (= :malformed-json (-> ex ex-data :code)))
     (t/is (= "invalid JSON in request body" (-> ex ex-data :hint)))))
 
+(defn- malformed-requests-count
+  "Value of the malformed-body counter of a metrics instance."
+  [metrics]
+  (.getSampleValue ^CollectorRegistry (mtx/get-registry metrics)
+                   "penpot_http_malformed_requests_total"
+                   (make-array String 0)
+                   (make-array String 0)))
+
+(t/deftest parse-request-malformed-json-body
+  ;; The body shape seen in production: an object where the parser expects a
+  ;; key. clojure.data.json signals it with a bare java.lang.Exception, which
+  ;; the class-based classification did not recognize, so it surfaced as a 500
+  ;; :unexpected with the whole stack trace in the log. It is a client error:
+  ;; 400 :malformed-json, and it is counted.
+  (let [metrics (ig/init-key :app.metrics/metrics {:default main/default-metrics})
+        handler (#'app.http.middleware/wrap-parse-request
+                 (fn [_] {::yres/status 200 ::yres/body :ok})
+                 metrics)
+        request (th/make-dummy-request
+                 {:method  :post
+                  :headers {"content-type" "application/json"}
+                  :body-bytes (.getBytes "{\"events\":[{{\"a\":1}:\"b\"}]}" "UTF-8")})
+        ex      (try
+                  (handler request)
+                  (catch clojure.lang.ExceptionInfo e e))]
+    (t/is (instance? clojure.lang.ExceptionInfo ex))
+    (t/is (= :validation (-> ex ex-data :type)))
+    (t/is (= :malformed-json (-> ex ex-data :code)))
+    (t/is (= 1.0 (malformed-requests-count metrics)))))
+
 (t/deftest parse-request-request-too-big-exception
   ;; When RequestTooBigException is raised (e.g. the request body
   ;; exceeded the configured size limit), the middleware should
   ;; convert it to a 413 :request-body-too-large validation
   ;; error.
   (let [handler (#'app.http.middleware/wrap-parse-request
-                 (fn [_] (throw (RequestTooBigException. "too large"))))
+                 (fn [_] (throw (RequestTooBigException. "too large")))
+                 (th/metrics-stub))
         request (th/make-dummy-request
                  {:method  :post
                   :headers {"content-type" "application/json"}
@@ -556,7 +590,8 @@
   ;; was closed before the parser could read it), the middleware
   ;; should convert it to a 400 :malformed-json validation error.
   (let [handler (#'app.http.middleware/wrap-parse-request
-                 (fn [_] (throw (java.io.EOFException. "stream closed"))))
+                 (fn [_] (throw (java.io.EOFException. "stream closed")))
+                 (th/metrics-stub))
         request (th/make-dummy-request
                  {:method  :post
                   :headers {"content-type" "application/json"}
@@ -579,7 +614,8 @@
         wrapped (doto (RuntimeException. "wrapped")
                   (.initCause iae))
         handler (#'app.http.middleware/wrap-parse-request
-                 (fn [_] (throw wrapped)))
+                 (fn [_] (throw wrapped))
+                 (th/metrics-stub))
         request (th/make-dummy-request
                  {:method  :post
                   :headers {"content-type" "application/json"}
@@ -597,7 +633,8 @@
   ;; path and return a 500 with :type :server-error :code
   ;; :unexpected. This is the "true internal error" path.
   (let [handler  (#'app.http.middleware/wrap-parse-request
-                  (fn [_] (throw (RuntimeException. "boom"))))
+                  (fn [_] (throw (RuntimeException. "boom")))
+                  (th/metrics-stub))
         request  (th/make-dummy-request
                   {:method  :post
                    :headers {"content-type" "application/json"}
@@ -617,7 +654,8 @@
   ;; has a dedicated handle-exception method that returns 500
   ;; with :code :io-exception.
   (let [handler  (#'app.http.middleware/wrap-parse-request
-                  (fn [_] (throw (java.io.IOException. "network gone"))))
+                  (fn [_] (throw (java.io.IOException. "network gone")))
+                  (th/metrics-stub))
         request  (th/make-dummy-request
                   {:method  :post
                    :headers {"content-type" "application/json"}