🍪🪦 Bien logguer dans Rails : le certificat de décès manquant

Bien logguer dans Rails : le certificat de décès manquant (2/5) — Temps de lecture : 8 minutes

sept. 02, 2026

🚨 Cette édition est relativement longue car beaucoup d’image, votre boîte mail risque de la tronquer. Je vous conseille de cliquer sur le titre ci-dessus pour l’ouvrir dans votre navigateur web. ☝️

Hello les petits Biscuits !

Bienvenue sur la 49ème édition de Ruby Biscuit.
Vous êtes maintenant 605 abonnés 🥳

Bonne lecture.

Vous lisez Ruby Biscuit, la newsletter Rails de Capsens. S’abonner gratuitement

Où en est l’enquête ? Un virement sortant de 15 000 € validé un mardi à 22h13 n’est jamais parti. Le client l’apprend le lendemain matin. La page de confirmation s’était affichée, la base montre le paiement figé en statut processing, et aucune alerte n’a sonné. On cherche ce qui est arrivé à ce virement dans la nuit. Seul matériel à disposition : les logs Rails par défaut, non structurés et non centralisés.

Quand on ouvre ces logs pour comprendre, on trouve quarante lignes par requête, des rendus de partials, des Parameters tronqués, et pour notre virement, l’enfilement du job à 22h13 et son exécution à 22h39. Après cette ligne, aucune trace : ni erreur, ni confirmation de fin. Le virement est mort quelque part dans la nuit sans qu’on sache ni quand ni pourquoi.

C’est le sujet de ce deuxième article : produire des logs qui racontent quelque chose. Dans le premier épisode, on a choisi les indicateurs à suivre ; avant de brancher les outils qui les exploiteront (ce sera le troisième), il faut s’assurer que la matière première est bonne. Un log est un témoignage écrit par votre application pour quelqu’un qui la relira dans trois mois, de mauvaise humeur, possiblement un soir d’incident. Écrivez pour ce lecteur-là.

Cette série suit un même incident, en fil rouge, au fil des techniques abordées. Les encadrés « ⏪ Ce que vous auriez vu » montrent les lignes de log ou les écrans que le bon outillage aurait produits cette nuit-là, et qui n’ont jamais existé faute de préparation. Vous pouvez les sauter : le reste se lit comme un tutoriel autonome.

Quoi logguer : les événements qui comptent

Le réflexe courant consiste à logguer ce qui est facile (les requêtes HTTP, que Rails journalise tout seul) et à oublier ce qui est important : les événements métier. Une connexion réussie après trois échecs, un changement d’IBAN, une élévation de droits, un virement initié puis annulé. Ce sont ces événements qu’on cherche pendant un incident, et qu’un régulateur ou un auditeur demandera.

Voici l’heuristique que j’utilise : si un événement devait apparaître dans la chronologie d’un rapport d’incident, il mérite une ligne de log. Pour une application financière, cela couvre au minimum l’authentification (succès et échecs), les opérations sur les moyens de paiement, les changements de droits et de données sensibles, et les actions d’administration.

Reste à choisir le niveau. Un niveau mal choisi rend les logs soit muets, soit assourdissants.

Les niveaux de log classent chaque message par gravité, du plus anodin au plus grave. Rails en propose cinq. debug : le détail de mise au point, utile en développement. info : une information de routine, comme un état courant (connexion, virement initié). warn : un événement qui pourrait poser problème (troisième échec de connexion, appel externe lent). error : un événement qui a probablement causé un problème et sur lequel quelqu’un doit se pencher. fatal : l’application ne peut plus fonctionner.

En pratique, dans un contrôleur ou un service :

Rails.logger.info("[payments] transfer initiated user_id=#{current_user.id} transfer_id=#{transfer.id} amount_cents=#{transfer.amount_cents}")
Rails.logger.warn("[auth] failed login attempt=3 user_id=#{user.id}")

Deux habitudes dans ces exemples : un préfixe entre crochets qui identifie le domaine (on filtre ensuite d’un simple grep), et des paires clé=valeur plutôt que des phrases. « L’utilisateur 42 a initié le virement 1337 » est agréable à lire une fois ; user_id=42 transfer_id=1337 se recherche, s’agrège et se compare des milliers de fois.

Le piège du `debug` en production

Voici le cœur de notre enquête. En production, on tourne généralement avec config.log_level = :info. Conséquence directe : tout appel à Rails.logger.debug construit d’abord sa chaîne de caractères, puis la jette sans rien écrire. Le message est produit, puis simplement jeté.

Note : ce gaspillage a un remède, la forme à bloc. Rails.logger.debug { "coûteux #{calcul}" } n’évalue son contenu que si le niveau debug est actif, donc jamais en production. Pratique pour les logs coûteux, mais attention : cela ne change rien à notre incident. La ligne reste filtrée dans les deux formes, seul le niveau la ferait apparaître.

C’est exactement ce qui a effacé notre preuve. Le job de virement, en échouant, faisait ceci :

def perform(transfer_id)
  transfer = Transfer.find(transfer_id)
  PaymentProvider.execute!(transfer)
rescue PaymentProvider::Error => e
  Rails.logger.debug("[payments] provider refused transfer_id=#{transfer_id} #{e.message}")
  raise # on relance pour laisser Sidekiq gérer le réessai
end

En développement, tout se voit et le code paraît irréprochable. En production, ce même message part au niveau debug, qui est filtré : le rejet du prestataire a bien eu lieu, mais il n’en reste aucune trace.

Il suffit de logguer à un niveau visible en production. Un rejet de paiement mérite au moins un warn, avec le contexte nécessaire à l’enquête.

rescue PaymentProvider::Error => e
  Rails.logger.warn("[payments] provider refused transfer_id=#{transfer_id} code=#{e.code} reason=#{e.reason}")
  raise
end

⏪ Ce que vous auriez vu Avec le bon niveau, cette ligne serait apparue dans les logs, horodatée à 22h39 : [payments] provider refused transfer_id=8843 code=PAY-503 reason="cut_off_window_closed". Le prestataire clôture sa fenêtre de remise des virements à 22h30 (remise classique, pas d’instant payment), et le job s’est présenté vingt-six minutes trop tard. Cette ligne n’a jamais existé. Le lecteur la voit, l’équipe ne la verra jamais.

À retenir : choisissez le niveau d’un log en vous demandant si quelqu’un aura besoin de le lire un soir d’incident. Si oui, debug ne suffit pas.

Des erreurs qui aident l’enquête

L’information qui manquera le soir de l’incident, c’est souvent un rescue silencieux qui l’a effacée. Deux outils changent la donne : une hiérarchie d’erreurs à vous, et des messages qui embarquent leur contexte.

# app/errors/payment_error.rb
class PaymentError < StandardError
  def initialize(msg = nil, code: "PAY-000")
    @code = code
    super(msg)
  end
  attr_reader :code
end

class InsufficientFundsError < PaymentError
  def initialize(wallet_id:, requested_cents:)
    super("insufficient funds wallet_id=#{wallet_id} requested_cents=#{requested_cents}", code: "PAY-012")
  end
end

La hiérarchie permet de rattraper finement (rescue PaymentError couvre toute la famille) et le code d’erreur, unique et stable, devient une clé de voûte : c’est lui qu’on cherche dans les logs, lui qu’on met dans la réponse au support (« donnez-nous le code affiché à l’écran »), lui qu’on compte pour repérer une anomalie récurrente. Le message, lui, embarque les identifiants nécessaires à l’enquête.

Note : le code d’erreur peut être montré à l’utilisateur, le message jamais tel quel. « insufficient funds wallet_id=87 » renseigne un attaquant sur votre modèle de données ; l’écran affichera plutôt « Une erreur est survenue » suivie d’un code de référence. Le détail vit dans les logs, la référence circule.

Ce qui ne doit pas s’y trouver, et ce qu’on doit garder

Passons au sujet qui fâche, et qui occupe une bonne partie de mes journées de RSSI.

Les logs sont des fichiers texte copiés, agrégés, transmis à des services tiers, conservés des mois et lus par toute une équipe. Toute donnée qui s’y glisse échappe au contrôle d’accès soigneusement construit dans votre application. Le RGPD s’applique aux logs comme au reste de l’application. Un mot de passe ou un IBAN qui s’y retrouve est une fuite, tout simplement.

La liste noire pour une application financière : mots de passe et tokens (évidemment), mais aussi emails, IBAN et numéros de carte, documents d’identité, adresses, et toute donnée de santé ou assimilée. La bonne pratique consiste à référencer plutôt que citer : user_id=42 permet de tout retrouver en base, où les contrôles d’accès s’appliquent, sans exposer qui que ce soit dans le fichier.

Rails fournit le mécanisme central : le filtrage des paramètres. Tout ce qui matche est remplacé par [FILTERED] dans les logs de requêtes.

# config/initializers/filter_parameter_logging.rb
Rails.application.config.filter_parameters += [
  # valeurs générées par défaut par Rails (la liste s'étoffe selon la version)
  :passw, :email, :secret, :token, :_key, :crypt, :salt, :certificate, :otp, :ssn, :cvv, :cvc,
  # ajouts propres à une application financière
  :iban, :bic, :card
]

La première série est générée par défaut par Rails ; elle évolue d’une version à l’autre, les plus récentes ajoutant par exemple :cvv et :cvc. On la complète avec les champs propres à son métier. Le matching se fait par sous-chaîne : :passw couvre password, password_confirmation et user[password].

Note : ce filtre couvre les paramètres de requêtes, et rien d’autre. Ni les chemins d’URL, ni les noms de fichiers, ni vos propres appels à Rails.logger. Un GET /documents/8412/download dont le nom de fichier est « justificatif-domicile-DUPONT.pdf » écrit ce nom en clair dans les access logs, hors de portée du filtre. Le réflexe qui protège : référencer par identifiant (document_id=8412), jamais par nom. Le filtrage automatique est un filet, pas une absolution.

Dernier point, la conservation, où deux forces tirent en sens inverse. La minimisation du RGPD pousse à effacer vite ; d’autres textes, comme DORA ou la lutte contre le blanchiment, imposent de garder de quoi enquêter. Pas de chiffre magique, donc, mais un arbitrage : la recommandation de la CNIL sur la journalisation donne un point d’équilibre courant de six mois à un an pour les journaux techniques ordinaires, au-delà seulement avec une justification.

Note (pour les équipes soumises à la finance réglementée) : on lit souvent que « les logs se conservent cinq ans » au titre de la LCB-FT. C’est un raccourci. L’article L.561-12 du code monétaire et financier vise la finalité de la donnée, pas son support : un journal qui constitue la trace d’une opération entre dans le périmètre des cinq ans, un log de rendu de template n’y entre pas. La durée se décide ligne par ligne, selon ce que chacune prouve, et cet arbitrage se documente.

Lograge : des logs qui se traitent en machine

Il reste un problème de forme. Voici ce que Rails écrit par défaut pour une seule requête en production :

Started GET "/transfers/1337" for 203.0.113.7 at 2026-08-05 22:13:41 +0200
Processing by TransfersController#show as HTML
  Parameters: {"id"=>"1337"}
  Rendered transfers/_summary.html.erb (Duration: 1.2ms)
  Rendered transfers/show.html.erb within layouts/application (Duration: 12.1ms)
Completed 200 OK in 89ms (Views: 32.1ms | ActiveRecord: 41.2ms)

Six lignes par requête, illisibles dès que mille requêtes s’entremêlent. Les outils de centralisation veulent l’inverse : une requête, une ligne, des champs structurés. C’est ce que fait Lograge, qui condense le tout en un événement JSON :

# config/initializers/lograge.rb
Rails.application.configure do
  config.lograge.enabled = true
  config.lograge.formatter = Lograge::Formatters::Json.new

  config.lograge.custom_payload do |controller|
    {
      request_id: controller.request.request_id,
      user_id: controller.respond_to?(:current_user) ? controller.current_user&.id : nil
    }
  end
end

Et le résultat :

{
  "method":"GET",
  "path":"/transfers/1337",
  "status":200,
  "duration":89.0,
  "db":41.2,
  "view":32.1,
  "controller":"TransfersController",
  "action":"show",
  "request_id":"9f80b7...",
  "user_id":42
}

Le custom_payload mérite votre attention : c’est lui qui transforme un log technique en log exploitable. Le request_id, généré par Rails pour chaque requête, permet de relier entre elles toutes les lignes d’une même requête ; ajoutez config.log_tags = [:request_id] pour qu’il apparaisse aussi sur vos propres appels à Rails.logger, et l’archéologie devient une simple recherche. Le user_id, lui, permet de reconstituer le parcours d’un utilisateur. Retenez ce champ : c’est de lui que dépendra, au prochain article, notre capacité à isoler un compte parmi des milliers.

Note : on retrouve dans ce JSON nos connaissances du premier article, duration, db et view. Les compteurs qu’on y bricolait avec un subscriber deviennent de simples agrégations sur ces champs : c’est tout l’intérêt d’un format structuré.

Note : en condensant chaque requête sur une ligne, Lograge retire au passage les temps de rendu par partial. Pour traquer une vue lente, ce sera dans l’outillage de métriques de l’article 3, plus dans les logs.

Le trou noir asynchrone : le cycle de vie des jobs

Nos logs de requêtes sont maintenant propres. Mais notre virement n’est pas mort dans une requête, il est mort dans un job Sidekiq, et c’est là que la piste s’était interrompue. Deux problèmes s’y cachent.

Un job est une tâche que l’application confie à l’arrière-plan plutôt que de la traiter pendant la requête : elle la dépose dans une file d’attente et répond aussitôt à l’utilisateur. Un processus séparé, le worker, dépile ces jobs et les exécute un à un, à part du trafic web. Sidekiq est la bibliothèque qui joue ce rôle dans l’écosystème Rails, en réessayant les jobs qui échouent. Un job qui échoue trop de fois est déclaré mort et mis de côté.

Le premier : le request_id ne franchit pas la frontière asynchrone. La requête HTTP qui déclenche le virement porte un identifiant, le job qui l’exécute n’en sait rien. On propage l’identifiant de corrélation avec un middleware, une couche qui intercepte chaque job à l’entrée et à la sortie, pour que le job hérite du fil de la requête qui l’a créé :

# config/initializers/sidekiq.rb
class CorrelationClientMiddleware
  def call(_worker, job, _queue, _redis)
    job["correlation_id"] ||= RequestStore.store[:request_id]
    yield
  end
end

class CorrelationServerMiddleware
  def call(_worker, job, _queue)
    RequestStore.store[:request_id] = job["correlation_id"]
    yield
  end
end

Le second, plus grave dans notre cas : la mort d’un job ne laisse aucune trace par défaut. Notre virement a été réessayé, puis abandonné, en silence. Encore faut-il maîtriser la politique de réessai, car le défaut de Sidekiq (vingt-cinq tentatives sur près de trois semaines) ne convient ni à un paiement ni à une opération à fenêtre. On la rend explicite, et on journalise l’abandon quand il survient :

class TransferJob
  include Sidekiq::Job
  sidekiq_options queue: :default, retry: 4

  # quatre réessais espacés de 20 minutes : on laisse au prestataire
  # le temps de se rétablir, sans traîner au-delà du raisonnable
  sidekiq_retry_in { |_count, _exception| 20.minutes.to_i }

  sidekiq_retries_exhausted do |job, exception|
    Rails.logger.error(
      "[payments] transfer job dead transfer_id=#{job['args'].first} " \
      "code=#{exception.respond_to?(:code) ? exception.code : 'unknown'}"
    )
  end

  def perform(transfer_id)
    # ...
  end
end

Avec cette configuration, le job tenté à 22h39 est repris à 22h59, 23h19, 23h39, puis abandonné peu avant minuit. Le sidekiq_retries_exhausted écrit alors le certificat de décès qui nous manquait.

La leçon tient en une phrase : la mort d’un job est un événement métier, elle mérite sa propre ligne de log plutôt qu’une place dans une file technique.

Note (le piège du dead set) : on pourrait croire que le dead set de Sidekiq, où atterrissent les jobs morts, tient lieu de mémoire. Il est plafonné, en nombre comme en durée, et évince les plus anciens quand il déborde : une rafale de jobs morts efface les précédents. Si une configuration héritée a un jour abaissé ce plafond pour « économiser la mémoire Redis », votre réserve de preuves se réduit à une fenêtre de quelques minutes. C’est exactement ce qui a fini d’effacer notre virement.

⏪ Ce que vous auriez vu Avec le death handler en place, une seule ligne aurait clos l’affaire, horodatée à 23h59 : [payments] transfer job dead transfer_id=8843 code=PAY-503. De l’enfilement à 22h13 jusqu’à l’abandon, la vie entière du virement aurait tenu dans une recherche sur transfer_id=8843.

En deux mots

Bien logguer tient en quelques disciplines : choisir les événements (le métier autant que la technique), écrire au bon niveau et sous forme exploitable, surveiller ce qui s’échappe et ce qu’on garde, et ne jamais laisser un job mourir sans un mot. Rien de spectaculaire, et c’est précisément le genre de travail qu’on remarque seulement le jour où il manque.

Reste que nos logs, aussi propres soient-ils, s’accumulent dans un fichier sur un serveur. Cela ne fait ni une recherche rapide, ni une courbe, ni une alerte. Or notre enquête bute maintenant sur deux questions que le virement seul ne peut pas résoudre : pourquoi a-t-il attendu vingt-six minutes avant de s’exécuter, et que faisaient ces GET /documents en volume anormal au même moment ? Le prochain article sort les logs du serveur pour commencer à compter.

— Inès, Responsable de la Sécurité des Systèmes d’Information chez Capsens

Pour aller plus loin

Niveaux de gravité des logs : table LogSeverity, Google Cloud Logging
Jobs, files d’attente et workers : Background Jobs & Queueing, Heroku Dev Center
Sidekiq : documentation officielle et wiki sur la gestion des erreurs
Lograge : dépôt et README
Filtrage des paramètres : ActionDispatch::Http::FilterParameters, API Rails
Conservation des journaux : recommandation de la CNIL sur la journalisation
Journalisation sous DORA : article 12 du règlement délégué (UE) 2024/1774
Conservation LCB-FT : article L.561-12 du code monétaire et financier

Si cet article vous a été utile, partagez-le à un(e) collègue.

Ruby Biscuit

Discussion à propos de ce post

Tout à fait prêt. Qu'avez-vous pour moi ?

Ruby Biscuit

🍪🪦 Bien logguer dans Rails : le certificat de décès manquant