[BUG] PHP-FPM + profiling + preload = segfault

B-Galati commented 1 year ago

Hello!

Bug description

I am currently using Datadog tracer and it's fine. Trying to enable Datadog profiler extension is causing PHP-FPM to produce segfault. PHP CLI is doing well :heavy_check_mark:

I found 2 things that fixes the issue:

Either disable preload
Or execute PHP-FPM with root (and keep preload of course)

In some ways it looks like to these 2 issues:

Output of gdb:

$ gdb php-fpm coredump-php-fpm.3091 
GNU gdb (Ubuntu 9.2-0ubuntu1~20.04.1) 9.2
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from php-fpm...
(No debugging symbols found in php-fpm)

warning: core file may not match specified executable file.
[New LWP 3091]
[New LWP 3093]
[New LWP 3094]
[New LWP 3092]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `php-fpm -v'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007f7e7082e2fe in ddtrace_get_profiling_context () at /home/circleci/datadog/tmp/build_extension/ext/profiling.c:11
11    /home/circleci/datadog/tmp/build_extension/ext/profiling.c: No such file or directory.
[Current thread is 1 (Thread 0x7f7e73fbe5c0 (LWP 3091))]
(gdb)

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 ```

Upgrading info

I am upgrading from 0.75.0 but it's the same problem with 0.75.0. Installing the profiler extension is what triggers the issue.

B-Galati commented 1 year ago

Please let me know if you need any further information :+1:

realFlowControl commented 1 year ago

Hey @B-Galati,

thanks for reaching out. Could you provide us with the backtrace? In case you don't know how, start gdb again and type bt:

$ gdb php-fpm coredump-php-fpm.3091 
...
(gdb) bt

And another question: does PHP-FPM segfault right away or does this happen at any later point in time, maybe even after serving some requests?

/Florian

B-Galati commented 1 year ago

@realFlowControl Hi and thanks!

Here it is

(gdb) run -v
Starting program: /usr/local/bin/php-fpm -v
warning: Error disabling address space randomization: Operation not permitted
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7f79e5078700 (LWP 812)]
[New Thread 0x7f79e4877700 (LWP 813)]
[New Thread 0x7f79dffff700 (LWP 814)]
[25-Jan-2023 13:01:04] NOTICE: PHP message: PHP Warning:  Can't preload already declared class ReflectionEnum in /opt/project/vendor/laminas/laminas-code/polyfill/ReflectionEnumPolyfill.php on line 8

Thread 1 "php-fpm" received signal SIGSEGV, Segmentation fault.
0x00007f79e781d2fe in ddtrace_get_profiling_context ()
    at /home/circleci/datadog/tmp/build_extension/ext/profiling.c:11
11      /home/circleci/datadog/tmp/build_extension/ext/profiling.c: No such file or directory.
(gdb) bt
#0  0x00007f79e781d2fe in ddtrace_get_profiling_context ()
    at /home/circleci/datadog/tmp/build_extension/ext/profiling.c:11
#1  0x00007f79e726335b in datadog_php_profiling::profiling::Profiler::collect_time ()
    at src/profiling.rs:784
#2  0x00007f79e7272c5d in datadog_php_profiling::interrupt_function::{{closure}} ()
    at src/lib.rs:898
#3  std::thread::local::LocalKey<T>::try_with ()
    at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/local.rs:413
#4  std::thread::local::LocalKey<T>::with ()
    at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/local.rs:389
#5  0x00007f79e727c4c4 in datadog_php_profiling::interrupt_function () at src/lib.rs:878
#6  datadog_php_profiling::execute_internal () at src/lib.rs:934
#7  0x00007f79e77fda46 in zai_interceptor_execute_internal_impl (execute_data=0x7f79eac127b0,
    return_value=0x7ffd52805dc8, prev=<optimized out>)
    at /home/circleci/datadog/tmp/build_extension/zend_abstract_interface/interceptor/php8/interceptor.c:694
#8  0x000056534c5590b3 in ?? ()
#9  0x000056534c55a01a in ?? ()
#10 0x00007f79e7a84f61 in ?? () from /usr/lib/php/20210902/blackfire.so
#11 0x000056534c7938bd in zend_execute ()
#12 0x00007f79e7aa51e8 in bf_load_embedded_code () from /usr/lib/php/20210902/blackfire.so
#13 0x00007f79e7a8c700 in zm_activate_blackfire () from /usr/lib/php/20210902/blackfire.so
#14 0x000056534c729b80 in zend_activate_modules ()
#15 0x000056534c6bf12c in php_request_startup ()
#16 0x000056534c563db7 in ?? ()
#17 0x00007f79ed034083 in __libc_start_main (main=0x56534c563be0, argc=2, argv=0x7ffd52815498,
    init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>,
    stack_end=0x7ffd52815488) at ../csu/libc-start.c:308
#18 0x000056534c565f5e in _start ()

bwoebi commented 1 year ago

This has been fixed by #1883.

B-Galati commented 1 year ago

Thank you!!

bwoebi commented 1 year ago

@B-Galati It also has been released with 0.84.0 now :-)

B-Galati commented 1 year ago

That's awesome, thanks! I'm going to test that whenever I can with a feedback.

B-Galati commented 1 year ago

@bwoebi Hello! I just tested with 0.84.0 but it still does not work. I can run php-fpm -v but no request can be served.

Here is the GDB debug info:

$ gdb php-fpm
GNU gdb (Ubuntu 9.2-0ubuntu1~20.04.1) 9.2
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from php-fpm...
(No debugging symbols found in php-fpm)
(gdb) r -F
Starting program: /usr/local/bin/php-fpm -F
warning: Error disabling address space randomization: Operation not permitted
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7fb36b050700 (LWP 894)]
[New Thread 0x7fb36a84f700 (LWP 895)]
[New Thread 0x7fb36a64e700 (LWP 896)]
[14-Feb-2023 12:16:15] NOTICE: [pool www] 'user' directive is ignored when FPM is not running as root
[14-Feb-2023 12:16:15] NOTICE: [pool www] 'group' directive is ignored when FPM is not running as root
[14-Feb-2023 12:16:15] NOTICE: fpm is running, pid 890
[Detaching after fork from child process 897]
[Detaching after fork from child process 898]
[Detaching after fork from child process 899]
[Detaching after fork from child process 900]
[Detaching after fork from child process 901]
[Detaching after fork from child process 902]
[Detaching after fork from child process 903]
[Detaching after fork from child process 904]
[Detaching after fork from child process 905]
[Detaching after fork from child process 906]
[Detaching after fork from child process 907]
[Detaching after fork from child process 908]
[Detaching after fork from child process 909]
[Detaching after fork from child process 910]
[Detaching after fork from child process 911]
[14-Feb-2023 12:16:15] NOTICE: ready to handle connections
[14-Feb-2023 12:16:15] NOTICE: systemd monitor interval set to 10000ms
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "thread '<unnamed>' panicked at 'overflow when subtracting durations', library/core/src/time.rs:940:31"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "stack backtrace:"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   0:     0x7fb36d425f74 - std::backtrace_rs::backtrace::libunwind::trace::hee598835bc88d35b"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   1:     0x7fb36d425f74 - std::backtrace_rs::backtrace::trace_unsynchronized::h9cdc730ba5cf5d72"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   2:     0x7fb36d425f74 - std::sys_common::backtrace::_print_fmt::h75aeaf7ed30e43fa"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:66:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   3:     0x7fb36d425f74 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h606862f787600875"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:45:22"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   4:     0x7fb36d23a56c - core::fmt::write::he803f0f418caf762"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/fmt/mod.rs:1190:17"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   5:     0x7fb36d420a1a - std::io::Write::write_fmt::h70bc45872f37e7bb"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/io/mod.rs:1657:15"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   6:     0x7fb36d428a06 - std::sys_common::backtrace::_print::h64d038cf8ac3e13e"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:48:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   7:     0x7fb36d428a06 - std::sys_common::backtrace::print::h359300b4a7fccf65"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:35:9"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   8:     0x7fb36d428a06 - std::panicking::default_hook::{{closure}}::hf51be35e2f510149"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:295:22"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   9:     0x7fb36d428726 - std::panicking::default_hook::h03ca0f22e1d2d25e"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:314:9"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  10:     0x7fb36d4291f6 - std::panicking::rust_panic_with_hook::h3b7380e99b825b63"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:698:17"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  11:     0x7fb36d428ec4 - std::panicking::begin_panic_handler::{{closure}}::h8e849d0710154ce0"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:588:13"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  12:     0x7fb36d4264b4 - std::sys_common::backtrace::__rust_end_short_backtrace::hedcdaddbd4c46cc5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:138:18"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  13:     0x7fb36d428c2d - rust_begin_unwind"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:584:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  14:     0x7fb36d20d643 - core::panicking::panic_fmt::he1bbc7336d49a357"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:143:14"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  15:     0x7fb36d239251 - core::panicking::panic_display::hb184394d54dc8360"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:73:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  16:     0x7fb36d2391fb - core::panicking::panic_str::ha42887cd972750c9"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:56:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  17:     0x7fb36d20d4b6 - core::option::expect_failed::h9159c9d16ed9fb7c"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/option.rs:1852:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  18:     0x7fb36d25f0f5 - core::option::Option<T>::expect::h0146023b03815a23"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/option.rs:715:21"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  19:     0x7fb36d25f0f5 - <core::time::Duration as core::ops::arith::Sub>::sub::h070e83f464182bab"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/time.rs:940:9"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  20:     0x7fb36d25f0f5 - cpu_time::clock_gettime::ThreadTime::duration_since::hfe0cfa2043c9a8b2"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rust/cargo/registry/src/github.com-1ecc6299db9ec823/cpu-time-1.0.0/src/clock_gettime.rs:142:9"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  21:     0x7fb36d25f0f5 - datadog_php_profiling::profiling::Profiler::collect_time::h8a77b6ecbad5744a"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /home/circleci/datadog/profiling/src/profiling.rs:763:40"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  22:     0x7fb36d274fad - datadog_php_profiling::interrupt_function::{{closure}}::h69f58f44f3894c1f"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /home/circleci/datadog/profiling/src/lib.rs:1006:22"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  23:     0x7fb36d274fad - std::thread::local::LocalKey<T>::try_with::h2d0e03924b180471"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/local.rs:413:16"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  24:     0x7fb36d274fad - std::thread::local::LocalKey<T>::with::hcf6fc41472b8ffbb"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/local.rs:389:9"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  25:     0x7fb36d2566c4 - datadog_php_profiling::interrupt_function::h160aae0519bd9947"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /home/circleci/datadog/profiling/src/lib.rs:986:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  26:     0x7fb36d2566c4 - datadog_php_profiling::execute_internal::hf2fbadc1444c8ba0"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /home/circleci/datadog/profiling/src/lib.rs:1042:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  27:     0x7fb36d7fdfe6 - zai_interceptor_execute_internal_impl"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /home/circleci/datadog/tmp/build_extension/zend_abstract_interface/interceptor/php8/interceptor.c:694"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  28:     0x555e345dc0b3 - <unknown>"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  29:     0x555e345dd01a - <unknown>"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  30:     0x7fb36da8af61 - <unknown>"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  31:     0x555e348168bd - zend_execute"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  32:     0x7fb36daab1e8 - bf_load_embedded_code"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  33:     0x7fb36da92700 - zm_activate_blackfire"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  34:     0x555e347acb80 - zend_activate_modules"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  35:     0x555e3474212c - php_request_startup"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  36:     0x555e345e7a9a - <unknown>"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  37:     0x7fb373037083 - __libc_start_main"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /build/glibc-SzIz7B/glibc-2.31/csu/../csu/libc-start.c:308:16"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  38:     0x555e345e8f5e - _start"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  39:                0x0 - <unknown>"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "fatal runtime error: failed to initiate panic, error 5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 exited on signal 6 (SIGABRT - core dumped) after 7.978483 seconds from start
[Detaching after fork from child process 914]
[14-Feb-2023 12:16:23] NOTICE: [pool www] child 914 started
^C
Thread 1 "php-fpm" received signal SIGINT, Interrupt.
0x00007fb37313246e in epoll_wait (epfd=10, events=0x555e35477f00, maxevents=71, timeout=1000) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
30      ../sysdeps/unix/sysv/linux/epoll_wait.c: No such file or directory.
(gdb) bt
#0  0x00007fb37313246e in epoll_wait (epfd=10, events=0x555e35477f00, maxevents=71, timeout=1000) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
#1  0x0000555e348a5677 in ?? ()
#2  0x0000555e34896d51 in ?? ()
#3  0x0000555e34890ca7 in ?? ()
#4  0x0000555e345e750c in ?? ()
#5  0x00007fb373037083 in __libc_start_main (main=0x555e345e6be0, argc=2, argv=0x7ffc7a232968, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffc7a232958) at ../csu/libc-start.c:308
#6  0x0000555e345e8f5e in _start ()

Please let me know if you need more information.

realFlowControl commented 1 year ago

Hello @B-Galati,

this is still with PHP 8.1.14? Can you post me your profiler config? Either a screenshot of the datadog-profiling section of phpinfo() or do a php --ri=datadog-profiling

Thanks in advance Florian

realFlowControl commented 1 year ago

Hello again @B-Galati,

another thing: can you try with datadog.profiling.experimental_cpu_time_enabled turned off and see if PHP-FPM will serve requests?

Kind regards Florian

B-Galati commented 1 year ago

@realFlowControl Still with 8.1.14 yes.

$ php --ri=datadog-profiling

datadog-profiling

Version => 0.13.0
Profiling Enabled => true
Experimental CPU Time Profiling Enabled => true
Experimental Allocation Profiling Enabled => false
Endpoint Collection Enabled => true
Platform's CPU Time API Works => true
Profiling Log Level => off
Profiling Agent Endpoint => http://localhost:8126/
Application's Environment (DD_ENV) =>
Application's Service (DD_SERVICE) => Standard input code
Application's Version (DD_VERSION) =>

Directive => Local Value => Master Value
datadog.profiling.enabled => On => On
datadog.profiling.endpoint_collection_enabled => On => On
datadog.profiling.experimental_cpu_time_enabled => On => On
datadog.profiling.experimental_cpu_enabled => On => On
datadog.profiling.experimental_allocation_enabled => Off => Off
datadog.profiling.log_level => off => off
datadog.profiling.output_pprof => no value => no value

I am going to try to disable datadog.profiling.experimental_cpu_time_enabled and let you know.

B-Galati commented 1 year ago

@realFlowControl Disabling datadog.profiling.experimental_cpu_time_enabled allows PHP-FPM to serve request :heavy_check_mark:

realFlowControl commented 1 year ago

Thanks @B-Galati for checking this. It should be fixed with #1926

B-Galati commented 1 year ago

Thanks! You guys are awesome 👍 What a reactivity!

B-Galati commented 1 year ago

Hi! Do you have an ETA for the next release?

bwoebi commented 1 year ago

Hey @B-Galati, we're targeting next week for the release.

bwoebi commented 1 year ago

Hey @B-Galati, sorry that releasing took a while, but 0.85.0 is out now, with all the fixes. I'll close that issue now, but feel free to re-open if there are still issues.

B-Galati commented 1 year ago

Thank you!! 🎉🙏

B-Galati commented 1 year ago

Hello @bwoebi, that's still KO but I cannot get any backtrace now :thinking:

How could I help?

Here is what I got but I don't think it's gonna help much:

$ gdb php-fpm
GNU gdb (Ubuntu 9.2-0ubuntu1~20.04.1) 9.2
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from php-fpm...
(No debugging symbols found in php-fpm)
(gdb) run -F
Starting program: /usr/local/bin/php-fpm -F
warning: Error disabling address space randomization: Operation not permitted
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7f20f8d34700 (LWP 936)]
[New Thread 0x7f20f8533700 (LWP 937)]
[New Thread 0x7f20f0332700 (LWP 938)]
[22-Mar-2023 16:06:14] NOTICE: [pool www] 'user' directive is ignored when FPM is not running as root
[22-Mar-2023 16:06:14] NOTICE: [pool www] 'group' directive is ignored when FPM is not running as root
[22-Mar-2023 16:06:14] NOTICE: fpm is running, pid 932
[Detaching after fork from child process 939]
[Detaching after fork from child process 940]
[Detaching after fork from child process 941]
[Detaching after fork from child process 942]
[Detaching after fork from child process 943]
[Detaching after fork from child process 944]
[Detaching after fork from child process 945]
[Detaching after fork from child process 946]
[Detaching after fork from child process 947]
[Detaching after fork from child process 948]
[Detaching after fork from child process 949]
[Detaching after fork from child process 950]
[Detaching after fork from child process 951]
[Detaching after fork from child process 952]
[Detaching after fork from child process 953]
[22-Mar-2023 16:06:14] NOTICE: ready to handle connections
[22-Mar-2023 16:06:14] NOTICE: systemd monitor interval set to 10000ms
[New Thread 0x7f20f8332700 (LWP 960)]
[Thread 0x7f20f8332700 (LWP 960) exited]
^C
Thread 1 "php-fpm" received signal SIGINT, Interrupt.
0x00007f2100e4346e in epoll_wait (epfd=11, events=0x55e2cc005c20, maxevents=71, timeout=1000) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
30      ../sysdeps/unix/sysv/linux/epoll_wait.c: No such file or directory.
(gdb) bt
#0  0x00007f2100e4346e in epoll_wait (epfd=11, events=0x55e2cc005c20, maxevents=71, timeout=1000) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
#1  0x000055e2caa1fda7 in ?? ()
#2  0x000055e2caa11481 in ?? ()
#3  0x000055e2caa0b397 in ?? ()
#4  0x000055e2ca761617 in ?? ()
#5  0x00007f2100d48083 in __libc_start_main (main=0x55e2ca760c80, argc=2, argv=0x7ffe9957a128, init=<optimized out>, fini=<optimized out>,
    rtld_fini=<optimized out>, stack_end=0x7ffe9957a118) at ../csu/libc-start.c:308
#6  0x000055e2ca76301e in _start ()

realFlowControl commented 1 year ago

Hello @B-Galati,

we had another issue (#1919) which sounds like it might have the same root cause as your problem. The fix for this is in #1975, has been merged already and will be released in 0.86.0 most likely today or tomorrow.

In short: When running php-fpm as non-root with preloading, the preloading happens in the php-fpm: master process before forking the workers. This leads to a situation where profiling will start in the php-fpm: master process, creating all the threads. When forking workers, only the main thread is forked, leaving it in a state where profiling seems enabled, but all the thread handles are invalid.

B-Galati commented 1 year ago

Thanks for the heads-up! Will try and let you know then. Thanks again 🙏

realFlowControl commented 1 year ago

Hey @B-Galati, 0.86.0 has been released containing the fix 🎉

B-Galati commented 1 year ago

Hey @realFlowControl,

That's still KO sadly :cry:

No backtrace, no error message.

Looks to work fine when commenting out the preload config

realFlowControl commented 1 year ago

Hey there 👋 sorry that this still seems to not fix your problem. Is it still true, that disabling datadog.profiling.experimental_cpu_time_enabled makes it work again? To recap your situation:

PHP 8.1.14 as php-fpm
with datadog-profiling in version 0.15.0 (dd-trace Version 0.86.0)
and php-fpm is not serving requests

Is this correct? Can you attach (or post in a Slack DM) your PHP-FPM logs? If you don't mind, you can sign up to our public Slack where you can find me as "Florian Engelhardt (Datadog)"

B-Galati commented 1 year ago

@realFlowControl hey thanks!

Some updates:

PHP 8.1.17 (fpm-fcgi) (built: Mar 16 2023 14:38:17)
Copyright (c) The PHP Group
Zend Engine v4.1.17, Copyright (c) Zend Technologies
    with Zend OPcache v8.1.17, Copyright (c), by Zend Technologies
    with blackfire v1.86.4~linux-x64-non_zts81, https://blackfire.io, by Blackfire
    with ddtrace v0.86.0, Copyright Datadog, by Datadog
    with datadog-profiling v0.15.0, Copyright Datadog, by Datadog
    with ddappsec v0.7.0, Copyright Datadog, by Datadog

And disabling datadog.profiling.experimental_cpu_time_enabled does not fix the issue.

I have no particular logs with PHP-FPM sadly :sweat_smile:

grigi commented 1 year ago

I have a similar crash that only happens on 0.86.0 (works fine on 0.85.0) for both PHP8.1.17 and PHP8.2.4 docker images (based on php:fpm-bullseye images from dockerhub) in kubernetes.

I only get the issue if profiling is enabled. I get a segfault on both php-fpm and when running CLI scripts.

No difference if I:

Disable OPcache (even built the image without it installed)
Disable datadog.profiling.experimental_cpu_time_enabled
Disable datadog.profiling.endpoint_collection_enabled

if I run with DD_PROFILING_LOG_LEVEL=trace I only get:

$ DD_PROFILING_LOG_LEVEL=trace php artisan migrate
[2023-03-29T13:42:15.540984Z DEBUG datadog_php_profiling] Recognized SAPI: Command Line Interface.
[2023-03-29T13:42:15.541179Z INFO  datadog_php_profiling] CPU Time profiling enabled.
[2023-03-29T13:42:15.543442Z DEBUG datadog_php_profiling::profiling] Started with an upload period of 67 seconds and approximate wall-time period of 10 milliseconds.
[2023-03-29T13:42:15.557658Z TRACE datadog_php_profiling::profiling] Sent stack sample of 5 frames and 2 labels to profiler.
[2023-03-29T13:42:15.567353Z TRACE datadog_php_profiling::profiling] Sent stack sample of 4 frames and 2 labels to profiler.
[2023-03-29T13:42:15.574669Z TRACE datadog_php_profiling::profiling] Sent stack sample of 5 frames and 2 labels to profiler.
[2023-03-29T13:42:15.585434Z TRACE datadog_php_profiling::profiling] Sent stack sample of 17 frames and 2 labels to profiler.
[2023-03-29T13:42:15.598832Z TRACE datadog_php_profiling::profiling] Sent stack sample of 11 frames and 2 labels to profiler.
[2023-03-29T13:42:15.605967Z TRACE datadog_php_profiling::profiling] Sent stack sample of 12 frames and 2 labels to profiler.
[2023-03-29T13:42:15.616126Z TRACE datadog_php_profiling::profiling] Sent stack sample of 8 frames and 2 labels to profiler.
[2023-03-29T13:42:15.626171Z TRACE datadog_php_profiling::profiling] Sent stack sample of 14 frames and 2 labels to profiler.
[2023-03-29T13:42:15.636024Z TRACE datadog_php_profiling::profiling] Sent stack sample of 15 frames and 2 labels to profiler.
[2023-03-29T13:42:15.652225Z TRACE datadog_php_profiling::profiling] Sent stack sample of 13 frames and 2 labels to profiler.
[2023-03-29T13:42:15.665501Z TRACE datadog_php_profiling::profiling] Sent stack sample of 13 frames and 2 labels to profiler.
[2023-03-29T13:42:15.677359Z TRACE datadog_php_profiling::profiling] Sent stack sample of 16 frames and 2 labels to profiler.
Segmentation fault

Which doesn't seem useful.

Downgrading to 0.85.0 seems to resolve the issue for us. So this may not be identical issue to the OP, but this is the closest in behaviour that I can determine.

realFlowControl commented 1 year ago

Hey @grigi,

I see you don't get a core dump, which would be super useful for us. Our troubleshooting guide could help you setup everything so that you get a core dump and could provide us with a backtrace to this segmentation fault.

Let me know if you need additional help obtaining a core dump.

grigi commented 1 year ago

I have not been able to replicate the issue outside of our production kubernetes cluster. Inside the kubernetes cluster, the pods have a policy that enforces to run as non-root (also /proc/sys/fs/suid_dumpable is 0) and with a readonly root filesystem.

Unfortunarely I don't think I'll be able to get you a core dump anytime soon.

ElijahLynn commented 1 year ago

crosslinking related sigsegv/segfault issue that was fixed on March 30th with 0.86.1 https://github.com/DataDog/dd-trace-php/issues/1993

realFlowControl commented 1 year ago

Hey there 👋 this should be fixed via #2013 and was just released as 0.87.0. I'll close this issue now, but feel free to re-open if there are still issues.

DataDog / dd-trace-php