[Bug]: _generated_tracer.php crashes with php-amqplib integration enabled

[CatoTH]

Bug report

We tried upgrading dd-trace-php and the PHP extension from an older version (0.79.0) to one of the more recent versions (we tried 0.88.1, 0.89.0 and 0.90.0). After this update, our php-amqplib rabbitmq-workers are crashing once a message actually comes in. We are getting the following stacktrace:

[2023-07-10T10:23:59+02:00] [ddtrace] [warning] - The span with name 'console' was closed without being finished first.
Argument 1 passed to DDTrace\Span::__construct() must be an instance of DDTrace\SpanData, null given, called in /opt/datadog/dd-library/0.89.0/dd-trace-sources/bridge/_generated_tracer.php on line 873
#0 /opt/datadog/dd-library/0.89.0/dd-trace-sources/bridge/_generated_tracer.php(873): DDTrace\Span->__construct(NULL, Object(DDTrace\SpanContext))
#1 /opt/datadog/dd-library/0.89.0/dd-trace-sources/bridge/_generated_tracer.php(813): DDTrace\ScopeManager->reconcileInternalAndUserland()
#2 /opt/datadog/dd-library/0.89.0/dd-trace-sources/bridge/_generated_tracer.php(1061): DDTrace\ScopeManager->getActive()
#3 /app/src/Application/Monolog/DatadogProcessor.php(32): DDTrace\Tracer->getActiveSpan()
#4 [internal function]: Application\Monolog\DatadogProcessor->__invoke(Array)
#5 /app/vendor/monolog/monolog/src/Monolog/Logger.php(340): call_user_func(Object(Application\Monolog\DatadogProcessor), Array)
#6 /app/vendor/monolog/monolog/src/Monolog/Logger.php(642): Monolog\Logger->addRecord(200, 'Executed comman...', Array)
#7 /app/src/#####CommandRunner.php(61): Monolog\Logger->info('Executed comman...', Array)
#8 /app/src/#####Consumer.php(29): #####CommandRunner->run('#####...', Array, '{"id":"90000000...', 60)
#9 /app/src/#####Consumer.php(50): #####Consumer->handle(Object(PhpAmqpLib\Message\AMQPMessage))
#10 [internal function]: #####Consumer->execute(Object(PhpAmqpLib\Message\AMQPMessage))
#11 /app/vendor/php-amqplib/rabbitmq-bundle/RabbitMq/Consumer.php(133): call_user_func(Array, Object(PhpAmqpLib\Message\AMQPMessage))
#12 /app/vendor/php-amqplib/rabbitmq-bundle/RabbitMq/Consumer.php(179): OldSound\RabbitMqBundle\RabbitMq\Consumer->processMessageQueueCallback(Object(PhpAmqpLib\Message\AMQPMessage), '#####...', Array)
#13 [internal function]: OldSound\RabbitMqBundle\RabbitMq\Consumer->processMessage(Object(PhpAmqpLib\Message\AMQPMessage))
#14 /app/vendor/php-amqplib/php-amqplib/PhpAmqpLib/Channel/AMQPChannel.php(1044): call_user_func(Array, Object(PhpAmqpLib\Message\AMQPMessage))
#15 [internal function]: PhpAmqpLib\Channel\AMQPChannel->basic_deliver(Object(PhpAmqpLib\Wire\AMQPReader), Object(PhpAmqpLib\Message\AMQPMessage))
#16 /app/vendor/php-amqplib/php-amqplib/PhpAmqpLib/Channel/AbstractChannel.php(220): call_user_func(Array, Object(PhpAmqpLib\Wire\AMQPReader), Object(PhpAmqpLib\Message\AMQPMessage))
#17 /app/vendor/php-amqplib/php-amqplib/PhpAmqpLib/Channel/AbstractChannel.php(374): PhpAmqpLib\Channel\AbstractChannel->dispatch('60,60', '8PHPPROCESS_sta...', Object(PhpAmqpLib\Message\AMQPMessage))
#18 /app/vendor/php-amqplib/rabbitmq-bundle/RabbitMq/Consumer.php(88): PhpAmqpLib\Channel\AbstractChannel->wait(NULL, false, 599)
#19 /app/vendor/php-amqplib/rabbitmq-bundle/Command/BaseConsumerCommand.php(90): OldSound\RabbitMqBundle\RabbitMq\Consumer->consume(0)
#20 /app/vendor/symfony/console/Command/Command.php(255): OldSound\RabbitMqBundle\Command\BaseConsumerCommand->execute(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#21 /app/vendor/symfony/console/Application.php(1010): Symfony\Component\Console\Command\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#22 /app/vendor/symfony/framework-bundle/Console/Application.php(86): Symfony\Component\Console\Application->doRunCommand(Object(OldSound\RabbitMqBundle\Command\ConsumerCommand), Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#23 /app/vendor/symfony/console/Application.php(255): Symfony\Bundle\FrameworkBundle\Console\Application->doRunCommand(Object(OldSound\RabbitMqBundle\Command\ConsumerCommand), Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#24 /app/vendor/symfony/framework-bundle/Console/Application.php(74): Symfony\Component\Console\Application->doRun(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#25 /app/vendor/symfony/console/Application.php(148): Symfony\Bundle\FrameworkBundle\Console\Application->doRun(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput))
#26 /app/app/console(51): Symfony\Component\Console\Application->run(Object(Symfony\Component\Console\Input\ArgvInput))
#27 {main}
[2023-07-10T10:23:59+02:00] [ddtrace] [warning] - The span with name 'console' was closed without being finished first.
Notifying profiler of finished local root span.
Flushing trace of size 16 to send-queue for http://####:8126

(That particular stacktrace was done with 0.89.0, but the same happened with a version earlier and later).

The exception does not happen anymore if we set the environment variable DD_TRACE_AMQP_ENABLED=0 , hence we guess the new php-amqplib integration might be triggering this behaviour.

PHP version

7.4.28

Tracer or profiler version

0.90.0

Installed extensions

[PHP Modules]
apcu
bcmath
Core
ctype
curl
datadog-profiling
date
ddappsec
ddtrace
dom
fileinfo
filter
ftp
gd
hash
iconv
igbinary
intl
json
libxml
mbstring
mysqlnd
openssl
pcntl
pcre
PDO
pdo_mysql
pdo_sqlite
Phar
posix
readline
Reflection
session
SimpleXML
sockets
sodium
SPL
sqlite3
standard
timezonedb
tokenizer
xml
xmlreader
xmlwriter
Zend OPcache
zip
zlib

[Zend Modules]
Zend OPcache
datadog-profiling
ddappsec
ddtrace

Output of phpinfo()

{ "date": "2023-07-19T12:49:40Z", "os_name": "Linux staging-stg1-######.x86_64 #1 SMP Wed Mar 15 00:26:42 UTC 2023 x86_64", "os_version": "######.x86_64", "version": "0.90.0", "lang": "php", "lang_version": "7.4.33", "env": "stg", "enabled": true, "service": "######", "enabled_cli": true, "agent_url": "http://######", "debug": false, "analytics_enabled": false, "sample_rate": 1, "sampling_rules": [ { "sample_rate": 0.01 } ], "tags": [], "service_mapping": { "pdo": "######", "redis": "######" }, "distributed_tracing_enabled": true, "priority_sampling_enabled": true, "dd_version": "53e1c410101951e39d822fcd4e04718307a5bc78", "architecture": "x86_64", "sapi": "fpm-fcgi", "datadog.trace.request_init_hook": "/opt/datadog/dd-library/0.90.0/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": false, "generate_root_span": true, "http_client_split_by_domain": true, "measure_compile_time": true, "report_hostname_on_root_span": false, "traced_internal_functions": null, "auto_prepend_file_configured": false, "integrations_disabled": "default", "enabled_from_env": true, "opcache.file_cache": null }

Upgrading from

0.79.0

[PROFeNoM]

Hi Tobias,

For now, it is not obvious to me what the problem is, and I will keep searching...

However, would it be possible for you to change the manual instrumentation you are doing in your DatadogProcessor to use the modern API instead of the legacy one to see whether there is still an issue of some kind? You can retrieve the active span using \DDTrace\active_span() (Doc, stub). If you need any help, please do not hesitate!

Thanks

[PROFeNoM]

Just a quick update on this @CatoTH, I've been trying to reproduce the issue from the information I can get from the stack trace (i.e., a symfony app with php-amqplib/rabbitmq-bundle and monolog/monolog where the active span is retrieved with the legacy API in a processor during the logging of a message as part of the callback of a delivered AMQPMessage), but I think I'll need more information on the operations you are doing. More specifically, could you please tell me if you are opening/finishing any span and how? If you have a small reproducer, well, that's even better 😃

[CatoTH]

So there is one spot that is somewhat curious here. In app/console, we are overwriting the resource name to include the RabbitMQ queue name. That's most likely not the most elegant way to solve that.

if (class_exists('\DDTrace\GlobalTracer')) {
    $span = \DDTrace\GlobalTracer::get()->getActiveSpan();
    if ($span) {
        $commandName = $input->getFirstArgument();
        if ($commandName === 'rabbitmq:consumer' && isset($_SERVER['argv'][2])) {
            $commandName .= '#' . $_SERVER['argv'][2];
        }
        $span->setTag('command_name', $commandName);
        $span->setResource($commandName);
    }
}

I assume, here, \DDTrace\active_span() would be more appropriate then, too?

As for DatadogProcessor.php, it's

<?php

declare(strict_types=1);

namespace Application\Monolog;

use DDTrace\GlobalTracer;

class DatadogProcessor
{
    private bool $isDatadogEnabled;

    public function __construct()
    {
        $this->isDatadogEnabled = function_exists('dd_trace_peek_span_id') && class_exists(GlobalTracer::class);
    }

    /**
     * @param array<mixed> $record
     *
     * @return array<mixed>
     */
    public function __invoke(array $record): array
    {
        if (!$this->isDatadogEnabled) {
            return $record;
        }

        $span = \DDTrace\GlobalTracer::get()->getActiveSpan();
        if (null === $span) {
            return $record;
        }

        $record['dd'] = [
            'trace_id' => $span->getTraceId(),
            'span_id' => \dd_trace_peek_span_id(),
        ];

        return $record;
    }
}

I can try if using \DDTrace\active_span() (and \DDTrace\trace_id(), probably) helps. Won't have a result before later tomorrow though, as testing it takes some time unfortunately

[PROFeNoM]

Thanks for these snippets!

You are absolutely right. Replacing \DDTrace\GlobalTracer::get()->getActiveSpan(); by \DDTrace\active_span() and $span->getTraceId() by \DDTrace\trace_id() should do it there 👍

Similarly/If needed, you may try replacing with the following in your app/console:

$span = \DDTrace\active_span();
if ($span) {
    $commandName = $input->getFirstArgument();
    if ($commandName === 'rabbitmq:consumer' && isset($_SERVER['argv'][2])) {
        $commandName .= '#' . $_SERVER['argv'][2];
    }
    $span->meta['command_name'] = $commandName;
    $span->resource = $commandName;
}

[CatoTH]

So at first glance / a first test, it indeed looks like using the new calls the problem does not appear anymore.
I do see that you still fixed an issue maybe related to this in #2177, so maybe we are going to wait for 0.91.0 anyway before upgrading (on top of the mentioned changes), just to be on the safe side.
Thank you for your help!

[CatoTH]

Hi,
so we installed 0.91.1, and this appears to have fixed the issue. Thanks a lot!