Related articles

🍪✈️ The black box of your Rails app: what we monitor on our Fintech platforms

Measuring reliability: the metrics that matter (1/5)
8 minutes
Read the article
The French newsletter for Ruby on Rails developers. Find similar content for free every month in your inbox!
Register
Share:
Blog
>
🍪🪦 Proper logging in Rails: the missing death certificate

🍪🪦 Proper logging in Rails: the missing death certificate

Where does the investigation stand? An outgoing transfer of €15,000 authorized on a Tuesday at 10:13 PM never went through. The client found out the next morning. The confirmation page had appeared, and the database showed the payment stuck in status processing, yet no alert was triggered. We are looking into what happened to that transfer during the night. The only material available: default Rails logs, which are unstructured and decentralized.

When we open these logs to investigate, we find forty lines per request, partial renders, truncated Parameters , and for our transfer, the job being queued at 10:13 PM and executed at 10:39 PM. After that line, there is no trace: no error, no confirmation of completion. The transfer died somewhere in the night without us knowing when or why.

That is the subject of this second article: producing logs that actually tell a story. In the first episode, we chose the indicators to track; before connecting the tools to process them (that will be the third part), we must ensure the raw material is high quality. A log is a testimony written by your application for someone who will read it three months from now, in a bad mood, possibly during an incident. Write for that reader.

This series follows a single incident as a common thread throughout the techniques discussed. The " ⏪ What you would have seen" boxes show the log lines or screens that proper tooling would have produced that night, which never existed due to a lack of preparation. You can skip them: the rest reads as a standalone tutorial.

What to log: events that matter

The common reflex is to log what is easy (HTTP requests, which Rails logs automatically) and forget what is important: business events. A successful login after three failed attempts, an IBAN change, a privilege escalation, a transfer initiated then canceled. These are the events we look for during an incident, and what a regulator or auditor will ask for.

Here is the heuristic I use: if an event should appear in an incident report timeline, it deserves a log line. For a financial application, this covers at a minimum authentication (successes and failures), payment method operations, changes to rights and sensitive data, and administrative actions.

The next step is choosing the level. A poorly chosen level makes logs either silent or deafening.

The log levels classify each message by severity, from the most trivial to the most critical. Rails offers five. debug : debugging details, useful during development. info : routine information, such as current status (connection, transfer initiated). warn : an event that could cause issues (third failed login attempt, slow external call). error : an event that likely caused a problem and requires attention. fatal : the application can no longer function.

In practice, within a controller or 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}")

Two habits in these examples: a bracketed prefix to identify the domain (which makes filtering easy with a simple grep), and key=value pairs rather than sentences. "User 42 initiated transfer 1337" is nice to read once; user_id=42 transfer_id=1337 is easy to search, aggregate, and compare thousands of times.

The debug in production trap

This is the heart of our investigation. In production, we generally run with config.log_level = :info. The direct consequence is that any call to Rails.logger.debug first builds its string, then discards it without writing anything. The message is generated and then simply thrown away.

Note: there is a fix for this waste, which is the block form. Rails.logger.debug { "expensive #{calculation}" } only evaluates its content if the debug level is active, so never in production. This is handy for expensive logs, but be careful: it doesn't change anything regarding our incident. The line remains filtered in both forms; only the level would make it appear.

This is exactly what erased our evidence. The transfer job, upon failing, did this:

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

In development, everything is visible and the code seems flawless. In production, this same message is sent at the debuglevel, which is filtered: the provider's rejection did indeed occur, but no trace of it remains.

You just need to log at a level visible in production. A payment rejection deserves at least a warn, along with the context necessary for the investigation.

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

⏪ What you would have seen With the correct level, this line would have appeared in the logs, timestamped at 10:39 PM: [payments] provider refused transfer_id=8843 code=PAY-503 reason="cut_off_window_closed"The provider closes its transfer submission window at 10:30 PM (standard submission, not instant payment), and the job arrived twenty-six minutes too late. This line never existed. The reader sees it, but the team will never see it.

Key takeaway: choose a log level by asking yourself if someone will need to read it on the night of an incident. If so, debug is not enough.

Errors that aid the investigation

The information that will be missing on the night of the incident is often what a rescue block silently erased. Two tools change the game: a custom error hierarchy and messages that carry their own context.

# 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

The hierarchy allows for precise handling (rescue PaymentError covers the entire family), and the unique, stable error code becomes a cornerstone: it is what we search for in the logs, what we provide to support ("give us the code displayed on the screen"), and what we count to identify recurring anomalies. The message itself carries the identifiers needed for the investigation.

Note: the error code can be shown to the user, but the message never should be as is. "insufficient funds wallet_id=87" informs an attacker about your data model; the screen should instead display "An error occurred" followed by a reference code. The details live in the logs, the reference circulates.

What should not be there, and what we must keep

Let's move on to the touchy subject that takes up a good part of my days as a CISO.

Logs are text files that are copied, aggregated, transmitted to third-party services, kept for months, and read by an entire team. Any data that slips into them bypasses the access controls carefully built into your application. GDPR applies to logs just as it does to the rest of the application. A password or an IBAN that ends up there is, quite simply, a leak.

The blacklist for a financial application: passwords and tokens (obviously), but also emails, IBANs and card numbers, identity documents, addresses, and any health-related or similar data. The best practice is to reference rather than quote: user_id=42 allows you to find everything in the database, where access controls apply, without exposing anyone in the file.

Rails provides the central mechanism: parameter filtering. Anything that matches is replaced by [FILTERED] in request logs.

# 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
]

The first set is generated by default by Rails; it evolves from one version to the next, with the most recent ones adding, for example, :cvv and :cvc. You can supplement this with your own business-specific fields. Matching is done by substring: :passw covers password, password_confirmation and user[password].

Note: this filter only covers request parameters. It does not cover URL paths, filenames, or your own calls to Rails.logger. A GET /documents/8412/download request with a filename like "proof-of-residence-SMITH.pdf" will write that name in plain text in the access logs, outside the filter's reach. The best practice for protection: reference by ID (document_id=8412), never by name. Automatic filtering is a net, not an absolution.

Finally, there is the issue of retention, where two forces pull in opposite directions. GDPR minimization encourages quick deletion, while other regulations, such as DORA or anti-money laundering laws, require keeping enough data for investigations. There is no magic number, then, but rather a trade-off: the CNIL recommendation on logging provides a common balance point of six months to one year for standard technical logs, with anything beyond that requiring justification.

Note (for teams subject to financial regulations): it is often said that "logs must be kept for five years" under AML-CFT requirements. This is a simplification. Article L.561-12 of the Monetary and Financial Code targets the purpose of the data, not the medium: a log that serves as a record of a transaction falls within the five-year scope, whereas a template rendering log does not. The retention period is decided line by line, based on what each one proves, and this trade-off must be documented.

Lograge: machine-readable logs

There remains a formatting problem. Here is what Rails writes by default for a single request in 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 lines per request, which become unreadable as soon as a thousand requests are interleaved. Centralization tools require the opposite: one request, one line, structured fields. This is what Logragedoes, condensing everything into a JSON event:

# 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

And the result:

{
  "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
}

The custom_payload deserves your attention: it is what transforms a technical log into an actionable one. The request_id, generated by Rails for each request, allows you to link all lines of the same request together; add config.log_tags = [:request_id] so that it also appears in your own calls to Rails.logger, and archaeology becomes a simple search. The user_id, for its part, allows us to reconstruct a user's journey. Keep this field in mind: our ability to isolate one account among thousands in the next article will depend on it.

Note: we find in this JSON the knowledge from our first article, duration, db and view. The counters we were tinkering with using a subscriber become simple aggregations on these fields: that is the whole point of a structured format.

Note: by condensing each request onto a single line, Lograge removes partial rendering times in the process. To track a slow view, you will need to use the metrics tools from article 3, not the logs.

The asynchronous black hole: the job lifecycle

Our request logs are now clean. But our transfer didn't die during a request; it died in a Sidekiq job, and that is where the trail went cold. Two problems are hidden there.

A job is a task that the application hands off to the background rather than processing it during the request: it places it in a queue and responds to the user immediately. A separate process, the worker, pulls these jobs from the queue and executes them one by one, separate from web traffic. Sidekiq is the library that plays this role in the Rails ecosystem, by retrying jobs that fail. A job that fails too many times is declared dead and set aside.

The first: the request_id does not cross the asynchronous boundary. The HTTP request that triggers the transfer carries an identifier, but the job that executes it knows nothing about it. We propagate the correlation ID using a middleware, a layer that intercepts every job at the entry and exit points, so that the job inherits the thread of the request that created it:

# 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

The second, more serious in our case: the death of a job leaves no trace by default. Our transfer was retried, then abandoned, in silence. It is essential to master the retry policy, as Sidekiq's default (twenty-five attempts over nearly three weeks) is not suitable for a payment or a time-sensitive operation. We make it explicit and log the abandonment when it occurs:

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

With this configuration, the job attempted at 10:39 PM is retried at 10:59 PM, 11:19 PM, 11:39 PM, and then abandoned shortly before midnight. The sidekiq_retries_exhausted then writes the death certificate we were missing.

The lesson can be summed up in one sentence: the death of a job is a business event; it deserves its own log line rather than a place in a technical queue.

Note (the dead set trap): one might think that Sidekiq's dead set, where dead jobs land, serves as a memory. It is capped, both in number and duration, and evicts the oldest entries when it overflows: a burst of dead jobs wipes out the previous ones. If a legacy configuration once lowered this limit to "save Redis memory," your reserve of evidence is reduced to a window of just a few minutes. That is exactly what ended up erasing our transfer.

⏪ What you would have seen With the death handler in place, a single line would have closed the case, timestamped at 11:59 PM: [payments] transfer job dead transfer_id=8843 code=PAY-503. From the queuing at 10:13 PM until the abandonment, the entire life of the transfer would have fit into a search for transfer_id=8843.

In a nutshell

Effective logging comes down to a few key disciplines: choosing the right events (both business and technical), writing at the appropriate level in a usable format, monitoring what is captured versus what is discarded, and never letting a job fail silently. It is nothing spectacular, but it is precisely the kind of work you only notice the day it is missing.

However, our logs, no matter how clean, just pile up in a file on a server. That doesn't provide quick searches, charts, or alerts. Yet our investigation is now hitting two questions that the transfer alone cannot solve: why did it wait twenty-six minutes before executing, and what were these GET /documents doing in such abnormal volumes at the same time? The next article will move the logs off the server to start crunching the numbers.

— Inès, Information Systems Security Manager at Capsens

Learn more