diff --git a/CHANGELOG.md b/CHANGELOG.md index 0f7b24bf4..f2607e07b 100644 --- a/CHANGELOG.md +++ b/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) diff --git a/docs/README.md b/docs/README.md index f0b4803f2..70b89a19c 100644 --- a/docs/README.md +++ b/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 diff --git a/docs/general/instrumentation.md b/docs/general/instrumentation.md new file mode 100644 index 000000000..d1296f68b --- /dev/null +++ b/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: # +} +``` diff --git a/docs/general/logging.md b/docs/general/logging.md new file mode 100644 index 000000000..a4feedb8e --- /dev/null +++ b/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) +``` diff --git a/lib/action_controller/serialization.rb b/lib/action_controller/serialization.rb index 1158e9751..7df6bd48d 100644 --- a/lib/action_controller/serialization.rb +++ b/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 diff --git a/lib/active_model/serializable_resource.rb b/lib/active_model/serializable_resource.rb index da1a772a8..1ec49e79b 100644 --- a/lib/active_model/serializable_resource.rb +++ b/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 diff --git a/lib/active_model/serializer.rb b/lib/active_model/serializer.rb index f61284105..8ea46b99d 100644 --- a/lib/active_model/serializer.rb +++ b/lib/active_model/serializer.rb @@ -6,6 +6,7 @@ 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 diff --git a/lib/active_model/serializer/logging.rb b/lib/active_model/serializer/logging.rb new file mode 100644 index 000000000..e9b9c5434 --- /dev/null +++ b/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 diff --git a/test/action_controller/serialization_test.rb b/test/action_controller/serialization_test.rb index e9288d564..a3b761981 100644 --- a/test/action_controller/serialization_test.rb +++ b/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 diff --git a/test/logging_test.rb b/test/logging_test.rb new file mode 100644 index 000000000..32c17f49a --- /dev/null +++ b/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