Add support for setting a logger

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

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

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,

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

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",

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,13 +193,44 @@ 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")
           assert_equal "", $stdout.string
         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,18 +352,34 @@ 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
 
       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