Create a gist now

Instantly share code, notes, and snippets.

@toretore /README.md
Last active Dec 19, 2015

What would you like to do?
Rails 0MQ logger

These files work together to extract useful data from a Rails application and publish it through a ZeroMQ PUSH socket as JSON.

The code in application_controller.rb will automatically log every request and exception, but you're free to log other things. If you're inside a controller, you can use log_message(atts) or emit_event(atts). These controller methods simply delegate to the global object $ZMQ_LOGGER, which responds to log(atts) and emit(atts). They add the data.http.request-id key if not already present.

The difference between logging and emitting is somewhat blurry, but I like to think of log messages as something that will be saved somewhere and emitted events as ephemeral.

All attributes are expected to use strings as keys. If you use symbols, you may experience issues.

You may use these files as you wish, with one exception: You may not package them into a reusable library and publish it. This is not easily reusable code, and any attempt to make it into a pre-packaged library will result in tears and loss of hair by its users. Anyone that wants to use this must have at least somewhat of an idea what's going on, because you will inevitably want to change something.

class ApplicationController < ActionController::Base
rescue_from Exception, :with => :handle_exception
rescue_from ActiveRecord::RecordNotFound, :with => :handle_not_found
before_filter :setup_logging
# [...]
private
def redirect_to(*a, &b)
#Set previous-request-id to track redirects
flash['previous-request-id'] = request.uuid
super(*a, &b)
end
def emit_event(atts)
atts['data'] ||= {}
atts['data']['http'] ||= {}
atts['data']['http']['request-id'] ||= request.uuid
$ZMQ_LOGGER.emit(atts)
rescue Exception => e
logger.error "[LOGGING ERROR] #{e.class}: #{e.message}\n#{e.backtrace.map{|l| " #{l}"}.join("\n")}"
end
def log_message(atts)
atts['data'] ||= {}
atts['data']['http'] ||= {}
atts['data']['http']['request-id'] ||= request.uuid
$ZMQ_LOGGER.log(atts)
rescue Exception => e
logger.error "[LOGGING ERROR] #{e.class}: #{e.message}\n#{e.backtrace.map{|l| " #{l}"}.join("\n")}"
end
def memory_usage#in kB
`ps -o rss= -p #{Process.pid}`.strip.to_i
rescue
nil
end
def handle_not_found(exception)
log_exception(exception)
if true#Rails.env.production?
respond_to do |format|
format.html{ render file: Rails.root.join('public', '404.html'), layout: false, status: 404 }
format.xml{ render xml: error_xml('The requested resource could not be found'), status: 404 }
end
else
raise exception
end
rescue Exception => e
logger.error "[EXCEPTION LOGGING EXCEPTION] #{e.class}: #{e.message}\n#{e.backtrace.map{|l| " #{l}"}.join("\n")}"
render :text => "Inxception :("
end
def handle_exception(exception)
if Rails.env.development?
log_exception(exception)
raise exception
else
begin
log_exception(exception)
respond_to do |format|
format.html{ render file: Rails.root.join('public', '500.html'), layout: false, status: 500 }
end
rescue Exception => e
logger.error "[EXCEPTION LOGGING EXCEPTION] #{e.class}: #{e.message}\n#{e.backtrace.map{|l| " #{l}"}.join("\n")}"
render :text => "Inxception :(", status: 500
end
end
end
def log_exception(exception)
atts = {
'type' => 'exception',
'message' => 'Uncaught exception',
'description' => 'An unanticipated exception occured',
'data' => {
'exception' => {
'type' => exception.class.name,
'message' => exception.message,
'backtrace' => exception.backtrace
},
'http' => request_data_for_logging
}
}
log_message(atts)
end
def setup_logging
@memory_before = memory_usage
start = Time.now
instr, mw = nil, nil
ActiveSupport::Notifications.instrument('zmq-logger.call-me', ->(atts){
instr = atts
log_request(atts, mw) if mw
})
request.env['zmq-logger.get-data'].call(->(data){
mw = data
log_request(instr, data) if instr
})
end
def log_request(instr, mw)
atts = {
'type' => 'request',
'data' => {
'time' => mw['rack_stop']-mw['rack_start'],
'timing' => {
'rails_start' => instr['start'],
'rails_stop' => instr['stop'],
'rails_time' => instr['stop']-instr['start'],
'rack_start' => mw['rack_start'],
'rack_stop' => mw['rack_stop'],
'rack_time' => mw['rack_stop']-mw['rack_start'],
'rails_db_time' => instr['db_runtime'],
'rails_view_time' => instr['view_runtime'],
'custom' => timing_data_for_logging
},
'memory' => [@memory_before, memory_usage], #[start of request, end of request]
'queries' => instr['queries'],
'renders' => instr['renders'],
'user' => {
'id' => current_user && current_user.id,
'username' => current_user && current_user.username
},
'http' => request_data_for_logging.merge(
'response' => {
'status' => mw['status'],
'headers' => mw['headers'],
'body' => false && mw['body'] # You may not want to log every response body
}
)
}
}
if mw['request_start']
atts['data']['timing'].merge!(
'request_start' => mw['request_start'],
'request_time' => atts['data']['timing']['rack_stop'] - mw['request_start'],
'queue_time' => atts['data']['timing']['rack_start'] - mw['request_start']
)
end
log_message(atts)
end
def request_data_for_logging
atts = {
'request-id' => request.uuid,
'headers' => request_headers_for_logging,
'method' => request.method,
'params' => request.filtered_parameters,
'session' => session
}
#If this was the result of a redirect, see if previous request left its ID so we can tie them together
atts['referer-request-id'] = flash['previous-request-id'] if flash['previous-request-id'] && flash['previous-request-id'] != atts['request-id']
atts
end
#Scrub headers for logging. headers == rack env, which has lots of crap in it from middleware
def request_headers_for_logging
headers = request.headers.reject do |key, value|
(!key.is_a?(String) && !key.is_a?(Symbol)) || !value.is_a?(String) ||
key.to_s =~ /\A(rack|action_controller|action_dispatch|zmq-logger)/ ||
key == 'HTTP_COOKIE'
end
#headers['HTTP_X_API_KEY'] = '[FILTERED]' if headers['HTTP_X_API_KEY']
headers
end
def timing_data_for_logging
@timing_data_for_logging ||= Hash.new{|h,k| h[k] = [] }
end
def time(name, &block)
t = Time.now
r = yield
timing_data_for_logging[name] << Time.now-t
r
end
helper_method :time
end
# This file is used by Rack-based servers to start the application.
require File.dirname(__FILE__)+'/lib/request_info_middleware'
use RequestInfoMiddleware
require ::File.expand_path('../config/environment', __FILE__)
run MyApp::Application
# config/initializers/data_gatherer.rb
#
# Gather data from ActiveSupport::Notifications instrumentation
#
# Gathers data for each request:
#
# * Request start, stop time
# * SQL queries with time
#
# To receive data at end of request, add a callback:
#
# ActiveSupport::Notifications.instrument ->(data){ ... }
#
# Data returned:
#
# {
# queries: [{sql: '...', time: durationTime}],
# start: requestStartTime, #As reported by ActionController
# stop: requestStopTime #Ditto
# }
class InstrumentationDataGatherer
def initialize
subscribe
end
def subscribe
ActiveSupport::Notifications.subscribe do |*event|
if event[0] == 'start_processing.action_controller'
start(event)
elsif event[0] == 'process_action.action_controller'
done(event)
elsif event[0] == 'zmq-logger.call-me'
@callbacks << event[4] if @callbacks
elsif event[0] == 'sql.active_record' && event[4][:name] != 'SCHEMA'
@queries << event if @queries
elsif event[0] == '!render_template.action_view'
@renders << event if @renders
end
end
end
def start(event)
@id = event[3]
@queries = []
@renders = []
@callbacks = []
end
def done(event)
@callbacks.each do |cb|
atts = {
'stop' => event[2],
'start' => event[1],
'controller' => event[4][:controller],
'action' => event[4][:action],
'queries' => @queries.map{|e| {'time' => e[2]-e[1], 'sql' => e[4][:sql]} },
'renders' => @renders.map{|e| {'time' => e[2]-e[1], 'path' => e[4][:virtual_path]} }
}
atts['view_runtime'] = event[4][:view_runtime] / 1000.0 if event[4][:view_runtime]
atts['db_runtime'] = event[4][:db_runtime] / 1000.0 if event[4][:db_runtime]
cb.call(atts)
end
rescue => e
Rails.logger.error "[LOGGER] #{e.class}: #{e.message}\n#{e.backtrace.map{|l| " #{l}"}.join("\n")}"
end
end
InstrumentationDataGatherer.new
View Raw

(Sorry about that, but we can’t show files that are this big right now.)

View Raw

(Sorry about that, but we can’t show files that are this big right now.)

View Raw

(Sorry about that, but we can’t show files that are this big right now.)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment