From 15606a3f85b6ad82ff7a753e5b4d7dfe7b3a2242 Mon Sep 17 00:00:00 2001 From: Andrey Antukh Date: Sat, 17 Oct 2026 13:46:22 +0000 Subject: [PATCH] :bug: 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 | 2 +- .serena/memories/backend/subtleties.md | 3 +- backend/src/app/http.clj | 3 +- backend/src/app/http/middleware.clj | 106 ++++++++++++++---- backend/src/app/main.clj | 6 + .../backend_tests/http_middleware_test.clj | 52 +++++++-- 6 files changed, 139 insertions(+), 33 deletions(-) diff --git a/.serena/memories/audit-log.md b/.serena/memories/audit-log.md index 3739612214..898e95e413 100644 --- a/.serena/memories/audit-log.md +++ b/.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) diff --git a/.serena/memories/backend/subtleties.md b/.serena/memories/backend/subtleties.md index 996b2c19d2..7e6c6ba54b 100644 --- a/.serena/memories/backend/subtleties.md +++ b/.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 ` ` 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 diff --git a/backend/src/app/http.clj b/backend/src/app/http.clj index 30efa426e4..aa6950fdeb 100644 --- a/backend/src/app/http.clj +++ b/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]]} diff --git a/backend/src/app/http/middleware.clj b/backend/src/app/http/middleware.clj index 45f8abecca..ad80bfe9c4 100644 --- a/backend/src/app/http/middleware.clj +++ b/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 diff --git a/backend/src/app/main.clj b/backend/src/app/main.clj index 9fc93eb26e..43039cdee4 100644 --- a/backend/src/app/main.clj +++ b/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) diff --git a/backend/test/backend_tests/http_middleware_test.clj b/backend/test/backend_tests/http_middleware_test.clj index 1651d92e0a..c572e20c09 100644 --- a/backend/test/backend_tests/http_middleware_test.clj +++ b/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"}