Fix FPM request_terminate_timeout not working (#692)

With HEROKU_PHP_GRACEFUL_SIGTERM=1, FPM children ignore SIGTERM (as sent by e.g. Heroku's process supervisor to all processes) so that the boot scripts can perform a clean shutdown by issuing SIGQUIT.

However, FPM internally depends on SIGTERM for terminating requests that exceed the timeout, so that's now being ignored.

We can, however, use SIGINT in this case, as it serves the same purpose.

Tests adapted to cover this case (the termination did previously work in some cases, e.g. when the script simply does a `sleep()`, as that is still interrupted by an incoming signal, even if the signal is being ignored).

GUS-W-14850175

CHANGELOG.md

@@ -13,6 +13,7 @@
 ### FIX
 
 - PHP `memory_limit` in `.user.ini` does not override PHP-FPM `php_value` for `$WEB_CONCURRENCY` calculation [David Zuelke]
+- PHP-FPM `request_terminate_timeout` may have no effect [David Zuelke]
 
 ## [v244] - 2024-01-24
 

support/build/patches/php/7/4/ignoresigterm.patch

@@ -0,0 +1,120 @@
+diff --git a/sapi/fpm/fpm/fpm_process_ctl.c b/sapi/fpm/fpm/fpm_process_ctl.c
+index 7a55d98b04..ba43ed5bfb 100644
+--- a/sapi/fpm/fpm/fpm_process_ctl.c
++++ b/sapi/fpm/fpm/fpm_process_ctl.c
+@@ -145,6 +145,12 @@ int fpm_pctl_kill(pid_t pid, int how) /* {{{ */
+ 		default :
+ 			break;
+ 	}
++
++	if (s == SIGTERM && fpm_signals_have_ignore_sigterm()) {
++		zlog(ZLOG_DEBUG, "Re-mapping SIGTERM to SIGINT due to HEROKU_PHP_GRACEFUL_SIGTERM");
++		s = SIGINT;
++	}
++
+ 	return kill(pid, s);
+ }
+ /* }}} */
+@@ -200,6 +206,11 @@ static void fpm_pctl_action_next()
+ 		timeout = 1;
+ 	}
+
++	if (sig == SIGTERM && fpm_signals_have_ignore_sigterm()) {
++		zlog(ZLOG_DEBUG, "Re-mapping SIGTERM to SIGINT due to HEROKU_PHP_GRACEFUL_SIGTERM");
++		sig = SIGINT;
++	}
++
+ 	fpm_pctl_kill_all(sig);
+ 	fpm_signal_sent = sig;
+ 	fpm_pctl_timeout_set(timeout);
+diff --git a/sapi/fpm/fpm/fpm_signals.c b/sapi/fpm/fpm/fpm_signals.c
+index aca7c9ed58..d81014a08a 100644
+--- a/sapi/fpm/fpm/fpm_signals.c
++++ b/sapi/fpm/fpm/fpm_signals.c
+@@ -21,6 +21,7 @@
+ static int sp[2];
+ static sigset_t block_sigset;
+ static sigset_t child_block_sigset;
++static int ignore_sigterm = 0;
+
+ const char *fpm_signal_names[NSIG + 1] = {
+ #ifdef SIGHUP
+@@ -182,9 +183,17 @@ static void sig_handler(int signo) /* {{{ */
+ }
+ /* }}} */
+
++int fpm_signals_have_ignore_sigterm(void)
++{
++	return ignore_sigterm;
++}
++
+ int fpm_signals_init_main() /* {{{ */
+ {
+-	struct sigaction act;
++	struct sigaction act, act_ign;
++
++	char* heroku_php_graceful_sigterm = getenv("HEROKU_PHP_GRACEFUL_SIGTERM");
++	ignore_sigterm = heroku_php_graceful_sigterm && atoi(heroku_php_graceful_sigterm);
+
+ 	if (0 > socketpair(AF_UNIX, SOCK_STREAM, 0, sp)) {
+ 		zlog(ZLOG_SYSERROR, "failed to init signals: socketpair()");
+@@ -205,7 +214,11 @@ int fpm_signals_init_main()
+ 	act.sa_handler = sig_handler;
+ 	sigfillset(&act.sa_mask);
+
+-	if (0 > sigaction(SIGTERM,  &act, 0) ||
++	memset(&act_ign, 0, sizeof(act_ign));
++	act_ign.sa_handler = SIG_IGN;
++
++	zlog(ZLOG_DEBUG, "HEROKU_PHP_GRACEFUL_SIGTERM is %d", fpm_signals_have_ignore_sigterm());
++	if (0 > sigaction(SIGTERM,  fpm_signals_have_ignore_sigterm() ? &act_ign : &act, 0) ||
+ 	    0 > sigaction(SIGINT,   &act, 0) ||
+ 	    0 > sigaction(SIGUSR1,  &act, 0) ||
+ 	    0 > sigaction(SIGUSR2,  &act, 0) ||
+@@ -225,20 +238,24 @@ int fpm_signals_init_main()
+
+ int fpm_signals_init_child()
+ {
+-	struct sigaction act, act_dfl;
++	struct sigaction act, act_dfl, act_ign;
+
+ 	memset(&act, 0, sizeof(act));
+ 	memset(&act_dfl, 0, sizeof(act_dfl));
++	memset(&act_ign, 0, sizeof(act_ign));
+
+ 	act.sa_handler = &sig_soft_quit;
+ 	act.sa_flags |= SA_RESTART;
+
+ 	act_dfl.sa_handler = SIG_DFL;
+
++	act_ign.sa_handler = SIG_IGN;
++
+ 	close(sp[0]);
+ 	close(sp[1]);
+
+-	if (0 > sigaction(SIGTERM,  &act_dfl,  0) ||
++	zlog(ZLOG_DEBUG, "HEROKU_PHP_GRACEFUL_SIGTERM is %d", fpm_signals_have_ignore_sigterm());
++	if (0 > sigaction(SIGTERM,  fpm_signals_have_ignore_sigterm() ? &act_ign : &act_dfl,  0) ||
+ 	    0 > sigaction(SIGINT,   &act_dfl,  0) ||
+ 	    0 > sigaction(SIGUSR1,  &act_dfl,  0) ||
+ 	    0 > sigaction(SIGUSR2,  &act_dfl,  0) ||
+@@ -289,6 +306,7 @@ int fpm_signals_init_mask()
+ 		}
+ 	}
+ 	if (0 > sigaddset(&child_block_sigset, SIGTERM) ||
++	    0 > sigaddset(&child_block_sigset, SIGINT) ||
+ 	    0 > sigaddset(&child_block_sigset, SIGQUIT)) {
+ 		zlog(ZLOG_SYSERROR, "failed to prepare child signal block mask: sigaddset()");
+ 		return -1;
+diff --git a/sapi/fpm/fpm/fpm_signals.h b/sapi/fpm/fpm/fpm_signals.h
+index 67c12efdf4..808263102c 100644
+--- a/sapi/fpm/fpm/fpm_signals.h
++++ b/sapi/fpm/fpm/fpm_signals.h
+@@ -5,6 +5,7 @@
+
+ #include <signal.h>
+
++int fpm_signals_have_ignore_sigterm(void);
+ int fpm_signals_init_main();
+ int fpm_signals_init_child();
+ int fpm_signals_get_fd();

support/build/patches/php/ignoresigterm.patch

@@ -0,0 +1,120 @@
+diff --git a/sapi/fpm/fpm/fpm_process_ctl.c b/sapi/fpm/fpm/fpm_process_ctl.c
+index 7a55d98b04..ba43ed5bfb 100644
+--- a/sapi/fpm/fpm/fpm_process_ctl.c
++++ b/sapi/fpm/fpm/fpm_process_ctl.c
+@@ -145,6 +145,12 @@ int fpm_pctl_kill(pid_t pid, int how) /* {{{ */
+ 		default :
+ 			break;
+ 	}
++
++	if (s == SIGTERM && fpm_signals_have_ignore_sigterm()) {
++		zlog(ZLOG_DEBUG, "Re-mapping SIGTERM to SIGINT due to HEROKU_PHP_GRACEFUL_SIGTERM");
++		s = SIGINT;
++	}
++
+ 	return kill(pid, s);
+ }
+ /* }}} */
+@@ -200,6 +206,11 @@ static void fpm_pctl_action_next(void)
+ 		timeout = 1;
+ 	}
+
++	if (sig == SIGTERM && fpm_signals_have_ignore_sigterm()) {
++		zlog(ZLOG_DEBUG, "Re-mapping SIGTERM to SIGINT due to HEROKU_PHP_GRACEFUL_SIGTERM");
++		sig = SIGINT;
++	}
++
+ 	fpm_pctl_kill_all(sig);
+ 	fpm_signal_sent = sig;
+ 	fpm_pctl_timeout_set(timeout);
+diff --git a/sapi/fpm/fpm/fpm_signals.c b/sapi/fpm/fpm/fpm_signals.c
+index aca7c9ed58..d81014a08a 100644
+--- a/sapi/fpm/fpm/fpm_signals.c
++++ b/sapi/fpm/fpm/fpm_signals.c
+@@ -21,6 +21,7 @@
+ static int sp[2];
+ static sigset_t block_sigset;
+ static sigset_t child_block_sigset;
++static int ignore_sigterm = 0;
+
+ const char *fpm_signal_names[NSIG + 1] = {
+ #ifdef SIGHUP
+@@ -182,9 +183,17 @@ static void sig_handler(int signo) /* {{{ */
+ }
+ /* }}} */
+
++int fpm_signals_have_ignore_sigterm(void)
++{
++	return ignore_sigterm;
++}
++
+ int fpm_signals_init_main(void)
+ {
+-	struct sigaction act;
++	struct sigaction act, act_ign;
++
++	char* heroku_php_graceful_sigterm = getenv("HEROKU_PHP_GRACEFUL_SIGTERM");
++	ignore_sigterm = heroku_php_graceful_sigterm && atoi(heroku_php_graceful_sigterm);
+
+ 	if (0 > socketpair(AF_UNIX, SOCK_STREAM, 0, sp)) {
+ 		zlog(ZLOG_SYSERROR, "failed to init signals: socketpair()");
+@@ -205,7 +214,11 @@ int fpm_signals_init_main(void)
+ 	act.sa_handler = sig_handler;
+ 	sigfillset(&act.sa_mask);
+
+-	if (0 > sigaction(SIGTERM,  &act, 0) ||
++	memset(&act_ign, 0, sizeof(act_ign));
++	act_ign.sa_handler = SIG_IGN;
++
++	zlog(ZLOG_DEBUG, "HEROKU_PHP_GRACEFUL_SIGTERM is %d", fpm_signals_have_ignore_sigterm());
++	if (0 > sigaction(SIGTERM,  fpm_signals_have_ignore_sigterm() ? &act_ign : &act, 0) ||
+ 	    0 > sigaction(SIGINT,   &act, 0) ||
+ 	    0 > sigaction(SIGUSR1,  &act, 0) ||
+ 	    0 > sigaction(SIGUSR2,  &act, 0) ||
+@@ -225,20 +238,24 @@ int fpm_signals_init_main(void)
+
+ int fpm_signals_init_child(void)
+ {
+-	struct sigaction act, act_dfl;
++	struct sigaction act, act_dfl, act_ign;
+
+ 	memset(&act, 0, sizeof(act));
+ 	memset(&act_dfl, 0, sizeof(act_dfl));
++	memset(&act_ign, 0, sizeof(act_ign));
+
+ 	act.sa_handler = &sig_soft_quit;
+ 	act.sa_flags |= SA_RESTART;
+
+ 	act_dfl.sa_handler = SIG_DFL;
+
++	act_ign.sa_handler = SIG_IGN;
++
+ 	close(sp[0]);
+ 	close(sp[1]);
+
+-	if (0 > sigaction(SIGTERM,  &act_dfl,  0) ||
++	zlog(ZLOG_DEBUG, "HEROKU_PHP_GRACEFUL_SIGTERM is %d", fpm_signals_have_ignore_sigterm());
++	if (0 > sigaction(SIGTERM,  fpm_signals_have_ignore_sigterm() ? &act_ign : &act_dfl,  0) ||
+ 	    0 > sigaction(SIGINT,   &act_dfl,  0) ||
+ 	    0 > sigaction(SIGUSR1,  &act_dfl,  0) ||
+ 	    0 > sigaction(SIGUSR2,  &act_dfl,  0) ||
+@@ -289,6 +306,7 @@ int fpm_signals_init_mask(void)
+ 		}
+ 	}
+ 	if (0 > sigaddset(&child_block_sigset, SIGTERM) ||
++	    0 > sigaddset(&child_block_sigset, SIGINT) ||
+ 	    0 > sigaddset(&child_block_sigset, SIGQUIT)) {
+ 		zlog(ZLOG_SYSERROR, "failed to prepare child signal block mask: sigaddset()");
+ 		return -1;
+diff --git a/sapi/fpm/fpm/fpm_signals.h b/sapi/fpm/fpm/fpm_signals.h
+index 67c12efdf4..808263102c 100644
+--- a/sapi/fpm/fpm/fpm_signals.h
++++ b/sapi/fpm/fpm/fpm_signals.h
+@@ -5,6 +5,7 @@
+
+ #include <signal.h>
+
++int fpm_signals_have_ignore_sigterm(void);
+ int fpm_signals_init_main(void);
+ int fpm_signals_init_child(void);
+ int fpm_signals_get_fd(void);

support/build/php

@@ -69,7 +69,7 @@ fi
 
 # freetype-config is gone on 20.04, but 7.3 doesn't use pkg-config yet
 if [[ $STACK == "heroku-20" && $dep_version == 7.3.* ]]; then
-	patch -p1 < "$(dirname "$BASH_SOURCE")/patches/php-freetype-pkgconfig.patch"
+	patch -p1 < "$(dirname "$BASH_SOURCE")/patches/php/7/3/freetype-pkgconfig.patch"
 	# we changed config.m4 for GD, re-generate configure
 	./buildconf --force
 fi
@@ -81,7 +81,13 @@ fi
 # see the AC_DEFUN([AC_FPM_TRACE] bits in sapi/fpm/config.m4
 sed -i 's/have_ptrace=yes/have_ptrace=no/' configure
 
-patch -p1 < $(dirname $BASH_SOURCE)/patches/php-ignoresigterm.patch
+if [[ $dep_version == 7.4.* ]]; then
+	patch -p1 < "$(dirname $BASH_SOURCE)/patches/php/7/4/ignoresigterm.patch"
+elif [[ $dep_version == 7.* ]]; then
+	patch -p1 < "$(dirname $BASH_SOURCE)/patches/php/7/ignoresigterm.patch"
+else
+	patch -p1 < "$(dirname $BASH_SOURCE)/patches/php/ignoresigterm.patch"
+fi
 
 configureopts=()
 if [[ $dep_version == 7.3.* ]]; then

test/fixtures/sigterm/index.php

@@ -1,9 +1,21 @@
 <?php
 
-$wait = (int)($_GET['wait']??0);
+// we can't simply use sleep() because signals will interrupt that
+function wait($wait = 1)
+{
+	$nano = 0;
+	while(($res = time_nanosleep($wait, $nano)) !== true) {
+		if($res === false) die("uhm, wat?");
+		$wait = $res["seconds"];
+		$nano = $res["nanoseconds"];
+		file_put_contents("php://stderr", sprintf("signal interrupted, resuming nanosleep with %s.%s us remaining\n", $wait, $nano));
+	};
+}
 
-sleep($wait);
+$wait = (int)($_GET['wait']??5);
+$start = hrtime(true);
+wait($wait);
 
-echo "hello world after $wait second(s)\n";
+printf("hello world after %s us (expected %s s)\n", hrtime(true)-$start, $wait);
 
 file_put_contents("php://stderr", "request complete");

test/spec/php_sigterm_shared.rb

@@ -22,7 +22,7 @@
 			cmd = "heroku-php-#{server} & pid=$! ; sleep 5; curl \"localhost:$PORT/index.php?wait=5\" & sleep 2; kill $pid; wait $pid"
 			retry_until retry: 3, sleep: 5 do
 				output = @app.run(cmd)
-				expect(output).to match(/^hello world after 5 second\(s\)$/)
+				expect(output).to match(/^hello world after 5\d{9} us \(expected 5 s\)$/)
 				expect(output).to match(/^request complete$/) # ensure a late log line is captured, meaning the logs tail process stays alive until the end
 			end
 		end
@@ -37,23 +37,35 @@
 			cmd = "heroku-php-#{server} & pid=$! ; sleep 5; curl \"localhost:$PORT/index.php?wait=5\" & curlpid=$!; sleep 2; kill $(pgrep -U $UID | grep -vw -e $$ -e $curlpid) 2>/dev/null; wait $pid"
 			retry_until retry: 3, sleep: 5 do
 				output = @app.run(cmd)
-				expect(output).to match(/^hello world after 5 second\(s\)$/)
+				expect(output).to match(/^hello world after 5\d{9} us \(expected 5 s\)$/)
 				expect(output).to match(/^request complete$/) # ensure a late log line is captured, meaning the logs tail process stays alive until the end
 			end
 		end
 
 		it "logs slowness, prints a trace, and terminates the process after configured timeouts" do
+			wait_script = "index.php"
+			wait_line = 17
+			wait_secs = 5
+			timeout_secs = 3
 			# launch web server wrapped in a 10 second timeout
 			# once web server is ready, `read` unblocks and we curl the sleep() script which will take a few seconds to run
 			# after `curl` completes, `waitforit.sh` will shut down
-			cmd = "./waitforit.sh 10 'ready for connections' heroku-php-#{server} -F fpm.request_slowlog_timeout.conf --verbose | { read && curl \"localhost:$PORT/index.php?wait=5\"; }"
+			cmd = "./waitforit.sh 10 'ready for connections' heroku-php-#{server} -F fpm.request_slowlog_timeout.conf --verbose | { read && curl \"localhost:$PORT/#{wait_script}?wait=#{wait_secs}\"; }"
 			retry_until retry: 3, sleep: 5 do
 				output = @app.run(cmd)
 				# ensure slowlog info and trace is there
 				expect(output).to include("executing too slow")
-				expect(output).to include("sleep() /app/index.php:5")
-				# ensure termination info is there
-				expect(output).to match(/execution timed out/)
+				expect(output).to include("wait() /app/#{wait_script}:#{wait_line}")
+				# FPM only logs the timeout once, because it successfully terminates the process
+				expect(output.scan(/execution timed out/).size).to eq(1)
+				# fetch child PID that it wanted to terminate
+				child = output.match(/WARNING: \[pool www\] child (?<cpid>\d+), script '\/app\/#{Regexp.escape(wait_script)}' \(request: "GET \/#{Regexp.escape(wait_script)}\?wait=#{wait_secs}"\) execution timed out \(#{timeout_secs}\.\d+ sec\), terminating$/)
+				expect(child).not_to be_nil
+				# check that this child was, indeed, terminated
+				expect(/WARNING: \[pool www\] child (?<cpid>\d+) exited on signal 2 \(SIGINT\) after #{timeout_secs}\.\d+ seconds from start/).to match(output).with_captures(:cpid => child[:cpid])
+				# ensure the child did not complete
+				expect(output).not_to include("hello world")
+				expect(output).not_to include("request complete")
 			end
 		end