Add DetailedLogSubscriber to more easily debug ActiveResource requests/responses

lib/active_resource/connection_ext.rb

@@ -2,15 +2,30 @@ require 'active_support/core_ext/module/aliasing'
 
 module ActiveResource
   class Connection
-    
+
     attr_reader :response
-    
+
     def handle_response_with_response_capture(response)
       @response = handle_response_without_response_capture(response)
     end
-    
+
+    def request_with_detailed_log_subscriber(method, path, *arguments)
+      result = request_without_detailed_log_subscriber(method, path, *arguments)
+      detailed_log_subscriber(result, arguments)
+      result
+    rescue => e
+      detailed_log_subscriber(e.response, arguments) if e.respond_to?(:response)
+      raise
+    end
+
+    def detailed_log_subscriber(response, arguments)
+      ActiveSupport::Notifications.instrument("request.active_resource_detailed") do |payload|
+        payload[:response] = response
+        payload[:data]     = arguments
+      end
+    end
+
     alias_method_chain :handle_response, :response_capture
-    # alias_method :handle_response_without_instance, :handle_response
-    # alias_method :handle_response, :handle_response_with_instance
+    alias_method_chain :request, :detailed_log_subscriber
   end
-end
+end

lib/active_resource/detailed_log_subscriber.rb

@@ -0,0 +1,19 @@
+module ActiveResource
+  class DetailedLogSubscriber < ActiveSupport::LogSubscriber
+    def request(event)
+      data = event.payload[:data]
+      headers = data.extract_options!
+      request_body = data.first
+
+      info "Request:\n#{request_body}" if request_body
+      info "Headers: #{headers.inspect}"
+      info "Response:\n#{event.payload[:response].body}"
+    end
+
+    def logger
+      ActiveResource::Base.logger
+    end
+  end
+end
+
+ActiveResource::DetailedLogSubscriber.attach_to :active_resource_detailed

lib/shopify_api.rb

@@ -5,6 +5,7 @@ require 'active_support/core_ext/class/attribute_accessors'
 require 'digest/md5'
 require 'base64'
 require 'active_resource/connection_ext'
+require 'active_resource/detailed_log_subscriber'
 require 'shopify_api/limits'
 require 'shopify_api/json_format'
 require 'active_resource/json_errors'

test/detailed_log_subscriber_test.rb

@@ -0,0 +1,46 @@
+require 'test_helper'
+require "active_support/log_subscriber/test_helper"
+
+class LogSubscriberTest < Test::Unit::TestCase
+  include ActiveSupport::LogSubscriber::TestHelper
+
+  def setup
+    super
+    @page = { :page => { :id => 1, :title => 'Shopify API' } }.to_json
+
+    ShopifyAPI::Base.site = "http://localhost/admin"
+
+    ActiveResource::LogSubscriber.attach_to :active_resource
+    ActiveResource::DetailedLogSubscriber.attach_to :active_resource_detailed
+  end
+
+  def set_logger(logger)
+    ActiveResource::Base.logger = logger
+  end
+
+  test "logging on #find" do
+    fake "pages/1", :method => :get, :body => @page
+
+    ShopifyAPI::Page.find(1)
+
+    assert_equal 4, @logger.logged(:info).size
+    assert_equal "GET http://localhost:80/admin/pages/1.json",                  @logger.logged(:info)[0]
+    assert_match /\-\-\> 200/,                                                  @logger.logged(:info)[1]
+    assert_equal "Headers: {\"Accept\"=>\"application/json\"}",                 @logger.logged(:info)[2]
+    assert_equal "Response:\n{\"page\":{\"title\":\"Shopify API\",\"id\":1}}",  @logger.logged(:info)[3]
+  end
+
+  test "logging on #find with an error" do
+    fake "pages/2", :method => :get, :body => nil, :status => 404
+
+    assert_raise ActiveResource::ResourceNotFound do
+      ShopifyAPI::Page.find(2)
+    end
+
+    assert_equal 4, @logger.logged(:info).size
+    assert_equal "GET http://localhost:80/admin/pages/2.json",  @logger.logged(:info)[0]
+    assert_match /\-\-\> 404/,                                  @logger.logged(:info)[1]
+    assert_equal "Headers: {\"Accept\"=>\"application/json\"}", @logger.logged(:info)[2]
+    assert_equal "Response:",                                   @logger.logged(:info)[3]
+  end
+end

test/test_helper.rb

@@ -49,7 +49,7 @@ class Test::Unit::TestCase
   end
 
   def fake(endpoint, options={})
-    body = options.delete(:body) || load_fixture(endpoint)
+    body   = options.has_key?(:body) ? options.delete(:body) : load_fixture(endpoint)
     format = options.delete(:format) || :json
     method = options.delete(:method) || :get
     extension = ".#{options.delete(:extension)||'json'}" unless options[:extension]==false