From 51424963da3ce009a2dc22fe9e976f87f3fbabc2 Mon Sep 17 00:00:00 2001 From: Mauro George Date: Wed, 21 Oct 2015 20:12:47 -0200 Subject: [PATCH 1/8] 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]: 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 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 | 1 + docs/README.md | 2 + docs/general/instrumentation.md | 18 +++++ docs/general/logging.md | 12 +++ lib/action_controller/serialization.rb | 1 + lib/active_model/serializable_resource.rb | 35 ++++++++- lib/active_model/serializer.rb | 2 + lib/active_model/serializer/logging.rb | 26 +++++++ test/action_controller/serialization_test.rb | 10 +++ test/logging_test.rb | 77 ++++++++++++++++++++ 10 files changed, 183 insertions(+), 1 deletion(-) create mode 100644 docs/general/instrumentation.md create mode 100644 docs/general/logging.md create mode 100644 lib/active_model/serializer/logging.rb create mode 100644 test/logging_test.rb 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 a1e9d908e..a05fdfb3d 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 c11b6c8ea..49455169b 100644 --- a/lib/action_controller/serialization.rb +++ b/lib/action_controller/serialization.rb @@ -32,6 +32,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 b513216fa..15c29f2bf 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 From 21bb306d38709cd75070ee9a8cbcfd3965ac2bbb Mon Sep 17 00:00:00 2001 From: Benjamin Fleischer Date: Sun, 8 Nov 2015 15:46:08 -0600 Subject: [PATCH 2/8] Keep Logging in the ActiveModelSerializers namespace --- docs/general/instrumentation.md | 17 +++---- docs/general/logging.md | 4 +- lib/active_model/serializable_resource.rb | 18 +------- lib/active_model/serializer.rb | 2 - lib/active_model/serializer/logging.rb | 26 ----------- lib/active_model/serializer/railtie.rb | 6 ++- lib/active_model_serializers.rb | 8 ++-- lib/active_model_serializers/logging.rb | 45 +++++++++++++++++++ .../logging_test.rb | 0 9 files changed, 66 insertions(+), 60 deletions(-) delete mode 100644 lib/active_model/serializer/logging.rb create mode 100644 lib/active_model_serializers/logging.rb rename test/{ => active_model_serializers}/logging_test.rb (100%) diff --git a/docs/general/instrumentation.md b/docs/general/instrumentation.md index d1296f68b..3adaefbd9 100644 --- a/docs/general/instrumentation.md +++ b/docs/general/instrumentation.md @@ -1,18 +1,19 @@ # 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. +ActiveModelSerializers uses the ActiveSupport::Notification API, which +allows for subscribing to events, such as for logging. -## render.active_model_serializers +## Events -|key | value | -|-------------|----------------------| -|:serializer | The serializer class | -|:adapter | The adapter instance | +Name: + +`render.active_model_serializers` + +Payload (example): ```ruby { serializer: PostSerializer, - adapter: # + adapter: ActiveModel::Serializer::Adapter::Attributes } ``` diff --git a/docs/general/logging.md b/docs/general/logging.md index a4feedb8e..010ae01a1 100644 --- a/docs/general/logging.md +++ b/docs/general/logging.md @@ -1,6 +1,6 @@ # Logging -If we are using AMS on Rails app by default the `Rails.logger` will be used. +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. @@ -8,5 +8,5 @@ used. If we need to customize the logger we can define this in an initializer: ```ruby -ActiveModel::Serializer.logger = Logger.new(STDOUT) +ActiveModelSerializers.logger = Logger.new(STDOUT) ``` diff --git a/lib/active_model/serializable_resource.rb b/lib/active_model/serializable_resource.rb index 1ec49e79b..d016adaed 100644 --- a/lib/active_model/serializable_resource.rb +++ b/lib/active_model/serializable_resource.rb @@ -2,15 +2,7 @@ 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 + include ActiveModelSerializers::Logging # Primary interface to composing a resource with a serializer and adapter. # @return the serializable_resource, ready for #as_json/#to_json/#serializable_hash. @@ -89,13 +81,5 @@ 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 15c29f2bf..b513216fa 100644 --- a/lib/active_model/serializer.rb +++ b/lib/active_model/serializer.rb @@ -6,7 +6,6 @@ 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. @@ -14,7 +13,6 @@ 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 deleted file mode 100644 index e9b9c5434..000000000 --- a/lib/active_model/serializer/logging.rb +++ /dev/null @@ -1,26 +0,0 @@ -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/lib/active_model/serializer/railtie.rb b/lib/active_model/serializer/railtie.rb index cade0354e..f6c2d27c1 100644 --- a/lib/active_model/serializer/railtie.rb +++ b/lib/active_model/serializer/railtie.rb @@ -1,9 +1,11 @@ +require 'active_model_serializers' require 'rails/railtie' + module ActiveModel class Railtie < Rails::Railtie initializer 'active_model_serializers.logger' do - ActiveSupport.on_load(:action_controller) do - ActiveModelSerializers.logger = ActionController::Base.logger + ActiveSupport.on_load(:active_model_serializers) do + self.logger = ActionController::Base.logger end end diff --git a/lib/active_model_serializers.rb b/lib/active_model_serializers.rb index 922fd876a..d2eb0fabf 100644 --- a/lib/active_model_serializers.rb +++ b/lib/active_model_serializers.rb @@ -1,14 +1,15 @@ -require 'logger' require 'active_model' require 'active_support' +require 'active_support/tagged_logging' +require 'active_support/logger' require 'action_controller' require 'action_controller/railtie' module ActiveModelSerializers - mattr_accessor :logger - self.logger = Rails.logger || Logger.new(IO::NULL) + mattr_accessor(:logger) { ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT)) } extend ActiveSupport::Autoload autoload :Model + autoload :Logging module_function @@ -50,6 +51,7 @@ def silence_warnings 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 diff --git a/lib/active_model_serializers/logging.rb b/lib/active_model_serializers/logging.rb new file mode 100644 index 000000000..e80fb5d53 --- /dev/null +++ b/lib/active_model_serializers/logging.rb @@ -0,0 +1,45 @@ +## +# Adapted from: +# https://github.com/rails/rails/blob/280654ef88/activejob/lib/active_job/logging.rb +module ActiveModelSerializers::Logging + extend ActiveSupport::Concern + + included do + extend ActiveModel::Callbacks + define_model_callbacks :render + around_render do |_, block, _| + notify_active_support do + block.call + end + end + end + + 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 + + private + + 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 + +ActiveModelSerializers::Logging::LogSubscriber.attach_to :active_model_serializers diff --git a/test/logging_test.rb b/test/active_model_serializers/logging_test.rb similarity index 100% rename from test/logging_test.rb rename to test/active_model_serializers/logging_test.rb From 360ecc88fecab6b0cd51288cb4d9e0c7dcfe36f3 Mon Sep 17 00:00:00 2001 From: Benjamin Fleischer Date: Sun, 8 Nov 2015 15:49:50 -0600 Subject: [PATCH 3/8] Clean up notification code with some meta-prog --- lib/action_controller/serialization.rb | 3 +- lib/active_model/serializable_resource.rb | 23 +++---------- lib/active_model/serializer/railtie.rb | 1 - lib/active_model_serializers/logging.rb | 39 +++++++++++++++++++---- test/test_helper.rb | 1 + 5 files changed, 39 insertions(+), 28 deletions(-) diff --git a/lib/action_controller/serialization.rb b/lib/action_controller/serialization.rb index 49455169b..901653af6 100644 --- a/lib/action_controller/serialization.rb +++ b/lib/action_controller/serialization.rb @@ -31,8 +31,7 @@ def get_serializer(resource, options = {}) serializable_resource.serialization_scope ||= serialization_scope serializable_resource.serialization_scope_name = _serialization_scope begin - serializable_resource.adapter - serializable_resource + serializable_resource.tap(&:adapter) rescue ActiveModel::Serializer::CollectionSerializer::NoSerializerError resource end diff --git a/lib/active_model/serializable_resource.rb b/lib/active_model/serializable_resource.rb index d016adaed..c91eea170 100644 --- a/lib/active_model/serializable_resource.rb +++ b/lib/active_model/serializable_resource.rb @@ -4,6 +4,11 @@ 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. def initialize(resource, options = {}) @@ -12,24 +17,6 @@ def initialize(resource, options = {}) options.partition { |k, _| ADAPTER_OPTION_KEYS.include? k }.map { |h| Hash[h] } end - 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 end diff --git a/lib/active_model/serializer/railtie.rb b/lib/active_model/serializer/railtie.rb index f6c2d27c1..533a191c3 100644 --- a/lib/active_model/serializer/railtie.rb +++ b/lib/active_model/serializer/railtie.rb @@ -1,4 +1,3 @@ -require 'active_model_serializers' require 'rails/railtie' module ActiveModel diff --git a/lib/active_model_serializers/logging.rb b/lib/active_model_serializers/logging.rb index e80fb5d53..6a1ede89e 100644 --- a/lib/active_model_serializers/logging.rb +++ b/lib/active_model_serializers/logging.rb @@ -2,14 +2,39 @@ # Adapted from: # https://github.com/rails/rails/blob/280654ef88/activejob/lib/active_job/logging.rb module ActiveModelSerializers::Logging - extend ActiveSupport::Concern + def self.included(base) + base.send(:include, ActiveSupport::Callbacks) + base.extend ClassMethods + base.class_eval do + define_callbacks :render + around_render do |_, block| + notify_active_support do + block.call + end + end + end + end - included do - extend ActiveModel::Callbacks - define_model_callbacks :render - around_render do |_, block, _| - notify_active_support do - block.call + module ClassMethods + def around_render(*filters, &blk) + set_callback(:render, :around, *filters, &blk) + end + ## + # Simple notify method that wraps up +name+ + # in a dummy method. It notifies 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 diff --git a/test/test_helper.rb b/test/test_helper.rb index 6495d2512..dc466864f 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -50,6 +50,7 @@ def Minitest.after_run(&block) end require 'active_model_serializers' +require 'active_model/serializer/railtie' require 'support/stream_capture' From 84c3b11491abf4995c7279b44156797227f1f989 Mon Sep 17 00:00:00 2001 From: Benjamin Fleischer Date: Sun, 8 Nov 2015 19:43:10 -0600 Subject: [PATCH 4/8] Use null logger in test; keep track of original logger --- test/logger_test.rb | 2 +- test/test_helper.rb | 5 +++++ 2 files changed, 6 insertions(+), 1 deletion(-) diff --git a/test/logger_test.rb b/test/logger_test.rb index d324570ad..9e4853ba0 100644 --- a/test/logger_test.rb +++ b/test/logger_test.rb @@ -2,7 +2,7 @@ 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 diff --git a/test/test_helper.rb b/test/test_helper.rb index dc466864f..f36bd42fd 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -63,3 +63,8 @@ def Minitest.after_run(&block) 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 From e8efc4eff4d832839da3b02c38c97e38ff17a4d0 Mon Sep 17 00:00:00 2001 From: Benjamin Fleischer Date: Sun, 8 Nov 2015 20:41:48 -0600 Subject: [PATCH 5/8] Refactor callbacks in ams::logging --- lib/active_model_serializers/logging.rb | 86 ++++++++++++++++++------- 1 file changed, 64 insertions(+), 22 deletions(-) diff --git a/lib/active_model_serializers/logging.rb b/lib/active_model_serializers/logging.rb index 6a1ede89e..2658da84f 100644 --- a/lib/active_model_serializers/logging.rb +++ b/lib/active_model_serializers/logging.rb @@ -1,31 +1,59 @@ ## # Adapted from: +# https://github.com/rubygems/rubygems/blob/cb28f5e991/lib/rubygems/deprecate.rb # https://github.com/rails/rails/blob/280654ef88/activejob/lib/active_job/logging.rb +# +# Provides a single method +notify+ to be used to declare when +# something a method notifies. +# +# class Adapter +# def self.klass_method +# # ... +# end +# +# def instance_method +# # ... +# end +# +# extend ActiveModelSerializers::Logging +# notify :instance_method, :render +# +# class << self +# extend ActiveModelSerializers::Logging +# notify :klass_method, :render +# end +# end module ActiveModelSerializers::Logging - def self.included(base) - base.send(:include, ActiveSupport::Callbacks) - base.extend ClassMethods - base.class_eval do + extend ActiveSupport::Concern + + included do + include ActiveSupport::Callbacks + instrument_around_render + end + + module ClassMethods + def instrument_around_render define_callbacks :render - around_render do |_, block| - notify_active_support do - block.call + around_render do |args, block| + tag_logger do + notify_render do + block.call(args) + end end end end - end - module ClassMethods def around_render(*filters, &blk) set_callback(:render, :around, *filters, &blk) end + ## # Simple notify method that wraps up +name+ - # in a dummy method. It notifies on each call to the dummy method - # telling what the current serializer and adapter are being rendered. + # 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}" @@ -39,25 +67,39 @@ def notify(name, callback_name) end end - def notify_active_support + def notify_render(*) event_name = 'render.active_model_serializers'.freeze - payload = { serializer: serializer, adapter: adapter } - ActiveSupport::Notifications.instrument(event_name, payload) do + 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 'AMS'.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?('AMS'.freeze) + end + 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 + 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 b36cc42f0347ab15a4c1d99ddbb2e51d9ffbbdbe Mon Sep 17 00:00:00 2001 From: Benjamin Fleischer Date: Sun, 8 Nov 2015 21:01:02 -0600 Subject: [PATCH 6/8] Separate out callbacks per ActiveJob pattern --- lib/active_model_serializers.rb | 1 + lib/active_model_serializers/callbacks.rb | 55 +++++++++++++++++++++ lib/active_model_serializers/logging.rb | 60 +++++++++++------------ 3 files changed, 86 insertions(+), 30 deletions(-) create mode 100644 lib/active_model_serializers/callbacks.rb diff --git a/lib/active_model_serializers.rb b/lib/active_model_serializers.rb index d2eb0fabf..ce09b08ad 100644 --- a/lib/active_model_serializers.rb +++ b/lib/active_model_serializers.rb @@ -9,6 +9,7 @@ module ActiveModelSerializers extend ActiveSupport::Autoload autoload :Model + autoload :Callbacks autoload :Logging module_function diff --git a/lib/active_model_serializers/callbacks.rb b/lib/active_model_serializers/callbacks.rb new file mode 100644 index 000000000..7f1cd689f --- /dev/null +++ b/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: + # + # * around_render + # + 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 diff --git a/lib/active_model_serializers/logging.rb b/lib/active_model_serializers/logging.rb index 2658da84f..5b30a1a18 100644 --- a/lib/active_model_serializers/logging.rb +++ b/lib/active_model_serializers/logging.rb @@ -1,39 +1,19 @@ ## -# Adapted from: -# https://github.com/rubygems/rubygems/blob/cb28f5e991/lib/rubygems/deprecate.rb -# https://github.com/rails/rails/blob/280654ef88/activejob/lib/active_job/logging.rb -# -# Provides a single method +notify+ to be used to declare when -# something a method notifies. -# -# class Adapter -# def self.klass_method -# # ... -# end -# -# def instance_method -# # ... -# end +# ActiveModelSerializers::Logging # -# extend ActiveModelSerializers::Logging -# notify :instance_method, :render +# https://github.com/rails/rails/blob/280654ef88/activejob/lib/active_job/logging.rb # -# class << self -# extend ActiveModelSerializers::Logging -# notify :klass_method, :render -# end -# end module ActiveModelSerializers::Logging extend ActiveSupport::Concern included do - include ActiveSupport::Callbacks - instrument_around_render + include ActiveModelSerializers::Callbacks + extend NotificationMacro + instrument_rendering end module ClassMethods - def instrument_around_render - define_callbacks :render + def instrument_rendering around_render do |args, block| tag_logger do notify_render do @@ -42,11 +22,31 @@ def instrument_around_render end end end + end - def around_render(*filters, &blk) - set_callback(:render, :around, *filters, &blk) - end - + # 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 + # notify :instance_method, :render + # + # class << self + # extend ActiveModelSerializers::Logging::NotificationMacro + # notify :klass_method, :render + # end + # end + module NotificationMacro ## # Simple notify method that wraps up +name+ # in a dummy method. It notifies on with the +callback_name+ notifier on From d1c44c719d08df24c2d8d26bda7bfd4201804972 Mon Sep 17 00:00:00 2001 From: Benjamin Fleischer Date: Tue, 10 Nov 2015 03:21:40 -0600 Subject: [PATCH 7/8] Update for review per maurogeorge feedback --- README.md | 4 + docs/general/instrumentation.md | 22 +++- lib/action_controller/serialization.rb | 3 + lib/active_model_serializers.rb | 2 - lib/active_model_serializers/logging.rb | 164 ++++++++++++------------ 5 files changed, 112 insertions(+), 83 deletions(-) diff --git a/README.md b/README.md index e2bab278e..684b39c1c 100644 --- a/README.md +++ b/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). diff --git a/docs/general/instrumentation.md b/docs/general/instrumentation.md index 3adaefbd9..160a9e765 100644 --- a/docs/general/instrumentation.md +++ b/docs/general/instrumentation.md @@ -1,7 +1,8 @@ # Instrumentation -ActiveModelSerializers uses the ActiveSupport::Notification API, which -allows for subscribing to events, such as for logging. +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 @@ -17,3 +18,20 @@ Payload (example): 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`. diff --git a/lib/action_controller/serialization.rb b/lib/action_controller/serialization.rb index 901653af6..5fefaedfc 100644 --- a/lib/action_controller/serialization.rb +++ b/lib/action_controller/serialization.rb @@ -31,6 +31,9 @@ def get_serializer(resource, options = {}) serializable_resource.serialization_scope ||= serialization_scope serializable_resource.serialization_scope_name = _serialization_scope begin + # 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 diff --git a/lib/active_model_serializers.rb b/lib/active_model_serializers.rb index ce09b08ad..c7a4d1d43 100644 --- a/lib/active_model_serializers.rb +++ b/lib/active_model_serializers.rb @@ -1,7 +1,5 @@ require 'active_model' require 'active_support' -require 'active_support/tagged_logging' -require 'active_support/logger' require 'action_controller' require 'action_controller/railtie' module ActiveModelSerializers diff --git a/lib/active_model_serializers/logging.rb b/lib/active_model_serializers/logging.rb index 5b30a1a18..cc1cdc34e 100644 --- a/lib/active_model_serializers/logging.rb +++ b/lib/active_model_serializers/logging.rb @@ -3,108 +3,114 @@ # # https://github.com/rails/rails/blob/280654ef88/activejob/lib/active_job/logging.rb # -module ActiveModelSerializers::Logging - extend ActiveSupport::Concern +module ActiveModelSerializers + module Logging + extend ActiveSupport::Concern - included do - include ActiveModelSerializers::Callbacks - extend NotificationMacro - instrument_rendering - end + 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) + module ClassMethods + def instrument_rendering + around_render do |args, block| + tag_logger do + notify_render do + block.call(args) + end end end end end - end - # 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 - # notify :instance_method, :render - # - # class << self - # extend ActiveModelSerializers::Logging::NotificationMacro - # notify :klass_method, :render - # end - # end - module NotificationMacro - ## - # 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. + # 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 - 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 + # + # 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 - end - def notify_render(*) - event_name = 'render.active_model_serializers'.freeze - ActiveSupport::Notifications.instrument(event_name, notify_render_payload) do - yield + def notify_render(*) + event_name = 'render.active_model_serializers'.freeze + ActiveSupport::Notifications.instrument(event_name, notify_render_payload) do + yield + end end - end - def notify_render_payload - { serializer: serializer, adapter: adapter } - end + def notify_render_payload + { serializer: serializer, adapter: adapter } + end - private + private - def tag_logger(*tags) - if ActiveModelSerializers.logger.respond_to?(:tagged) - tags.unshift 'AMS'.freeze unless logger_tagged_by_active_model_serializers? - ActiveModelSerializers.logger.tagged(*tags) { yield } - else - yield + def tag_logger(*tags) + if ActiveModelSerializers.logger.respond_to?(:tagged) + tags.unshift 'AMS'.freeze unless logger_tagged_by_active_model_serializers? + ActiveModelSerializers.logger.tagged(*tags) { yield } + else + yield + end end - end - def logger_tagged_by_active_model_serializers? - ActiveModelSerializers.logger.formatter.current_tags.include?('AMS'.freeze) - end + def logger_tagged_by_active_model_serializers? + ActiveModelSerializers.logger.formatter.current_tags.include?('AMS'.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)" + 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 - end - def logger - ActiveModelSerializers.logger + def logger + ActiveModelSerializers.logger + end end end end From 733f5bca7e076d99c131d92717c3d1b8effe1202 Mon Sep 17 00:00:00 2001 From: Benjamin Fleischer Date: Thu, 19 Nov 2015 12:44:30 -0600 Subject: [PATCH 8/8] Rename event from AMS to active_model_serializers per NullVoxPopuli comment --- lib/active_model_serializers/logging.rb | 4 ++-- test/active_model_serializers/logging_test.rb | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/active_model_serializers/logging.rb b/lib/active_model_serializers/logging.rb index cc1cdc34e..511ef764f 100644 --- a/lib/active_model_serializers/logging.rb +++ b/lib/active_model_serializers/logging.rb @@ -87,7 +87,7 @@ def notify_render_payload def tag_logger(*tags) if ActiveModelSerializers.logger.respond_to?(:tagged) - tags.unshift 'AMS'.freeze unless logger_tagged_by_active_model_serializers? + tags.unshift 'active_model_serializsers'.freeze unless logger_tagged_by_active_model_serializers? ActiveModelSerializers.logger.tagged(*tags) { yield } else yield @@ -95,7 +95,7 @@ def tag_logger(*tags) end def logger_tagged_by_active_model_serializers? - ActiveModelSerializers.logger.formatter.current_tags.include?('AMS'.freeze) + ActiveModelSerializers.logger.formatter.current_tags.include?('active_model_serializsers'.freeze) end class LogSubscriber < ActiveSupport::LogSubscriber diff --git a/test/active_model_serializers/logging_test.rb b/test/active_model_serializers/logging_test.rb index 32c17f49a..1773071dc 100644 --- a/test/active_model_serializers/logging_test.rb +++ b/test/active_model_serializers/logging_test.rb @@ -40,7 +40,7 @@ def logger(logger) def test_uses_ams_as_tag ActiveModel::SerializableResource.new(@post).serializable_hash - assert_match(/\[AMS\]/, @logger.messages) + assert_match(/\[active_model_serializsers\]/, @logger.messages) end def test_logs_when_call_serializable_hash