Skip to content

Instantly share code, notes, and snippets.

@troy
Created August 10, 2012 02:13
  • Star 36 You must be signed in to star a gist
  • Fork 6 You must be signed in to fork a gist
Star You must be signed in to star a gist
Save troy/3310392 to your computer and use it in GitHub Desktop.
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
Copy link

jelder 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
Copy link

gnomet 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
Copy link

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
Copy link

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