Fix GH-9754: SaltStack hangs when running php-fpm 8.1.11

bukka · bukka · commit 98bf52c33a81 · 2022-10-29T20:22:49.000+01:00
SaltStack uses Python subprocess and redirects stderr to stdout which is then piped to the returned output. If php-fpm starts in daemonized mode, it should close stderr. However a fix introduced in GH-8913 keeps stderr around so it can be later restored. That causes the issue reported in GH-9754. The solution is to keep stderr around only when php-fpm runs in foreground as the issue is most likely visible only there. Basically there is no need to restore stderr when php-fpm is daemonized.
diff --git a/sapi/fpm/fpm/fpm_conf.c b/sapi/fpm/fpm/fpm_conf.c
@@ -1282,7 +1282,7 @@ static int fpm_conf_post_process(int force_daemon) /* {{{ */
 		fpm_evaluate_full_path(&fpm_global_config.error_log, NULL, PHP_LOCALSTATEDIR, 0);
 	}
 
-	if (0 > fpm_stdio_save_original_stderr()) {
+	if (!fpm_global_config.daemonize && 0 > fpm_stdio_save_original_stderr()) {
 		return -1;
 	}
 
diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c
@@ -74,7 +74,9 @@ int fpm_stdio_init_final(void)
 
 int fpm_stdio_save_original_stderr(void)
 {
-	/* php-fpm loses STDERR fd after call of the fpm_stdio_init_final(). Check #8555. */
+	/* STDERR fd gets lost after callingfpm_stdio_init_final() (check GH-8555) so it can be saved.
+	 * It should be used only when PHP-FPM is not daemonized otherwise it might break some
+	 * applications (e.g. GH-9754). */
 	zlog(ZLOG_DEBUG, "saving original STDERR fd: dup()");
 	fd_stderr_original = dup(STDERR_FILENO);
 	if (0 > fd_stderr_original) {
@@ -87,7 +89,7 @@ int fpm_stdio_save_original_stderr(void)
 
 int fpm_stdio_restore_original_stderr(int close_after_restore)
 {
-	/* php-fpm loses STDERR fd after call of the fpm_stdio_init_final(). Check #8555. */
+	/* Restore original STDERR fd if it was previously saved. */
 	if (-1 != fd_stderr_original) {
 		zlog(ZLOG_DEBUG, "restoring original STDERR fd: dup2()");
 		if (0 > dup2(fd_stderr_original, STDERR_FILENO)) {
@@ -98,9 +100,6 @@ int fpm_stdio_restore_original_stderr(int close_after_restore)
 				close(fd_stderr_original);
 			}
 		}
-	} else {
-		zlog(ZLOG_DEBUG, "original STDERR fd is not restored, maybe function is called from a child: dup2()");
-		return -1;
 	}
 
 	return 0;
diff --git a/sapi/fpm/tests/gh9754-daemonized-stderr-close.phpt b/sapi/fpm/tests/gh9754-daemonized-stderr-close.phpt
@@ -0,0 +1,44 @@
+--TEST--
+FPM: GH-9754 - stderr is not closed in daemonized run
+--SKIPIF--
+<?php
+include "skipif.inc";
+FPM\Tester::skipIfRoot();
+?>
+--FILE--
+<?php
+
+require_once "tester.inc";
+
+$cfg = <<<EOT
+[global]
+error_log = {{FILE:LOG}}
+pid = {{FILE:PID}}
+[unconfined]
+listen = {{ADDR}}
+pm = dynamic
+pm.max_children = 5
+pm.start_servers = 1
+pm.min_spare_servers = 1
+pm.max_spare_servers = 3
+EOT;
+
+$tester = new FPM\Tester($cfg);
+$tester->start(daemonize: true);
+$tester->expectLogStartNotices();
+$tester->switchLogSource('{{MASTER:OUT}}');
+$tester->expectLogEmpty();
+$tester->switchLogSource('{{FILE:LOG}}');
+$tester->terminate();
+$tester->expectLogTerminatingNotices();
+$tester->close();
+
+?>
+Done
+--EXPECT--
+Done
+--CLEAN--
+<?php
+require_once "tester.inc";
+FPM\Tester::clean();
+?>
diff --git a/sapi/fpm/tests/logreader.inc b/sapi/fpm/tests/logreader.inc
@@ -81,15 +81,23 @@ class LogReader
     /**
      * Get a single log line.
      *
-     * @param int $timeoutSeconds
-     * @param int $timeoutMicroseconds
+     * @param int  $timeoutSeconds      Read timeout in seconds
+     * @param int  $timeoutMicroseconds Read timeout in microseconds
+     * @param bool $throwOnTimeout      Whether to throw an exception on timeout
      *
      * @return null|string
      * @throws \Exception
      */
-    public function getLine(int $timeoutSeconds = 3, int $timeoutMicroseconds = 0): ?string
-    {
-        $line = $this->getSource()->getLine($timeoutSeconds, $timeoutMicroseconds);
+    public function getLine(
+        int $timeoutSeconds = 3,
+        int $timeoutMicroseconds = 0,
+        bool $throwOnTimeout = false
+    ): ?string {
+        $line = $this->getSource()->getLine(
+            $timeoutSeconds,
+            $timeoutMicroseconds,
+            $throwOnTimeout
+        );
         $this->trace(is_null($line) ? "LINE - null" : "LINE: $line");
 
         return $line;
@@ -196,17 +204,27 @@ class LogReader
     }
 }
 
+class LogTimoutException extends \Exception
+{
+}
+
 abstract class LogSource
 {
     /**
      * Get single line from the source.
      *
-     * @param int $timeoutSeconds      Read timeout in seconds
-     * @param int $timeoutMicroseconds Read timeout in microseconds
+     * @param int  $timeoutSeconds      Read timeout in seconds
+     * @param int  $timeoutMicroseconds Read timeout in microseconds
+     * @param bool $throwOnTimeout      Whether to throw an exception on timeout
      *
      * @return string|null
+     * @throws LogTimoutException
      */
-    public abstract function getLine(int $timeoutSeconds, int $timeoutMicroseconds): ?string;
+    public abstract function getLine(
+        int $timeoutSeconds,
+        int $timeoutMicroseconds,
+        bool $throwOnTimeout = false
+    ): ?string;
 
     /**
      * Get all lines that has been returned by getLine() method.
@@ -236,13 +254,18 @@ class LogStreamSource extends LogSource
     /**
      * Get single line from the stream.
      *
-     * @param int $timeoutSeconds      Read timeout in seconds
-     * @param int $timeoutMicroseconds Read timeout in microseconds
+     * @param int  $timeoutSeconds      Read timeout in seconds
+     * @param int  $timeoutMicroseconds Read timeout in microseconds
+     * @param bool $throwOnTimeout      Whether to throw an exception on timeout
      *
      * @return string|null
+     * @throws LogTimoutException
      */
-    public function getLine(int $timeoutSeconds, int $timeoutMicroseconds): ?string
-    {
+    public function getLine(
+        int $timeoutSeconds,
+        int $timeoutMicroseconds,
+        bool $throwOnTimeout = false
+    ): ?string {
         if (feof($this->stream)) {
             return null;
         }
@@ -255,6 +278,10 @@ class LogStreamSource extends LogSource
 
             return $line;
         } else {
+            if ($throwOnTimeout) {
+                throw new LogTimoutException('Timout exceeded when reading line');
+            }
+
             return null;
         }
     }
@@ -296,13 +323,18 @@ class LogFileSource extends LogSource
     /**
      * Get single line from the file.
      *
-     * @param int $timeoutSeconds      Read timeout in seconds
-     * @param int $timeoutMicroseconds Read timeout in microseconds
+     * @param int  $timeoutSeconds      Read timeout in seconds
+     * @param int  $timeoutMicroseconds Read timeout in microseconds
+     * @param bool $throwOnTimeout      Whether to throw an exception on timeout
      *
      * @return string|null
+     * @throws LogTimoutException
      */
-    public function getLine(int $timeoutSeconds, int $timeoutMicroseconds): ?string
-    {
+    public function getLine(
+        int $timeoutSeconds,
+        int $timeoutMicroseconds,
+        bool $throwOnTimeout = false
+    ): ?string {
         $endTime = microtime(true) + $timeoutSeconds + ($timeoutMicroseconds / 1_000_000);
         while ($this->position >= count($this->lines)) {
             if (is_file($this->filePath)) {
@@ -317,6 +349,10 @@ class LogFileSource extends LogSource
             }
             usleep(50_000);
             if (microtime(true) > $endTime) {
+                if ($throwOnTimeout) {
+                    throw new LogTimoutException('Timout exceeded when reading line');
+                }
+
                 return null;
             }
         }
diff --git a/sapi/fpm/tests/tester.inc b/sapi/fpm/tests/tester.inc
@@ -104,6 +104,11 @@ class Tester
      */
     private $masterProcess;
 
+    /**
+     * @var bool
+     */
+    private bool $daemonized;
+
     /**
      * @var resource
      */
@@ -373,21 +378,27 @@ class Tester
      *
      * @param array $extraArgs   Command extra arguments.
      * @param bool  $forceStderr Whether to output to stderr so error log is used.
+     * @param bool $daemonize Whether to start FPM daemonized
      *
      * @return bool
      * @throws \Exception
      */
-    public function start(array $extraArgs = [], bool $forceStderr = true)
+    public function start(array $extraArgs = [], bool $forceStderr = true, bool $daemonize = false)
     {
         $configFile = $this->createConfig();
         $desc       = $this->outDesc ? [] : [1 => array('pipe', 'w'), 2 => array('redirect', 1)];
 
-        $cmd = [self::findExecutable(), '-F', '-y', $configFile];
+        $cmd = [self::findExecutable(), '-y', $configFile];
 
         if ($forceStderr) {
             $cmd[] = '-O';
         }
 
+        $this->daemonized = $daemonize;
+        if ( ! $daemonize) {
+            $cmd[] = '-F';
+        }
+
         if (getenv('TEST_FPM_RUN_AS_ROOT')) {
             $cmd[] = '--allow-to-run-as-root';
         }
@@ -410,6 +421,9 @@ class Tester
         if ( ! $this->outDesc !== false) {
             $this->outDesc = $pipes[1];
             $this->logReader->setStreamSource('{{MASTER:OUT}}', $this->outDesc);
+            if ($daemonize) {
+                $this->switchLogSource('{{FILE:LOG}}');
+            }
         }
 
         return true;
@@ -833,7 +847,11 @@ class Tester
      */
     public function terminate()
     {
-        proc_terminate($this->masterProcess);
+        if ($this->daemonized) {
+            $this->signal('TERM');
+        } else {
+            proc_terminate($this->masterProcess);
+        }
     }
 
     /**
@@ -1272,6 +1290,25 @@ class Tester
         $this->logTool->checkTruncatedMessage($this->response->getErrorData());
     }
 
+    /**
+     * Expect log to be closed.
+     *
+     * @throws \Exception
+     */
+    public function expectLogEmpty() {
+        try {
+            $line = $this->logReader->getLine(1, 0, true);
+            if ($line === '') {
+                $line = $this->logReader->getLine(1, 0, true);
+            }
+            if ($line !== null) {
+                $this->error('Log is not closed and returned line: ' . $line);
+            }
+        } catch (LogTimoutException $exception) {
+            $this->error('Log is not closed and timed out', $exception);
+        }
+    }
+
     /**
      * Expect reloading lines to be logged.
      *

Original file line number	Diff line number	Diff line change
`@@ -1282,7 +1282,7 @@ static int fpm_conf_post_process(int force_daemon) /* {{{ */`
`1282`	`1282`	`fpm_evaluate_full_path(&fpm_global_config.error_log, NULL, PHP_LOCALSTATEDIR, 0);`
`1283`	`1283`	`}`
`1284`	`1284`
`1285`		`- if (0 > fpm_stdio_save_original_stderr()) {`
	`1285`	`+ if (!fpm_global_config.daemonize && 0 > fpm_stdio_save_original_stderr()) {`
`1286`	`1286`	`return -1;`
`1287`	`1287`	`}`
`1288`	`1288`
Original file line number	Diff line number	Diff line change
`@@ -74,7 +74,9 @@ int fpm_stdio_init_final(void)`
`74`	`74`
`75`	`75`	`int fpm_stdio_save_original_stderr(void)`
`76`	`76`	`{`
`77`		`- /* php-fpm loses STDERR fd after call of the fpm_stdio_init_final(). Check #8555. */`
	`77`	`+ /* STDERR fd gets lost after callingfpm_stdio_init_final() (check GH-8555) so it can be saved.`
	`78`	`+ * It should be used only when PHP-FPM is not daemonized otherwise it might break some`
	`79`	`+ * applications (e.g. GH-9754). */`
`78`	`80`	`zlog(ZLOG_DEBUG, "saving original STDERR fd: dup()");`
`79`	`81`	`fd_stderr_original = dup(STDERR_FILENO);`
`80`	`82`	`if (0 > fd_stderr_original) {`
`@@ -87,7 +89,7 @@ int fpm_stdio_save_original_stderr(void)`
`87`	`89`
`88`	`90`	`int fpm_stdio_restore_original_stderr(int close_after_restore)`
`89`	`91`	`{`
`90`		`- /* php-fpm loses STDERR fd after call of the fpm_stdio_init_final(). Check #8555. */`
	`92`	`+ /* Restore original STDERR fd if it was previously saved. */`
`91`	`93`	`if (-1 != fd_stderr_original) {`
`92`	`94`	`zlog(ZLOG_DEBUG, "restoring original STDERR fd: dup2()");`
`93`	`95`	`if (0 > dup2(fd_stderr_original, STDERR_FILENO)) {`
`@@ -98,9 +100,6 @@ int fpm_stdio_restore_original_stderr(int close_after_restore)`
`98`	`100`	`close(fd_stderr_original);`
`99`	`101`	`}`
`100`	`102`	`}`
`101`		`- } else {`
`102`		`- zlog(ZLOG_DEBUG, "original STDERR fd is not restored, maybe function is called from a child: dup2()");`
`103`		`- return -1;`
`104`	`103`	`}`
`105`	`104`
`106`	`105`	`return 0;`