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 a facility for easily subscribing to AS::Notifications #324

Closed
wants to merge 1 commit into from

Conversation

dasch
Copy link
Contributor

@dasch dasch commented Jan 23, 2018

This helper starts a span before the instrumented code starts executing,
waits for the code to finish, then calls the subscriber block with the
span and the AS::Notifications event details.

This allows you to more easily trace nested spans.

@palazzem palazzem added community Was opened by a community member integrations Involves tracing integrations labels Jan 24, 2018
Copy link
Contributor

@delner delner left a comment

Choose a reason for hiding this comment

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

I think this looks promising! Could be pretty useful for frameworks that implement ActiveSupport::Notifications.

Just some questions about customization, thread safety, and loading.

@@ -0,0 +1,34 @@
module Datadog
class Notifications
def self.subscribe(pattern, tracer = Datadog.tracer, &block)
Copy link
Contributor

Choose a reason for hiding this comment

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

I really like the elegance of this! Could it benefit from more customization? It might be useful to be able to pass options to the trace method (which would also remedy the `'' span name.)

To do so, it could look something like:

def self.subscribe(pattern, span_name, options = {}, tracer = Datadog.tracer, &block)
  subscriber = Subscriber.new(span_name, options, tracer, &block)
  ActiveSupport::Notifications.subscribe(pattern, subscriber)
end

Copy link
Contributor Author

Choose a reason for hiding this comment

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

👍


def finish(name, id, payload)
# We close spans in reverse order.
span = @spans.pop or raise "no spans left in stack!"
Copy link
Contributor

Choose a reason for hiding this comment

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

It's thoughtful to use a stack here, but is this thread safe? Haven't been able to confirm that much. We do have an active_span function for retrieving spans in a safe way, which might be a good substitute for the stack here.

The equivalent would be:

span = Datadog.tracer.active_span

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I believe it's thread safe, as AS::N subscribers are thread local, but I'll switch to this way.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Hmm, that doesn't seem to work...

Copy link
Contributor

Choose a reason for hiding this comment

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

What kind of problem did you run into?

@@ -0,0 +1,34 @@
module Datadog
class Notifications
Copy link
Contributor

Choose a reason for hiding this comment

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

Given the purpose of this module is to aid integrations into frameworks/libraries that implement ActiveSupport::Notifications, would it make sense to move this into that Contrib namespace, where that integration support lives? Something like Datadog::Contrib::ActiveSupport::Notifications?

I think one of our goals is to reduce framework dependencies in the core library, isolating them to the Contrib namespace, where we can optionally load code based on the presence of libraries (e.g. ActiveSupport.) In such a case, we could then modify the Racecar::Patcher to require 'ddtrace/contrib/active_support/notifications' when it verifies the presence of ActiveSupport and patches Racecar.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Good idea.

@@ -33,28 +36,23 @@ def patched?
@patched = false
end

def start(event, _, payload)
ensure_clean_context!
def unpatch
Copy link
Contributor

Choose a reason for hiding this comment

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

I see this being referenced in the tests. What is it used for?

Copy link
Contributor Author

@dasch dasch Jan 25, 2018

Choose a reason for hiding this comment

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

patch modifies global state, and only does anything the first time around – so the setup code we need to e.g. pass the tracer to the Subscriber instances won't be called on the second go. Because of that, we need a way to clear the state such that we can call patch again. I'm not even sure why it worked before...

Copy link
Contributor

@delner delner Jan 29, 2018

Choose a reason for hiding this comment

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

Gotcha. So this is particularly for testing purposes? If that's the case, do you think it might be reasonable to move this behavior into the test suite, and run it before/after tests run?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Sure. How is this handled in other specs? I'd assume that, since patch is a no-op on the second call, this would be a general problem?

Copy link
Contributor

@delner delner Feb 1, 2018

Choose a reason for hiding this comment

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

In the general sense, it's usually not an issue because most integrations only monkey patch code, send some metadata, so we don't need to redo it each time for each test. There's something to be said about not carrying over any state between test runs, which is normally really important/preferable. However, it's not really feasible to truly un-monkey patch code and reset back to actual original state given the nature of this meta-programming.

Although in the case of Racecar, the patching is also subscribing to some instrumentation, maybe we don't need to do this actually? Since the subscriptions should still be good across example runs. Or did this fix something that wasn't working?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

The problem was that the tracer instance is per-test, but once patched, the first tracer is permanently baked into the patch. I don't know why this hasn't been a problem until now.

Copy link
Contributor

@delner delner Feb 2, 2018

Choose a reason for hiding this comment

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

Ahhh, okay I see. Because when we patch, we create a Subscriber with the reference to the tracer, and subscribe it to AS::N. Then that Subscriber object remains subscribed to AS::N with the reference to the old tracer, even as a new example starts running.

Perhaps we should make the Subscriber objects accessible, such that we can modify/unsubscribe them in the tests. Maybe something like:

contrib/active_support/notifications.rb

self.subscribe(pattern, subscriber)
  ::ActiveSupport::Notifications.subscribe(pattern, subscriber)
end

self.unsubscribe(subscriber)
  ::ActiveSupport::Notifications.unsubscribe(subscriber)
end

self.subscribe!(pattern, span_name, options = {}, tracer = Datadog.tracer, &block)
  subscriber(tracer, span_name, options, &block).tap do |subscriber|
    subscribe(pattern, subscriber)
  end
end

self.subscriber(span_name, options = {}, tracer = Datadog.tracer, &block)
  Subscriber.new(tracer, span_name, options, &block)
end

contrib/racecar/patcher.rb

def patch
  #...
  subscribe!
end

def subscribe!
  subscribers.each do |pattern, subscriber|
    Contrib::ActiveSupport::Notifications.subscribe(pattern, subscriber)
  end
end

def subscribers
  @subscribers ||= {
    'process_message.racecar' => Contrib::ActiveSupport::Notifications.subscriber(NAME_MESSAGE, {}, configuration[:tracer], &method(:process))
    'process_batch.racecar' => Contrib::ActiveSupport::Notifications.subscriber(BATCH_MESSAGE, {}, configuration[:tracer], &method(:process))
  }
end

racecar_spec.rb

before(:each) do
  Contrib::Racecar::Patcher.subscribers.each do |_pattern, subscriber|
    subscriber.instance_variable_set(:@tracer, tracer)
  end
end

Although I think the above should work, I also think this case highlights a weakness in the current Racecar implementation; that once configured, you cannot reconfigure Racecar with a different tracer.

We could go a step further, and try to fix this by re-subscribing to AS::N with new Subscribers everytime the configuration changes, or maybe by doing some kind of lazy evaluation of configurable options like tracer (both of which are kind of complicated.) Something to think about maybe?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I think it's actually possible to keep adding subscribers, it's just that patch short-circuits before getting to that part:

https://github.com/dasch/dd-trace-rb/blob/ce6b30cf66435fa88f7ee191549a99549c4324f5/lib/ddtrace/contrib/racecar/patcher.rb#L17-L23

I think a better solution would be to manage the patch status in a separate component and just let patch do its thing regardless of whether it's already been applied. It seems that the idempotency mechanics are the same everywhere, i.e. a class instance variable @patched that gets set to true.

Copy link
Contributor

@delner delner Feb 6, 2018

Choose a reason for hiding this comment

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

If we keep adding subscribers, won't we collect a bunch of old subscribers that errantly write redundant traces (possibly to the same tracer)? I'm worried about potential side effects from that.

If that's not much of a concern for these tests, then I perhaps I might suggest a simpler, lighter approach? By just undoing the @patched manually in the tests?

before(:each) do
  # Do this before calling Datadog.configure
  Datadog::Contrib::Racecar::Patcher.instance_variable_set(:@patched, false)
end

This helper starts a span before the instrumented code starts executing,
waits for the code to finish, then calls the subscriber block with the
span and the AS::Notifications event details.

This allows you to more easily trace nested spans.

def finish(name, id, payload)
# We close spans in reverse order.
span = @spans.pop or raise "no spans left in stack!"
Copy link
Contributor

Choose a reason for hiding this comment

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

I'm a bit concerned using a stack here would be thread unsafe. You mentioned getting the @tracer.active_span didn't work; what was the issue you ran into?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I'm not sure – the spans aren't completed correctly. I'd love to get some feedback on that.

Copy link
Contributor

Choose a reason for hiding this comment

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

Yeah, I think I'd like to take a look at that. I'll see if I can clone and test this.

Copy link
Contributor

@delner delner Feb 8, 2018

Choose a reason for hiding this comment

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

@dasch Okay, I cloned down your changes locally, and dug deeper into this.

This @tracer.active_span wasn't working, because as an isolated change, during the tests, the unpatch method was creating many subscriptions with many tracers, for each example. And if I'm understanding the issue correctly, when there are multiple tracers concurrently writing, it tends to cause problems with context propagation (which gets shared between the tracers), causing the tests to fail.

By applying the @tracer.active_span change in conjunction with the subscribers change suggested in the other comment thread, I got these tests passing locally. I've created a patch file which has all the above changes, which will fix the tests and Rubocop issues breaking the CI build. Feel free to try it out on your branch!

Git diff (apply on your branch with git apply datadog_asn.txt):
datadog_asn.txt


configuration[:tracer].set_service_info(
Contrib::ActiveSupport::Notifications.subscribe('process_message.racecar', NAME_MESSAGE, {}, tracer, &method(:process))
Copy link
Contributor

Choose a reason for hiding this comment

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

Pretty cool!

@delner delner added this to the 0.12.0 milestone Feb 5, 2018
@delner delner changed the base branch from master to 0.12-dev February 5, 2018 18:58
@delner delner added the feature Involves a product feature label Feb 5, 2018
@dasch
Copy link
Contributor Author

dasch commented Feb 16, 2018

@delner unfortunately I won't have much time to continue work on this – would you be able to bring it forward?

@delner
Copy link
Contributor

delner commented Feb 16, 2018

No problem @dasch. I think we're close to having this ready to roll. Thanks for your contribution!

@ianks
Copy link

ianks commented Mar 16, 2018

We would love this functionality! Prob the most important feature we need.

Would it be possible to add some documentation to this?

@delner
Copy link
Contributor

delner commented Mar 21, 2018

Opened a new pull request which re-implements this one.

See #380 for the new Datadog::Contrib::ActiveSupport::Notifications::Subscriber module.
See #381 for the Racecar update, as an implementation example of the new module.

@dasch @ianks feel free to check out/review/comment on those! Going to close this one in favor of those.

@delner delner closed this Mar 21, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
community Was opened by a community member feature Involves a product feature integrations Involves tracing integrations
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants