Emit canonical JSON request log lines via rails_semantic_logger

config/application.rb

@@ -32,6 +32,14 @@ class Application < Rails::Application
     config.time_zone = 'London'
     config.active_record.default_timezone = :local
 
+    # Request id as a named tag so it reaches canonical JSON log lines as a
+    # field, not an anonymous array entry.
+    config.log_tags = { request_id: :request_id }
+
+    # Canonical JSON log lines identify this app (SemanticLogger defaults to
+    # "Semantic Logger").
+    config.semantic_logger.application = "planner"
+
     # Related to https://stackoverflow.com/questions/72970170/upgrading-to-rails-6-1-6-1-causes-psychdisallowedclass-tried-to-load-unspecif
     # and https://discuss.rubyonrails.org/t/cve-2022-32224-possible-rce-escalation-bug-with-serialized-columns-in-active-record/81017
     config.active_record.yaml_column_permitted_classes = [Symbol, Date, Time, ActiveSupport::TimeWithZone, ActiveSupport::TimeZone, ActiveSupport::HashWithIndifferentAccess]
@@ -42,9 +50,13 @@ class Application < Rails::Application
 config.active_job.queue_adapter = :delayed_job
 
 if ENV["RAILS_LOG_TO_STDOUT"].present?
+      require "canonical_json_formatter"
+
       $stdout.sync = true
-      config.rails_semantic_logger.add_file_appender = false
-      config.semantic_logger.add_appender(io: $stdout, formatter: config.rails_semantic_logger.format)
+      # Declaring appenders here stops RSL building its default file appender.
+      config.rails_semantic_logger.appenders do |appenders|
+        appenders.add(io: $stdout, formatter: CanonicalJsonFormatter.new)
+      end
     end
   end
 end

config/environments/production.rb

@@ -38,9 +38,9 @@
   # Skip http-to-https redirect for the default health check endpoint.
   # config.ssl_options = { redirect: { exclude: ->(request) { request.path == "/up" } } }
 
-  # Log to STDOUT with the current request id as a default log tag.
-  config.log_tags = [ :request_id ]
-  config.logger   = ActiveSupport::TaggedLogging.logger(STDOUT)
+  # Request id log tag is configured in application.rb as a named tag so it
+  # reaches canonical JSON log lines as a field; rails_semantic_logger owns
+  # Rails.logger.
 
   # Change to "debug" to log everything (including potentially personally-identifiable information!).
   config.log_level = ENV.fetch("RAILS_LOG_LEVEL", "info")

config/initializers/canonical_log.rb

@@ -0,0 +1,14 @@
+# frozen_string_literal: true
+
+# Adds the matched route template to the request-completion log payload so
+# canonical log lines carry a normalized path: no record IDs, no query string.
+# Example: "/workshops/:id(.:format)". Unmatched routes are rejected by the
+# router before any controller runs, so they emit no Completed line at all.
+module CanonicalLogPathTemplate
+  def append_info_to_payload(payload)
+    super
+    payload[:path_template] = request.route_uri_pattern
+  end
+end
+
+ActionController::Base.prepend(CanonicalLogPathTemplate)

lib/canonical_json_formatter.rb

@@ -0,0 +1,23 @@
+# frozen_string_literal: true
+
+# JSON formatter for the canonical stdout log lines.
+#
+# SemanticLogger's stock JSON formatter emits redundant fields; this subclass
+# drops them so each line carries one value per concept:
+# - duration: the human string form of duration_ms
+# - level_index: internal enum, derivable from level
+# - payload.status_message: derivable from status
+class CanonicalJsonFormatter < SemanticLogger::Formatters::Json
+  def level
+    hash[:level] = log.level
+  end
+
+  def duration
+    hash[:duration_ms] = log.duration if log.duration
+  end
+
+  def payload
+    super
+    hash[:payload]&.delete(:status_message)
+  end
+end

spec/requests/canonical_log_line_spec.rb

@@ -0,0 +1,51 @@
+# frozen_string_literal: true
+
+require 'rails_helper'
+
+RSpec.describe 'canonical request log line' do
+  let(:events) do
+    capture = SemanticLogger::Test::CaptureLogEvents.new
+    appender = SemanticLogger.add_appender(appender: capture)
+    get '/faq'
+    SemanticLogger.flush
+    capture.events
+  ensure
+    SemanticLogger.remove_appender(appender)
+  end
+
+  it 'logs one structured Completed event with the canonical fields' do
+    completed = events.find { |event| event.message.to_s.start_with?('Completed') }
+    expect(completed).to be_present, 'expected a Completed log event for the request'
+
+    payload = completed.payload
+    expect(payload[:controller]).to eq('DashboardController')
+    expect(payload[:action]).to eq('faq')
+    expect(payload[:method]).to eq('GET')
+    expect(payload[:status]).to eq(200)
+    expect(payload[:path]).to eq('/faq')
+    expect(payload[:path_template]).to eq('/faq(.:format)')
+    expect(payload).to include(:db_runtime)
+  end
+
+  it 'carries the request id as a named tag' do
+    completed = events.find { |event| event.message.to_s.start_with?('Completed') }
+
+    expect(completed.named_tags[:request_id]).to be_present
+  end
+
+  it 'normalizes parameterized routes and excludes query strings' do
+    capture = SemanticLogger::Test::CaptureLogEvents.new
+    appender = SemanticLogger.add_appender(appender: capture)
+
+    get '/unsubscribe/some-token?utm_source=email'
+    SemanticLogger.flush
+
+    completed = capture.events.find { |event| event.message.to_s.start_with?('Completed') }
+    expect(completed).to be_present, 'expected a Completed log event for the request'
+    payload = completed.payload
+    expect(payload[:path_template]).to eq('/unsubscribe/:token(.:format)')
+    expect(payload[:path]).to eq('/unsubscribe/some-token')
+  ensure
+    SemanticLogger.remove_appender(appender)
+  end
+end