From 100146f831be4705a3e3c7f54572144386117ea5 Mon Sep 17 00:00:00 2001 From: Mauro George Date: Wed, 21 Oct 2015 20:12:47 -0200 Subject: [PATCH 01/12] Add Logging Generates logging when renders a serializer. --- lib/active_model/serializable_resource.rb | 27 +++++++- lib/active_model/serializer.rb | 2 + lib/active_model/serializer/logging.rb | 32 ++++++++++ test/logging_test.rb | 77 +++++++++++++++++++++++ test/test_helper.rb | 2 + 5 files changed, 139 insertions(+), 1 deletion(-) create mode 100644 lib/active_model/serializer/logging.rb create mode 100644 test/logging_test.rb diff --git a/lib/active_model/serializable_resource.rb b/lib/active_model/serializable_resource.rb index da1a772a8..62e3c7e5a 100644 --- a/lib/active_model/serializable_resource.rb +++ b/lib/active_model/serializable_resource.rb @@ -11,7 +11,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) + notify_active_support do + adapter.serializable_hash(*args) + end + end + + def as_json(*args) + notify_active_support do + adapter.as_json(*args) + end + end + + def to_json(*args) + notify_active_support do + adapter.to_json(*args) + end + end def serialization_scope=(scope) serializer_opts[:scope] = scope @@ -64,5 +80,14 @@ def serializer? protected attr_reader :resource, :adapter_opts, :serializer_opts + + def notify_active_support(&block) + return unless serializer? + event_name = 'render.active_model_serializers' + payload = { serializer: serializer, adapter: adapter } + ActiveSupport::Notifications.instrument(event_name, payload) do + block.call + 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..e6fec816a --- /dev/null +++ b/lib/active_model/serializer/logging.rb @@ -0,0 +1,32 @@ +module ActiveModel + class Serializer + module Logging + extend ActiveSupport::Concern + + included do + cattr_accessor(:logger) do + ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT)) + end + end + + class LogSubscriber < ActiveSupport::LogSubscriber + def render(event) + serializer = event.payload[:serializer] + adapter = event.payload[:adapter] + duration = event.duration.round(2) + logger.tagged('AMS') do + info do + "Rendered #{serializer.name} with #{adapter.class} (#{duration}ms)" + end + end + end + + def logger + ActiveModel::Serializer.logger + end + end + end + end +end + +ActiveModel::Serializer::Logging::LogSubscriber.attach_to :active_model_serializers diff --git a/test/logging_test.rb b/test/logging_test.rb new file mode 100644 index 000000000..d8c9ce54e --- /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 = ActiveModel::Serializer.logger + @logger = ActiveSupport::TaggedLogging.new(TestLogger.new) + logger @logger + end + + def teardown + logger @old_logger + end + + def logger(logger) + ActiveModel::Serializer.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 diff --git a/test/test_helper.rb b/test/test_helper.rb index 6495d2512..54110105a 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -62,3 +62,5 @@ def Minitest.after_run(&block) require 'fixtures/active_record' require 'fixtures/poro' + +ActiveModel::Serializer.logger = Logger.new(nil) From e5c79692a2d923e131559083f31ecff572595c1f Mon Sep 17 00:00:00 2001 From: Mauro George Date: Fri, 23 Oct 2015 07:46:18 -0200 Subject: [PATCH 02/12] Tunning performance on notify_active_support - Use yield over block.call - Freeze the event name string --- lib/active_model/serializable_resource.rb | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/active_model/serializable_resource.rb b/lib/active_model/serializable_resource.rb index 62e3c7e5a..5cfcd9ecb 100644 --- a/lib/active_model/serializable_resource.rb +++ b/lib/active_model/serializable_resource.rb @@ -81,12 +81,12 @@ def serializer? attr_reader :resource, :adapter_opts, :serializer_opts - def notify_active_support(&block) + def notify_active_support return unless serializer? - event_name = 'render.active_model_serializers' + event_name = 'render.active_model_serializers'.freeze payload = { serializer: serializer, adapter: adapter } ActiveSupport::Notifications.instrument(event_name, payload) do - block.call + yield end end end From 3ad21974753d0d1d7989cbc9631db84a3671bffe Mon Sep 17 00:00:00 2001 From: Mauro George Date: Fri, 23 Oct 2015 08:06:12 -0200 Subject: [PATCH 03/12] 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]: https://github.com/rails/rails/blob/2ad9afe4ff2c12d1a9e4a00d9009d040e636c9b0/activejob/lib/active_job/railtie.rb#L9-L11 [2]: https://github.com/rails/rails/blob/2ad9afe4ff2c12d1a9e4a00d9009d040e636c9b0/activerecord/lib/active_record/railtie.rb#L75-L77 [3]: https://github.com/rails/rails/blob/2ad9afe4ff2c12d1a9e4a00d9009d040e636c9b0/actionview/lib/action_view/railtie.rb#L19-L21 [4]: https://github.com/rails/rails/blob/2ad9afe4ff2c12d1a9e4a00d9009d040e636c9b0/activejob/lib/active_job/logging.rb#L10-L11 --- lib/active_model/serializer/railtie.rb | 4 +--- lib/active_model_serializers.rb | 3 --- test/logger_test.rb | 18 ------------------ 3 files changed, 1 insertion(+), 24 deletions(-) delete mode 100644 test/logger_test.rb diff --git a/lib/active_model/serializer/railtie.rb b/lib/active_model/serializer/railtie.rb index cade0354e..fe472d026 100644 --- a/lib/active_model/serializer/railtie.rb +++ b/lib/active_model/serializer/railtie.rb @@ -2,9 +2,7 @@ module ActiveModel class Railtie < Rails::Railtie initializer 'active_model_serializers.logger' do - ActiveSupport.on_load(:action_controller) do - ActiveModelSerializers.logger = ActionController::Base.logger - end + ActiveSupport.on_load(:active_model_serializers) { self.logger ||= Rails.logger } end initializer 'generators' do |app| diff --git a/lib/active_model_serializers.rb b/lib/active_model_serializers.rb index 922fd876a..1d2ac8d46 100644 --- a/lib/active_model_serializers.rb +++ b/lib/active_model_serializers.rb @@ -4,9 +4,6 @@ require 'action_controller' require 'action_controller/railtie' module ActiveModelSerializers - mattr_accessor :logger - self.logger = Rails.logger || Logger.new(IO::NULL) - extend ActiveSupport::Autoload autoload :Model diff --git a/test/logger_test.rb b/test/logger_test.rb deleted file mode 100644 index d324570ad..000000000 --- a/test/logger_test.rb +++ /dev/null @@ -1,18 +0,0 @@ -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 - end - - def test_logger_can_be_set - original_logger = ActiveModelSerializers.logger - logger = Logger.new(STDOUT) - - ActiveModelSerializers.logger = logger - - assert_equal ActiveModelSerializers.logger, logger - ensure - ActiveModelSerializers.logger = original_logger - end -end From ac473c777acd724c46a16c4a692c5a65bdbfe6ee Mon Sep 17 00:00:00 2001 From: Mauro George Date: Fri, 23 Oct 2015 08:20:23 -0200 Subject: [PATCH 04/12] 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. --- lib/active_model/serializer/logging.rb | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/active_model/serializer/logging.rb b/lib/active_model/serializer/logging.rb index e6fec816a..ca5219fd1 100644 --- a/lib/active_model/serializer/logging.rb +++ b/lib/active_model/serializer/logging.rb @@ -11,11 +11,11 @@ module Logging class LogSubscriber < ActiveSupport::LogSubscriber def render(event) - serializer = event.payload[:serializer] - adapter = event.payload[:adapter] - duration = event.duration.round(2) 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 From b0ef4d7b2dbf857088f487e5aa6dec47253d956c Mon Sep 17 00:00:00 2001 From: Mauro George Date: Sat, 24 Oct 2015 12:15:55 -0200 Subject: [PATCH 05/12] Remove not needed check on SerializableResource --- lib/active_model/serializable_resource.rb | 1 - 1 file changed, 1 deletion(-) diff --git a/lib/active_model/serializable_resource.rb b/lib/active_model/serializable_resource.rb index 5cfcd9ecb..d3c6fcd82 100644 --- a/lib/active_model/serializable_resource.rb +++ b/lib/active_model/serializable_resource.rb @@ -82,7 +82,6 @@ def serializer? attr_reader :resource, :adapter_opts, :serializer_opts def notify_active_support - return unless serializer? event_name = 'render.active_model_serializers'.freeze payload = { serializer: serializer, adapter: adapter } ActiveSupport::Notifications.instrument(event_name, payload) do From 981c2293f4ca46daf1ebcd51468497611a389687 Mon Sep 17 00:00:00 2001 From: Mauro George Date: Sat, 24 Oct 2015 14:06:57 -0200 Subject: [PATCH 06/12] 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. --- lib/action_controller/serialization.rb | 1 + test/action_controller/serialization_test.rb | 10 ++++++++++ 2 files changed, 11 insertions(+) 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/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 From 2a80cdbfd4b99057613abe6cf46b5964f42f3b48 Mon Sep 17 00:00:00 2001 From: Mauro George Date: Sat, 24 Oct 2015 14:25:50 -0200 Subject: [PATCH 07/12] Add docs about logging --- docs/README.md | 1 + docs/general/logging.md | 12 ++++++++++++ 2 files changed, 13 insertions(+) create mode 100644 docs/general/logging.md diff --git a/docs/README.md b/docs/README.md index f0b4803f2..4e1153ea6 100644 --- a/docs/README.md +++ b/docs/README.md @@ -9,6 +9,7 @@ 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) ## How to diff --git a/docs/general/logging.md b/docs/general/logging.md new file mode 100644 index 000000000..f66372720 --- /dev/null +++ b/docs/general/logging.md @@ -0,0 +1,12 @@ +# Logging + +If we are using AMS on Rails app 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) +``` From 67c7db1fb37da5984b826442ea78c4dda3fbb97f Mon Sep 17 00:00:00 2001 From: Mauro George Date: Sat, 24 Oct 2015 14:29:18 -0200 Subject: [PATCH 08/12] Add a CHANGELOG entry --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) 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) From e28e2b57dc55623a00ba92e6a19c8489e7914b39 Mon Sep 17 00:00:00 2001 From: Mauro George Date: Thu, 29 Oct 2015 18:42:31 -0200 Subject: [PATCH 09/12] Keep the ActiveModelSerializers.logger --- lib/active_model/serializer/logging.rb | 8 +------- lib/active_model/serializer/railtie.rb | 4 +++- lib/active_model_serializers.rb | 3 +++ test/logger_test.rb | 18 ++++++++++++++++++ test/logging_test.rb | 4 ++-- test/test_helper.rb | 2 -- 6 files changed, 27 insertions(+), 12 deletions(-) create mode 100644 test/logger_test.rb diff --git a/lib/active_model/serializer/logging.rb b/lib/active_model/serializer/logging.rb index ca5219fd1..e9b9c5434 100644 --- a/lib/active_model/serializer/logging.rb +++ b/lib/active_model/serializer/logging.rb @@ -3,12 +3,6 @@ class Serializer module Logging extend ActiveSupport::Concern - included do - cattr_accessor(:logger) do - ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT)) - end - end - class LogSubscriber < ActiveSupport::LogSubscriber def render(event) logger.tagged('AMS') do @@ -22,7 +16,7 @@ def render(event) end def logger - ActiveModel::Serializer.logger + ActiveModelSerializers.logger end end end diff --git a/lib/active_model/serializer/railtie.rb b/lib/active_model/serializer/railtie.rb index fe472d026..cade0354e 100644 --- a/lib/active_model/serializer/railtie.rb +++ b/lib/active_model/serializer/railtie.rb @@ -2,7 +2,9 @@ module ActiveModel class Railtie < Rails::Railtie initializer 'active_model_serializers.logger' do - ActiveSupport.on_load(:active_model_serializers) { self.logger ||= Rails.logger } + ActiveSupport.on_load(:action_controller) do + ActiveModelSerializers.logger = ActionController::Base.logger + end end initializer 'generators' do |app| diff --git a/lib/active_model_serializers.rb b/lib/active_model_serializers.rb index 1d2ac8d46..922fd876a 100644 --- a/lib/active_model_serializers.rb +++ b/lib/active_model_serializers.rb @@ -4,6 +4,9 @@ require 'action_controller' require 'action_controller/railtie' module ActiveModelSerializers + mattr_accessor :logger + self.logger = Rails.logger || Logger.new(IO::NULL) + extend ActiveSupport::Autoload autoload :Model diff --git a/test/logger_test.rb b/test/logger_test.rb new file mode 100644 index 000000000..d324570ad --- /dev/null +++ b/test/logger_test.rb @@ -0,0 +1,18 @@ +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 + end + + def test_logger_can_be_set + original_logger = ActiveModelSerializers.logger + logger = Logger.new(STDOUT) + + ActiveModelSerializers.logger = logger + + assert_equal ActiveModelSerializers.logger, logger + ensure + ActiveModelSerializers.logger = original_logger + end +end diff --git a/test/logging_test.rb b/test/logging_test.rb index d8c9ce54e..32c17f49a 100644 --- a/test/logging_test.rb +++ b/test/logging_test.rb @@ -25,7 +25,7 @@ def setup @author.posts = [@post] @post_serializer = PostSerializer.new(@post, custom_options: true) - @old_logger = ActiveModel::Serializer.logger + @old_logger = ActiveModelSerializers.logger @logger = ActiveSupport::TaggedLogging.new(TestLogger.new) logger @logger end @@ -35,7 +35,7 @@ def teardown end def logger(logger) - ActiveModel::Serializer.logger = logger + ActiveModelSerializers.logger = logger end def test_uses_ams_as_tag diff --git a/test/test_helper.rb b/test/test_helper.rb index 54110105a..6495d2512 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -62,5 +62,3 @@ def Minitest.after_run(&block) require 'fixtures/active_record' require 'fixtures/poro' - -ActiveModel::Serializer.logger = Logger.new(nil) From ca4139ea48e04e79d0ff8b5126a03fa5977f5c31 Mon Sep 17 00:00:00 2001 From: Mauro George Date: Thu, 29 Oct 2015 18:50:26 -0200 Subject: [PATCH 10/12] Better wording on Logging docs [ci skip] --- docs/general/logging.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/general/logging.md b/docs/general/logging.md index f66372720..a4feedb8e 100644 --- a/docs/general/logging.md +++ b/docs/general/logging.md @@ -1,6 +1,6 @@ # Logging -If we are using AMS on Rails app the `Rails.logger` will be used. +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. From 2c4a028bed946d10b2972c975ef9c2501ef43c25 Mon Sep 17 00:00:00 2001 From: Mauro George Date: Thu, 29 Oct 2015 19:05:59 -0200 Subject: [PATCH 11/12] Add doc about instrumentation [ci skip] --- docs/README.md | 1 + docs/general/instrumentation.md | 18 ++++++++++++++++++ 2 files changed, 19 insertions(+) create mode 100644 docs/general/instrumentation.md diff --git a/docs/README.md b/docs/README.md index 4e1153ea6..70b89a19c 100644 --- a/docs/README.md +++ b/docs/README.md @@ -10,6 +10,7 @@ This is the documentation of AMS, it's focused on the **0.10.x version.** - [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: # +} +``` From 49c8f69080f9734a0bda5268aa7ede56f753b465 Mon Sep 17 00:00:00 2001 From: Mauro George Date: Thu, 5 Nov 2015 19:15:34 -0200 Subject: [PATCH 12/12] Use ActiveModel::Callbacks on the SerializableResource --- lib/active_model/serializable_resource.rb | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/lib/active_model/serializable_resource.rb b/lib/active_model/serializable_resource.rb index d3c6fcd82..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. @@ -12,19 +21,19 @@ def initialize(resource, options = {}) end def serializable_hash(*args) - notify_active_support do + run_callbacks :render do adapter.serializable_hash(*args) end end def as_json(*args) - notify_active_support do + run_callbacks :render do adapter.as_json(*args) end end def to_json(*args) - notify_active_support do + run_callbacks :render do adapter.to_json(*args) end end