From 137ca706478440c64a9f236dd7a23561788105b6 Mon Sep 17 00:00:00 2001 From: Matthew Ford Date: Mon, 12 Aug 2024 15:12:27 +0100 Subject: [PATCH 1/8] wip --- Gemfile | 1 + Gemfile.lock | 4 ++ config/environments/development.rb | 14 +++++ lib/formatters/asim_formatter.rb | 88 ++++++++++++++++++++++++++++++ 4 files changed, 107 insertions(+) create mode 100644 lib/formatters/asim_formatter.rb diff --git a/Gemfile b/Gemfile index 07bf7d7af..15dd59cc1 100644 --- a/Gemfile +++ b/Gemfile @@ -129,6 +129,7 @@ gem "puma", "~> 6.4.2" gem "appsignal" # Log formatting +gem 'json_tagged_logger' gem "lograge" # speedup server boot time diff --git a/Gemfile.lock b/Gemfile.lock index 1251427d0..b46cf6158 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -291,6 +291,9 @@ GEM js_cookie_rails (2.1.4) railties (>= 3.1) json (2.6.3) + json_tagged_logger (0.7.0) + actionpack (>= 6.1) + activesupport (>= 6.1) jwt (2.8.1) base64 kaminari (1.2.2) @@ -751,6 +754,7 @@ DEPENDENCIES jquery-ui-rails (>= 7.0.0) js_cookie_rails (= 2.1.4) json + json_tagged_logger kaminari launchy letter_opener diff --git a/config/environments/development.rb b/config/environments/development.rb index 39341b495..050451cd1 100644 --- a/config/environments/development.rb +++ b/config/environments/development.rb @@ -1,4 +1,5 @@ require "active_support/core_ext/integer/time" +require Rails.root.join('lib/formatters/asim_formatter') Rails.application.configure do # Settings specified here will take precedence over those in config/application.rb. @@ -70,4 +71,17 @@ # Uncomment if you wish to allow Action Cable access from any origin. # config.action_cable.disable_request_forgery_protection = true + + config.log_tags = JsonTaggedLogger::LogTagsConfig.generate( + :request_id, + :remote_ip, + JsonTaggedLogger::TagFromSession.get(:user_id), + :user_agent + ) + logger = ActiveSupport::Logger.new(STDOUT) + config.logger = JsonTaggedLogger::Logger.new(logger) + + config.lograge.enabled = true + config.lograge.formatter = AsimFormatter.new + end diff --git a/lib/formatters/asim_formatter.rb b/lib/formatters/asim_formatter.rb new file mode 100644 index 000000000..ac4cdc9fb --- /dev/null +++ b/lib/formatters/asim_formatter.rb @@ -0,0 +1,88 @@ +require "time" +require "date" + +class AsimFormatter + def call(data) + end_time = Time.now.utc + start_time = end_time - (data[:duration] || 0) + + { + "EventMessage" => data[:message], + "EventCount" => 1, + "EventStartTime" => format_time(start_time), + "EventEndTime" => format_time(end_time), + "EventType" => event_type(data), + "EventResult" => event_result(data), + "EventSeverity" => map_severity(data[:level]), + "EventOriginalSeverity" => data[:level], + "EventSchema" => "ProcessEvent", + "EventSchemaVersion" => "0.1.4", + "EventOriginalUid" => data[:original_id], + "EventProduct" => "KAE", + "EventProductVersion" => Rails.version, + "EventVendor" => "Ruby", + "EventReportUrl" => data[:report_url], + "EventOwner" => data[:owner], + "ActingAppType" => "Rails", + "SrcIpAddr" => data[:remote_ip], + "SrcPortNumber" => ENV["PORT"] || 3000, + "IpAddr" => data[:remote_ip], + "SrcUserId" => data[:user_id], + "HttpUserAgent" => data[:user_agent], + "DvcDomain" => ENV['DOMAIN'] || 'unknown', + "AdditionalFields" => { + "RailsLogFormatterAsimVersion" => "1.0.0", + "TraceHeaders" => trace_headers(data), + "RawLog" => data.to_json, + }, + }.to_json + end + + private + + def format_time(time) + time.iso8601 if time + end + + def event_type(data) + controller = data[:controller] + action = data[:action] + if controller && action + "#{controller}##{action}" + else + "UnknownEvent" + end + end + + def event_result(data) + status = data[:status] + if status + status >= 400 ? "Failure" : "Success" + else + "NA" + end + end + + def map_severity(level) + case level.to_s.upcase + when "DEBUG" + "Informational" + when "INFO" + "Informational" + when "WARN" + "Medium" + when "ERROR" + "High" + when "FATAL" + "High" + else + "Informational" + end + end + + def trace_headers(data) + { + "X-Request-Id" => data[:request_id], + } + end +end From cdc45271bb3df791fa1602c5b97b64e6d2371121 Mon Sep 17 00:00:00 2001 From: Matthew Ford Date: Mon, 12 Aug 2024 15:55:46 +0100 Subject: [PATCH 2/8] wip --- lib/formatters/asim_formatter.rb | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/lib/formatters/asim_formatter.rb b/lib/formatters/asim_formatter.rb index ac4cdc9fb..25afb9067 100644 --- a/lib/formatters/asim_formatter.rb +++ b/lib/formatters/asim_formatter.rb @@ -3,11 +3,11 @@ class AsimFormatter def call(data) + end_time = Time.now.utc start_time = end_time - (data[:duration] || 0) { - "EventMessage" => data[:message], "EventCount" => 1, "EventStartTime" => format_time(start_time), "EventEndTime" => format_time(end_time), @@ -17,18 +17,16 @@ def call(data) "EventOriginalSeverity" => data[:level], "EventSchema" => "ProcessEvent", "EventSchemaVersion" => "0.1.4", - "EventOriginalUid" => data[:original_id], "EventProduct" => "KAE", "EventProductVersion" => Rails.version, - "EventVendor" => "Ruby", - "EventReportUrl" => data[:report_url], + "EventVendor" => "Ruby on Rails", "EventOwner" => data[:owner], - "ActingAppType" => "Rails", + "ActingAppType" => "Ruby on Rails", "SrcIpAddr" => data[:remote_ip], "SrcPortNumber" => ENV["PORT"] || 3000, "IpAddr" => data[:remote_ip], - "SrcUserId" => data[:user_id], "HttpUserAgent" => data[:user_agent], + "Dvc" => ENV['DOMAIN'] || 'unknown', "DvcDomain" => ENV['DOMAIN'] || 'unknown', "AdditionalFields" => { "RailsLogFormatterAsimVersion" => "1.0.0", From 84d36d67b5711ea8ba1b4bd5a2c4bfbb4e8407b2 Mon Sep 17 00:00:00 2001 From: Matthew Ford Date: Mon, 12 Aug 2024 16:05:27 +0100 Subject: [PATCH 3/8] Adding Current via ActiveSupport::CurrentAttributes For the Asim formatter to get the current user and type. --- app/controllers/application_controller.rb | 12 ++++++++++++ app/models/current.rb | 5 +++++ lib/formatters/asim_formatter.rb | 2 ++ 3 files changed, 19 insertions(+) create mode 100644 app/models/current.rb diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb index 23d6199f5..67560dbfb 100644 --- a/app/controllers/application_controller.rb +++ b/app/controllers/application_controller.rb @@ -9,6 +9,7 @@ class ApplicationController < ActionController::Base before_action :configure_permitted_parameters, if: :devise_controller? before_action :set_context_tags + before_action :set_current_attributes before_action :set_paper_trail_whodunnit before_action :disable_browser_caching! @@ -165,6 +166,17 @@ def set_context_tags private + def set_current_attributes + Current.user_id = current_user.id || current_admin.id + Current.user_type = if current_user.present? + "User" + elsif current_admin.present? + "Admin" + else + "Other" + end + end + def configure_permitted_parameters devise_parameter_sanitizer.permit( :sign_up, diff --git a/app/models/current.rb b/app/models/current.rb new file mode 100644 index 000000000..1cffdb4bb --- /dev/null +++ b/app/models/current.rb @@ -0,0 +1,5 @@ +class Current < ActiveSupport::CurrentAttributes + attribute :user_id + attribute :user_type +end + diff --git a/lib/formatters/asim_formatter.rb b/lib/formatters/asim_formatter.rb index 25afb9067..1ca4b731a 100644 --- a/lib/formatters/asim_formatter.rb +++ b/lib/formatters/asim_formatter.rb @@ -25,6 +25,8 @@ def call(data) "SrcIpAddr" => data[:remote_ip], "SrcPortNumber" => ENV["PORT"] || 3000, "IpAddr" => data[:remote_ip], + "SrcUserId" => Current.user_id, + "SrcUserType" => Current.user_type, "HttpUserAgent" => data[:user_agent], "Dvc" => ENV['DOMAIN'] || 'unknown', "DvcDomain" => ENV['DOMAIN'] || 'unknown', From f010f8be23ff669f05a7cb7d542aaef7bf31059a Mon Sep 17 00:00:00 2001 From: Matthew Ford Date: Tue, 13 Aug 2024 01:05:44 +0100 Subject: [PATCH 4/8] Update application_controller.rb --- app/controllers/application_controller.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb index 67560dbfb..fe4527e90 100644 --- a/app/controllers/application_controller.rb +++ b/app/controllers/application_controller.rb @@ -167,7 +167,7 @@ def set_context_tags private def set_current_attributes - Current.user_id = current_user.id || current_admin.id + Current.user_id = current_user&.id || current_admin&.id Current.user_type = if current_user.present? "User" elsif current_admin.present? From 11fd53295c422b212e6bf05d73f2d487f54df1ae Mon Sep 17 00:00:00 2001 From: Matthew Ford Date: Mon, 12 Aug 2024 15:12:27 +0100 Subject: [PATCH 5/8] feat: Change logger to use ASIM format Adding Current via ActiveSupport::CurrentAttributes for the Asim formatter to get the current user and type. --- Gemfile | 1 + Gemfile.lock | 4 ++ app/controllers/application_controller.rb | 12 ++++ app/models/current.rb | 4 ++ config/environments/development.rb | 13 ++++ config/environments/production.rb | 16 +++-- lib/formatters/asim_formatter.rb | 88 +++++++++++++++++++++++ 7 files changed, 132 insertions(+), 6 deletions(-) create mode 100644 app/models/current.rb create mode 100644 lib/formatters/asim_formatter.rb diff --git a/Gemfile b/Gemfile index 07bf7d7af..51e138957 100644 --- a/Gemfile +++ b/Gemfile @@ -129,6 +129,7 @@ gem "puma", "~> 6.4.2" gem "appsignal" # Log formatting +gem "json_tagged_logger" gem "lograge" # speedup server boot time diff --git a/Gemfile.lock b/Gemfile.lock index 1251427d0..b46cf6158 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -291,6 +291,9 @@ GEM js_cookie_rails (2.1.4) railties (>= 3.1) json (2.6.3) + json_tagged_logger (0.7.0) + actionpack (>= 6.1) + activesupport (>= 6.1) jwt (2.8.1) base64 kaminari (1.2.2) @@ -751,6 +754,7 @@ DEPENDENCIES jquery-ui-rails (>= 7.0.0) js_cookie_rails (= 2.1.4) json + json_tagged_logger kaminari launchy letter_opener diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb index 23d6199f5..f96d990cc 100644 --- a/app/controllers/application_controller.rb +++ b/app/controllers/application_controller.rb @@ -9,6 +9,7 @@ class ApplicationController < ActionController::Base before_action :configure_permitted_parameters, if: :devise_controller? before_action :set_context_tags + before_action :set_current_attributes before_action :set_paper_trail_whodunnit before_action :disable_browser_caching! @@ -165,6 +166,17 @@ def set_context_tags private + def set_current_attributes + Current.user_id = current_user&.id || current_admin&.id + Current.user_type = if current_user.present? + "User" + elsif current_admin.present? + "Admin" + else + "Other" + end + end + def configure_permitted_parameters devise_parameter_sanitizer.permit( :sign_up, diff --git a/app/models/current.rb b/app/models/current.rb new file mode 100644 index 000000000..03cba1834 --- /dev/null +++ b/app/models/current.rb @@ -0,0 +1,4 @@ +class Current < ActiveSupport::CurrentAttributes + attribute :user_id + attribute :user_type +end diff --git a/config/environments/development.rb b/config/environments/development.rb index 39341b495..143e8c972 100644 --- a/config/environments/development.rb +++ b/config/environments/development.rb @@ -1,4 +1,5 @@ require "active_support/core_ext/integer/time" +require Rails.root.join("lib/formatters/asim_formatter") Rails.application.configure do # Settings specified here will take precedence over those in config/application.rb. @@ -70,4 +71,16 @@ # Uncomment if you wish to allow Action Cable access from any origin. # config.action_cable.disable_request_forgery_protection = true + + config.log_tags = JsonTaggedLogger::LogTagsConfig.generate( + :request_id, + :remote_ip, + JsonTaggedLogger::TagFromSession.get(:user_id), + :user_agent, + ) + logger = ActiveSupport::Logger.new(STDOUT) + config.logger = JsonTaggedLogger::Logger.new(logger) + + config.lograge.enabled = true + config.lograge.formatter = AsimFormatter.new end diff --git a/config/environments/production.rb b/config/environments/production.rb index bbe9edb99..a227de1e6 100644 --- a/config/environments/production.rb +++ b/config/environments/production.rb @@ -86,14 +86,18 @@ # Send deprecation notices to registered listeners. config.active_support.deprecation = :notify + config.log_tags = JsonTaggedLogger::LogTagsConfig.generate( + :request_id, + :remote_ip, + JsonTaggedLogger::TagFromSession.get(:user_id), + :user_agent, + ) + logger = ActiveSupport::Logger.new(STDOUT) + config.logger = JsonTaggedLogger::Logger.new(logger) + config.lograge.enabled = true config.lograge.ignore_actions = ["HealthcheckController#index"] - config.lograge.keep_original_rails_log = true - config.lograge.logger = Appsignal::Logger.new( - "rails", - format: Appsignal::Logger::LOGFMT, - ) - config.logger = ActiveSupport::Logger.new($stdout) # Lograge-formatted logs to STDOUT + config.lograge.formatter = AsimFormatter.new # Do not dump schema after migrations. config.active_record.dump_schema_after_migration = false diff --git a/lib/formatters/asim_formatter.rb b/lib/formatters/asim_formatter.rb new file mode 100644 index 000000000..1ca4b731a --- /dev/null +++ b/lib/formatters/asim_formatter.rb @@ -0,0 +1,88 @@ +require "time" +require "date" + +class AsimFormatter + def call(data) + + end_time = Time.now.utc + start_time = end_time - (data[:duration] || 0) + + { + "EventCount" => 1, + "EventStartTime" => format_time(start_time), + "EventEndTime" => format_time(end_time), + "EventType" => event_type(data), + "EventResult" => event_result(data), + "EventSeverity" => map_severity(data[:level]), + "EventOriginalSeverity" => data[:level], + "EventSchema" => "ProcessEvent", + "EventSchemaVersion" => "0.1.4", + "EventProduct" => "KAE", + "EventProductVersion" => Rails.version, + "EventVendor" => "Ruby on Rails", + "EventOwner" => data[:owner], + "ActingAppType" => "Ruby on Rails", + "SrcIpAddr" => data[:remote_ip], + "SrcPortNumber" => ENV["PORT"] || 3000, + "IpAddr" => data[:remote_ip], + "SrcUserId" => Current.user_id, + "SrcUserType" => Current.user_type, + "HttpUserAgent" => data[:user_agent], + "Dvc" => ENV['DOMAIN'] || 'unknown', + "DvcDomain" => ENV['DOMAIN'] || 'unknown', + "AdditionalFields" => { + "RailsLogFormatterAsimVersion" => "1.0.0", + "TraceHeaders" => trace_headers(data), + "RawLog" => data.to_json, + }, + }.to_json + end + + private + + def format_time(time) + time.iso8601 if time + end + + def event_type(data) + controller = data[:controller] + action = data[:action] + if controller && action + "#{controller}##{action}" + else + "UnknownEvent" + end + end + + def event_result(data) + status = data[:status] + if status + status >= 400 ? "Failure" : "Success" + else + "NA" + end + end + + def map_severity(level) + case level.to_s.upcase + when "DEBUG" + "Informational" + when "INFO" + "Informational" + when "WARN" + "Medium" + when "ERROR" + "High" + when "FATAL" + "High" + else + "Informational" + end + end + + def trace_headers(data) + { + "X-Request-Id" => data[:request_id], + } + end +end From 64acb4246e65c4cfc80d024b49387b08acb25eaf Mon Sep 17 00:00:00 2001 From: Matthew Ford Date: Tue, 13 Aug 2024 12:17:59 +0100 Subject: [PATCH 6/8] feat: Enable ASIM logger in dev via ENABLE_ASIM_LOGGER env var --- .env.example | 1 + config/environments/development.rb | 16 +++++++++++----- 2 files changed, 12 insertions(+), 5 deletions(-) diff --git a/.env.example b/.env.example index 8eb12c5b4..6509a090b 100644 --- a/.env.example +++ b/.env.example @@ -24,3 +24,4 @@ GOV_UK_NOTIFY_API_KEY=key GOV_UK_NOTIFY_API_TEMPLATE_ID=id SESSION_TIMEOUT=1 HOST=http://localhost:3000 +ENABLE_ASIM_LOGGER=false diff --git a/config/environments/development.rb b/config/environments/development.rb index 143e8c972..ec96fc3d8 100644 --- a/config/environments/development.rb +++ b/config/environments/development.rb @@ -72,15 +72,21 @@ # Uncomment if you wish to allow Action Cable access from any origin. # config.action_cable.disable_request_forgery_protection = true + # Enable ASIM logging if ENABLE_ASIM_LOGGER is set to 'true' + if ENV['ENABLE_ASIM_LOGGER'] == 'true' + config.lograge.enabled = true + config.lograge.formatter = AsimFormatter.new + config.logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT)) + else + # normal development logging configuration + config.logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT)) + end + config.log_tags = JsonTaggedLogger::LogTagsConfig.generate( :request_id, :remote_ip, JsonTaggedLogger::TagFromSession.get(:user_id), - :user_agent, + :user_agent ) - logger = ActiveSupport::Logger.new(STDOUT) - config.logger = JsonTaggedLogger::Logger.new(logger) - config.lograge.enabled = true - config.lograge.formatter = AsimFormatter.new end From b43cd002f2ac6c08cfab7ca23d01f960483a45a5 Mon Sep 17 00:00:00 2001 From: Matthew Ford Date: Tue, 13 Aug 2024 12:23:27 +0100 Subject: [PATCH 7/8] lint --- config/environments/development.rb | 9 ++++----- config/environments/production.rb | 2 +- lib/formatters/asim_formatter.rb | 5 ++--- 3 files changed, 7 insertions(+), 9 deletions(-) diff --git a/config/environments/development.rb b/config/environments/development.rb index ec96fc3d8..b5ea3d819 100644 --- a/config/environments/development.rb +++ b/config/environments/development.rb @@ -73,20 +73,19 @@ # config.action_cable.disable_request_forgery_protection = true # Enable ASIM logging if ENABLE_ASIM_LOGGER is set to 'true' - if ENV['ENABLE_ASIM_LOGGER'] == 'true' + if ENV["ENABLE_ASIM_LOGGER"] == "true" config.lograge.enabled = true config.lograge.formatter = AsimFormatter.new - config.logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT)) + config.logger = ActiveSupport::TaggedLogging.new(Logger.new($stdout)) else # normal development logging configuration - config.logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT)) + config.logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new($stdout)) end config.log_tags = JsonTaggedLogger::LogTagsConfig.generate( :request_id, :remote_ip, JsonTaggedLogger::TagFromSession.get(:user_id), - :user_agent + :user_agent, ) - end diff --git a/config/environments/production.rb b/config/environments/production.rb index a227de1e6..72eb267ad 100644 --- a/config/environments/production.rb +++ b/config/environments/production.rb @@ -92,7 +92,7 @@ JsonTaggedLogger::TagFromSession.get(:user_id), :user_agent, ) - logger = ActiveSupport::Logger.new(STDOUT) + logger = ActiveSupport::Logger.new($stdout) config.logger = JsonTaggedLogger::Logger.new(logger) config.lograge.enabled = true diff --git a/lib/formatters/asim_formatter.rb b/lib/formatters/asim_formatter.rb index 1ca4b731a..c580e4cdc 100644 --- a/lib/formatters/asim_formatter.rb +++ b/lib/formatters/asim_formatter.rb @@ -3,7 +3,6 @@ class AsimFormatter def call(data) - end_time = Time.now.utc start_time = end_time - (data[:duration] || 0) @@ -28,8 +27,8 @@ def call(data) "SrcUserId" => Current.user_id, "SrcUserType" => Current.user_type, "HttpUserAgent" => data[:user_agent], - "Dvc" => ENV['DOMAIN'] || 'unknown', - "DvcDomain" => ENV['DOMAIN'] || 'unknown', + "Dvc" => ENV["DOMAIN"] || "unknown", + "DvcDomain" => ENV["DOMAIN"] || "unknown", "AdditionalFields" => { "RailsLogFormatterAsimVersion" => "1.0.0", "TraceHeaders" => trace_headers(data), From 29aaf7d5d89fad5d8c9bf99f6b25246eb8e2c71f Mon Sep 17 00:00:00 2001 From: Matthew Ford Date: Tue, 13 Aug 2024 12:28:07 +0100 Subject: [PATCH 8/8] Update asim_formatter.rb --- lib/formatters/asim_formatter.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/formatters/asim_formatter.rb b/lib/formatters/asim_formatter.rb index c580e4cdc..44f9babbc 100644 --- a/lib/formatters/asim_formatter.rb +++ b/lib/formatters/asim_formatter.rb @@ -56,7 +56,7 @@ def event_type(data) def event_result(data) status = data[:status] if status - status >= 400 ? "Failure" : "Success" + (status >= 400) ? "Failure" : "Success" else "NA" end