Skip to content

Instantly share code, notes, and snippets.

Embed
What would you like to do?
One-line detailed logging for Rails 3 (ActiveSupport::Notifications) and later
# Outputs this at warn log level:
# 1.2.3.4 GET /path 200 OK BlahController#action HTML 938.2 (DB 11.8, View 719.7) {params} {optional params from flash[:log]}
#
# Save as config/initializers/oneline_detailed_logging.rb. Consider
# decreasing the log level from "info" to "warn" (in production.rb) so
# the one-line log message replaces the standard request logs.
# override process_action to add 2 things to the payload:
# - remote IP
# - an optional stash which is available to subscribers. Basically, flash[:log].inspect will be logged.
# 3.0: https://github.com/rails/rails/blob/3-0-stable/actionpack/lib/action_controller/metal/instrumentation.rb
# 3.1: https://github.com/rails/rails/blob/master/actionpack/lib/action_controller/metal/instrumentation.rb
ActionController::Instrumentation.send(:define_method, "process_action") do |arg|
raw_payload = {
:controller => self.class.name,
:action => self.action_name,
:params => request.filtered_parameters,
:formats => request.formats.map(&:to_sym),
:method => request.method,
:path => (request.fullpath rescue "unknown"),
:ip => request.remote_ip,
:stash => request.session['flash'] && request.session['flash'][:log]
}
ActiveSupport::Notifications.instrument("start_processing.action_controller", raw_payload.dup)
ActiveSupport::Notifications.instrument("process_action.action_controller", raw_payload) do |payload|
result = super(arg)
payload[:status] = response.status
append_info_to_payload(payload)
result
end
end
ActiveSupport::Notifications.subscribe "process_action.action_controller" do |name, start, finish, id, payload|
# borrows from
# https://github.com/rails/rails/blob/3-0-stable/actionpack/lib/action_controller/log_subscriber.rb
params = payload[:params].except('controller', 'action', 'format', '_method', 'only_path')
format = payload[:formats].first.to_s.upcase
duration = (finish-start)*1000
status = payload[:status]
if status.nil? && payload[:exception].present?
# 3.1: http://rubydoc.info/docs/rails/3.1.1/ActionController/LogSubscriber#process_action-instance_method
status = Rack::Utils.status_code(ActionDispatch::ShowExceptions.rescue_responses[payload[:exception].first]) rescue nil
end
m = "%s %s %s %s %s %s\#%s %s %.1f (DB %.1f, View %.1f) %s %s" % [
payload[:ip], payload[:method], payload[:path],
status, Rack::Utils::HTTP_STATUS_CODES[status],
payload[:controller], payload[:action], format,
duration || 0, payload[:db_runtime] || 0, payload[:view_runtime] || 0,
params.inspect, payload[:stash].try(:inspect) || {}.inspect ]
Rails.logger.warn(m)
end
@jelder

This comment has been minimized.

Copy link

commented May 14, 2013

Hi Troy,

This might need an update for Rails 3.2 and beyond:

DEPRECATION WARNING: ActionDispatch::ShowExceptions.rescue_responses is deprecated. Please configure your exceptions using a railtie or in your application config instead.
@gnomet

This comment has been minimized.

Copy link

commented Jun 3, 2013

@jelder
I picked the solution for that line from the fork at https://gist.github.com/kyamaguchi/4231083 and it seems to remove the deprecation warning.

@gavingmiller

This comment has been minimized.

Copy link

commented Oct 7, 2013

As an FYI if you're using Rails 4 on Heroku this works, but setting the log_level to :warn won't take effect due to the rails_stdout_logging gem. So you'll see the old logs, and the compressed logs. This is because the gem is not respecting any config/environment/production.rb setting. The issue has been logged on github and a temp workaround is to set the LOG_LEVEL in the heroku config settings

@sebastianvirlan

This comment has been minimized.

Copy link

commented Dec 6, 2017

Hi, is there any solution in order to print :view_runtime and :db_runtime direct to the webpage?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.