PHP CLI process hangs on the PeriodicTaskExecutor destructor's thread_.join() call

Describe the bug In our setup a main PHP CLI process triggered by cron is creating sub PHP processes to do work parallelly. We have observed that after some time, there are multiple child processes that are stuck. Their unit of work is completed, but they are not terminating. Upon further investigating these processes, we have seen that they are waiting for a lock to be released. After reproducing the issue locally we have seen in the traces that the PHP CLI process hangs on the PeriodicTaskExecutor class destructor's thread_.join() call.

strace outpout of the stuck process

strace: Process 488 attached
futex(0x7f66c8bff910, FUTEX_WAIT_BITSET|FUTEX_CLOCK_REALTIME, 492, NULL, FUTEX_BITSET_MATCH_ANY

gbd backtrace

(gdb) backtrace
#0  __futex_abstimed_wait_common64 (private=128, cancel=true, abstime=0x0, op=265, expected=492, futex_word=0x7f66c8bff910) at ./nptl/futex-internal.c:57
#1  __futex_abstimed_wait_common (cancel=true, private=128, abstime=0x0, clockid=0, expected=492, futex_word=0x7f66c8bff910) at ./nptl/futex-internal.c:87
#2  __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x7f66c8bff910, expected=492, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=128) at ./nptl/futex-internal.c:139
#3  0x00007f66d0636624 in __pthread_clockjoin_ex (threadid=140079431415360, thread_return=0x0, clockid=0, abstime=0x0, block=<optimized out>) at ./nptl/pthread_join_common.c:105
#4  0x00007f66c93d9a63 in __gthread_join (__value_ptr=0x0, __threadid=<optimized out>) at /home/build/prerequisities/gcc-12.2.0/x86_64-linux-gnu/libstdc++-v3/include/x86_64-linux-gnu/bits/gthr-default.h:669
#5  std::thread::join (this=0x5653fcdf7688) at ../../../.././libstdc++-v3/src/c++11/thread.cc:112
#6  0x00007f66c9328f1a in elasticapm::php::PeriodicTaskExecutor::~PeriodicTaskExecutor (this=0x5653fcdf7640, __in_chrg=<optimized out>) at /source/agent/native/libcommon/code/./PeriodicTaskExecutor.h:35
#7  elasticapm::php::PeriodicTaskExecutor::~PeriodicTaskExecutor (this=0x5653fcdf7640, __in_chrg=<optimized out>) at /source/agent/native/libcommon/code/./PeriodicTaskExecutor.h:37
#8  std::default_delete<elasticapm::php::PeriodicTaskExecutor>::operator() (__ptr=0x5653fcdf7640, this=<optimized out>) at /opt/gcc-12.2.0/include/c++/12.2.0/bits/unique_ptr.h:95
#9  std::unique_ptr<elasticapm::php::PeriodicTaskExecutor, std::default_delete<elasticapm::php::PeriodicTaskExecutor> >::~unique_ptr (this=0x5653fce212c8, __in_chrg=<optimized out>) at /opt/gcc-12.2.0/include/c++/12.2.0/bits/unique_ptr.h:396
#10 elasticapm::php::AgentGlobals::~AgentGlobals (this=0x5653fce21290, __in_chrg=<optimized out>) at /source/agent/native/libcommon/code/./AgentGlobals.h:12
#11 zm_globals_dtor_elastic_apm (elastic_apm_globals=0x7f66c947dd80 <elastic_apm_globals>) at /source/agent/native/ext/elastic_apm.cpp:299
#12 0x00005653fafc4758 in module_destructor (module=0x7f66c947d8a0 <elastic_apm_module_entry>) at ./Zend/zend_API.c:3075
#13 0x00005653fafd1015 in _zend_hash_del_el_ex (prev=<optimized out>, p=0x5653fca2df00, idx=59, ht=0x5653fb2458a0 <module_registry>) at ./Zend/zend_hash.c:1425
#14 _zend_hash_del_el (p=0x5653fca2df00, idx=59, ht=0x5653fb2458a0 <module_registry>) at ./Zend/zend_hash.c:1452
#15 zend_hash_graceful_reverse_destroy (ht=0x5653fb2458a0 <module_registry>) at ./Zend/zend_hash.c:1977
#16 0x00005653fafc2e96 in zend_destroy_modules () at ./Zend/zend_API.c:2384
#17 0x00005653fafbded7 in zend_shutdown () at ./Zend/zend.c:1099
#18 0x00005653faf575ba in php_module_shutdown () at ./main/main.c:2453
#19 php_module_shutdown () at ./main/main.c:2430
#20 0x00005653fadecbf2 in main (argc=5, argv=0x5653fc9e96e0) at ./sapi/cli/php_cli.c:1346

To Reproduce Running the following setup reproduces the situation consistently for me:

Files:
- ./Dockerfile
```
FROM ubuntu:22.04
ARG DEBIAN_FRONTEND=noninteractive
ARG PHP_VERSION=8.2
```
RUN apt -y update RUN apt-get -y install software-properties-common RUN apt-get -y install tar gdb strace

RUN add-apt-repository -c main -c main/debug ppa:ondrej/php RUN apt -y update

RUN apt-get -y install php${PHP_VERSION} php${PHP_VERSION}-cli-dbgsym RUN update-alternatives --set php /usr/bin/php${PHP_VERSION}

RUN apt-get -y install php${PHP_VERSION}-dom php${PHP_VERSION}-mysql php${PHP_VERSION}-soap

ADD --chmod=0755 https://github.com/elastic/apm-agent-php/releases/download/v1.13.0/apm-agent-php_1.13.0_amd64.deb /root ADD --chmod=0755 https://github.com/elastic/apm-agent-php/releases/download/v1.13.0/apm-agent-php-debugsymbols-linux-x86-64.tar /root

RUN dpkg -i /root/apm-agent-php_1.13.0_amd64.deb RUN tar xvf /root/apm-agent-php-debugsymbols-linux-x86-64.tar -C /usr/lib/debug

RUN touch /var/log/apm_process.log

COPY ./src /root/src WORKDIR /root/src
```
- ./docker-compose.yml
```
name: apm_process services: apm_process: build: context: "." args: PHP_VERSION: ${PHP_VERSION-8.2} volumes:
- "./src:/root/src"
- "./99-elastic-apm-custom.ini:/etc/php/${PHP_VERSION-8.2}/cli/conf.d/99-elastic-apm-custom.ini" cap_add:
- SYS_PTRACE tty: true stdin_open: true
```
- ./99-elastic-apm-custom.ini
```
  [elastic] elastic_apm.enabled = true elastic_apm.secret_token = "{{REPLACE_ME}}" elastic_apm.server_url = "{{REPLACE_ME}}" elastic_apm.environment = "local" elastic_apm.log_level = "DEBUG" elastic_apm.log_level_stderr = "DEBUG" elastic_apm.server_timeout = "30s" elastic_apm.service_name = "apm_process" elastic_apm.service_version = "v1" elastic_apm.transaction_max_spans = 500 elastic_apm.transaction_sample_rate = 1.0 elastic_apm.verify_server_cert = true elastic_apm.dev_internal_backend_comm_log_verbose = true elastic_apm.profiling_inferred_spans_enabled = true
```
- ./src/test.php
```
  <?php
use Elastic\Apm\ElasticApm;

chdir(DIR); $transaction = ElasticApm::getCurrentTransaction(); $transaction->setName('PARENT');

echo 'PARENT transaction id:' . $transaction->getId() . "\n";

for ($i = 0; $i < 10000; $i++) { $param = random_int(0, 60);
```
$command = "nohup /usr/bin/php -f run.php " . $param . " " . getmypid() . '-' . $i . " 2>>/var/log/apm_process.log 1>&2 &";
echo "Running: " . $command . "\n";

$span = $transaction->beginChildSpan('child span ' . $i, 'process', 'run.php', 'execute');
shell_exec($command);
$span->end();

$sleepBetweenChildren = random_int(0, 1000);
echo "Sleeping for " . $sleepBetweenChildren . "(us)\n";
usleep($sleepBetweenChildren);
```
}
```
- ./src/run.php
```
<?php

use Elastic\Apm\ElasticApm;

$transaction = ElasticApm::getCurrentTransaction(); $transaction->setName('CHILD'); echo getmypid() . ' Child transaction id:' . $transaction->getId() . "\n";

$span = $transaction->beginChildSpan('wait', 'custom'); $sleepTime = $argv[1]; echo getmypid() . ' Child sleep for ' . $sleepTime . "(ms)\n"; usleep(1000 * $sleepTime); $span->end();
Steps:
1. docker compose up
2. docker compose exec apm_process /bin/bash
3. php test.php 2>>/var/log/apm_process.log 1>&2
4. After the process finished, check with top command the list of processes and there should be at least one, but possibly multiple like this /usr/bin/php -f run.php {{delay_time}} {{main_process_id}}-{{counter_of_child_processes}} stuck forever.
5. with strace -p {{process_id}} we should see that the process is stuck on a futex() call like above.
Notes:
- The issue is possibly a race condition, so it might take a few runs to reproduce, but for me the above setup consistently ended in multiple stuck processes.
- I have originally started with our production setup and dependencies to reproduce the issue, but managed to strip down to this relative minimalistic example. The 3 extensions (dom, mysql, soap) seems to be needed to reproduce the issue. If any of them is taken out of the example, the problem did not occur for me.

Expected behavior PHP process should not stuck upon terminating when APM extension is enabled.

elastic / apm-agent-php

PHP CLI process hangs on the PeriodicTaskExecutor destructor's thread_.join() call #1209