diff --git a/CHANGELOG.md b/CHANGELOG.md index 0f7b24bf..f2607e07 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/README.md b/README.md index e2bab278..684b39c1 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/README.md b/docs/README.md index a1e9d908..a05fdfb3 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 00000000..160a9e76 --- /dev/null +++ b/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`. diff --git a/docs/general/logging.md b/docs/general/logging.md new file mode 100644 index 00000000..010ae01a --- /dev/null +++ b/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) +``` diff --git a/lib/action_controller/serialization.rb b/lib/action_controller/serialization.rb index c11b6c8e..5fefaedf 100644 --- a/lib/action_controller/serialization.rb +++ b/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 diff --git a/lib/active_model/serializable_resource.rb b/lib/active_model/serializable_resource.rb index da1a772a..c91eea17 100644 --- a/lib/active_model/serializable_resource.rb +++ b/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 diff --git a/lib/active_model/serializer/railtie.rb b/lib/active_model/serializer/railtie.rb index cade0354..533a191c 100644 --- a/lib/active_model/serializer/railtie.rb +++ b/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 - 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 922fd876..c7a4d1d4 100644 --- a/lib/active_model_serializers.rb +++ b/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 - self.logger = Rails.logger || Logger.new(IO::NULL) + mattr_accessor(:logger) { ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT)) } 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 diff --git a/lib/active_model_serializers/callbacks.rb b/lib/active_model_serializers/callbacks.rb new file mode 100644 index 00000000..7f1cd689 --- /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 new file mode 100644 index 00000000..511ef764 --- /dev/null +++ b/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 diff --git a/test/action_controller/serialization_test.rb b/test/action_controller/serialization_test.rb index e9288d56..a3b76198 100644 --- a/test/action_controller/serialization_test.rb +++ b/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 diff --git a/test/active_model_serializers/logging_test.rb b/test/active_model_serializers/logging_test.rb new file mode 100644 index 00000000..1773071d --- /dev/null +++ b/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 diff --git a/test/logger_test.rb b/test/logger_test.rb index d324570a..9e4853ba 100644 --- a/test/logger_test.rb +++ b/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 diff --git a/test/test_helper.rb b/test/test_helper.rb index 9257c24a..f494eba1 100644 --- a/test/test_helper.rb +++ b/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