DataDog / dd-trace-php

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

[Bug]: Xdebug skips breakpoints after Psr\Log\LoggerInterface methods are called, only when DDTrace is enabled #2774

Closed paigeruten closed 2 weeks ago

paigeruten commented 1 month ago

Bug report

Hello, we've been finding that when debugging our app with Xdebug, it doesn't stop on breakpoints after any Psr\Log\LoggerInterface method is called, only when ddtrace is enabled. Here's a simple example:

$logger = new SomeLogger(); // Can be any logger that implements Psr\Log\LoggerInterface
echo 'a'; // Set breakpoint here
$logger->info('test');
echo 'b'; // Set breakpoint here

(There's a full example with Dockerfile and steps to reproduce in this repo if you're interested: https://github.com/paigeruten/dd-trace-php-logger-bug)

When step-debugging this code with Xdebug, it will hit the first breakpoint but will skip the second breakpoint after hitting "resume". Any other breakpoints added after the $logger->info() line will be skipped too. Also, if you try to step one line forward after the $logger->info() call, it will just go immediately to the end of the script. This happens in PHPStorm, VSCode, and dbgp.

Disabling the ddtrace extension, or calling dd_trace_disable_in_request() at the top of the script, will fix the issue.

I'm not sure if this is an Xdebug issue or a dd-trace-php issue, but it seems to have to do with how ddtrace installs hooks into Psr\Log\LoggerInterface. Any ideas for either a fix or a workaround would be much appreciated 🙂 Currently we are using xdebug_break() as a workaround, or temporarily disabling ddtrace when debugging.

Here's a video that shows the breakpoints being skipped, only when certain methods are called on the Psr\Log\LoggerInterface and only when ddtrace is enabled:

https://github.com/user-attachments/assets/6d4fcdd5-4bf1-4085-ae69-8ff334ff42b4

PHP version

8.3.9

Tracer or profiler version

1.2.0

Installed extensions

[PHP Modules]
Core
ctype
curl
date
ddappsec
ddtrace
dom
fileinfo
filter
hash
iconv
json
libxml
mbstring
mysqlnd
openssl
pcre
PDO
pdo_sqlite
Phar
posix
random
readline
Reflection
session
SimpleXML
sodium
SPL
sqlite3
standard
tokenizer
xdebug
xml
xmlreader
xmlwriter
zlib

[Zend Modules]
Xdebug
ddappsec
ddtrace

Output of phpinfo()

Datadog tracing support => disabled
Version => 1.2.0
DATADOG TRACER CONFIGURATION => {
    "date": "2024-07-24T18:46:55Z",
    "os_name": "Linux orbstack 6.9.8-orbstack-00170-g7b4100b7ced4 #1 SMP Thu Jul 11 03:32:20 UTC 2024 aarch64",
    "os_version": "6.9.8-orbstack-00170-g7b4100b7ced4",
    "version": "1.2.0",
    "lang": "php",
    "lang_version": "8.3.9",
    "env": null,
    "enabled": true,
    "service": null,
    "enabled_cli": false,
    "agent_url": "http:\/\/localhost:8126",
    "debug": false,
    "analytics_enabled": false,
    "sample_rate": -1,
    "sampling_rules": [],
    "tags": [],
    "service_mapping": [],
    "distributed_tracing_enabled": true,
    "dd_version": null,
    "architecture": "aarch64",
    "instrumentation_telemetry_enabled": true,
    "sapi": "cli",
    "datadog.trace.sources_path": "\/opt\/datadog\/dd-library\/1.2.0\/dd-trace-sources\/src",
    "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,
    "enabled_from_env": false,
    "opcache.file_cache": null,
    "sidecar_trace_sender": false
}

Directive => Local Value => Master Value
datadog.agent_host => no value => no value
datadog.amqp_analytics_enabled => Off => Off
datadog.amqp_analytics_sample_rate => 1 => 1
datadog.api_key => no value => no value
datadog.appsec.sca_enabled => Off => Off
datadog.autofinish_spans => Off => Off
datadog.autoload_no_compile => 0 => 0
datadog.cakephp_analytics_enabled => Off => Off
datadog.cakephp_analytics_sample_rate => 1 => 1
datadog.codeigniter_analytics_enabled => Off => Off
datadog.codeigniter_analytics_sample_rate => 1 => 1
datadog.curl_analytics_enabled => Off => Off
datadog.curl_analytics_sample_rate => 1 => 1
datadog.dbm_propagation_mode => disabled => disabled
datadog.distributed_tracing => On => On
datadog.dogstatsd_port => 8125 => 8125
datadog.dogstatsd_url => no value => no value
datadog.drupal_analytics_enabled => Off => Off
datadog.drupal_analytics_sample_rate => 1 => 1
datadog.elasticsearch_analytics_enabled => Off => Off
datadog.elasticsearch_analytics_sample_rate => 1 => 1
datadog.eloquent_analytics_enabled => Off => Off
datadog.eloquent_analytics_sample_rate => 1 => 1
datadog.env => no value => no value
datadog.exec_analytics_enabled => Off => Off
datadog.exec_analytics_sample_rate => 1 => 1
datadog.frankenphp_analytics_enabled => Off => Off
datadog.frankenphp_analytics_sample_rate => 1 => 1
datadog.git_commit_sha => no value => no value
datadog.git_repository_url => no value => no value
datadog.guzzle_analytics_enabled => Off => Off
datadog.guzzle_analytics_sample_rate => 1 => 1
datadog.http_server_route_based_naming => On => On
datadog.instrumentation_telemetry_enabled => On => On
datadog.integration_metrics_enabled => On => On
datadog.laminas_analytics_enabled => Off => Off
datadog.laminas_analytics_sample_rate => 1 => 1
datadog.laravel_analytics_enabled => Off => Off
datadog.laravel_analytics_sample_rate => 1 => 1
datadog.laravelqueue_analytics_enabled => Off => Off
datadog.laravelqueue_analytics_sample_rate => 1 => 1
datadog.log_backtrace => Off => Off
datadog.logs_analytics_enabled => Off => Off
datadog.logs_analytics_sample_rate => 1 => 1
datadog.logs_injection => Off => Off
datadog.lumen_analytics_enabled => Off => Off
datadog.lumen_analytics_sample_rate => 1 => 1
datadog.magento_analytics_enabled => Off => Off
datadog.magento_analytics_sample_rate => 1 => 1
datadog.memcache_analytics_enabled => Off => Off
datadog.memcache_analytics_sample_rate => 1 => 1
datadog.memcached_analytics_enabled => Off => Off
datadog.memcached_analytics_sample_rate => 1 => 1
datadog.mongo_analytics_enabled => Off => Off
datadog.mongo_analytics_sample_rate => 1 => 1
datadog.mongodb_analytics_enabled => Off => Off
datadog.mongodb_analytics_sample_rate => 1 => 1
datadog.mysqli_analytics_enabled => Off => Off
datadog.mysqli_analytics_sample_rate => 1 => 1
datadog.nette_analytics_enabled => Off => Off
datadog.nette_analytics_sample_rate => 1 => 1
datadog.openai_analytics_enabled => Off => Off
datadog.openai_analytics_sample_rate => 1 => 1
datadog.openai_log_prompt_completion_sample_rate => 0.1 => 0.1
datadog.openai_logs_enabled => Off => Off
datadog.openai_metrics_enabled => On => On
datadog.openai_service => no value => no value
datadog.openai_span_char_limit => 128 => 128
datadog.openai_span_prompt_completion_sample_rate => 1.0 => 1.0
datadog.pcntl_analytics_enabled => Off => Off
datadog.pcntl_analytics_sample_rate => 1 => 1
datadog.pdo_analytics_enabled => Off => Off
datadog.pdo_analytics_sample_rate => 1 => 1
datadog.phpredis_analytics_enabled => Off => Off
datadog.phpredis_analytics_sample_rate => 1 => 1
datadog.predis_analytics_enabled => Off => Off
datadog.predis_analytics_sample_rate => 1 => 1
datadog.psr18_analytics_enabled => Off => Off
datadog.psr18_analytics_sample_rate => 1 => 1
datadog.roadrunner_analytics_enabled => Off => Off
datadog.roadrunner_analytics_sample_rate => 1 => 1
datadog.service => no value => no value
datadog.service_mapping => no value => no value
datadog.slim_analytics_enabled => Off => Off
datadog.slim_analytics_sample_rate => 1 => 1
datadog.span_sampling_rules => [] => []
datadog.span_sampling_rules_file => no value => no value
datadog.sqlsrv_analytics_enabled => Off => Off
datadog.sqlsrv_analytics_sample_rate => 1 => 1
datadog.swoole_analytics_enabled => Off => Off
datadog.swoole_analytics_sample_rate => 1 => 1
datadog.symfony_analytics_enabled => Off => Off
datadog.symfony_analytics_sample_rate => 1 => 1
datadog.tags => no value => no value
datadog.telemetry_heartbeat_interval => 60 => 60
datadog.trace.128_bit_traceid_generation_enabled => On => On
datadog.trace.128_bit_traceid_logging_enabled => Off => Off
datadog.trace.agent_connect_timeout => 100 => 100
datadog.trace.agent_debug_verbose_curl => Off => Off
datadog.trace.agent_flush_after_n_requests => 10 => 10
datadog.trace.agent_flush_interval => 5000 => 5000
datadog.trace.agent_max_payload_size => 52428800 => 52428800
datadog.trace.agent_port => 0 => 0
datadog.trace.agent_retries => 0 => 0
datadog.trace.agent_stack_backlog => 12 => 12
datadog.trace.agent_stack_initial_size => 131072 => 131072
datadog.trace.agent_timeout => 500 => 500
datadog.trace.agent_url => no value => no value
datadog.trace.agentless => Off => Off
datadog.trace.amqp_analytics_enabled => Off => Off
datadog.trace.amqp_analytics_sample_rate => 1 => 1
datadog.trace.amqp_enabled => On => On
datadog.trace.analytics_enabled => Off => Off
datadog.trace.append_trace_ids_to_logs => Off => Off
datadog.trace.auto_flush_enabled => Off => Off
datadog.trace.beta_high_memory_pressure_percent => 80 => 80
datadog.trace.bgs_connect_timeout => 2000 => 2000
datadog.trace.bgs_timeout => 5000 => 5000
datadog.trace.buffer_size => 2097152 => 2097152
datadog.trace.cakephp_analytics_enabled => Off => Off
datadog.trace.cakephp_analytics_sample_rate => 1 => 1
datadog.trace.cakephp_enabled => On => On
datadog.trace.cli_enabled => Off => Off
datadog.trace.client_ip_enabled => Off => Off
datadog.trace.client_ip_header => no value => no value
datadog.trace.codeigniter_analytics_enabled => Off => Off
datadog.trace.codeigniter_analytics_sample_rate => 1 => 1
datadog.trace.codeigniter_enabled => On => On
datadog.trace.curl_analytics_enabled => Off => Off
datadog.trace.curl_analytics_sample_rate => 1 => 1
datadog.trace.curl_enabled => On => On
datadog.trace.db_client_split_by_instance => Off => Off
datadog.trace.debug => Off => Off
datadog.trace.debug_curl_output => Off => Off
datadog.trace.debug_prng_seed => -1 => -1
datadog.trace.drupal_analytics_enabled => Off => Off
datadog.trace.drupal_analytics_sample_rate => 1 => 1
datadog.trace.drupal_enabled => On => On
datadog.trace.elasticsearch_analytics_enabled => Off => Off
datadog.trace.elasticsearch_analytics_sample_rate => 1 => 1
datadog.trace.elasticsearch_enabled => On => On
datadog.trace.eloquent_analytics_enabled => Off => Off
datadog.trace.eloquent_analytics_sample_rate => 1 => 1
datadog.trace.eloquent_enabled => On => On
datadog.trace.enabled => Off => On
datadog.trace.exec_analytics_enabled => Off => Off
datadog.trace.exec_analytics_sample_rate => 1 => 1
datadog.trace.exec_enabled => On => On
datadog.trace.flush_collect_cycles => Off => Off
datadog.trace.forked_process => On => On
datadog.trace.frankenphp_analytics_enabled => Off => Off
datadog.trace.frankenphp_analytics_sample_rate => 1 => 1
datadog.trace.frankenphp_enabled => On => On
datadog.trace.generate_root_span => On => On
datadog.trace.git_metadata_enabled => On => On
datadog.trace.guzzle_analytics_enabled => Off => Off
datadog.trace.guzzle_analytics_sample_rate => 1 => 1
datadog.trace.guzzle_enabled => On => On
datadog.trace.header_tags => no value => no value
datadog.trace.health_metrics_enabled => Off => Off
datadog.trace.health_metrics_heartbeat_sample_rate => 0.001 => 0.001
datadog.trace.hook_limit => 100 => 100
datadog.trace.http_client_split_by_domain => Off => Off
datadog.trace.http_post_data_param_allowed => no value => no value
datadog.trace.http_url_query_param_allowed => * => *
datadog.trace.laminas_analytics_enabled => Off => Off
datadog.trace.laminas_analytics_sample_rate => 1 => 1
datadog.trace.laminas_enabled => On => On
datadog.trace.laravel_analytics_enabled => Off => Off
datadog.trace.laravel_analytics_sample_rate => 1 => 1
datadog.trace.laravel_enabled => On => On
datadog.trace.laravel_queue_distributed_tracing => On => On
datadog.trace.laravelqueue_analytics_enabled => Off => Off
datadog.trace.laravelqueue_analytics_sample_rate => 1 => 1
datadog.trace.laravelqueue_enabled => On => On
datadog.trace.log_file => no value => no value
datadog.trace.log_level => error => error
datadog.trace.logs_analytics_enabled => Off => Off
datadog.trace.logs_analytics_sample_rate => 1 => 1
datadog.trace.logs_enabled => Off => Off
datadog.trace.lumen_analytics_enabled => Off => Off
datadog.trace.lumen_analytics_sample_rate => 1 => 1
datadog.trace.lumen_enabled => On => On
datadog.trace.magento_analytics_enabled => Off => Off
datadog.trace.magento_analytics_sample_rate => 1 => 1
datadog.trace.magento_enabled => On => On
datadog.trace.measure_compile_time => On => On
datadog.trace.memcache_analytics_enabled => Off => Off
datadog.trace.memcache_analytics_sample_rate => 1 => 1
datadog.trace.memcache_enabled => On => On
datadog.trace.memcached_analytics_enabled => Off => Off
datadog.trace.memcached_analytics_sample_rate => 1 => 1
datadog.trace.memcached_enabled => On => On
datadog.trace.memcached_obfuscation => On => On
datadog.trace.memory_limit => no value => no value
datadog.trace.mongo_analytics_enabled => Off => Off
datadog.trace.mongo_analytics_sample_rate => 1 => 1
datadog.trace.mongo_enabled => On => On
datadog.trace.mongodb_analytics_enabled => Off => Off
datadog.trace.mongodb_analytics_sample_rate => 1 => 1
datadog.trace.mongodb_enabled => On => On
datadog.trace.mysqli_analytics_enabled => Off => Off
datadog.trace.mysqli_analytics_sample_rate => 1 => 1
datadog.trace.mysqli_enabled => On => On
datadog.trace.nette_analytics_enabled => Off => Off
datadog.trace.nette_analytics_sample_rate => 1 => 1
datadog.trace.nette_enabled => On => On
datadog.trace.obfuscation_query_string_regexp => (?i)(?:(?:"|%22)?)(?:(?:old[-_]?|new[-_]?)?p(?:ass)?w(?:or)?d(?:1|2)?|pass(?:[-_]?phrase)?|secret|(?:api[-_]?|private[-_]?|public[-_]?|access[-_]?|secret[-_]?|app(?:lication)?[-_]?)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(?:-{5})?(?:\n|%0A)?|(?:ssh-(?:rsa|dss)|ecdsa-[a-z0-9]+-[a-z0-9]+)(?:\s|%20|%09)+(?:[a-z0-9/.+]|%2F|%5C|%2B){100,}(?:=|%3D)*(?:(?:\s|%20|%09)+[a-z0-9._-]+)?) => (?i)(?:(?:"|%22)?)(?:(?:old[-_]?|new[-_]?)?p(?:ass)?w(?:or)?d(?:1|2)?|pass(?:[-_]?phrase)?|secret|(?:api[-_]?|private[-_]?|public[-_]?|access[-_]?|secret[-_]?|app(?:lication)?[-_]?)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(?:-{5})?(?:\n|%0A)?|(?:ssh-(?:rsa|dss)|ecdsa-[a-z0-9]+-[a-z0-9]+)(?:\s|%20|%09)+(?:[a-z0-9/.+]|%2F|%5C|%2B){100,}(?:=|%3D)*(?:(?:\s|%20|%09)+[a-z0-9._-]+)?)
datadog.trace.once_logs => On => On
datadog.trace.openai_analytics_enabled => Off => Off
datadog.trace.openai_analytics_sample_rate => 1 => 1
datadog.trace.openai_enabled => On => On
datadog.trace.otel_enabled => Off => Off
datadog.trace.pcntl_analytics_enabled => Off => Off
datadog.trace.pcntl_analytics_sample_rate => 1 => 1
datadog.trace.pcntl_enabled => On => On
datadog.trace.pdo_analytics_enabled => Off => Off
datadog.trace.pdo_analytics_sample_rate => 1 => 1
datadog.trace.pdo_enabled => On => On
datadog.trace.peer_service_defaults_enabled => Off => Off
datadog.trace.peer_service_mapping => no value => no value
datadog.trace.phpredis_analytics_enabled => Off => Off
datadog.trace.phpredis_analytics_sample_rate => 1 => 1
datadog.trace.phpredis_enabled => On => On
datadog.trace.predis_analytics_enabled => Off => Off
datadog.trace.predis_analytics_sample_rate => 1 => 1
datadog.trace.predis_enabled => On => On
datadog.trace.propagate_service => Off => Off
datadog.trace.propagate_user_id_default => Off => Off
datadog.trace.propagation_style => datadog,tracecontext => datadog,tracecontext
datadog.trace.propagation_style_extract => datadog,tracecontext,B3,B3 single header => datadog,tracecontext,B3,B3 single header
datadog.trace.propagation_style_inject => datadog,tracecontext => datadog,tracecontext
datadog.trace.psr18_analytics_enabled => Off => Off
datadog.trace.psr18_analytics_sample_rate => 1 => 1
datadog.trace.psr18_enabled => On => On
datadog.trace.rate_limit => 0 => 0
datadog.trace.redis_client_split_by_host => Off => Off
datadog.trace.remove_autoinstrumentation_orphans => Off => Off
datadog.trace.remove_integration_service_names_enabled => Off => Off
datadog.trace.remove_root_span_laravel_queue => On => On
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.retain_thread_capabilities => Off => Off
datadog.trace.roadrunner_analytics_enabled => Off => Off
datadog.trace.roadrunner_analytics_sample_rate => 1 => 1
datadog.trace.roadrunner_enabled => On => On
datadog.trace.sample_rate => -1 => -1
datadog.trace.sampling_rules => [] => []
datadog.trace.sampling_rules_format => glob => glob
datadog.trace.shutdown_timeout => 5000 => 5000
datadog.trace.sidecar_trace_sender => Off => Off
datadog.trace.slim_analytics_enabled => Off => Off
datadog.trace.slim_analytics_sample_rate => 1 => 1
datadog.trace.slim_enabled => On => On
datadog.trace.sources_path => /opt/datadog/dd-library/1.2.0/dd-trace-sources/src => /opt/datadog/dd-library/1.2.0/dd-trace-sources/src
datadog.trace.spans_limit => 1000 => 1000
datadog.trace.sqlsrv_analytics_enabled => Off => Off
datadog.trace.sqlsrv_analytics_sample_rate => 1 => 1
datadog.trace.sqlsrv_enabled => On => On
datadog.trace.startup_logs => On => On
datadog.trace.swoole_analytics_enabled => Off => Off
datadog.trace.swoole_analytics_sample_rate => 1 => 1
datadog.trace.swoole_enabled => On => On
datadog.trace.symfony_analytics_enabled => Off => Off
datadog.trace.symfony_analytics_sample_rate => 1 => 1
datadog.trace.symfony_enabled => On => On
datadog.trace.traced_internal_functions => no value => no value
datadog.trace.url_as_resource_names_enabled => On => On
datadog.trace.warn_legacy_dd_trace => On => On
datadog.trace.web_analytics_enabled => Off => Off
datadog.trace.web_analytics_sample_rate => 1 => 1
datadog.trace.web_enabled => On => On
datadog.trace.wordpress_additional_actions => no value => no value
datadog.trace.wordpress_analytics_enabled => Off => Off
datadog.trace.wordpress_analytics_sample_rate => 1 => 1
datadog.trace.wordpress_callbacks => On => On
datadog.trace.wordpress_enabled => On => On
datadog.trace.x_datadog_tags_max_length => 512 => 512
datadog.trace.yii_analytics_enabled => Off => Off
datadog.trace.yii_analytics_sample_rate => 1 => 1
datadog.trace.yii_enabled => On => On
datadog.trace.zendframework_analytics_enabled => Off => Off
datadog.trace.zendframework_analytics_sample_rate => 1 => 1
datadog.trace.zendframework_enabled => On => On
datadog.version => no value => no value
datadog.web_analytics_enabled => Off => Off
datadog.web_analytics_sample_rate => 1 => 1
datadog.wordpress_analytics_enabled => Off => Off
datadog.wordpress_analytics_sample_rate => 1 => 1
datadog.yii_analytics_enabled => Off => Off
datadog.yii_analytics_sample_rate => 1 => 1
datadog.zendframework_analytics_enabled => Off => Off
datadog.zendframework_analytics_sample_rate => 1 => 1
ddtrace.cgroup_file => /proc/self/cgroup => /proc/self/cgroup
ddtrace.disable => 0 => 0

Upgrading from

No response

bwoebi commented 1 month ago

Hey @paigeruten,

thanks for the report, we're going to look into it soon :-)

bwoebi commented 1 week ago

We fixed and released this in 1.3.0 now - thanks for the report again!

paigeruten commented 4 days ago

Thank you for the fix!