Swap to rails_semantic_logger

Gemfile

@@ -12,7 +12,6 @@ gem 'faraday_middleware-aws-sigv4'
 gem 'flipflop'
 gem 'graphql'
 gem 'jwt'
-gem 'lograge'
 gem 'mitlibraries-theme',
     git: 'https://github.com/mitlibraries/mitlibraries-theme',
     tag: 'v1.5'
@@ -22,6 +21,7 @@ gem 'puma'
 gem 'rack-attack'
 gem 'rack-cors'
 gem 'rails', '~> 8.1.0'
+gem 'rails_semantic_logger'
 gem 'redis'
 gem 'sass-rails'
 gem 'sentry-rails'
@@ -34,6 +34,7 @@ group :production do
 end
 
 group :development, :test do
+  gem 'amazing_print'
   gem 'byebug'
   gem 'dotenv-rails'
   gem 'sqlite3'

Gemfile.lock

@@ -86,6 +86,7 @@ GEM
       uri (>= 0.13.1)
     addressable (2.9.0)
       public_suffix (>= 2.0.2, < 8.0)
+    amazing_print (2.0.0)
     annotaterb (4.24.0)
       activerecord (>= 6.0.0)
       activesupport (>= 6.0.0)
@@ -235,11 +236,6 @@ GEM
       rb-fsevent (~> 0.10, >= 0.10.3)
       rb-inotify (~> 0.9, >= 0.9.10)
     logger (1.7.0)
-    lograge (0.15.0)
-      actionpack (>= 4)
-      activesupport (>= 4)
-      railties (>= 4)
-      request_store (~> 1.0)
     loofah (2.25.2)
       crass (~> 1.0.2)
       nokogiri (>= 1.12.0)
@@ -333,6 +329,10 @@ GEM
     rails-html-sanitizer (1.7.1)
       loofah (~> 2.25, >= 2.25.2)
       nokogiri (>= 1.15.7, != 1.16.7, != 1.16.6, != 1.16.5, != 1.16.4, != 1.16.3, != 1.16.2, != 1.16.1, != 1.16.0.rc1, != 1.16.0)
+    rails_semantic_logger (5.1.0)
+      rack
+      railties (>= 7.2)
+      semantic_logger (>= 5.1)
     railties (8.1.3.1)
       actionpack (= 8.1.3.1)
       activesupport (= 8.1.3.1)
@@ -363,8 +363,6 @@ GEM
     regexp_parser (2.12.0)
     reline (0.6.3)
       io-console (~> 0.5)
-    request_store (1.7.0)
-      rack (>= 1.4)
     responders (3.2.0)
       actionpack (>= 7.0)
       railties (>= 7.0)
@@ -414,6 +412,8 @@ GEM
       rexml (~> 3.2, >= 3.2.5)
       rubyzip (>= 1.2.2, < 4.0)
       websocket (~> 1.0)
+    semantic_logger (5.1.0)
+      concurrent-ruby (~> 1.0)
     sentry-rails (6.6.2)
       railties (>= 5.2.0)
       sentry-ruby (~> 6.6.2)
@@ -472,6 +472,7 @@ PLATFORMS
   ruby
 
 DEPENDENCIES
+  amazing_print
   annotaterb
   aws-sdk-lambda
   aws-sdk-sts
@@ -491,7 +492,6 @@ DEPENDENCIES
   jekyll-seo-tag
   jwt
   listen
-  lograge
   minitest
   mitlibraries-theme!
   mocha
@@ -502,6 +502,7 @@ DEPENDENCIES
   rack-attack
   rack-cors
   rails (~> 8.1.0)
+  rails_semantic_logger
   redis
   rubocop
   rubocop-rails

app/controllers/application_controller.rb

@@ -5,12 +5,18 @@ class ApplicationController < ActionController::Base
 
   private
 
+  # Appends additional information to the log payload that are not Controller specific
+  def append_info_to_payload(payload)
+    super
+    payload[:host] = request.host
+  end
+
   # redirects herokuapp domains and old domains to preferred domains
   def ensure_domain
     return unless ENV['PREFERRED_DOMAIN']
     return if request.host == ENV['PREFERRED_DOMAIN']
 
     Rails.logger.info("Handling Domain Redirect: #{request.host}")
-    redirect_to "https://#{ENV['PREFERRED_DOMAIN']}", status: :moved_permanently, allow_other_host: true
+    redirect_to "https://#{ENV.fetch('PREFERRED_DOMAIN', nil)}", status: :moved_permanently, allow_other_host: true
   end
 end

app/controllers/graphql_controller.rb

@@ -2,13 +2,15 @@ class GraphqlController < ApplicationController
   skip_before_action :verify_authenticity_token
 
   def execute
+    @graphql_search_events = []
     variables = ensure_hash(params[:variables])
     query = params[:query]
     operation_name = params[:operationName]
     context = {
       # Query context goes here, for example:
       # current_user: current_user,
-      tracers: [request_tracer]
+      request_id: request.request_id,
+      graphql_search_events: @graphql_search_events
     }
     result = TimdexSchema.execute(query, variables: variables,
                                          context: context,
@@ -48,7 +50,13 @@ def handle_error_in_development(err)
                    data: {} }, status: :internal_server_error
   end
 
-  def request_tracer
-    @request_tracer ||= TimdexRequestTracer.new
+  # Appends additional information to the log payload that is specific to GraphQL requests
+  def append_info_to_payload(payload)
+    super
+
+    return if @graphql_search_events.blank?
+
+    payload[:graphql_search_events] = @graphql_search_events
+    payload.merge!(@graphql_search_events.first) if @graphql_search_events.one?
   end
 end

app/graphql/timdex_field_usage_analyzer.rb

@@ -1,17 +1,17 @@
-# TimdexFieldUsageAnalyzer largely overrides some methods from the inherited FieldUsage
-# We to log data in a format we can work with and return it to be used along with Tracers
-# to determine which fields are being requested so we can modify our OpenSearch query.
+# TimdexFieldUsageAnalyzer overrides FieldUsage so we can collect query usage data
+# (including deprecated fields and arguments) and place it directly on GraphQL context.
+# Resolvers then read this context data to shape OpenSearch query behavior and logging.
 # https://graphql-ruby.org/queries/ast_analysis.html
 class TimdexFieldUsageAnalyzer < GraphQL::Analysis::AST::FieldUsage
   # This overrides a GraphQL::Analysis::AST::FieldUsage method
   def result
-    Rails.logger.debug("GraphQL used fields: #{@used_fields.to_a}")
-    Rails.logger.info("GraphQL used deprecated fields: #{@used_deprecated_fields.to_a}")
-    Rails.logger.info("GraphQL used deprecated arguments: #{@used_deprecated_arguments.to_a}")
-    {
+    analysis_data = {
       used_fields: @used_fields.to_a,
       used_deprecated_fields: @used_deprecated_fields.to_a,
       used_deprecated_arguments: @used_deprecated_arguments.to_a
     }
+
+    query.context[:graphql_analysis] = analysis_data
+    analysis_data
   end
 end

app/graphql/types/query_type.rb

@@ -115,7 +115,7 @@ def record_id(id:, index:)
     def search(searchterm:, citation:, contributors:, funding_information:, geodistance:, geobox:, identifiers:,
                locations:, subjects:, title:, index:, source:, from:, boolean_type:, fulltext:, per_page: 20,
                query_mode: 'keyword', use_global_scoring: false, tuning_parameters_input: nil, **filters)
-      Rails.logger.info("Searchterm: #{format_searchterm_for_log(searchterm)}")
+      analyzer_data = context[:graphql_analysis] || {}
 
       query = construct_query(searchterm, citation, contributors, funding_information, geodistance, geobox, identifiers,
                               locations, subjects, title, source, boolean_type, filters, per_page, query_mode)
@@ -132,11 +132,21 @@ def search(searchterm:, citation:, contributors:, funding_information:, geodista
       response[:hits] = results['hits']['total']['value']
       response[:records] = inject_hits_fields_into_source(results['hits']['hits'])
       response[:aggregations] = collapse_buckets(results['aggregations'])
+
+      context[:graphql_search_events]&.push(
+        searchterm: format_searchterm_for_log(searchterm),
+        query_mode: query_mode,
+        timdex_result_count: response[:hits],
+        used_deprecated_fields: analyzer_data[:used_deprecated_fields] || [],
+        used_deprecated_arguments: analyzer_data[:used_deprecated_arguments] || []
+      )
+
       response
     end
 
     def highlight_requested?
-      context[:tracers].first.log_data[:used_fields].include?('Record.highlight')
+      used_fields = context.dig(:graphql_analysis, :used_fields) || []
+      used_fields.include?('Record.highlight')
     end
 
     # Convert aggregation fields to format expected by aggregations model.
@@ -150,7 +160,7 @@ def requested_aggregation_field(field_name)
     end
 
     def requested_aggregations
-      used_fields = context[:tracers].first.log_data[:used_fields]
+      used_fields = context.dig(:graphql_analysis, :used_fields) || []
       used_fields.select { |field| field.start_with?('Aggregations.') }
                  .map { |field| requested_aggregation_field(field.sub('Aggregations.', '')) }
     end

config/environments/development.rb

@@ -65,9 +65,10 @@
   # Raises error for missing translations.
   # config.i18n.raise_on_missing_translations = true
 
-  logger           = ActiveSupport::Logger.new(STDOUT)
-  logger.formatter = config.log_formatter
-  config.logger = ActiveSupport::TaggedLogging.new(logger)
+  config.rails_semantic_logger.appenders do |appenders|
+    # appenders.add(file_name: "log/#{Rails.env}.log", formatter: :color)
+    appenders.add(io: $stdout, formatter: :color)
+  end
 
   # Annotate rendered view with file names.
   config.action_view.annotate_rendered_view_with_filenames = true

config/environments/production.rb

@@ -39,10 +39,9 @@
   # Skip http-to-https redirect for the default health check endpoint.
   # config.ssl_options = { redirect: { exclude: ->(request) { request.path == "/up" } } }
 
-  # Log to STDOUT by default
-  config.logger = ActiveSupport::Logger.new(STDOUT)
-    .tap  { |logger| logger.formatter = ::Logger::Formatter.new }
-    .then { |logger| ActiveSupport::TaggedLogging.new(logger) }
+  config.rails_semantic_logger.appenders do |appenders|
+    appenders.add(io: $stdout, formatter: :json)
+  end
 
   # Log to STDOUT with the current request id as a default log tag.
   config.log_tags = [ :request_id ]