DataDog
[BUG] Can hook into method, but span is not updated
Bug description
hello everyone,
we've got the following use case:
we trace the handleMessage method of the Symfony Messenger component. handleMessage() does not throw any errors, but rather dispatches events on failures. we want to hook on those events and mark the current span as an error.
after trying out different things we ended up with the following solution:
write a trace_method callback for tracing the handle_message() write hook_method for dispatchEvent() to mark span as error every time a Failure Event gets dispatched
the result is weird - we can see that the hook_method callback gets called, but the span does not get the error attached. we've built a workaround (tracing both methods with trace_method), but would like to stick to the above approach if possible.
any ideas?
please find the code below:
<?php
use Symfony\Component\Messenger\Exception\HandlerFailedException;
function initTracing()
{
$spanData = null;
if (function_exists('\DDTrace\trace_method') === false) {
return;
}
if (function_exists('\DDTrace\hook_method') === false) {
return;
}
if (function_exists('\ddtrace_config_app_name') === false) {
return;
}
\DDTrace\trace_method(
'Symfony\Component\Messenger\Worker',
'handleMessage',
function (\DDTrace\SpanData $span, $args) use (&$spanData) {
echo "setting";
/** @var \Symfony\Component\Messenger\Envelope $envelope */
$envelope = $args[0];
$messageName = (new ReflectionClass($envelope->getMessage()))->getShortName();
$span->name = 'symfony.messenger';
$span->resource = "MessageHandler#{$messageName}";
$span->service = \ddtrace_config_app_name('symfony');
$spanData = $span;
}
);
\DDTrace\hook_method(
'Symfony\Component\Messenger\Worker',
'dispatchEvent',
function ($worker, $_, $args) use (&$spanData) {
if (($spanData instanceof \DDTrace\SpanData) === false) {
return;
}
$event = $args[0];
if ($event instanceof \Symfony\Component\Messenger\Event\WorkerMessageFailedEvent) {
$exception = $event->getThrowable();
echo "tracing error"
if ($exception instanceof HandlerFailedException) {
$exception = $exception->getNestedExceptions()[0];
}
$spanData->meta['error.msg'] = $exception->getMessage();
$spanData->meta['error.type'] = get_class($exception);
$spanData->meta['error.stack'] = $exception->getTraceAsString();
}
}
);
}
initTracing();
PHP version
PHP 7.4.12 (cli) (built: Nov 18 2020 09:41:41) ( NTS ) Copyright (c) The PHP Group Zend Engine v3.4.0, Copyright (c) Zend Technologies with Zend OPcache v7.4.12, Copyright (c), by Zend Technologies with ddtrace v0.50.0, Copyright Datadog, by Datadog
Installed extensions
[PHP Modules]
amqp
apcu
Core
ctype
curl
date
ddtrace
dom
fileinfo
filter
ftp
hash
iconv
json
libxml
mbstring
mongodb
mysqlnd
openssl
pcntl
pcre
PDO
pdo_sqlite
Phar
posix
readline
Reflection
session
SimpleXML
sodium
SPL
sqlite3
standard
tokenizer
xml
xmlreader
xmlwriter
Zend OPcache
zlib
[Zend Modules]
Zend OPcache
ddtrace
OS info
PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster
Diagnostics and configuration
Output of phpinfo() (ddtrace >= 0.47.0)
Datadog tracing support => enabled
Version => 0.50.0
DATADOG TRACER CONFIGURATION => {"date":"2020-11-26T08:38:18Z","os_name":"Linux voucher-service-message-consumer-765fb54698-8z4h6 4.14.203-156.332.amzn2.x86_64 #1 SMP Fri Oct 30 19:19:33 UTC 2020 x86_64","os_version":"4.14.203-156.332.amzn2.x86_64","version":"0.50.0","lang":"php","lang_version":"7.4.2","env":"stg","enabled":true,"service":"fxt.webc.book.voucher_service","enabled_cli":true,"agent_url":"http://datadogstatsd.monitoring:8126","debug":false,"analytics_enabled":true,"sample_rate":1.000000,"sampling_rules":null,"tags":null,"service_mapping":null,"distributed_tracing_enabled":true,"priority_sampling_enabled":true,"dd_version":null,"architecture":"x86_64","sapi":"cli","ddtrace.request_init_hook":"/opt/datadog-php/dd-trace-sources/bridge/dd_wrap_autoloader.php","open_basedir_configured":false,"uri_fragment_regex":null,"uri_mapping_incoming":null,"uri_mapping_outgoing":null,"auto_flush_enabled":true,"generate_root_span":false,"http_client_split_by_domain":false,"measure_compile_time":true,"report_hostname_on_root_span":false,"traced_internal_functions":null,"auto_prepend_file_configured":false,"integrations_disabled":null,"enabled_from_env":true,"opcache.file_cache":null}
Diagnostic checks => passed
Directive => Local Value => Master Value
ddtrace.disable => Off => Off
ddtrace.request_init_hook => /opt/datadog-php/dd-trace-sources/bridge/dd_wrap_autoloader.php => /opt/datadog-php/dd-trace-sources/bridge/dd_wrap_autoloader.php
👋 @stanislau93! You have a very interesting use case here so I'd like to make sure I understand what you're trying to achieve.
You have an instance of Symfony\Component\Messenger\Worker and have a custom instrumentation for Worker::handleMessage(). When Worker::dispatchEvent() is invoked, it could contain an error event from Worker::handleMessage() which will always be an instance of WorkerMessageFailedEvent. You would like to mark the span created from Worker::handleMessage() as an error span in this case.
Did I get that right? If so, at the moment it is not possible. However, we will be introducing a new API in the coming months that will allow you to access the active span that was generated from DDTrace\trace_method(). That API should give you access to the active span from DDTrace\hook_method() so that you can attach the error metadata to it.
I'll change the label to "feature request" and will follow up here again when the API is ready.
@stanislau93 I was thinking about your solution a bit more and thought of a workaround that you might be able to use until we release the active-span API. If you run the tracing closure for Worker::handleMessage as a prehook, that will make sure $spanData is set before the Worker::dispatchEvent is called.
\DDTrace\trace_method(
'Symfony\Component\Messenger\Worker',
'handleMessage',
['prehook' => function (\DDTrace\SpanData $span, $args) use (&$spanData) {
// ...
}]
);
Does that temporary workaround solve the issue for you?
Hello @SammyK ,
Many thanks for your attention to the issue!
You get the issue absolutely correctly. We will try out your workaround once we come to it. Thanks again!