Merge pull request #1322 from bf4/maurogeorge-patch-10

Instrumenting rendering of resources

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)

README.md

@@ -381,6 +381,10 @@ All serializable resources must pass the ActiveModel::Serializer::Lint::Tests.
 See the ActiveModelSerializers::Model for a base class that implements the full
 API for a plain-old Ruby object (PORO).
 
+## Hooks
+
+To run a hook when ActiveModelSerializers is loaded, use `ActiveSupport.on_load(:active_model_serializers) do end`
+
 ## Getting Help
 
 If you find a bug, please report an [Issue](https://github.com/rails-api/active_model_serializers/issues/new).

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,37 @@
+# Instrumentation
+
+ActiveModelSerializers uses the
+[ActiveSupport::Notification API](http://guides.rubyonrails.org/active_support_instrumentation.html#subscribing-to-an-event),
+which allows for subscribing to events, such as for logging.
+
+## Events
+
+Name:
+
+`render.active_model_serializers`
+
+Payload (example):
+
+```ruby
+{
+  serializer: PostSerializer,
+  adapter: ActiveModel::Serializer::Adapter::Attributes
+}
+```
+
+Subscribing:
+
+```ruby
+ActiveSupport::Notifications.subscribe 'render.active_model_serializers' do |name, started, finished, unique_id, data|
+  # whatever
+end
+ActiveSupport::Notifications.subscribe 'render.active_model_serializers' do |*args|
+  event = ActiveSupport::Notifications::Event.new(*args)
+  # event.payload
+  # whatever
+end
+
+## [LogSubscriber](http://api.rubyonrails.org/classes/ActiveSupport/LogSubscriber.html)
+
+ActiveModelSerializers includes an `ActiveModelSerializers::LogSubscriber` that attaches to
+`render.active_model_serializers`.

docs/general/logging.md

@@ -0,0 +1,12 @@
+# Logging
+
+If we are using ActiveModel::Serializers 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
+ActiveModelSerializers.logger = Logger.new(STDOUT)
+```

lib/action_controller/serialization.rb

@@ -31,7 +31,10 @@ module ActionController
         serializable_resource.serialization_scope ||= serialization_scope
         serializable_resource.serialization_scope_name = _serialization_scope
         begin
-          serializable_resource.adapter
+          # Necessary to ensure we have an adapter for the serializable resource
+          # after it has been figured.
+          # TODO: This logic should be less opaque and probably moved into the SerializableResource.
+          serializable_resource.tap(&:adapter)
         rescue ActiveModel::Serializer::CollectionSerializer::NoSerializerError
           resource
         end

lib/active_model/serializable_resource.rb

@@ -2,6 +2,12 @@ require 'set'
 module ActiveModel
   class SerializableResource
     ADAPTER_OPTION_KEYS = Set.new([:include, :fields, :adapter, :meta, :meta_key, :links])
+    include ActiveModelSerializers::Logging
+
+    delegate :serializable_hash, :as_json, :to_json, to: :adapter
+    notify :serializable_hash, :render
+    notify :as_json, :render
+    notify :to_json, :render
 
     # Primary interface to composing a resource with a serializer and adapter.
     # @return the serializable_resource, ready for #as_json/#to_json/#serializable_hash.
@@ -11,8 +17,6 @@ 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 serialization_scope=(scope)
       serializer_opts[:scope] = scope
     end

lib/active_model/serializer/railtie.rb

@@ -1,9 +1,10 @@
 require 'rails/railtie'
+
 module ActiveModel
   class Railtie < Rails::Railtie
     initializer 'active_model_serializers.logger' do
-      ActiveSupport.on_load(:action_controller) do
+      ActiveSupport.on_load(:active_model_serializers) do
-        ActiveModelSerializers.logger = ActionController::Base.logger
+        self.logger = ActionController::Base.logger
       end
     end
 

lib/active_model_serializers.rb

@@ -1,14 +1,14 @@
-require 'logger'
 require 'active_model'
 require 'active_support'
 require 'action_controller'
 require 'action_controller/railtie'
 module ActiveModelSerializers
-  mattr_accessor :logger
+  mattr_accessor(:logger) { ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT)) }
-  self.logger = Rails.logger || Logger.new(IO::NULL)
 
   extend ActiveSupport::Autoload
   autoload :Model
+  autoload :Callbacks
+  autoload :Logging
 
   module_function
 
@@ -50,6 +50,7 @@ require 'active_model/serializer/version'
 
 require 'action_controller/serialization'
 ActiveSupport.on_load(:action_controller) do
+  ActiveSupport.run_load_hooks(:active_model_serializers, ActiveModelSerializers)
   include ::ActionController::Serialization
   ActionDispatch::Reloader.to_prepare do
     ActiveModel::Serializer.serializers_cache.clear

lib/active_model_serializers/callbacks.rb

@@ -0,0 +1,55 @@
+# Adapted from
+# https://github.com/rails/rails/blob/7f18ea14c8/activejob/lib/active_job/callbacks.rb
+require 'active_support/callbacks'
+
+module ActiveModelSerializers
+  # = ActiveModelSerializers Callbacks
+  #
+  # ActiveModelSerializers provides hooks during the life cycle of serialization and
+  # allow you to trigger logic. Available callbacks are:
+  #
+  # * <tt>around_render</tt>
+  #
+  module Callbacks
+    extend ActiveSupport::Concern
+    include ActiveSupport::Callbacks
+
+    included do
+      define_callbacks :render
+    end
+
+    # These methods will be included into any ActiveModelSerializers object, adding
+    # callbacks for +render+.
+    module ClassMethods
+      # Defines a callback that will get called around the render method,
+      # whether it is as_json, to_json, or serializable_hash
+      #
+      #   class ActiveModel::SerializableResource
+      #     include ActiveModelSerializers::Callbacks
+      #
+      #     around_render do |args, block|
+      #       tag_logger do
+      #         notify_render do
+      #           block.call(args)
+      #         end
+      #       end
+      #     end
+      #
+      #     def as_json
+      #       run_callbacks :render do
+      #         adapter.as_json
+      #       end
+      #     end
+      #     # Note: So that we can re-use the instrumenter for as_json, to_json, and
+      #     # serializable_hash, we aren't using the usual format, which would be:
+      #     # def render(args)
+      #     #   adapter.as_json
+      #     # end
+      #   end
+      #
+      def around_render(*filters, &blk)
+        set_callback(:render, :around, *filters, &blk)
+      end
+    end
+  end
+end

lib/active_model_serializers/logging.rb

@@ -0,0 +1,118 @@
+##
+# ActiveModelSerializers::Logging
+#
+#   https://github.com/rails/rails/blob/280654ef88/activejob/lib/active_job/logging.rb
+#
+module ActiveModelSerializers
+  module Logging
+    extend ActiveSupport::Concern
+
+    included do
+      include ActiveModelSerializers::Callbacks
+      extend Macros
+      instrument_rendering
+    end
+
+    module ClassMethods
+      def instrument_rendering
+        around_render do |args, block|
+          tag_logger do
+            notify_render do
+              block.call(args)
+            end
+          end
+        end
+      end
+    end
+
+    # Macros that can be used to customize the logging of class or instance methods,
+    # by extending the class or its singleton.
+    #
+    # Adapted from:
+    #   https://github.com/rubygems/rubygems/blob/cb28f5e991/lib/rubygems/deprecate.rb
+    #
+    # Provides a single method +notify+ to be used to declare when
+    # something a method notifies, with the argument +callback_name+ of the notification callback.
+    #
+    #     class Adapter
+    #       def self.klass_method
+    #         # ...
+    #       end
+    #
+    #       def instance_method
+    #         # ...
+    #       end
+    #
+    #       include ActiveModelSerializers::Logging::Macros
+    #       notify :instance_method, :render
+    #
+    #       class << self
+    #         extend ActiveModelSerializers::Logging::Macros
+    #         notify :klass_method, :render
+    #       end
+    #     end
+    module Macros
+      ##
+      # Simple notify method that wraps up +name+
+      # in a dummy method. It notifies on with the +callback_name+ notifier on
+      # each call to the dummy method, telling what the current serializer and adapter
+      # are being rendered.
+      # Adapted from:
+      #   https://github.com/rubygems/rubygems/blob/cb28f5e991/lib/rubygems/deprecate.rb
+      def notify(name, callback_name)
+        class_eval do
+          old = "_notifying_#{callback_name}_#{name}"
+          alias_method old, name
+          define_method name do |*args, &block|
+            run_callbacks callback_name do
+              send old, *args, &block
+            end
+          end
+        end
+      end
+    end
+
+    def notify_render(*)
+      event_name = 'render.active_model_serializers'.freeze
+      ActiveSupport::Notifications.instrument(event_name, notify_render_payload) do
+        yield
+      end
+    end
+
+    def notify_render_payload
+      { serializer: serializer, adapter: adapter }
+    end
+
+    private
+
+    def tag_logger(*tags)
+      if ActiveModelSerializers.logger.respond_to?(:tagged)
+        tags.unshift 'active_model_serializsers'.freeze unless logger_tagged_by_active_model_serializers?
+        ActiveModelSerializers.logger.tagged(*tags) { yield }
+      else
+        yield
+      end
+    end
+
+    def logger_tagged_by_active_model_serializers?
+      ActiveModelSerializers.logger.formatter.current_tags.include?('active_model_serializsers'.freeze)
+    end
+
+    class LogSubscriber < ActiveSupport::LogSubscriber
+      def render(event)
+        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
+
+      def logger
+        ActiveModelSerializers.logger
+      end
+    end
+  end
+end
+
+ActiveModelSerializers::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/active_model_serializers/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(/\[active_model_serializsers\]/, @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

test/logger_test.rb

@@ -2,7 +2,7 @@ require 'test_helper'
 
 class ActiveModelSerializers::LoggerTest < Minitest::Test
   def test_logger_is_set_to_action_controller_logger_when_initializer_runs
-    assert_equal ActiveModelSerializers.logger, ActionController::Base.logger
+    assert_equal $action_controller_logger, ActionController::Base.logger # rubocop:disable Style/GlobalVars
   end
 
   def test_logger_can_be_set

test/test_helper.rb

@@ -54,6 +54,7 @@ else
 end
 
 require 'active_model_serializers'
+require 'active_model/serializer/railtie'
 
 require 'support/stream_capture'
 
@@ -66,3 +67,8 @@ require 'support/serialization_testing'
 require 'fixtures/active_record'
 
 require 'fixtures/poro'
+
+ActiveSupport.on_load(:active_model_serializers) do
+  $action_controller_logger = ActiveModelSerializers.logger # rubocop:disable Style/GlobalVars
+  ActiveModelSerializers.logger = Logger.new(IO::NULL)
+end