diff --git a/lib/rails_semantic_logger/action_controller/log_subscriber.rb b/lib/rails_semantic_logger/action_controller/log_subscriber.rb index 80b9b5f..a1c97a6 100644 --- a/lib/rails_semantic_logger/action_controller/log_subscriber.rb +++ b/lib/rails_semantic_logger/action_controller/log_subscriber.rb @@ -5,63 +5,23 @@ class LogSubscriber < ActiveSupport::LogSubscriber # Log as debug to hide Processing messages in production def start_processing(event) - controller_logger(event).debug { "Processing ##{event.payload[:action]}" } + controller_logger(event).debug do + { + message: "Processing ##{event.payload[:action]}", + payload: build_payload(event), + } + end 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 - - # 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) + ::ActionController::Base.log_process_action(event.payload) { - message: "Completed ##{payload[:action]}", + message: "Completed ##{event.payload[:action]}", duration: event.duration, - payload: payload + payload: build_payload(event) } end end @@ -107,6 +67,55 @@ 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/test/controllers/articles_controller_test.rb b/test/controllers/articles_controller_test.rb index f6ed780..eedb80a 100644 --- a/test/controllers/articles_controller_test.rb +++ b/test/controllers/articles_controller_test.rb @@ -41,7 +41,21 @@ class ArticlesControllerTest < ActionDispatch::IntegrationTest messages[1], message: "Processing #create", name: "ArticlesController", - level: :debug + level: :debug, + payload: { + controller: "ArticlesController", + action: "create", + params: { + "article" => { + "text" => "Text1", + "title" => "Title1" + } + }, + format: "HTML", + method: "POST", + path: "/articles", + allocations: 0, + } ) assert_semantic_logger_event( diff --git a/test/controllers/dashboard_controller_test.rb b/test/controllers/dashboard_controller_test.rb index b9bea58..75a5a0c 100644 --- a/test/controllers/dashboard_controller_test.rb +++ b/test/controllers/dashboard_controller_test.rb @@ -32,7 +32,14 @@ class DashboardControllerTest < ActionDispatch::IntegrationTest level: :debug, name: "Rails", message: "Processing #show", - payload: nil + payload: { + controller: "DashboardController", + action: "show", + format: "HTML", + method: "GET", + path: "/dashboard", + allocations: 0, + } ) assert_semantic_logger_event( diff --git a/test/dummy/db/test.sqlite3 b/test/dummy/db/test.sqlite3 index 50d4e75..dc726f3 100644 Binary files a/test/dummy/db/test.sqlite3 and b/test/dummy/db/test.sqlite3 differ