Add Logging #1291

maurogeorge · 2015-10-22T21:33:40Z

Hi guys,

I think today we do not logging nothing right? Based on this I started working on a logging using ActiveSupport::Notifications and ActiveSupport::LogSubscriber.

The actual log output on this patch is:

[AMS] Rendered PostSerializer with ActiveModel::Serializer::Adapter::JsonApi (5.72ms)

This makes sense to you guys? If make sense I can continue working on it.

bf4 · 2015-10-22T22:15:32Z

lib/active_model/serializable_resource.rb

+      payload = { serializer: serializer, adapter: adapter }
+      ActiveSupport::Notifications.instrument(event_name, payload) do
+        block.call
+      end


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, 💯

Thanks, I made these changes 👍

bf4 · 2015-10-22T22:20:35Z

🎆 😻 yay.. plz see comments re: existing logger

maurogeorge · 2015-10-23T10:23:40Z

@bf4 thanks for the review, I made some changes. I prefer keep the commits for now when it is ok I squash these.

maurogeorge · 2015-10-23T10:32:05Z

@bf4 I answered each of your comments, they are under the "Show outdated diff" link, since the code changed.

I waiting for your feedback ❤️

Generates logging when renders a serializer.

- Use yield over block.call - Freeze the event name string

* 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

Move the definition of locals to inside the `info` block this way the code is executed only when the logger is called.

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.

beauby · 2015-10-25T22:02:07Z

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


Could you explain why you made that change?

Take a look on this commit message maurogeorge@981c229

Didn't clear it up for me

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.

beauby · 2015-10-25T22:04:31Z

I'm generally 👍 with this PR.

bf4 · 2015-10-25T22:50:48Z

docs/general/logging.md

@@ -0,0 +1,12 @@
+# Logging
+
+If we are using AMS on Rails app the `Rails.logger` will be used.


Also, document that the event is render.active_model_serializers

bf4 · 2015-10-25T23:00:18Z

This PR mixes a desired feature with good code and tests with an architectural and behavior change this maintainer is very 👎 on. Please separate the two into two PRs so we can get the feature (logging notifications) into master.

bf4 · 2015-10-25T23:01:42Z

Also, please fix warnings

Calling deprecated ArraySerializer in /home/travis/build/rails-api/active_model_serializers/test/collection_serializer_test.rb:10:in `new'. Please use CollectionSerializer

beauby · 2015-10-25T23:03:23Z

@bf4 I believe the warning fixes do not belong in this PR since it does not touch the file causing the warning. Those should probably have been corrected in the PR that deprecated ArraySerializer.

beauby · 2015-10-25T23:05:12Z

Or am I missing something?

bf4 · 2015-10-26T00:13:11Z

If they were in there, yeah i must have missed them in a rebase

B mobile phone

On Oct 25, 2015, at 6:03 PM, Lucas Hosseini notifications@github.com wrote:

@bf4 I believe the warning fixes do not belong in this PR since it does not touch the file causing the warning. Those should probably have been corrected in the PR that deprecated ArraySerializer.

—
Reply to this email directly or view it on GitHub.

maurogeorge · 2015-10-26T12:31:33Z

Thanks for the review guys, I will made the changes when working on the project again.

[ci skip]

maurogeorge · 2015-10-29T21:12:26Z

@bf4 @beauby I made the changes as suggested, waiting for your review.
Thanks 😄

maurogeorge · 2015-11-04T21:30:51Z

@bf4 @beauby I rollback all changes related with ActiveModel::Serializer.logger and keep the actual ActiveModelSerializers.logger since this namespace is a discussion on other thread.

When you guys have some time please review.

I think we can remove the labels Hold and Needs Team Discussion I think this is related with the namespace I am right?

Thanks a lot guys

NullVoxPopuli · 2015-11-04T21:36:25Z

@maurogeorge I think I'm good with this.

i'll give a few hours for other team members to comment

bf4 · 2015-11-05T04:39:23Z

lib/active_model/serializable_resource.rb

+      notify_active_support do
+        adapter.to_json(*args)
+      end
+    end


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

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

bf4 · 2015-11-05T04:40:35Z

@NullVoxPopuli please don't take off a hold when the raised issues haven't been addressed

bf4 · 2015-11-05T04:44:13Z

lib/active_model/serializer/logging.rb

@@ -0,0 +1,26 @@
+module ActiveModel
+  class Serializer
+    module Logging


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

@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

wagenet · 2015-11-05T19:40:20Z

I'm definitely interested in this for use by Skylight. The instrumentation part of this looks great.

bf4 · 2015-11-05T19:45:31Z

@maurogeorge can we scope this PR to just the notifications?

+    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

maurogeorge · 2015-11-05T21:33:37Z

@bf4 why? I made the last change you ask.

At #1291 (comment) you say we need 2 👍 to go on, I think we have theses on #1291 (comment) and #1291 (comment). If I am not wrong you concern is around the namespace right? I think we can go this way until we solve the namespace issue.

bf4 · 2015-11-05T23:21:33Z

lib/active_model/serializable_resource.rb

+      notify_active_support do
+        block.call
+      end
+    end


yeah, I think you're right. This doesn't add anything but complexity. Sorry for having you extra work. I meant it as a thought if it made sense.. and it's more indirection than helpful

maurogeorge · 2015-11-09T11:26:12Z

@bf4 after the #1322 what is the idea? I stop working here and continue making revision on the new PR? If the Idea is to stop sending more code to this branch I think we can close this.

Thanks

bf4 · 2015-11-09T14:33:05Z

Up for discussion.... I could close that pr and make it into this one

I thought maybe you'd want to do more logging stuff here

Really whatever makes you feel most appreciated. I wouldn't have couldn't have the 'follow up' pr without this one.

B mobile phone

On Nov 9, 2015, at 5:26 AM, Mauro George notifications@github.com wrote:

@bf4 after the #1322 what is the idea? I stop working here and continue making revision on the new PR? If the Idea is to stop sending more code to this branch I think we can close this.

Thanks

—
Reply to this email directly or view it on GitHub.

maurogeorge · 2015-11-09T19:26:24Z

I will close this and help with the review of the new one.

Thanks for the rebase and keep the reference ❤️

bf4 reviewed Oct 22, 2015
View reviewed changes

maurogeorge added 8 commits October 24, 2015 14:31

Add Logging

100146f

Generates logging when renders a serializer.

Tunning performance on notify_active_support

e5c7969

- Use yield over block.call - Freeze the event name string

Performance tunning on LogSubscriber#render

ac473c7

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

b0ef4d7

Add docs about logging

2a80cdb

Add a CHANGELOG entry

67c7db1

maurogeorge force-pushed the patch-10 branch from 16e06ae to 67c7db1 Compare October 24, 2015 16:32

maurogeorge mentioned this pull request Oct 24, 2015

RFC: Name-spacing of objects under (module) ActiveModelSerializers vs. (core class) ActiveModel::Serializer #1298

Closed

beauby reviewed Oct 25, 2015
View reviewed changes

bf4 reviewed Oct 25, 2015
View reviewed changes

bf4 added C: Feature V: 0.10.x S: Needs Team Discussion labels Oct 26, 2015

maurogeorge mentioned this pull request Oct 26, 2015

Proposal: Create assert_response_schema test helper #1270

Closed

maurogeorge added 3 commits October 29, 2015 18:48

Keep the ActiveModelSerializers.logger

e28e2b5

Better wording on Logging docs

ca4139e

[ci skip]

Add doc about instrumentation

2c4a028

[ci skip]

NullVoxPopuli removed S: Hold S: Needs Team Discussion labels Nov 4, 2015

bf4 reviewed Nov 5, 2015
View reviewed changes

bf4 added S: Needs Team Discussion S: Hold labels Nov 5, 2015

bf4 reviewed Nov 5, 2015
View reviewed changes

beauby mentioned this pull request Nov 5, 2015

ActiveSupport::Notifications Support #1319

Closed

Use ActiveModel::Callbacks on the SerializableResource

49c8f69

bf4 reviewed Nov 5, 2015
View reviewed changes

bf4 mentioned this pull request Nov 8, 2015

Instrumenting rendering of resources #1322

Merged

maurogeorge closed this Nov 9, 2015

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add Logging #1291

Add Logging #1291

maurogeorge commented Oct 22, 2015

bf4 Oct 22, 2015

maurogeorge Oct 23, 2015

bf4 commented Oct 22, 2015

maurogeorge commented Oct 23, 2015

maurogeorge commented Oct 23, 2015

beauby Oct 25, 2015

bf4 Oct 25, 2015

maurogeorge Oct 26, 2015

bf4 Nov 5, 2015

maurogeorge Nov 5, 2015

beauby commented Oct 25, 2015

bf4 Oct 25, 2015

bf4 Oct 25, 2015

bf4 commented Oct 25, 2015

bf4 commented Oct 25, 2015

beauby commented Oct 25, 2015

beauby commented Oct 25, 2015

bf4 commented Oct 26, 2015

maurogeorge commented Oct 26, 2015

maurogeorge commented Oct 29, 2015

maurogeorge commented Nov 4, 2015

NullVoxPopuli commented Nov 4, 2015

bf4 Nov 5, 2015

maurogeorge Nov 5, 2015

bf4 commented Nov 5, 2015

bf4 Nov 5, 2015

NullVoxPopuli Nov 5, 2015

wagenet commented Nov 5, 2015

bf4 commented Nov 5, 2015

maurogeorge commented Nov 5, 2015

bf4 Nov 5, 2015

maurogeorge commented Nov 9, 2015

bf4 commented Nov 9, 2015

maurogeorge commented Nov 9, 2015

		@@ -0,0 +1,12 @@
		# Logging

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

Add Logging #1291

Add Logging #1291

Conversation

maurogeorge commented Oct 22, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bf4 commented Oct 22, 2015

maurogeorge commented Oct 23, 2015

maurogeorge commented Oct 23, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

beauby commented Oct 25, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bf4 commented Oct 25, 2015

bf4 commented Oct 25, 2015

beauby commented Oct 25, 2015

beauby commented Oct 25, 2015

bf4 commented Oct 26, 2015

maurogeorge commented Oct 26, 2015

maurogeorge commented Oct 29, 2015

maurogeorge commented Nov 4, 2015

NullVoxPopuli commented Nov 4, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bf4 commented Nov 5, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wagenet commented Nov 5, 2015

bf4 commented Nov 5, 2015

maurogeorge commented Nov 5, 2015

Choose a reason for hiding this comment

maurogeorge commented Nov 9, 2015

bf4 commented Nov 9, 2015

maurogeorge commented Nov 9, 2015