[BUG] APM data are not sent

Lethgir commented 4 years ago

Describe the bug I setup Datadog to monitor our queues consumers but nothing is received in APM and logs. Our application is containerized and we are using supervisord to maintain php queue consumers alive. The tracer is supposed to send logs to agent in another container.

I already have a working installation but it doesn't use supervisord and works as a web server (php-fpm).

I am able to manually send traces through :

curl datadog-agent:8126/v0.4/traces \
    -X POST \
    -H 'Content-Type: application/json' \
    -d '[[{"span_id":7888852067085145860,"trace_id":8410276558263903151,"parent_id":0,"name":"symfony.request","service":"some_service","type":"web","resource":"/","start":1568281716000000000,"duration":265471}]]'

I added :

DD_TRACE_NO_AUTOLOADER=true
DD_TRACE_URL_AS_RESOURCE_NAMES_ENABLED=true

Since, some logs are sent to datadog but only them about ddtrace (not php application logs).

My env vars :

DD_AGENT_PORT=8126
DD_TRACE_ANALYTICS_ENABLED=true
DD_SERVICE_NAME=supervisord
DD_TRACE_CLI_ENABLED=true
DD_TRACE_ENABLED=true
DD_TRACE_URL_AS_RESOURCE_NAMES_ENABLED=true
DD_INTEGRATIONS_DISABLED=
DD_TRACE_NO_AUTOLOADER=true
DD_AUTOFINISH_SPANS=false
DD_AGENT_HOST=datadog-agent
DD_TRACE_DEBUG=true

Logs from ddtrace :

[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - New span console console recorded.
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Attempting integrations load
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration cakephp
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration curl
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration elasticsearch
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration eloquent
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration guzzle
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration laravel
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration lumen
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Integration memcached not available. New attempts WILL NOT be performed.
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Integration mongo not available. New attempts WILL NOT be performed.
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Integration mysqli not available. New attempts WILL NOT be performed.
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration pdo
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration predis
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration slim
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration symfony
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration web
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration zendframework
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration codeigniter
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration wordpress
[2020-03-26T16:46:11+00:00] [ddtrace] [debug] - Loaded integration yii

PHP Info

Output of php -v

PHP 7.4.4 (cli) (built: Mar 24 2020 01:34:16) ( NTS )
Copyright (c) The PHP Group
Zend Engine v3.4.0, Copyright (c) Zend Technologies
with Zend OPcache v7.4.4, Copyright (c), by Zend Technologies
with blackfire v1.31.0~linux-musl-x64-non_zts74, https://blackfire.io, by Blackfire

Output of php -m


[PHP Modules]
apcu
bcmath
blackfire
bz2
calendar
Core
ctype
curl
date
ddtrace
dom
fileinfo
filter
ftp
hash
iconv
intl
json
libxml
maxminddb
mbstring
mysqlnd
openssl
pcntl
pcre
PDO
pdo_mysql
pdo_sqlite
Phar
posix
readline
redis
Reflection
session
SimpleXML
sodium
SPL
sqlite3
standard
tokenizer
uuid
xml
xmlreader
xmlwriter
xsl
Zend OPcache
zip
zlib

[Zend Modules] Zend OPcache blackfire


**OS Info**

- Output of `cat /etc/os-release | grep -E "(NAME)|(VERSION)"`

NAME="Alpine Linux" ID=alpine VERSION_ID=3.11.5


**Output of dd-doctor**
With `DD_TRACE_NO_AUTOLOADER` and ` DD_TRACE_URL_AS_RESOURCE_NAMES_ENABLED` :

[2020-03-26T16:35:28+00:00] [ddtrace] [debug] - New span dd-doctor.php dd-doctor.php recorded. [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Attempting integrations load [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration cakephp [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration curl [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration elasticsearch [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration eloquent [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration guzzle [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration laravel [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration lumen [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Integration memcached not available. New attempts WILL NOT be performed. [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Integration mongo not available. New attempts WILL NOT be performed. [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Integration mysqli not available. New attempts WILL NOT be performed. [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration pdo [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration predis [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration slim [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration symfony [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration web [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration zendframework [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration codeigniter [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration wordpress [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - Loaded integration yii WARNING: Script is running from the CLI SAPI. Please run this script from your web browser.

DataDog trace extension verification

PHP version and SAPI [7.4.4 - cli]
ddtrace extension installed [OK]
ddtrace version (installed) [0.41.1]
ddtrace version (const) [0.41.1]
ddtrace version (userland) [0.41.1]
ddtrace versions in sync [OK]
dd_trace() function available [OK]
dd_trace_env_config() function available [OK]
ddtrace.request_init_hook set [OK]
ddtrace.request_init_hook reachable [OK]
ddtrace.request_init_hook has run [OK]
'open_basedir' allows access to '/proc/self/' [OK]
IntegrationsLoader exists [OK]
Integrations not loaded yet [FAIL]
Registering an autoloader...
Integrations loaded [OK]
DDTrace\Tracer class exists [OK]
Background sender is enabled? [NO]

You can enable the background sender via DD_TRACE_BETA_SEND_TRACES_VIA_THREAD=true
Configured Agent host [datadog-agent]
Configured Agent port [8126] [2020-03-26T16:35:28+00:00] [ddtrace] [debug] - New span curl_exec curl_exec recorded.
Agent can receive traces [OK]

Without DD_TRACE_NO_AUTOLOADER and DD_TRACE_URL_AS_RESOURCE_NAMES_ENABLED :

WARNING: Script is running from the CLI SAPI.
         Please run this script from your web browser.

DataDog trace extension verification

- PHP version and SAPI                               [7.4.4 - cli]
- ddtrace extension installed                        [OK]
- ddtrace version (installed)                        [0.41.1]
- ddtrace version (const)                            [0.41.1]
- ddtrace version (userland)                         [0.41.1]
- ddtrace versions in sync                           [OK]
- dd_trace() function available                      [OK]
- dd_trace_env_config() function available           [OK]
- ddtrace.request_init_hook set                      [OK]
- ddtrace.request_init_hook reachable                [OK]
- ddtrace.request_init_hook has run                  [OK]
- 'open_basedir' allows access to '/proc/self/'      [OK]
- IntegrationsLoader exists                          [OK]
- Integrations not loaded yet                        [OK]
- Registering an autoloader...
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - New span dd-doctor.php dd-doctor.php recorded.
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Attempting integrations load
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration cakephp
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration curl
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration elasticsearch
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration eloquent
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration guzzle
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration laravel
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration lumen
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Integration memcached not available. New attempts WILL NOT be performed.
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Integration mongo not available. New attempts WILL NOT be performed.
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Integration mysqli not available. New attempts WILL NOT be performed.
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration pdo
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration predis
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration slim
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration symfony
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration web
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration zendframework
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration codeigniter
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration wordpress
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - Loaded integration yii
- Integrations loaded                                [OK]
- DDTrace\Tracer class exists                        [OK]
- Background sender is enabled?                      [NO]
  > You can enable the background sender via
    DD_TRACE_BETA_SEND_TRACES_VIA_THREAD=true
- Configured Agent host                              [datadog-agent]
- Configured Agent port                              [8126]
[2020-03-26T17:02:21+00:00] [ddtrace] [debug] - New span curl_exec curl_exec recorded.
- Agent can receive traces                           [OK]

labbati commented 4 years ago

Hi, thanks for opening this issue. If I understand it correctly you are executing a long running php scripts that runs, as an example, for days and from within there you are consuming a queue and executing some callback.

If this is the case we are currently not supporting this use case. We are currently working on supporting this for similar use cases (e.g. AWS SQS) and we plan to release such support before end of April.

Lethgir commented 4 years ago

Hi, thanks for your answer. I look forward to this update. I would like to understand why you currently can't manage long running php scripts. It would help me to know where I can implement Datadog for now.

We also have scripts executed by cronjob which are not "long" running (shortest about some minutes and longer about 30mn). Do you think I can implement Datadog for them ?

labbati commented 4 years ago

Hi. The specific use case we do not support yet (but we have 1 eng focusing 100% on this, so we expect to support it within a few weeks) CLI processes that are supposed to emit more then 1 trace.

So for example:

"A CLI script that calculates some stats in a DB, send an email via a post request and exit": we support this use case (1 trace including many spans...db, curl etc...)
"A CLI script running a callback at every message in a queue via a while(true) {} :)": you want a trace for every logical operation (which in this case seems to be every time a callback is executed for a new message) we are not currently supporting this scenario and it is what I see landing in a very few weeks
"A web request": we of course support this scenario 100%

Lethgir commented 4 years ago

Hello, I am trying to setup Datadog for CLI script (which access to the database, send an email, output some logs and finish) with the same config than above. My container can communicate with datadog-agent container but it looks like dd-trace does not send data to datadog-agent.

Here logs from my container :

[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - New span console console recorded.
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Attempting integrations load
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration cakephp
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration curl
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration elasticsearch
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration eloquent
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration guzzle
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration laravel
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration lumen
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Integration memcached not available. New attempts WILL NOT be performed.
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Integration mongo not available. New attempts WILL NOT be performed.
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Integration mysqli not available. New attempts WILL NOT be performed.
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration pdo
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration predis
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration slim
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration symfony
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration web
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration zendframework
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration codeigniter
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration wordpress
[2020-04-02T13:17:59+00:00] [ddtrace] [debug] - Loaded integration yii
Command "xxx" starting
<logs>
Command "xxx" ended

How can I debug why dd-trace does not send logs ?

labbati commented 4 years ago

How does your script exit? Maybe an exit() or a die()?

Lethgir commented 4 years ago

We use Symfony Console Command without a specific way to exit, the script ends by itself when its job is done.

vadimiron commented 4 years ago

We also need this feature! Thank you in advance

Bibob7 commented 4 years ago

Hi, whats the current state of this?

SammyK commented 4 years ago

Hey @Lethgir, @vadimiron, and @Bibob7! We recently added support for tracing long-running processes like queue workers/consumers. You can see an example of configuration and code from #834.

Let us know if that helps solve your issue.

Bibob7 commented 4 years ago

Hey @SammyK, thanks for talking care of this. I tested long running processed with the new version 0.44.1 .

My long running process now looks like this:

declare(strict_types=1);
ini_set('display_errors', 'stderr');

require dirname(__DIR__) . '/config/bootstrap.php';

use App\Kernel;
use App\Infrastructure\Grpc\Service\ProductService;
use ShowcaseCatalog\ProductServiceInterface;
use Spiral\RoadRunner;

// This will be the top-level span of the trace
\dd_trace_method(\Spiral\GRPC\ServiceWrapper::class, 'invoke', function (\DDTrace\SpanData $span, array $args) {
    $span->name = 'grpc.request';
    $span->service = 'roadrunner';
    $span->resource = $args[0];
});

$kernel = new Kernel($_SERVER['APP_ENV'], (bool)$_SERVER['APP_DEBUG']);
$kernel->boot();

$server = new \Spiral\GRPC\Server();
$productServiceInterface = ProductServiceInterface::class;
/** @var ProductService $productService */
$productService = $kernel->getContainer()->get($productServiceInterface);
$server->registerService($productServiceInterface, $productService);
$w = new RoadRunner\Worker(new \Spiral\Goridge\StreamRelay(STDIN, STDOUT));
$server->serve($w);

with

DD_TRACE_CLI_ENABLED=true
DD_TRACE_GENERATE_ROOT_SPAN=false
DD_TRACE_AUTO_FLUSH_ENABLED=true

The invoke method is called in a loop of the server class, if a grpc request is received. On dev with debug enabled, is see this:

[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Attempting integrations load
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Loaded integration cakephp
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Loaded integration curl
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Loaded integration elasticsearch
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Loaded integration eloquent
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Integration guzzle not loaded. New attempts might be performed.
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Integration laravel not loaded. New attempts might be performed.
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Loaded integration lumen
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Integration memcached not available. New attempts WILL NOT be performed.
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Integration mongo not available. New attempts WILL NOT be performed.
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Integration mysqli not available. New attempts WILL NOT be performed.
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Loaded integration pdo
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Loaded integration predis
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Loaded integration slim
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Loaded integration symfony
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Loaded integration web
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Loaded integration zendframework
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Integration codeigniter not loaded. New attempts might be performed.
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Loaded integration wordpress
[30-Apr-2020 08:13:12 Europe/Berlin] [2020-04-30T08:13:12+02:00] [ddtrace] [debug] - Loaded integration yii
[30-Apr-2020 08:13:17 Europe/Berlin] [2020-04-30T08:13:17+02:00] [ddtrace] [debug] - Flushing 0 traces, 1 spans
[30-Apr-2020 08:13:17 Europe/Berlin] [2020-04-30T08:13:17+02:00] [ddtrace] [debug] - No finished traces to be sent to the agent
[30-Apr-2020 08:13:17 Europe/Berlin] [2020-04-30T08:13:17+02:00] [ddtrace] [debug] - About to send trace(s) to the agent
[30-Apr-2020 08:13:17 Europe/Berlin] [2020-04-30T08:13:17+02:00] [ddtrace] [debug] - circuit breaker status: closed => , total_failures => 4,consecutive_failures => 4, opened_timestamp => 1777291575, last_failure_timestamp=> 1824553346
[30-Apr-2020 08:13:17 Europe/Berlin] [2020-04-30T08:13:17+02:00] [ddtrace] [error] - Reporting of spans failed: 7 / Failed to connect to localhost port 8126: Connection refused
[30-Apr-2020 08:13:17 Europe/Berlin] [2020-04-30T08:13:17+02:00] [ddtrace] [error] - *   Trying 127.0.0.1:8126...
* TCP_NODELAY set
* connect to 127.0.0.1 port 8126 failed: Connection refused
*   Trying ::1:8126...
* TCP_NODELAY set
* Immediate connect fail for ::1: Address not available
*   Trying ::1:8126...
* TCP_NODELAY set
* Immediate connect fail for ::1: Address not available
* Failed to connect to localhost port 8126: Connection refused
* Closing connection 0

I also added some custom debug output in the flush method. This is what I can see there:

[
  [
    {
      "trace_id": 1844958335553794740,
      "span_id": 1844958335553794740,
      "start": 1588227264126373244,
      "duration": 164302456,
      "name": "grpc.request",
      "resource": "GetProduct",
      "service": "roadrunner",
      "meta": {
        "system.pid": "241"
      }
    }
  ]
]

However in the Datadog ui, I can't see anything.

Edit: Okay, it was my mistake. I used the wrong service name. Now it is working!

SammyK commented 4 years ago

Glad it's working for you now @Bibob7!

@Lethgir @vadimiron I'm going to close this issue since upgrading to the latest version of the tracer supports tracing long-running processes. For more details, check out PR #834. Please feel free to reopen the issue if you're having any trouble with it.

DataDog / dd-trace-php

[BUG] APM data are not sent #805