dd-trace-php
dd-trace-php copied to clipboard
DataDog
[BUG] distributed-tracing-multi not showing individual curl multi requests
As indicated in https://github.com/DataDog/dd-trace-php/issues/1005#issuecomment-784976357
Bug description
Individual requests are not being traced when using distributed-tracing-multi.php:
distributed-tracing.php and distributed-tracing-multi-guzzle.php are showing the individual requests:
This bug also results in my application (using multi curl extensively) not showing individual requests, only the main function call.
PHP version
PHP 7.4.6 (cli) (built: May 14 2020 10:02:18) ( NTS )
Copyright (c) The PHP Group
Zend Engine v3.4.0, Copyright (c) Zend Technologies
with Zend OPcache v7.4.6, Copyright (c), by Zend Technologies
with ddtrace v0.55.0, Copyright Datadog, by Datadog
Installed extensions
[PHP Modules]
calendar
Core
ctype
curl
date
ddtrace
dom
exif
FFI
fileinfo
filter
ftp
gd
gettext
hash
iconv
imagick
json
libxml
mbstring
openssl
pcntl
pcre
PDO
pdo_sqlsrv
Phar
posix
readline
Reflection
session
shmop
SimpleXML
sockets
sodium
SPL
sqlsrv
standard
sysvmsg
sysvsem
sysvshm
tokenizer
xml
xmlreader
xmlwriter
xsl
Zend OPcache
zip
zlib
[Zend Modules]
Zend OPcache
ddtrace
OS info
NAME="Ubuntu"
VERSION="16.04.1 LTS (Xenial Xerus)"
PRETTY_NAME="Ubuntu 16.04.1 LTS"
VERSION_ID="16.04"
UBUNTU_CODENAME=xenial
Diagnostics and configuration
Output of phpinfo() (ddtrace >= 0.47.0)
Thanks for the report and opening a new issue for this @kishanmd. This issue does not seem to affect PHP 8. We'll investigate this further and update this thread with more information.
@SammyK are you sure? I've just installed php8 as a test and I've written a test using Guzzle (guzzlehttp/guzzle ^7.2) to test why I'm not seeing the cURL calls:
PHP -v:
PHP 8.0.2 (cli) (built: Feb 23 2021 15:13:39) ( NTS )
Copyright (c) The PHP Group
Zend Engine v4.0.2, Copyright (c) Zend Technologies
with Zend OPcache v8.0.2, Copyright (c), by Zend Technologies
with ddtrace v0.55.0, Copyright Datadog, by Datadog
The test I wrote:
dd-multi.php
<?php
use GuzzleHttp\Client;
use GuzzleHttp\HandlerStack;
use GuzzleHttp\Handler\CurlMultiHandler;
require __DIR__ . '/vendor/autoload.php';
class MultiDebug
{
public function testMultiAsyncCalls()
{
$curl = new CurlMultiHandler();
$client = new Client(
[
'handler' => HandlerStack::create($curl),
]
);
$posts = [];
$resolver = function ($response) use (&$posts) {
$content = $response->getBody();
$posts[] = json_decode($content, true);
};
$promises = [];
for ($i = 1; $i < mt_rand(10, 50); $i++) {
$promises[] = $client->getAsync("https://jsonplaceholder.typicode.com/posts/$i")->then($resolver);
}
foreach ($promises as $promise) {
$promise->wait();
}
return $posts;
}
}
$debug = new MultiDebug();
$result = $debug->testMultiAsyncCalls();
var_dump($result);
This returns the following output when running DD_TRACE_DEBUG=true DD_TRACE_CLI_ENABLED=true php dd-multi.php
[2021-02-25T17:42:22+01:00] [ddtrace] [debug] - New span dd-multi.php recorded.
[2021-02-25T17:42:22+01:00] [ddtrace] [debug] - Attempting integrations load
[2021-02-25T17:42:22+01:00] [ddtrace] [debug] - Loaded integration web
[2021-02-25T17:42:22+01:00] [ddtrace] [debug] - Loaded integration codeigniter
[2021-02-25T17:42:22+01:00] [ddtrace] [debug] - Loaded integration curl
[2021-02-25T17:42:22+01:00] [ddtrace] [debug] - Loaded integration eloquent
[2021-02-25T17:42:22+01:00] [ddtrace] [debug] - Loaded integration guzzle
Cannot overwrite existing dispatch for 'fire()'
[2021-02-25T17:42:22+01:00] [ddtrace] [debug] - Loaded integration laravel
[2021-02-25T17:42:22+01:00] [ddtrace] [debug] - Integration mysqli not available. New attempts WILL NOT be performed.
array(14) {
// BUNCH_OF_OUTPUT_FROM_API_CALLS
}
[2021-02-25T17:42:22+01:00] [ddtrace] [debug] - Flushing 1 traces, 15 spans
[2021-02-25T17:42:22+01:00] [ddtrace] [debug] - Encoding span '7904251818104689156' op: 'dd-multi.php' serv: 'dd-multi.php' res: 'dd-multi.php' type 'cli'
[2021-02-25T17:42:22+01:00] [ddtrace] [debug] - Tags for span 7904251818104689156 'tag:chars_count' are: system.pid:5
[2021-02-25T17:42:22+01:00] [ddtrace] [debug] - About to send trace(s) to the agent
Successfully memoized Agent HTTP headers
And shows the following under traces:
Am I missing something? It is possible to trace the timings of the underlying cURL calls, even if the server is not on the same machine, correct? So I'm able to see what API calls are being made from the 14 in my test, when they ran in the request (which ran parallel and when), and how long each separate call took, correct?
@kishanmd
It is possible to trace the timings of the underlying cURL calls, even if the server is not on the same machine, correct?
Unfortunately a limitation of distributed tracing via the curl_multi_*() API is that the tracer does not create spans for the curl_multi requests. This means that only requests that are traced will appear in the distributed trace, but requests to third-party sources will not appear. Using your example, traced request do appear in the distributed trace on PHP 8.
Adding spans for curl_multi requests is something we will be addressing in a future release, but I'm not able to provide an ETA of when that will be released at the moment.
The original issue of traced requests on appearing in the distributed trace will be fixed when #1159 is merged and released. Thanks again for the report of this issue, @kishanmd!
@SammyK alright, thank you for clarifying, glad that the issue of the distributed tracing is addressed, I'm looking forward to tracing requests to third parties with curl_multi!
Is there any update on this? Currently I see a lot of holes in the tracing, because it looks like the current guzzle tracing is not picking up anything besides the transfer method call.
There is currently some internal work going on as to enable us to properly trace these. (We will eventually move the implementation of the current CurlIntegration PHP code onto the extension level, which will enable us accessing the full state of the curl request and also fixing this properly.)
This work still needs a couple months to be completed.
We could not prioritize this as we have other priorities. Contributions are welcome, of course.
Hello!
Is there any chance that the issue will be prioritized?
It's currently quite problematic to monitor Symfony traces with the CurlHttpClient usage.
Hey @FlorianBaba,
The work on the pre-requirements (concretely an internal SDK for internally instrumenting) is still prioritized. We may prioritize this once these are done. This will still take a while though.
Also have this issue, we can't monitor Symfony when it calls out to external APIs.
Using latest dd trace.
php datadog-setup.php --php-bin=all --enable-appsec --enable-profiling
Cannot load Zend OPcache - it was already loaded
Searching for available php binaries, this operation might take a while.
Downloading installable archive from https://github.com/DataDog/dd-trace-php/releases/download/0.84.0/dd-library-php-0.84.0-x86_64-linux-gnu.tar.gz.
It's possible to see the issue using some simple code snippets.
Using this code.
<?php
$ch = curl_init('https://httpbin.org/delay/1');
curl_exec($ch);
?>
Generates:
Using this code.
<?php
// create both cURL resources
$ch1 = curl_init();
$ch2 = curl_init();
// set URL and other appropriate options
curl_setopt($ch1, CURLOPT_URL, "https://httpbin.org/delay/1");
curl_setopt($ch1, CURLOPT_HEADER, 0);
curl_setopt($ch2, CURLOPT_URL, "https://httpbin.org/delay/2");
curl_setopt($ch2, CURLOPT_HEADER, 0);
//create the multiple cURL handle
$mh = curl_multi_init();
//add the two handles
curl_multi_add_handle($mh,$ch1);
curl_multi_add_handle($mh,$ch2);
$active = null;
//execute the handles
do {
$mrc = curl_multi_exec($mh, $active);
} while ($mrc == CURLM_CALL_MULTI_PERFORM);
while ($active && $mrc == CURLM_OK) {
if (curl_multi_select($mh) != -1) {
do {
$mrc = curl_multi_exec($mh, $active);
} while ($mrc == CURLM_CALL_MULTI_PERFORM);
}
}
//close the handles
curl_multi_remove_handle($mh, $ch1);
curl_multi_remove_handle($mh, $ch2);
curl_multi_close($mh);
?>
Generates this trace
I thought a bit today about how exactly to implement it (given all pre-requisite APIs like install_hook are present now).
With #2347, this now generates a trace like:
