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