mirror of
https://github.com/stripe/stripe-ruby.git
synced 2025-08-10 00:01:09 -04:00
Implement STRIPE_LOG for stripe-ruby
Adds logging support for stripe-ruby in a similar way that we did it for stripe-python [1], with the idea that users you can optionally get some additional low-cost-to-configure logging for operational visibility or debugging. I made a few tweaks from the Python implementation (which I'll try to contribute back to there): * Added an elapsed parameter to responses so you can tell how long they lasted. * Mixed in idempotency_key to all lines that users have a way to aggregate logs related to a request from start to finish. * Standardized naming between different log lines as much as possible. * Detect a TTY and produce output that's colorized and formatted. [1] https://github.com/stripe/stripe-python/pull/269
This commit is contained in:
Brandur
parent
a24b7bcf77
commit
ce69d749e1
1
Gemfile
1
Gemfile
@ -7,6 +7,7 @@ group :development do
|
||||
gem 'rake'
|
||||
gem 'shoulda-context'
|
||||
gem 'test-unit'
|
||||
gem 'timecop'
|
||||
gem 'webmock'
|
||||
|
||||
# Rack 2.0+ requires Ruby >= 2.2.2 which is problematic for the test suite on
|
||||
|
||||
18
README.md
18
README.md
@ -135,6 +135,24 @@ Please take care to set conservative read timeouts. Some API requests can take
|
||||
some time, and a short timeout increases the likelihood of a problem within our
|
||||
servers.
|
||||
|
||||
### Logging
|
||||
|
||||
The library can be configured to emit logging that will give you better insight
|
||||
into what it's doing. The `info` logging level is usually most appropriate for
|
||||
production use, but `debug` is also available for more verbosity.
|
||||
|
||||
There are a few options for enabling it:
|
||||
|
||||
1. Set the environment variable `STRIPE_LOG` to the value `debug` or `info`:
|
||||
```
|
||||
$ export STRIPE_LOG=info
|
||||
```
|
||||
|
||||
2. Set `Stripe.log_level`:
|
||||
``` ruby
|
||||
Stripe.log_level = "info"
|
||||
```
|
||||
|
||||
### Writing a Plugin
|
||||
|
||||
If you're writing a plugin that uses the library, we'd appreciate it if you
|
||||
|
||||
@ -83,6 +83,8 @@ module Stripe
|
||||
@connect_base = 'https://connect.stripe.com'
|
||||
@uploads_base = 'https://uploads.stripe.com'
|
||||
|
||||
@log_level = nil
|
||||
|
||||
@max_network_retries = 0
|
||||
@max_network_retry_delay = 2
|
||||
@initial_network_retry_delay = 0.5
|
||||
@ -142,6 +144,24 @@ module Stripe
|
||||
end
|
||||
end
|
||||
|
||||
LEVEL_DEBUG = "debug"
|
||||
LEVEL_INFO = "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.
|
||||
def self.log_level
|
||||
@log_level
|
||||
end
|
||||
|
||||
def self.log_level=(val)
|
||||
if val != nil && ![LEVEL_DEBUG, LEVEL_INFO].include?(val)
|
||||
raise ArgumentError, "log_level should only be set to `nil`, `debug` or `info`"
|
||||
end
|
||||
@log_level = val
|
||||
end
|
||||
|
||||
def self.max_network_retries
|
||||
@max_network_retries
|
||||
end
|
||||
@ -174,3 +194,7 @@ module Stripe
|
||||
deprecate :uri_encode, "Stripe::Util#encode_parameters", 2016, 01
|
||||
end
|
||||
end
|
||||
|
||||
unless ENV["STRIPE_LOG"].nil?
|
||||
Stripe.log_level = ENV["STRIPE_LOG"]
|
||||
end
|
||||
|
||||
@ -109,7 +109,7 @@ module Stripe
|
||||
end
|
||||
end
|
||||
|
||||
def execute_request(method, url,
|
||||
def execute_request(method, path,
|
||||
api_base: nil, api_key: nil, headers: {}, params: {})
|
||||
|
||||
api_base ||= Stripe.api_base
|
||||
@ -118,7 +118,7 @@ module Stripe
|
||||
check_api_key!(api_key)
|
||||
|
||||
params = Util.objects_to_ids(params)
|
||||
url = api_url(url, api_base)
|
||||
url = api_url(path, api_base)
|
||||
|
||||
case method.to_s.downcase.to_sym
|
||||
when :get, :head, :delete
|
||||
@ -133,14 +133,22 @@ module Stripe
|
||||
end
|
||||
end
|
||||
|
||||
http_resp = execute_request_with_rescues(api_base, 0) do
|
||||
conn.run_request(
|
||||
method,
|
||||
url,
|
||||
payload,
|
||||
# TODO: Convert RestClient-style parameters.
|
||||
request_headers(api_key, method).update(headers)
|
||||
) do |req|
|
||||
headers = request_headers(api_key, method).
|
||||
update(Util.normalize_headers(headers))
|
||||
|
||||
# stores information on the request we're about to make so that we don't
|
||||
# have to pass as many parameters around for logging.
|
||||
context = RequestLogContext.new(
|
||||
api_key: api_key,
|
||||
api_version: headers["Stripe-Version"] || Stripe.api_version,
|
||||
idempotency_key: headers["Idempotency-Key"],
|
||||
method: method,
|
||||
path: path,
|
||||
payload: payload,
|
||||
)
|
||||
|
||||
http_resp = execute_request_with_rescues(api_base, context) do
|
||||
conn.run_request(method, url, payload, headers) do |req|
|
||||
req.options.open_timeout = Stripe.open_timeout
|
||||
req.options.timeout = Stripe.read_timeout
|
||||
end
|
||||
@ -180,14 +188,31 @@ module Stripe
|
||||
end
|
||||
end
|
||||
|
||||
def execute_request_with_rescues(api_base, retry_count, &block)
|
||||
def execute_request_with_rescues(api_base, context, &block)
|
||||
retry_count = 0
|
||||
begin
|
||||
request_start = Time.now
|
||||
log_request(context)
|
||||
resp = block.call
|
||||
context = context.dup_from_response(resp)
|
||||
log_response(context, request_start, resp.status, resp.body)
|
||||
|
||||
# We rescue all exceptions from a request so that we have an easy spot to
|
||||
# implement our retry logic across the board. We'll re-raise if it's a type
|
||||
# of exception that we didn't expect to handle.
|
||||
rescue => e
|
||||
# If we modify context we copy it into a new variable so as not to
|
||||
# taint the original on a retry.
|
||||
error_context = context
|
||||
|
||||
if e.respond_to?(:response) && e.response
|
||||
error_context = context.dup_from_response(e.response)
|
||||
log_response(error_context, request_start,
|
||||
e.response[:status], e.response[:body])
|
||||
else
|
||||
log_response_error(error_context, request_start, e)
|
||||
end
|
||||
|
||||
if self.class.should_retry?(e, retry_count)
|
||||
retry_count = retry_count + 1
|
||||
sleep self.class.sleep_time(retry_count)
|
||||
@ -197,9 +222,9 @@ module Stripe
|
||||
case e
|
||||
when Faraday::ClientError
|
||||
if e.response
|
||||
handle_error_response(e.response)
|
||||
handle_error_response(e.response, error_context)
|
||||
else
|
||||
handle_network_error(e, retry_count, api_base)
|
||||
handle_network_error(e, error_context, retry_count, api_base)
|
||||
end
|
||||
|
||||
# Only handle errors when we know we can do so, and re-raise otherwise.
|
||||
@ -229,7 +254,7 @@ module Stripe
|
||||
str
|
||||
end
|
||||
|
||||
def handle_error_response(http_resp)
|
||||
def handle_error_response(http_resp, context)
|
||||
begin
|
||||
resp = StripeResponse.from_faraday_hash(http_resp)
|
||||
error_data = resp.data[:error]
|
||||
@ -243,16 +268,26 @@ module Stripe
|
||||
end
|
||||
|
||||
if error_data.is_a?(String)
|
||||
error = specific_oauth_error(resp, error_data)
|
||||
error = specific_oauth_error(resp, error_data, context)
|
||||
else
|
||||
error = specific_api_error(resp, error_data)
|
||||
error = specific_api_error(resp, error_data, context)
|
||||
end
|
||||
|
||||
error.response = resp
|
||||
raise(error)
|
||||
end
|
||||
|
||||
def specific_api_error(resp, error_data)
|
||||
def specific_api_error(resp, error_data, context)
|
||||
Util.log_info('Stripe API error',
|
||||
status: resp.http_status,
|
||||
error_code: error_data['code'],
|
||||
error_message: error_data['message'],
|
||||
error_param: error_data['param'],
|
||||
error_type: error_data['type'],
|
||||
idempotency_key: context.idempotency_key,
|
||||
request_id: context.request_id
|
||||
)
|
||||
|
||||
case resp.http_status
|
||||
when 400, 404
|
||||
error = InvalidRequestError.new(
|
||||
@ -297,9 +332,17 @@ module Stripe
|
||||
|
||||
# Attempts to look at a response's error code and return an OAuth error if
|
||||
# one matches. Will return `nil` if the code isn't recognized.
|
||||
def specific_oauth_error(resp, error_code)
|
||||
def specific_oauth_error(resp, error_code, context)
|
||||
description = resp.data[:error_description] || error_code
|
||||
|
||||
Util.log_info('Stripe OAuth error',
|
||||
status: resp.http_status,
|
||||
error_code: error_code,
|
||||
error_description: description,
|
||||
idempotency_key: context.idempotency_key,
|
||||
request_id: context.request_id
|
||||
)
|
||||
|
||||
args = [error_code, description, {
|
||||
http_status: resp.http_status, http_body: resp.http_body,
|
||||
json_body: resp.data, http_headers: resp.http_headers
|
||||
@ -319,7 +362,13 @@ module Stripe
|
||||
end
|
||||
end
|
||||
|
||||
def handle_network_error(e, retry_count, api_base=nil)
|
||||
def handle_network_error(e, context, retry_count, api_base=nil)
|
||||
Util.log_info('Stripe OAuth error',
|
||||
error_message: e.message,
|
||||
idempotency_key: context.idempotency_key,
|
||||
request_id: context.request_id
|
||||
)
|
||||
|
||||
case e
|
||||
when Faraday::ConnectionFailed
|
||||
message = "Unexpected error communicating when trying to connect to Stripe. " \
|
||||
@ -388,6 +437,104 @@ module Stripe
|
||||
headers
|
||||
end
|
||||
|
||||
def log_request(context)
|
||||
Util.log_info("Request to Stripe API",
|
||||
api_version: context.api_version,
|
||||
idempotency_key: context.idempotency_key,
|
||||
method: context.method,
|
||||
path: context.path
|
||||
)
|
||||
Util.log_debug("Request details",
|
||||
body: context.payload,
|
||||
idempotency_key: context.idempotency_key
|
||||
)
|
||||
end
|
||||
private :log_request
|
||||
|
||||
def log_response(context, request_start, status, body)
|
||||
Util.log_info("Response from Stripe API",
|
||||
api_version: context.api_version,
|
||||
elapsed: Time.now - request_start,
|
||||
idempotency_key: context.idempotency_key,
|
||||
method: context.method,
|
||||
path: context.path,
|
||||
request_id: context.request_id,
|
||||
status: status
|
||||
)
|
||||
Util.log_debug("Response details",
|
||||
body: body,
|
||||
idempotency_key: context.idempotency_key,
|
||||
request_id: context.request_id,
|
||||
)
|
||||
if context.request_id
|
||||
Util.log_debug("Dashboard link for request",
|
||||
idempotency_key: context.idempotency_key,
|
||||
request_id: context.request_id,
|
||||
url: Util.request_id_dashboard_url(context.request_id, context.api_key)
|
||||
)
|
||||
end
|
||||
end
|
||||
private :log_response
|
||||
|
||||
def log_response_error(context, request_start, e)
|
||||
Util.log_info("Request error",
|
||||
elapsed: Time.now - request_start,
|
||||
error_message: e.message,
|
||||
idempotency_key: context.idempotency_key,
|
||||
method: context.method,
|
||||
path: context.path,
|
||||
)
|
||||
end
|
||||
private :log_response_error
|
||||
|
||||
# RequestLogContext stores information about a request that's begin made so
|
||||
# that we can log certain information. It's useful because it means that we
|
||||
# don't have to pass around as many parameters.
|
||||
class RequestLogContext
|
||||
attr_accessor :api_key
|
||||
attr_accessor :api_version
|
||||
attr_accessor :idempotency_key
|
||||
attr_accessor :method
|
||||
attr_accessor :path
|
||||
attr_accessor :payload
|
||||
attr_accessor :request_id
|
||||
|
||||
def initialize(api_key: nil, api_version: nil, idempotency_key: nil,
|
||||
method: nil, path: nil, payload: nil)
|
||||
self.api_key = api_key
|
||||
self.api_version = api_version
|
||||
self.idempotency_key = idempotency_key
|
||||
self.method = method
|
||||
self.path = path
|
||||
self.payload = payload
|
||||
end
|
||||
|
||||
# The idea with this method is that we might want to update some of
|
||||
# context information because a response that we've received from the API
|
||||
# contains information that's more authoritative than what we started
|
||||
# with for a request. For example, we should trust whatever came back in
|
||||
# a `Stripe-Version` header beyond what configuration information that we
|
||||
# might have had available.
|
||||
def dup_from_response(resp)
|
||||
return self if resp.nil?
|
||||
|
||||
# Faraday's API is a little unusual. Normally it'll produce a response
|
||||
# object with a `headers` method, but on error what it puts into
|
||||
# `e.response` is an untyped `Hash`.
|
||||
headers = if resp.is_a?(Faraday::Response)
|
||||
resp.headers
|
||||
else
|
||||
resp[:headers]
|
||||
end
|
||||
|
||||
context = self.dup
|
||||
context.api_version = headers["Stripe-Version"]
|
||||
context.idempotency_key = headers["Idempotency-Key"]
|
||||
context.request_id = headers["Request-Id"]
|
||||
context
|
||||
end
|
||||
end
|
||||
|
||||
# SystemProfiler extracts information about the system that we're running
|
||||
# in so that we can generate a rich user agent header to help debug
|
||||
# integrations.
|
||||
|
||||
@ -89,6 +89,20 @@ module Stripe
|
||||
end
|
||||
end
|
||||
|
||||
def self.log_info(message, data = {})
|
||||
if Stripe.log_level == Stripe::LEVEL_DEBUG ||Stripe.log_level == Stripe::LEVEL_INFO
|
||||
log_internal(message, data, color: :cyan,
|
||||
level: Stripe::LEVEL_INFO, out: $stdout)
|
||||
end
|
||||
end
|
||||
|
||||
def self.log_debug(message, data = {})
|
||||
if Stripe.log_level == Stripe::LEVEL_DEBUG
|
||||
log_internal(message, data, color: :blue,
|
||||
level: Stripe::LEVEL_DEBUG, out: $stdout)
|
||||
end
|
||||
end
|
||||
|
||||
def self.file_readable(file)
|
||||
# This is nominally equivalent to File.readable?, but that can
|
||||
# report incorrect results on some more oddball filesystems
|
||||
@ -220,8 +234,59 @@ module Stripe
|
||||
key
|
||||
end
|
||||
|
||||
# Normalizes header keys so that they're all lower case and each
|
||||
# hyphen-delimited section starts with a single capitalized letter. For
|
||||
# example, `request-id` becomes `Request-Id`. This is useful for extracting
|
||||
# certain key values when the user could have set them with a variety of
|
||||
# diffent naming schemes.
|
||||
def self.normalize_headers(headers)
|
||||
headers.inject({}) do |new_headers, (k, v)|
|
||||
if k.is_a?(Symbol)
|
||||
k = titlecase_parts(k.to_s.gsub("_", "-"))
|
||||
elsif k.is_a?(String)
|
||||
k = titlecase_parts(k)
|
||||
end
|
||||
|
||||
new_headers[k] = v
|
||||
new_headers
|
||||
end
|
||||
end
|
||||
|
||||
# Generates a Dashboard link to inspect a request ID based off of a request
|
||||
# ID value and an API key, which is used to attempt to extract whether the
|
||||
# environment is livemode or testmode.
|
||||
def self.request_id_dashboard_url(request_id, api_key)
|
||||
env = !api_key.nil? && api_key.start_with?("sk_live") ? "live" : "test"
|
||||
"https://dashboard.stripe.com/#{env}/logs/#{request_id}"
|
||||
end
|
||||
|
||||
# Constant time string comparison to prevent timing attacks
|
||||
# Code borrowed from ActiveSupport
|
||||
def self.secure_compare(a, b)
|
||||
return false unless a.bytesize == b.bytesize
|
||||
|
||||
l = a.unpack "C#{a.bytesize}"
|
||||
|
||||
res = 0
|
||||
b.each_byte { |byte| res |= byte ^ l.shift }
|
||||
res == 0
|
||||
end
|
||||
|
||||
private
|
||||
|
||||
COLOR_CODES = {
|
||||
:black => 0, :light_black => 60,
|
||||
:red => 1, :light_red => 61,
|
||||
:green => 2, :light_green => 62,
|
||||
:yellow => 3, :light_yellow => 63,
|
||||
:blue => 4, :light_blue => 64,
|
||||
:magenta => 5, :light_magenta => 65,
|
||||
:cyan => 6, :light_cyan => 66,
|
||||
:white => 7, :light_white => 67,
|
||||
:default => 9
|
||||
}
|
||||
private_constant :COLOR_CODES
|
||||
|
||||
# We use a pretty janky version of form encoding (Rack's) that supports
|
||||
# more complex data structures like maps and arrays through the use of
|
||||
# specialized syntax. To encode an array of maps like:
|
||||
@ -258,17 +323,71 @@ module Stripe
|
||||
end
|
||||
end
|
||||
end
|
||||
private_class_method :check_array_of_maps_start_keys!
|
||||
|
||||
# Constant time string comparison to prevent timing attacks
|
||||
# Code borrowed from ActiveSupport
|
||||
def self.secure_compare(a, b)
|
||||
return false unless a.bytesize == b.bytesize
|
||||
# Uses an ANSI escape code to colorize text if it's going to be sent to a
|
||||
# TTY.
|
||||
def self.colorize(val, color, isatty)
|
||||
return val unless isatty
|
||||
|
||||
l = a.unpack "C#{a.bytesize}"
|
||||
mode = 0 # default
|
||||
foreground = 30 + COLOR_CODES.fetch(color)
|
||||
background = 40 + COLOR_CODES.fetch(:default)
|
||||
|
||||
res = 0
|
||||
b.each_byte { |byte| res |= byte ^ l.shift }
|
||||
res == 0
|
||||
"\033[#{mode};#{foreground};#{background}m#{val}\033[0m"
|
||||
end
|
||||
private_class_method :colorize
|
||||
|
||||
# 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)
|
||||
data_str = data.select { |k,v| !v.nil? }.
|
||||
map { |(k,v)|
|
||||
"%s=%s" % [
|
||||
colorize(k, color, out.isatty),
|
||||
wrap_logfmt_value(v)
|
||||
]
|
||||
}.join(" ")
|
||||
|
||||
if out.isatty
|
||||
out.puts "%s %s %s" %
|
||||
[colorize(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]
|
||||
end
|
||||
end
|
||||
private_class_method :log_internal
|
||||
|
||||
def self.titlecase_parts(s)
|
||||
s.split("-").
|
||||
select { |p| p != "" }.
|
||||
map { |p| p[0].upcase + p[1..-1].downcase }.
|
||||
join("-")
|
||||
end
|
||||
private_class_method :titlecase_parts
|
||||
|
||||
# Wraps a value in double quotes if it looks sufficiently complex so that
|
||||
# it can be read by logfmt parsers.
|
||||
def self.wrap_logfmt_value(val)
|
||||
# If value is any kind of number, just allow it to be formatted directly
|
||||
# to a string (this will handle integers or floats).
|
||||
return val if val.is_a?(Numeric)
|
||||
|
||||
# Hopefully val is a string, but protect in case it's not.
|
||||
val = val.to_s
|
||||
|
||||
if %r{[^\w\-/]} =~ val
|
||||
# If the string contains any special characters, escape any double
|
||||
# quotes it has, remove newlines, and wrap the whole thing in quotes.
|
||||
%{"%s"} % val.gsub('"', '\"').gsub("\n", "")
|
||||
else
|
||||
# Otherwise use the basic value if it looks like a standard set of
|
||||
# characters (and allow a few special characters like hyphens, and
|
||||
# slashes)
|
||||
val
|
||||
end
|
||||
end
|
||||
private_class_method :wrap_logfmt_value
|
||||
end
|
||||
end
|
||||
|
||||
@ -141,6 +141,158 @@ module Stripe
|
||||
end
|
||||
end
|
||||
|
||||
context "logging" do
|
||||
setup do
|
||||
# Freeze time for the purposes of the `elapsed` parameter that we
|
||||
# emit for responses. I didn't want to bring in a new dependency for
|
||||
# this, but Mocha's `anything` parameter can't match inside of a hash
|
||||
# and is therefore not useful for this purpose. If we switch over to
|
||||
# rspec-mocks at some point, we can probably remove Timecop from the
|
||||
# project.
|
||||
Timecop.freeze(Time.local(1990))
|
||||
end
|
||||
|
||||
teardown do
|
||||
Timecop.return
|
||||
end
|
||||
|
||||
should "produce appropriate logging" do
|
||||
body = JSON.generate({ object: "account" })
|
||||
|
||||
Util.expects(:log_info).with("Request to Stripe API",
|
||||
api_version: '2010-11-12',
|
||||
idempotency_key: "abc",
|
||||
method: :post,
|
||||
path: "/v1/account"
|
||||
)
|
||||
Util.expects(:log_debug).with("Request details",
|
||||
body: '',
|
||||
idempotency_key: "abc"
|
||||
)
|
||||
|
||||
Util.expects(:log_info).with("Response from Stripe API",
|
||||
api_version: '2010-11-12',
|
||||
elapsed: 0.0,
|
||||
idempotency_key: "abc",
|
||||
method: :post,
|
||||
path: "/v1/account",
|
||||
request_id: "req_123",
|
||||
status: 200
|
||||
)
|
||||
Util.expects(:log_debug).with("Response details",
|
||||
body: body,
|
||||
idempotency_key: "abc",
|
||||
request_id: "req_123"
|
||||
)
|
||||
Util.expects(:log_debug).with("Dashboard link for request",
|
||||
idempotency_key: "abc",
|
||||
request_id: "req_123",
|
||||
url: Util.request_id_dashboard_url("req_123", Stripe.api_key)
|
||||
)
|
||||
|
||||
stub_request(:post, "#{Stripe.api_base}/v1/account").
|
||||
to_return(
|
||||
body: body,
|
||||
headers: {
|
||||
"Idempotency-Key" => "abc",
|
||||
"Request-Id" => "req_123",
|
||||
"Stripe-Version" => "2010-11-12"
|
||||
}
|
||||
)
|
||||
|
||||
client = StripeClient.new
|
||||
client.execute_request(:post, '/v1/account',
|
||||
headers: {
|
||||
"Idempotency-Key" => "abc",
|
||||
"Stripe-Version" => "2010-11-12"
|
||||
}
|
||||
)
|
||||
end
|
||||
|
||||
should "produce logging on API error" do
|
||||
Util.expects(:log_info).with("Request to Stripe API",
|
||||
api_version: nil,
|
||||
idempotency_key: nil,
|
||||
method: :post,
|
||||
path: "/v1/account"
|
||||
)
|
||||
Util.expects(:log_info).with("Response from Stripe API",
|
||||
api_version: nil,
|
||||
elapsed: 0.0,
|
||||
idempotency_key: nil,
|
||||
method: :post,
|
||||
path: "/v1/account",
|
||||
request_id: nil,
|
||||
status: 500
|
||||
)
|
||||
|
||||
error = {
|
||||
code: 'code',
|
||||
message: 'message',
|
||||
param: 'param',
|
||||
type: 'type',
|
||||
}
|
||||
Util.expects(:log_info).with('Stripe API error',
|
||||
status: 500,
|
||||
error_code: error['code'],
|
||||
error_message: error['message'],
|
||||
error_param: error['param'],
|
||||
error_type: error['type'],
|
||||
idempotency_key: nil,
|
||||
request_id: nil
|
||||
)
|
||||
|
||||
stub_request(:post, "#{Stripe.api_base}/v1/account").
|
||||
to_return(
|
||||
body: JSON.generate({ :error => error }),
|
||||
status: 500
|
||||
)
|
||||
|
||||
client = StripeClient.new
|
||||
assert_raises Stripe::APIError do
|
||||
client.execute_request(:post, '/v1/account')
|
||||
end
|
||||
end
|
||||
|
||||
should "produce logging on OAuth error" do
|
||||
Util.expects(:log_info).with("Request to Stripe API",
|
||||
api_version: nil,
|
||||
idempotency_key: nil,
|
||||
method: :post,
|
||||
path: "/oauth/token"
|
||||
)
|
||||
Util.expects(:log_info).with("Response from Stripe API",
|
||||
api_version: nil,
|
||||
elapsed: 0.0,
|
||||
idempotency_key: nil,
|
||||
method: :post,
|
||||
path: "/oauth/token",
|
||||
request_id: nil,
|
||||
status: 400
|
||||
)
|
||||
|
||||
Util.expects(:log_info).with('Stripe OAuth error',
|
||||
status: 400,
|
||||
error_code: "invalid_request",
|
||||
error_description: "No grant type specified",
|
||||
idempotency_key: nil,
|
||||
request_id: nil
|
||||
)
|
||||
|
||||
stub_request(:post, "#{Stripe.connect_base}/oauth/token").
|
||||
to_return(body: JSON.generate({
|
||||
error: "invalid_request",
|
||||
error_description: "No grant type specified",
|
||||
}), status: 400)
|
||||
|
||||
client = StripeClient.new
|
||||
opts = {api_base: Stripe.connect_base}
|
||||
assert_raises Stripe::OAuth::InvalidRequestError do
|
||||
client.execute_request(:post, '/oauth/token', opts)
|
||||
end
|
||||
end
|
||||
end
|
||||
|
||||
context "Stripe-Account header" do
|
||||
should "use a globally set header" do
|
||||
begin
|
||||
|
||||
@ -145,5 +145,169 @@ module Stripe
|
||||
should "#array_to_hash should convert an array into a hash with integer keys" do
|
||||
assert_equal({"0" => 1, "1" => 2, "2" => 3}, Util.array_to_hash([1, 2, 3]))
|
||||
end
|
||||
|
||||
context ".request_id_dashboard_url" do
|
||||
should "generate a livemode URL" do
|
||||
assert_equal "https://dashboard.stripe.com/live/logs/request-id",
|
||||
Util.request_id_dashboard_url("request-id", "sk_live_123")
|
||||
end
|
||||
|
||||
should "generate a testmode URL" do
|
||||
assert_equal "https://dashboard.stripe.com/test/logs/request-id",
|
||||
Util.request_id_dashboard_url("request-id", "sk_test_123")
|
||||
end
|
||||
|
||||
should "default to a testmode URL" do
|
||||
assert_equal "https://dashboard.stripe.com/test/logs/request-id",
|
||||
Util.request_id_dashboard_url("request-id", nil)
|
||||
end
|
||||
end
|
||||
|
||||
context ".log_*" do
|
||||
setup do
|
||||
@old_log_level = Stripe.log_level
|
||||
Stripe.log_level = nil
|
||||
|
||||
@old_stdout = $stdout
|
||||
$stdout = StringIO.new
|
||||
end
|
||||
|
||||
teardown do
|
||||
Stripe.log_level = @old_log_level
|
||||
$stdout = @old_stdout
|
||||
end
|
||||
|
||||
context ".log_debug" do
|
||||
should "not log if logging is disabled" do
|
||||
Util.log_debug("foo")
|
||||
assert_equal "", $stdout.string
|
||||
end
|
||||
|
||||
should "log if level set to debug" do
|
||||
Stripe.log_level = Stripe::LEVEL_DEBUG
|
||||
Util.log_debug("foo")
|
||||
assert_equal "message=foo level=debug \n", $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_info" do
|
||||
should "not log if logging is disabled" do
|
||||
Util.log_info("foo")
|
||||
assert_equal "", $stdout.string
|
||||
end
|
||||
|
||||
should "log if level set to debug" do
|
||||
Stripe.log_level = Stripe::LEVEL_DEBUG
|
||||
Util.log_info("foo")
|
||||
assert_equal "message=foo level=info \n", $stdout.string
|
||||
end
|
||||
|
||||
should "log if level set to info" do
|
||||
Stripe.log_level = Stripe::LEVEL_INFO
|
||||
Util.log_info("foo")
|
||||
assert_equal "message=foo level=info \n", $stdout.string
|
||||
end
|
||||
end
|
||||
end
|
||||
|
||||
context ".normalize_headers" do
|
||||
should "normalize the format of a header key" do
|
||||
assert_equal({ "Request-Id" => nil },
|
||||
Util.normalize_headers({ "Request-Id" => nil }))
|
||||
assert_equal({ "Request-Id" => nil },
|
||||
Util.normalize_headers({ "request-id" => nil }))
|
||||
assert_equal({ "Request-Id" => nil },
|
||||
Util.normalize_headers({ "Request-ID" => nil }))
|
||||
assert_equal({ "Request-Id" => nil },
|
||||
Util.normalize_headers({ :request_id => nil }))
|
||||
end
|
||||
|
||||
should "tolerate bad formatting" do
|
||||
assert_equal({ "Request-Id" => nil },
|
||||
Util.normalize_headers({ "-Request--Id-" => nil }))
|
||||
assert_equal({ "Request-Id" => nil },
|
||||
Util.normalize_headers({ :request__id => nil }))
|
||||
end
|
||||
end
|
||||
|
||||
#
|
||||
# private
|
||||
#
|
||||
# I don't feel particularly good about using #send to invoke these, but I
|
||||
# want them hidden from the public interface, and each method is far easier
|
||||
# to test in isolation (as opposed to going through a public method).
|
||||
#
|
||||
|
||||
context ".colorize" do
|
||||
should "colorize for a TTY" do
|
||||
assert_equal "\033[0;32;49mfoo\033[0m",
|
||||
Util.send(:colorize, "foo", :green, true)
|
||||
end
|
||||
|
||||
should "not colorize otherwise" do
|
||||
assert_equal "foo", Util.send(:colorize, "foo", :green, false)
|
||||
end
|
||||
end
|
||||
|
||||
context ".log_internal" do
|
||||
should "log in a terminal friendly way" do
|
||||
out = StringIO.new
|
||||
|
||||
# Sketchy as anything, but saves us from pulling in a mocking library.
|
||||
# Open this instance of StringIO, and add a method override so that it
|
||||
# looks like a TTY.
|
||||
out.instance_eval do
|
||||
def isatty; true; end
|
||||
end
|
||||
|
||||
Util.send(:log_internal, "message", { foo: "bar" },
|
||||
color: :green, level: Stripe::LEVEL_DEBUG, 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)
|
||||
assert_equal "message=message level=debug foo=bar\n",
|
||||
out.string
|
||||
end
|
||||
end
|
||||
|
||||
context ".wrap_logfmt_value" do
|
||||
should "pass through simple values" do
|
||||
assert_equal "abc", Util.send(:wrap_logfmt_value, "abc")
|
||||
assert_equal "123", Util.send(:wrap_logfmt_value, "123")
|
||||
assert_equal "a-b_c/d", Util.send(:wrap_logfmt_value, "a-b_c/d")
|
||||
end
|
||||
|
||||
should "pass through numerics" do
|
||||
assert_equal 123, Util.send(:wrap_logfmt_value, 123)
|
||||
assert_equal 1.23, Util.send(:wrap_logfmt_value, 1.23)
|
||||
end
|
||||
|
||||
should "wrap more complex values in double quotes" do
|
||||
assert_equal %{"abc=123"}, Util.send(:wrap_logfmt_value, %{abc=123})
|
||||
end
|
||||
|
||||
should "escape double quotes already in the value" do
|
||||
assert_equal %{"abc=\\"123\\""}, Util.send(:wrap_logfmt_value, %{abc="123"})
|
||||
end
|
||||
|
||||
should "remove newlines" do
|
||||
assert_equal %{"abc"}, Util.send(:wrap_logfmt_value, "a\nb\nc")
|
||||
end
|
||||
|
||||
should "not error if given a non-string" do
|
||||
assert_equal "true", Util.send(:wrap_logfmt_value, true)
|
||||
end
|
||||
end
|
||||
end
|
||||
end
|
||||
|
||||
@ -3,6 +3,7 @@ require 'test/unit'
|
||||
require 'mocha/setup'
|
||||
require 'stringio'
|
||||
require 'shoulda/context'
|
||||
require "timecop"
|
||||
require 'webmock/test_unit'
|
||||
|
||||
PROJECT_ROOT = File.expand_path("../../", __FILE__)
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user