Merge pull request #598 from rest-client/ab-log-response-time

Track start/end times on response objects.

lib/restclient/abstract_response.rb

@@ -5,12 +5,27 @@ module RestClient
 
   module AbstractResponse
 
-    attr_reader :net_http_res, :request
+    attr_reader :net_http_res, :request, :start_time, :end_time, :duration
 
     def inspect
       raise NotImplementedError.new('must override in subclass')
     end
 
+    # Logger from the request, potentially nil.
+    def log
+      request.log
+    end
+
+    def log_response
+      return unless log
+
+      code = net_http_res.code
+      res_name = net_http_res.class.to_s.gsub(/\ANet::HTTP/, '')
+      content_type = (net_http_res['Content-type'] || '').gsub(/;.*\z/, '')
+
+      log << "# => #{code} #{res_name} | #{content_type} #{size} bytes, #{sprintf('%.2f', duration)}s\n"
+    end
+
     # HTTP status code
     def code
       @code ||= @net_http_res.code.to_i
@@ -31,9 +46,20 @@ module RestClient
       @raw_headers ||= @net_http_res.to_hash
     end
 
-    def response_set_vars(net_http_res, request)
+    # @param [Net::HTTPResponse] net_http_res
+    # @param [RestClient::Request] request
+    # @param [Time] start_time
+    def response_set_vars(net_http_res, request, start_time)
       @net_http_res = net_http_res
       @request = request
+      @start_time = start_time
+      @end_time = Time.now
+
+      if @start_time
+        @duration = @end_time - @start_time
+      else
+        @duration = nil
+      end
 
       # prime redirection history
       history

lib/restclient/raw_response.rb

@@ -13,25 +13,36 @@ module RestClient
 
     include AbstractResponse
 
-    attr_reader :file, :request
+    attr_reader :file, :request, :start_time, :end_time
 
     def inspect
       "<RestClient::RawResponse @code=#{code.inspect}, @file=#{file.inspect}, @request=#{request.inspect}>"
     end
 
-    def initialize(tempfile, net_http_res, request)
+    # @param [Tempfile] tempfile The temporary file containing the body
-      @net_http_res = net_http_res
+    # @param [Net::HTTPResponse] net_http_res
+    # @param [RestClient::Request] request
+    # @param [Time] start_time
+    def initialize(tempfile, net_http_res, request, start_time=nil)
       @file = tempfile
-      @request = request
+
+      # reopen the tempfile so we can read it
+      @file.open
+
+      response_set_vars(net_http_res, request, start_time)
     end
 
     def to_s
-      @file.open
+      body
+    end
+
+    def body
+      @file.rewind
       @file.read
     end
 
     def size
-      File.size file
+      file.size
     end
 
   end

lib/restclient/request.rb

@@ -98,6 +98,12 @@ module RestClient
       @block_response = args[:block_response]
       @raw_response = args[:raw_response] || false
 
+      @stream_log_percent = args[:stream_log_percent] || 10
+      if @stream_log_percent <= 0 || @stream_log_percent > 100
+        raise ArgumentError.new(
+          "Invalid :stream_log_percent #{@stream_log_percent.inspect}")
+      end
+
       @proxy = args.fetch(:proxy) if args.include?(:proxy)
 
       @ssl_opts = {}
@@ -138,7 +144,6 @@ module RestClient
       end
 
       @log = args[:log]
-      @tf = nil # If you are a raw request, this is your tempfile
       @max_redirects = args[:max_redirects] || 10
       @processed_headers = make_headers headers
       @args = args
@@ -548,18 +553,6 @@ module RestClient
       log << out.join(', ') + "\n"
     end
 
-    def log_response res
-      return unless log
-
-      size = if @raw_response
-               File.size(@tf.path)
-             else
-               res.body.nil? ? 0 : res.body.size
-             end
-
-      log << "# => #{res.code} #{res.class.to_s.gsub(/^Net::HTTP/, '')} | #{(res['Content-type'] || '').gsub(/;.*$/, '')} #{size} bytes\n"
-    end
-
     # Return a hash of headers whose keys are capitalized strings
     def stringify_headers headers
       headers.inject({}) do |result, (key, value)|
@@ -724,6 +717,9 @@ module RestClient
 
       log_request
 
+      start_time = Time.now
+      tempfile = nil
+
       net.start do |http|
         established_connection = true
 
@@ -731,10 +727,16 @@ module RestClient
           net_http_do_request(http, req, payload, &@block_response)
         else
           res = net_http_do_request(http, req, payload) { |http_response|
-            fetch_body(http_response)
+            if @raw_response
+              # fetch body into tempfile
+              tempfile = fetch_body_to_tempfile(http_response)
+            else
+              # fetch body
+              http_response.read_body
+            end
+            http_response
           }
-          log_response res
+          process_result(res, start_time, tempfile, &block)
-          process_result res, & block
         end
       end
     rescue EOFError
@@ -777,44 +779,50 @@ module RestClient
       req.basic_auth(user, password) if user && !headers.has_key?("Authorization")
     end
 
-    def fetch_body(http_response)
+    def fetch_body_to_tempfile(http_response)
-      if @raw_response
+      # Taken from Chef, which as in turn...
-        # Taken from Chef, which as in turn...
+      # Stolen from http://www.ruby-forum.com/topic/166423
-        # Stolen from http://www.ruby-forum.com/topic/166423
+      # Kudos to _why!
-        # Kudos to _why!
+      tf = Tempfile.new('rest-client.')
-        @tf = Tempfile.new('rest-client.')
+      tf.binmode
-        @tf.binmode
+
-        size, total = 0, http_response['Content-Length'].to_i
+      size = 0
-        http_response.read_body do |chunk|
+      total = http_response['Content-Length'].to_i
-          @tf.write chunk
+      stream_log_bucket = nil
-          size += chunk.size
+
-          if log
+      http_response.read_body do |chunk|
-            if size == 0
+        tf.write chunk
-              log << "%s %s done (0 length file)\n" % [@method, @url]
+        size += chunk.size
-            elsif total == 0
+        if log
-              log << "%s %s (zero content length)\n" % [@method, @url]
+          if total == 0
-            else
+            log << "streaming %s %s (%d of unknown) [0 Content-Length]\n" % [@method.upcase, @url, size]
-              log << "%s %s %d%% done (%d of %d)\n" % [@method, @url, (size * 100) / total, size, total]
+          else
+            percent = (size * 100) / total
+            current_log_bucket, _ = percent.divmod(@stream_log_percent)
+            if current_log_bucket != stream_log_bucket
+              stream_log_bucket = current_log_bucket
+              log << "streaming %s %s %d%% done (%d of %d)\n" % [@method.upcase, @url, (size * 100) / total, size, total]
             end
           end
         end
-        @tf.close
-        @tf
-      else
-        http_response.read_body
       end
-      http_response
+      tf.close
+      tf
     end
 
-    def process_result res, & block
+    # @param res The Net::HTTP response object
+    # @param start_time [Time] Time of request start
+    def process_result(res, start_time, tempfile=nil, &block)
       if @raw_response
         # We don't decode raw requests
-        response = RawResponse.new(@tf, res, self)
+        response = RawResponse.new(tempfile, res, self, start_time)
       else
         decoded = Request.decode(res['content-encoding'], res.body)
-        response = Response.create(decoded, res, self)
+        response = Response.create(decoded, res, self, start_time)
       end
 
+      response.log_response
+
       if block_given?
         block.call(response, self, res, & block)
       else

lib/restclient/response.rb

@@ -38,19 +38,25 @@ module RestClient
       "<RestClient::Response #{code.inspect} #{body_truncated(10).inspect}>"
     end
 
-    def log
+    # Initialize a Response object. Because RestClient::Response is
-      request.log
+    # (unfortunately) a subclass of String for historical reasons,
-    end
+    # Response.create is the preferred initializer.
-
+    #
-    def self.create(body, net_http_res, request)
+    # @param [String, nil] body The response body from the Net::HTTPResponse
+    # @param [Net::HTTPResponse] net_http_res
+    # @param [RestClient::Request] request
+    # @param [Time] start_time
+    def self.create(body, net_http_res, request, start_time=nil)
       result = self.new(body || '')
 
-      result.response_set_vars(net_http_res, request)
+      result.response_set_vars(net_http_res, request, start_time)
       fix_encoding(result)
 
       result
     end
 
+    # Set the String encoding according to the 'Content-Type: charset' header,
+    # if possible.
     def self.fix_encoding(response)
       charset = RestClient::Utils.get_encoding_from_headers(response.headers)
       encoding = nil

spec/helpers.rb

@@ -1,10 +1,36 @@
 require 'uri'
 
 module Helpers
-  def response_double(opts={})
+
-    double('response', {:to_hash => {}}.merge(opts))
+  # @param [Hash] opts A hash of methods, passed directly to the double
+  #   definition. Use this to stub other required methods.
+  #
+  # @return double for Net::HTTPResponse
+  def res_double(opts={})
+    instance_double('Net::HTTPResponse', {to_hash: {}, body: 'response body'}.merge(opts))
   end
 
+  # Given a Net::HTTPResponse or double and a Request or double, create a
+  # RestClient::Response object.
+  #
+  # @param net_http_res_double an rspec double for Net::HTTPResponse
+  # @param request A RestClient::Request or rspec double
+  #
+  # @return [RestClient::Response]
+  #
+  def response_from_res_double(net_http_res_double, request=nil, duration: 1)
+    request ||= request_double()
+    start_time = Time.now - duration
+
+    response = RestClient::Response.create(net_http_res_double.body, net_http_res_double, request, start_time)
+
+    # mock duration to ensure it gets the value we expect
+    allow(response).to receive(:duration).and_return(duration)
+
+    response
+  end
+
+  # Redirect stderr to a string for the duration of the passed block.
   def fake_stderr
     original_stderr = $stderr
     $stderr = StringIO.new
@@ -14,9 +40,11 @@ module Helpers
     $stderr = original_stderr
   end
 
+  # Create a double for RestClient::Request
   def request_double(url: 'http://example.com', method: 'get')
-    double('request', url: url, uri: URI.parse(url), method: method,
+    instance_double('RestClient::Request',
-           user: nil, password: nil, cookie_jar: HTTP::CookieJar.new,
+      url: url, uri: URI.parse(url), method: method, user: nil, password: nil,
-           redirection_history: nil, args: {url: url, method: method})
+      cookie_jar: HTTP::CookieJar.new, redirection_history: nil,
+      args: {url: url, method: method})
   end
 end

spec/unit/abstract_response_spec.rb

@@ -2,21 +2,21 @@ require_relative '_lib'
 
 describe RestClient::AbstractResponse, :include_helpers do
 
+  # Sample class implementing AbstractResponse used for testing.
   class MyAbstractResponse
 
     include RestClient::AbstractResponse
 
     attr_accessor :size
 
-    def initialize net_http_res, request
+    def initialize(net_http_res, request)
-      @net_http_res = net_http_res
+      response_set_vars(net_http_res, request, Time.now - 1)
-      @request = request
     end
 
   end
 
   before do
-    @net_http_res = double('net http response')
+    @net_http_res = res_double()
     @request = request_double(url: 'http://example.com', method: 'get')
     @response = MyAbstractResponse.new(@net_http_res, @request)
   end
@@ -92,8 +92,8 @@ describe RestClient::AbstractResponse, :include_helpers do
     it 'handles cookies when URI scheme is implicit' do
       net_http_res = double('net http response')
       expect(net_http_res).to receive(:to_hash).and_return('set-cookie' => ['session_id=1; path=/'])
-      request = double(url: 'example.com', uri: URI.parse('http://example.com'),
+      request = double('request', url: 'example.com', uri: URI.parse('http://example.com'),
-                       method: 'get', cookie_jar: HTTP::CookieJar.new)
+                       method: 'get', cookie_jar: HTTP::CookieJar.new, redirection_history: nil)
       response = MyAbstractResponse.new(net_http_res, request)
       expect(response.cookie_jar).to be_a HTTP::CookieJar
 
@@ -135,7 +135,7 @@ describe RestClient::AbstractResponse, :include_helpers do
     end
 
     it "should gracefully handle 302 redirect with no location header" do
-      @net_http_res = response_double(code: 302, location: nil)
+      @net_http_res = res_double(code: 302)
       @request = request_double()
       @response = MyAbstractResponse.new(@net_http_res, @request)
       expect(@response).to receive(:check_max_redirects).and_return('fake-check')

spec/unit/raw_response_spec.rb

@@ -2,9 +2,9 @@ require_relative '_lib'
 
 describe RestClient::RawResponse do
   before do
-    @tf = double("Tempfile", :read => "the answer is 42", :open => true)
+    @tf = double("Tempfile", :read => "the answer is 42", :open => true, :rewind => true)
     @net_http_res = double('net http response')
-    @request = double('http request')
+    @request = double('restclient request', :redirection_history => nil)
     @response = RestClient::RawResponse.new(@tf, @net_http_res, @request)
   end
 
@@ -15,4 +15,8 @@ describe RestClient::RawResponse do
   it "exposes a Tempfile" do
     expect(@response.file).to eq @tf
   end
+
+  it "includes AbstractResponse" do
+    expect(RestClient::RawResponse.ancestors).to include(RestClient::AbstractResponse)
+  end
 end

spec/unit/request_spec.rb

@@ -52,21 +52,21 @@ describe RestClient::Request, :include_helpers do
   end
 
   it "processes a successful result" do
-    res = response_double
+    res = res_double
     allow(res).to receive(:code).and_return("200")
     allow(res).to receive(:body).and_return('body')
     allow(res).to receive(:[]).with('content-encoding').and_return(nil)
-    expect(@request.send(:process_result, res).body).to eq 'body'
+    expect(@request.send(:process_result, res, Time.now).body).to eq 'body'
-    expect(@request.send(:process_result, res).to_s).to eq 'body'
+    expect(@request.send(:process_result, res, Time.now).to_s).to eq 'body'
   end
 
   it "doesn't classify successful requests as failed" do
     203.upto(207) do |code|
-      res = response_double
+      res = res_double
       allow(res).to receive(:code).and_return(code.to_s)
       allow(res).to receive(:body).and_return("")
       allow(res).to receive(:[]).with('content-encoding').and_return(nil)
-      expect(@request.send(:process_result, res)).to be_empty
+      expect(@request.send(:process_result, res, Time.now)).to be_empty
     end
   end
 
@@ -535,25 +535,25 @@ describe RestClient::Request, :include_helpers do
 
   describe "exception" do
     it "raises Unauthorized when the response is 401" do
-      res = response_double(:code => '401', :[] => ['content-encoding' => ''], :body => '' )
+      res = res_double(:code => '401', :[] => ['content-encoding' => ''], :body => '' )
-      expect { @request.send(:process_result, res) }.to raise_error(RestClient::Unauthorized)
+      expect { @request.send(:process_result, res, Time.now) }.to raise_error(RestClient::Unauthorized)
     end
 
     it "raises ResourceNotFound when the response is 404" do
-      res = response_double(:code => '404', :[] => ['content-encoding' => ''], :body => '' )
+      res = res_double(:code => '404', :[] => ['content-encoding' => ''], :body => '' )
-      expect { @request.send(:process_result, res) }.to raise_error(RestClient::ResourceNotFound)
+      expect { @request.send(:process_result, res, Time.now) }.to raise_error(RestClient::ResourceNotFound)
     end
 
     it "raises RequestFailed otherwise" do
-      res = response_double(:code => '500', :[] => ['content-encoding' => ''], :body => '' )
+      res = res_double(:code => '500', :[] => ['content-encoding' => ''], :body => '' )
-      expect { @request.send(:process_result, res) }.to raise_error(RestClient::InternalServerError)
+      expect { @request.send(:process_result, res, Time.now) }.to raise_error(RestClient::InternalServerError)
     end
   end
 
   describe "block usage" do
     it "returns what asked to" do
-      res = response_double(:code => '401', :[] => ['content-encoding' => ''], :body => '' )
+      res = res_double(:code => '401', :[] => ['content-encoding' => ''], :body => '' )
-      expect(@request.send(:process_result, res){|response, request| "foo"}).to eq "foo"
+      expect(@request.send(:process_result, res, Time.now){|response, request| "foo"}).to eq "foo"
     end
   end
 
@@ -667,26 +667,29 @@ describe RestClient::Request, :include_helpers do
 
     it "logs a response including the status code, content type, and result body size in bytes" do
       log = RestClient.log = []
-      res = double('result', :code => '200', :class => Net::HTTPOK, :body => 'abcd')
+      res = res_double(code: '200', class: Net::HTTPOK, body: 'abcd')
       allow(res).to receive(:[]).with('Content-type').and_return('text/html')
-      @request.log_response res
+      response = response_from_res_double(res, @request)
-      expect(log[0]).to eq "# => 200 OK | text/html 4 bytes\n"
+      response.log_response
+      expect(log).to eq ["# => 200 OK | text/html 4 bytes, 1.00s\n"]
     end
 
     it "logs a response with a nil Content-type" do
       log = RestClient.log = []
-      res = double('result', :code => '200', :class => Net::HTTPOK, :body => 'abcd')
+      res = res_double(code: '200', class: Net::HTTPOK, body: 'abcd')
       allow(res).to receive(:[]).with('Content-type').and_return(nil)
-      @request.log_response res
+      response = response_from_res_double(res, @request)
-      expect(log[0]).to eq "# => 200 OK |  4 bytes\n"
+      response.log_response
+      expect(log).to eq ["# => 200 OK |  4 bytes, 1.00s\n"]
     end
 
     it "logs a response with a nil body" do
       log = RestClient.log = []
-      res = double('result', :code => '200', :class => Net::HTTPOK, :body => nil)
+      res = res_double(code: '200', class: Net::HTTPOK, body: nil)
       allow(res).to receive(:[]).with('Content-type').and_return('text/html; charset=utf-8')
-      @request.log_response res
+      response = response_from_res_double(res, @request)
-      expect(log[0]).to eq "# => 200 OK | text/html 0 bytes\n"
+      response.log_response
+      expect(log).to eq ["# => 200 OK | text/html 0 bytes, 1.00s\n"]
     end
 
     it 'does not log request password' do
@@ -704,10 +707,11 @@ describe RestClient::Request, :include_helpers do
 
   it "strips the charset from the response content type" do
     log = RestClient.log = []
-    res = double('result', :code => '200', :class => Net::HTTPOK, :body => 'abcd')
+    res = res_double(code: '200', class: Net::HTTPOK, body: 'abcd')
     allow(res).to receive(:[]).with('Content-type').and_return('text/html; charset=utf-8')
-    @request.log_response res
+    response = response_from_res_double(res, @request)
-    expect(log[0]).to eq "# => 200 OK | text/html 4 bytes\n"
+    response.log_response
+    expect(log).to eq ["# => 200 OK | text/html 4 bytes, 1.00s\n"]
   end
 
   describe "timeout" do
@@ -1155,7 +1159,7 @@ describe RestClient::Request, :include_helpers do
     )
     net_http_res = Net::HTTPNoContent.new("", "204", "No Content")
     allow(net_http_res).to receive(:read_body).and_return(nil)
-    expect(@http).to receive(:request).and_return(@request.send(:fetch_body, net_http_res))
+    expect(@http).to receive(:request).and_return(net_http_res)
     response = @request.send(:transmit, @uri, 'req', 'payload')
     expect(response).not_to be_nil
     expect(response.code).to eq 204
@@ -1173,7 +1177,8 @@ describe RestClient::Request, :include_helpers do
 
       net_http_res = Net::HTTPOK.new(nil, "200", "body")
       allow(net_http_res).to receive(:read_body).and_return("body")
-      @request.send(:fetch_body, net_http_res)
+      received_tempfile = @request.send(:fetch_body_to_tempfile, net_http_res)
+      expect(received_tempfile).to eq tempfile
     end
   end
 

spec/unit/response_spec.rb

@@ -2,10 +2,10 @@ require_relative '_lib'
 
 describe RestClient::Response, :include_helpers do
   before do
-    @net_http_res = double('net http response', :to_hash => {"Status" => ["200 OK"]}, :code => 200)
+    @net_http_res = res_double(to_hash: {'Status' => ['200 OK']}, code: '200', body: 'abc')
     @example_url = 'http://example.com'
     @request = request_double(url: @example_url, method: 'get')
-    @response = RestClient::Response.create('abc', @net_http_res, @request)
+    @response = response_from_res_double(@net_http_res, @request, duration: 1)
   end
 
   it "behaves like string" do
@@ -17,6 +17,7 @@ describe RestClient::Response, :include_helpers do
   end
 
   it "accepts nil strings and sets it to empty for the case of HEAD" do
+    # TODO
     expect(RestClient::Response.create(nil, @net_http_res, @request).to_s).to eq ""
   end
 
@@ -27,13 +28,13 @@ describe RestClient::Response, :include_helpers do
     end
 
     it 'handles multiple headers by joining with comma' do
-      @net_http_res = double('net http response', :to_hash => {'My-Header' => ['foo', 'bar']}, :code => 200)
+      net_http_res = res_double(to_hash: {'My-Header' => ['foo', 'bar']}, code: '200', body: nil)
-      @example_url = 'http://example.com'
+      example_url = 'http://example.com'
-      @request = request_double(url: @example_url, method: 'get')
+      request = request_double(url: example_url, method: 'get')
-      @response = RestClient::Response.create('abc', @net_http_res, @request)
+      response = response_from_res_double(net_http_res, request)
 
-      expect(@response.raw_headers['My-Header']).to eq ['foo', 'bar']
+      expect(response.raw_headers['My-Header']).to eq ['foo', 'bar']
-      expect(@response.headers[:my_header]).to eq 'foo, bar'
+      expect(response.headers[:my_header]).to eq 'foo, bar'
     end
   end
 
@@ -72,7 +73,7 @@ describe RestClient::Response, :include_helpers do
   describe "exceptions processing" do
     it "should return itself for normal codes" do
       (200..206).each do |code|
-        net_http_res = response_double(:code => '200')
+        net_http_res = res_double(:code => '200')
         resp = RestClient::Response.create('abc', net_http_res, @request)
         resp.return!
       end
@@ -81,7 +82,7 @@ describe RestClient::Response, :include_helpers do
     it "should throw an exception for other codes" do
       RestClient::Exceptions::EXCEPTIONS_MAP.each_pair do |code, exc|
         unless (200..207).include? code
-          net_http_res = response_double(:code => code.to_i)
+          net_http_res = res_double(:code => code.to_i)
           resp = RestClient::Response.create('abc', net_http_res, @request)
           allow(@request).to receive(:max_redirects).and_return(5)
           expect { resp.return! }.to raise_error(exc)
@@ -131,28 +132,27 @@ describe RestClient::Response, :include_helpers do
     end
 
     it "doesn't follow a 301 when the request is a post" do
-      net_http_res = response_double(:code => 301)
+      net_http_res = res_double(:code => 301)
+      response = response_from_res_double(net_http_res, request_double(method: 'post'))
 
-      response = RestClient::Response.create('abc', net_http_res,
-                                             request_double(method: 'post'))
       expect {
         response.return!
       }.to raise_error(RestClient::MovedPermanently)
     end
 
     it "doesn't follow a 302 when the request is a post" do
-      net_http_res = response_double(:code => 302)
+      net_http_res = res_double(:code => 302)
-      response = RestClient::Response.create('abc', net_http_res,
+      response = response_from_res_double(net_http_res, request_double(method: 'post'))
-                                             request_double(method: 'post'))
+
       expect {
         response.return!
       }.to raise_error(RestClient::Found)
     end
 
     it "doesn't follow a 307 when the request is a post" do
-      net_http_res = response_double(:code => 307)
+      net_http_res = res_double(:code => 307)
-      response = RestClient::Response.create('abc', net_http_res,
+      response = response_from_res_double(net_http_res, request_double(method: 'post'))
-                                             request_double(method: 'post'))
+
       expect(response).not_to receive(:follow_redirection)
       expect {
         response.return!
@@ -160,9 +160,8 @@ describe RestClient::Response, :include_helpers do
     end
 
     it "doesn't follow a redirection when the request is a put" do
-      net_http_res = response_double(:code => 301)
+      net_http_res = res_double(:code => 301)
-      response = RestClient::Response.create('abc', net_http_res,
+      response = response_from_res_double(net_http_res, request_double(method: 'put'))
-                                             request_double(method: 'put'))
       expect {
         response.return!
       }.to raise_error(RestClient::MovedPermanently)