Instrument ActiveModelSerializers

[sullimander]

I'm currently using ActiveModelSerializers on a few different Rails projects, and want to be able to trace the serialization like a rails view. This implementation borrows heavily from the racecar patcher.

• Subscribe to the appropriate event for AMS 0.10 and AMS 0.9
  • 0.10 - https://github.com/rails-api/active_model_serializers/blob/v0.10.6/docs/general/instrumentation.md
  • 0.9 - https://github.com/rails-api/active_model_serializers/blob/v0.10.6/docs/general/instrumentation.md
• Trace a span with the serializer as the name

I still need to write tests, but wanted to open the PR early to get feedback on the implementation. Thanks!

[delner]

Hey @skisulli , thanks for the contribution! Looked through what you have so far; I think it's looks congruent with what we're doing. So far so good!

Looking forward to giving it another look when you think it's ready! :)

[delner]

Maybe we shouldn't set this tag if the value is nil?

[sullimander]

@delner I think this is ready now, I added tests, and refactored the implementation a bit. Let me know what you think. I also will try to pull this into one of my projects and make sure I get data flowing through.

[sullimander]

I got all errors with integration fixed, but when I use this branch on one of my apps, the project won't track. Is there anything that looks like it might cause tracking to not work?

[delner]

I think our API is a little misleading here, but the argument for trace should be a name, which is a generic name for a kind of span e.g. active_model.serializer.render, not a resource, which is a name that uniquely identifies what category of user data this belongs to e.g. FooSerializer. (I think that's what this payload represents.)

I would change this argument to a fixed constant of a name. I think the reason you might not be seeing traces/spans show up might be because resource is nil, causing the spans to be filtered out. If you give resource a value, that might fix it.

[sullimander]

@delner sorry for taking a bit to get back about this, I was out of town over the weekend.

I tried that, but the app is still not tracking in APM when I try to use this fork. It's the entire app that won't track, not just the active model serializers span. There are no errors in the logs, and the debug info looks like everything should be working.

[delner]

@skisulli Sorry for the late reply! This sometimes happens when there are unfinished spans in the trace. If that happens, it will discard the whole trace.

You can enable debug tracing to see if there are any messages/warnings indicating this might be the case:

Datadog.configure do |c|
  c.tracer debug: true
end

Want to give that a shot and see if it prints out any useful output?

I would also double check that all of your spans have assigned resource and service names.

[sullimander]

@delner sorry I haven't had time to work on this the last few days. I think I will wait until #324 is merged, as that will make this much simpler to implement.

[delner]

@skisulli Okay, that could be some time still, but yeah, there's a lot in common between these two PRs. I can ping you when that gets merged.

[delner]

@skisulli we've merged #380 which introduces a module for tracing ActiveSupport::Notifications events. Want to check that out, see if that helps your implementation here?

[sullimander]

@delner thanks, I will refactor this PR to use #380 today

[sullimander]

@delner I updated the PR, but I'm not getting AMS traces in my project. It looks like the parent id isn't being set on the span.

Name: active_model_serializers.render
Span ID: 1550656567870880260
Parent ID: 0
Trace ID: 6014754472295484098
Type: template
Service: active_model_serializers
Resource: TestSerializer
Error: 0
Start: 1522279512494623744
End: 1522279512496435456
Duration: 1811666
Tags: [
   system.pid => 1,
   env => qa,
   active_model_serializers.serializer => TestSerializer,
   active_model_serializers.adapter => ActiveModelSerializers::Adapter::JsonApi]
Metrics: [
   ]]

Name: rack.request
Span ID: 6509417548762274954
Parent ID: 0
Trace ID: 1522068641061761794
Type: http
Service: test-service
Resource: TestController#show
Error: 0
Start: 1522279512459008256
End: 1522279512497485824
Duration: 38477670
Tags: [
   system.pid => 1,
   env => qa,
   http.method => GET,
   http.url => /test/1234
   http.base_url => https://example.com,
   http.status_code => 200,
   http.request_id => 41bfcc78-010f-46a5-b2fb-385217cf6fdf]
Metrics: [ ],

Name: rails.action_controller
Span ID: 7814864499603388285
Parent ID: 6509417548762274954
Trace ID: 1522068641061761794
Type: http
Service: test-service
Resource: TestController#show
Error: 0
Start: 1522279512460049152
End: 1522279512497244416
Duration: 37195333
Tags: [
   env => qa,
   rails.route.action => show,
   rails.route.controller => TestController]
Metrics: [ ]

[delner]

@skisulli Can you reproduce the issue in a test?

[sullimander]

@delner I added a test, and after further digging in, it looks to be related to ensure_clean_context! in lib/ddtrace/contrib/active_support/notifications/subscription.rb.

[delner]

@skisulli Can you tell me a little more about why ensure_clean_context! was causing it to fail?

[sullimander]

@delner I don't know why, specifically, but I'll dig in. I added a test for a parent span, that was failing. Removing call to ensure_clean_context! made the test pass. With this change, the ActiveModel Serializer spans are now showing properly on my test app.

Test: https://github.com/DataDog/dd-trace-rb/pull/340/files#diff-2ee47dfd5fdfd4b57ceb20ce22377b30R34

[delner]

@skisulli Good to hear that it's working for you. I think I want to pin why that ensure_clean_context! caused an issue and whether we should remove it. If I remember correctly, that function is supposed to prevent context leaks between traces. I'd prefer to keep it if we can.

[sullimander]

@delner I dug into the code more, and now understand why the ensure_clean_context! call is causing the new span to have no parent. ensure_clean_context! will overwrite the current tracer context if there is a current span. So when tracer.trace(@span_name, @options) gets called, tracer now has a new context. The first line of tracer.trace sets options[:child_of] = call_context. Since ensure_clean_context! was called, the call_context of the tracer is empty, and options[:child_of] will be set to an empty context, meaning the new span will have no parent span.

def ensure_clean_context!
  return unless tracer.call_context.current_span
  tracer.provider.context = Context.new
end

[delner]

@skisulli Ahhh okay. Here's what I suspect... I'm guessing ensure_clean_context! was written for anActiveSupport::Notifications based integration which represented the root of a trace, i.e. span that shouldn't have a parent.

I think this might apply when something like Racecar (from which integration this pattern was extracted) re-uses threads. Contexts are supposed thread bound, so if a thread gets re-used, then the old context object might leak into a new trace.

This ensure_clean_context! is very specific to such an integration, and hence was probably errantly leaked into the generic ActiveSupport::Notifications subscription when it was extracted from Racecar. So I think you're right in removing it from the subscription.

However, doing so could break Racecar in the process. I think that functionality might need to be fixed first, which would involve moving ensure_clean_context! back to Racecar and adding some appropriate "hook" to the subscription API so Racecar can trigger it at the correct time for its own purposes.

Such a change probably belongs in its own PR. I suppose I should probably make that, then you could rebase your PR on top of that once its merged.

[delner]

@skisulli Implemented what should be a fix in #390 (removes #ensure_clean_context!)... wanna rebase your PR on that, see if that fixes the issue?

[sullimander]

@delner I rebased to the #390 branch the tests are passing, and my test app is properly tracking ActiveModelSerializers traces, so it looks like everything is working with this PR now.

[delner]

@skisulli Awesome. Plan here then is: 1) I'll do one more review/check to make sure nothing else needs to be addressed, 2) wait for #390 to be merged, then rebase this PR back on top, 3) then we'll merge this.

[sullimander]

@delner thanks! I appreciate you working with me on this.

[delner]

Some general feedback, and a possible bug to address.

[delner]

Name of this function is a little misleading; thought it implied a specific major version number. Could we change this name to something more that reflects "AMS 0.10 or greater"?

Alternatively, maybe it'd be more clear to communicate intent with these function names e.g. use_render_event_name? or use_serializer_name? that are based on a common ams10_or_newer?.

The latter suggestion is just food for thought; if you think the prior is better, that's probably fine too.

[delner]

I think there's a bug here: finish_span would be applying the wrong finish time.

My suggestion here would be to:

def call(name, start, finish, id, payload)
  start_span(name, id, payload, start)
  finish_span(name, id, payload, finish)
end

def start(name, id, payload)
  start_span(name, id, payload)
end

def finish(name, id, payload)
  finish_span(name, id, payload)
end

protected

def start_span(name, id, payload, start = nil)
  # Run callbacks
  run_callbacks(@before_trace_callbacks)

  # Start a trace
  tracer.trace(@span_name, @options).tap do |span|
    # Assign start time if provided
    span.start_time = start unless start.nil?
  end
end

def end_span(name, id, payload, finish = nil)
  tracer.active_span.tap do |span|
    # If no active span, return.
    return nil if span.nil?

    # Call block for event
    block.call(span, name, id, payload)

    # Assign finish time if provided. Else finish.
    finish.nil? ? span.finish : span.finish(finish)

    # Run callbacks
    run_callbacks(@after_trace_callbacks)
  end
end

[delner]

Thinking on the example above, we might want to add some error handling around block.call too, so an error in that block doesn't break the trace.

[sullimander]

@delner working on this now. For the error use case, should it still raise the error up? Thinking something like this, but not sure if I should sill raise the error up the chain.

def finish_span(name, id, payload, finish = nil)
  tracer.active_span.tap do |span|
    # If no span return
    return nil if span.nil?

    begin
      # Call event block
      block.call(span, name, id, payload)
    rescue StandardError => error
      span.set_error(error)
      raise
    ensure
      # Finsih span `span.finish` will default to current time if finish.nil?
      span.finish(finish)

      # Run after callbacks
      run_callbacks(@after_trace_callbacks)
    end
  end
end

[delner]

@skisulli I don't think we should raise or set any kind of error, since generating trace data is meta, and shouldn't break legitimate user code if it fails. When tracing fails, we instead use the tracer logger to quietly log errors.

I'm going to open (another) PR to implement this change (with the call) too, because I think this is important for ASN subscription, and I'd like to isolate it from ActiveModelSerializers. We'll rebase on top of that once its merged.

[delner]

If call and start/finish both exist, which does ActiveSupport::Notifications use? Does it call both?

[sullimander]

ActiveSupport 4 and 5 appear to just call start/finish, and ActiveSupport 3 calls call. I ran into this when testing the ActiveModelSerializers using contrib-old

[delner]

Ah good to know.

[delner]

@skisulli Merged #395. Go ahead on rebase on 0.12-dev again.

[sullimander]

@delner rebased on 0.12-dev and updated the PR to point back to 0.12-dev

[delner]

Hey @skisulli, we added a new Datadog::Contrib::ActiveSupport::Notifications::Event helper to 0.13-dev that might be useful here. You can checkout how it works, and some examples of it being implemented in other integrations here: #400

Think it could be a good fit here? Let me know what you think!

[sullimander]

@delner it looks like it would be a good fit. I'll take a look in more detail and update this PR.

[sullimander]

@delner I updated the implementation to use the model in #400. I still need to update/fix the tests.

[delner]

This is the older < 0.10 event right? I would consider overriding the supported? method here and checking the version number, so it doesn't subscribe in 0.10+. See the ActiveRecord for an example. Same likely applies to the Render event.

[sullimander]

@delner updated the tests and added the supported? method for both events.

[delner]

One thing related to tests, otherwise I'm very happy with this.

[delner]

Can we move this into the spec/ddtrace/contrib/active_model_serializers folder, since these helpers are specific to the integration specs and not generally useful to other examples in the test suite?

Also, I'm generally not a fan of defining constants in test suites using class or module, because they tend to sit in the global namespace and potentially cause naming conflicts. You've mitigated this here by putting this in a module with a name that's less likely to conflict, so this point doesn't exactly constitute blocking feedback.

However, I would consider leveraging RSpec's stub_const, Class.new, or both to create test constants that only survive the scope of an example. This might look like in helpers.rb:

module ActiveModelSerializersHelpers
  def ams_0_10_or_newer?
    Gem.loaded_specs['active_model_serializers'] \
      && Gem.loaded_specs['active_model_serializers'].version >= Gem::Version.new('0.10')
  end

  def disable_logging
    if ams_0_10_or_newer?
      ActiveModelSerializers.logger.level = Logger::Severity::UNKNOWN
    end
  end
end

RSpec.shared_context 'AMS serializer' do
  extend ActiveModelSerializersHelpers

  let(:serializer_class) do
    stub_const('TestModelSerializer', Class.new(ActiveModel::Serializer) do
      attributes :name
    end)
  end

  if ams_0_10_or_newer?
    let(:model_base_class) do
      Class.new(ActiveModelSerializers::Model) do
        attr_writer :id
      end
    end

    let(:model_class) do
      stub_const('TestModel', Class.new(model_base_class) do
        attributes :name
      end)
    end
  else
    let(:model_base_class) do
      Class.new(ActiveModelSerializers::Model) do
        attr_writer :id

        def initialize(hash = {})
          @attributes = hash
        end

        def read_attribute_for_serialization(name)
          if name == :id || name == 'id'
            object_id
          elsif respond_to?(name)
            send name
          else
            @attributes[name]
          end
        end
      end
    end

    let(:model_class) do
      stub_const('TestModel', Class.new(model_base_class))
    end
  end
end

Then in your test file just add:

require_relative 'helpers'

RSpec.describe 'ActiveModelSerializers patcher' do
  include_context 'AMS serializer'

  # Perform test here...
end

The really cool benefit you get from doing this, other than not having conflicting constants, is you can also override behavior/definitions of these constants in your examples. This makes it easier to test different variations, implementations and edge cases without having to define constants for each.

[sullimander]

@delner updated the tests per your feedback. I had tried that earlier and couldn't get it working right. Took some experimentation but got it working with a before block, for some reason using the lets didn't work right.

[delner]

This is looking good to me! Let's merge it.

[delner]

@skisulli This one has been a long time coming, but thanks so much for your patience and hard work on this one! 💯 It's looking great, and I'm looking forward to it being used!