[php-src] Issue #15161: Seeing randomly frequent SIGKILL messages in logs, followed by PHP FPM service failure

From: Date: Tue, 30 Jul 2024 00:13:20 +0000
Subject: [php-src] Issue #15161: Seeing randomly frequent SIGKILL messages in logs, followed by PHP FPM service failure
Groups: php.bugs 
Request: Send a blank email to php-bugs+get-247396@lists.php.net to get a copy of this message
Issue: https://github.com/php/php-src/issues/15161 Author: dale-c-anderson ### Description We've got a lovely production-only bug here running PHP FPM & NGINX I'm looking for guidance on how to determine what's causing this. After several days of trying to reproduce or get any more dirt on what's happening, the team is starting to suspect a bug in PHP. Nothing had changed in our deployed PHP (Drupal 10) application for at least a week , and then from out of nowhere, the following sigkill messages start flooding the log files of both our load balanced ec2 worker nodes, at the rate of about one every other second: ``` [25-Jul-2024 23:45:38] WARNING: [pool xxxxxx] child 33944 exited on signal 9 (SIGKILL) after 12.011399 seconds from start [25-Jul-2024 23:45:40] WARNING: [pool xxxxxx] child 33953 exited on signal 9 (SIGKILL) after 12.010867 seconds from start [25-Jul-2024 23:45:42] WARNING: [pool xxxxxx] child 33968 exited on signal 9 (SIGKILL) after 12.009866 seconds from start [25-Jul-2024 23:45:44] WARNING: [pool xxxxxx] child 33979 exited on signal 9 (SIGKILL) after 12.009435 seconds from start [25-Jul-2024 23:45:46] WARNING: [pool xxxxxx] child 33988 exited on signal 9 (SIGKILL) after 12.007592 seconds from start [25-Jul-2024 23:45:48] WARNING: [pool xxxxxx] child 33997 exited on signal 9 (SIGKILL) after 12.009038 seconds from start [25-Jul-2024 23:45:50] WARNING: [pool xxxxxx] child 34011 exited on signal 9 (SIGKILL) after 12.009187 seconds from start [25-Jul-2024 23:45:52] WARNING: [pool xxxxxx] child 34027 exited on signal 9 (SIGKILL) after 12.009532 seconds from start ``` **Problem behavior** * About 30-60 minutes after these sigkill messages start happening, PHP FPM starts to fail, and Nginx starts returning 502 Bad Gateway errors. * Sometimes these messages only appear on one ec2, sometimes they're on both. * The warnings started last thursday AM and persisted all day, then almost didn't appear at all on friday, even though friday was almost identical traffic load. * There was one burst of them this morning (monday) on only one node, and then nothing since. * The sigkills return randomly and without warning. * It does appear to happen more often during busier periods. The site's traffic is mostly used by a corporate audience, so M-F 9-5 is the traffic pattern. **What we've tried and checked** * There's no shortage of resources. At least 13 GB unused memory on each node, CPU load of 10-20%, almost no disk activity * There's no corresponding errors in our application-level PHP FPM logs. * The number of active child PHP FPM process typically sits between 0 and 3, with 7 total running, and in the busiest part of the day, total child processes will go as high as 15 , but nowhere near maxing out. * Adding auditd to the system, and trying to suss out the origin of the sigkill with ``` auditctl -a always,exit -F arch=b64 -F a1=9 -S kill -k log_kill ``` turned up nothing. None of the sigkills have appeared in the audit log. **Current workaround** Reloading or restarting the PHP FPM 8.1 temporarily resolves the issue after it's started, so when there's no one on deck to step in (or catch this thing in the act), we have cron automatically reloading the service on each ec2 every 20 minutes, which is short enough to keep the sigkill messages from even starting. --------- **Environment** Let me know what else might be relevant here: ``` $ php8.1 --version PHP 8.1.29 (cli) (built: Jun 6 2024 16:52:57) (NTS) Copyright (c) The PHP Group Zend Engine v4.1.29, Copyright (c) Zend Technologies with Zend OPcache v8.1.29, Copyright (c), by Zend Technologies $ uname -a Linux xxxxx 5.15.0-1065-aws #71~20.04.1-Ubuntu SMP Fri Jun 28 19:58:04 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux $ cat /etc/*release DISTRIB_ID=Ubuntu DISTRIB_RELEASE=20.04 DISTRIB_CODENAME=focal DISTRIB_DESCRIPTION="Ubuntu 20.04.6 LTS" NAME="Ubuntu" VERSION="20.04.6 LTS (Focal Fossa)" ID=ubuntu ID_LIKE=debian PRETTY_NAME="Ubuntu 20.04.6 LTS" VERSION_ID="20.04" HOME_URL="https://www.ubuntu.com/" SUPPORT_URL="https://help.ubuntu.com/" BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/" PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy" VERSION_CODENAME=focal UBUNTU_CODENAME=focal $ nginx -V nginx version: nginx/1.18.0 (Ubuntu) built with OpenSSL 1.1.1f 31 Mar 2020 TLS SNI support enabled configure arguments: --with-cc-opt='-g -O2 -fdebug-prefix-map=/build/nginx-BUo7Uw/nginx-1.18.0=. -fstack-protector-strong -Wformat -Werror=format-security -fPIC -Wdate-time -D_FORTIFY_SOURCE=2' --with-ld-opt='-Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-z,now -fPIC' --prefix=/usr/share/nginx --conf-path=/etc/nginx/nginx.conf --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log --lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid --modules-path=/usr/lib/nginx/modules --http-client-body-temp-path=/var/lib/nginx/body --http-fastcgi-temp-path=/var/lib/nginx/fastcgi --http-proxy-temp-path=/var/lib/nginx/proxy --http-scgi-temp-path=/var/lib/nginx/scgi --http-uwsgi-temp-path=/var/lib/nginx/uwsgi --with-compat --with-debug --with-pcre-jit --with-http_ssl_module --with-http_stub_status_module --with-http_realip_module --with-http_auth_request_module --with-http_v2_module --with-http_dav_module --with-http_slice_module --with-threads --with-http_addition_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_sub_module $ free -h total used free shared buff/cache available Mem: 15Gi 1.6Gi 10Gi 65Mi 3.5Gi 13Gi Swap: 0B 0B 0B ``` file: /etc/php/8.1/fpm/php-fpm.conf ``` [global] pid = /run/php/php8.1-fpm.pid error_log = /var/log/php8.1-fpm.log include=/etc/php/8.1/fpm/pool.d/*.conf ``` file: /etc/php/8.1/fpm/pool.d/application.conf ``` [myapp] user = myserviceuser group = myservicegroup listen = /var/run/php8.1-fpm-my-app.sock listen.owner = www-data listen.group = www-data pm = static pm.max_children = 45 pm.start_servers = 2 pm.min_spare_servers = 1 pm.max_spare_servers = 3 pm.max_requests = 250 pm.status_path = /status catch_workers_output = no chdir = / php_admin_flag[log_errors] = on php_admin_value[error_log] = /var/log/vhosts/myuser/myapp/php-fpm-error.log php_admin_value[max_execution_time] = 300 php_admin_value[default_socket_timeout] = 300 security.limit_extensions = .php php_admin_value[open_basedir] = "/home/myuser/www/myapp/:/tmp/" php_value[newrelic.appname] = "my-app (production @ aws)" php_flag[expose_php] = off php_admin_value[upload_max_filesize] = 100M php_admin_value[post_max_size] = 100M php_admin_value[memory_limit] = 256M php_admin_value[max_input_vars] = 3001 php_admin_value[short_open_tag] = Off php_admin_value[request_slowlog_timeout] = 5s php_admin_value[slowlog] = /var/log/vhosts/myuser/myapp/php-fpm-slow.log ``` file: /etc/php/8.1/fpm/pool.d/www.conf # not actually used for anything, but still technically part of the config ``` [www] user = www-data group = www-data listen = /run/php/php8.1-fpm.sock listen.owner = www-data listen.group = www-data pm = dynamic pm.max_children = 5 pm.start_servers = 2 pm.min_spare_servers = 1 pm.max_spare_servers = 3 ``` ### PHP Version PHP 8.1.29 ### Operating System Ubuntu 20.04.6 LTS

« previous php.bugs (#247396) next »