diff --git a/config/application.rb b/config/application.rb index de593e373..83b7e22bc 100644 --- a/config/application.rb +++ b/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 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/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 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