An example for logging Fog requests in a Rails app

README.rdoc

Instrument Fog Requests in Rails

This code adds debug statements to the rails log for each fog reqests (similar to how active record shows SQL queries):

Fog AWS Compute Request (803.0ms)  [ {"Action"=>"DescribeInstances", ...} ]

The end of the request includes cumulative Fog info:

Completed 200 OK in 6043ms (Views: 2955.0ms | ActiveRecord: 319.9ms | Fog: 1642.6ms, 4 reqs)

fog_extensions.rb

# Wrap Fog real requests with notifications

# TODO: create/discover safer way to get notifications on requests
# Change 'request' method to send an activesupport notification
request_with_notifications = %q{
  alias_method :request_without_notifications, :request

  def request(params, &block)
    ActiveSupport::Notifications.instrument('request.fog', :object => self, :params => params) do
      request_without_notifications(params, &block)
    end
  end
}

# Classes to duckpunch. These are the ones I use, be sure to add your own.
classes = [Fog::AWS::RDS::Real, Fog::AWS::Compute::Real, Fog::AWS::ELB::Real]
classes.each do |klass|
  klass.class_eval(request_with_notifications)
end

fog_instrumentation.rb

# Log fog requests in Rails
# Based on:
# https://gist.github.com/566725
module FogInstrumentation

  # Subscriber borrows heavily from 
  # https://github.com/rails/rails/blob/master/activerecord/lib/active_record/log_subscriber.rb
  class LogSubscriber < ActiveSupport::LogSubscriber
    def self.runtime=(value)
      Thread.current[:fog_runtime] = value
    end

    def self.runtime
      Thread.current[:fog_runtime] ||= 0
    end

    def self.reset_runtime
      rt, self.runtime = runtime, 0
      rt
    end

    def self.count=(value)
      Thread.current[:fog_count] = value
    end

    def self.count
      Thread.current[:fog_count] ||= 0
    end

    def self.reset_count
      c, self.count = count, 0
      c
    end
    
    def request(event)
      self.class.runtime += event.duration
      self.class.count += 1
      return unless logger.debug?

      klass = event.payload[:object].class
      friendly_name = klass.to_s.split('::')[0,3] * ' '
      name = '%s (%.1fms)' % ["#{friendly_name} Request", event.duration]

      debug "  #{color(name, GREEN, true)}  [ #{color(event.payload[:params].inspect, WHITE)} ]"
    end
  end

  # Controller borrows heavily from
  # https://github.com/rails/rails/blob/master/activerecord/lib/active_record/railties/controller_runtime.rb
  module ControllerRuntime
    extend ActiveSupport::Concern

    protected

    attr_internal :fog_runtime
    def cleanup_view_runtime
      fog_rt_before_render = FogInstrumentation::LogSubscriber.reset_runtime
      runtime = super
      fog_rt_after_render = FogInstrumentation::LogSubscriber.reset_runtime
      self.fog_runtime = fog_rt_before_render + fog_rt_after_render
      runtime - fog_rt_after_render
    end

    def append_info_to_payload(payload)
      super
      payload[:fog_runtime] = fog_runtime
    end

    module ClassMethods
      def log_process_action(payload)
        fog_requests = FogInstrumentation::LogSubscriber.reset_count
        messages, fog_runtime = super, payload[:fog_runtime]

        messages << ("Fog: %.1fms, %d reqs" % [fog_runtime.to_f, fog_requests]) if fog_runtime
        messages
      end
    end
  end
  
end

FogInstrumentation::LogSubscriber.attach_to :fog
ActiveSupport.on_load(:action_controller) do
  include FogInstrumentation::ControllerRuntime
end