Merge pull request #17 from jcagarcia/logger

feature(#12): Allow to provide a logger instance for logging useful information

CHANGELOG.md

@@ -12,15 +12,16 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Changed
 
-* [#16](https://github.com/jcagarcia/grape-idempotency/pull/16): Changing error response code to 422 for conflict - [@Flip120](https://github.com/Flip120).
 * [#11](https://github.com/jcagarcia/grape-idempotency/pull/11): Changing error response formats - [@Flip120](https://github.com/Flip120).
+* [#16](https://github.com/jcagarcia/grape-idempotency/pull/16): Changing error response code to 422 for conflict - [@Flip120](https://github.com/Flip120).
 
 * Your contribution here.
 
 ### Feature
 
-* [#15](https://github.com/jcagarcia/grape-idempotency/pull/15): Allow to mark the idempotent header as required - [@jcagarcia](https://github.com/jcagarcia).
 * [#11](https://github.com/jcagarcia/grape-idempotency/pull/11): Return 409 conflict when a request is still being processed - [@Flip120](https://github.com/Flip120).
+* [#15](https://github.com/jcagarcia/grape-idempotency/pull/15): Allow to mark the idempotent header as required - [@jcagarcia](https://github.com/jcagarcia).
+* [#17](https://github.com/jcagarcia/grape-idempotency/pull/17): Allow to configure logger - [@jcagarcia](https://github.com/jcagarcia).
 * Your contribution here.
 
 ## [0.1.3] - 2023-01-07

README.md

@@ -160,6 +160,40 @@ end
 
 In the case above, you request your consumers to use the `X-Trace-Id: <trace-id>` header when requesting your API.
 
+### logger, logger_level and logger_prefix
+
+By default, the logger used by the gem is configured like `Logger.new(STDOUT)` and `INFO` level. As this gem does not log any message with `INFO` level, only `ERROR` messages will be logged.
+
+
+If you want to provide your own logger, you want to change the level to `DEBUG` or you want to provide your own prefix, you can configure the gem like:
+
+```ruby
+Grape::Idempotency.configure do |c|
+  c.logger = Infrastructure::MyLogger.new
+  c.logger_level = :debug
+  c.logger_prefix = '[my-own-prefix]'
+end
+```
+
+An example of the logged information when changing the level of the log to `DEBUG` and customizing the `logger_prefix`:
+
+```shell
+I, [2023-11-23T22:41:39.148163 #1]  DEBUG -- : [my-own-prefix] Performing endpoint "/payments" with idempotency.
+I, [2023-11-23T22:41:39.148176 #1]  DEBUG -- : [my-own-prefix] Idempotency key is NOT mandatory for this endpoint.
+I, [2023-11-23T22:41:39.148192 #1]  DEBUG -- : [my-own-prefix] Idempotency key received in request header "x-custom-idempotency-key" => "fd77c9d6-b7da-4966-aac8-40ee258f24aa"
+I, [2023-11-23T22:41:39.148210 #1]  DEBUG -- : [my-own-prefix] Previous request information has NOT been found for the provided idempotency key.
+I, [2023-11-23T22:41:39.148248 #1]  DEBUG -- : [my-own-prefix] Request stored as processing.
+I, [2023-11-23T22:41:39.148261 #1]  DEBUG -- : [my-own-prefix] Performing the provided block.
+I, [2023-11-23T22:41:39.148268 #1]  DEBUG -- : [my-own-prefix] Block has been performed.
+I, [2023-11-23T22:41:39.148287 #1]  DEBUG -- : [my-own-prefix] Storing response.
+I, [2023-11-23T22:41:39.148317 #1]  DEBUG -- : [my-own-prefix] Response stored.
+I, [2023-11-23T22:41:39.148473 #1]  DEBUG -- : [my-own-prefix] Performing endpoint "/payments" with idempotency.
+I, [2023-11-23T22:41:39.148486 #1]  DEBUG -- : [my-own-prefix] Idempotency key is NOT mandatory for this endpoint.
+I, [2023-11-23T22:41:39.148502 #1]  DEBUG -- : [my-own-prefix] Idempotency key received in request header "x-custom-idempotency-key" => "fd77c9d6-b7da-4966-aac8-40ee258f24aa"
+I, [2023-11-23T22:41:39.148523 #1]  DEBUG -- : [my-own-prefix] Request has been found for the provided idempotency key => {"path"=>"/payments", "params"=>{"locale"=>"undefined", "{\"amount\":10000}"=>nil}, "status"=>500, "original_request"=>"wadus", "response"=>"{\"error\":\"Internal Server Error\"}"}
+I, [2023-11-23T22:41:39.148537 #1]  DEBUG -- : [my-own-prefix] Returning the response from the original request.
+```
+
 ### conflict_error_response
 
 When providing a `Idempotency-Key: <key>` header, this gem compares incoming parameters to those of the original request (if exists) and returns a `409 - Conflict` status code if they don't match, preventing accidental misuse. The response body returned by the gem looks like:

lib/grape/idempotency.rb

@@ -1,4 +1,5 @@
 require 'grape'
+require 'logger'
 require 'securerandom'
 require 'grape/idempotency/version'
 require 'grape/idempotency/middleware/error'
@@ -23,51 +24,77 @@ def restore_configuration
 
       def idempotent(grape, required: false, &block)
         validate_config!
+        log(:debug, "Performing endpoint \"#{grape.request.path}\" with idempotency.")
+        log(:debug, "Idempotency key is #{!required ? 'NOT' : ''} mandatory for this endpoint.")
 
         idempotency_key = get_idempotency_key(grape.request.headers)
+        log(:debug, "Idempotency key received in request header \"#{configuration.idempotency_key_header.downcase}\" => \"#{idempotency_key}\"") if idempotency_key
 
         grape.error!(configuration.mandatory_header_response, 400) if required && !idempotency_key
         return block.call if !idempotency_key
 
         cached_request = get_from_cache(idempotency_key)
+        log(:debug, "Request has been found for the provided idempotency key => #{cached_request}") if cached_request
         if cached_request && (cached_request["params"] != grape.request.params || cached_request["path"] != grape.request.path)
+          log(:debug, "Request has conflicts. Same params? => #{cached_request["params"] != grape.request.params}. Same path? => #{cached_request["path"] != grape.request.path}")
+          log(:debug, "Returning conflict error response.")
           grape.error!(configuration.conflict_error_response, 422)
         elsif cached_request && cached_request["processing"] == true
+          log(:debug, "Returning processing error response.")
           grape.error!(configuration.processing_response, 409)
         elsif cached_request
+          log(:debug, "Returning the response from the original request.")
           grape.status cached_request["status"]
           grape.header(ORIGINAL_REQUEST_HEADER, cached_request["original_request"])
           grape.header(configuration.idempotency_key_header, idempotency_key)
           return cached_request["response"]
         end
 
+        log(:debug, "Previous request information has NOT been found for the provided idempotency key.")
+
         original_request_id = get_request_id(grape.request.headers)
         success = store_processing_request(idempotency_key, grape.request.path, grape.request.params, original_request_id)
         if !success
+          log(:error, "Request NOT stored as processing. Concurrent requests for the same idempotency key appeared.")
           grape.error!(configuration.processing_response, 409)
+        else
+          log(:debug, "Request stored as processing.")
         end
 
+        log(:debug, "Performing the provided block.")
+
         response = catch(:error) do
           block.call
         end
 
-        response = response[:message] if is_an_error?(response)
+        log(:debug, "Block has been performed.")
+
+        if is_an_error?(response)
+          log(:debug, "An error response was returned by the performed block. => #{response}")
+          response = response[:message]
+        end
 
         grape.header(ORIGINAL_REQUEST_HEADER, original_request_id)
         grape.body response
       rescue => e
+        log(:debug, "An unexpected error was raised when performing the block.")
         if !cached_request && !response
           validate_config!
+          log(:debug, "Storing error response.")
           original_request_id = get_request_id(grape.request.headers)
           stored_key = store_error_request(idempotency_key, grape.request.path, grape.request.params, grape.status, original_request_id, e)
+          log(:debug, "Error response stored.")
           grape.header(ORIGINAL_REQUEST_HEADER, original_request_id)
           grape.header(configuration.idempotency_key_header, stored_key)
         end
+        log(:debug, "Re-raising the error.")
         raise
       ensure
         if !cached_request && response
           validate_config!
+          log(:debug, "Storing response.")
           stored_key = store_request_response(idempotency_key, grape.request.path, grape.request.params, grape.status, original_request_id, response)
+          log(:debug, "Response stored.")
           grape.header(configuration.idempotency_key_header, stored_key)
         end
       end
@@ -91,11 +118,11 @@ def update_error_with_rescue_from_result(error, status, response)
       private
 
       def validate_config!
-        storage = configuration.storage
+        raise Configuration::Error.new("A Redis instance must be configured as cache storage") unless valid_storage?
+      end
 
-        if storage.nil? || !storage.respond_to?(:set)
-          raise Configuration::Error.new("A Redis instance must be configured as cache storage")
-        end
+      def valid_storage?
+        configuration.storage && configuration.storage.respond_to?(:set)
       end
 
       def get_idempotency_key(headers)
@@ -206,18 +233,34 @@ def storage
         configuration.storage
       end
 
+      def log(level, msg)
+        logger.send(level, "#{configuration.logger_prefix} #{msg}")
+      end
+
+      def logger
+        return @logger if @logger
+
+        @logger = configuration.logger
+        @logger.level = configuration.logger_level
+        @logger
+      end
+
       def configuration
         @configuration ||= Configuration.new
       end
     end
 
     class Configuration
-      attr_accessor :storage, :expires_in, :idempotency_key_header, :request_id_header, :conflict_error_response, :processing_response, :mandatory_header_response
+      attr_accessor :storage, :logger, :logger_level, :logger_prefix, :expires_in, :idempotency_key_header,
+        :request_id_header, :conflict_error_response, :processing_response, :mandatory_header_response
 
       class Error < StandardError; end
 
       def initialize
         @storage = nil
+        @logger = Logger.new(STDOUT)
+        @logger_level = Logger::INFO
+        @logger_prefix = "[grape-idempotency]"
         @expires_in = 216_000
         @idempotency_key_header = "idempotency-key"
         @request_id_header = "x-request-id"

lib/grape/idempotency/middleware/error.rb

@@ -3,14 +3,18 @@
 module Grape
   module Middleware
     class Error < Base
-      def run_rescue_handler(handler, error)
+      def run_rescue_handler(handler, error, endpoint=nil)
         if handler.instance_of?(Symbol)
           raise NoMethodError, "undefined method '#{handler}'" unless respond_to?(handler)
 
           handler = public_method(handler)
         end
 
-        response = handler.arity.zero? ? instance_exec(&handler) : instance_exec(error, &handler)
+        if endpoint
+          response = handler.arity.zero? ? endpoint.instance_exec(&handler) : endpoint.instance_exec(error, &handler)
+        else
+          response = handler.arity.zero? ? instance_exec(&handler) : instance_exec(error, &handler)
+        end
 
         if response.is_a?(Rack::Response)
           update_idempotency_error_with(error, response)

lib/grape/idempotency/version.rb

@@ -2,6 +2,6 @@
 
 module Grape
   module Idempotency
-    VERSION = '0.1.3'
+    VERSION = '1.0.0'
   end
 end

spec/idempotent_spec.rb

@@ -230,7 +230,7 @@
               post 'payments?locale=undefined', { amount: 100_00 }.to_json
             end
 
-            context 'but there is no possible to store the request as processing' do
+            context 'but is no possible to store the request as processing' do
               it 'returns conflict' do
                 app.post('/payments') do
                   idempotent do