Merge pull request #225 from AlanFoster/add-additional-request-tracking

Add additional request tracking

README.md

@@ -285,6 +285,7 @@ Billy.configure do |c|
   c.proxy_port = 12345 # defaults to random
   c.proxied_request_host = nil
   c.proxied_request_port = 80
+  c.record_requests = true # defaults to false
   c.cache_request_body_methods = ['post', 'patch', 'put'] # defaults to ['post']
 end
 ```
@@ -367,6 +368,64 @@ directory/puffing-billy/certs`.
 `c.proxied_request_host` and `c.proxied_request_port` are used if an internal proxy
 server is required to access the internet.  Most common in larger companies.
 
+`c.record_requests` can be used to record all requests that puffing billy proxied.
+This can be useful for debugging purposes, for instance if you are unsure why
+your stubbed requests are not being successfully proxied.
+
+Example usage:
+
+```ruby
+require 'table_print' # Add this dependency to your gemfile
+
+Billy.configure do |c|
+  c.record_requests = true
+end
+
+RSpec.configure do |config|
+  config.prepend_after(:example, type: :feature) do
+    puts "Requests received via Puffing Billy Proxy:"
+
+    puts TablePrint::Printer.table_print(Billy.proxy.requests, [
+      :status,
+      :handler,
+      :method,
+      { url: { width: 100 } },
+      :headers,
+      :body
+    ])
+  end
+end
+```
+
+This will generate a human readable list of all requests after each test run:
+
+```
+Requests received via Puffing Billy Proxy:
+STATUS   | HANDLER | METHOD  | URL                                     | HEADERS                        | BODY
+---------|---------|---------|-----------------------------------------|--------------------------------|-----
+complete | proxy   | GET     | http://127.0.0.1:56692/                 | {"Accept"=>"text/html,appli... |
+complete | proxy   | GET     | http://127.0.0.1:56692/assets/appl...   | {"Accept"=>"text/css,*/*;q=... |
+complete | proxy   | GET     | http://127.0.0.1:56692/assets/app...    | {"Accept"=>"*/*", "Referer"... |
+complete | proxy   | GET     | http://127.0.0.1:56692/javascript/index | {"Accept"=>"text/html,appli... |
+complete | stubs   | OPTIONS | https://api.github.com:443/             | {"Access-Control-Request-Me... |
+complete | stubs   | GET     | https://api.github.com:443/             | {"Accept"=>"*/*", "Referer"... |
+inflight |         | GET     | http://127.0.0.1:56692/example          | {"Referer"=>"http://127.0.0... |
+.
+
+Finished in 1.98 seconds (files took 2.11 seconds to load)
+1 example, 0 failures
+```
+
+The handler column indicates how Puffing Billy handled your request:
+
+- proxy: This request was successfully routed to the original target
+- stubs: This was handled via a stub
+- error: This request was not handled by a stub, and was not successfully handled
+- cache: This response was handled by a previous cache
+
+If your `status` is set to in_flight this request has not yet been handled fully. Either puffing billy crashed
+internally on this request, or your test ended before it could complete successfully.
+
 `c.cache_request_body_methods` is used to specify HTTP methods of requests that you would like to cache separately based on the contents of the request body. The default is ['post'].
 
 `c.after_cache_handles_request` is used to configure a callback that can operate on the response after it has been retrieved from the cache but before it is returned. The callback receives the request and response as arguments, with a request object like: `{ method: method, url: url, headers: headers, body: body }`. An example usage would be manipulating the Access-Control-Allow-Origin header so that your test server doesn't always have to run on the same port in order to accept cached responses to CORS requests:

lib/billy.rb

@@ -2,6 +2,7 @@
 require 'billy/config'
 require 'billy/handlers/handler'
 require 'billy/handlers/request_handler'
+require 'billy/handlers/request_log'
 require 'billy/handlers/stub_handler'
 require 'billy/handlers/proxy_handler'
 require 'billy/handlers/cache_handler'

lib/billy/config.rb

@@ -11,7 +11,7 @@ class Config
                   :non_whitelisted_requests_disabled, :cache_path, :certs_path, :proxy_host, :proxy_port, :proxied_request_inactivity_timeout,
                   :proxied_request_connect_timeout, :dynamic_jsonp, :dynamic_jsonp_keys, :dynamic_jsonp_callback_name, :merge_cached_responses_whitelist,
                   :strip_query_params, :proxied_request_host, :proxied_request_port, :cache_request_body_methods, :after_cache_handles_request,
-                  :cache_simulates_network_delays, :cache_simulates_network_delay_time, :record_stub_requests, :use_ignore_params
+                  :cache_simulates_network_delays, :cache_simulates_network_delay_time, :record_requests, :record_stub_requests, :use_ignore_params
 
     def initialize
       @logger = defined?(Rails) ? Rails.logger : Logger.new(STDOUT)
@@ -47,6 +47,7 @@ def reset
       @after_cache_handles_request = nil
       @cache_simulates_network_delays = false
       @cache_simulates_network_delay_time = 0.1
+      @record_requests = false
       @record_stub_requests = false
       @use_ignore_params = true
     end

lib/billy/handlers/request_handler.rb

@@ -6,6 +6,7 @@ class RequestHandler
     include Handler
 
     def_delegators :stub_handler, :stub, :unstub
+    def_delegators :request_log, :requests
 
     def handlers
       @handlers ||= { stubs: StubHandler.new,
@@ -14,14 +15,18 @@ def handlers
     end
 
     def handle_request(method, url, headers, body)
+      request = request_log.record(method, url, headers, body)
+
       # Process the handlers by order of importance
       [:stubs, :cache, :proxy].each do |key|
         if (response = handlers[key].handle_request(method, url, headers, body))
+          @request_log.complete(request, key)
           return response
         end
       end
 
       body_msg = Billy.config.cache_request_body_methods.include?(method) ? " with body '#{body}'" : ''
+      request_log.complete(request, :error)
       { error: "Connection to #{url}#{body_msg} not cached and new http connections are disabled" }
     rescue => error
       { error: error.message }
@@ -33,12 +38,17 @@ def handles_request?(method, url, headers, body)
       end
     end
 
+    def request_log
+      @request_log ||= RequestLog.new
+    end
+
     def stubs
       stub_handler.stubs
     end
 
     def reset
       handlers.each_value(&:reset)
+      request_log.reset
     end
 
     def reset_stubs

lib/billy/handlers/request_log.rb

@@ -0,0 +1,36 @@
+module Billy
+  class RequestLog
+    attr_reader :requests
+
+    def initialize
+      @requests = []
+    end
+
+    def reset
+      @requests = []
+    end
+
+    def record(method, url, headers, body)
+      return unless Billy.config.record_requests
+
+      request = {
+        status: :inflight,
+        handler: nil,
+        method: method,
+        url: url,
+        headers: headers,
+        body: body
+      }
+      @requests.push(request)
+
+      request
+    end
+
+    def complete(request, handler)
+      return unless Billy.config.record_requests
+
+      request.merge! status: :complete,
+                     handler: handler
+    end
+  end
+end

lib/billy/proxy.rb

@@ -6,7 +6,7 @@ class Proxy
     extend Forwardable
     attr_reader :request_handler
 
-    def_delegators :request_handler, :stub, :stubs, :unstub, :reset, :reset_cache, :restore_cache, :handle_request
+    def_delegators :request_handler, :stub, :stubs, :unstub, :reset, :reset_cache, :restore_cache, :requests, :handle_request
 
     def initialize
       @request_handler = Billy::RequestHandler.new

spec/lib/billy/handlers/request_handler_spec.rb

@@ -69,32 +69,40 @@
     end
 
     describe '#handle_request' do
+      before do
+        allow(Billy::config).to receive(:record_requests).and_return(true)
+      end
+
       it 'returns stubbed responses' do
         expect(stub_handler).to receive(:handle_request).with(*args).and_return('foo')
         expect(cache_handler).to_not receive(:handle_request)
         expect(proxy_handler).to_not receive(:handle_request)
         expect(subject.handle_request(*args)).to eql 'foo'
+        expect(subject.requests).to eql([{status: :complete, handler: :stubs, method: 'get', url: 'url', headers: 'headers', body: 'body'}])
       end
 
       it 'returns cached responses' do
         expect(stub_handler).to receive(:handle_request).with(*args)
         expect(cache_handler).to receive(:handle_request).with(*args).and_return('bar')
         expect(proxy_handler).to_not receive(:handle_request)
         expect(subject.handle_request(*args)).to eql 'bar'
+        expect(subject.requests).to eql([{status: :complete, handler: :cache, method: 'get', url: 'url', headers: 'headers', body: 'body'}])
       end
 
       it 'returns proxied responses' do
         expect(stub_handler).to receive(:handle_request).with(*args)
         expect(cache_handler).to receive(:handle_request).with(*args)
         expect(proxy_handler).to receive(:handle_request).with(*args).and_return('baz')
         expect(subject.handle_request(*args)).to eql 'baz'
+        expect(subject.requests).to eql([{status: :complete, handler: :proxy, method: 'get', url: 'url', headers: 'headers', body: 'body'}])
       end
 
       it 'returns an error hash if request is not handled' do
         expect(stub_handler).to receive(:handle_request).with(*args)
         expect(cache_handler).to receive(:handle_request).with(*args)
         expect(proxy_handler).to receive(:handle_request).with(*args)
         expect(subject.handle_request(*args)).to eql(error: 'Connection to url not cached and new http connections are disabled')
+        expect(subject.requests).to eql([{status: :complete, handler: :error, method: 'get', url: 'url', headers: 'headers', body: 'body'}])
       end
 
       it 'returns an error hash with body message if request cached based on body is not handled' do
@@ -103,6 +111,7 @@
         expect(cache_handler).to receive(:handle_request).with(*args)
         expect(proxy_handler).to receive(:handle_request).with(*args)
         expect(subject.handle_request(*args)).to eql(error: "Connection to url with body 'body' not cached and new http connections are disabled")
+        expect(subject.requests).to eql([{status: :complete, handler: :error, method: 'post', url: 'url', headers: 'headers', body: 'body'}])
       end
 
       it 'returns an error hash on unhandled exceptions' do
@@ -140,6 +149,7 @@
         handlers.each do |_key, handler|
           expect(handler).to receive(:reset)
         end
+        expect(subject.request_log).to receive(:reset)
         subject.reset
       end
     end

spec/lib/billy/handlers/request_log_spec.rb

@@ -0,0 +1,74 @@
+require 'spec_helper'
+
+describe Billy::RequestLog do
+  let(:request_log) { Billy::RequestLog.new }
+
+  describe '#record' do
+    it 'returns the request details if record_requests is enabled' do
+      allow(Billy::config).to receive(:record_requests).and_return(true)
+      expected_request = {
+        status: :inflight,
+        handler: nil,
+        method: :method,
+        url: :url,
+        headers: :headers,
+        body: :body
+      }
+      expect(request_log.record(:method, :url, :headers, :body)).to eql(expected_request)
+    end
+
+    it 'returns nil if record_requests is disabled' do
+      allow(Billy::config).to receive(:record_requests).and_return(false)
+      expect(request_log.record(:method, :url, :headers, :body)).to be_nil
+    end
+  end
+
+  describe '#complete' do
+    it 'marks the request as complete if record_requests is enabled' do
+      allow(Billy::config).to receive(:record_requests).and_return(true)
+
+      request = request_log.record(:method, :url, :headers, :body)
+      expected_request = {
+        status: :complete,
+        handler: :handler,
+        method: :method,
+        url: :url,
+        headers: :headers,
+        body: :body
+      }
+      expect(request_log.complete(request, :handler)).to eql(expected_request)
+    end
+
+    it 'marks the request as complete if record_requests is disabled' do
+      allow(Billy::config).to receive(:record_requests).and_return(false)
+      expect(request_log.complete(nil, :handler)).to be_nil
+    end
+  end
+
+  describe '#requests' do
+    it 'returns an empty array when there are no requests' do
+      expect(request_log.requests).to be_empty
+    end
+
+    it 'returns the currently known requests' do
+      allow(Billy::config).to receive(:record_requests).and_return(true)
+
+      request1 = request_log.record(:method, :url, :headers, :body)
+      request2 = request_log.record(:method, :url, :headers, :body)
+      expect(request_log.requests).to eql([request1, request2])
+    end
+  end
+
+  describe '#reset' do
+    it 'resets known requests' do
+      allow(Billy::config).to receive(:record_requests).and_return(true)
+
+      request1 = request_log.record(:method, :url, :headers, :body)
+      request2 = request_log.record(:method, :url, :headers, :body)
+      expect(request_log.requests).to eql([request1, request2])
+
+      request_log.reset
+      expect(request_log.requests).to be_empty
+    end
+  end
+end