From d1dc16151445f700f0e00c282bfa041fde223735 Mon Sep 17 00:00:00 2001
From: Etki <etki@etki.me>
Date: Thu, 3 Aug 2017 18:47:27 +0300
Subject: [PATCH] Enhanced log output

---
 lib/mapper/engine/recursive_mapper.rb         | 71 +++++++++++++------
 lib/mapper/engine/recursive_normalizer.rb     | 26 ++++++-
 lib/mapper/mixin/suppression_support.rb       |  4 +-
 lib/mapper/type/attribute.rb                  | 13 +++-
 test/suite/unit/mapper/type/attribute.spec.rb |  6 +-
 5 files changed, 94 insertions(+), 26 deletions(-)

diff --git a/lib/mapper/engine/recursive_mapper.rb b/lib/mapper/engine/recursive_mapper.rb
index 9c3d8fc..9bc6f95 100644
--- a/lib/mapper/engine/recursive_mapper.rb
+++ b/lib/mapper/engine/recursive_mapper.rb
@@ -1,5 +1,7 @@
 # frozen_string_literal: true
 
+# rubocop:disable Metrics/ClassLength
+
 require_relative '../mixin/suppression_support'
 require_relative '../mixin/errors'
 require_relative '../error'
@@ -23,14 +25,7 @@ def initialize(registry)
           # @param [Array<AMA::Entity::Mapper::Type] types
           # @param [AMA::Entity::Mapper::Context] context
           def map(source, types, context)
-            message = "Mapping #{source.class} into one of " \
-              "#{types.map(&:to_def).join(', ')}"
-            context.logger.debug(message)
-            successful(types, Mapper::Error) do |type|
-              result = map_type(source, type, context)
-              type.valid!(result, context)
-              result
-            end
+            map_unsafe(source, types, context)
           rescue StandardError => e
             message = "Failed to map #{source.class} " \
               "to any of provided types (#{types.map(&:to_def).join(', ')}). " \
@@ -45,18 +40,51 @@ def map(source, types, context)
           def map_type(source, type, ctx)
             ctx.logger.debug("Mapping #{source.class} to type #{type.to_def}")
             source, reassembled = request_reassembly(source, type, ctx)
+            epithet = reassembled ? 'reassembled' : 'source'
+            if type.attributes.empty?
+              message = "#{type.to_def} has no attributes, " \
+                "returning #{epithet} instance"
+              ctx.logger.debug(message)
+              return source
+            end
+            process_attributes(source, type, ctx)
+          end
+
+          private
+
+          # @param [Object] source
+          # @param [Array<AMA::Entity::Mapper::Type] types
+          # @param [AMA::Entity::Mapper::Context] context
+          def map_unsafe(source, types, context)
+            message = "Mapping #{source.class} into one of: " \
+              "#{types.map(&:to_def).join(', ')}"
+            context.logger.debug(message)
+            successful(types, Mapper::Error, context) do |type|
+              result = map_type(source, type, context)
+              context.logger.debug("Validating resulting #{type.to_def}")
+              type.valid!(result, context)
+              result
+            end
+          end
+
+          # @param [Object] source
+          # @param [AMA::Entity::Mapper::Type] type
+          # @param [AMA::Entity::Mapper::Context] ctx
+          # @return [Object]
+          def process_attributes(source, type, ctx)
             attributes = map_attributes(source, type, ctx)
             if attributes.select(&:first).empty?
-              epithet = reassembled ? 'reassembled' : 'source'
-              ctx.logger.debug("No changes detected, returning #{epithet} data")
+              message = 'No changes in attributes detected, ' \
+                "returning #{source.class}"
+              ctx.logger.debug(message)
               return source
             end
+            ctx.logger.debug("Creating new #{type.to_def} instance")
             target = type.factory.create(type, source, ctx)
+            ctx.logger.debug("Installing #{type.to_def} attributes")
             install_attributes(target, type, attributes, ctx)
           end
 
-          private
-
           # Returns array of mapped attribute in format
           # [[changed?, attribute, value, attribute_context],..]
           # @param [Object] source
@@ -64,13 +92,15 @@ def map_type(source, type, ctx)
           # @param [AMA::Entity::Mapper::Context] ctx
           # @return [Array]
           def map_attributes(source, type, ctx)
-            ctx.logger.debug("Mapping #{source} attributes")
+            ctx.logger.debug("Mapping #{source.class} attributes")
             enumerator = type.enumerator.enumerate(source, type, ctx)
             enumerator.map do |attribute, value, segment|
               local_ctx = segment.nil? ? ctx : ctx.advance(segment)
               mutated = map_attribute(value, attribute, local_ctx)
               changed = !mutated.equal?(value)
-              ctx.logger.debug("#{attribute} has changed") if changed
+              if changed
+                ctx.logger.debug("Attribute #{attribute.to_def} has changed")
+              end
               [changed, attribute, mutated, local_ctx]
             end
           end
@@ -79,7 +109,8 @@ def map_attributes(source, type, ctx)
           # @param [AMA::Entity::Mapper::Type::Attribute] attribute
           # @param [AMA::Entity::Mapper::Context] context
           def map_attribute(source, attribute, context)
-            message = "Extracting attribute #{attribute} from #{source.class}"
+            message = "Extracting attribute #{attribute.to_def} " \
+              "from #{source.class}"
             context.logger.debug(message)
             successful(attribute.types, Mapper::Error) do |type|
               if source.nil? && attribute.nullable
@@ -87,6 +118,7 @@ def map_attribute(source, attribute, context)
                 break nil
               end
               result = map_type(source, type, context)
+              context.logger.debug("Validating resulting #{attribute.to_def}")
               attribute.valid!(result, context)
               result
             end
@@ -97,7 +129,7 @@ def map_attribute(source, attribute, context)
           # @param [Array] attributes
           # @param [AMA::Entity::Mapper::Context] ctx
           def install_attributes(target, type, attributes, ctx)
-            ctx.logger.debug("Installing updated attributes on #{type}")
+            ctx.logger.debug("Installing updated attributes on #{type.to_def}")
             attributes.each do |_, attribute, value, local_ctx|
               type.injector.inject(target, type, attribute, value, local_ctx)
             end
@@ -110,9 +142,8 @@ def install_attributes(target, type, attributes, ctx)
           # @return [Array<Object, TrueClass, FalseClass>]
           def request_reassembly(source, type, context)
             if type.instance?(source)
-              message = "Not reassembling #{source} as #{type.to_def}, " \
-                'already of target type'
-              context.logger.debug(message)
+              msg = "Not reassembling #{source.class}, already of target type"
+              context.logger.debug(msg)
               return [source, false]
             end
             reassemble(source, type, context)
@@ -123,7 +154,7 @@ def request_reassembly(source, type, context)
           # @param [AMA::Entity::Mapper::Context] context
           # @return [Object]
           def reassemble(source, type, context)
-            message = "Reassembling #{source.class} as #{type.to_def}"
+            message = "Reassembling #{source.class} as #{type.type}"
             context.logger.debug(message)
             source_type = @registry.find(source.class) || Type.new(source.class)
             normalizer = source_type.normalizer
diff --git a/lib/mapper/engine/recursive_normalizer.rb b/lib/mapper/engine/recursive_normalizer.rb
index 6e57c9c..33fb6b1 100644
--- a/lib/mapper/engine/recursive_normalizer.rb
+++ b/lib/mapper/engine/recursive_normalizer.rb
@@ -19,19 +19,39 @@ def initialize(registry)
           def normalize(entity, ctx, type = nil)
             type ||= find_type(entity.class)
             target = entity
-            unless type.virtual
+            ctx.logger.debug("Normalizing #{entity.class} as #{type.type}")
+            if type.virtual
+              message = "Type #{type.type} is virtual, skipping to attributes"
+              ctx.logger.debug(message)
+            else
               target = type.normalizer.normalize(entity, type, ctx)
             end
             target_type = find_type(target.class)
-            normalize_attributes(target, target_type, ctx)
+            process_attributes(target, target_type, ctx)
           end
 
           private
 
+          # @param [Object] entity
+          # @param [AMA::Entity::Mapper::Type] type
+          # @param [AMA::Entity::Mapper::Context] ctx
+          def process_attributes(entity, type, ctx)
+            if type.attributes.empty?
+              message = "No attributes found on #{type.type}, returning " \
+                "#{entity.class} as is"
+              ctx.logger.debug(message)
+              return entity
+            end
+            normalize_attributes(entity, type, ctx)
+          end
+
           # @param [Object] entity
           # @param [AMA::Entity::Mapper::Type] type
           # @param [AMA::Entity::Mapper::Context] ctx
           def normalize_attributes(entity, type, ctx)
+            message = "Normalizing attributes of #{entity.class} " \
+              "(as #{type.type})"
+            ctx.logger.debug(message)
             enumerator = type.enumerator.enumerate(entity, type, ctx)
             enumerator.each do |attribute, value, segment|
               local_ctx = ctx.advance(segment)
@@ -41,6 +61,8 @@ def normalize_attributes(entity, type, ctx)
             entity
           end
 
+          # @param [Class, Module] klass
+          # @return [AMA::Entity::Mapper::Type]
           def find_type(klass)
             @registry.find(klass) || Type.new(klass)
           end
diff --git a/lib/mapper/mixin/suppression_support.rb b/lib/mapper/mixin/suppression_support.rb
index 06cae7b..749da06 100644
--- a/lib/mapper/mixin/suppression_support.rb
+++ b/lib/mapper/mixin/suppression_support.rb
@@ -16,12 +16,14 @@ module SuppressionSupport
           #
           # @param [Enumerator] enumerator
           # @param [Class<? extends StandardError>] error
-          def successful(enumerator, error = StandardError)
+          # @param [AMA::Entity::Mapper::Context] ctx
+          def successful(enumerator, error = StandardError, ctx = nil)
             suppressed = []
             enumerator.each do |*args|
               begin
                 return yield(*args)
               rescue error => e
+                ctx.logger.debug("#{e.class} raised: #{e.message}") if ctx
                 suppressed.push(e)
               end
             end
diff --git a/lib/mapper/type/attribute.rb b/lib/mapper/type/attribute.rb
index a04155b..515b29d 100644
--- a/lib/mapper/type/attribute.rb
+++ b/lib/mapper/type/attribute.rb
@@ -1,5 +1,7 @@
 # frozen_string_literal: true
 
+# rubocop:disable Metrics/ClassLength
+
 require_relative '../handler/attribute/validator'
 require_relative '../mixin/errors'
 require_relative '../mixin/handler_support'
@@ -146,9 +148,18 @@ def ==(other)
             eql?(other)
           end
 
+          def to_def
+            types = @types ? @types.map(&:to_def).join(', ') : 'none'
+            message = "#{owner.type}.#{name}"
+            message += ':virtual' if virtual
+            "#{message}<#{types}>"
+          end
+
           def to_s
             message = "Attribute #{owner.type}.#{name}"
-            virtual ? "#{message} (virtual)" : message
+            message = "#{message} (virtual)" if virtual
+            types = @types ? @types.map(&:to_def).join(', ') : 'none'
+            "#{message} <#{types}>"
           end
 
           private
diff --git a/test/suite/unit/mapper/type/attribute.spec.rb b/test/suite/unit/mapper/type/attribute.spec.rb
index efbd6ee..0632ab1 100644
--- a/test/suite/unit/mapper/type/attribute.spec.rb
+++ b/test/suite/unit/mapper/type/attribute.spec.rb
@@ -13,7 +13,8 @@
     double(
       type: Class.new,
       is_a?: true,
-      to_s: 'type',
+      to_s: 'Type',
+      to_def: 'Type',
       resolved?: true,
       resolved!: nil
     )
@@ -23,7 +24,8 @@
     double(
       type: Class.new,
       is_a?: true,
-      to_s: 'other type',
+      to_s: 'OtherType',
+      to_def: 'OtherType',
       resolved?: true,
       resolved!: nil
     )