From 4e4bde90545d1cf9bbc370c1ab9c216583af6389 Mon Sep 17 00:00:00 2001 From: Reid Morrison Date: Sat, 29 Jun 2024 10:57:49 -0400 Subject: [PATCH 1/6] Start adding metrics to rails log entries --- .../action_controller/log_subscriber.rb | 119 ++++++++++-------- .../action_view/log_subscriber.rb | 9 +- .../active_record/log_subscriber.rb | 20 ++- test/action_controller_test.rb | 16 ++- test/active_record_test.rb | 49 ++++++-- 5 files changed, 141 insertions(+), 72 deletions(-) diff --git a/lib/rails_semantic_logger/action_controller/log_subscriber.rb b/lib/rails_semantic_logger/action_controller/log_subscriber.rb index 80b9b5f..d7e6e98 100644 --- a/lib/rails_semantic_logger/action_controller/log_subscriber.rb +++ b/lib/rails_semantic_logger/action_controller/log_subscriber.rb @@ -10,58 +10,16 @@ def start_processing(event) def process_action(event) controller_logger(event).info do - payload = event.payload.dup - # Unused, but needed for Devise 401 status code monkey patch to still work. - ::ActionController::Base.log_process_action(payload) - - params = payload[:params] - - if params.is_a?(Hash) || params.is_a?(::ActionController::Parameters) - # According to PR https://github.com/reidmorrison/rails_semantic_logger/pull/37/files - # params is not always a Hash. - payload[:params] = params.to_unsafe_h unless params.is_a?(Hash) - payload[:params] = params.except(*INTERNAL_PARAMS) - - if payload[:params].empty? - payload.delete(:params) - elsif params["file"] - # When logging to JSON the entire tempfile is logged, so convert it to a string. - payload[:params]["file"] = params["file"].inspect - end - end - - format = payload[:format] - payload[:format] = format.to_s.upcase if format.is_a?(Symbol) - - payload[:path] = extract_path(payload[:path]) if payload.key?(:path) - - exception = payload.delete(:exception) - if payload[:status].nil? && exception.present? - exception_class_name = exception.first - payload[:status] = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name) - end - - # Rounds off the runtimes. For example, :view_runtime, :mongo_runtime, etc. - payload.keys.each do |key| - payload[key] = payload[key].to_f.round(2) if key.to_s =~ /(.*)_runtime/ - end - - # Rails 6+ includes allocation count - payload[:allocations] = event.allocations if event.respond_to?(:allocations) - - payload[:status_message] = ::Rack::Utils::HTTP_STATUS_CODES[payload[:status]] if payload[:status].present? + ::ActionController::Base.log_process_action(event.payload) - # Causes excessive log output with Rails 5 RC1 - payload.delete(:headers) - # Causes recursion in Rails 6.1.rc1 - payload.delete(:request) - payload.delete(:response) + payload = build_payload(event) { message: "Completed ##{payload[:action]}", duration: event.duration, - payload: payload + payload: payload, + metric: "rails.controller.action" } end end @@ -71,17 +29,29 @@ def halted_callback(event) end def send_file(event) - controller_logger(event).info(message: "Sent file", payload: {path: event.payload[:path]}, duration: event.duration) + controller_logger(event).info( + message: "Sent file", + payload: {path: event.payload[:path]}, + duration: event.duration, + metric: "rails.controller.send_file" + ) end def redirect_to(event) - controller_logger(event).info(message: "Redirected to", payload: {location: event.payload[:location]}) + controller_logger(event).info( + message: "Redirected to", + payload: {location: event.payload[:location]}, + metric: "rails.controller.redirect_to" + ) end def send_data(event) - controller_logger(event).info(message: "Sent data", - payload: {file_name: event.payload[:filename]}, - duration: event.duration) + controller_logger(event).info( + message: "Sent data", + payload: {file_name: event.payload[:filename]}, + duration: event.duration, + metric: "rails.controller.send_data" + ) end def unpermitted_parameters(event) @@ -107,6 +77,53 @@ def #{method}(event) private + def build_payload(event) + payload = event.payload.dup + + params = payload[:params] + if params.is_a?(Hash) || params.is_a?(::ActionController::Parameters) + # According to PR https://github.com/reidmorrison/rails_semantic_logger/pull/37/files + # params is not always a Hash. + payload[:params] = params.to_unsafe_h unless params.is_a?(Hash) + payload[:params] = params.except(*INTERNAL_PARAMS) + + if payload[:params].empty? + payload.delete(:params) + elsif params["file"] + # When logging to JSON the entire tempfile is logged, so convert it to a string. + payload[:params]["file"] = params["file"].inspect + end + end + + format = payload[:format] + payload[:format] = format.to_s.upcase if format.is_a?(Symbol) + + payload[:path] = extract_path(payload[:path]) if payload.key?(:path) + + exception = payload.delete(:exception) + if payload[:status].nil? && exception.present? + exception_class_name = exception.first + payload[:status] = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name) + end + + # Rounds off the runtimes. For example, :view_runtime, :mongo_runtime, etc. + payload.keys.each do |key| + payload[key] = payload[key].to_f.round(2) if key.to_s =~ /(.*)_runtime/ + end + + # Rails 6+ includes allocation count + payload[:allocations] = event.allocations if event.respond_to?(:allocations) + + payload[:status_message] = ::Rack::Utils::HTTP_STATUS_CODES[payload[:status]] if payload[:status].present? + + # Causes excessive log output with Rails 5 RC1 + payload.delete(:headers) + # Causes recursion in Rails 6.1.rc1 + payload.delete(:request) + payload.delete(:response) + payload + end + # Returns the logger for the supplied event. # Returns ActionController::Base.logger if no controller is present def controller_logger(event) diff --git a/lib/rails_semantic_logger/action_view/log_subscriber.rb b/lib/rails_semantic_logger/action_view/log_subscriber.rb index 9a91577..40dcd05 100644 --- a/lib/rails_semantic_logger/action_view/log_subscriber.rb +++ b/lib/rails_semantic_logger/action_view/log_subscriber.rb @@ -29,7 +29,8 @@ def render_template(event) self.class.rendered_log_level, "Rendered", payload: payload, - duration: event.duration + duration: event.duration, + metric: "rails.view.render.template" ) end @@ -47,7 +48,8 @@ def render_partial(event) self.class.rendered_log_level, "Rendered", payload: payload, - duration: event.duration + duration: event.duration, + metric: "rails.view.render.partial" ) end @@ -67,7 +69,8 @@ def render_collection(event) self.class.rendered_log_level, "Rendered", payload: payload, - duration: event.duration + duration: event.duration, + metric: "rails.view.render.collection" ) end diff --git a/lib/rails_semantic_logger/active_record/log_subscriber.rb b/lib/rails_semantic_logger/active_record/log_subscriber.rb index 357303b..da64707 100644 --- a/lib/rails_semantic_logger/active_record/log_subscriber.rb +++ b/lib/rails_semantic_logger/active_record/log_subscriber.rb @@ -29,15 +29,24 @@ def sql(event) name = payload[:name] return if IGNORE_PAYLOAD_NAMES.include?(name) - log_payload = {sql: payload[:sql]} - log_payload[:binds] = bind_values(payload) unless (payload[:binds] || []).empty? + # Create a logger instance that uses the class name that the original log message came from. + logger = self.logger + words = name.split + if words.size == 2 + logger = SemanticLogger[words[0]] + name = words[1] + end + + log_payload = {sql: payload[:sql]} + log_payload[:binds] = bind_values(payload) unless (payload[:binds] || []).empty? log_payload[:allocations] = event.allocations if event.respond_to?(:allocations) - log_payload[:cached] = event.payload[:cached] + log_payload[:cached] = event.payload[:cached] log = { message: name, payload: log_payload, - duration: event.duration + duration: event.duration, + metric: "rails.active_record.sql" } # Log the location of the query itself. @@ -208,7 +217,8 @@ def type_casted_binds_v5_1_5(casted_binds) elsif Rails.version.to_i >= 4 # 4.x alias bind_values bind_values_v4 alias render_bind render_bind_v4_2 - else # 3.x + else + # 3.x alias bind_values bind_values_v3 end end diff --git a/test/action_controller_test.rb b/test/action_controller_test.rb index d90b52f..cb4c477 100644 --- a/test/action_controller_test.rb +++ b/test/action_controller_test.rb @@ -12,7 +12,8 @@ class ActionControllerTest < Minitest::Test Time.zone.now, SecureRandom.uuid, { - payload: "{}" + action: "index", + path: "/path" } ) @@ -21,6 +22,19 @@ class ActionControllerTest < Minitest::Test end assert_equal 1, messages.count, messages + assert_semantic_logger_event( + messages[0], + level: :info, + name: "Rails", + message: "Completed #index", + payload: { + action: "index", + path: "/path", + allocations: 0 + }, + metric: "rails.controller.action" + ) + assert messages[0].duration.is_a?(Float) end end end diff --git a/test/active_record_test.rb b/test/active_record_test.rb index 0fc3866..9ea43ba 100644 --- a/test/active_record_test.rb +++ b/test/active_record_test.rb @@ -17,8 +17,9 @@ class ActiveRecordTest < Minitest::Test assert_semantic_logger_event( messages[0], level: :debug, - name: "ActiveRecord", - message: "Sample Load", + name: "Sample", + message: "Load", + metric: "rails.active_record.sql", payload_includes: { sql: expected_sql, binds: {limit: 1} @@ -38,8 +39,9 @@ class ActiveRecordTest < Minitest::Test assert_semantic_logger_event( messages[0], level: :debug, - name: "ActiveRecord", - message: "Sample Load", + name: "Sample", + message: "Load", + metric: "rails.active_record.sql", payload_includes: { sql: expected_sql, binds: {name: "foo", limit: 1} @@ -50,8 +52,9 @@ class ActiveRecordTest < Minitest::Test assert_semantic_logger_event( messages[1], level: :debug, - name: "ActiveRecord", - message: "Sample Load", + name: "Sample", + message: "Load", + metric: "rails.active_record.sql", payload_includes: { sql: expected_sql, binds: {name: "foo", limit: 1}, @@ -77,8 +80,9 @@ class ActiveRecordTest < Minitest::Test assert_semantic_logger_event( messages[0], level: :debug, - name: "ActiveRecord", - message: "Sample Load", + name: "Sample", + message: "Load", + metric: "rails.active_record.sql", payload_includes: { sql: expected_sql, binds: {name: "Jack", limit: 1} @@ -100,8 +104,9 @@ class ActiveRecordTest < Minitest::Test assert_semantic_logger_event( messages[0], level: :debug, - name: "ActiveRecord", - message: "Sample Load", + name: "Sample", + message: "Load", + metric: "rails.active_record.sql", payload_includes: { sql: expected_sql, binds: {age: [2, 21], limit: 1} @@ -123,14 +128,34 @@ class ActiveRecordTest < Minitest::Test assert_semantic_logger_event( messages[0], level: :debug, - name: "ActiveRecord", - message: "Sample Load", + name: "Sample", + message: "Load", + metric: "rails.active_record.sql", payload_includes: { sql: expected_sql, binds: {age: [2, 3], limit: 1} } ) end + + it "counts" do + expected_sql = "SELECT COUNT(*) FROM \"samples\"" + + messages = semantic_logger_events do + Sample.count + end + assert_equal 1, messages.count, messages + + assert_semantic_logger_event( + messages[0], + level: :debug, + name: "Sample", + message: "Count", + metric: "rails.active_record.sql", + payload_includes: {sql: expected_sql} + ) + assert_instance_of Integer, messages[0].payload[:allocations] if Rails.version.to_i >= 6 + end end end end From 87fcd91dd7b0b54ddb93a20f5b484754f92943be Mon Sep 17 00:00:00 2001 From: Reid Morrison Date: Mon, 1 Jul 2024 10:31:26 -0400 Subject: [PATCH 2/6] Fix Sidekiq error handler not taking effect --- .../extensions/sidekiq/sidekiq.rb | 9 ++++----- test/sidekiq_test.rb | 10 ---------- 2 files changed, 4 insertions(+), 15 deletions(-) diff --git a/lib/rails_semantic_logger/extensions/sidekiq/sidekiq.rb b/lib/rails_semantic_logger/extensions/sidekiq/sidekiq.rb index 7a38c3b..64ab36f 100644 --- a/lib/rails_semantic_logger/extensions/sidekiq/sidekiq.rb +++ b/lib/rails_semantic_logger/extensions/sidekiq/sidekiq.rb @@ -108,20 +108,19 @@ def call(ex, ctx) class Config remove_const :ERROR_HANDLER - ERROR_HANDLER = ->(ex, ctx, cfg = Sidekiq.default_configuration) { + ERROR_HANDLER = ->(ex, ctx, cfg = Sidekiq.default_configuration) do unless ctx.empty? job_hash = ctx[:job] || {} klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"] logger = klass ? SemanticLogger[klass] : Sidekiq.logger ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx) end - } + end end else # Sidekiq >= 6.5 - # TODO: Not taking effect. See test/sidekiq_test.rb - def self.default_error_handler(ex, ctx) - binding.irb + Sidekiq.error_handlers.delete(Sidekiq::DEFAULT_ERROR_HANDLER) + Sidekiq.error_handlers << ->(ex, ctx) do unless ctx.empty? job_hash = ctx[:job] || {} klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"] diff --git a/test/sidekiq_test.rb b/test/sidekiq_test.rb index bc30fe4..37a6a22 100644 --- a/test/sidekiq_test.rb +++ b/test/sidekiq_test.rb @@ -28,17 +28,7 @@ class SidekiqTest < Minitest::Test end elsif Sidekiq::VERSION.to_i == 6 let(:processor) do - # TODO: Sidekiq 6.5 default handler is not accepting the patch - handler = ->(ex, ctx) { - unless ctx.empty? - job_hash = ctx[:job] || {} - klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"] - logger = klass ? SemanticLogger[klass] : Sidekiq.logger - ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx) - end - } config = Sidekiq - config[:error_handlers] = [handler] config[:fetch] = Sidekiq::BasicFetch.new(config) Sidekiq::Processor.new(config) { |*args| } end From 4697c01cadb2c1d7465c1e3eebb8b6fa5cde4bfe Mon Sep 17 00:00:00 2001 From: Reid Morrison Date: Wed, 3 Jul 2024 09:32:21 -0400 Subject: [PATCH 3/6] When name is not present --- .../active_record/log_subscriber.rb | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/lib/rails_semantic_logger/active_record/log_subscriber.rb b/lib/rails_semantic_logger/active_record/log_subscriber.rb index da64707..c91c6cc 100644 --- a/lib/rails_semantic_logger/active_record/log_subscriber.rb +++ b/lib/rails_semantic_logger/active_record/log_subscriber.rb @@ -31,10 +31,12 @@ def sql(event) # Create a logger instance that uses the class name that the original log message came from. logger = self.logger - words = name.split - if words.size == 2 - logger = SemanticLogger[words[0]] - name = words[1] + if name.present? + words = name.split + if words.size == 2 + logger = SemanticLogger[words[0]] + name = words[1] + end end log_payload = {sql: payload[:sql]} From 684d8855ccd99d20935f59ae269b632540bba9cf Mon Sep 17 00:00:00 2001 From: Reid Morrison Date: Wed, 4 Dec 2024 16:45:01 -0500 Subject: [PATCH 4/6] Processing log level --- .../action_controller/log_subscriber.rb | 22 +++++++++++++++++-- 1 file changed, 20 insertions(+), 2 deletions(-) diff --git a/lib/rails_semantic_logger/action_controller/log_subscriber.rb b/lib/rails_semantic_logger/action_controller/log_subscriber.rb index d7e6e98..ef85464 100644 --- a/lib/rails_semantic_logger/action_controller/log_subscriber.rb +++ b/lib/rails_semantic_logger/action_controller/log_subscriber.rb @@ -3,9 +3,24 @@ module ActionController class LogSubscriber < ActiveSupport::LogSubscriber INTERNAL_PARAMS = %w[controller action format _method only_path].freeze + class_attribute :start_processing_log_level, default: :debug + class_attribute :start_processing_entire_payload, default: false + # Log as debug to hide Processing messages in production def start_processing(event) - controller_logger(event).debug { "Processing ##{event.payload[:action]}" } + payload = + if start_processing_entire_payload + build_payload(event) + else + {path: event.payload[:path], action: event.payload[:action]} + end + + controller_logger(event).send( + start_processing_log_level || :debug, + message: "Processing ##{event.payload[:action]}", + payload: payload, + metric: "rails.controller.start" + ) end def process_action(event) @@ -25,7 +40,10 @@ def process_action(event) end def halted_callback(event) - controller_logger(event).info { "Filter chain halted as #{event.payload[:filter].inspect} rendered or redirected" } + controller_logger(event).info( + "Filter chain halted as #{event.payload[:filter].inspect} rendered or redirected", + metric: "rails.controller.halted" + ) end def send_file(event) From 2e01dd991d3b91cb442a5dba7d063e661c0e0633 Mon Sep 17 00:00:00 2001 From: Reid Morrison Date: Wed, 4 Dec 2024 16:45:31 -0500 Subject: [PATCH 5/6] Otel Logging --- lib/rails_semantic_logger/engine.rb | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/lib/rails_semantic_logger/engine.rb b/lib/rails_semantic_logger/engine.rb index 30a957a..75da5d0 100644 --- a/lib/rails_semantic_logger/engine.rb +++ b/lib/rails_semantic_logger/engine.rb @@ -104,6 +104,13 @@ class Engine < ::Rails::Engine Moped.logger = SemanticLogger[Moped] if defined?(Moped) Mongo::Logger.logger = SemanticLogger[Mongo] if defined?(Mongo::Logger) + # Replace default Stdout Open Telemetry logger, can be overridden during configuration + if defined?(::OpenTelemetry) + formatter = Rails.application.config.colorize_logging ? :color : :default + OpenTelemetry.logger = SemanticLogger::Appender.factory(io: $stdout, formatter: formatter) + OpenTelemetry.logger.name = "OpenTelemetry" + end + # Replace the Resque Logger Resque.logger = SemanticLogger[Resque] if defined?(Resque) && Resque.respond_to?(:logger=) From f8811f1f03f68bc21385f75ba05c8fff9a9e1e70 Mon Sep 17 00:00:00 2001 From: Reid Morrison Date: Wed, 4 Dec 2024 16:46:00 -0500 Subject: [PATCH 6/6] Update comments --- lib/rails_semantic_logger/options.rb | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/rails_semantic_logger/options.rb b/lib/rails_semantic_logger/options.rb index 3da3e85..378264e 100644 --- a/lib/rails_semantic_logger/options.rb +++ b/lib/rails_semantic_logger/options.rb @@ -22,11 +22,11 @@ module RailsSemanticLogger # # config.rails_semantic_logger.rendered = false # - # * Override the Awesome Print options for logging Hash data as text: + # * Override the Amazing Print options for logging Hash data as text: # - # Any valid AwesomePrint option for rendering data. + # Any valid AmazingPrint option for rendering data. # The defaults can changed be creating a `~/.aprc` file. - # See: https://github.com/michaeldv/awesome_print + # See: https://github.com/amazing-print/amazing_print # # Note: The option :multiline is set to false if not supplied. # Note: Has no effect if Awesome Print is not installed.