From ce69d749e1efbdfd8432de38e4e870ab8a3a18a9 Mon Sep 17 00:00:00 2001 From: Brandur Date: Tue, 1 Aug 2017 14:42:56 -0700 Subject: [PATCH] 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 --- Gemfile | 1 + README.md | 18 +++ lib/stripe.rb | 24 ++++ lib/stripe/stripe_client.rb | 185 +++++++++++++++++++++++++++--- lib/stripe/util.rb | 135 ++++++++++++++++++++-- test/stripe/stripe_client_test.rb | 152 ++++++++++++++++++++++++ test/stripe/util_test.rb | 164 ++++++++++++++++++++++++++ test/test_helper.rb | 1 + 8 files changed, 653 insertions(+), 27 deletions(-) diff --git a/Gemfile b/Gemfile index eb9c71fa..f404178d 100644 --- a/Gemfile +++ b/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 diff --git a/README.md b/README.md index 2711f98c..4f161508 100644 --- a/README.md +++ b/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 diff --git a/lib/stripe.rb b/lib/stripe.rb index 55e3a8ef..3a12f8c1 100644 --- a/lib/stripe.rb +++ b/lib/stripe.rb @@ -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 diff --git a/lib/stripe/stripe_client.rb b/lib/stripe/stripe_client.rb index 4487c197..acd476d0 100644 --- a/lib/stripe/stripe_client.rb +++ b/lib/stripe/stripe_client.rb @@ -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. diff --git a/lib/stripe/util.rb b/lib/stripe/util.rb index 81e675a6..bc3b42e0 100644 --- a/lib/stripe/util.rb +++ b/lib/stripe/util.rb @@ -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 diff --git a/test/stripe/stripe_client_test.rb b/test/stripe/stripe_client_test.rb index 025684a1..dc2ea0f8 100644 --- a/test/stripe/stripe_client_test.rb +++ b/test/stripe/stripe_client_test.rb @@ -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 diff --git a/test/stripe/util_test.rb b/test/stripe/util_test.rb index 098e9253..d8ddcddf 100644 --- a/test/stripe/util_test.rb +++ b/test/stripe/util_test.rb @@ -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 diff --git a/test/test_helper.rb b/test/test_helper.rb index e0fab540..c4e63458 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -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__)