Format logs using MS ASIM

.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

Gemfile

@@ -129,6 +129,7 @@ gem "puma", "~> 6.4.2"
 gem "appsignal"
 
 # Log formatting
+gem "json_tagged_logger"
 gem "lograge"
 
 # speedup server boot time

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

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,

app/models/current.rb

@@ -0,0 +1,4 @@
+class Current < ActiveSupport::CurrentAttributes
+  attribute :user_id
+  attribute :user_type
+end

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,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,
+  )
 end

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

lib/formatters/asim_formatter.rb

@@ -0,0 +1,87 @@
+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