diff --git a/lib/rails_semantic_logger/action_controller/log_subscriber.rb b/lib/rails_semantic_logger/action_controller/log_subscriber.rb index 80b9b5f..ef85464 100644 --- a/lib/rails_semantic_logger/action_controller/log_subscriber.rb +++ b/lib/rails_semantic_logger/action_controller/log_subscriber.rb @@ -3,85 +3,73 @@ 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) 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 + ::ActionController::Base.log_process_action(event.payload) - # 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 = build_payload(event) { message: "Completed ##{payload[:action]}", duration: event.duration, - payload: payload + payload: payload, + metric: "rails.controller.action" } end 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) - 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 +95,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..c91c6cc 100644 --- a/lib/rails_semantic_logger/active_record/log_subscriber.rb +++ b/lib/rails_semantic_logger/active_record/log_subscriber.rb @@ -29,15 +29,26 @@ 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 + if name.present? + words = name.split + if words.size == 2 + logger = SemanticLogger[words[0]] + name = words[1] + end + 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 +219,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/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=) 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. 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