search

DataDog / dd-trace-php

Datadog PHP Clients
https://docs.datadoghq.com/tracing/setup/php
Other
486 stars 151 forks source link

[BUG] BC break with GlobalTracer custom instrumentation #1882

Closed B-Galati closed 1 year ago

B-Galati commented 1 year ago

Hello!

Bug description

I tried to upgrade from v0.75.0 to v0.83.1 and I observed some changes in Datadog UI. Some custom span are not reported anymore with Symfony Messenger Worker (a long running PHP process with PHP CLI).

Custom variables used for that worker are:

:point_right: This is what is advised in the doc for long running processes.

Here is the code that was working with 0.75.0:

:point_right: DatadogMessengerWorkerListener.php ```php shouldHandle()) { return; } $this->span = GlobalTracer::get()->startSpan('symfony.messenger.worker'); $this->span->setResource(\get_class($event->getEnvelope()->getMessage())); $this->span->setTag(Tag::SERVICE_NAME, dd_trace_env_config('DD_SERVICE')); $this->span->setTag(Tag::SPAN_TYPE, Type::MESSAGE_CONSUMER); } public function onMessageHandled(WorkerMessageHandledEvent $event): void { if (null === $this->span) { return; } $this->span->finish(); $this->span = null; } public function onMessageFailed(WorkerMessageFailedEvent $event): void { if (null === $this->span) { return; } $this->span->setError($event->getThrowable()); $this->span->finish(); $this->span = null; } /** * {@inheritdoc} */ public static function getSubscribedEvents(): array { return [ WorkerMessageReceivedEvent::class => 'onMessageReceived', WorkerMessageHandledEvent::class => 'onMessageHandled', WorkerMessageFailedEvent::class => 'onMessageFailed', ]; } } ```
:point_right: ConsoleCommandListener.php ```php ['onConsoleCommand', 0], ConsoleEvents::TERMINATE => ['onConsoleTerminate', 0], ]; } public function onConsoleCommand(ConsoleCommandEvent $event): void { $command = $event->getCommand(); if (null === $command || !self::isTraceable()) { return; } $scope = GlobalTracer::get()->startRootSpan('symfony.console.command'); $span = $scope->getSpan(); $span->setResource(\get_class($command)); $span->setTag(Tag::SERVICE_NAME, dd_trace_env_config('DD_SERVICE')); if ($command instanceof ConsumeMessagesCommand) { $span->setTag(Tag::SPAN_TYPE, Type::MESSAGE_CONSUMER); } else { $span->setTag(Tag::SPAN_TYPE, Type::CLI); } $input = $event->getInput(); $this->addOptionsAsTags($input, $span); $this->addArgumentsAsTags($input, $span); } public function onConsoleTerminate(ConsoleTerminateEvent $event): void { $scope = GlobalTracer::get()->getRootScope(); if (null === $scope || !self::isTraceable()) { return; } $span = $scope->getSpan(); $span->setTag('exit_code', $event->getExitCode()); $scope->close(); } private function addOptionsAsTags(InputInterface $input, Span $span): void { foreach ($input->getOptions() as $optionName => $optionValue) { if (\is_array($optionValue)) { foreach ($optionValue as $key => $value) { $span->setTag('options.'.$optionName.'.'.$key, $value); } } else { $span->setTag('options.'.$optionName, $optionValue); } } } private function addArgumentsAsTags(InputInterface $input, Span $span): void { foreach ($input->getArguments() as $argumentName => $argumentValue) { if (\is_array($argumentValue)) { foreach ($argumentValue as $key => $value) { $span->setTag('arguments.'.$argumentName.'.'.$key, $value); } } else { $span->setTag('arguments.'.$argumentName, $argumentValue); } } } private static function isTraceable(): bool { return 'cli' === \PHP_SAPI && \extension_loaded('ddtrace'); } } ```
:point_right: DatadogMiddleware.php ```php next()->handle($envelope, $stack); } // Do not record a new span for messages consumed by worker because // they are going to be managed by DatadogMessengerWorkerListener if ($this->isMessageConsumedByWorker($envelope)) { return $stack->next()->handle($envelope, $stack); } $scope = GlobalTracer::get()->startActiveSpan('symfony.messenger.handle'); $span = $scope->getSpan(); $span->setResource(\get_class($envelope->getMessage())); $span->setTag(Tag::SERVICE_NAME, dd_trace_env_config('DD_SERVICE')); try { return $stack->next()->handle($envelope, $stack); } catch (\Throwable $e) { $span->setError($e); throw $e; } finally { $scope->close(); } } private function isMessageConsumedByWorker(Envelope $envelope): bool { return null !== $envelope->last(ConsumedByWorkerStamp::class); } } ```

The lifecycle is as follow when starting up a worker:

  1. ConsoleCommandListener is triggered
  2. DatadogMessengerWorkerListener is triggered for each consumed message
  3. For each consumed message, DatadogMiddleware may be triggerred 0 or more times
  4. After some times, 4 minutes for me, the worker command stops and the command span is finished.

And since I upgrade to v0.83.1 there is no more trace symfony.messenger.worker (Sometimes it appears in case of error attached to the span).

Let me know for anything that can help, thanks!

PHP version

$ php -v
PHP 8.1.14 (cli) (built: Jan 13 2023 10:43:22) (NTS)
Copyright (c) The PHP Group
Zend Engine v4.1.14, Copyright (c) Zend Technologies
    with Zend OPcache v8.1.14, Copyright (c), by Zend Technologies
    with blackfire v1.86.3~linux-x64-non_zts81, https://blackfire.io, by Blackfire
    with ddtrace v0.83.1, Copyright Datadog, by Datadog
    with datadog-profiling v0.12.0, Copyright Datadog, by Datadog
    with ddappsec v0.4.5, Copyright Datadog, by Datadog

Tracer version

$ php -r "echo phpversion('ddtrace').PHP_EOL;"
0.83.1

Installed extensions

Expand ``` $ php -m [PHP Modules] amqp apcu bcmath blackfire calendar Core ctype curl datadog-profiling date ddappsec ddtrace dom exif FFI fileinfo filter ftp gd gettext hash iconv igbinary imagick intl json libxml mbstring mysqli mysqlnd openssl pcntl pcre PDO pdo_mysql pdo_pgsql pdo_sqlite pgsql Phar posix readline redis Reflection session shmop SimpleXML soap sockets sodium SPL sqlite3 standard sysvmsg sysvsem sysvshm tokenizer xml xmlreader xmlwriter xsl Zend OPcache zip zlib [Zend Modules] Zend OPcache blackfire datadog-profiling ddappsec ddtrace ```

OS info

$ cat /etc/os-release | grep -E "(NAME)|(VERSION)"
NAME="Ubuntu"
VERSION="20.04.5 LTS (Focal Fossa)"
PRETTY_NAME="Ubuntu 20.04.5 LTS"
VERSION_ID="20.04"
VERSION_CODENAME=focal
UBUNTU_CODENAME=focal

Diagnostics and configuration

Expand ``` $ php --ri=ddtrace ddtrace Datadog PHP tracer extension For help, check out the documentation at https://docs.datadoghq.com/tracing/languages/php/ (c) Datadog 2020 Datadog tracing support => disabled Version => 0.83.1 DATADOG TRACER CONFIGURATION => { "date": "2023-01-25T09:27:11Z", "os_name": "Linux some 4.15.0-192-generic #203-Ubuntu SMP Wed Aug 10 17:40:03 UTC 2022 x86_64", "os_version": "4.15.0-192-generic", "version": "0.83.1", "lang": "php", "lang_version": "8.1.8", "env": "multitesting", "enabled": true, "enabled_cli": false, "agent_url": "http:\/\/datadog:8888", "debug": false, "analytics_enabled": false, "sample_rate": 1, "sampling_rules": [], "distributed_tracing_enabled": true, "priority_sampling_enabled": true, "dd_version": "sha_82405523", "architecture": "x86_64", "sapi": "cli", "datadog.trace.request_init_hook": "\/opt\/datadog\/dd-library\/0.83.1\/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": false, "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": false, "opcache.file_cache": null } Directive => Local Value => Master Value ddtrace.disable => Off => Off ddtrace.cgroup_file => /proc/self/cgroup => /proc/self/cgroup datadog.trace.request_init_hook => /opt/datadog/dd-library/0.83.1/dd-trace-sources/bridge/dd_wrap_autoloader.php => /opt/datadog/dd-library/0.83.1/dd-trace-sources/bridge/dd_wrap_autoloader.php ddtrace.request_init_hook => /opt/datadog/dd-library/0.83.1/dd-trace-sources/bridge/dd_wrap_autoloader.php => /opt/datadog/dd-library/0.83.1/dd-trace-sources/bridge/dd_wrap_autoloader.php datadog.trace.agent_url => no value => no value datadog.agent_host => datadog => datadog datadog.dogstatsd_url => no value => no value datadog.distributed_tracing => On => On datadog.dogstatsd_port => 8888 => 8888 datadog.env => multitesting => multitesting datadog.autofinish_spans => Off => Off datadog.trace.url_as_resource_names_enabled => On => On datadog.integrations_disabled => default => default datadog.priority_sampling => On => On datadog.trace.agent_port => 8126 => 8126 datadog.trace.analytics_enabled => Off => Off datadog.trace.auto_flush_enabled => Off => Off datadog.trace.cli_enabled => Off => Off datadog.trace.measure_compile_time => On => On datadog.trace.debug => Off => Off datadog.trace.enabled => Off => On datadog.trace.health_metrics_enabled => Off => Off datadog.trace.health_metrics_heartbeat_sample_rate => 0.001 => 0.001 datadog.trace.db_client_split_by_instance => Off => Off datadog.trace.http_client_split_by_domain => Off => Off datadog.trace.redis_client_split_by_host => Off => Off datadog.trace.memory_limit => no value => no value datadog.trace.report_hostname => Off => Off datadog.trace.resource_uri_fragment_regex => no value => no value datadog.trace.resource_uri_mapping_incoming => no value => no value datadog.trace.resource_uri_mapping_outgoing => no value => no value datadog.trace.resource_uri_query_param_allowed => no value => no value datadog.trace.http_url_query_param_allowed => * => * datadog.trace.rate_limit => 0 => 0 datadog.trace.sample_rate => 1 => 1 datadog.sampling_rate => 1 => 1 datadog.trace.sampling_rules => [] => [] datadog.span_sampling_rules => [] => [] datadog.span_sampling_rules_file => no value => no value datadog.trace.header_tags => no value => no value datadog.trace.x_datadog_tags_max_length => 512 => 512 datadog.trace.propagate_service => Off => Off datadog.propagation_style_extract => Datadog,B3,B3 single header => Datadog,B3,B3 single header datadog.propagation_style_inject => Datadog => Datadog datadog.trace.traced_internal_functions => no value => no value datadog.trace.agent_timeout => 500 => 500 datadog.trace.agent_connect_timeout => 100 => 100 datadog.trace.debug_prng_seed => -1 => -1 datadog.log_backtrace => Off => Off datadog.trace.generate_root_span => On => On datadog.trace.spans_limit => 1000 => 1000 datadog.trace.agent_max_consecutive_failures => 3 => 3 datadog.trace.agent_attempt_retry_time_msec => 5000 => 5000 datadog.trace.bgs_connect_timeout => 2000 => 2000 datadog.trace.bgs_timeout => 5000 => 5000 datadog.trace.agent_flush_interval => 5000 => 5000 datadog.trace.agent_flush_after_n_requests => 10 => 10 datadog.trace.shutdown_timeout => 5000 => 5000 datadog.trace.startup_logs => On => On datadog.trace.agent_debug_verbose_curl => Off => Off datadog.trace.debug_curl_output => Off => Off datadog.trace.beta_high_memory_pressure_percent => 80 => 80 datadog.trace.warn_legacy_dd_trace => On => On datadog.trace.retain_thread_capabilities => Off => Off datadog.version => sha_82405523 => sha_82405523 datadog.trace.obfuscation_query_string_regexp => (?i)(?:p(?:ass)?w(?:or)?d|pass(?:_?phrase)?|secret|(?:api_?|private_?|public_?|access_?|secret_?)key(?:_?id)?|token|consumer_?(?:id|key|secret)|sign(?:ed|ature)?|auth(?:entication|orization)?)(?:(?:\s|%20)*(?:=|%3D)[^&]+|(?:"|%22)(?:\s|%20)*(?::|%3A)(?:\s|%20)*(?:"|%22)(?:%2[^2]|%[^2]|[^"%])+(?:"|%22))|bearer(?:\s|%20)+[a-z0-9\._\-]|token(?::|%3A)[a-z0-9]{13}|gh[opsu]_[0-9a-zA-Z]{36}|ey[I-L](?:[\w=-]|%3D)+\.ey[I-L](?:[\w=-]|%3D)+(?:\.(?:[\w.+\/=-]|%3D|%2F|%2B)+)?|[\-]{5}BEGIN(?:[a-z\s]|%20)+PRIVATE(?:\s|%20)KEY[\-]{5}[^\-]+[\-]{5}END(?:[a-z\s]|%20)+PRIVATE(?:\s|%20)KEY|ssh-rsa(?:\s|%20)*(?:[a-z0-9\/\.+]|%2F|%5C|%2B){100,} => (?i)(?:p(?:ass)?w(?:or)?d|pass(?:_?phrase)?|secret|(?:api_?|private_?|public_?|access_?|secret_?)key(?:_?id)?|token|consumer_?(?:id|key|secret)|sign(?:ed|ature)?|auth(?:entication|orization)?)(?:(?:\s|%20)*(?:=|%3D)[^&]+|(?:"|%22)(?:\s|%20)*(?::|%3A)(?:\s|%20)*(?:"|%22)(?:%2[^2]|%[^2]|[^"%])+(?:"|%22))|bearer(?:\s|%20)+[a-z0-9\._\-]|token(?::|%3A)[a-z0-9]{13}|gh[opsu]_[0-9a-zA-Z]{36}|ey[I-L](?:[\w=-]|%3D)+\.ey[I-L](?:[\w=-]|%3D)+(?:\.(?:[\w.+\/=-]|%3D|%2F|%2B)+)?|[\-]{5}BEGIN(?:[a-z\s]|%20)+PRIVATE(?:\s|%20)KEY[\-]{5}[^\-]+[\-]{5}END(?:[a-z\s]|%20)+PRIVATE(?:\s|%20)KEY|ssh-rsa(?:\s|%20)*(?:[a-z0-9\/\.+]|%2F|%5C|%2B){100,} datadog.trace.forked_process => On => On datadog.trace.agent_max_payload_size => 52428800 => 52428800 datadog.trace.agent_stack_initial_size => 131072 => 131072 datadog.trace.agent_stack_backlog => 12 => 12 datadog.trace.cakephp_enabled => On => On datadog.trace.cakephp_analytics_enabled => Off => Off datadog.cakephp_analytics_enabled => Off => Off datadog.trace.cakephp_analytics_sample_rate => 1 => 1 datadog.cakephp_analytics_sample_rate => 1 => 1 datadog.trace.codeigniter_enabled => On => On datadog.trace.codeigniter_analytics_enabled => Off => Off datadog.codeigniter_analytics_enabled => Off => Off datadog.trace.codeigniter_analytics_sample_rate => 1 => 1 datadog.codeigniter_analytics_sample_rate => 1 => 1 datadog.trace.curl_enabled => On => On datadog.trace.curl_analytics_enabled => Off => Off datadog.curl_analytics_enabled => Off => Off datadog.trace.curl_analytics_sample_rate => 1 => 1 datadog.curl_analytics_sample_rate => 1 => 1 datadog.trace.elasticsearch_enabled => On => On datadog.trace.elasticsearch_analytics_enabled => Off => Off datadog.elasticsearch_analytics_enabled => Off => Off datadog.trace.elasticsearch_analytics_sample_rate => 1 => 1 datadog.elasticsearch_analytics_sample_rate => 1 => 1 datadog.trace.eloquent_enabled => On => On datadog.trace.eloquent_analytics_enabled => Off => Off datadog.eloquent_analytics_enabled => Off => Off datadog.trace.eloquent_analytics_sample_rate => 1 => 1 datadog.eloquent_analytics_sample_rate => 1 => 1 datadog.trace.guzzle_enabled => On => On datadog.trace.guzzle_analytics_enabled => Off => Off datadog.guzzle_analytics_enabled => Off => Off datadog.trace.guzzle_analytics_sample_rate => 1 => 1 datadog.guzzle_analytics_sample_rate => 1 => 1 datadog.trace.laravel_enabled => On => On datadog.trace.laravel_analytics_enabled => Off => Off datadog.laravel_analytics_enabled => Off => Off datadog.trace.laravel_analytics_sample_rate => 1 => 1 datadog.laravel_analytics_sample_rate => 1 => 1 datadog.trace.lumen_enabled => On => On datadog.trace.lumen_analytics_enabled => Off => Off datadog.lumen_analytics_enabled => Off => Off datadog.trace.lumen_analytics_sample_rate => 1 => 1 datadog.lumen_analytics_sample_rate => 1 => 1 datadog.trace.memcached_enabled => On => On datadog.trace.memcached_analytics_enabled => Off => Off datadog.memcached_analytics_enabled => Off => Off datadog.trace.memcached_analytics_sample_rate => 1 => 1 datadog.memcached_analytics_sample_rate => 1 => 1 datadog.trace.mongo_enabled => On => On datadog.trace.mongo_analytics_enabled => Off => Off datadog.mongo_analytics_enabled => Off => Off datadog.trace.mongo_analytics_sample_rate => 1 => 1 datadog.mongo_analytics_sample_rate => 1 => 1 datadog.trace.mongodb_enabled => On => On datadog.trace.mongodb_analytics_enabled => Off => Off datadog.mongodb_analytics_enabled => Off => Off datadog.trace.mongodb_analytics_sample_rate => 1 => 1 datadog.mongodb_analytics_sample_rate => 1 => 1 datadog.trace.mysqli_enabled => On => On datadog.trace.mysqli_analytics_enabled => Off => Off datadog.mysqli_analytics_enabled => Off => Off datadog.trace.mysqli_analytics_sample_rate => 1 => 1 datadog.mysqli_analytics_sample_rate => 1 => 1 datadog.trace.nette_enabled => On => On datadog.trace.nette_analytics_enabled => Off => Off datadog.nette_analytics_enabled => Off => Off datadog.trace.nette_analytics_sample_rate => 1 => 1 datadog.nette_analytics_sample_rate => 1 => 1 datadog.trace.pcntl_enabled => On => On datadog.trace.pcntl_analytics_enabled => Off => Off datadog.pcntl_analytics_enabled => Off => Off datadog.trace.pcntl_analytics_sample_rate => 1 => 1 datadog.pcntl_analytics_sample_rate => 1 => 1 datadog.trace.pdo_enabled => On => On datadog.trace.pdo_analytics_enabled => Off => Off datadog.pdo_analytics_enabled => Off => Off datadog.trace.pdo_analytics_sample_rate => 1 => 1 datadog.pdo_analytics_sample_rate => 1 => 1 datadog.trace.phpredis_enabled => On => On datadog.trace.phpredis_analytics_enabled => Off => Off datadog.phpredis_analytics_enabled => Off => Off datadog.trace.phpredis_analytics_sample_rate => 1 => 1 datadog.phpredis_analytics_sample_rate => 1 => 1 datadog.trace.predis_enabled => On => On datadog.trace.predis_analytics_enabled => Off => Off datadog.predis_analytics_enabled => Off => Off datadog.trace.predis_analytics_sample_rate => 1 => 1 datadog.predis_analytics_sample_rate => 1 => 1 datadog.trace.roadrunner_enabled => On => On datadog.trace.roadrunner_analytics_enabled => Off => Off datadog.roadrunner_analytics_enabled => Off => Off datadog.trace.roadrunner_analytics_sample_rate => 1 => 1 datadog.roadrunner_analytics_sample_rate => 1 => 1 datadog.trace.slim_enabled => On => On datadog.trace.slim_analytics_enabled => Off => Off datadog.slim_analytics_enabled => Off => Off datadog.trace.slim_analytics_sample_rate => 1 => 1 datadog.slim_analytics_sample_rate => 1 => 1 datadog.trace.symfony_enabled => On => On datadog.trace.symfony_analytics_enabled => Off => Off datadog.symfony_analytics_enabled => Off => Off datadog.trace.symfony_analytics_sample_rate => 1 => 1 datadog.symfony_analytics_sample_rate => 1 => 1 datadog.trace.web_enabled => On => On datadog.trace.web_analytics_enabled => Off => Off datadog.web_analytics_enabled => Off => Off datadog.trace.web_analytics_sample_rate => 1 => 1 datadog.web_analytics_sample_rate => 1 => 1 datadog.trace.wordpress_enabled => On => On datadog.trace.wordpress_analytics_enabled => Off => Off datadog.wordpress_analytics_enabled => Off => Off datadog.trace.wordpress_analytics_sample_rate => 1 => 1 datadog.wordpress_analytics_sample_rate => 1 => 1 datadog.trace.yii_enabled => On => On datadog.trace.yii_analytics_enabled => Off => Off datadog.yii_analytics_enabled => Off => Off datadog.trace.yii_analytics_sample_rate => 1 => 1 datadog.yii_analytics_sample_rate => 1 => 1 datadog.trace.zendframework_enabled => On => On datadog.trace.zendframework_analytics_enabled => Off => Off datadog.zendframework_analytics_enabled => Off => Off datadog.trace.zendframework_analytics_sample_rate => 1 => 1 datadog.zendframework_analytics_sample_rate => 1 => 1 ```
bwoebi commented 1 year ago

Hey @B-Galati,

I've been looking for a while at your code (which looks right) and tried to reproduce it with minimal simple code, but have been failing to do so. I wonder, if you run this code with DD_TRACE_DEBUG=1 set, are you seeing any error messages?

Otherwise, without having the proper glue code to reproduce this, I'm going to have a hard time tracking your issue down.

B-Galati commented 1 year ago

@bwoebi Thanks, it helps indeed! I don't understand what I am doing wrong though.

[2023-01-25T16:20:20+00:00] [ddtrace] [debug] - Attempting integrations load; note: some integrations are only loaded on first usage
[2023-01-25T16:20:20+00:00] [ddtrace] [debug] - Loaded integration web
[2023-01-25T16:20:20+00:00] [ddtrace] [debug] - Loaded integration pcntl
[2023-01-25T16:20:20+00:00] [ddtrace] [debug] - Loaded integration curl
[2023-01-25T16:20:20+00:00] [ddtrace] [debug] - Loaded integration guzzle
[2023-01-25T16:20:20+00:00] [ddtrace] [debug] - Integration laravel not loaded. New attempts might be performed.
[2023-01-25T16:20:20+00:00] [ddtrace] [debug] - Loaded integration mysqli
[2023-01-25T16:20:20+00:00] [ddtrace] [debug] - Integration DDTrace\Integrations\Symfony\SymfonyIntegration not loaded. New attempts might be performed.
[2023-01-25T16:22:40+00:00] [ddtrace] [debug] - Loaded integration DDTrace\Integrations\PDO\PDOIntegration
There is no user-span on the top of the stack. Cannot close.
[2023-01-25T16:22:40+00:00] [ddtrace] [warning] - The span with name 'symfony.messenger.worker' was closed without being finished first.
There is no user-span on the top of the stack. Cannot close.
[2023-01-25T16:22:49+00:00] [ddtrace] [warning] - The span with name 'symfony.messenger.worker' was closed without being finished first.
There is no user-span on the top of the stack. Cannot close.
[2023-01-25T16:22:54+00:00] [ddtrace] [warning] - The span with name 'symfony.messenger.worker' was closed without being finished first.
There is no user-span on the top of the stack. Cannot close.
[2023-01-25T16:22:59+00:00] [ddtrace] [warning] - The span with name 'symfony.messenger.worker' was closed without being finished first.
There is no user-span on the top of the stack. Cannot close.
[2023-01-25T16:23:04+00:00] [ddtrace] [warning] - The span with name 'symfony.messenger.worker' was closed without being finished first.
There is no user-span on the top of the stack. Cannot close.
[2023-01-25T16:23:09+00:00] [ddtrace] [warning] - The span with name 'symfony.messenger.worker' was closed without being finished first.
There is no user-span on the top of the stack. Cannot close.
[2023-01-25T16:23:16+00:00] [ddtrace] [warning] - The span with name 'symfony.messenger.worker' was closed without being finished first.
There is no user-span on the top of the stack. Cannot close.
[2023-01-25T16:23:21+00:00] [ddtrace] [warning] - The span with name 'symfony.messenger.worker' was closed without being finished first.
B-Galati commented 1 year ago

Another bunch of logs from HTTP context this time:

[25-Jan-2023 16:26:19] WARNING: [pool www] child 123 said into stderr: "NOTICE: PHP message: [2023-01-25T16:26:19+00:00] [ddtrace] [debug] - Attempting integrations load; note: some integrations are only loaded on first usage"
[25-Jan-2023 16:26:19] WARNING: [pool www] child 123 said into stderr: "NOTICE: PHP message: [2023-01-25T16:26:19+00:00] [ddtrace] [debug] - Loaded integration web"
[25-Jan-2023 16:26:19] WARNING: [pool www] child 123 said into stderr: "NOTICE: PHP message: [2023-01-25T16:26:19+00:00] [ddtrace] [debug] - Integration pcntl not available. New attempts WILL NOT be performed."
[25-Jan-2023 16:26:19] WARNING: [pool www] child 123 said into stderr: "NOTICE: PHP message: [2023-01-25T16:26:19+00:00] [ddtrace] [debug] - Loaded integration curl"
[25-Jan-2023 16:26:19] WARNING: [pool www] child 123 said into stderr: "NOTICE: PHP message: [2023-01-25T16:26:19+00:00] [ddtrace] [debug] - Loaded integration guzzle"
[25-Jan-2023 16:26:19] WARNING: [pool www] child 123 said into stderr: "NOTICE: PHP message: [2023-01-25T16:26:19+00:00] [ddtrace] [debug] - Loaded integration laravel"
[25-Jan-2023 16:26:19] WARNING: [pool www] child 123 said into stderr: "NOTICE: PHP message: [2023-01-25T16:26:19+00:00] [ddtrace] [debug] - Loaded integration mysqli"
[25-Jan-2023 16:26:19] WARNING: [pool www] child 123 said into stderr: "NOTICE: PHP message: [2023-01-25T16:26:19+00:00] [ddtrace] [debug] - Loaded integration DDTrace\Integrations\Symfony\SymfonyIntegration"
[25-Jan-2023 16:26:19] WARNING: [pool www] child 123 said into stderr: "NOTICE: PHP message: [2023-01-25T16:26:19+00:00] [ddtrace] [warning] - The span with name 'symfony.request' was closed without being finished first."
[25-Jan-2023 16:26:19] WARNING: [pool www] child 123 said into stderr: "NOTICE: PHP message: Notifying profiler of finished local root span."

Looks like the Symfony integration is doing something wrong :thinking:

B-Galati commented 1 year ago

Also don't get why it loads Laravel integration.

bwoebi commented 1 year ago 
The span with name '...' was closed without being finished first.

Means that that spans destructor was invoked (should be destructed, not closed in that error message), without it being properly finished (scope->close() or span->finish()).

Due to internal changes, the implementation has become a little less forgiving over the last 8 versions basically and may drop some not properly closed spans.

Examining your trace debug output, it seems like sometimes the onMessageReceived is executed twice, followed by onMessageHandled being executed twice, thus overwriting $this->span, and then the second call to onMessageHandled tries to finish an already finished span.

It loads the laravel integration because that's one enabled-by-default integration (in ancient times they were all enabled by default). We should change that, but feel free to ignore it.

Regarding the HTTP context - are you by chance running with DD_TRACE_GENERATE_ROOT_SPAN=false in http context as well, and wrapping the execution into your own span (which then is not properly closed)?

What the symfony integration does is setting the name of the root span to symfony.request when Symfony\Component\HttpKernel\Kernel::handle() is executed. It does not care about the lifetime of the root span itself.

B-Galati commented 1 year ago

Thanks for these helpful answers!

The span with name '...' was closed without being finished first.

Means that that spans destructor was invoked (should be destructed, not closed in that error message), without it being properly finished (scope->close() or span->finish()).

Alright but before that it says There is no user-span on the top of the stack. Cannot close.. So may be the message you mentioned is just a consequence of the previous one?

Regarding the HTTP context - are you by chance running with DD_TRACE_GENERATE_ROOT_SPAN=false in http context as well, and wrapping the execution into your own span (which then is not properly closed)?

No I have the default values for HTTP context :heavy_check_mark:

bwoebi commented 1 year ago

So may be the message you mentioned is just a consequence of the previous one?

Yes :-)

No I have the default values for HTTP context

In that case I don't really know why that would happen. As far as I can judge, there is nothing obvious I can do to help with the code you shared.

But I suspect, you'll have to resolve that on your side - or open a ticket with our suppport team so that one of us can help you track the issue down in your application.

B-Galati commented 1 year ago

Thanks for your help @bwoebi! I will try to remove all the custom instrumentation and re-add them one by one.

I'll re-open the issue if I found something relevant.

B-Galati commented 1 year ago

FYI it's fixed, the console listener and the worker listener should not be started together. They were messing up with each other.

The fix:

diff --git a/src/Infrastructure/Datadog/Symfony/EventListener/ConsoleCommandListener.php b/src/Infrastructure/Datadog/Symfony/EventListener/ConsoleCommandListener.php
index 858f078..cee5468 100644
--- a/src/Infrastructure/Datadog/Symfony/EventListener/ConsoleCommandListener.php
+++ b/src/Infrastructure/Datadog/Symfony/EventListener/ConsoleCommandListener.php
@@ -6,6 +6,7 @@ namespace Infrastructure\Datadog\Symfony\EventListener;

 use DDTrace\Contracts\Span;
 use DDTrace\GlobalTracer;
+use DDTrace\Scope;
 use DDTrace\Tag;
 use DDTrace\Type;
 use Symfony\Component\Console\ConsoleEvents;
@@ -17,6 +18,11 @@ use Symfony\Component\Messenger\Command\ConsumeMessagesCommand;

 class ConsoleCommandListener implements EventSubscriberInterface
 {
+    private ?Scope $scope = null;
+
+    /**
+     * {@inheritDoc}
+     */
     public static function getSubscribedEvents(): array
     {
         return [
@@ -28,21 +34,20 @@ class ConsoleCommandListener implements EventSubscriberInterface
     public function onConsoleCommand(ConsoleCommandEvent $event): void
     {
         $command = $event->getCommand();
-        if (null === $command || !self::isTraceable()) {
+        if (null === $command
+            || $command instanceof ConsumeMessagesCommand
+            || !$this->isTraceable()
+        ) {
             return;
         }

-        $scope = GlobalTracer::get()->startRootSpan('symfony.console.command');
+        $this->scope = GlobalTracer::get()->startRootSpan('symfony.console.command');

-        $span = $scope->getSpan();
+        $span = $this->scope->getSpan();
         $span->setResource(\get_class($command));
         $span->setTag(Tag::SERVICE_NAME, dd_trace_env_config('DD_SERVICE'));
-
-        if ($command instanceof ConsumeMessagesCommand) {
-            $span->setTag(Tag::SPAN_TYPE, Type::MESSAGE_CONSUMER);
-        } else {
-            $span->setTag(Tag::SPAN_TYPE, Type::CLI);
-        }
+        $span->setTag(Tag::SPAN_TYPE, Type::CLI);

         $input = $event->getInput();
         $this->addOptionsAsTags($input, $span);
@@ -51,15 +56,14 @@ class ConsoleCommandListener implements EventSubscriberInterface

     public function onConsoleTerminate(ConsoleTerminateEvent $event): void
     {
-        $scope = GlobalTracer::get()->getRootScope();
-        if (null === $scope || !self::isTraceable()) {
+        if (null === $this->scope || !$this->isTraceable()) {
             return;
         }

-        $span = $scope->getSpan();
+        $span = $this->scope->getSpan();
         $span->setTag('exit_code', $event->getExitCode());
-
-        $scope->close();
+        $this->scope->close();
+        $this->scope = null;
     }

     private function addOptionsAsTags(InputInterface $input, Span $span): void
@@ -88,7 +92,7 @@ class ConsoleCommandListener implements EventSubscriberInterface
         }
     }

-    private static function isTraceable(): bool
+    private function isTraceable(): bool
     {
         return 'cli' === \PHP_SAPI && \extension_loaded('ddtrace');
     }
diff --git a/src/Infrastructure/Datadog/Symfony/EventListener/DatadogMessengerWorkerListener.php b/src/Infrastructure/Datadog/Symfony/EventListener/DatadogMessengerWorkerListener.php
index 3907be9..a97e930 100644
--- a/src/Infrastructure/Datadog/Symfony/EventListener/DatadogMessengerWorkerListener.php
+++ b/src/Infrastructure/Datadog/Symfony/EventListener/DatadogMessengerWorkerListener.php
@@ -4,8 +4,8 @@ declare(strict_types=1);

 namespace Infrastructure\Datadog\Symfony\EventListener;

-use DDTrace\Contracts\Span;
 use DDTrace\GlobalTracer;
+use DDTrace\Scope;
 use DDTrace\Tag;
 use DDTrace\Type;
 use Symfony\Component\EventDispatcher\EventSubscriberInterface;
@@ -15,7 +15,7 @@ use Symfony\Component\Messenger\Event\WorkerMessageReceivedEvent;

 class DatadogMessengerWorkerListener implements EventSubscriberInterface
 {
-    private ?Span $span = null;
+    private ?Scope $scope = null;

     public function onMessageReceived(WorkerMessageReceivedEvent $event): void
     {
@@ -27,31 +27,32 @@ class DatadogMessengerWorkerListener implements EventSubscriberInterface
             return;
         }

-        $this->span = GlobalTracer::get()->startSpan('symfony.messenger.worker');
-        $this->span->setResource(\get_class($event->getEnvelope()->getMessage()));
-        $this->span->setTag(Tag::SERVICE_NAME, dd_trace_env_config('DD_SERVICE'));
-        $this->span->setTag(Tag::SPAN_TYPE, Type::MESSAGE_CONSUMER);
+        $this->scope = GlobalTracer::get()->startRootSpan('symfony.messenger.worker');
+        $span = $this->scope->getSpan();
+        $span->setResource(\get_class($event->getEnvelope()->getMessage()));
+        $span->setTag(Tag::SERVICE_NAME, dd_trace_env_config('DD_SERVICE'));
+        $span->setTag(Tag::SPAN_TYPE, Type::MESSAGE_CONSUMER);
     }

     public function onMessageHandled(WorkerMessageHandledEvent $event): void
     {
-        if (null === $this->span) {
+        if (null === $this->scope) {
             return;
         }

-        $this->span->finish();
-        $this->span = null;
+        $this->scope->close();
+        $this->scope = null;
     }

     public function onMessageFailed(WorkerMessageFailedEvent $event): void
     {
-        if (null === $this->span) {
+        if (null === $this->scope) {
             return;
         }

-        $this->span->setError($event->getThrowable());
-        $this->span->finish();
-        $this->span = null;
+        $this->scope->getSpan()->setError($event->getThrowable());
+        $this->scope->close();
+        $this->scope = null;
     }

     /**
bwoebi commented 1 year ago

Great to hear that you've managed to understand and fix your issue :-)