Aller au contenu

Runbook — Observabilité (logs + métriques)

Où regarder quand quelque chose casse, et comment la chaîne est câblée. Contexte : issue #155. Le tracing distribué est hors périmètre — voir #509.


La chaîne en une phrase

L'API écrit des logs JSON sur stdout et dans des fichiers tournants sur un volume monté, et expose des métriques Prometheus sur un port interne ; un conteneur Grafana Alloy par serveur scrape ce port et pousse les séries vers Grafana Cloud.

  API ──stdout (JSON) ───────────> visionneuse de logs de la plateforme (live, éphémère)
   ├──/app/logs/*.log (monté) ───> copie durable, sur la machine
   └──:9464/metrics ─────────────> Alloy ──> Grafana Cloud (Prometheus)

Les logs ne quittent jamais la machine. Pas de Loki, pas d'expédition externe : la rédaction des secrets est un filet best-effort basé sur les noms de clés, et une donnée client partie chez un tiers ne se rattrape pas. Alloy ne transporte que des métriques.

Prometheus et Grafana ne sont pas auto-hébergés. La production est une machine à 2 vCPU / 4 Go qui fait déjà tourner l'API, Postgres, Redis et Garage : une TSDB locale plus Grafana n'y tiennent pas. Alloy est plafonné à 256 Mo.


Séparer beta et production

Le forfait gratuit Grafana Cloud ne donne qu'une seule stack (plusieurs stacks sont payantes). Les deux environnements y coexistent, séparés par un label env posé par Alloy via GRAFANA_CLOUD_ENVl'application ne sait pas dans quel environnement elle tourne.

  • Dashboards : variable $env.
  • Logs : rien à séparer — ils restent sur la machine qui les a produits, donc l'environnement est celui de la machine où vous les lisez.
  • Alertes : toujours filtrées sur env="production". Ce n'est pas optionnel. deploy.yml vide et re-seed la base de beta à chaque merge sur dev : beta produit donc des pics d'erreurs et des coupures par construction. Une règle non filtrée alerterait à chaque merge, serait coupée en une semaine, et emporterait les vraies alertes avec elle.

Budget de séries

Le forfait gratuit plafonne à 10 000 séries actives, partagées entre les deux environnements. Le dépôt compte 229 routes, donc un histogramme labellisé par route coûte à lui seul ~2 500 séries.

profil séries
production full ~4 240 + 1 par workspace
beta minimal ~1 550

METRICS_PROFILE=minimal réduit le label route à la constante all sur l'histogramme de latence et sur db_queries_by_route_total, et n'enregistre pas du tout le compteur par workspace. Sur beta ce dernier point est une correction, pas une économie : le wipe régénère tous les ULID de workspace à chaque déploiement, donc le compteur accumulerait un jeu de séries mortes à chaque déploiement.

Avant d'ajouter un histogramme labellisé par route, vérifiez le budget.


Logs

Chaque ligne est du JSON portant service, env, release, level, message, plus le contexte de requête (requestId, userId, workspaceId) ou de job (jobId, jobName).

Où ils sont

Live La visionneuse de logs de la plateforme lit stdout. Pratique, mais c'est un tampon : il ne survit pas au redéploiement.
Durable /app/logs/combined.log et /app/logs/error.log dans le conteneur, montés sur un répertoire de l'hôte.

Le Dockerfile fixe LOG_FILE_DIR=/app/logs et LOG_FORMAT=json : l'image déclare sa propre posture de log au lieu de la déduire de NODE_ENV, qu'un déploiement peut oublier de poser. Ce chemin doit être un volume monté. Sans montage, les fichiers meurent avec le conteneur et remplissent sa couche inscriptible au passage — le pire des deux mondes.

Vérifier le montage avant de compter dessus :

docker inspect <conteneur> --format '{{range .Mounts}}{{.Destination}} <- {{.Source}}{{"\n"}}{{end}}'
# doit lister /app/logs

Les fichiers sont bornés : LOG_MAX_SIZE_BYTES (10 Mo) x LOG_MAX_FILES (5), par fichier, soit ~100 Mo au pire pour les deux. C'est ce qui évite le retour du combined.log de 194 Mo qu'avait produit l'absence de rotation.

Les lire

# une requête de bout en bout
grep '01M0HWYM62KBA4J8R47QDVWGEK' /app/logs/combined.log | jq .

# les erreurs du jour
jq -c 'select(.level=="error")' /app/logs/error.log

# les requêtes lentes
jq -c 'select(.durationMs > 1000) | {route, durationMs, requestId}' /app/logs/combined.log

Le requestId vient de l'en-tête X-Request-Id quand Traefik en fournit un, sinon d'un ULID généré, et il est renvoyé dans la réponse — un utilisateur peut donc le citer dans un rapport de bug.

Niveaux

  • info — transition d'état métier (paiement encaissé, escrow libéré, KYC approuvé, payout envoyé, utilisateur suspendu) et une ligne d'accès par requête HTTP.
  • debug — no-ops, gardes d'idempotence, ticks de sweeper, éditions de profil courantes.
  • warn / error — anomalies. Un 5xx est loggué en error ; un 4xx reste en info (faute du client, pas un incident).

Production tourne en info, beta en debug.

Jamais dans les logs

Aucun identifiant de connexion, aucune adresse e-mail. Un format de rédaction masque toute valeur dont la clé ressemble à un secret (token, secret, password, authorization, api_key, signature, cookie, dsn) — filet de sécurité, pas un permis de logguer. Les notifications logguent userId ; la waitlist, qui précède tout compte, ne logue que le domaine de l'adresse. Les requêtes SQL lentes sont empreintées (littéraux retirés) parce que Sequelize inline les valeurs échappées dans l'instruction.


Métriques

Port interne, jamais publié : il n'a aucune authentification et Traefik n'expose que le port de l'app. Vérification depuis le réseau interne :

docker exec -it <alloy> wget -qO- http://web:9464/metrics | head
Métrique Sert à répondre à
http_requests_total{method,route,status} trafic, taux d'erreur par route
http_request_duration_seconds{method,route} p50/p95/p99 par route
http_requests_by_workspace_total{workspace_id} quel tenant sature l'API
db_queries_by_route_total{route} ÷ http_requests_total = requêtes par requête → N+1
db_slow_queries_total{operation} requêtes au-delà de DB_SLOW_QUERY_MS
queue_jobs_total{job_name,outcome} débit et taux d'échec des jobs
queue_depth{state} le worker suit-il ?
external_adapter_calls_total{adapter,operation,outcome} Moneroo / Garage / SMTP lents ou en erreur

Le label route est toujours le gabarit (/api/leads/:id), jamais l'URL brute : les chemins portent des ULID. Une requête qui ne matche aucune route est comptée sous unmatched.

Détecter un N+1

rate(db_queries_by_route_total{env="production"}[5m])
  / on(route) rate(http_requests_total{env="production"}[5m])

Alertes

Configurées dans Grafana Cloud, toutes filtrées sur env="production" :

Alerte Seuil
Taux d'erreur par route > 1 % sur 5 min
Latence p95 par route > 1 s sur 5 min
Profondeur de file > 1000
Taux d'échec des jobs > 5 % sur 5 min
Erreurs adaptateur > 5 % sur 5 min par (adapter, operation)
Erreurs stockage > 2 % sur 5 min par operation
Event loop lag p99 > 200 ms

Configuration Coolify (action opérateur)

À faire une fois, dans l'UI — rien de tout cela n'est versionné :

  1. Sondes de santé. Sur backend-beta et backend-production : health_check_path = /api/health/ready, puis activer health_check_enabled. #154 a livré les endpoints mais la porte de déploiement Coolify n'a jamais été pointée dessus ; aujourd'hui la santé du conteneur ne vient que du HEALTHCHECK du Dockerfile.
  2. LOG_LEVELinfo en production, debug sur beta. Puis supprimer VERBOSE : logger.ts le lit encore par compatibilité, mais un seul bouton nommé pour ce qu'il fait vaut mieux que deux.
  3. METRICS_PROFILEfull en production, minimal sur beta.
  4. Déployer Alloy sur chaque serveur, en service Coolify séparé. Les applis backend sont en build_pack: dockerimage : Coolify tire une image et n'utilise pas le docker-compose.yml du dépôt. Ce fichier est donc la définition de référence à recopier — image, montage read-only de observability/alloy/config.alloy et du socket Docker, mem_limit, aucun port publié. Renseigner les secrets GRAFANA_CLOUD_*, avec GRAFANA_CLOUD_ENV à production ou beta selon le serveur.
  5. Label ikloze.metrics=true sur les conteneurs backend : Alloy filtre là-dessus pour ne pas scraper les autres projets hébergés sur la même machine.
  6. Ne jamais publier METRICS_PORT.

SENTRY_RELEASE n'est pas à configurer ici : Coolify déploie une image pré-construite et ne build jamais, donc la release est gravée dans l'image au build par deploy.yml (build-args: SENTRY_RELEASE=${{ github.sha }}). Une variable Coolify devrait être éditée à la main à chaque déploiement.


Mesurer le coût de l'instrumentation

scripts/bench-paired.mjs compare deux builds de l'API tournant côte à côte, chargés en alternance stricte, et rapporte le temps CPU par requête lu dans /proc. Le mode d'emploi complet est en tête du fichier.

Pourquoi cette forme : mesurer un build puis l'autre ne marche pas. Sur une machine de dev, deux mesures du même build ont varié de 5 à 18 ms — bien plus que l'effet cherché. L'alternance fait porter la dérive (thermique, fréquence CPU, autres process) sur les deux bras dans la même fenêtre de quelques secondes, et elle s'annule dans la différence appariée. Le CPU est retenu plutôt que le temps mur parce qu'il est ~100× moins bruité et que c'est lui qui décide combien de requêtes une machine à 2 vCPU peut servir.

Deux pièges vérifiés à la dure :

  • Rediriger stdout vers un fichier fausse la mesure d'un facteur ~4. Node écrit synchronement dans un fichier et bloque la boucle d'événements à chaque ligne. En conteneur stdout est un tube, donc asynchrone. Toujours mesurer avec | cat, jamais > fichier.
  • Un microbenchmark de la même ligne de log la donne ~10× moins chère qu'en conditions réelles : une boucle serrée laisse V8 optimiser la pression d'allocation qu'un vrai chemin de requête subit. Se fier à la mesure appariée, pas au microbenchmark.

Mesures obtenues sur un portable (bruyant — à refaire sur beta pour un chiffre net) :

Route delta CPU latence coût relatif
/api/health/live (trivial) +76 à +228 µs selon la campagne +0,06 à +0,10 ms grand % d'un tout petit chiffre
/api/projects (authentifié, ~16 ms) +810 µs (IC ±648) +0,59 ms +5,2 % CPU, +3,6 % latence
/api/health/live, access log coupé +31 µs (IC ±129) −0,01 ms indiscernable de zéro

Lecture : le coût est essentiellement la ligne d'access log. Le contexte ALS, les métriques et les hooks Sequelize ne se mesurent pas. Comme le coût est à peu près constant par requête, il pèse lourd en pourcentage sur une route triviale et peu sur une vraie route.

Si ce coût devenait gênant, le levier est l'access log : l'échantillonner (tous les 4xx/5xx, 1 sur N pour les 2xx) ou passer à pino. LOG_LEVEL=warn le coupe déjà à chaud, sans rollback — mais fait taire aussi les événements métier.


Diagnostic

/metrics ne répond pas. L'API démarre quand même : un port de métriques qui ne bind pas ne doit jamais faire tomber l'API, l'échec est loggué (metrics: listener failed) et rien d'autre. Cherchez un port déjà pris.

Aucune série n'arrive dans Grafana Cloud. Le conteneur porte-t-il le label ikloze.metrics=true ? Alloy filtre là-dessus, précisément pour ne pas scraper les autres projets hébergés sur la même machine.

queue_depth est figé. La lecture parle à Redis ; en cas d'échec elle est avalée avec un warn (metrics: queue depth read failed) plutôt que de faire échouer tout le scrape et marquer la cible down, ce qui masquerait toutes les autres métriques.

Un job échoue sans rien dans Sentry. Le worker tourne hors requête, donc rien ne passe par SentryGlobalFilter : c'est recordFailedJob qui appelle captureException avec un tag job. Si l'événement manque, vérifiez SENTRY_DSN.