Add rlimit notifications and reports

Also improve the current mattermost reporting for make it
more easily to filter
This commit is contained in:
Andrey Antukh
2026-02-11 15:40:15 +01:00
parent 394d597736
commit d114008eb6
11 changed files with 217 additions and 73 deletions

View File

@@ -12,6 +12,7 @@ penpot - error list
<a class="{% if version = 3 %}strong{% endif %}" href="?version=3">[BACKEND ERRORS]</a>
<a class="{% if version = 4 %}strong{% endif %}" href="?version=4">[FRONTEND ERRORS]</a>
<a class="{% if version = 5 %}strong{% endif %}" href="?version=5">[RLIMIT REPORTS]</a>
</div>
</nav>
<main class="horizontal-list">

View File

@@ -0,0 +1,40 @@
{% extends "app/templates/base.tmpl" %}
{% block title %}
Report: {{hint|abbreviate:150}} - {{id}} - Penpot Rate Limit Report
{% endblock %}
{% block content %}
<nav>
<div>[<a href="/dbg/error?version={{version}}">⮜</a>]</div>
<div>[<a href="#head">head</a>]</div>
<div>[<a href="#context">context</a>]</div>
<div>[<a href="#result">result</a>]</div>
</nav>
<main>
<div class="table">
<div class="table-row multiline">
<div id="head" class="table-key">HEAD:</div>
<div class="table-val">
<h1><span class="not-important">Hint:</span> <br/> {{hint}}</h1>
<h2><span class="not-important">Reported at:</span> <br/> {{created-at}}</h2>
<h2><span class="not-important">Report ID:</span> <br/> {{id}}</h2>
</div>
</div>
<div class="table-row multiline">
<div id="context" class="table-key">CONTEXT: </div>
<div class="table-val">
<pre>{{context}}</pre>
</div>
</div>
<div class="table-row multiline">
<div id="context" class="table-key">RESULT: </div>
<div class="table-val">
<pre>{{result}}</pre>
</div>
</div>
</div>
</main>
{% endblock %}

View File

@@ -3,9 +3,9 @@
{:default
[[:default :window "200000/h"]]
;; #{:command/get-teams}
;; #{:main/get-teams}
;; [[:burst :bucket "5/5/5s"]]
;; #{:command/get-profile}
;; #{:main/get-profile}
;; [[:burst :bucket "60/60/1m"]]
}

View File

@@ -240,6 +240,13 @@
(tmpl/render (-> content
(assoc :id id)
(assoc :version 4)
(assoc :created-at (ct/format-inst created-at :rfc1123))))))
(render-template-v5 [{:keys [content id created-at]}]
(-> (io/resource "app/templates/error-report.v5.tmpl")
(tmpl/render (-> content
(assoc :id id)
(assoc :version 5)
(assoc :created-at (ct/format-inst created-at :rfc1123))))))]
(if-let [report (get-report request)]
@@ -247,7 +254,8 @@
1 (render-template-v1 report)
2 (render-template-v2 report)
3 (render-template-v3 report)
4 (render-template-v4 report))]
4 (render-template-v4 report)
5 (render-template-v5 report))]
{::yres/status 200
::yres/body result
::yres/headers {"content-type" "text/html; charset=utf-8"

View File

@@ -151,20 +151,22 @@
uuid/zero)
props (-> (or (::replace-props resultm)
(-> params
(merge (::props resultm))
(dissoc :profile-id)
(dissoc :type)))
(merge params (::props resultm)))
(clean-props))
context (merge (::context resultm)
(prepare-context-from-request request))
ip-addr (inet/parse-request request)]
ip-addr (inet/parse-request request)
module (get cfg ::rpc/module)]
{::type (or (::type resultm)
(::rpc/type cfg))
::name (or (::name resultm)
(::sv/name mdata))
(let [sname (::sv/name mdata)]
(if (not= module "main")
(str module "-" sname)
sname)))
::profile-id profile-id
::ip-addr ip-addr
::props props

View File

@@ -15,6 +15,7 @@
[app.config :as cf]
[app.db :as db]
[app.loggers.audit :as audit]
[app.rpc.rlimit :as-alias rlimit]
[clojure.spec.alpha :as s]
[integrant.core :as ig]
[promesa.exec :as px]
@@ -41,7 +42,7 @@
(or (instance? java.util.concurrent.CompletionException cause)
(instance? java.util.concurrent.ExecutionException cause)))
(defn record->report
(defn- log-record->report
[{:keys [::l/context ::l/message ::l/props ::l/logger ::l/level ::l/cause] :as record}]
(assert (l/valid-record? record) "expectd valid log record")
(let [data (if (concurrent-exception? cause)
@@ -86,16 +87,16 @@
[{:keys [::db/pool]} {:keys [::l/id] :as record}]
(try
(let [uri (cf/get :public-uri)
report (-> record record->report d/without-nils)]
report (-> record log-record->report d/without-nils)]
(l/dbg :hint "registering error on database"
:id id
:id (str id)
:src "logging"
:uri (str uri "/dbg/error/" id))
(persist-on-database! pool id 3 report))
(catch Throwable cause
(l/warn :hint "unexpected exception on database error logger" :cause cause))))
(defn- event->report
(defn- audit-event->report
[{:keys [::audit/context ::audit/props ::audit/ip-addr] :as record}]
(let [context
(reduce-kv (fn [context k v]
@@ -125,15 +126,51 @@
[{:keys [::db/pool]} {:keys [::audit/id] :as event}]
(try
(let [uri (cf/get :public-uri)
report (-> event event->report d/without-nils)]
report (-> event audit-event->report d/without-nils)]
(l/dbg :hint "registering error on database"
:id id
:id (str id)
:src "audit-log"
:uri (str uri "/dbg/error/" id))
(persist-on-database! pool id 4 report))
(catch Throwable cause
(l/warn :hint "unexpected exception on database error logger" :cause cause))))
(defn- rlimit-event->report
[event]
(let [context
(-> {}
(assoc :rlimit/uid (::rlimit/uid event))
(assoc :rlimit/method (::rlimit/method event))
(assoc :backend/tenant (cf/get :tenant))
(assoc :backend/host (cf/get :host))
(assoc :backend/public-uri (str (cf/get :public-uri)))
(assoc :backend/version (:full cf/version)))
result
(->> (::rlimit/results event)
(mapv (fn [result]
(-> (into (sorted-map) result)
(dissoc ::rlimit/method)))))]
{:hint (str "Rate Limit Rejection: " (::rlimit/method event) " for " (::rlimit/uid event))
:context (-> (into (sorted-map) context)
(pp/pprint-str :length 50))
:result (pp/pprint-str result :length 50)}))
(defn- handle-rlimit-event
"Convert the log record into a report object and persist it on the database"
[{:keys [::db/pool]} {:keys [::rlimit/id] :as event}]
(try
(let [uri (cf/get :public-uri)
report (-> event rlimit-event->report d/without-nils)]
(l/dbg :hint "registering rate limit rejection"
:id (str id)
:src "rlimit"
:uri (str uri "/dbg/error/" id))
(persist-on-database! pool id 5 report))
(catch Throwable cause
(l/warn :hint "unexpected exception on database error logger" :cause cause))))
(defmethod ig/assert-key ::reporter
[_ params]
(assert (db/pool? (::db/pool params)) "expect valid database pool"))
@@ -154,6 +191,9 @@
(::audit/id item)
(handle-audit-event cfg item)
(::rlimit/id item)
(handle-rlimit-event cfg item)
:else
(l/warn :hint "received unexpected item" :item item))

View File

@@ -9,10 +9,12 @@
(:require
[app.common.exceptions :as ex]
[app.common.logging :as l]
[app.common.pprint :as pp]
[app.common.uri :as u]
[app.config :as cf]
[app.http.client :as http]
[app.loggers.audit :as audit]
[app.rpc.rlimit :as-alias rlimit]
[app.util.json :as json]
[integrant.core :as ig]
[promesa.exec :as px]
@@ -22,21 +24,28 @@
(defn- send-mattermost-notification!
[cfg {:keys [id] :as report}]
(let [type (get report :type)
text (str "#" type " | " (get report :hint) "\n"
(when id
(str (u/join (cf/get :public-uri) "/dbg/error/" id) " "))
(let [url (u/join (cf/get :public-uri) "/dbg/error/" id)
text (str "Exception: " url " "
(when-let [pid (:profile-id report)]
(str "(pid: #uuid-" pid ")"))
(if (uuid? pid)
(str "(pid: #uuid-" pid ")")
(str "(pid: #ip-" pid ")")))
"\n"
"- host: #" (:host report) "\n"
"- tenant: #" (:tenant report) "\n"
"- origin: #" (:origin report) "\n"
"- href: `" (:href report) "`\n"
"- frontend-version: `" (:frontend-version report) "`\n"
"- backend-version: `" (:backend-version report) "`\n"
(when-let [href (get report :href)]
(str "- href: `" href "`\n"))
(when-let [version (get report :frontend-version)]
(str "- frontend-version: `" version "`\n"))
(when-let [version (get report :backend-version)]
(str "- backend-version: `" version "`\n"))
"\n"
(when-let [info (:info report)]
(str "```\n" info "```"))
(when-let [trace (:trace report)]
(str "```\n"
"Trace:\n"
@@ -54,13 +63,15 @@
(l/warn :hint "error on sending data"
:response (pr-str resp)))))
(defn- record->report
[{:keys [::l/context ::l/id ::l/cause] :as record}]
(defn- log-record->report
[{:keys [::l/context ::l/id ::l/cause ::l/message] :as record}]
(assert (l/valid-record? record) "expectd valid log record")
(let [public-uri (cf/get :public-uri)]
{:id id
:type "exception"
:origin "logging"
:hint (or (some-> cause ex-message) @message)
:tenant (cf/get :tenant)
:host (cf/get :host)
:backend-version (:full cf/version)
@@ -74,7 +85,9 @@
(defn- audit-event->report
[{:keys [::audit/context ::audit/props ::audit/id] :as event}]
{:id id
:type "exception"
:origin "audit-log"
:hint (get props :hint)
:tenant (cf/get :tenant)
:host (cf/get :host)
:backend-version (:full cf/version)
@@ -82,18 +95,35 @@
:profile-id (:audit/profile-id event)
:href (get props :href)})
(defn- handle-log-record
[cfg record]
(try
(let [report (record->report record)]
(send-mattermost-notification! cfg report))
(catch Throwable cause
(l/warn :hint "unhandled error" :cause cause))))
(defn- rlimit-event->report
[event]
{:id (::rlimit/id event)
:type "notification"
:origin "rlimit"
:hint (str "rlimit reject of "
(::rlimit/method event)
" for "
(::rlimit/uid event))
:tenant (cf/get :tenant)
:host (cf/get :host)
:backend-version (:full cf/version)
:profile-id (::rlimit/profile-id event)
:info (with-out-str
(println "Rejected by:")
(println "------------")
(println "Method: " (::rlimit/method event))
(println "Limit Name: " (::rlimit/name event))
(println "Limit Strategy:" (::rlimit/strategy event))
(println)
(println "Results & Config:")
(println "-----------------")
(doseq [result (::rlimit/results event)]
(pp/pprint (into (sorted-map) result))))})
(defn- handle-audit-event
[cfg record]
(defn- handle-event
[cfg event event->report]
(try
(let [report (audit-event->report record)]
(let [report (event->report event)]
(send-mattermost-notification! cfg report))
(catch Throwable cause
(l/warn :hint "unhandled error" :cause cause))))
@@ -116,10 +146,13 @@
(when @enabled
(cond
(::l/id item)
(handle-log-record cfg item)
(handle-event cfg item log-record->report)
(::audit/id item)
(handle-audit-event cfg item)
(handle-event cfg item audit-event->report)
(::rlimit/id item)
(handle-event cfg item rlimit-event->report)
:else
(l/warn :hint "received unexpected item" :item item)))

View File

@@ -317,7 +317,13 @@
::climit/enabled (contains? cf/flags :rpc-climit)}
:app.rpc/rlimit
{::wrk/executor (ig/ref ::wrk/netty-executor)}
{::wrk/executor (ig/ref ::wrk/netty-executor)
:app.loggers.mattermost/reporter
(ig/ref :app.loggers.mattermost/reporter)
:app.loggers.database/reporter
(ig/ref :app.loggers.database/reporter)}
:app.rpc/methods
{::http.client/client (ig/ref ::http.client/client)

View File

@@ -90,7 +90,7 @@
[methods]
(let [methods (update-vals methods peek)]
(fn [{:keys [params path-params method] :as request}]
(let [handler-name (:type path-params)
(let [handler-name (:method-name path-params)
etag (yreq/get-header request "if-none-match")
key-id (get request ::http/auth-key-id)
@@ -227,8 +227,8 @@
(wrap-authentication cfg $ mdata)))
(defn- process-method
[cfg module wrap-fn [f mdata]]
(l/trc :hint "add method" :module module :name (::sv/name mdata))
[cfg wrap-fn [f mdata]]
(l/wrn :hint "add method" :module (::module cfg) :type (::type cfg) :name (::sv/name mdata))
(let [f (wrap-fn cfg f mdata)
k (keyword (::sv/name mdata))]
[k [mdata (partial f cfg)]]))
@@ -239,7 +239,7 @@
(defn- resolve-methods
[cfg]
(let [cfg (assoc cfg ::type "command" ::metrics-id :rpc-command-timing)]
(let [cfg (assoc cfg ::module "main" ::type "command" ::metrics-id :rpc-main-timing)]
(->> (sv/scan-ns
'app.rpc.commands.access-token
'app.rpc.commands.audit
@@ -266,7 +266,7 @@
'app.rpc.commands.verify-token
'app.rpc.commands.viewer
'app.rpc.commands.webhooks)
(map (partial process-method cfg "rpc" wrap))
(map (partial process-method cfg wrap))
(into {}))))
(def ^:private schema:methods-params
@@ -298,13 +298,13 @@
(defn- resolve-management-methods
[cfg]
(let [cfg (assoc cfg ::type "management" ::metrics-id :rpc-management-timing)
(let [cfg (assoc cfg ::module "management" ::type "command" ::metrics-id :rpc-management-timing)
mods (cond->> (list 'app.rpc.management.exporter)
(contains? cf/flags :nitrate)
(cons 'app.rpc.management.nitrate))]
(->> (apply sv/scan-ns mods)
(map (partial process-method cfg "management" wrap-management))
(map (partial process-method cfg wrap-management))
(into {}))))
(def ^:private schema:management-methods-params
@@ -359,7 +359,7 @@
(let [public-uri (cf/get :public-uri)]
["/api"
["/management"
["/methods/:type"
["/methods/:method-name"
{:middleware [[mw/shared-key-auth shared-keys]
[session/authz cfg]]
:handler (make-rpc-handler management-methods)}]
@@ -370,7 +370,7 @@
:description "MANAGEMENT API")]
["/main"
["/methods/:type"
["/methods/:method-name"
{:middleware [[mw/cors]
[sec/client-header-check]
[session/authz cfg]
@@ -388,7 +388,7 @@
["/openapi" {:handler (redirect (u/join public-uri "/api/main/doc/openapi"))}]
["/openapi.join" {:handler (redirect (u/join public-uri "/api/main/doc/openapi.json"))}]
["/rpc/command/:type"
["/rpc/command/:method-name"
{:middleware [[mw/cors]
[sec/client-header-check]
[session/authz cfg]

View File

@@ -52,6 +52,8 @@
[app.common.uuid :as uuid]
[app.config :as cf]
[app.http :as-alias http]
[app.loggers.database :as loggers.db]
[app.loggers.mattermost :as loggers.mm]
[app.redis :as rds]
[app.redis.script :as-alias rscript]
[app.rpc :as-alias rpc]
@@ -171,9 +173,9 @@
:hint (str/ffmt "looks like '%' does not have a valid format" opts))))
(defmethod process-limit :bucket
[rconn profile-id now {:keys [::key ::params ::service ::capacity ::interval ::rate] :as limit}]
[rconn profile-id now {:keys [::key ::params ::method ::capacity ::interval ::rate] :as limit}]
(let [script (-> bucket-rate-limit-script
(assoc ::rscript/keys [(str key "." service "." profile-id)])
(assoc ::rscript/keys [(str key "." method "." profile-id)])
(assoc ::rscript/vals (conj params (->seconds now))))
result (rds/eval rconn script)
allowed? (boolean (nth result 0))
@@ -181,7 +183,7 @@
reset (* (/ (inst-ms interval) rate)
(- capacity remaining))]
(l/trace :hint "limit processed"
:service service
:method method
:limit (name (::name limit))
:strategy (name (::strategy limit))
:opts (::opts limit)
@@ -193,17 +195,17 @@
(assoc ::lresult/remaining remaining))))
(defmethod process-limit :window
[rconn profile-id now {:keys [::permits ::unit ::key ::service] :as limit}]
[rconn uid now {:keys [::permits ::unit ::key ::method] :as limit}]
(let [ts (ct/truncate now unit)
ttl (ct/diff now (ct/plus ts {unit 1}))
script (-> window-rate-limit-script
(assoc ::rscript/keys [(str key "." service "." profile-id "." (ct/format-inst ts))])
(assoc ::rscript/keys [(str key "." method "." uid "." (ct/format-inst ts))])
(assoc ::rscript/vals [permits (->seconds ttl)]))
result (rds/eval rconn script)
allowed? (boolean (nth result 0))
remaining (nth result 1)]
(l/trace :hint "limit processed"
:service service
:method method
:name (name (::name limit))
:strategy (name (::strategy limit))
:opts (::opts limit)
@@ -211,12 +213,13 @@
:remaining remaining)
(-> limit
(assoc ::lresult/allowed allowed?)
(assoc ::lresult/timestamp ts)
(assoc ::lresult/remaining remaining)
(assoc ::lresult/reset (ct/plus ts {unit 1})))))
(defn- process-limits
[rconn profile-id limits now]
(let [results (into [] (map (partial process-limit rconn profile-id now)) limits)
[{:keys [::rds/conn] :as cfg} uid limits now]
(let [results (into [] (map (partial process-limit conn uid now)) limits)
remaining (->> results
(d/index-by ::name ::lresult/remaining)
(uri/map->query-string))
@@ -227,11 +230,22 @@
rejected (d/seek (complement ::lresult/allowed) results)]
(when rejected
(l/warn :hint "rejected rate limit"
:profile-id (str profile-id)
:limit-service (-> rejected ::service name)
:limit-name (-> rejected ::name name)
:limit-strategy (-> rejected ::strategy name)))
(let [event {::id (uuid/next)
::uid uid
::method (-> rejected ::method name)
::name (-> rejected ::name name)
::strategy (-> rejected ::strategy name)
::results results}]
(l/warn :hint "rejected rate limit"
:method (-> rejected ::method name)
:name (-> rejected ::name name)
:strategy (-> rejected ::strategy name)
:uid (str uid)
:report-id (:id event))
(loggers.mm/emit cfg event)
(loggers.db/emit cfg event)))
{::enabled true
::allowed (not (some? rejected))
@@ -244,7 +258,7 @@
[state skey sname]
(when-let [limits (or (get-in @state [::limits skey])
(get-in @state [::limits :default]))]
(into [] (map #(assoc % ::service sname)) limits)))
(into [] (map #(assoc % ::method sname)) limits)))
(defn- get-uid
[{:keys [::rpc/profile-id] :as params}]
@@ -254,10 +268,10 @@
uuid/zero)))
(defn- process-request'
[{:keys [::rds/conn] :as cfg} limits params]
[cfg limits params]
(try
(let [uid (get-uid params)
result (process-limits conn uid limits (ct/now))]
result (process-limits cfg uid limits (ct/now))]
(if (contains? cf/flags :soft-rpc-rlimit)
{::enabled false}
result))
@@ -275,8 +289,8 @@
(assert (or (nil? rlimit) (valid-rlimit-instance? rlimit)) "expected a valid rlimit instance")
(if rlimit
(let [skey (keyword (::rpc/type cfg) (->> mdata ::sv/spec name))
sname (str (::rpc/type cfg) "." (->> mdata ::sv/spec name))
(let [skey (keyword (::rpc/module cfg) (->> mdata ::sv/spec name))
sname (str (::rpc/module cfg) "." (->> mdata ::sv/spec name))
cfg (-> cfg
(assoc ::skey skey)
(assoc ::sname sname))]

View File

@@ -104,13 +104,13 @@
(assoc-in [::db/pool ::db/password] (:database-password config))
(assoc-in [:app.rpc/methods :app.setup/templates] templates)
(assoc-in [:app.rpc/methods :app.setup/templates] templates)
(update :app.rpc/methods
(fn [state]
(-> state
(assoc :app.setup/templates templates)
(assoc :app.loggers.mattermost/reporter nil)
(assoc :app.loggers.database/reporter nil))))
(update :app.rpc/rlimit assoc
:app.loggers.mattermost/reporter nil
:app.loggers.database/reporter nil)
(update :app.rpc/methods assoc
:app.setup/templates templates
:app.loggers.mattermost/reporter nil
:app.loggers.database/reporter nil)
(dissoc :app.srepl/server
:app.http/server
:app.http/route