Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add Logging #1291

Closed
wants to merge 12 commits into from
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
1 change: 1 addition & 0 deletions docs/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
12 changes: 12 additions & 0 deletions docs/general/logging.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,12 @@
# Logging

If we are using AMS on Rails app the `Rails.logger` will be used.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

by default

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also, document that the event is render.active_model_serializers


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)
```
1 change: 1 addition & 0 deletions lib/action_controller/serialization.rb
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,7 @@ def get_serializer(resource, options = {})
serializable_resource.serialization_scope_name = _serialization_scope
begin
serializable_resource.adapter
serializable_resource
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could you explain why you made that change?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

seconded

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Take a look on this commit message maurogeorge@981c229

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Didn't clear it up for me

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The main purpose of this is to the instrumentation be called on the Rails controller, so if I remove, this test will be broken.

As you can see here the instrumentation is made on the ActiveModel::SerializableResource what I think is the canonical way to use a serializer and as you can see we simply delegate the method to the adapter. If we call the adapter directly over use the ActiveModel::SerializableResource we will need to change all adapters to call instrumentation on they methods serializable_hash, as_json and to_json.

Keeping the ActiveModel::SerializableResource we define this once and all adapter, including new ones, will have instrumentation.

Let me know if you have some doubt.

rescue ActiveModel::Serializer::CollectionSerializer::NoSerializerError
resource
end
Expand Down
26 changes: 25 additions & 1 deletion lib/active_model/serializable_resource.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

call me crazy, but I think this might be a good use case for an around filter

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi @bf4 I updated to use this 49c8f69. Personally I don't like, but I can live with it 😄


def serialization_scope=(scope)
serializer_opts[:scope] = scope
Expand Down Expand Up @@ -64,5 +80,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
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

did you need to use the &block form? I think you should be able to remove the method argument and replace block.call with yield (which is faster and saves object creation

we should also freeze the string here or reduce object allocations on what would be frequently called method, even if the notifications are turned off.

otherwise, 💯

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks, I made these changes 👍

end
end
end
2 changes: 2 additions & 0 deletions lib/active_model/serializer.rb
Original file line number Diff line number Diff line change
Expand Up @@ -6,13 +6,15 @@
require 'active_model/serializer/configuration'
require 'active_model/serializer/fieldset'
require 'active_model/serializer/lint'
require 'active_model/serializer/logging'
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this should be required in lib/active_model_serializers, I think. It's more of a global concern than local to this file. feel free to disagree


# ActiveModel::Serializer is an abstract class that is
# reified when subclassed to decorate a resource.
module ActiveModel
class Serializer
include Configuration
include Associations
include Logging
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👎 does not belong here

require 'active_model/serializer/adapter'

# Matches
Expand Down
32 changes: 32 additions & 0 deletions lib/active_model/serializer/logging.rb
Original file line number Diff line number Diff line change
@@ -0,0 +1,32 @@
module ActiveModel
class Serializer
module Logging
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm 👎 on adding new namespaces to what I hope to become the legacy namespace, #1310

It either needs to be in lib/active_model_serializers.rb, in lib/active_model_serializers/logging.rb or have 2 👍 by other maintainers

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@bf4 are you saying everything should be switched to the new namespace before adding anything?

wouldn't that only matter depending on the order of merges? waiting on stuff like that causes needless delays, imo

but maybe I misunderstand? idk

extend ActiveSupport::Concern

included do
cattr_accessor(:logger) do
ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT))
end
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So, there's a logger already defined on ActiveModelSerializers.logger which should be used. it should default to the null logger and be configured in the railtie, which is extra work, I hope you don't mind

so, you could remove the line from the test helper since it defaults to null

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I prefer keep the ActiveModel::Serializer.logger since this is the way we define configs today like the adapter. More info about my rationale here maurogeorge@d2c2378

In fact, what you think about using the config like: ActiveModel::Serializer.config.logger the same way we define the adapter we can define a custom log.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry. I cannot support this.

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)"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The more work you can do in the info block the better (i.e. all the locals here), since it is only evaluated when the info log level. (I think it should be debug, so this should be configurable.. logger.add(Logger::DEBUG) { "Rendered..." } would be fine

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I do not understand this line:

...so this should be configurable.. logger.add(Logger::DEBUG) { "Rendered..." } would be fine

Could you please clarify?
I follow the same idea of Active Job and Action View for example the uses the info to log.

end
end
end

def logger
ActiveModel::Serializer.logger
end
end
end
end
end

ActiveModel::Serializer::Logging::LogSubscriber.attach_to :active_model_serializers
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

should be configured in the railtie

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why? We still want logging on other environments right?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

you mean like non-Rails?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sorry, was referring to notifications above. logging should be configured in rails in the railtie. outside rails, manually

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the review, I will update next time I work on the project.

I do not understand what you want here? Do you want that I move ActiveModel::Serializer::Logging::LogSubscriber.attach_to :active_model_serializers to the Railtie? Could you please clarify?

Thanks

4 changes: 1 addition & 3 deletions lib/active_model/serializer/railtie.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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 }
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This won't work for two reasons:

  1. It's not our lib that needs to be loaded for Rails.logger to be defined, it's Rails.
  2. This won't work because there's nothing running this hook

end

initializer 'generators' do |app|
Expand Down
3 changes: 0 additions & 3 deletions lib/active_model_serializers.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
10 changes: 10 additions & 0 deletions test/action_controller/serialization_test.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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
18 changes: 0 additions & 18 deletions test/logger_test.rb

This file was deleted.

77 changes: 77 additions & 0 deletions test/logging_test.rb
Original file line number Diff line number Diff line change
@@ -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
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

just use your own logger. that's kind of the point, no?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think so. I know that the ActiveModelSerializers.logger do his job, so to avoid open the log, parse the log, delete the log and so on. I prefer using a custom logger this way I can have all messages on a easy way. This is the same logic followed by Active Job

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, I think that makes sense. I would have @file = StringIO.new; logger = ActiveSupport::Logger.new(@file); @file.rewind; @file.read but this hides that complexity

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

re naming, to me

ActiveJob::Base.logger corresponds to ActiveModelSerializers.logger

and

ActiveJob::Logging corresponds to ActiveModelSerializers::Logging


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)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nice tests

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks 😊

end
end
end
end
2 changes: 2 additions & 0 deletions test/test_helper.rb
Original file line number Diff line number Diff line change
Expand Up @@ -62,3 +62,5 @@ def Minitest.after_run(&block)
require 'fixtures/active_record'

require 'fixtures/poro'

ActiveModel::Serializer.logger = Logger.new(nil)