Feature: Improved Logging

CHANGELOG.md

@@ -12,6 +12,16 @@
 
 - (Dan) Updates ruby version to 2.7.8 and alpine version to 3.16 [GH-455](https://github.com/epimorphics/ukhpi/issues/455)
 
+## 1.7.6 - 2024-10
+
+- (Jon) Split the error logging into it's own method as well as adjusted the
+  logged message to be either the response message or the response status
+- (Jon) Renamed `render_error` method to `handle_error`
+- (Jon) Set the Internal Error Instrumentation to an `unless` statement to
+  ensure the application does not report internal errors to the Prometheus
+  metrics when the error is a 404 thereby reducing the noise in the Slack alerts
+  channel
+
 ## 1.7.5 - 2024-09
 
 - (Jon) Created a `local` makefile target to allow for local development without
@@ -113,7 +123,7 @@
 - (Bogdan) Added alt text to application logo
   [GH-404](https://github.com/epimorphics/ukhpi/issues/404)
 
-## 1.7.4 - 2024-04-19
+## 1.7.4 - 2024-05-01
 
 - (Jon) Updated print presenter to use
   [`.try(:first)`](https://apidock.com/rails/Object/try) which resolves by

Gemfile

@@ -49,6 +49,10 @@ group :development, :test do
 end
 
 group :development do
+  # Devtools panel for Rails development
+  # https://chromewebstore.google.com/detail/rails-panel/gjpfobpafnhjhbajcjgccbbdofdckggg?pli=1
+  gem 'meta_request'
+
   # Access an IRB console on exception pages or by using <%= console %> in views
   gem 'web-console'
 

Gemfile.lock

@@ -210,6 +210,9 @@ GEM
       net-smtp
     marcel (1.0.4)
     matrix (0.4.2)
+    meta_request (0.8.4)
+      rack-contrib (>= 1.1, < 3)
+      railties (>= 3.0.0, < 8)
     method_source (1.1.0)
     mini_mime (1.1.5)
     minitest (5.25.1)
@@ -266,6 +269,8 @@ GEM
       puma (>= 6.0)
     racc (1.8.1)
     rack (3.1.8)
+    rack-contrib (2.5.0)
+      rack (< 4)
     rack-proxy (0.7.7)
       rack
     rack-session (2.0.0)
@@ -475,6 +480,7 @@ DEPENDENCIES
   json_expressions
   json_rails_logger!
   m
+  meta_request
   minitest-rails
   minitest-reporters
   mocha

Makefile

@@ -37,8 +37,11 @@ ${GITHUB_TOKEN}:
 	@echo ${PAT} > ${GITHUB_TOKEN}
 
 assets:
+	@echo "Installing bundler packages ..."
 	@./bin/bundle install
+	@echo "Installing yarn packages ..."
 	@yarn install
+	@echo "Cleaning and precompiling static assets ..."
 	@./bin/rails assets:clean assets:precompile
 
 auth: ${GITHUB_TOKEN} ${BUNDLE_CFG}
@@ -68,14 +71,6 @@ image: auth
 lint: assets
 	@./bin/bundle exec rubocop
 
-local:
-	@echo "Installing bundler packages ..."
-	@./bin/bundle install
-	@echo "Installing yarn packages ..."
-	@yarn install
-	@echo "Starting local server ..."
-	@./bin/rails server -p ${PORT}
-
 publish: image
 	@echo Publishing image: ${REPO}:${TAG} ...
 	@docker tag ${NAME}:${TAG} ${REPO}:${TAG} 2>&1
@@ -89,8 +84,12 @@ run: start
 	@if docker network inspect dnet > /dev/null 2>&1; then echo "Using docker network dnet"; else echo "Create docker network dnet"; docker network create dnet; sleep 2; fi
 	@docker run -p ${PORT}:3000 -e API_SERVICE_URL=${API_SERVICE_URL} --network dnet --rm --name ${SHORTNAME} ${NAME}:${TAG}
 
-server: assets start
+secret:
+	@echo "Creating secret ..."
 	@export SECRET_KEY_BASE=$(./bin/rails secret)
+
+server:
+	@echo "Starting local server ..."
 	@API_SERVICE_URL=${API_SERVICE_URL} ./bin/rails server -p ${PORT}
 
 start:

app/controllers/application_controller.rb

@@ -39,35 +39,48 @@ def log_request_result
 
   private
 
-  # rubocop:disable Metrics/AbcSize
+  # rubocop:disable Metrics/AbcSize, Metrics/MethodLength, Layout/LineLength
   def detailed_request_log(duration)
     env = request.env
 
     log_fields = {
+      accept: env['HTTP_ACCEPT'],
+      body: request.body.gets&.gsub("\n", '\n'),
       duration: duration,
-      request_id: env['X_REQUEST_ID'],
       forwarded_for: env['X_FORWARDED_FOR'],
+      message: response.message || Rack::Utils::HTTP_STATUS_CODES[response.status],
       path: env['REQUEST_PATH'],
       query_string: env['QUERY_STRING'],
-      user_agent: env['HTTP_USER_AGENT'],
-      accept: env['HTTP_ACCEPT'],
-      body: request.body.gets&.gsub("\n", '\n'),
+      request_id: env['X_REQUEST_ID'],
+      request_uri: env['REQUEST_URI'],
       method: request.method,
-      status: response.status,
-      message: Rack::Utils::HTTP_STATUS_CODES[response.status]
+      status: response.status
     }
 
-    case response.status
-    when 500..599
+    if env['HTTP_USER_AGENT'] && Rails.env.production?
+      log_fields[:user_agent] = env['HTTP_USER_AGENT']
+    end
+
+    if (500..599).include?(Rack::Utils::SYMBOL_TO_STATUS_CODE[response.status])
       log_fields[:message] = env['action_dispatch.exception'].to_s
-      Rails.logger.error(JSON.generate(log_fields))
+      log_fields[:backtrace] = env['action_dispatch.backtrace'].join("\n") unless Rails.env.production?
+    end
+
+    log_response(response.status, log_fields)
+  end
+  # rubocop:enable Metrics/AbcSize, Metrics/MethodLength, Layout/LineLength
+
+  # Log the error with the appropriate log level based on the status code
+  def log_response(status, error_log)
+    case status
+    when 500..599
+      Rails.logger.error(JSON.generate(error_log))
     when 400..499
-      Rails.logger.warn(JSON.generate(log_fields))
+      Rails.logger.warn(JSON.generate(error_log))
     else
-      Rails.logger.info(JSON.generate(log_fields))
+      Rails.logger.info(JSON.generate(error_log))
     end
   end
-  # rubocop:enable Metrics/AbcSize
 
   # Notify subscriber(s) of an internal error event with the payload of the
   # exception once done

app/controllers/browse_controller.rb

@@ -3,7 +3,7 @@
 # Controller for the main user experience of browsing the UKHPI statistics.
 # Usually the primary interaction will be via JavaScript and XHR, but we also
 # support non-JS access by setting browse preferences in the `edit` action.
-class BrowseController < ApplicationController
+class BrowseController < ApplicationController # rubocop:disable Metrics/ClassLength
   layout 'webpack_application'
 
   def show

app/controllers/compare_controller.rb

@@ -31,7 +31,7 @@ def render_print
     render 'compare/print', layout: 'print'
   end
 
-  def perform_query(user_compare_selections)
+  def perform_query(user_compare_selections) # rubocop:disable Metrics/MethodLength
     query_results = {}
     base_selection = UserSelections.new(
       __safe_params: {

app/controllers/exceptions_controller.rb

@@ -4,14 +4,12 @@
 class ExceptionsController < ApplicationController
   layout 'application'
 
-  def render_error
+  def handle_error
     env = request.env
     exception = env['action_dispatch.exception']
     status_code = ActionDispatch::ExceptionWrapper.new(env, exception).status_code
 
     sentry_code = maybe_report_to_sentry(exception, status_code)
-    # add the exception to the prometheus metrics
-    instrument_internal_error(exception)
 
     render :error_page,
            locals: { status: status_code, sentry_code: sentry_code },
@@ -22,9 +20,12 @@ def render_error
   private
 
   def maybe_report_to_sentry(exception, status_code)
-    return nil if Rails.env.development? # Why are we reporting to Senty in dev?
+    return nil if Rails.env.development? # Why are we reporting to Sentry in dev?
     return nil unless status_code >= 500
 
+    # Trigger error metrics on 5xx errors only to reduce slack noise
+    instrument_internal_error(exception)
+
     sevent = Sentry.capture_exception(exception)
     sevent&.event_id
   end

app/models/concerns/user_choices.rb

@@ -55,7 +55,7 @@ def alternative_key(key)
 
   # Recognise a date. Accepts ISO-8601 strings or Date objects.
   # Dates that match YYYY-MM will be transformed to YYYY-MM-01.
-  # @param date Either an ISO0-8601 date string, or a date object
+  # @param date Either an ISO-8601 date string, or a date object
   def parse_date(date)
     if date.is_a?(Date)
       date

app/models/latest_values_command.rb

@@ -7,33 +7,57 @@ class LatestValuesCommand
   attr_reader :results
 
   def perform_query(service = nil)
+    log_fields = {}
+    log_fields[:message] = 'Received Data Services API query'
+    log_fields[:request_status] = 'received'
+
+    Rails.logger.info(JSON.generate(log_fields))
     hpi = service_api(service)
 
     (hpi && run_query(hpi)) || no_service
   end
 
   private
 
-  def service_api(service) # rubocop:disable Metrics/AbcSize
-    service || dataset(:ukhpi)
-  rescue Faraday::ConnectionFailed => e
-    Rails.logger.error { 'Failed to connect to UK HPI ' }
-    Rails.logger.error { "Status: #{e.status}, body: '#{e.message}'" }
-    Rails.logger.error { e }
-    nil
-  rescue DataServicesApi::ServiceException => e
-    Rails.logger.error { 'Failed to get response from UK HPI service' }
-    Rails.logger.error { "Status: #{e.status}, body: '#{e.service_message}'" }
-    nil
-  rescue RuntimeError => e
-    Rails.logger.error { "Runtime error #{e.inspect}" }
-    Rails.logger.error { e.class }
-    Rails.logger.error { e.backtrace.join("\n") }
-    Rails.logger.error { "Caused by: #{e.cause}" } if e.cause
-    nil
+  def service_api(service) # rubocop:disable Metrics/AbcSize, Metrics/MethodLength, Metrics/CyclomaticComplexity, Metrics/PerceivedComplexity
+    log_fields = {}
+    service = nil if service.blank?
+    begin
+      service || dataset(:ukhpi)
+      log_fields[:message] = 'Connected to UK HPI service'
+      log_type = 'info'
+    rescue Faraday::ConnectionFailed => e
+      log_fields[:message] = 'Failed to connect to UK HPI service'
+      log_fields[:status] = e.status
+      log_fields[:body] = e.message
+      log_fields[:backtrace] = e&.backtrace&.join("\n") if Rails.env.development?
+      log_fields[:request_status] = 'error'
+
+      service = nil
+    rescue DataServicesApi::ServiceException => e
+      log_fields[:message] = 'Failed to get response from UK HPI service'
+      log_fields[:status] = e.status
+      log_fields[:body] = e.service_message
+      log_fields[:request_status] = 'error'
+
+      service = nil
+    rescue RuntimeError => e
+      log_fields[:message] = "Runtime error #{e.inspect}"
+      log_fields[:status] = e.status
+      log_fields[:body] = "Caused by: #{e.cause} in " if e.cause
+      log_fields[:body] += e.class
+      log_fields[:backtrace] = e&.backtrace&.join("\n") if Rails.env.development?
+      log_fields[:request_status] = 'error'
+
+      service = nil
+    end
+    Rails.logger.send(log_type) { log_fields }
+    service
   end
 
-  def run_query(hpi) # rubocop:disable Metrics/AbcSize
+  def run_query(hpi) # rubocop:disable Metrics/AbcSize, Metrics/MethodLength
+    log_fields = {}
+
     success = true
     query = add_date_range_constraint(base_query)
     query = add_location_constraint(query)
@@ -43,15 +67,29 @@ def run_query(hpi) # rubocop:disable Metrics/AbcSize
     start = Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond)
     begin
       @results = hpi.query(query)
+      time_taken = (Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond) - start) / 1000
+      message = format("Processing Data Services API query: '#{query.to_json}' in %.0fms", time_taken)
+      log_fields[:duration] = time_taken
+      log_fields[:message] = message
+      log_fields[:request_status] = 'processing'
+      log_type = 'info'
     rescue NoMethodError => e
-      Rails.logger.debug { "Application failed with: NoMethodError #{e.inspect}" }
+      log_fields[:message] = "Application failed with: NoMethodError: #{e.inspect}"
+      log_fields[:request_status] = 'error'
+      log_type = 'error'
+      success = false
+    rescue ArgumentError => e
+      log_fields[:message] = "Data Services API query failed with: ArgumentError: #{e.inspect}"
+      log_fields[:request_status] = 'error'
+      log_type = 'error'
       success = false
     rescue RuntimeError => e
-      Rails.logger.error { "API query failed with: #{e.inspect}" }
+      log_fields[:message] = "Data Services API query failed with: #{e.inspect}"
+      log_fields[:request_status] = 'error'
+      log_type = 'error'
       success = false
     end
-    time_taken = (Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond) - start)
-    Rails.logger.info { format("API query '#{query.to_json}' completed in %.0f μs\n", time_taken) }
+    Rails.logger.send(log_type) { JSON.generate(log_fields) }
     success
   end
 

app/models/user_selections.rb

@@ -8,7 +8,7 @@
 # standard set of statistics is presented if there is no information in the
 # user parameters yet. This functionality combines the previous
 # `models/UserPreferences` and `presenters/Aspects`
-class UserSelections
+class UserSelections # rubocop:disable Metrics/ClassLength
   include UserChoices
   include UserSelectionValidations
   include UserLanguage

app/services/query_command.rb

@@ -15,8 +15,12 @@ def initialize(user_selections)
   # @param service Optional API service end-point to use. Defaults to the UKHPI
   # API service endpoint
   def perform_query(service = nil)
+    log_fields = {}
     time_taken = execute_query(service, query)
-    Rails.logger.info(format("API roundtrip took %.0f μs\n", time_taken))
+    log_fields[:message] = format("Completed Data Services API roundtrip took %.0fms\n", time_taken)
+    log_fields[:request_status] = 'completed'
+    log_fields[:duration] = time_taken
+    Rails.logger.info(log_fields)
   end
 
   # @return True if this a query execution command
@@ -33,9 +37,13 @@ def explain_query_command?
 
   # Construct the DsAPI query that matches the given user constraints
   def build_query
+    log_fields = {}
+    log_fields[:message] = 'Received Data Services API query'
+    log_fields[:request_status] = 'received'
     query = add_date_range_constraint(base_query)
     query1 = add_location_constraint(query)
     add_sort(query1)
+    Rails.logger.info(log_fields)
   end
 
   def api_service(service)
@@ -48,9 +56,13 @@ def default_service
 
   # Run the given query, stash the results, and return time taken in microseconds.
   def execute_query(service, query)
+    log_fields = {}
+    log_fields[:message] = 'Processing Data Services API query'
+    log_fields[:request_status] = 'processing'
     start = Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond)
     @results = api_service(service).query(query)
-    (Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond) - start)
+    Rails.logger.info(log_fields)
+    (Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond) - start) / 1000
   end
 
   def add_date_range_constraint(query)