Rails 0MQ logger

README.md

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.

application_controller.rb

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

config.ru

# 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

data_gatherer.rb

# 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

overview.png

request.png

request_info_middleware.rb

unicorn.rb

zmq-elasticsearch-logger.rb