From dc0ea3a69c9ce7f1b51d1d246cf95a89507db732 Mon Sep 17 00:00:00 2001 From: Andrey Antukh Date: Tue, 29 Sep 2026 09:47:07 +0200 Subject: [PATCH] :bug: Attribute audit events to the caller, not the response (#11952) * :bug: Attribute audit events to the caller, not the response prepare-rpc-event took the event profile-id from the result map whenever it carried one, before falling back to the caller. Any command returning a response with a :profile-id key silently credited the action to somebody else. get-error-report returns the report with its decoded content merged in, and that content holds the profile that owned the report, so privileged reads were logged against the users whose crashes were being inspected. verify-token on a team invitation returns the inviter's profile-id, so accepting an invitation was logged against the inviter. Resolution is now ::audit/profile-id metadata, then ::rpc/profile-id, then the zero uuid; the response is never consulted. The two verify-token branches that relied on it now declare the profile in the result metadata. Every other command either already declared it or returns no :profile-id; all 30 registered command namespaces were checked. The tests that pinned the old behavior are replaced by ones covering the new contract. AI-assisted-by: space-bunny-free * :bug: Coerce the audit profile-id override to a uuid The only sanctioned way for a command to override the profile of an audit event is the ::audit/profile-id metadata, and the value is set by hand in a dozen commands, some of them reading it from token claims or other sources we do not type. schema:event requires a uuid and submit* swallows the validation error, so a string did not fail loudly: the row was dropped silently. Values that cannot become a uuid are now discarded with a warning and the event falls back to the caller, which is always a valid uuid. A uuid, the common case, exits on the first check. AI-assisted-by: space-bunny-free --- .serena/memories/backend/audit-log.md | 2 + backend/src/app/loggers/audit.clj | 38 +++++- backend/src/app/rpc/commands/verify_token.clj | 46 ++++--- backend/test/backend_tests/rpc_audit_test.clj | 113 ++++++++++++------ .../rpc_commands_error_reports_test.clj | 60 ++++++---- .../test/backend_tests/rpc_profile_test.clj | 53 ++++++++ 6 files changed, 226 insertions(+), 86 deletions(-) diff --git a/.serena/memories/backend/audit-log.md b/.serena/memories/backend/audit-log.md index fe401cef0c..825d9a2162 100644 --- a/.serena/memories/backend/audit-log.md +++ b/.serena/memories/backend/audit-log.md @@ -16,6 +16,8 @@ Penpot records what users do as events in the Postgres `audit_log` table. There - Most backend events need no manual code: `wrap-audit` in `app.rpc` runs after every RPC handler when `:webhooks`, `:audit-log` or `:telemetry` is on (unless the command sets `::audit/skip`) and builds the event via `prepare-rpc-event`. The event name defaults to the command name (prefixed with `-` outside `main`), props default to the request params, and timestamps come from the server request time. - Commands customize through result metadata (`rph/with-meta`): `::audit/replace-props` swaps the props wholesale (auth commands use `profile->props` so a register event carries the profile, not the password), `::audit/props` merges extras, `::audit/context`/`profile-id`/`name`/`type` override the defaults. `clean-props` always strips nils, qualified keys and `:session-id/:password/:old-password/:token/:client-secret` as a last line of defense. +- INVARIANT: the event's `profile-id` is the caller, resolved as `::audit/profile-id` metadata -> `::rpc/profile-id` -> `uuid/zero`. It is NEVER taken from the response. Results carry `:profile-id` keys that belong to someone else (`get-error-report` returns the report with its content merged, so the profile that owned the report; `verify-token` on a team invitation returns the inviter), and honoring them misattributes the action. Commands with `::rpc/auth false` (`login-*`, `register-profile`, `create-demo-profile`, `verify-token`, `prepare-register-profile`) have no caller to fall back on, so they MUST set `::audit/profile-id` in the result metadata or the event lands on `uuid/zero`. +- The `::audit/profile-id` override goes through `coerce-profile-id`: a string is parsed, anything that cannot become a uuid is discarded (with a warning) and the event falls back to the caller. Do not pass the value straight through: `schema:event` requires `::sm/uuid` and `submit*` swallows the validation error, so a non-uuid override silently loses the row instead of failing loudly. Hand-built events built with `event-from-rpc-params` + `submit` (clone-template, accept-team-invitation, `management/nitrate` push-audit-events) do NOT go through that coercion: they must supply a uuid. - `submit` is the normal entry point (fills defaults, validates `schema:event`, runs inside `tx-run!`, logs failures without failing the RPC). `insert` is the low-level one for CLI/helpers and the webhook subsystem: direct write, no webhook/telemetry fan-out, silent unless `:audit-log` is on. Boot emits `trigger/instance-start` from `setup/props` so every restart is visible in the log. ## Consumers I: webhooks (`app.loggers.webhooks`) diff --git a/backend/src/app/loggers/audit.clj b/backend/src/app/loggers/audit.clj index 28d14c3daa..01f2ae3a94 100644 --- a/backend/src/app/loggers/audit.clj +++ b/backend/src/app/loggers/audit.clj @@ -350,14 +350,44 @@ {})] (assoc params :context context))) +(defn- coerce-profile-id + "Normalize a hand-written `::audit/profile-id` override to a uuid. + + `schema:event` requires a uuid and `submit*` swallows the validation + error, so a value that is not a uuid loses the event instead of + failing loudly. Commands read the override from places that are not + typed by us (token claims, stringly-typed drivers), so a string has + to be accepted. Anything that cannot become a uuid is discarded, and + the event falls back to the caller, which is always a valid uuid." + [v] + (let [coerced (cond + ;; Fast path: the override comes straight from a `profile` + ;; row in almost every command, so it is already a uuid. + (uuid? v) + v + + (string? v) + (uuid/parse* v) + + :else + nil)] + (when (and (nil? coerced) (some? v)) + (l/error :hint "ignoring unusable ::audit/profile-id" + :profile-id v)) + + coerced)) + (defn prepare-rpc-event [cfg mdata params result] (let [resultm (meta result) request (-> params meta ::http/request) - profile-id (or (::profile-id resultm) - (some-> (:profile-id result) - (cond-> (string? (:profile-id result)) - uuid/parse*)) + ;; SECURITY: the event belongs to whoever made the request. The only + ;; sanctioned override is the `::audit/profile-id` metadata, set + ;; explicitly by the command. Never derive it from the response: + ;; results can carry a `:profile-id` that belongs to somebody else + ;; (the owner of an error report, the inviter of an invitation, ...) + ;; and that silently misattributes the action. + profile-id (or (coerce-profile-id (::profile-id resultm)) (::rpc/profile-id params) uuid/zero) diff --git a/backend/src/app/rpc/commands/verify_token.clj b/backend/src/app/rpc/commands/verify_token.clj index d46c7a8057..3c893dc6b2 100644 --- a/backend/src/app/rpc/commands/verify_token.clj +++ b/backend/src/app/rpc/commands/verify_token.clj @@ -97,7 +97,11 @@ (profile/strip-private-attrs) (update :props profile/filter-props) (with-nitrate-licence cfg))] - (assoc claims :profile profile))) + ;; The command is anonymous, so the audit event has no caller to fall + ;; back on and the profile must be declared here. The claims also carry + ;; a `:profile-id`, but the audit layer ignores the response on purpose. + (-> (assoc claims :profile profile) + (rph/with-meta {::audit/profile-id (:id profile)})))) ;; --- Team Invitation @@ -313,25 +317,29 @@ :user-who-send-invitation (:created-by invitation)) (audit/clean-props)))))) - (cond-> (assoc claims :state :created) - ;; when the invitation is to an organization, instead of a team, add the - ;; accepted-team-id as :organization-team-id - (:organization-id claims) - (assoc :organization-team-id accepted-team-id) + (-> (cond-> (assoc claims :state :created) + ;; when the invitation is to an organization, instead of a team, add the + ;; accepted-team-id as :organization-team-id + (:organization-id claims) + (assoc :organization-team-id accepted-team-id) - organization-id-on-add - (assoc :organization-invitation-audit - {:origin organization-event-origin - :props - (-> props - (assoc :organization-id organization-id-on-add - :organization-member-add-source organization-add-source - :belongs-to-team-on-add (boolean team-id) - :user-id (:id profile) - :user-who-send-invitation (:created-by invitation) - :organization-member-count-before - organization-member-count-before) - (audit/clean-props))})))))) + organization-id-on-add + (assoc :organization-invitation-audit + {:origin organization-event-origin + :props + (-> props + (assoc :organization-id organization-id-on-add + :organization-member-add-source organization-add-source + :belongs-to-team-on-add (boolean team-id) + :user-id (:id profile) + :user-who-send-invitation (:created-by invitation) + :organization-member-count-before + organization-member-count-before) + (audit/clean-props))})) + ;; The response carries the inviter's profile-id, so the + ;; audit event has to name the accepting profile explicitly + ;; or the invitation gets logged against the wrong user. + (rph/with-meta {::audit/profile-id (:id profile)})))))) (do ;; If the user is not logged-in and the invitation has been canceled diff --git a/backend/test/backend_tests/rpc_audit_test.clj b/backend/test/backend_tests/rpc_audit_test.clj index 6148df5831..2fd3a43c62 100644 --- a/backend/test/backend_tests/rpc_audit_test.clj +++ b/backend/test/backend_tests/rpc_audit_test.clj @@ -515,46 +515,83 @@ (t/is (= {} (:props row))) (t/is (= {} (:context row)))))) -;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; -;; PREPARE-RPC-EVENT PROFILE-ID CONVERSION -;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +;; PREPARE-RPC-EVENT PROFILE-ID RESOLUTION +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; -(t/deftest prepare-rpc-event-converts-string-profile-id-to-uuid - ;; When result contains a string :profile-id (e.g. from error reports), - ;; prepare-rpc-event must convert it to a UUID for audit schema compliance. - (let [prof (th/create-profile* 1 {:is-active true}) - string-pid "33601240-a00b-11ea-ba1b-c554cc60e361" - expected #uuid "33601240-a00b-11ea-ba1b-c554cc60e361" - mdata {::sv/name "test-cmd"} - params {::rpc/profile-id (:id prof) - ::rpc/request-id (uuid/next) - ::rpc/request-at (ct/now)} - mock-req (reify - yetti.request/IRequest - (get-header [_ _] nil) - (remote-addr [_] "127.0.0.1")) - params (with-meta params {:app.http/request mock-req}) - result {:profile-id string-pid :some-data "value"} - event (audit/prepare-rpc-event th/*system* mdata params result)] - ;; profile-id must be a UUID, not a string - (t/is (uuid? (:profile-id event))) - (t/is (= expected (:profile-id event))))) - -(t/deftest prepare-rpc-event-handles-invalid-string-profile-id - ;; When result contains an invalid string :profile-id, it should fall back - ;; to the RPC params profile-id (which is always a valid UUID). - (let [prof (th/create-profile* 1 {:is-active true}) - mdata {::sv/name "test-cmd"} - params {::rpc/profile-id (:id prof) - ::rpc/request-id (uuid/next) - ::rpc/request-at (ct/now)} +(defn- prepare-event + "Call prepare-rpc-event with a bare request, returning the built event." + [caller result] + (let [mdata {::sv/name "test-cmd"} + params {::rpc/profile-id caller + ::rpc/request-id (uuid/next) + ::rpc/request-at (ct/now)} mock-req (reify yetti.request/IRequest (get-header [_ _] nil) (remote-addr [_] "127.0.0.1")) - params (with-meta params {:app.http/request mock-req}) - result {:profile-id "not-a-valid-uuid"} - event (audit/prepare-rpc-event th/*system* mdata params result)] - ;; profile-id must fall back to the RPC params profile-id - (t/is (uuid? (:profile-id event))) - (t/is (= (:id prof) (:profile-id event))))) + params (with-meta params {:app.http/request mock-req})] + (audit/prepare-rpc-event th/*system* mdata params result))) + +(t/deftest prepare-rpc-event-ignores-profile-id-from-result + ;; An audit event belongs to the caller, never to whatever `:profile-id` + ;; the response carries. `get-error-report` returns the report with its + ;; decoded content merged in, and that content can hold the profile that + ;; owned the report, so honoring it attributed the call to somebody who + ;; never made it. + (let [caller (th/create-profile* 1 {:is-active true})] + (t/is (= (:id caller) + (:profile-id (prepare-event (:id caller) + {:profile-id "33601240-a00b-11ea-ba1b-c554cc60e361" + :some-data "value"})))) + ;; an unparseable one must not break the event either + (t/is (= (:id caller) + (:profile-id (prepare-event (:id caller) + {:profile-id "not-a-valid-uuid"})))))) + +(t/deftest prepare-rpc-event-uses-metadata-profile-id + ;; `::audit/profile-id` metadata is the only sanctioned override: it is + ;; how commands that authenticate somebody else (login, verify-token) + ;; attribute the event to the right profile. + (let [caller (th/create-profile* 1 {:is-active true}) + target (th/create-profile* 2 {:is-active true}) + result (with-meta {:some-data "value"} + {::audit/profile-id (:id target)})] + (t/is (= (:id target) + (:profile-id (prepare-event (:id caller) result)))))) + +(t/deftest prepare-rpc-event-falls-back-to-zero-for-anonymous-callers + ;; With no metadata and no authenticated caller there is nobody to + ;; attribute the event to, so it lands on the zero uuid. + (t/is (= uuid/zero + (:profile-id (prepare-event nil {:some-data "value"}))))) + +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +;; PREPARE-RPC-EVENT PROFILE-ID COERCION +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; + +(t/deftest prepare-rpc-event-coerces-string-metadata-profile-id + ;; `::audit/profile-id` is set by hand in a dozen commands, and some of + ;; them read the value from token claims or other stringly-typed sources. + ;; The audit schema demands a uuid, and `submit*` swallows the validation + ;; error, so an unconverted string would drop the event on the floor. + (let [caller (th/create-profile* 1 {:is-active true}) + target "33601240-a00b-11ea-ba1b-c554cc60e361" + result (with-meta {:some-data "value"} + {::audit/profile-id target})] + (t/is (= #uuid "33601240-a00b-11ea-ba1b-c554cc60e361" + (:profile-id (prepare-event (:id caller) result)))) + (t/is (uuid? (:profile-id (prepare-event (:id caller) result)))))) + +(t/deftest prepare-rpc-event-discards-unusable-metadata-profile-id + ;; An override that cannot be turned into a uuid is dropped, not honoured + ;; and not propagated: the event falls back to the caller, which is always + ;; a valid uuid, instead of failing the schema check and losing the row. + (let [caller (th/create-profile* 1 {:is-active true})] + (doseq [bad ["not-a-valid-uuid" "" " " 42 {} [] :whatever nil false]] + (let [result (with-meta {:some-data "value"} + (cond-> {::audit/profile-id bad} + (nil? bad) (dissoc ::audit/profile-id)))] + (t/is (= (:id caller) + (:profile-id (prepare-event (:id caller) result))) + (str "override " (pr-str bad) " must fall back to the caller")))))) diff --git a/backend/test/backend_tests/rpc_commands_error_reports_test.clj b/backend/test/backend_tests/rpc_commands_error_reports_test.clj index c317fe0cbd..6a40db62b7 100644 --- a/backend/test/backend_tests/rpc_commands_error_reports_test.clj +++ b/backend/test/backend_tests/rpc_commands_error_reports_test.clj @@ -256,31 +256,41 @@ ;; --- Audit event tests -(t/deftest get-error-report-audit-event-has-uuid-profile-id - ;; When get-error-report returns a report with string profile-id in content, - ;; the audit event must have a proper UUID profile-id (not a string). - ;; This tests the prepare-rpc-event function directly since the test RPC - ;; flow doesn't include the audit middleware wrapper. - (let [profile (th/create-profile* 1 {:is-active true}) - id (uuid/next) - orig-pid "33601240-a00b-11ea-ba1b-c554cc60e361" - ;; Simulate the result from get-error-report with string profile-id - result {:id id - :source "logging" - :hint "test error" - :profile-id orig-pid} - mdata {::sv/name "get-error-report"} - params {::rpc/profile-id (:id profile) - ::rpc/request-id (uuid/next) - ::rpc/request-at (ct/now)} - mock-req (reify yetti.request/IRequest - (get-header [_ _] nil) - (remote-addr [_] "127.0.0.1")) - params (with-meta params {:app.http/request mock-req}) - event (audit/prepare-rpc-event th/*system* mdata params result)] - ;; profile-id must be a UUID, not a string - (t/is (uuid? (:profile-id event))) - (t/is (= #uuid "33601240-a00b-11ea-ba1b-c554cc60e361" (:profile-id event))))) +(t/deftest get-error-report-audit-event-attributes-the-caller + ;; The report content carries the profile that owned the report and the + ;; handler merges that content into the response, so the response holds a + ;; `:profile-id` that does not belong to the caller. The audit event must + ;; still belong to the caller: deriving it from the response attributed + ;; privileged reads to the users whose crashes were being inspected. + (let [caller (th/create-profile* 1 {:is-active true}) + owner "33601240-a00b-11ea-ba1b-c554cc60e361" + id (uuid/next)] + (insert-report! th/*system* + {:id id + :source 4 + :content {:profile-id owner + :hint "test error"}}) + + (let [out (token-cmd caller {::th/type :get-error-report :id id})] + (t/is (th/success? out)) + + (let [result (:result out) + event (audit/prepare-rpc-event + th/*system* + {::sv/name "get-error-report"} + (with-meta {::rpc/profile-id (:id caller) + ::rpc/request-id (uuid/next) + ::rpc/request-at (ct/now) + :id id} + {:app.http/request (reify + yetti.request/IRequest + (get-header [_ _] nil) + (remote-addr [_] "127.0.0.1"))}) + result)] + ;; the response does expose the report owner's profile... + (t/is (= owner (get result :profile-id))) + ;; ...but the audit event belongs to whoever called the command + (t/is (= (:id caller) (:profile-id event))))))) ;; Note: The integration of access token middleware with audit context is tested ;; via unit tests in rpc_audit_test.clj and http_middleware_test.clj. diff --git a/backend/test/backend_tests/rpc_profile_test.clj b/backend/test/backend_tests/rpc_profile_test.clj index ab10c91f4c..94f08a21b5 100644 --- a/backend/test/backend_tests/rpc_profile_test.clj +++ b/backend/test/backend_tests/rpc_profile_test.clj @@ -1385,3 +1385,56 @@ (t/is (th/ex-info? (:error out))) (t/is (th/ex-of-type? (:error out) :validation)) (t/is (th/ex-of-code? (:error out) :weak-password)))) + +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +;; VERIFY-TOKEN AUDIT ATTRIBUTION +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; + +(t/deftest verify-token-auth-audit-event-attributes-the-authenticated-profile + ;; `verify-token` is anonymous, so the audit event cannot infer the profile + ;; from the caller: the handler must declare it in the result metadata. + (let [profile (th/create-profile* 1 {:is-active true}) + token (tokens/generate th/*system* + {:iss :auth + :exp (ct/in-future "1h") + :profile-id (:id profile)}) + out (th/command! {::th/type :verify-token + :token token})] + (t/is (th/success? out)) + (t/is (= (:id profile) + (get-in (meta (:result out)) [:app.loggers.audit/profile-id]))))) + +(t/deftest verify-token-invitation-audit-event-attributes-the-accepting-profile + ;; Both the invitation claims and the response carry the inviter's + ;; profile-id, so the event must not end up on the inviter: the member who + ;; clicked the link is the one who accepted the invitation. + (with-redefs [app.config/flags #{:login-with-password}] + (let [owner (th/create-profile* 1 {:is-active true}) + team (th/create-team* 1 {:profile-id (:id owner)}) + member (th/create-profile* 2 {:is-active true + :email "invited@example.com"}) + email (:email member) + token (tokens/generate th/*system* + {:iss :team-invitation + :exp (ct/in-future "48h") + :role :editor + :profile-id (:id owner) + :team-id (:id team) + :member-email email + :member-id (:id member)})] + (th/db-insert! :team-invitation + {:id (uuid/random) + :team-id (:id team) + :email-to email + :created-by (:id owner) + :role "editor" + :valid-until (ct/in-future "48h")}) + + (let [out (th/command! {::th/type :verify-token + :token token + ::rpc/profile-id (:id member) + ::rpc/auth-type :session}) + event-pid (get-in (meta (:result out)) [:app.loggers.audit/profile-id])] + (t/is (th/success? out)) + (t/is (= (:id member) event-pid)) + (t/is (not= (:id owner) event-pid))))))