Add support for tracing Dispatched Events in Laravel 5.8+

[ralphschindler]

Description

Add the appropriate 5.8+ Event Dispatcher method for tracing. See: https://laravel.com/docs/5.8/upgrade#events

Readiness checklist

• (only for Members) Changelog has been added to the release document.
• Tests added for this feature/bug.

Reviewer checklist

• Appropriate labels assigned.
• Milestone is set.
• Changelog has been added to the release document. For community contributors the reviewer is in charge of this task.

[ralphschindler]

These tests made me think, and maybe you're handling this with other code?....

Should this integration be tracking the dispatching of the event, even if there are no listeners to the event? Or, will the datadog ui be smart enough that if there are no listeners, an empty span for a dispatched event won't show up?

Unsure what it looked like in pre 5.8 when the method fire was being tracked.

Thanks for your work on this!

[bwoebi]

Pre 5.8 it looked exactly like it does in the tests here:

dd-trace-php/tests/Integrations/Laravel/V4/CommonScenariosTest.php

Lines 57 to 86 in 79fe244

	->withChildren([
	SpanAssertion::exists('laravel.application.handle')
	->withChildren([
	SpanAssertion::build('laravel.action', 'laravel', 'web', 'simple')
	->withExactTags([
	'some.key1' => 'value',
	'some.key2' => 'value2',
	Tag::COMPONENT => 'laravel',
	]),
	SpanAssertion::exists('laravel.event.handle'),
	SpanAssertion::exists('laravel.event.handle'),
	SpanAssertion::exists('laravel.event.handle'),
	SpanAssertion::exists('laravel.event.handle'),
	]),
	SpanAssertion::exists(
	'laravel.provider.load',
	'Illuminate\Foundation\ProviderRepository::load'
	)->withChildren([
	SpanAssertion::exists('laravel.event.handle'),
	SpanAssertion::exists('laravel.event.handle'),
	SpanAssertion::exists('laravel.event.handle'),
	SpanAssertion::exists('laravel.event.handle'),
	SpanAssertion::exists('laravel.event.handle'),
	SpanAssertion::exists('laravel.event.handle'),
	SpanAssertion::exists('laravel.event.handle'),
	]),
	SpanAssertion::exists('laravel.event.handle'),
	SpanAssertion::exists('laravel.event.handle'),
	SpanAssertion::exists('laravel.event.handle'),
	]),

.

No, the datadog UI does not magically know about there being an event handler.

[bwoebi]

Thanks for the PR!

Anyway, on the topic of:

Should this integration be tracking the dispatching of the event, even if there are no listeners to the event.

Currently, the way to go is yes.
In particular it isn't that simple to determine whether there's a receiver: it might be broadcast conditionally, there might be listeners on an interface, which are not directly tied to the event itself (Dispatcher::addInterfaceListeners e.g.).
Now the question is, how would we, the tracer, know whether the event actually was dispatched anywhere? There is in fact a way to do that: wrapping any returned Closure from $this->getListeners(), but that will be visible in stacktraces. Just simply tracing the returned Closures would be an option - but that functionality is going to only be implemented next week.

Anyway, we may consider improving upon that in future, but for now, that's what we're going to do.

[ralphschindler]

Thanks @bwoebi for digging into this PR and taking it to the finish line- and so promptly!
We will be updating to 0.84.0 ASAP.

[bwoebi]

0.84.0 just has been released, hope it works just as you expect :-)

[joelharkes]

Seems to work well :)

It does all of a sudden adds a lot more spans to each process though. People (for example us) wit heavy applications, could have problems reaching the 1000+ spans now or see their datadog bill all of a sudden increase when upgrading the tracer package. good to keep this in mind when adding these things.

[joelharkes]

We also trace these things:

use Illuminate\Queue\Jobs\Job;
  \DDTrace\trace_method(Worker::class, 'runJob', function (\DDTrace\SpanData $span, $args) {
            /** @var Job $job */
            $job = $args[0];
            $span->service = 'worker';
            $span->resource = $job->resolveName();
            $span->name = 'laravel.queue';
            $span->meta['job.name'] = $job->getName();
            $span->meta['job.id'] = $job->getJobId();
            $span->meta['connection'] = $job->getConnectionName();
            $span->meta['queue'] = $job->getQueue();
            $span->meta['attempts'] = $job->attempts();
        });

        \DDTrace\trace_method(Dispatcher::class, 'dispatchNow', function (\DDTrace\SpanData $span, $args) {
            $job = $args[0];
            $span->service = 'job';
            $span->name = 'laravel.job';
            $span->resource = class_basename($job);
            if (method_exists($job, 'context')) {
                $context = $job->context();
                if (is_array($context)) {
                    foreach ($context as $key => $value) {
                        if (null !== $value) {
                            $span->meta[$key] = (string) $value;
                        }
                    }
                }
            }
        });

and another one for our cron/command dispatcher but that one is completely custom.

[jaewun]

Sorry for dredging this up but after updating our staging environment, this caused a bit of trouble for us. Just in case anyone comes here trying to figure out how to reduce the insane amount of spans this produces...

\DD_Trace\trace_method('Illuminate\Events\Dispatcher', 'dispatch', function ($span) {

	//$span->resource contains the event name, you can use this 
	//to decide if you want to drop the span and its children
	
    return false;
});

We added some logic in the closure to only drop the noise from Laravel events and keep our own events being tracked. $span->resource holds the event name. As mentioned here it's not perfect but seemed to do the trick for us.

You can choose to drop a span by using returning false from trace_method/trace_function, but there are some issues with it because it effectively orphans (or drops) all its children spans too. If that's a side-effect you can live with (in many cases you can, because they won't make database calls or do anything else that is interesting) then that's your work-around.

[kirkbushell]

Seems to work well :)

It does all of a sudden adds a lot more spans to each process though. People (for example us) wit heavy applications, could have problems reaching the 1000+ spans now or see their datadog bill all of a sudden increase when upgrading the tracer package. good to keep this in mind when adding these things.

Yeah this really needed more thought/planning from the product team. The amount of span noise as a result of this change is immense, and has resulted in us not being able to appropriately diagnose performance issues as a result (due to the truncated trace as we have literally thousands of spans), effectively impacting the power of datadog.

This needs to be addressed holistically. It would be much better if the library allowed us to "opt in" to various trace mechanisms rather than enable them by default.