From e885c18a2bb1993a47624fbf45c9caa72d4a7542 Mon Sep 17 00:00:00 2001 From: Lucas Uyezu Date: Fri, 16 Aug 2013 15:59:23 -0300 Subject: [PATCH 1/6] Added initial logging support. --- lib/httparty.rb | 13 ++++++ lib/httparty/logger/apache_logger.rb | 27 +++++++++++ lib/httparty/logger/curl_logger.rb | 52 ++++++++++++++++++++++ lib/httparty/logger/logger.rb | 18 ++++++++ lib/httparty/request.rb | 4 ++ lib/httparty/response.rb | 5 +++ spec/httparty/logger/apache_logger_spec.rb | 26 +++++++++++ spec/httparty/logger/curl_logger_spec.rb | 21 +++++++++ spec/httparty/logger/logger_spec.rb | 22 +++++++++ spec/httparty/request_spec.rb | 8 +++- 10 files changed, 195 insertions(+), 1 deletion(-) create mode 100644 lib/httparty/logger/apache_logger.rb create mode 100644 lib/httparty/logger/curl_logger.rb create mode 100644 lib/httparty/logger/logger.rb create mode 100644 spec/httparty/logger/apache_logger_spec.rb create mode 100644 spec/httparty/logger/curl_logger_spec.rb create mode 100644 spec/httparty/logger/logger_spec.rb diff --git a/lib/httparty.rb b/lib/httparty.rb index 4db00076..30c5eb2b 100644 --- a/lib/httparty.rb +++ b/lib/httparty.rb @@ -11,6 +11,7 @@ require 'httparty/net_digest_auth' require 'httparty/version' require 'httparty/connection_adapter' +require 'httparty/logger/logger' # @see HTTParty::ClassMethods module HTTParty @@ -70,6 +71,18 @@ module ClassMethods extend AllowedFormatsDeprecation + # Turns on logging + # + # class Foo + # include HTTParty + # logger Logger.new('http_logger'), :info, :apache + # end + def logger(logger, level=:info, format=:apache) + default_options[:logger] = logger + default_options[:log_level] = level + default_options[:log_format] = format + end + # Allows setting http proxy information to be used # # class Foo diff --git a/lib/httparty/logger/apache_logger.rb b/lib/httparty/logger/apache_logger.rb new file mode 100644 index 00000000..8e4014f2 --- /dev/null +++ b/lib/httparty/logger/apache_logger.rb @@ -0,0 +1,27 @@ +module HTTParty + module Logger + class ApacheLogger #:nodoc: + TAG_NAME = HTTParty.name + + attr_accessor :level, :logger, :current_time + + def initialize(logger, level) + @logger = logger + @level = level.to_sym + end + + def format(request, response) + @current_time ||= Time.new.strftime("%Y-%m-%d %H:%M:%S.%L %z") + http_method = request.http_method.name.split("::").last.upcase + path = request.path.to_s + content_length = response['Content-Length'] + + print(response.code, content_length, http_method, path) + end + + def print(code, content_length, http_method, path) + @logger.send @level, "[#{TAG_NAME}] [#{@current_time}] #{code} \"#{http_method} #{path}\" #{content_length || "-"} " + end + end + end +end diff --git a/lib/httparty/logger/curl_logger.rb b/lib/httparty/logger/curl_logger.rb new file mode 100644 index 00000000..24e90571 --- /dev/null +++ b/lib/httparty/logger/curl_logger.rb @@ -0,0 +1,52 @@ +module HTTParty + module Logger + class CurlLogger #:nodoc: + TAG_NAME = HTTParty.name + + attr_accessor :level, :logger, :current_time + + def initialize(logger, level) + @logger = logger + @level = level.to_sym + end + + def format(request, response) + @messages = [] + @current_time ||= Time.new.strftime("%Y-%m-%d %H:%M:%S.%L %z") + http_method = request.http_method.name.split("::").last.upcase + path = request.path.to_s + + print_outgoing "#{http_method} #{path}" + if request.options[:headers] && request.options[:headers].size > 0 + request.options[:headers].each do |k, v| + print_outgoing "#{k}: #{v}" + end + end + + print_outgoing "" + print_incoming "HTTP/#{response.http_version} #{response.code}" + + headers = response.respond_to?(:headers) ? response.headers : response + response.each_header do |response_header| + print_incoming "#{response_header.capitalize}: #{headers[response_header]}" + end + + print_incoming "\n#{response.body}" + + @logger.send @level, @messages.join("\n") + end + + def print_outgoing(line) + @messages << print(">", line) + end + + def print_incoming(line) + @messages << print("<", line) + end + + def print(direction, line) + "[#{TAG_NAME}] [#{@current_time}] #{direction} #{line}" + end + end + end +end diff --git a/lib/httparty/logger/logger.rb b/lib/httparty/logger/logger.rb new file mode 100644 index 00000000..36f96fb3 --- /dev/null +++ b/lib/httparty/logger/logger.rb @@ -0,0 +1,18 @@ +require 'httparty/logger/apache_logger' +require 'httparty/logger/curl_logger' + +module HTTParty + module Logger + def self.build(logger, level, formatter) + level ||= :info + format ||= :apache + + case formatter + when :curl + Logger::CurlLogger.new(logger, level) + else + Logger::ApacheLogger.new(logger, level) + end + end + end +end diff --git a/lib/httparty/request.rb b/lib/httparty/request.rb index 1323de8d..c83c2c11 100644 --- a/lib/httparty/request.rb +++ b/lib/httparty/request.rb @@ -245,6 +245,10 @@ def encode_body(body) def handle_response(body, &block) if response_redirects? options[:limit] -= 1 + if options[:logger] + logger = HTTParty::Logger.build(options[:logger], options[:log_level], options[:log_format]) + logger.format(self, last_response) + end self.path = last_response['location'] self.redirect = true self.http_method = Net::HTTP::Get unless options[:maintain_method_across_redirects] diff --git a/lib/httparty/response.rb b/lib/httparty/response.rb index 9a97482e..90888f49 100644 --- a/lib/httparty/response.rb +++ b/lib/httparty/response.rb @@ -12,6 +12,11 @@ def initialize(request, response, parsed_block, options={}) @body = options[:body] || response.body @parsed_block = parsed_block @headers = Headers.new(response.to_hash) + + if request.options[:logger] + logger = ::HTTParty::Logger.build(request.options[:logger], request.options[:log_level], request.options[:log_format]) + logger.format(request, self) + end end def parsed_response diff --git a/spec/httparty/logger/apache_logger_spec.rb b/spec/httparty/logger/apache_logger_spec.rb new file mode 100644 index 00000000..32da245f --- /dev/null +++ b/spec/httparty/logger/apache_logger_spec.rb @@ -0,0 +1,26 @@ +require File.expand_path(File.join(File.dirname(__FILE__), '..', '..', 'spec_helper')) + +describe HTTParty::Logger::ApacheLogger do + describe "#format" do + it "formats a response in a style that resembles apache's access log" do + request_time = Time.new.strftime("%Y-%m-%d %H:%M:%S.%L %z") + log_message = "[HTTParty] [#{request_time}] 302 \"GET http://my.domain.com/my_path\" - " + + request_double = double( + :http_method => Net::HTTP::Get, + :path => "http://my.domain.com/my_path" + ) + response_double = double( + :code => 302, + :[] => nil + ) + + logger_double = double + logger_double.should_receive(:info).with(log_message) + + subject = described_class.new(logger_double, :info) + subject.current_time = request_time + subject.format(request_double, response_double) + end + end +end diff --git a/spec/httparty/logger/curl_logger_spec.rb b/spec/httparty/logger/curl_logger_spec.rb new file mode 100644 index 00000000..52f72420 --- /dev/null +++ b/spec/httparty/logger/curl_logger_spec.rb @@ -0,0 +1,21 @@ +require File.expand_path(File.join(File.dirname(__FILE__), '..', '..', 'spec_helper')) + +describe HTTParty::Logger::CurlLogger do + describe "#format" do + it "formats a response in a style that resembles a -v curl" do + request_time = Time.new.strftime("%Y-%m-%d %H:%M:%S.%L %z") + + logger_double = double + logger_double.should_receive(:info).with( + /\[HTTParty\] \[#{request_time}\] > GET http:\/\/localhost\n/) + + subject = described_class.new(logger_double, :info) + subject.current_time = request_time + + stub_http_response_with("google.html") + + response = HTTParty::Request.new.perform + subject.format(response.request, response) + end + end +end diff --git a/spec/httparty/logger/logger_spec.rb b/spec/httparty/logger/logger_spec.rb new file mode 100644 index 00000000..45f8eaf0 --- /dev/null +++ b/spec/httparty/logger/logger_spec.rb @@ -0,0 +1,22 @@ +require File.expand_path(File.join(File.dirname(__FILE__), '..', '..', 'spec_helper')) + +describe HTTParty::Logger do + describe ".build" do + subject { HTTParty::Logger } + + it "defaults level to :info" do + logger_double = double() + subject.build(logger_double, nil, nil).level.should == :info + end + + it "defaults format to :apache" do + logger_double = double() + subject.build(logger_double, nil, nil).should be_an_instance_of(HTTParty::Logger::ApacheLogger) + end + + it "builds :curl style logger" do + logger_double = double() + subject.build(logger_double, nil, :curl).should be_an_instance_of(HTTParty::Logger::CurlLogger) + end + end +end diff --git a/spec/httparty/request_spec.rb b/spec/httparty/request_spec.rb index dc768825..95ffae1e 100644 --- a/spec/httparty/request_spec.rb +++ b/spec/httparty/request_spec.rb @@ -517,6 +517,13 @@ @request.perform.should == {"hash" => {"foo" => "bar"}} @request.http_method.should == Net::HTTP::Delete end + + it 'should log the redirection' do + logger_double = double + logger_double.should_receive(:info).twice + @request.options[:logger] = logger_double + @request.perform + end end describe "infinitely" do @@ -592,4 +599,3 @@ end end end - From e0a96f8383895d3881488b3035254baf6fe28def Mon Sep 17 00:00:00 2001 From: Lucas Uyezu Date: Mon, 7 Oct 2013 22:02:39 -0300 Subject: [PATCH 2/6] Logging request body --- lib/httparty/logger/curl_logger.rb | 1 + lib/httparty/request.rb | 2 +- 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/lib/httparty/logger/curl_logger.rb b/lib/httparty/logger/curl_logger.rb index 24e90571..aba8c6d3 100644 --- a/lib/httparty/logger/curl_logger.rb +++ b/lib/httparty/logger/curl_logger.rb @@ -23,6 +23,7 @@ def format(request, response) end end + print_outgoing request.raw_request.body if request.raw_request && request.raw_request.body print_outgoing "" print_incoming "HTTP/#{response.http_version} #{response.code}" diff --git a/lib/httparty/request.rb b/lib/httparty/request.rb index c83c2c11..efffd6d0 100644 --- a/lib/httparty/request.rb +++ b/lib/httparty/request.rb @@ -27,7 +27,7 @@ class Request #:nodoc: end attr_accessor :http_method, :options, :last_response, :redirect, :last_uri - attr_reader :path + attr_reader :path, :raw_request def initialize(http_method, path, o={}) self.http_method = http_method From f0bfbcd3387934dd79629b857f9cdedf80448191 Mon Sep 17 00:00:00 2001 From: Lucas Uyezu Date: Wed, 9 Oct 2013 16:28:25 -0300 Subject: [PATCH 3/6] Testing regexp must consider timezones with '+' and '-'. --- spec/httparty/logger/curl_logger_spec.rb | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/spec/httparty/logger/curl_logger_spec.rb b/spec/httparty/logger/curl_logger_spec.rb index 52f72420..332a4ef7 100644 --- a/spec/httparty/logger/curl_logger_spec.rb +++ b/spec/httparty/logger/curl_logger_spec.rb @@ -3,14 +3,11 @@ describe HTTParty::Logger::CurlLogger do describe "#format" do it "formats a response in a style that resembles a -v curl" do - request_time = Time.new.strftime("%Y-%m-%d %H:%M:%S.%L %z") - logger_double = double logger_double.should_receive(:info).with( - /\[HTTParty\] \[#{request_time}\] > GET http:\/\/localhost\n/) + /\[HTTParty\] \[\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\.\d{3} [+-]\d{4}\] > GET http:\/\/localhost/) subject = described_class.new(logger_double, :info) - subject.current_time = request_time stub_http_response_with("google.html") From c0fe182ae4ffd47907dfe8f2231b4bbbbd7e5980 Mon Sep 17 00:00:00 2001 From: Lucas Uyezu Date: Wed, 9 Oct 2013 17:09:30 -0300 Subject: [PATCH 4/6] Ruby 1.8 does not support %L on Time#strftime. --- lib/httparty/logger/curl_logger.rb | 2 +- spec/httparty/logger/curl_logger_spec.rb | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/httparty/logger/curl_logger.rb b/lib/httparty/logger/curl_logger.rb index aba8c6d3..124564dd 100644 --- a/lib/httparty/logger/curl_logger.rb +++ b/lib/httparty/logger/curl_logger.rb @@ -12,7 +12,7 @@ def initialize(logger, level) def format(request, response) @messages = [] - @current_time ||= Time.new.strftime("%Y-%m-%d %H:%M:%S.%L %z") + @current_time ||= Time.new.strftime("%Y-%m-%d %H:%M:%S %z") http_method = request.http_method.name.split("::").last.upcase path = request.path.to_s diff --git a/spec/httparty/logger/curl_logger_spec.rb b/spec/httparty/logger/curl_logger_spec.rb index 332a4ef7..917bd7d6 100644 --- a/spec/httparty/logger/curl_logger_spec.rb +++ b/spec/httparty/logger/curl_logger_spec.rb @@ -5,7 +5,7 @@ it "formats a response in a style that resembles a -v curl" do logger_double = double logger_double.should_receive(:info).with( - /\[HTTParty\] \[\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\.\d{3} [+-]\d{4}\] > GET http:\/\/localhost/) + /\[HTTParty\] \[\d{4}-\d\d-\d\d \d\d:\d\d:\d\d\ [+-]\d{4}\] > GET http:\/\/localhost/) subject = described_class.new(logger_double, :info) From 9934d6d12053bb19b5100b802fb50c817340fc3a Mon Sep 17 00:00:00 2001 From: Lucas Uyezu Date: Wed, 9 Oct 2013 18:15:35 -0300 Subject: [PATCH 5/6] Removing memoization --- lib/httparty/logger/apache_logger.rb | 2 +- lib/httparty/logger/curl_logger.rb | 2 +- spec/httparty/logger/apache_logger_spec.rb | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/httparty/logger/apache_logger.rb b/lib/httparty/logger/apache_logger.rb index 8e4014f2..ac6781ca 100644 --- a/lib/httparty/logger/apache_logger.rb +++ b/lib/httparty/logger/apache_logger.rb @@ -11,7 +11,7 @@ def initialize(logger, level) end def format(request, response) - @current_time ||= Time.new.strftime("%Y-%m-%d %H:%M:%S.%L %z") + @current_time = Time.new.strftime("%Y-%m-%d %H:%M:%S %z") http_method = request.http_method.name.split("::").last.upcase path = request.path.to_s content_length = response['Content-Length'] diff --git a/lib/httparty/logger/curl_logger.rb b/lib/httparty/logger/curl_logger.rb index 124564dd..c024dabf 100644 --- a/lib/httparty/logger/curl_logger.rb +++ b/lib/httparty/logger/curl_logger.rb @@ -12,7 +12,7 @@ def initialize(logger, level) def format(request, response) @messages = [] - @current_time ||= Time.new.strftime("%Y-%m-%d %H:%M:%S %z") + @current_time = Time.new.strftime("%Y-%m-%d %H:%M:%S %z") http_method = request.http_method.name.split("::").last.upcase path = request.path.to_s diff --git a/spec/httparty/logger/apache_logger_spec.rb b/spec/httparty/logger/apache_logger_spec.rb index 32da245f..bba44748 100644 --- a/spec/httparty/logger/apache_logger_spec.rb +++ b/spec/httparty/logger/apache_logger_spec.rb @@ -3,7 +3,7 @@ describe HTTParty::Logger::ApacheLogger do describe "#format" do it "formats a response in a style that resembles apache's access log" do - request_time = Time.new.strftime("%Y-%m-%d %H:%M:%S.%L %z") + request_time = Time.new.strftime("%Y-%m-%d %H:%M:%S %z") log_message = "[HTTParty] [#{request_time}] 302 \"GET http://my.domain.com/my_path\" - " request_double = double( From 45c9b55c78cca0cbc5759fbc72c0c23c36dcd0e3 Mon Sep 17 00:00:00 2001 From: Lucas Uyezu Date: Wed, 9 Oct 2013 18:35:08 -0300 Subject: [PATCH 6/6] Exposing raw_body instead of raw_request. --- lib/httparty/logger/curl_logger.rb | 2 +- lib/httparty/request.rb | 6 +++++- 2 files changed, 6 insertions(+), 2 deletions(-) diff --git a/lib/httparty/logger/curl_logger.rb b/lib/httparty/logger/curl_logger.rb index c024dabf..6fef2909 100644 --- a/lib/httparty/logger/curl_logger.rb +++ b/lib/httparty/logger/curl_logger.rb @@ -23,7 +23,7 @@ def format(request, response) end end - print_outgoing request.raw_request.body if request.raw_request && request.raw_request.body + print_outgoing request.raw_body print_outgoing "" print_incoming "HTTP/#{response.http_version} #{response.code}" diff --git a/lib/httparty/request.rb b/lib/httparty/request.rb index efffd6d0..a05f80ba 100644 --- a/lib/httparty/request.rb +++ b/lib/httparty/request.rb @@ -27,7 +27,7 @@ class Request #:nodoc: end attr_accessor :http_method, :options, :last_response, :redirect, :last_uri - attr_reader :path, :raw_request + attr_reader :path def initialize(http_method, path, o={}) self.http_method = http_method @@ -107,6 +107,10 @@ def perform(&block) handle_response(chunked_body, &block) end + def raw_body + @raw_request.body + end + private def http