Skip to content

Add metrics to log entries #229

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 9 commits into
base: master
Choose a base branch
from
Open
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
141 changes: 88 additions & 53 deletions lib/rails_semantic_logger/action_controller/log_subscriber.rb
Original file line number Diff line number Diff line change
@@ -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)
9 changes: 6 additions & 3 deletions lib/rails_semantic_logger/action_view/log_subscriber.rb
Original file line number Diff line number Diff line change
@@ -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

22 changes: 17 additions & 5 deletions lib/rails_semantic_logger/active_record/log_subscriber.rb
Original file line number Diff line number Diff line change
@@ -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
7 changes: 7 additions & 0 deletions lib/rails_semantic_logger/engine.rb
Original file line number Diff line number Diff line change
@@ -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=)

6 changes: 3 additions & 3 deletions lib/rails_semantic_logger/options.rb
Original file line number Diff line number Diff line change
@@ -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.
16 changes: 15 additions & 1 deletion test/action_controller_test.rb
Original file line number Diff line number Diff line change
@@ -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
49 changes: 37 additions & 12 deletions test/active_record_test.rb
Original file line number Diff line number Diff line change
@@ -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