diff --git a/README.md b/README.md index 4f161508b..37c4db007 100644 --- a/README.md +++ b/README.md @@ -150,7 +150,7 @@ There are a few options for enabling it: 2. Set `Stripe.log_level`: ``` ruby - Stripe.log_level = "info" + Stripe.log_level = Stripe::LEVEL_INFO ``` ### Writing a Plugin diff --git a/lib/stripe.rb b/lib/stripe.rb index 3a12f8c14..f6f7df22c 100644 --- a/lib/stripe.rb +++ b/lib/stripe.rb @@ -1,6 +1,7 @@ # Stripe Ruby bindings # API spec at https://stripe.com/docs/api require 'cgi' +require 'logger' require 'openssl' require 'rbconfig' require 'set' @@ -84,6 +85,7 @@ module Stripe @uploads_base = 'https://uploads.stripe.com' @log_level = nil + @logger = nil @max_network_retries = 0 @max_network_retry_delay = 2 @@ -144,24 +146,51 @@ def self.ca_store end end - LEVEL_DEBUG = "debug" - LEVEL_INFO = "info" + # map to the same values as the standard library's logger + LEVEL_DEBUG = Logger::DEBUG + LEVEL_ERROR = Logger::ERROR + LEVEL_INFO = Logger::INFO - # When set prompts the library to log some extra information to $stdout about - # what it's doing. For example, it'll produce information about requests, - # responses, and errors that are received. Valid log levels are `debug` and - # `info`, with `debug` being a little more verbose in places. + # When set prompts the library to log some extra information to $stdout and + # $stderr about what it's doing. For example, it'll produce information about + # requests, responses, and errors that are received. Valid log levels are + # `debug` and `info`, with `debug` being a little more verbose in places. + # + # Use of this configuration is only useful when `.logger` is _not_ set. When + # it is, the decision what levels to print is entirely deferred to the logger. def self.log_level @log_level end def self.log_level=(val) - if val != nil && ![LEVEL_DEBUG, LEVEL_INFO].include?(val) + # Backwards compatibility for values that we briefly allowed + if val == "debug" + val = LEVEL_DEBUG + elsif val == "info" + val = LEVEL_INFO + end + + if val != nil && ![LEVEL_DEBUG, LEVEL_ERROR, LEVEL_INFO].include?(val) raise ArgumentError, "log_level should only be set to `nil`, `debug` or `info`" end @log_level = val end + # Sets a logger to which logging output will be sent. The logger should + # support the same interface as the `Logger` class that's part of Ruby's + # standard library (hint, anything in `Rails.logger` will likely be + # suitable). + # + # If `.logger` is set, the value of `.log_level` is ignored. The decision on + # what levels to print is entirely deferred to the logger. + def self.logger + @logger + end + + def self.logger=(val) + @logger = val + end + def self.max_network_retries @max_network_retries end diff --git a/lib/stripe/stripe_client.rb b/lib/stripe/stripe_client.rb index 8ecb32e24..f683a70be 100644 --- a/lib/stripe/stripe_client.rb +++ b/lib/stripe/stripe_client.rb @@ -279,7 +279,7 @@ def handle_error_response(http_resp, context) end def specific_api_error(resp, error_data, context) - Util.log_info('Stripe API error', + Util.log_error('Stripe API error', status: resp.http_status, error_code: error_data['code'], error_message: error_data['message'], @@ -336,7 +336,7 @@ def specific_api_error(resp, error_data, context) def specific_oauth_error(resp, error_code, context) description = resp.data[:error_description] || error_code - Util.log_info('Stripe OAuth error', + Util.log_error('Stripe OAuth error', status: resp.http_status, error_code: error_code, error_description: description, @@ -364,7 +364,7 @@ def specific_oauth_error(resp, error_code, context) end def handle_network_error(e, context, num_retries, api_base=nil) - Util.log_info('Stripe OAuth error', + Util.log_error('Stripe network error', error_message: e.message, idempotency_key: context.idempotency_key, request_id: context.request_id @@ -481,7 +481,7 @@ def log_response(context, request_start, status, body) private :log_response def log_response_error(context, request_start, e) - Util.log_info("Request error", + Util.log_error("Request error", elapsed: Time.now - request_start, error_message: e.message, idempotency_key: context.idempotency_key, diff --git a/lib/stripe/util.rb b/lib/stripe/util.rb index bc3b42e00..454eb350e 100644 --- a/lib/stripe/util.rb +++ b/lib/stripe/util.rb @@ -89,17 +89,27 @@ def self.convert_to_stripe_object(data, opts = {}) end end + def self.log_error(message, data = {}) + if !Stripe.logger.nil? || + !Stripe.log_level.nil? && Stripe.log_level <= Stripe::LEVEL_ERROR + log_internal(message, data, color: :cyan, + level: Stripe::LEVEL_ERROR, logger: Stripe.logger, out: $stderr) + end + end + def self.log_info(message, data = {}) - if Stripe.log_level == Stripe::LEVEL_DEBUG ||Stripe.log_level == Stripe::LEVEL_INFO + if !Stripe.logger.nil? || + !Stripe.log_level.nil? && Stripe.log_level <= Stripe::LEVEL_INFO log_internal(message, data, color: :cyan, - level: Stripe::LEVEL_INFO, out: $stdout) + level: Stripe::LEVEL_INFO, logger: Stripe.logger, out: $stdout) end end def self.log_debug(message, data = {}) - if Stripe.log_level == Stripe::LEVEL_DEBUG + if !Stripe.logger.nil? || + !Stripe.log_level.nil? && Stripe.log_level <= Stripe::LEVEL_DEBUG log_internal(message, data, color: :blue, - level: Stripe::LEVEL_DEBUG, out: $stdout) + level: Stripe::LEVEL_DEBUG, logger: Stripe.logger, out: $stdout) end end @@ -338,23 +348,39 @@ def self.colorize(val, color, isatty) end private_class_method :colorize + # Turns an integer log level into a printable name. + def self.level_name(level) + case level + when LEVEL_DEBUG then "debug" + when LEVEL_ERROR then "error" + when LEVEL_INFO then "info" + else level + end + end + private_class_method :level_name + # TODO: Make these named required arguments when we drop support for Ruby # 2.0. - def self.log_internal(message, data = {}, color: nil, level: nil, out: nil) + def self.log_internal(message, data = {}, color: nil, level: nil, logger: nil, out: nil) data_str = data.select { |k,v| !v.nil? }. map { |(k,v)| "%s=%s" % [ - colorize(k, color, out.isatty), + colorize(k, color, !out.nil? && out.isatty), wrap_logfmt_value(v) ] }.join(" ") - if out.isatty + if !logger.nil? + # the library's log levels are mapped to the same values as the + # standard library's logger + logger.log(level, + "message=%s %s" % [wrap_logfmt_value(message), data_str]) + elsif out.isatty out.puts "%s %s %s" % - [colorize(level[0, 4].upcase, color, out.isatty), message, data_str] + [colorize(level_name(level)[0, 4].upcase, color, out.isatty), message, data_str] else out.puts "message=%s level=%s %s" % - [wrap_logfmt_value(message), level, data_str] + [wrap_logfmt_value(message), level_name(level), data_str] end end private_class_method :log_internal diff --git a/test/stripe/stripe_client_test.rb b/test/stripe/stripe_client_test.rb index 43ba382e6..809aad4a8 100644 --- a/test/stripe/stripe_client_test.rb +++ b/test/stripe/stripe_client_test.rb @@ -240,7 +240,7 @@ class StripeClientTest < Test::Unit::TestCase param: 'param', type: 'type', } - Util.expects(:log_info).with('Stripe API error', + Util.expects(:log_error).with('Stripe API error', status: 500, error_code: error['code'], error_message: error['message'], @@ -282,7 +282,7 @@ class StripeClientTest < Test::Unit::TestCase status: 400 ) - Util.expects(:log_info).with('Stripe OAuth error', + Util.expects(:log_error).with('Stripe OAuth error', status: 400, error_code: "invalid_request", error_description: "No grant type specified", diff --git a/test/stripe/util_test.rb b/test/stripe/util_test.rb index d8ddcddfe..f9a6ea9da 100644 --- a/test/stripe/util_test.rb +++ b/test/stripe/util_test.rb @@ -168,12 +168,16 @@ class UtilTest < Test::Unit::TestCase @old_log_level = Stripe.log_level Stripe.log_level = nil + @old_stderr = $stderr + $stderr = StringIO.new + @old_stdout = $stdout $stdout = StringIO.new end teardown do Stripe.log_level = @old_log_level + $stderr = @old_stderr $stdout = @old_stdout end @@ -189,6 +193,12 @@ class UtilTest < Test::Unit::TestCase assert_equal "message=foo level=debug \n", $stdout.string end + should "not log if level set to error" do + Stripe.log_level = Stripe::LEVEL_ERROR + Util.log_debug("foo") + assert_equal "", $stdout.string + end + should "not log if level set to info" do Stripe.log_level = Stripe::LEVEL_INFO Util.log_debug("foo") @@ -196,6 +206,31 @@ class UtilTest < Test::Unit::TestCase end end + context ".log_error" do + should "not log if logging is disabled" do + Util.log_error("foo") + assert_equal "", $stdout.string + end + + should "log if level set to debug" do + Stripe.log_level = Stripe::LEVEL_DEBUG + Util.log_error("foo") + assert_equal "message=foo level=error \n", $stderr.string + end + + should "log if level set to error" do + Stripe.log_level = Stripe::LEVEL_ERROR + Util.log_error("foo") + assert_equal "message=foo level=error \n", $stderr.string + end + + should "log if level set to info" do + Stripe.log_level = Stripe::LEVEL_INFO + Util.log_error("foo") + assert_equal "message=foo level=error \n", $stderr.string + end + end + context ".log_info" do should "not log if logging is disabled" do Util.log_info("foo") @@ -208,6 +243,12 @@ class UtilTest < Test::Unit::TestCase assert_equal "message=foo level=info \n", $stdout.string end + should "not log if level set to error" do + Stripe.log_level = Stripe::LEVEL_ERROR + Util.log_debug("foo") + assert_equal "", $stdout.string + end + should "log if level set to info" do Stripe.log_level = Stripe::LEVEL_INFO Util.log_info("foo") @@ -216,6 +257,42 @@ class UtilTest < Test::Unit::TestCase end end + context ".log_* with a logger" do + setup do + @out = StringIO.new + logger = ::Logger.new(@out) + + # Set a really simple formatter to make matching output as easy as + # possible. + logger.formatter = proc { |_severity, _datetime, _progname, message| + message + } + + Stripe.logger = logger + end + + context ".log_debug" do + should "log to the logger" do + Util.log_debug("foo") + assert_equal "message=foo ", @out.string + end + end + + context ".log_error" do + should "log to the logger" do + Util.log_error("foo") + assert_equal "message=foo ", @out.string + end + end + + context ".log_info" do + should "log to the logger" do + Util.log_info("foo") + assert_equal "message=foo ", @out.string + end + end + end + context ".normalize_headers" do should "normalize the format of a header key" do assert_equal({ "Request-Id" => nil }, @@ -255,6 +332,14 @@ class UtilTest < Test::Unit::TestCase end end + context ".level_name" do + should "convert levels to names" do + assert_equal "debug", Util.send(:level_name, LEVEL_DEBUG) + assert_equal "error", Util.send(:level_name, LEVEL_ERROR) + assert_equal "info", Util.send(:level_name, LEVEL_INFO) + end + end + context ".log_internal" do should "log in a terminal friendly way" do out = StringIO.new @@ -267,7 +352,7 @@ def isatty; true; end end Util.send(:log_internal, "message", { foo: "bar" }, - color: :green, level: Stripe::LEVEL_DEBUG, out: out) + color: :green, level: Stripe::LEVEL_DEBUG, logger: nil, out: out) assert_equal "\e[0;32;49mDEBU\e[0m message \e[0;32;49mfoo\e[0m=bar\n", out.string end @@ -275,10 +360,26 @@ def isatty; true; end should "log in a data friendly way" do out = StringIO.new Util.send(:log_internal, "message", { foo: "bar" }, - color: :green, level: Stripe::LEVEL_DEBUG, out: out) + color: :green, level: Stripe::LEVEL_DEBUG, logger: nil, out: out) assert_equal "message=message level=debug foo=bar\n", out.string end + + should "log to a logger if set" do + out = StringIO.new + logger = ::Logger.new(out) + + # Set a really simple formatter to make matching output as easy as + # possible. + logger.formatter = proc { |_severity, _datetime, _progname, message| + message + } + + Util.send(:log_internal, "message", { foo: "bar" }, + color: :green, level: Stripe::LEVEL_DEBUG, logger: logger, out: nil) + assert_equal "message=message foo=bar", + out.string + end end context ".wrap_logfmt_value" do