From cb111a8e74dff8f575eda28894fb5921f69cfaad Mon Sep 17 00:00:00 2001 From: Brandur Date: Fri, 11 Aug 2017 11:16:29 -0700 Subject: [PATCH 1/2] Add support for setting a logger Adds support for setting `Stripe.logger` to a logger that's compatible with `Logger` from Ruby's standard library. In set, the library will no longer log to stdout, and instead emit straight to the logger and defer decision on what log level to print to it. Addresses a request in #566. --- lib/stripe.rb | 19 +++++++++++++++ lib/stripe/util.rb | 25 ++++++++++++++------ test/stripe/util_test.rb | 50 ++++++++++++++++++++++++++++++++++++++-- 3 files changed, 85 insertions(+), 9 deletions(-) diff --git a/lib/stripe.rb b/lib/stripe.rb index 3a12f8c14..1a833eafe 100644 --- a/lib/stripe.rb +++ b/lib/stripe.rb @@ -84,6 +84,7 @@ module Stripe @uploads_base = 'https://uploads.stripe.com' @log_level = nil + @logger = nil @max_network_retries = 0 @max_network_retry_delay = 2 @@ -151,6 +152,9 @@ def self.ca_store # 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 @@ -162,6 +166,21 @@ def self.log_level=(val) @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/util.rb b/lib/stripe/util.rb index bc3b42e00..883b1242a 100644 --- a/lib/stripe/util.rb +++ b/lib/stripe/util.rb @@ -90,16 +90,19 @@ def self.convert_to_stripe_object(data, opts = {}) 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 == Stripe::LEVEL_DEBUG || + 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 == 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 @@ -340,16 +343,24 @@ def self.colorize(val, color, isatty) # 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? + str = "message=%s %s" % [wrap_logfmt_value(message), data_str] + case level + when Stripe::LEVEL_DEBUG + logger.debug(str) + else # Stripe::LEVEL_INFO (there should be no other values) + logger.info(str) + end + elsif out.isatty out.puts "%s %s %s" % [colorize(level[0, 4].upcase, color, out.isatty), message, data_str] else diff --git a/test/stripe/util_test.rb b/test/stripe/util_test.rb index d8ddcddfe..35127c0b7 100644 --- a/test/stripe/util_test.rb +++ b/test/stripe/util_test.rb @@ -1,3 +1,4 @@ +require "logger" require File.expand_path('../../test_helper', __FILE__) module Stripe @@ -216,6 +217,35 @@ 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_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 }, @@ -267,7 +297,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 +305,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 From 1ca67cb9548e09fe64ca2c138ab4a0b6c4a16e30 Mon Sep 17 00:00:00 2001 From: Brandur Date: Fri, 11 Aug 2017 11:45:43 -0700 Subject: [PATCH 2/2] Correct behavior for error logging A few changes: * Add a new `Util.log_error` method which will forward to the equivalent of `#error` on a logger. * Move errors produced by `StripeClient` to use `Util.log_error`. * Change standard stdout logging behavior to log to stderr in the case of `Util.log_error. * Change `Stripe.log_level` values to be an enum in a similar fashion as the standard library's built in `Logger`. --- README.md | 2 +- lib/stripe.rb | 24 +++++++++---- lib/stripe/stripe_client.rb | 8 ++--- lib/stripe/util.rb | 39 ++++++++++++++------- test/stripe/stripe_client_test.rb | 4 +-- test/stripe/util_test.rb | 57 ++++++++++++++++++++++++++++++- 6 files changed, 107 insertions(+), 27 deletions(-) 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 1a833eafe..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' @@ -145,13 +146,15 @@ 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. @@ -160,7 +163,14 @@ def self.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 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 883b1242a..454eb350e 100644 --- a/lib/stripe/util.rb +++ b/lib/stripe/util.rb @@ -89,10 +89,17 @@ 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.logger.nil? || - Stripe.log_level == Stripe::LEVEL_DEBUG || - Stripe.log_level == Stripe::LEVEL_INFO + !Stripe.log_level.nil? && Stripe.log_level <= Stripe::LEVEL_INFO log_internal(message, data, color: :cyan, level: Stripe::LEVEL_INFO, logger: Stripe.logger, out: $stdout) end @@ -100,7 +107,7 @@ def self.log_info(message, data = {}) def self.log_debug(message, data = {}) if !Stripe.logger.nil? || - Stripe.log_level == Stripe::LEVEL_DEBUG + !Stripe.log_level.nil? && Stripe.log_level <= Stripe::LEVEL_DEBUG log_internal(message, data, color: :blue, level: Stripe::LEVEL_DEBUG, logger: Stripe.logger, out: $stdout) end @@ -341,6 +348,17 @@ 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, logger: nil, out: nil) @@ -353,19 +371,16 @@ def self.log_internal(message, data = {}, color: nil, level: nil, logger: nil, o }.join(" ") if !logger.nil? - str = "message=%s %s" % [wrap_logfmt_value(message), data_str] - case level - when Stripe::LEVEL_DEBUG - logger.debug(str) - else # Stripe::LEVEL_INFO (there should be no other values) - logger.info(str) - end + # 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 35127c0b7..f9a6ea9da 100644 --- a/test/stripe/util_test.rb +++ b/test/stripe/util_test.rb @@ -1,4 +1,3 @@ -require "logger" require File.expand_path('../../test_helper', __FILE__) module Stripe @@ -169,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 @@ -190,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") @@ -197,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") @@ -209,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") @@ -238,6 +278,13 @@ class UtilTest < Test::Unit::TestCase 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") @@ -285,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