From cdc5140aabdcb121a21107f78c033a4f5351ab95 Mon Sep 17 00:00:00 2001
From: Alexey Bespalov <nulldefiner@gmail.com>
Date: Thu, 15 Feb 2024 17:00:36 +0100
Subject: [PATCH] add payload
---
.../action_controller/log_subscriber.rb | 107 ++++++++++--------
test/controllers/articles_controller_test.rb | 16 ++-
test/controllers/dashboard_controller_test.rb | 9 +-
test/dummy/db/test.sqlite3 | Bin 20480 -> 28672 bytes
4 files changed, 81 insertions(+), 51 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..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 50d4e7518444684e7848d2981bb65ad21306d190..dc726f3226f36dba7c8855d65ccbeee161cd4adc 100644
GIT binary patch
delta 719
zcmZ`#O>5Lp6n)8<q%AXf?V<$fqK^zn2W%%VUsH=<qXb7fR-I1KA`)IRFP&hL!OWYn
zuG-O6my$o=Uyy=ZcdlHj3s?3R6gRF-i`Igf#pQC(y@zwoJ$%O<{@~EoqgKc$3i@eG
z7&5>t;CZl)5CDMBOL~iLUFE^b=%^xp24eXXz-#gs8OlfH)5@p!<Co=waYv98%i>;d
zFtQs_l6qmnXqu47izy>r!blM&-f6o|$3-3IcFRR-(TR$d)aUe-ibf>$dn84h4?1Xb
zyVXJu+xPA}?H#n??#x|B>WD-`dU2M0gi2}2u4UgK^74K`tKAhv<*CJiFzM3$!HXzQ
z?vWwupU+;A1rHaY(tb%&>UD0sm<{FblgoB$&J|JFu20e!_&pjEFAn!o!oq$s@bG_-
zkpF!uFOYqgx27L+lCrSCy%91SV(IL)do;}w*!vsttRMe^GwbC_&f#Gbzz?u_JU4q2
z9z?uQedaiSBnCZ#cX7kC8>_bO8#o|7*0og=Hv-)@iD4K4)##0GfQhARy1A_B%h*EL
zTC>bGtgo0>17mISrpXD_dB>s2C`|iFOcR$eI$*^F+ipw{$v5`Qd6W|Xf5MYI%2&7u
QOI7Yt4qh%*r~fIj-vKSqC;$Ke
delta 207
zcmZp8z}T>WQ6V_cC$l6~AuYcsH?c&)m_dMnk&(ecL4kpRfdz<JCo0&BvM}fg{N@FT
z@IGST*WtUxm&5yLv!Fm8uUI2H3%j_jK4YVPW?o8aMQL7UVQFgoWLZ8XBUa}iSH}=n
zg-}1wz))8OPd^ve2n8jmisIyq)ZE1Q+|2Z%#FEVXykaE<f4|8-eDYkHIn3<h`al!e
zCrj|9FltV|!WYaL$jB}(EzQ_eIoW{UkloWS#MRw3XmSRB#^jm23Y)+2b2$J2d2lyG