From 5a87828c9889ca76535a4aded8fe6f3f213e23c9 Mon Sep 17 00:00:00 2001 From: Jeremy Prevost Date: Thu, 20 Aug 2026 15:55:02 -0400 Subject: [PATCH] Swap to rails_semantic_logger Builds a few individual logging lines into a single rich line --- Gemfile | 3 ++- Gemfile.lock | 17 +++++++-------- app/controllers/application_controller.rb | 7 ++++++- app/controllers/graphql_controller.rb | 13 +++++++++--- app/graphql/timdex_field_usage_analyzer.rb | 14 ++++++------- app/graphql/timdex_request_tracer.rb | 15 -------------- app/graphql/types/query_type.rb | 13 +++++++++--- config/environments/development.rb | 24 +++++++++++++++++++--- config/environments/production.rb | 7 +++---- config/initializers/lograge.rb | 20 ------------------ 10 files changed, 68 insertions(+), 65 deletions(-) delete mode 100644 app/graphql/timdex_request_tracer.rb delete mode 100644 config/initializers/lograge.rb diff --git a/Gemfile b/Gemfile index 5d3f8fc6..08cc6585 100644 --- a/Gemfile +++ b/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' diff --git a/Gemfile.lock b/Gemfile.lock index 95807dcf..ee1144d8 100644 --- a/Gemfile.lock +++ b/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 diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb index ed74353c..20774a93 100644 --- a/app/controllers/application_controller.rb +++ b/app/controllers/application_controller.rb @@ -5,12 +5,17 @@ class ApplicationController < ActionController::Base private + 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 diff --git a/app/controllers/graphql_controller.rb b/app/controllers/graphql_controller.rb index 37ea8b30..460fe319 100644 --- a/app/controllers/graphql_controller.rb +++ b/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,12 @@ def handle_error_in_development(err) data: {} }, status: :internal_server_error end - def request_tracer - @request_tracer ||= TimdexRequestTracer.new + 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 diff --git a/app/graphql/timdex_field_usage_analyzer.rb b/app/graphql/timdex_field_usage_analyzer.rb index 41aa96c2..a0b138c7 100644 --- a/app/graphql/timdex_field_usage_analyzer.rb +++ b/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 diff --git a/app/graphql/timdex_request_tracer.rb b/app/graphql/timdex_request_tracer.rb deleted file mode 100644 index 2208d007..00000000 --- a/app/graphql/timdex_request_tracer.rb +++ /dev/null @@ -1,15 +0,0 @@ -# TimdexRequestTracer will populate the context of a query with data from our analyzers so we -# can use the data to modify how we contstruct queries -# It is called from the graphql_controller as part of the request context. -# https://graphql-ruby.org/queries/executing_queries.html#context -# https://graphql-ruby.org/queries/tracing.html -# https://medium.com/omada-health-tech/graphql-tips-the-backend-553375e1b669 -class TimdexRequestTracer - attr_accessor :log_data - - def trace(key, _data) - result = yield - self.log_data = result.first if key == 'analyze_query' - result - end -end diff --git a/app/graphql/types/query_type.rb b/app/graphql/types/query_type.rb index 27185734..81a39fd0 100644 --- a/app/graphql/types/query_type.rb +++ b/app/graphql/types/query_type.rb @@ -115,7 +115,13 @@ 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] || {} + context[:graphql_search_events]&.push( + searchterm: format_searchterm_for_log(searchterm), + query_mode: query_mode, + used_deprecated_fields: analyzer_data[:used_deprecated_fields] || [], + used_deprecated_arguments: analyzer_data[:used_deprecated_arguments] || [] + ) query = construct_query(searchterm, citation, contributors, funding_information, geodistance, geobox, identifiers, locations, subjects, title, source, boolean_type, filters, per_page, query_mode) @@ -136,7 +142,8 @@ def search(searchterm:, citation:, contributors:, funding_information:, geodista 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 +157,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 diff --git a/config/environments/development.rb b/config/environments/development.rb index 52f95f10..4a93c7c0 100644 --- a/config/environments/development.rb +++ b/config/environments/development.rb @@ -65,9 +65,27 @@ # 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_server( + # formatter: { + # color: { + # ap: { multiline: true }, + # color_map: SemanticLogger::Formatters::Color::ColorMap.new( + # trace: SemanticLogger::AnsiColors::MAGENTA, + # debug: SemanticLogger::AnsiColors::GREEN, + # info: SemanticLogger::AnsiColors::CYAN, + # warn: SemanticLogger::AnsiColors::YELLOW, + # error: SemanticLogger::AnsiColors::RED, + # fatal: SemanticLogger::AnsiColors::RED, + # bold: SemanticLogger::AnsiColors::BOLD, + # clear: SemanticLogger::AnsiColors::CLEAR + # ) + # } + # } + # ) + appenders.add(io: $stdout, formatter: :color) + end # Annotate rendered view with file names. config.action_view.annotate_rendered_view_with_filenames = true diff --git a/config/environments/production.rb b/config/environments/production.rb index 6aaa258b..c3ff7ce1 100644 --- a/config/environments/production.rb +++ b/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 ] diff --git a/config/initializers/lograge.rb b/config/initializers/lograge.rb deleted file mode 100644 index 44fa85fb..00000000 --- a/config/initializers/lograge.rb +++ /dev/null @@ -1,20 +0,0 @@ -Rails.application.configure do - unless ENV["DISABLE_LOGRAGE"].present? - config.lograge.enabled = true - end - - config.lograge.custom_options = lambda do |event| - exceptions = %w(controller action format id) - { - params: event.payload[:params].except(*exceptions), - time: Time.now.utc().iso8601(3), - } - end - - # This is mostly only useful when central logging is set up - config.lograge.custom_payload do |controller| - { - host: controller.request.host - } - end -end