Add Logging

CHANGELOG.md

@@ -14,6 +14,7 @@ Breaking changes:
 
 Features:
 
+- [#1291](https://github.com/rails-api/active_model_serializers/pull/1291) Add logging (@maurogeorge)
 - [#1225](https://github.com/rails-api/active_model_serializers/pull/1125) Better serializer lookup, use nested serializer when it exists (@beauby)
 - [#1172](https://github.com/rails-api/active_model_serializers/pull/1172) Better serializer registration, get more than just the first module (@bf4)
 - [#1158](https://github.com/rails-api/active_model_serializers/pull/1158) Add support for wildcards in `include` option (@beauby)

docs/README.md

@@ -9,6 +9,8 @@ This is the documentation of AMS, it's focused on the **0.10.x version.**
 - [Getting Started](general/getting_started.md)
 - [Adapters](general/adapters.md)
 - [Configuration Options](general/configuration_options.md)
+- [Logging](general/logging.md)
+- [Instrumentation](general/instrumentation.md)
 
 ## How to
 

docs/general/instrumentation.md

@@ -0,0 +1,18 @@
+# Instrumentation
+
+AMS uses the instrumentation API provided by Active Support this way we
+can choose to be notified when AMS events occur inside our application.
+
+## render.active_model_serializers
+
+|key          | value                |
+|-------------|----------------------|
+|:serializer  | The serializer class |
+|:adapter     | The adapter instance |
+
+```ruby
+{
+  serializer: PostSerializer,
+  adapter: #<ActiveModel::Serializer::Adapter::Attributes:0x007f96e81eb730>
+}
+```

docs/general/logging.md

@@ -0,0 +1,12 @@
+# Logging
+
+If we are using AMS on Rails app by default the `Rails.logger` will be used.
+
+On a non Rails enviroment by default the `ActiveSupport::TaggedLogging` will be
+used.
+
+If we need to customize the logger we can define this in an initializer:
+
+```ruby
+ActiveModel::Serializer.logger = Logger.new(STDOUT)
+```

lib/action_controller/serialization.rb

@@ -31,6 +31,7 @@ def get_serializer(resource, options = {})
         serializable_resource.serialization_scope_name = _serialization_scope
         begin
           serializable_resource.adapter
+          serializable_resource
         rescue ActiveModel::Serializer::CollectionSerializer::NoSerializerError
           resource
         end

lib/active_model/serializable_resource.rb

@@ -2,6 +2,15 @@
 module ActiveModel
   class SerializableResource
     ADAPTER_OPTION_KEYS = Set.new([:include, :fields, :adapter, :meta, :meta_key, :links])
+    extend ActiveModel::Callbacks
+
+    define_model_callbacks :render
+
+    around_render do |_, block, _|
+      notify_active_support do
+        block.call
+      end
+    end
 
     # Primary interface to composing a resource with a serializer and adapter.
     # @return the serializable_resource, ready for #as_json/#to_json/#serializable_hash.
@@ -11,7 +20,23 @@ def initialize(resource, options = {})
         options.partition { |k, _| ADAPTER_OPTION_KEYS.include? k }.map { |h| Hash[h] }
     end
 
-    delegate :serializable_hash, :as_json, :to_json, to: :adapter
+    def serializable_hash(*args)
+      run_callbacks :render do
+        adapter.serializable_hash(*args)
+      end
+    end
+
+    def as_json(*args)
+      run_callbacks :render do
+        adapter.as_json(*args)
+      end
+    end
+
+    def to_json(*args)
+      run_callbacks :render do
+        adapter.to_json(*args)
+      end
+    end
 
     def serialization_scope=(scope)
       serializer_opts[:scope] = scope
@@ -64,5 +89,13 @@ def serializer?
     protected
 
     attr_reader :resource, :adapter_opts, :serializer_opts
+
+    def notify_active_support
+      event_name = 'render.active_model_serializers'.freeze
+      payload = { serializer: serializer, adapter: adapter }
+      ActiveSupport::Notifications.instrument(event_name, payload) do
+        yield
+      end
+    end
   end
 end

lib/active_model/serializer.rb

@@ -6,13 +6,15 @@
 require 'active_model/serializer/configuration'
 require 'active_model/serializer/fieldset'
 require 'active_model/serializer/lint'
+require 'active_model/serializer/logging'
 
 # ActiveModel::Serializer is an abstract class that is
 # reified when subclassed to decorate a resource.
 module ActiveModel
   class Serializer
     include Configuration
     include Associations
+    include Logging
     require 'active_model/serializer/adapter'
 
     # Matches

lib/active_model/serializer/logging.rb

@@ -0,0 +1,26 @@
+module ActiveModel
+  class Serializer
+    module Logging
+      extend ActiveSupport::Concern
+
+      class LogSubscriber < ActiveSupport::LogSubscriber
+        def render(event)
+          logger.tagged('AMS') do
+            info do
+              serializer = event.payload[:serializer]
+              adapter = event.payload[:adapter]
+              duration = event.duration.round(2)
+              "Rendered #{serializer.name} with #{adapter.class} (#{duration}ms)"
+            end
+          end
+        end
+
+        def logger
+          ActiveModelSerializers.logger
+        end
+      end
+    end
+  end
+end
+
+ActiveModel::Serializer::Logging::LogSubscriber.attach_to :active_model_serializers

test/action_controller/serialization_test.rb

@@ -420,6 +420,16 @@ def use_adapter?
           controller.get_serializer(Profile.new)
         end)
       end
+
+      def test_render_event_is_emmited
+        ActiveSupport::Notifications.subscribe('render.active_model_serializers') do |name|
+          @name = name
+        end
+
+        get :render_using_implicit_serializer
+
+        assert_equal 'render.active_model_serializers', @name
+      end
     end
   end
 end

test/logging_test.rb

@@ -0,0 +1,77 @@
+require 'test_helper'
+
+module ActiveModel
+  class Serializer
+    class LoggingTest < Minitest::Test
+      class TestLogger < ActiveSupport::Logger
+        def initialize
+          @file = StringIO.new
+          super(@file)
+        end
+
+        def messages
+          @file.rewind
+          @file.read
+        end
+      end
+
+      def setup
+        @author = Author.new(name: 'Steve K.')
+        @post = Post.new(title: 'New Post', body: 'Body')
+        @comment = Comment.new(id: 1, body: 'ZOMG A COMMENT')
+        @post.comments = [@comment]
+        @comment.post = @post
+        @post.author = @author
+        @author.posts = [@post]
+        @post_serializer = PostSerializer.new(@post, custom_options: true)
+
+        @old_logger = ActiveModelSerializers.logger
+        @logger = ActiveSupport::TaggedLogging.new(TestLogger.new)
+        logger @logger
+      end
+
+      def teardown
+        logger @old_logger
+      end
+
+      def logger(logger)
+        ActiveModelSerializers.logger = logger
+      end
+
+      def test_uses_ams_as_tag
+        ActiveModel::SerializableResource.new(@post).serializable_hash
+        assert_match(/\[AMS\]/, @logger.messages)
+      end
+
+      def test_logs_when_call_serializable_hash
+        ActiveModel::SerializableResource.new(@post).serializable_hash
+        assert_match(/Rendered/, @logger.messages)
+      end
+
+      def test_logs_when_call_as_json
+        ActiveModel::SerializableResource.new(@post).as_json
+        assert_match(/Rendered/, @logger.messages)
+      end
+
+      def test_logs_when_call_to_json
+        ActiveModel::SerializableResource.new(@post).to_json
+        assert_match(/Rendered/, @logger.messages)
+      end
+
+      def test_logs_correct_serializer
+        ActiveModel::SerializableResource.new(@post).serializable_hash
+        assert_match(/PostSerializer/, @logger.messages)
+      end
+
+      def test_logs_correct_adapter
+        ActiveModel::SerializableResource.new(@post).serializable_hash
+        assert_match(/ActiveModel::Serializer::Adapter::Attributes/, @logger.messages)
+      end
+
+      def test_logs_the_duration
+        ActiveModel::SerializableResource.new(@post).serializable_hash
+        assert_match(/\(\d+\.\d+ms\)/, @logger.messages)
+      end
+    end
+  end
+end