From 414553278ae36b4e213cbd56a56e4e09a5f441eb Mon Sep 17 00:00:00 2001 From: Andrey Antukh Date: Thu, 15 Oct 2026 19:50:06 +0200 Subject: [PATCH] :sparkles: Count the application logs as a metric, by logger and level (#12313) * :sparkles: Count the application logs as a metric, by logger and level The error panels had no metric to read: they counted log lines in Loki, because the backend published nothing about the errors of the application (the only thing alive in Prometheus was the http listener error count, which measures another thing). Now there is `penpot_log_events_total{logger, level}`. The counter comes from a new component, `app.loggers.metrics/reporter`, which hooks a watch on the log record like the database and mattermost reporters do, but without a thread or a channel: the increment is in memory, so it runs in the watcher itself. Only `warn`, `error` and `fatal` are counted, and only the records that go through `app.common.logging`: the lines a library writes straight to log4j2 are not counted (one in a thousand today). The body of the watcher is wrapped in a `try/catch` that swallows the error on purpose: the watcher fires from the `swap!` of the log record, inside the logging path, so an exception there would reach whoever was logging and would take the logging executor down with it. A test pins that a failing publication does not propagate. The suite removes the reporter (it would count the logs of the tests and the recording of their `mtx/run!`), so a test of its own pins the wiring. The memories carry the counter, its two limits and why the `try/catch` is not noise; the grafana one also brings the notes of this afternoon about the service account, the dashboard search and Cloudflare, which were waiting for a commit. AI-assisted-by: deepseek-v4.1-flash * :books: Address the review findings on the log-events metric The review of the counter found that the reason written for the `try/catch` was not the real one, so the memory and the comments say now what happens if it is removed: with `::l/sync?` the exception reaches whoever was logging, and on the async path it dies in the uncaught handler of the logging executor -- outside the application's logging -- where the pool replaces the worker, so logging continues and that line is lost. They also say that a publication failing every time is silent: the counter stays flat and nothing is written about it. The rest are small things the review asked for: the test of the `fatal` level (it was in the counted set and nothing verified it), the HELP of the metric naming the three levels, the require of the test without the unused alias that clj-kondo flagged, and the note that the `level` is lowercase here and uppercase in Loki. The grafana memory loses what was said twice: the two pairs of bullets about reading the API (the service account 403s and the search that lies) are merged, the CLIMIT notes are one bullet instead of two, and the four bullets about editing dashboards are grouped in their own section. Its host name is gone as well, which the first line of that file forbids. AI-assisted-by: deepseek-v4.1-flash --- .serena/memories/backend/subtleties.md | 4 + .serena/memories/prod-infra/grafana.md | 24 +++- backend/src/app/loggers/metrics.clj | 46 ++++++ backend/src/app/main.clj | 11 +- backend/test/backend_tests/helpers.clj | 1 + .../backend_tests/loggers_metrics_test.clj | 135 ++++++++++++++++++ 6 files changed, 213 insertions(+), 8 deletions(-) create mode 100644 backend/src/app/loggers/metrics.clj create mode 100644 backend/test/backend_tests/loggers_metrics_test.clj diff --git a/.serena/memories/backend/subtleties.md b/.serena/memories/backend/subtleties.md index 241d1e1567..ed7f390af6 100644 --- a/.serena/memories/backend/subtleties.md +++ b/.serena/memories/backend/subtleties.md @@ -57,6 +57,10 @@ - The xnio worker MXBean can return transient `-1` (e.g. on the queue or the pool size); negative samples are discarded (gauge keeps its previous value). Undertow exposes absolute request/error totals, so the sampler keeps a watermark atom and publishes deltas; a counter reset (decreasing totals) skips the negative delta and moves the watermark forward. - The `process_*` families (`process_open_fds`, `process_max_fds`, `process_cpu_seconds_total`, …) come from the prometheus client `StandardExports`, registered by `app.metrics/create-registry`. They read the OS MXBean reflectively and need the `jdk.management` module: on a pruned `jlink` JRE the MXBean is `sun.management.BaseOperatingSystemImpl`, the getters throw `NoSuchMethodException` and `StandardExports#collect` swallows it, so those families silently vanish from `/metrics`. `docker/images/Dockerfile.backend` keeps `jdk.management` in the `--add-modules` list, and `backend-tests.metrics-test` pins the contract. +## Log-derived metrics + +- `app.loggers.metrics/reporter` counts the log records the application emits and publishes them as `penpot_log_events_total{logger, level}` (counter), so the error panels do not have to count text in Loki. It is a component that hooks `add-watch` on `app.common.logging/log-record`, like `app.loggers.database`, but with no thread and no channel: the increment is in memory, so it goes straight in the watcher. Only `warn`, `error` and `fatal` are counted, and only the records that go through `app.common.logging` (the application's own logs; a library writing straight to log4j2 is not counted, and today that is one line in a thousand). The body of the watcher is wrapped in a `try/catch` that swallows the error on purpose: the watcher fires from the `swap!` of the log record, inside the logging path. With `::l/sync?` (`app.binfile.v1`, `app.msgbus`) an exception there would reach whoever was logging; on the async path it escapes to the logging executor worker, whose trace goes to the thread's uncaught handler -- outside the application's logging -- and the pool replaces the dead worker, so logging continues and that line is lost. The catch also makes a publication that fails every time invisible: `penpot_log_events_total` stays flat and nothing is written about it. The published `level` values are lowercase (`warn`), unlike the `level` label of the Loki logs (`ERROR`), so a panel that moves from one source to the other has to change it. Cardinality is `logger` (fixed names taken from the code) times `level`; a logger built from a dynamic value would break that. + ## Storage and media - Storage abstraction, backend configuration, logical buckets, object lifecycle, deduplication, access rules, and garbage collection: `mem:backend/storage`. diff --git a/.serena/memories/prod-infra/grafana.md b/.serena/memories/prod-infra/grafana.md index fbc40ec6e5..10af277db2 100644 --- a/.serena/memories/prod-infra/grafana.md +++ b/.serena/memories/prod-infra/grafana.md @@ -6,15 +6,15 @@ Keep this memory free of internal names: no host names, no deployed versions, no ## Datasources -- Metrics — **Prometheus**, uid `xkRmyFBGk`. PromQL. Metric families: `penpot_*` (RPC, task timings, CLIMIT, HTTP, websocket, storage), `hikaricp_*`, `jvm_*` and `process_*` on the backend (`job="app"`); `pg_*` from the Postgres exporter (`job="postgres"`); `redis_*` from the Redis exporter (`job="redis"`); `node_*` and `container_*` from node-exporter and cAdvisor. Backend histograms are in **milliseconds**. -- Logs — **Loki**, uid `h3CGKhEMk`. LogQL, and filter by the structured metadata `logger`/`level` (`{job="penpot"} | logger="..." | level="ERROR"`). Signals that only exist as logs: the profile behind a CLIMIT queue (`logger="app.rpc.climit"`, whose `id` carries the key). CLIMIT rejections have their own counters (`penpot_rpc_climit_rejected_total`, by `name` and `reason`), and their `hint="rejected"` line goes out at WARN only when something stays queued, so counting the lines is not counting the rejections. +- Metrics — **Prometheus**, uid `xkRmyFBGk`. PromQL. Metric families: `penpot_*` (RPC, task timings, CLIMIT, HTTP, websocket, storage, and the application log events of the backend), `hikaricp_*`, `jvm_*` and `process_*` on the backend (`job="app"`); `pg_*` from the Postgres exporter (`job="postgres"`); `redis_*` from the Redis exporter (`job="redis"`); `node_*` and `container_*` from node-exporter and cAdvisor. Backend histograms are in **milliseconds**. +- Logs — **Loki**, uid `h3CGKhEMk`. LogQL, and filter by the structured metadata `logger`/`level` (`{job="penpot"} | logger="..." | level="ERROR"`). Two things to remember when counting from it: the CLIMIT rejections have their own counters (`penpot_rpc_climit_rejected_total`, by `name` and `reason`) and their `hint="rejected"` line goes out at WARN only when something is left queued behind the call (a lone caller that times out is written at TRACE), so counting lines is not counting rejections -- the same goes for `hint="enqueued"` and `hint="acquired"`; and the only signal that exists nowhere else is the profile behind a queue (`logger="app.rpc.climit"`, whose `id` carries the key), chased there on demand. - SQL — **Postgres**, uid `y8ea9tfMk`. Panels need `rawQuery: true`, `editorMode: "code"` and `format: "table"`. The `task` table is the only truth about the queue depth. It is a **read-only replica**: it rejects any write, `CREATE TEMP TABLE` included, so queries through it must be plain `SELECT`s. It also cuts long-running queries (the MCP path has a short timeout), so bound them (e.g. a list of ids); an empty answer there is not proof that there is no data. - **Postgres (telemetry)**, uid `9YAUuM_Gz`. - `$__rate_interval` and `$__interval` are substituted by Grafana; use them instead of fixed windows in graphs. ## Main dashboard -- `Production status`, uid `penpot-production-status`. Sections: general state and deploy, RPC and CLIMIT, PostgreSQL and pool, Redis/msgbus, tasks, JVM/process. Variables `$env` and `$host` (custom), no auto refresh. +- `Production status`, uid `penpot-production-status`. Sections: general state and deploy, `RPC y CLIMIT`, PostgreSQL and pool, Redis/msgbus, tasks, JVM/process. Variables `$env` and `$host` (custom), no auto refresh. Every section opens collapsed except `RPC y CLIMIT`, which is the one read on a normal day. - Per-host investigation dashboards are separate, and the alert rules deeplink into them. ## Conventions @@ -26,6 +26,20 @@ Keep this memory free of internal names: no host names, no deployed versions, no - Cron "did it run" comes from the task metrics, not from the cron registry table (it keeps rows from old versions). - Dashboard thresholds must match the alert rule thresholds. +## Editing dashboards through the API + +- Saving through the API normalizes the dashboard: submit the native form, rows with `panels: []` and their panels top-level with contiguous `y`. A row that has to start collapsed (or open) is sent holding its children in `panels` with `collapsed` set, and the top-level `y` are recomputed by hand: one unit per collapsed row, with the expanded block kept contiguous. Grafana accepts it and returns the same shape. +- A `remove` operation on a panel leaves its `gridPos` hole behind: Grafana does not refill the layout (the UI behaves the same), so a neighbouring panel has to be moved by hand when the gap matters. +- Check `list_dashboard_versions` before writing and prefer `operations` patches: the user edits dashboards by hand and a full-JSON overwrite silently reverts that work. + +## Reading the API by hand + +- The MCP authenticates with a service account token (`GRAFANA_SERVICE_ACCOUNT_TOKEN`, set in the environment of the MCP server), and a service account has no user behind it: a 403 is never the token being bad. On `/api/user` and `/api/user/orgs` it is normal; on a single dashboard (`Access denied to this dashboard`, which is not a 404) it means that identity cannot see it, a permission on that dashboard or its folder. Restarting the MCP or rotating the token changes nothing, and `X-Grafana-Org-Id` does not help when the identity belongs to another organization. +- Listing is reliable, filtering is not: a dashboard search with a text query answers empty in this instance (through the tool and through `/api/search?query=...` alike), and `list_prometheus_metric_names` also lists names that survive only in the retained series of a metric that stopped being published. Use the listing without a query, and `count()` to tell whether a metric is alive today. +- The MCP Prometheus tool can answer empty for every query, `up` included, while the datasource itself is fine: run PromQL by hand with `grafana_api_request` against `/api/datasources/uid//resources/api/v1/query?query=...`. +- `curl` and `python` from the shell cannot reach the Grafana host of the deployment: Cloudflare blocks them (`error code: 1010`, which looks like a 403 and has nothing to do with Grafana). Probe the API through the MCP (`grafana_api_request`), which is what the deployment lets through. +- A Loki query by hand goes through `GET /api/datasources/proxy/uid//loki/api/v1/query_range?query=&start=&end=&step=` (the range comes back as `resultType: matrix`, one series per group). For Loki the `/api/datasources/uid//resources/...` route answers 500, and `/api/ds/query` is not reachable from `grafana_api_request` at all (404), even though that is the path the dashboards use. + ## Gotchas - PromQL literal dots need `\\.`; simpler to use `[.]` or a plain dot. @@ -34,9 +48,5 @@ Keep this memory free of internal names: no host names, no deployed versions, no - Prometheus: `label_replace(, "host", "$1", "instance", "([^.]+)[.][^.]+.*")` plus `legendFormat: "... {{host}}"`. - Loki metric query: `| label_format host="{{ regexReplaceAll "[.][^.]*[.][^.]*[.][^.]*$" .instance "" }}"` plus `legendFormat: "{{host}}"`. Quotes inside the template must be escaped as `\"`, or LogQL closes the string early (`not a valid duration string`). - Tables from a Prometheus raw selector carry a `__name__` column; hide it with `organize`. -- Saving through the API normalizes the dashboard (rows may be flattened, `y` recomputed): submit the native form (rows with `panels: []`, panels top-level, contiguous `y`). - Panel images cannot be rendered (no image renderer installed) and there is no browser here: verify a dashboard by running its queries with the variables substituted. - Signals that exist only as logs are counted with Loki, and the count is then cross-checked against the nginx access log for the same window and the same status code (`job="frontend"`, e.g. a `429`): two independent sources must agree before a number is trusted. -- The app writes its own logs at WARN only when something is left queued behind the call and at TRACE otherwise, so production Loki holds just the under-pressure lines: a count of `hint="enqueued"` or `hint="acquired"` is not the number of calls, and neither is a count of `hint="rejected"` lines, because a rejection that leaves the queue empty (a lone caller that times out) is written at TRACE. The rejection counters are the real number. -- The MCP Prometheus tool can answer empty for every query, `up` included, while the datasource itself is fine: an empty result from it is not proof that a panel has no data, and blaming the datasource for it is wrong. Run PromQL by hand with `grafana_api_request` against `/api/datasources/uid//resources/api/v1/query?query=...` (or `POST /api/ds/query`, the path dashboards use), and check when a series is expected but the tool says nothing. -- **Check `list_dashboard_versions` before writing.** The user edits dashboards by hand and a full-JSON overwrite silently reverts that work; prefer `operations` patches per panel. diff --git a/backend/src/app/loggers/metrics.clj b/backend/src/app/loggers/metrics.clj new file mode 100644 index 0000000000..07c97debd1 --- /dev/null +++ b/backend/src/app/loggers/metrics.clj @@ -0,0 +1,46 @@ +;; This Source Code Form is subject to the terms of the Mozilla Public +;; License, v. 2.0. If a copy of the MPL was not distributed with this +;; file, You can obtain one at http://mozilla.org/MPL/2.0/. +;; +;; Copyright (c) KALEIDOS INC Sucursal en España SL + +(ns app.loggers.metrics + "A reporter that counts the log records of this application, by logger and + level, and publishes them as a counter." + (:require + [app.common.logging :as l] + [app.metrics :as mtx] + [integrant.core :as ig])) + +(def ^:private counted-levels + "The levels worth counting: `info` is emitted often and says nothing about + the health of the application." + #{:warn :error :fatal}) + +(defmethod ig/assert-key ::reporter + [_ params] + (assert (mtx/metrics? (::mtx/metrics params)) "expect valid metrics instance")) + +(defmethod ig/init-key ::reporter + [_ {::mtx/keys [metrics]}] + (add-watch l/log-record ::reporter + (fn [_ _ _ record] + ;; This runs inside the logging path: the watcher fires from + ;; the `swap!` of the log record, so an exception here would + ;; reach whoever was logging on the synchronous path, and on + ;; the async one it would die in the executor's uncaught + ;; handler, taking that log line out of Loki. Swallowed on + ;; purpose either way. + (try + (let [level (::l/level record)] + (when (contains? counted-levels level) + (mtx/run! metrics + :id :log-events + :inc 1 + :labels (into-array String [(::l/logger record) (name level)])))) + (catch Throwable _ nil)))) + {::mtx/metrics metrics}) + +(defmethod ig/halt-key! ::reporter + [_ _] + (remove-watch l/log-record ::reporter)) diff --git a/backend/src/app/main.clj b/backend/src/app/main.clj index 86ce7883be..221c20af3a 100644 --- a/backend/src/app/main.clj +++ b/backend/src/app/main.clj @@ -50,7 +50,13 @@ (:gen-class)) (def default-metrics - {:update-file-changes + {:log-events + {::mdef/name "penpot_log_events_total" + ::mdef/help "Log records at WARN, ERROR and FATAL emitted by the application, by logger and level." + ::mdef/labels ["logger" "level"] + ::mdef/type :counter} + + :update-file-changes {::mdef/name "penpot_rpc_update_file_changes_total" ::mdef/help "A total number of changes submitted to update-file." ::mdef/type :counter} @@ -534,6 +540,9 @@ :app.loggers.database/reporter {::db/pool (ig/ref ::db/pool)} + :app.loggers.metrics/reporter + {::mtx/metrics (ig/ref ::mtx/metrics)} + ::sto/storage {::db/pool (ig/ref ::db/pool) ::sto/backends diff --git a/backend/test/backend_tests/helpers.clj b/backend/test/backend_tests/helpers.clj index 89c0d33084..2771470506 100644 --- a/backend/test/backend_tests/helpers.clj +++ b/backend/test/backend_tests/helpers.clj @@ -126,6 +126,7 @@ :app.notifications/handler :app.loggers.mattermost/reporter :app.loggers.database/reporter + :app.loggers.metrics/reporter :app.worker/cron :app.worker/dispatcher [:app.main/default :app.worker/runner] diff --git a/backend/test/backend_tests/loggers_metrics_test.clj b/backend/test/backend_tests/loggers_metrics_test.clj new file mode 100644 index 0000000000..984ad3b0f8 --- /dev/null +++ b/backend/test/backend_tests/loggers_metrics_test.clj @@ -0,0 +1,135 @@ +;; This Source Code Form is subject to the terms of the Mozilla Public +;; License, v. 2.0. If a copy of the MPL was not distributed with this +;; file, You can obtain one at http://mozilla.org/MPL/2.0/. +;; +;; Copyright (c) KALEIDOS INC Sucursal en España SL + +(ns backend-tests.loggers-metrics-test + "The reporter that turns log records into a counter." + (:require + [app.common.logging :as l] + [app.loggers.metrics] ;; registers the integrant methods of the reporter key + [app.main :as main] + [app.metrics :as mtx] + [clojure.test :as t] + [integrant.core :as ig]) + (:import + io.prometheus.client.CollectorRegistry)) + +(def ^:private logger + "The logger of a record is the namespace of the code that logs, and that is + this namespace." + (str *ns*)) + +(defn- init-metrics + [] + (ig/init-key :app.metrics/metrics {:default main/default-metrics})) + +(defn- init-reporter + [metrics] + (ig/init-key :app.loggers.metrics/reporter {::mtx/metrics metrics})) + +(defn- halt-reporter! + [reporter] + (ig/halt-key! :app.loggers.metrics/reporter reporter)) + +(defn- sample + "Value of the counter for one logger and level, read from the registry. Nil + when that combination has never been published." + [metrics logger level] + (.getSampleValue ^CollectorRegistry (mtx/get-registry metrics) + "penpot_log_events_total" + (into-array String ["logger" "level"]) + (into-array String [logger level]))) + +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +;; COUNTING +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; + +(t/deftest warn-and-error-are-counted-by-logger-and-level + (let [metrics (init-metrics) + reporter (init-reporter metrics)] + (try + ;; `:sync?` so the record is emitted on this thread and the assertion + ;; does not depend on the logging executor. + (l/warn :hint "una prueba" ::l/sync? true) + (l/error :hint "otra prueba" ::l/sync? true) + + (t/is (= 1.0 (sample metrics logger "warn"))) + (t/is (= 1.0 (sample metrics logger "error"))) + + (l/error :hint "y otra mas" ::l/sync? true) + (t/is (= 2.0 (sample metrics logger "error"))) + + (finally + (halt-reporter! reporter))))) + +(t/deftest info-is-not-counted + (let [metrics (init-metrics) + reporter (init-reporter metrics)] + (try + (l/info :hint "un mensaje normal" ::l/sync? true) + (t/is (nil? (sample metrics logger "info"))) + + (finally + (halt-reporter! reporter))))) + +(t/deftest fatal-is-counted + (let [metrics (init-metrics) + reporter (init-reporter metrics)] + (try + ;; No macro of the logging emits `:fatal`; this is the only way a record + ;; gets that level. + (l/log :fatal :hint "algo muy malo" ::l/sync? true) + (t/is (= 1.0 (sample metrics logger "fatal"))) + + (finally + (halt-reporter! reporter))))) + +(t/deftest halting-the-reporter-stops-counting + (let [metrics (init-metrics) + reporter (init-reporter metrics)] + + (halt-reporter! reporter) + + (l/error :hint "despues de parar" ::l/sync? true) + (t/is (nil? (sample metrics logger "error"))))) + +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +;; SAFETY +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; + +(t/deftest a-failing-publication-does-not-break-the-logging + ;; The watcher fires from the `swap!` of the log record, inside the logging + ;; path. With `::l/sync?` an exception here would reach whoever was logging; + ;; on the async path it would end in the executor's uncaught handler, which + ;; is outside the application's logging, taking that log line out of Loki and + ;; out of this counter. + (let [metrics (init-metrics) + reporter (init-reporter metrics)] + (try + (with-redefs [mtx/run! (fn [& _] (throw (ex-info "publicando mal" {})))] + (t/is (nil? (l/error :hint "no debe propagar" ::l/sync? true)))) + + (finally + (halt-reporter! reporter))))) + +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +;; DEFINITION +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; + +(t/deftest the-log-events-metric-is-defined + (let [metrics (init-metrics)] + (t/is (= ["logger" "level"] + (:app.metrics.definition/labels (mtx/get-collector metrics :log-events)))))) + +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; +;; WIRING +;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; + +(t/deftest the-system-declares-the-reporter + ;; The reporter hooks itself to the logging, so declaring it in the system is + ;; all the wiring there is. The tests of the suite remove it, so this is the + ;; only place that pins it. + (t/is (= {::mtx/metrics (ig/ref ::mtx/metrics)} + (:app.loggers.metrics/reporter main/system-config))))