FPM. access.log with stderr begins to write logs to error_log after daemon reload (GH-8885)

sapi/fpm/fpm/fpm_conf.c

@@ -1294,6 +1294,10 @@ 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()) {
+		return -1;
+	}
+
 	if (0 > fpm_stdio_open_error_log(0)) {
 		return -1;
 	}

sapi/fpm/fpm/fpm_events.c

@@ -104,6 +104,11 @@ static void fpm_got_signal(struct fpm_event_s *ev, short which, void *arg) /* {{
 				break;
 			case '1' :                  /* SIGUSR1 */
 				zlog(ZLOG_DEBUG, "received SIGUSR1");
+
+				/* fpm_stdio_init_final tied STDERR fd with error_log fd. This affects logging to the
+				 * access.log if it was configured to write to the stderr. Check #8885. */
+				fpm_stdio_restore_original_stderr(0);
+
 				if (0 == fpm_stdio_open_error_log(1)) {
 					zlog(ZLOG_NOTICE, "error log file re-opened");
 				} else {
@@ -118,6 +123,9 @@ static void fpm_got_signal(struct fpm_event_s *ev, short which, void *arg) /* {{
 				}
 				/* else no access log are set */
 
+				/* We need to tie stderr with error_log in the master process after log files reload. Check #8885. */
+				fpm_stdio_redirect_stderr_to_error_log();
+
 				break;
 			case '2' :                  /* SIGUSR2 */
 				zlog(ZLOG_DEBUG, "received SIGUSR2");

sapi/fpm/fpm/fpm_process_ctl.c

@@ -18,6 +18,7 @@
 #include "fpm_worker_pool.h"
 #include "fpm_scoreboard.h"
 #include "fpm_sockets.h"
+#include "fpm_stdio.h"
 #include "zlog.h"
 
 
@@ -100,6 +101,9 @@ static void fpm_pctl_exec(void) /* {{{ */
 	);
 
 	fpm_cleanups_run(FPM_CLEANUP_PARENT_EXEC);
+
+	fpm_stdio_restore_original_stderr(1);
+
 	execvp(saved_argv[0], saved_argv);
 	zlog(ZLOG_SYSERROR, "failed to reload: execvp() failed");
 	exit(FPM_EXIT_SOFTWARE);

sapi/fpm/fpm/fpm_stdio.c

@@ -20,6 +20,7 @@
 #include "fpm_stdio.h"
 #include "zlog.h"
 
+static int fd_stderr_original = -1;
 static int fd_stdout[2];
 static int fd_stderr[2];
 
@@ -62,28 +63,82 @@ static inline int fpm_use_error_log(void) {  /* {{{ */
 
 /* }}} */
 int fpm_stdio_init_final() /* {{{ */
+{
+	if (0 > fpm_stdio_redirect_stderr_to_error_log() ||
+	    0 > fpm_stdio_redirect_stderr_to_dev_null_for_syslog()) {
+
+		return -1;
+	}
+
+	zlog_set_launched();
+	return 0;
+}
+/* }}} */
+
+int fpm_stdio_save_original_stderr(void)
+{
+	/* php-fpm loses STDERR fd after call of the fpm_stdio_init_final(). Check #8555. */
+	zlog(ZLOG_DEBUG, "saving original STDERR fd: dup()");
+	fd_stderr_original = dup(STDERR_FILENO);
+	if (0 > fd_stderr_original) {
+		zlog(ZLOG_SYSERROR, "failed to save original STDERR fd, access.log records may appear in error_log: dup()");
+		return -1;
+	}
+
+	return 0;
+}
+
+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. */
+	if (-1 != fd_stderr_original) {
+		zlog(ZLOG_DEBUG, "restoring original STDERR fd: dup2()");
+		if (0 > dup2(fd_stderr_original, STDERR_FILENO)) {
+			zlog(ZLOG_SYSERROR, "failed to restore original STDERR fd, access.log records may appear in error_log: dup2()");
+			return -1;
+		} else {
+			if (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;
+}
+
+int fpm_stdio_redirect_stderr_to_error_log(void)
 {
 	if (fpm_use_error_log()) {
 		/* prevent duping if logging to syslog */
 		if (fpm_globals.error_log_fd > 0 && fpm_globals.error_log_fd != STDERR_FILENO) {
 
 			/* there might be messages to stderr from other parts of the code, we need to log them all */
 			if (0 > dup2(fpm_globals.error_log_fd, STDERR_FILENO)) {
-				zlog(ZLOG_SYSERROR, "failed to init stdio: dup2()");
+				zlog(ZLOG_SYSERROR, "failed to tie stderr fd with error_log fd: dup2()");
 				return -1;
 			}
 		}
+	}
+
+	return 0;
+}
+
+int fpm_stdio_redirect_stderr_to_dev_null_for_syslog(void)
+{
+	if (fpm_use_error_log()) {
 #ifdef HAVE_SYSLOG_H
-		else if (fpm_globals.error_log_fd == ZLOG_SYSLOG) {
+		if (fpm_globals.error_log_fd == ZLOG_SYSLOG) {
 			/* dup to /dev/null when using syslog */
 			dup2(STDOUT_FILENO, STDERR_FILENO);
 		}
 #endif
 	}
-	zlog_set_launched();
+
 	return 0;
 }
-/* }}} */
 
 int fpm_stdio_init_child(struct fpm_worker_pool_s *wp) /* {{{ */
 {
@@ -336,10 +391,6 @@ int fpm_stdio_open_error_log(int reopen) /* {{{ */
 	}
 
 	if (reopen) {
-		if (fpm_use_error_log()) {
-			dup2(fd, STDERR_FILENO);
-		}
-
 		dup2(fd, fpm_globals.error_log_fd);
 		close(fd);
 		fd = fpm_globals.error_log_fd; /* for FD_CLOSEXEC to work */

sapi/fpm/fpm/fpm_stdio.h

@@ -16,5 +16,9 @@ void fpm_stdio_child_use_pipes(struct fpm_child_s *child);
 int fpm_stdio_parent_use_pipes(struct fpm_child_s *child);
 int fpm_stdio_discard_pipes(struct fpm_child_s *child);
 int fpm_stdio_open_error_log(int reopen);
+int fpm_stdio_save_original_stderr(void);
+int fpm_stdio_restore_original_stderr(int close_after_restore);
+int fpm_stdio_redirect_stderr_to_dev_null_for_syslog(void);
+int fpm_stdio_redirect_stderr_to_error_log(void);
 
 #endif

sapi/fpm/tests/bug8885-stderr-fd-reload-usr1.phpt

@@ -0,0 +1,92 @@
+--TEST--
+FPM: bug8885 - access.log with stderr begins to write logs to error_log after daemon reload (GH-8885)
+--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}}
+access.log=/proc/self/fd/2
+ping.path = /ping
+ping.response = pong
+pm = dynamic
+pm.max_children = 5
+pm.start_servers = 1
+pm.min_spare_servers = 1
+pm.max_spare_servers = 3
+EOT;
+
+// php-fpm must not be launched with --force-stderr option
+$tester = new FPM\Tester($cfg, '', [FPM\Tester::PHP_FPM_DISABLE_FORCE_STDERR => true]);
+// getPrefixedFile('err.log') is the same path that returns processTemplate('{{FILE:LOG}}')
+$errorLogFile = $tester->getPrefixedFile('err.log');
+
+$tester->start();
+$tester->expectNoLogMessages();
+
+$content = file_get_contents($errorLogFile);
+assert($content !== false && strlen($content) > 0, 'File must not be empty');
+
+$errorLogLines = explode("\n", $content);
+array_pop($errorLogLines);
+
+assert(count($errorLogLines) === 2, 'Expected 2 records in the error_log file');
+assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
+assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
+
+$tester->ping('{{ADDR}}');
+$stderrLines = $tester->getLogLines(-1);
+assert(count($stderrLines) === 1, 'Expected 1 record in the stderr output (access.log)');
+$stderrLine = $stderrLines[0];
+assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLine), 'Incorrect format of access.log record');
+
+$tester->signal('USR1');
+$tester->expectNoLogMessages();
+
+$content = file_get_contents($errorLogFile);
+assert($content !== false && strlen($content) > 0, 'File must not be empty');
+$errorLogLines = explode("\n", $content);
+array_pop($errorLogLines);
+
+assert(count($errorLogLines) >= 4, 'Expected at least 4 records in the error_log file');
+assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
+assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
+assert(strpos($errorLogLines[2], 'NOTICE: error log file re-opened'));
+assert(strpos($errorLogLines[3], 'NOTICE: access log file re-opened'));
+
+
+$tester->ping('{{ADDR}}');
+$stderrLines = $tester->getLogLines(-1);
+assert(count($stderrLines) === 1, 'Must be only 1 record in the access.log');
+assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLines[0]), 'Incorrect format of access.log record');
+
+$tester->terminate();
+$stderrLines = $tester->expectNoLogMessages();
+
+$content = file_get_contents($errorLogFile);
+assert($content !== false && strlen($content) > 0, 'File must not be empty');
+$errorLogLines = explode("\n", $content);
+array_pop($errorLogLines);
+$errorLogLastLine = array_pop($errorLogLines);
+assert(strpos($errorLogLastLine, 'NOTICE: exiting, bye-bye'));
+
+$tester->close();
+?>
+Done
+--EXPECT--
+Done
+--CLEAN--
+<?php
+require_once "tester.inc";
+FPM\Tester::clean();
+?>

sapi/fpm/tests/bug8885-stderr-fd-reload-usr2.phpt

@@ -0,0 +1,92 @@
+--TEST--
+FPM: bug8885 - access.log with stderr begins to write logs to error_log after daemon reload (GH-8885)
+--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}}
+access.log=/proc/self/fd/2
+ping.path = /ping
+ping.response = pong
+pm = dynamic
+pm.max_children = 5
+pm.start_servers = 1
+pm.min_spare_servers = 1
+pm.max_spare_servers = 3
+EOT;
+
+// php-fpm must not be launched with --force-stderr option
+$tester = new FPM\Tester($cfg, '', [FPM\Tester::PHP_FPM_DISABLE_FORCE_STDERR => true]);
+// getPrefixedFile('err.log') is the same path that returns processTemplate('{{FILE:LOG}}')
+$errorLogFile = $tester->getPrefixedFile('err.log');
+
+$tester->start();
+$tester->expectNoLogMessages();
+
+$content = file_get_contents($errorLogFile);
+assert($content !== false && strlen($content) > 0, 'File must not be empty');
+
+$errorLogLines = explode("\n", $content);
+array_pop($errorLogLines);
+
+assert(count($errorLogLines) === 2, 'Expected 2 records in the error_log file');
+assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
+assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
+
+$tester->ping('{{ADDR}}');
+$stderrLines = $tester->getLogLines(-1);
+assert(count($stderrLines) === 1, 'Expected 1 record in the stderr output (access.log)');
+$stderrLine = $stderrLines[0];
+assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLine), 'Incorrect format of access.log record');
+
+$tester->signal('USR2');
+$tester->expectLogNotice('using inherited socket fd=\d+, "127.0.0.1:\d+"');
+
+$content = file_get_contents($errorLogFile);
+assert($content !== false && strlen($content) > 0, 'File must not be empty');
+$errorLogLines = explode("\n", $content);
+array_pop($errorLogLines);
+
+assert(count($errorLogLines) >= 5, 'Expected at least 5 records in the error_log file');
+assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
+assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
+assert(strpos($errorLogLines[2], 'NOTICE: Reloading in progress'));
+assert(strpos($errorLogLines[3], 'NOTICE: reloading: execvp'));
+assert(strpos($errorLogLines[4], 'NOTICE: using inherited socket'));
+
+$tester->ping('{{ADDR}}');
+$stderrLines = $tester->getLogLines(-1);
+assert(count($stderrLines) === 1, 'Must be only 1 record in the access.log');
+assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLines[0]), 'Incorrect format of access.log record');
+
+$tester->terminate();
+$stderrLines = $tester->expectNoLogMessages();
+
+$content = file_get_contents($errorLogFile);
+assert($content !== false && strlen($content) > 0, 'File must not be empty');
+$errorLogLines = explode("\n", $content);
+array_pop($errorLogLines);
+$errorLogLastLine = array_pop($errorLogLines);
+assert(strpos($errorLogLastLine, 'NOTICE: exiting, bye-bye'));
+
+$tester->close();
+?>
+Done
+--EXPECT--
+Done
+--CLEAN--
+<?php
+require_once "tester.inc";
+FPM\Tester::clean();
+?>

sapi/fpm/tests/tester.inc

@@ -35,6 +35,11 @@ class Tester
      */
     const FILE_EXT_PID = 'pid';
 
+    /**
+     * Name for the option to manage php-fpm --force-stderr flag
+     */
+    const PHP_FPM_DISABLE_FORCE_STDERR = 'disable-force-stderr';
+
     /**
      * @var array
      */
@@ -365,7 +370,15 @@ class Tester
     {
         $configFile = $this->createConfig();
         $desc = $this->outDesc ? [] : [1 => array('pipe', 'w'), 2 => array('redirect', 1)];
-        $cmd = [self::findExecutable(), '-F', '-O', '-y', $configFile];
+
+        $cmd = [self::findExecutable(), '-F', '-y', $configFile];
+
+        if (!(isset($this->options[self::PHP_FPM_DISABLE_FORCE_STDERR]) &&
+            $this->options[self::PHP_FPM_DISABLE_FORCE_STDERR] === true)
+        ) {
+            $cmd[] = '-O';
+        }
+
         if (getenv('TEST_FPM_RUN_AS_ROOT')) {
             $cmd[] = '--allow-to-run-as-root';
         }
@@ -1138,7 +1151,7 @@ class Tester
      * @param string $prefix
      * @return string
      */
-    private function getPrefixedFile(string $extension, string $prefix = null)
+    public function getPrefixedFile(string $extension, string $prefix = null)
     {
         $fileName = rtrim($this->fileName, '.');
         if (!is_null($prefix)) {