Fix bug #78334 (fpm log prefix message includes wrong stdout/stderr notation)

NEWS

@@ -11,6 +11,10 @@ PHP                                                                        NEWS
   . Fixed bug #77812 (Interactive mode does not support PHP 7.3-style heredoc).
     (cmb, Nikita)
 
+- FPM:
+  . Fixed bug #78334 (fpm log prefix message includes wrong stdout/stderr
+    notation). (Tsuyoshi Sadakata)
+
 - Intl:
   . Ensure IDNA2003 rules are used with idn_to_ascii() and idn_to_utf8()
     when requested. (Sara)

sapi/fpm/fpm/fpm_stdio.c

@@ -144,11 +144,22 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg)
 		zlog_stream_init_ex(log_stream, ZLOG_WARNING, STDERR_FILENO);
 		zlog_stream_set_decorating(log_stream, child->wp->config->decorate_workers_output);
 		zlog_stream_set_wrapping(log_stream, ZLOG_TRUE);
-		zlog_stream_set_msg_prefix(log_stream, "[pool %s] child %d said into %s: ",
+		zlog_stream_set_msg_prefix(log_stream, STREAM_SET_MSG_PREFIX_FMT,
 				child->wp->config->name, (int) child->pid, is_stdout ? "stdout" : "stderr");
 		zlog_stream_set_msg_quoting(log_stream, ZLOG_TRUE);
+		zlog_stream_set_is_stdout(log_stream, is_stdout);
+		zlog_stream_set_child_pid(log_stream, (int)child->pid);
 	} else {
 		log_stream = child->log_stream;
+		// if fd type (stdout/stderr) or child's pid is changed,
+		// then the stream will be finished and msg's prefix will be reinitialized
+		if (log_stream->is_stdout != (unsigned int)is_stdout || log_stream->child_pid != (int)child->pid) {
+			zlog_stream_finish(log_stream);
+			zlog_stream_set_msg_prefix(log_stream, STREAM_SET_MSG_PREFIX_FMT,
+					child->wp->config->name, (int) child->pid, is_stdout ? "stdout" : "stderr");
+			zlog_stream_set_is_stdout(log_stream, is_stdout);
+			zlog_stream_set_child_pid(log_stream, (int)child->pid);
+		}
 	}
 
 	while (fifo_in || fifo_out) {

sapi/fpm/fpm/fpm_stdio.h

@@ -5,6 +5,8 @@
 
 #include "fpm_worker_pool.h"
 
+#define STREAM_SET_MSG_PREFIX_FMT "[pool %s] child %d said into %s: "
+
 int fpm_stdio_init_main();
 int fpm_stdio_init_final();
 int fpm_stdio_init_child(struct fpm_worker_pool_s *wp);

sapi/fpm/fpm/zlog.c

@@ -563,6 +563,18 @@ void zlog_stream_set_wrapping(struct zlog_stream *stream, zlog_bool wrap) /* {{{
 }
 /* }}} */
 
+void zlog_stream_set_is_stdout(struct zlog_stream *stream, zlog_bool is_stdout) /* {{{ */
+{
+	stream->is_stdout = is_stdout ? 1 : 0;
+}
+/* }}} */
+
+void zlog_stream_set_child_pid(struct zlog_stream *stream, int child_pid) /* {{{ */
+{
+	stream->child_pid = child_pid;
+}
+/* }}} */
+
 void zlog_stream_set_msg_quoting(struct zlog_stream *stream, zlog_bool quote) /* {{{ */
 {
 	stream->msg_quote = quote && stream->decorate ? 1 : 0;
@@ -583,9 +595,11 @@ zlog_bool zlog_stream_set_msg_prefix(struct zlog_stream *stream, const char *fmt
 	len = vsnprintf(buf, MAX_WRAPPING_PREFIX_LENGTH - 1, fmt, args);
 	va_end(args);
 
-	stream->msg_prefix = malloc(len + 1);
-	if (stream->msg_prefix == NULL) {
-		return ZLOG_FALSE;
+	if (stream->msg_prefix_len < len) {
+		stream->msg_prefix = stream->msg_prefix_len ? realloc(stream->msg_prefix, len + 1) : malloc(len + 1);
+		if (stream->msg_prefix == NULL) {
+			return ZLOG_FALSE;
+		}
 	}
 	memcpy(stream->msg_prefix, buf, len);
 	stream->msg_prefix[len] = 0;

sapi/fpm/fpm/zlog.h

@@ -73,8 +73,10 @@ struct zlog_stream {
 	unsigned int wrap:1;
 	unsigned int msg_quote:1;
 	unsigned int decorate:1;
+	unsigned int is_stdout:1;
 	int fd;
 	int line;
+	int child_pid;
 	const char *function;
 	struct zlog_stream_buffer buf;
 	size_t len;
@@ -92,6 +94,8 @@ void zlog_stream_init(struct zlog_stream *stream, int flags);
 void zlog_stream_init_ex(struct zlog_stream *stream, int flags, int fd);
 void zlog_stream_set_decorating(struct zlog_stream *stream, zlog_bool decorate);
 void zlog_stream_set_wrapping(struct zlog_stream *stream, zlog_bool wrap);
+void zlog_stream_set_is_stdout(struct zlog_stream *stream, zlog_bool is_stdout);
+void zlog_stream_set_child_pid(struct zlog_stream *stream, int child_pid);
 void zlog_stream_set_msg_quoting(struct zlog_stream *stream, zlog_bool quote);
 zlog_bool zlog_stream_set_msg_prefix(struct zlog_stream *stream, const char *fmt, ...)
 		__attribute__ ((format(printf,2,3)));

sapi/fpm/tests/log-bwd-multiple-msgs-stdout-stderr.phpt

@@ -0,0 +1,50 @@
+--TEST--
+FPM: Buffered worker output decorated log with multiple continuous messages (stdout/stderr mixed)
+--SKIPIF--
+<?php include "skipif.inc"; ?>
+--FILE--
+<?php
+
+require_once "tester.inc";
+
+$cfg = <<<EOT
+[global]
+error_log = {{FILE:LOG}}
+[unconfined]
+listen = {{ADDR}}
+pm = dynamic
+pm.max_children = 5
+pm.start_servers = 1
+pm.min_spare_servers = 1
+pm.max_spare_servers = 3
+catch_workers_output = yes
+EOT;
+
+$code = <<<EOT
+<?php
+file_put_contents('php://stdout', "msg 1 - ");
+usleep(1);
+file_put_contents('php://stderr', "msg 2 - ");
+usleep(1);
+file_put_contents('php://stderr', "msg 3");
+EOT;
+
+$tester = new FPM\Tester($cfg, $code);
+$tester->start();
+$tester->expectLogStartNotices();
+$tester->request()->expectEmptyBody();
+$tester->request()->expectEmptyBody();
+$tester->terminate();
+$tester->expectLogLine('msg 1 - ', false);
+$tester->expectLogLine('msg 2 - msg 3', true);
+$tester->close();
+
+?>
+Done
+--EXPECT--
+Done
+--CLEAN--
+<?php
+require_once "tester.inc";
+FPM\Tester::clean();
+?>

sapi/fpm/tests/logtool.inc

@@ -6,6 +6,7 @@ class LogTool
 {
     const P_TIME = '\[\d\d-\w\w\w-\d{4} \d\d:\d\d:\d\d\]';
     const P_PREFIX = '\[pool unconfined\] child \d+ said into stderr: ';
+    const P_PREFIX_STDOUT = '\[pool unconfined\] child \d+ said into stdout: ';
     const FINAL_SUFFIX = ', pipe is closed';
 
     /**
@@ -130,7 +131,7 @@ class LogTool
      * @param bool $decorated
      * @return bool
      */
-    public function checkWrappedMessage(array $lines, bool $terminated = true, bool $decorated = true)
+    public function checkWrappedMessage(array $lines, bool $terminated = true, bool $decorated = true, bool $is_stderr = true)
     {
         if ($this->message === null) {
             throw new \LogicException('The message has not been set');
@@ -140,7 +141,7 @@ class LogTool
                 '/^(%s %s: %s)"([^"]*)"(.*)?$/',
                 self::P_TIME,
                 $this->getExpectedLevel(),
-                self::P_PREFIX
+                $is_stderr ? self::P_PREFIX : self::P_PREFIX_STDOUT
             );
         } else {
             $this->pattern = null;
@@ -157,7 +158,7 @@ class LogTool
             $suffixPattern = sprintf(
                 '/^%s %s: %s(.*)$/',
                 self::P_TIME, $this->getExpectedLevel(),
-                self::P_PREFIX
+                $is_stderr ? self::P_PREFIX : self::P_PREFIX_STDOUT
             );
             $line = $lines[++$idx];
             if (preg_match($suffixPattern, $line, $matches) === 0) {

sapi/fpm/tests/tester.inc

@@ -1080,7 +1080,7 @@ class Tester
      * @param string $message
      * @return bool
      */
-    public function expectLogLine(string $message)
+    public function expectLogLine(string $message, bool $is_stderr = true)
     {
         $messageLen = strlen($message);
         $limit = $messageLen > 1024 ? $messageLen + 16 : 1024;
@@ -1090,7 +1090,7 @@ class Tester
             $this->message("LOG LINE: " . ($logLines[0] ?? ''));
         }
 
-        return $this->logTool->checkWrappedMessage($logLines, false);
+        return $this->logTool->checkWrappedMessage($logLines, false, true, $is_stderr);
     }
 
     /**