Rails Logging Waar Je Daadwerkelijk Mee Kunt Debuggen

Vorige maand werd ik om 23:00 uur bij een productie-incident getrokken. Gebruikers konden niet afrekenen. De fout zat ergens in een request-cyclus van 200 regels die drie services, twee queues en een betaalgateway raakte. Ik opende de logs en vond dit:

Started POST "/orders" for 10.0.1.52 at 2026-01-14 23:02:17 +0100
Processing by OrdersController#create as HTML
  Parameters: {"order"=>{"product_id"=>"482", "quantity"=>"1"}, "commit"=>"Place Order"}
  User Load (0.4ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1
  Product Load (0.3ms)  SELECT "products".* FROM "products" WHERE "products"."id" = $1
  TRANSACTION (0.1ms)  BEGIN
  Order Create (0.6ms)  INSERT INTO "orders" ...
  TRANSACTION (0.2ms)  COMMIT
Completed 500 Internal Server Error in 3241ms

Drie seconden wall time. Tientallen SQL-regels. Geen idee wat er feitelijk misging. De stacktrace wees naar een Stripe-aanroep, maar welke? Met welke parameters? Wat was het antwoord?

Dit is waar de meeste Rails-apps leven: alles loggen en niets communiceren.

Het Probleem met Standaard Rails Logs

Rails wordt geleverd met ActiveSupport::Logger, geconfigureerd om behulpzaam te zijn tijdens development. Elke SQL-query, elke parameter-hash, elke gerenderde partial — alles gedumpt naar de log. Tijdens development is dat prima. Je bekijkt één request tegelijk.

In productie, met vijftig requests per seconde, worden die meerregelige entries ruis. Je kunt er niet betrouwbaar doorheen greppen. Je kunt ze niet naar een log-aggregator pipen zonder parsing-problemen. En je kunt al helemaal niet een gefaald request correleren met je achtergrondtaken en externe service-aanroepen.

Stap Één: Lograge

Lograge condenseert elk request tot één regel. Eén request, één log-entry.

# Gemfile
gem 'lograge'

# config/environments/production.rb
config.lograge.enabled = true
config.lograge.formatter = Lograge::Formatters::Json.new

Nu wordt die puinhoop van 12 regels:

{"method":"POST","path":"/orders","format":"html","controller":"OrdersController","action":"create","status":500,"duration":3241.08,"db":1.6,"view":0.0}

Eén regel. Parseerbaar. Grepbaar. Maar nog steeds zonder context. Wie was deze gebruiker? Welke order? Dat lossen we op.

Bedrijfscontext Toevoegen

Lograge laat je extra data toevoegen via custom_options:

# config/initializers/lograge.rb
Rails.application.configure do
  config.lograge.custom_options = lambda do |event|
    exceptions = %w[controller action format id]
    {
      params: event.payload[:params]
                    .except(*exceptions)
                    .reject { |_, v| v.blank? },
      user_id: event.payload[:user_id],
      request_id: event.payload[:request_id]
    }
  end
end

En in je ApplicationController:

class ApplicationController < ActionController::Base
  def append_info_to_payload(payload)
    super
    payload[:user_id] = current_user&.id
    payload[:request_id] = request.request_id
  end
end

Nu draagt elke logregel het user ID en een request ID dat je kunt traceren door je hele stack.

Stap Twee: Semantic Logger voor Al het Andere

Lograge regelt request-logs. Maar je applicatie logt ook buiten de request-cyclus — in achtergrondtaken, rake tasks, service-objecten. Daarvoor geeft rails_semantic_logger je gestructureerde output overal.

# Gemfile
gem 'rails_semantic_logger'

# config/environments/production.rb
config.log_level = :info
config.rails_semantic_logger.format = :json
config.semantic_logger.add_appender(
  io: $stdout,
  formatter: :json
)

Dan in je code:

class PaymentService
  include SemanticLogger::Loggable

  def charge(order)
    logger.info("Charging customer", order_id: order.id, amount: order.total, currency: "EUR")

    response = Stripe::Charge.create(
      amount: order.total_cents,
      currency: 'eur',
      customer: order.user.stripe_customer_id
    )

    logger.info("Charge succeeded", order_id: order.id, charge_id: response.id)
    response
  rescue Stripe::CardError => e
    logger.error("Charge failed", order_id: order.id, error: e.message, code: e.code)
    raise
  end
end

Elke log-aanroep produceert een JSON-regel met timestamps, logniveau, classnaam en je eigen velden. Wanneer de telefoon om 23:00 gaat, zoek je op order_id: 9482 en zie je elke stap die die order nam — van controller tot service tot achtergrondtaak.

Request ID Propagatie

De X-Request-Id header is je beste vriend. Rails genereert er automatisch een, of je kunt er een meegeven vanuit je load balancer. De sleutel is het overal meenemen.

# Propageren naar achtergrondtaken
class ApplicationJob < ActiveJob::Base
  around_perform do |job, block|
    SemanticLogger.tagged(request_id: job.arguments.last[:request_id]) do
      block.call
    end
  end
end

# Propageren naar HTTP-aanroepen
class ApiClient
  def get(url, request_id:)
    HTTP.headers("X-Request-Id" => request_id).get(url)
  end
end

Eén request ID, traceerbaar van de browser van de gebruiker door je hele stack. Als iets kapotgaat, zoek je op dat ID en krijg je het complete verhaal.

Wat Log Je Wel, Wat Niet

Structured logging verleidt je om alles te loggen. Weersta die verleiding. Elke logregel kost opslag, verwerking en aandacht.

Wel loggen:

• Business events (order geplaatst, betaling verwerkt, gebruiker aangemeld)
• Fouten met volledige context (wat werd geprobeerd, wat mislukte, wat de input was)
• Externe service-aanroepen met duur en response-status
• State-transities (order pending → bevestigd → verzonden)
• Feature flag evaluaties naast request-context, zodat je weet welk codepad een gebruiker nam

Niet loggen:

• SQL-queries (je APM-tool doet dit beter)
• Succesvolle cache hits (te luidruchtig, te frequent)
• Request-parameters die dupliceren wat Lograge al vastlegt
• Alles met PII die je niet nodig hebt voor debugging

Een goede vuistregel: als je het om 23:00 zou willen zien tijdens het debuggen, log het. Als je er voorbij zou scrollen, doe het niet.

De Logniveaus die Niemand Goed Gebruikt

De meeste codebases behandelen logniveaus als binair: info voor gewone dingen, error voor slechte dingen. De tussenliggende niveaus bestaan met een reden.

• debug: Alleen development. SQL, cache-details, variabele-dumps.
• info: Business events. Dingen die gebeurd zijn en ertoe doen.
• warn: Iets onverwachts maar afgehandeld. Een retry die slaagde. Een fallback die aansloeg. Een deprecation die je moet fixen voordat het breekt.
• error: Iets is mislukt en een gebruiker of proces werd geraakt.
• fatal: De applicatie gaat onderuit.

Het warn-niveau wordt bijzonder weinig gebruikt. Het is je vroege waarschuwingssysteem — de kanarie-logs die je vertellen dat iets verslechtert voordat het daadwerkelijk faalt.

if retries > 0
  logger.warn("Payment retry succeeded", order_id: order.id, retries: retries, duration_ms: elapsed)
else
  logger.info("Payment succeeded", order_id: order.id, duration_ms: elapsed)
end

Alles Samenbrengen

Dit is de productie-setup die ik gebruik voor de meeste Rails-apps van klanten:

# Gemfile
gem 'lograge'
gem 'rails_semantic_logger'

# config/environments/production.rb
config.lograge.enabled = true
config.lograge.formatter = Lograge::Formatters::Json.new
config.lograge.custom_options = lambda do |event|
  {
    user_id: event.payload[:user_id],
    request_id: event.payload[:request_id],
    host: event.payload[:host]
  }
end

config.log_level = :info
config.rails_semantic_logger.format = :json

Pipe stdout naar je log-aggregator naar keuze — CloudWatch, Datadog, Loki, zelfs een self-hosted ELK-stack. Het JSON-formaat betekent geen custom parsers, geen grok-patronen, geen regex-nachtmerries.

De Debug-sessie, Herzien

Met deze setup verloopt dat incident om 23:00 anders. Ik zoek op het request ID van de falende gebruiker. Ik krijg een tijdlijn:

{"level":"info","name":"OrdersController","message":"Creating order","user_id":891,"request_id":"abc-123"}
{"level":"info","name":"PaymentService","message":"Charging customer","order_id":9482,"amount":89.99,"request_id":"abc-123"}
{"level":"error","name":"PaymentService","message":"Charge failed","order_id":9482,"error":"Your card was declined","code":"card_declined","request_id":"abc-123"}

Drie regels. Compleet verhaal. De kaart werd geweigerd, de foutafhandeling in de controller was niet netjes, en de gebruiker kreeg een 500 in plaats van een behulpzaam bericht. Foutafhandeling fixen, deployen, terug naar bed.

Dat is wat logging moet doen. Niet elke SQL-query documenteren die je ORM genereert — gewoon vertellen wat er gebeurde en waarom. En als je background jobs draait, geldt dezelfde gestructureerde aanpak — propageer het request ID naar elke job zodat failures end-to-end traceerbaar zijn.

Veelgestelde Vragen

Wat is het verschil tussen Lograge en Rails Semantic Logger?

Lograge herformatteert Rails request-logs naar single-line entries (één regel per request). Semantic Logger vervangt het hele Rails logging-framework door gestructureerde output overal — controllers, models, jobs en custom code. Gebruik beide samen: Lograge voor schone request-logs, Semantic Logger voor al het andere.

Hoeveel kost gestructureerde logging qua opslag?

JSON-logs zijn groter dan platte tekst per regel, maar je logt doorgaans minder regels omdat je stopt met het dumpen van SQL-queries en partial renders. In de praktijk zien de meeste teams vergelijkbaar of verminderd logvolume na het overstappen. De echte kostenoverweging is de prijsstelling van je log-aggregator — diensten als Datadog rekenen per ingested GB, dus wees selectief in wat je logt.

Moet ik in development op dezelfde manier loggen als in productie?

Nee. Houd verbose, menselijk leesbare logs in development — je wilt SQL-queries, render-tijden en parameterdetails wanneer je lokaal werkt. Schakel alleen in productie en staging over naar gestructureerde JSON. Configureer dit in je environment-bestanden zodat developers lokaal een goede ervaring hebben.

Hoe voeg ik logging toe aan background jobs zonder boilerplate te herhalen?

Maak een around_perform callback in je ApplicationJob basisklasse die elke job wrapt in een Semantic Logger tagged block. Neem de job-class, job ID en relevante business-identifiers op. Dit geeft elke job automatisch gestructureerde context zonder individuele job-classes aan te raken.