Merge pull request #459 from Dynamoid/add-log-formatter-config-option

Log formatting

Author: andrykonchin

README.md

@@ -1069,7 +1069,7 @@ Listed below are all configuration options.
 * `models_dir` - `dynamoid:create_tables` rake task loads DynamoDb
   models from this directory. Default is `./app/models`.
 * `application_timezone` - Dynamoid converts all `datetime` fields to
-* specified time zone when loads data from the storage.
+  specified time zone when loads data from the storage.
   Acceptable values - `:utc`, `:local` (to use system time zone) and
   time zone name e.g. `Eastern Time (US & Canada)`. Default is `utc`
 * `dynamodb_timezone` - When a datetime field is stored in string format
@@ -1089,6 +1089,11 @@ Listed below are all configuration options.
   `nil`
 * `backoff_strategies`: is a hash and contains all available strategies.
   Default is { constant: ..., exponential: ...}
+* `log_formatter`: overrides default AWS SDK formatter. There are
+  several canned formatters: `Aws::Log::Formatter.default`,
+  `Aws::Log::Formatter.colored` and `Aws::Log::Formatter.short`. Please
+  look into `Aws::Log::Formatter` AWS SDK documentation in order to
+  provide own formatter.
 * `http_continue_timeout`: The number of seconds to wait for a
   100-continue HTTP response before sending the request body. Default
   option value is `nil`. If not specified effected value is `1`

lib/dynamoid/adapter_plugin/aws_sdk_v3.rb

@@ -109,12 +109,14 @@ def connection_config
           end
         end
 
-        # https://github.com/aws/aws-sdk-ruby/blob/master/gems/aws-sdk-core/lib/aws-sdk-core/plugins/logging.rb
-        # https://github.com/aws/aws-sdk-ruby/blob/master/gems/aws-sdk-core/lib/aws-sdk-core/log/formatter.rb
-        formatter = Aws::Log::Formatter.new(':operation | Request :http_request_body | Response :http_response_body')
         @connection_hash[:logger] = Dynamoid::Config.logger
         @connection_hash[:log_level] = :debug
-        @connection_hash[:log_formatter] = formatter
+
+        # https://github.com/aws/aws-sdk-ruby/blob/master/gems/aws-sdk-core/lib/aws-sdk-core/plugins/logging.rb
+        # https://github.com/aws/aws-sdk-ruby/blob/master/gems/aws-sdk-core/lib/aws-sdk-core/log/formatter.rb
+        if Dynamoid::Config.log_formatter
+          @connection_hash[:log_formatter] = Dynamoid::Config.log_formatter
+        end
 
         @connection_hash
       end

lib/dynamoid/config.rb

@@ -54,6 +54,7 @@ module Config
       constant: BackoffStrategies::ConstantBackoff,
       exponential: BackoffStrategies::ExponentialBackoff
     }
+    option :log_formatter, default: nil
     option :http_continue_timeout, default: nil # specify if you'd like to overwrite Aws Configure - default: 1
     option :http_idle_timeout, default: nil     #                                                  - default: 5
     option :http_open_timeout, default: nil     #                                                  - default: 15

lib/dynamoid/log/formatter.rb

@@ -0,0 +1,26 @@
+module Dynamoid
+  module Log
+    module Formatter
+
+      # https://docs.aws.amazon.com/sdk-for-ruby/v3/api/Aws/Log/Formatter.html
+      # https://docs.aws.amazon.com/sdk-for-ruby/v2/api/Seahorse/Client/Response.html
+      # https://aws.amazon.com/ru/blogs/developer/logging-requests/
+      class Debug
+        def format(response)
+          bold = "\x1b[1m"
+          color = "\x1b[34m"
+          reset = "\x1b[0m"
+
+          [
+            response.context.operation.name,
+            "#{bold}#{color}\nRequest:\n#{reset}#{bold}",
+            JSON.pretty_generate(JSON.parse(response.context.http_request.body.string)),
+            "#{bold}#{color}\nResponse:\n#{reset}#{bold}",
+            JSON.pretty_generate(JSON.parse(response.context.http_response.body.string)),
+            reset
+          ].join("\n")
+        end
+      end
+    end
+  end
+end

spec/dynamoid/config_spec.rb

@@ -26,4 +26,30 @@
       expect(credentials.secret_access_key).to eq 'your_secret_access_key'
     end
   end
+
+  describe 'log_formatter' do
+    let(:log_formatter) { Aws::Log::Formatter.short }
+    let(:logger) { Logger.new(buffer) }
+    let(:buffer) { StringIO.new }
+
+    before do
+      @log_formatter = Dynamoid.config.log_formatter
+      @logger = Dynamoid.config.logger
+
+      Dynamoid.config.log_formatter = log_formatter
+      Dynamoid.config.logger = logger
+      Dynamoid.adapter.connect!  # clear cached client
+    end
+
+    after do
+      Dynamoid.config.log_formatter = @log_formatter
+      Dynamoid.config.logger = @logger
+      Dynamoid.adapter.connect!  # clear cached client
+    end
+
+    it 'changes logging format' do
+      new_class.create_table
+      expect(buffer.string).to match(/\[Aws::DynamoDB::Client 200 .+\] create_table \n/)
+    end
+  end
 end

spec/dynamoid/log/formatter/debug_spec.rb

@@ -0,0 +1,92 @@
+require 'spec_helper'
+require 'dynamoid/log/formatter'
+
+describe Dynamoid::Log::Formatter::Debug do
+  describe '#format' do
+    let(:subject) { described_class.new }
+
+    let(:logger) { Logger.new(buffer) }
+    let(:buffer) { StringIO.new }
+
+    let(:request) do
+      <<~JSON
+        {
+          "TableName": "dynamoid_tests_items",
+          "KeySchema": [
+            {
+              "AttributeName": "id",
+              "KeyType": "HASH"
+            }
+          ],
+          "AttributeDefinitions": [
+            {
+              "AttributeName": "id",
+              "AttributeType": "S"
+            }
+          ],
+          "BillingMode": "PROVISIONED",
+          "ProvisionedThroughput": {
+            "ReadCapacityUnits": 100,
+            "WriteCapacityUnits": 20
+          }
+        }
+      JSON
+    end
+
+    let(:response_pattern) do
+      Regexp.compile <<~JSON
+        \\{
+          "TableDescription": \\{
+            "AttributeDefinitions": \\[
+              \\{
+                "AttributeName": "id",
+                "AttributeType": "S"
+              \\}
+            \\],
+            "TableName": "dynamoid_tests_items",
+            "KeySchema": \\[
+              \\{
+                "AttributeName": "id",
+                "KeyType": "HASH"
+              \\}
+            \\],
+            "TableStatus": "ACTIVE",
+            "CreationDateTime": .+?,
+            "ProvisionedThroughput": \\{
+              "LastIncreaseDateTime": 0.0,
+              "LastDecreaseDateTime": 0.0,
+              "NumberOfDecreasesToday": 0,
+              "ReadCapacityUnits": 100,
+              "WriteCapacityUnits": 20
+            \\},
+            "TableSizeBytes": 0,
+            "ItemCount": 0,
+            "TableArn": ".+?"
+          \\}
+        \\}
+      JSON
+    end
+
+    before do
+      @log_formatter = Dynamoid.config.log_formatter
+      @logger = Dynamoid.config.logger
+
+      Dynamoid.config.log_formatter = subject
+      Dynamoid.config.logger = logger
+      Dynamoid.adapter.connect!  # clear cached client
+    end
+
+    after do
+      Dynamoid.config.log_formatter = @log_formatter
+      Dynamoid.config.logger = @logger
+      Dynamoid.adapter.connect!  # clear cached client
+    end
+
+    it 'logs request and response JSON body' do
+      new_class(table_name: 'items').create_table
+
+      expect(buffer.string).to include(request)
+      expect(buffer.string).to match(response_pattern)
+    end
+  end
+end

spec/spec_helper.rb

@@ -10,6 +10,7 @@
 
 require 'rspec'
 require 'dynamoid'
+require 'dynamoid/log/formatter'
 require 'pry'
 require 'byebug' if ENV['DEBUG']
 
@@ -27,6 +28,7 @@
   config.warn_on_scan = false
   config.sync_retry_wait_seconds = 0
   config.sync_retry_max_times = 3
+  config.log_formatter = Dynamoid::Log::Formatter::Debug.new
 end
 
 Dynamoid.logger.level = Logger::FATAL