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