Add debug logging to all middleware (#167)

codegen/smithy-ruby-codegen-test/integration-specs/auth_spec.rb

@@ -215,7 +215,7 @@ module Auth
       Hearth::IdentityResolver.new(proc { identity })
     end
 
-    let(:client) { Client.new(**{ stub_responses: true }.merge(config_hash)) }
+    let(:client) { Client.new(stub_responses: true, **config_hash) }
 
     describe '#http_api_key_auth' do
       let(:config_hash) do

hearth/lib/hearth/http/middleware/content_length.rb

@@ -17,8 +17,16 @@ def call(input, context)
           request = context.request
           if request.body.respond_to?(:size) &&
              !request.headers.key?('Content-Length')
+            context.logger.debug(
+              '[HTTP::Middleware::ContentLength] ' \
+              'Started setting Content-Length'
+            )
             length = request.body.size
             request.headers['Content-Length'] = length
+            context.logger.debug(
+              '[HTTP::Middleware::ContentLength] ' \
+              'Finished setting Content-Length'
+            )
           end
 
           @app.call(input, context)

hearth/lib/hearth/http/middleware/content_md5.rb

@@ -16,8 +16,14 @@ def initialize(app, _ = {})
         def call(input, context)
           request = context.request
           unless request.headers.key?('Content-MD5')
+            context.logger.debug(
+              '[HTTP::Middleware::ContentMD5] Started setting Content-MD5'
+            )
             md5 = Hearth::Checksums.md5(request.body)
             request.headers['Content-MD5'] = md5
+            context.logger.debug(
+              '[HTTP::Middleware::ContentMD5] Finished setting Content-MD5'
+            )
           end
 
           @app.call(input, context)

hearth/lib/hearth/http/middleware/request_compression.rb

@@ -10,10 +10,17 @@ class RequestCompression
         SUPPORTED_ENCODINGS = %w[gzip].freeze
         CHUNK_SIZE = 1 * 1024 * 1024 # one MB
 
-        def initialize(app,
-                       disable_request_compression:,
-                       request_min_compression_size_bytes:,
-                       encodings:,
+        # @param [Class] app The next middleware in the stack.
+        # @param [Boolean] disable_request_compression If true, the request
+        #  body is not compressed.
+        # @param [Integer] request_min_compression_size_bytes The minimum size
+        #  of the request body to be compressed.
+        # @param [Array<String>] encodings The encodings to be used for
+        #  compression.
+        # @param [Boolean] streaming If true, the request body is compressed
+        #  in chunks.
+        def initialize(app, disable_request_compression:,
+                       request_min_compression_size_bytes:, encodings:,
                        streaming:)
           @app = app
           @disable_request_compression = disable_request_compression
@@ -27,24 +34,34 @@ def initialize(app,
         # @param context
         # @return [Output]
         def call(input, context)
-          request = context.request
-          unless @disable_request_compression
-            selected_encoding = @encodings.find do |encoding|
-              SUPPORTED_ENCODINGS.include?(encoding)
-            end
-            if selected_encoding
-              if @streaming
-                process_streaming_compression(selected_encoding, request)
-              elsif request.body.size >= @request_min_compression_size_bytes
-                process_compression(selected_encoding, request)
-              end
-            end
-          end
+          compress_request(context) unless @disable_request_compression
           @app.call(input, context)
         end
 
         private
 
+        def compress_request(context)
+          selected_encoding = @encodings.find do |encoding|
+            SUPPORTED_ENCODINGS.include?(encoding)
+          end
+          return unless selected_encoding
+
+          context.logger.debug(
+            '[HTTP::Middleware::RequestCompression] ' \
+            'Started compressing request'
+          )
+          request = context.request
+          if @streaming
+            compress_streaming_body(selected_encoding, request)
+          elsif request.body.size >= @request_min_compression_size_bytes
+            compress_body(selected_encoding, request)
+          end
+          context.logger.debug(
+            '[HTTP::Middleware::RequestCompression] ' \
+            'Finished compressing request'
+          )
+        end
+
         def update_content_encoding(encoding, request)
           headers = request.headers
           if headers['Content-Encoding']
@@ -54,7 +71,7 @@ def update_content_encoding(encoding, request)
           end
         end
 
-        def process_compression(encoding, request)
+        def compress_body(encoding, request)
           case encoding
           when 'gzip'
             gzip_compress(request)
@@ -85,7 +102,7 @@ def update_in_chunks(compressor, io)
           end
         end
 
-        def process_streaming_compression(encoding, request)
+        def compress_streaming_body(encoding, request)
           case encoding
           when 'gzip'
             request.body = GzipIO.new(request.body)

hearth/lib/hearth/middleware/auth.rb

@@ -33,8 +33,10 @@ def initialize(app, auth_resolver:, auth_params:, auth_schemes:, **kwargs)
       # @param context
       # @return [Output]
       def call(input, context)
+        context.logger.debug('[Middleware::Auth] Started resolving auth')
         auth_options = @auth_resolver.resolve(@auth_params)
         context.auth = resolve_auth(auth_options)
+        context.logger.debug('[Middleware::Auth] Finished resolving auth')
         @app.call(input, context)
       end
 

hearth/lib/hearth/middleware/build.rb

@@ -36,7 +36,7 @@ def call(input, context)
         )
         return Hearth::Output.new(error: interceptor_error) if interceptor_error
 
-        @builder.build(context.request, input: input)
+        build(input, context)
 
         interceptor_error = Interceptors.invoke(
           hook: Interceptor::READ_AFTER_SERIALIZATION,
@@ -49,6 +49,14 @@ def call(input, context)
 
         @app.call(input, context)
       end
+
+      private
+
+      def build(input, context)
+        context.logger.debug('[Middleware::Build] Started building request')
+        @builder.build(context.request, input: input)
+        context.logger.debug('[Middleware::Build] Finished building request')
+      end
     end
   end
 end

hearth/lib/hearth/middleware/host_prefix.rb

@@ -21,15 +21,19 @@ def initialize(app, disable_host_prefix:, host_prefix:)
       # @param context
       # @return [Output]
       def call(input, context)
-        unless @disable_host_prefix
-          prefix = apply_labels(@host_prefix, input)
-          context.request.prefix_host(prefix)
-        end
+        prefix_host(input, context) unless @disable_host_prefix
         @app.call(input, context)
       end
 
       private
 
+      def prefix_host(input, context)
+        context.logger.debug('[Middleware::HostPrefix] Started prefixing host')
+        prefix = apply_labels(@host_prefix, input)
+        context.request.prefix_host(prefix)
+        context.logger.debug('[Middleware::HostPrefix] Finished prefixing host')
+      end
+
       def apply_labels(host_prefix, input)
         host_prefix.gsub(/\{.+?\}/) do |host_label|
           key = host_label.delete('{}')

hearth/lib/hearth/middleware/initialize.rb

@@ -27,6 +27,7 @@ def call(input, context)
           if interceptor_error
             Hearth::Output.new(error: interceptor_error)
           else
+            context.logger.debug('[Middleware::Initialize] Started request')
             @app.call(input, context)
           end
 
@@ -39,6 +40,8 @@ def call(input, context)
         )
         output.error = interceptor_error if interceptor_error
 
+        context.logger.debug('[Middleware::Initialize] Finished request')
+
         interceptor_error = Interceptors.invoke(
           hook: Interceptor::READ_AFTER_EXECUTION,
           input: input,

hearth/lib/hearth/middleware/parse.rb

@@ -66,11 +66,15 @@ def call(input, context)
       private
 
       def parse_error(context, output)
+        context.logger.debug('[Middleware::Parse] Started parsing error')
         output.error = @error_parser.parse(context.response, output.metadata)
+        context.logger.debug('[Middleware::Parse] Finished parsing error')
       end
 
       def parse_data(context, output)
+        context.logger.debug('[Middleware::Parse] Started parsing data')
         output.data = @data_parser.parse(context.response)
+        context.logger.debug('[Middleware::Parse] Finished parsing data')
       end
     end
   end

hearth/lib/hearth/middleware/retry.rb

@@ -33,11 +33,10 @@ def call(input, context)
         )
         return Hearth::Output.new(error: interceptor_error) if interceptor_error
 
-        token = @retry_strategy.acquire_initial_retry_token(
-          context.metadata[:retry_token_scope]
-        )
-
+        token_scope = context.metadata[:retry_token_scope]
+        token = @retry_strategy.acquire_initial_retry_token(token_scope)
         output = nil
+        context.logger.debug('[Middleware::Retry] Starting retry loop')
         loop do
           interceptor_error = Interceptors.invoke(
             hook: Interceptor::READ_BEFORE_ATTEMPT,
@@ -51,6 +50,7 @@ def call(input, context)
             if interceptor_error
               Hearth::Output.new(error: interceptor_error)
             else
+              context.logger.debug('[Middleware::Retry] Trying request')
               @app.call(input, context)
             end
 
@@ -73,20 +73,28 @@ def call(input, context)
           output.error = interceptor_error if interceptor_error
 
           if (error = output.error)
+            context.logger.debug(
+              "[Middleware::Retry] Request errored: #{error.class}"
+            )
             error_info = @error_inspector_class.new(error, context.response)
             token = @retry_strategy.refresh_retry_token(token, error_info)
             break unless token
 
+            context.logger.debug(
+              "[Middleware::Retry] Sleeping #{token.retry_delay} before retry"
+            )
             Kernel.sleep(token.retry_delay)
           else
             @retry_strategy.record_success(token)
+            context.logger.debug('[Middleware::Retry] Finished sending request')
             break
           end
 
           reset_request(context)
           reset_response(context, output)
           @retries += 1
         end
+        context.logger.debug('[Middleware::Retry] Finished retry loop')
         output
       end
 

hearth/lib/hearth/middleware/send.rb

@@ -70,19 +70,23 @@ def call(input, context)
       private
 
       def stub_response(input, context, output)
+        context.logger.debug('[Middleware::Send] Started stubbing response')
         stub = @stubs.next(context.operation_name)
         apply_stub(stub, input, context, output)
+        context.logger.debug('[Middleware::Send] Finished stubbing response')
         return unless context.response.body.respond_to?(:rewind)
 
         context.response.body.rewind
       end
 
       def send_request(context, output)
+        context.logger.debug('[Middleware::Send] Started sending request')
         @client.transmit(
           request: context.request,
           response: context.response,
           logger: context.logger
         )
+        context.logger.debug('[Middleware::Send] Finished sending request')
       rescue Hearth::NetworkingError => e
         output.error = e
       end

hearth/lib/hearth/middleware/sign.rb

@@ -50,13 +50,14 @@ def call(input, context)
       private
 
       def sign_request(context)
+        context.logger.debug('[Middleware::Sign] Started signing request')
         auth = context.auth
-
         auth.signer.sign(
           request: context.request,
           identity: auth.identity,
           properties: auth.signer_properties
         )
+        context.logger.debug('[Middleware::Sign] Finished signing request')
       end
     end
   end

hearth/lib/hearth/middleware/validate.rb

@@ -21,9 +21,17 @@ def initialize(app, validate_input:, validator:)
       # @param context
       # @return [Output]
       def call(input, context)
-        @validator.validate!(input, context: 'input') if @validate_input
+        validate_input(input, context)
         @app.call(input, context)
       end
+
+      private
+
+      def validate_input(input, context)
+        context.logger.debug('[Middleware::Validate] Started validating input')
+        @validator.validate!(input, context: 'input') if @validate_input
+        context.logger.debug('[Middleware::Validate] Finished validating input')
+      end
     end
   end
 end

hearth/spec/hearth/http/middleware/content_length_spec.rb

@@ -5,25 +5,25 @@ module HTTP
     module Middleware
       describe ContentLength do
         let(:app) { double('app', call: output) }
+        let(:input) { double('input') }
+        let(:output) { double('output') }
 
         subject { ContentLength.new(app) }
 
         describe '#call' do
-          let(:input) { double('input') }
-          let(:output) { double('output') }
-
           let(:request) do
             Request.new(
               http_method: 'GET',
               body: body
             )
           end
-
           let(:response) { double('response') }
+          let(:logger) { Logger.new(IO::NULL) }
           let(:context) do
             Context.new(
               request: request,
-              response: response
+              response: response,
+              logger: logger
             )
           end
 

hearth/spec/hearth/http/middleware/content_md5_spec.rb

@@ -5,27 +5,26 @@ module HTTP
     module Middleware
       describe ContentMD5 do
         let(:app) { double('app', call: output) }
+        let(:input) { double('input') }
+        let(:output) { double('output') }
 
         subject { ContentMD5.new(app) }
 
         describe '#call' do
-          let(:input) { double('input') }
-          let(:output) { double('output') }
-
           let(:body) { StringIO.new('test-body') }
-
           let(:request) do
             Request.new(
               http_method: 'GET',
               body: body
             )
           end
-
           let(:response) { double('response') }
+          let(:logger) { Logger.new(IO::NULL) }
           let(:context) do
             Context.new(
               request: request,
-              response: response
+              response: response,
+              logger: logger
             )
           end