ActiveSupport::Notifications render.active_model_serializers

Squashed commits:

Add Logging

Generates logging when renders a serializer.

Tunning performance on notify_active_support

- Use yield over block.call
- Freeze the event name string

Organize the logger architeture

* Keep only the `ActiveModel::Serializer.logger` to follow the same public API we
  have for example to config, like `ActiveModel::Serializer.config.adapter` and
  remove the `ActiveModelSerializers.logger` API.
* Define the logger on the load of the AMS, following the Rails convention on
  Railties [1], [2] and [3].

This way on non Rails apps we have a default logger and on Rails apps we will
use the `Rails.logger` the same way that Active Job do [4].

[1]: 2ad9afe4ff/activejob/lib/active_job/railtie.rb (L9-L11)
[2]: 2ad9afe4ff/activerecord/lib/active_record/railtie.rb (L75-L77)
[3]: 2ad9afe4ff/actionview/lib/action_view/railtie.rb (L19-L21)
[4]: 2ad9afe4ff/activejob/lib/active_job/logging.rb (L10-L11)

Performance tunning on LogSubscriber#render

Move the definition of locals to inside the `info` block this way the code is
executed only when the logger is called.

Remove not needed check on SerializableResource

Use SerializableResource on ActionController integration

On the ActionController was using a adapter, and since the instrumentation is
made on the SerializableResource we need to use the SerializableResource over
the adapter directly. Otherwise the logger is not called on a Rails app.

Use SerializableResource on the ActionController, since this is the main
interface to create and call a serializer.

Using always the SerializableResource we can keep the adapter code more easy to
mantain since no Adapter will need to call the instrumentation, only the
SerializableResource care about this.

Add docs about logging

Add a CHANGELOG entry

Keep the ActiveModelSerializers.logger

Better wording on Logging docs

[ci skip]

Add doc about instrumentation

[ci skip]

Use ActiveModel::Callbacks on the SerializableResource

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

@@ -32,6 +32,7 @@ module ActionController
         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 @@ require 'set'
 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 @@ module ActiveModel
         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 @@ module ActiveModel
     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,6 +6,7 @@ require 'active_model/serializer/associations'
 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.
@@ -13,6 +14,7 @@ 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 @@ module ActionController
           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