From 4785d6ec81fcbfe4d771a7f08b768b526d3d8feb Mon Sep 17 00:00:00 2001 From: Morgan Roderick Date: Thu, 10 Sep 2026 13:25:28 +0200 Subject: [PATCH 1/2] Emit canonical JSON request logs via rails_semantic_logger Planner's request logging is multi-line and unstructured, which makes request-level analysis (latency percentiles, error rates per controller) impractical outside the app. Emit one JSON line per request instead. Switch the stdout appender to JSON when RAILS_LOG_TO_STDOUT is set and tag requests with the request id as a named tag, so it lands as a log field. Add path_template (the normalized route pattern, e.g. /workshops/:id) to the request-completion payload so lines carry no raw IDs or query strings. Drop the production config.logger override: rails_semantic_logger replaces Rails.logger regardless, so the TaggedLogging line was dead code that obscured where logging is configured. --- config/application.rb | 6 ++- config/environments/production.rb | 6 +-- config/initializers/canonical_log.rb | 14 +++++++ spec/requests/canonical_log_line_spec.rb | 51 ++++++++++++++++++++++++ 4 files changed, 73 insertions(+), 4 deletions(-) create mode 100644 config/initializers/canonical_log.rb create mode 100644 spec/requests/canonical_log_line_spec.rb diff --git a/config/application.rb b/config/application.rb index de593e373..8c021649a 100644 --- a/config/application.rb +++ b/config/application.rb @@ -32,6 +32,10 @@ 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 } + # 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] @@ -44,7 +48,7 @@ class Application < Rails::Application if ENV["RAILS_LOG_TO_STDOUT"].present? $stdout.sync = true config.rails_semantic_logger.add_file_appender = false - config.semantic_logger.add_appender(io: $stdout, formatter: config.rails_semantic_logger.format) + config.semantic_logger.add_appender(io: $stdout, formatter: :json) end end end diff --git a/config/environments/production.rb b/config/environments/production.rb index 88a103058..f54bc868a 100644 --- a/config/environments/production.rb +++ b/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") diff --git a/config/initializers/canonical_log.rb b/config/initializers/canonical_log.rb new file mode 100644 index 000000000..adccf6d85 --- /dev/null +++ b/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) diff --git a/spec/requests/canonical_log_line_spec.rb b/spec/requests/canonical_log_line_spec.rb new file mode 100644 index 000000000..78d2072e4 --- /dev/null +++ b/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 From d0e3e4eae45ee2729409d93b25162e1e947ebaaa Mon Sep 17 00:00:00 2001 From: Morgan Roderick Date: Sun, 13 Sep 2026 17:06:00 +0200 Subject: [PATCH 2/2] Identify planner in canonical log lines and trim redundant fields Set SemanticLogger.application to planner so canonical lines carry the app name instead of the RSL default ("Semantic Logger"), and emit stdout lines through a CanonicalJsonFormatter that drops three redundant fields: duration (string duplicate of duration_ms), level_index (derivable from level), and payload.status_message (derivable from status). Declare the stdout appender via config.rails_semantic_logger.appenders, the current API, instead of the deprecated add_file_appender= writer. Declaring appenders also stops RSL building its default file appender. --- config/application.rb | 12 ++++++++++-- lib/canonical_json_formatter.rb | 23 +++++++++++++++++++++++ 2 files changed, 33 insertions(+), 2 deletions(-) create mode 100644 lib/canonical_json_formatter.rb diff --git a/config/application.rb b/config/application.rb index 8c021649a..83b7e22bc 100644 --- a/config/application.rb +++ b/config/application.rb @@ -36,6 +36,10 @@ class Application < Rails::Application # 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] @@ -46,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: :json) + # 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 diff --git a/lib/canonical_json_formatter.rb b/lib/canonical_json_formatter.rb new file mode 100644 index 000000000..38e922dd2 --- /dev/null +++ b/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