Fix bug #77653 (operator displayed instead of the real error message)

NEWS

@@ -22,6 +22,10 @@ PHP                                                                        NEWS
     cmb)
   . Fixed bug #79271 (DOMDocumentType::$childNodes is NULL). (cmb)
 
+- FPM:
+  . Fixed bug #77653 (operator displayed instead of the real error message).
+    (Jakub Zelenka)
+
 - PCRE:
   . Fixed bug #79188 (Memory corruption in preg_replace/preg_replace_callback
     and unicode). (Nikita)

sapi/fpm/fpm/fpm_main.c

@@ -87,6 +87,7 @@ int __riscosify_control = __RISCOSIFY_STRICT_UNIX_SPECS;
 #include "fpm_request.h"
 #include "fpm_status.h"
 #include "fpm_signals.h"
+#include "fpm_stdio.h"
 #include "fpm_conf.h"
 #include "fpm_php.h"
 #include "fpm_log.h"
@@ -1968,6 +1969,8 @@ fastcgi_request_done:
 
 			php_request_shutdown((void *) 0);
 
+			fpm_stdio_flush_child();
+
 			requests++;
 			if (UNEXPECTED(max_requests && (requests == max_requests))) {
 				fcgi_request_set_keep(request, 0);

sapi/fpm/fpm/fpm_request.c

@@ -16,7 +16,6 @@
 #include "fpm_children.h"
 #include "fpm_scoreboard.h"
 #include "fpm_status.h"
-#include "fpm_stdio.h"
 #include "fpm_request.h"
 #include "fpm_log.h"
 
@@ -200,7 +199,6 @@ void fpm_request_end(void) /* {{{ */
 #endif
 	proc->memory = memory;
 	fpm_scoreboard_proc_release(proc);
-	fpm_stdio_flush_child();
 }
 /* }}} */
 

sapi/fpm/fpm/fpm_stdio.c

@@ -106,9 +106,11 @@ int fpm_stdio_init_child(struct fpm_worker_pool_s *wp) /* {{{ */
 }
 /* }}} */
 
+#define FPM_STDIO_CMD_FLUSH "\0fscf"
+
 int fpm_stdio_flush_child() /* {{{ */
 {
-	return write(STDERR_FILENO, "\0", 1);
+	return write(STDERR_FILENO, FPM_STDIO_CMD_FLUSH, sizeof(FPM_STDIO_CMD_FLUSH));
 }
 /* }}} */
 
@@ -120,10 +122,8 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg)
 	struct fpm_child_s *child;
 	int is_stdout;
 	struct fpm_event_s *event;
-	int fifo_in = 1, fifo_out = 1;
-	int in_buf = 0;
-	int read_fail = 0, finish_log_stream = 0, create_log_stream;
-	int res;
+	int in_buf = 0, cmd_pos = 0, pos, start;
+	int read_fail = 0, create_log_stream;
 	struct zlog_stream *log_stream;
 
 	if (!arg) {
@@ -162,48 +162,52 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg)
 		}
 	}
 
-	while (fifo_in || fifo_out) {
-		if (fifo_in) {
-			res = read(fd, buf + in_buf, max_buf_size - 1 - in_buf);
-			if (res <= 0) { /* no data */
-				fifo_in = 0;
-				if (res == 0 || (errno != EAGAIN && errno != EWOULDBLOCK)) {
-					/* pipe is closed or error */
-					read_fail = (res < 0) ? res : 1;
-				}
+	while (1) {
+stdio_read:
+		in_buf = read(fd, buf, max_buf_size - 1);
+		if (in_buf <= 0) { /* no data */
+			if (in_buf == 0 || (errno != EAGAIN && errno != EWOULDBLOCK)) {
+				/* pipe is closed or error */
+				read_fail = (in_buf < 0) ? in_buf : 1;
+			}
+			break;
+		}
+		start = 0;
+		if (cmd_pos > 0) {
+			if 	((sizeof(FPM_STDIO_CMD_FLUSH) - cmd_pos) <= in_buf &&
+					!memcmp(buf, &FPM_STDIO_CMD_FLUSH[cmd_pos], sizeof(FPM_STDIO_CMD_FLUSH) - cmd_pos)) {
+				zlog_stream_finish(log_stream);
+				start = cmd_pos;
 			} else {
-				in_buf += res;
-				/* if buffer ends with \0, then the stream will be finished */
-				if (!buf[in_buf - 1]) {
-					finish_log_stream = 1;
-					in_buf--;
-				}
+				zlog_stream_str(log_stream, &FPM_STDIO_CMD_FLUSH[0], cmd_pos);
+			}
+			cmd_pos = 0;
+		}
+		for (pos = start; pos < in_buf; pos++) {
+			switch (buf[pos]) {
+				case '\n':
+					zlog_stream_str(log_stream, buf + start, pos - start);
+					zlog_stream_finish(log_stream);
+					start = pos + 1;
+					break;
+				case '\0':
+					if (pos + sizeof(FPM_STDIO_CMD_FLUSH) <= in_buf) {
+						if (!memcmp(buf + pos, FPM_STDIO_CMD_FLUSH, sizeof(FPM_STDIO_CMD_FLUSH))) {
+							zlog_stream_str(log_stream, buf + start, pos - start);
+							zlog_stream_finish(log_stream);
+							start = pos + sizeof(FPM_STDIO_CMD_FLUSH);
+							pos = start - 1;
+						}
+					} else if (!memcmp(buf + pos, FPM_STDIO_CMD_FLUSH, in_buf - pos)) {
+						cmd_pos = in_buf - pos;
+						zlog_stream_str(log_stream, buf + start, pos - start);
+						goto stdio_read;
+					}
+					break;
 			}
 		}
-
-		if (fifo_out) {
-			if (in_buf == 0) {
-				fifo_out = 0;
-			} else {
-				char *nl;
-
-				nl = memchr(buf, '\n', in_buf);
-				if (nl) {
-					/* we should print each new line int the new message */
-					int out_len = nl - buf;
-					zlog_stream_str(log_stream, buf, out_len);
-					zlog_stream_finish(log_stream);
-					/* skip new line */
-					out_len++;
-					/* move data in the buffer */
-					memmove(buf, buf + out_len, in_buf - out_len);
-					in_buf -= out_len;
-				} else if (in_buf == max_buf_size - 1 || !fifo_in) {
-					/* we should print if no more space in the buffer or no more data to come */
-					zlog_stream_str(log_stream, buf, in_buf);
-					in_buf = 0;
-				}
-			}
+		if (start < pos) {
+			zlog_stream_str(log_stream, buf + start, pos - start);
 		}
 	}
 
@@ -225,8 +229,6 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg)
 			close(child->fd_stderr);
 			child->fd_stderr = -1;
 		}
-	} else if (finish_log_stream) {
-		zlog_stream_finish(log_stream);
 	}
 }
 /* }}} */

sapi/fpm/fpm/zlog.c

@@ -734,14 +734,16 @@ ssize_t zlog_stream_format(struct zlog_stream *stream, const char *fmt, ...) /*
 
 ssize_t zlog_stream_str(struct zlog_stream *stream, const char *str, size_t str_len) /* {{{ */
 {
+	/* do not write anything if the stream is full or str is empty */
+	if (str_len == 0 || stream->full) {
+		return 0;
+	}
+
 	/* reset stream if it is finished */
 	if (stream->finished) {
 		stream->finished = 0;
 		stream->len = 0;
 		stream->full = 0;
-	} else if (stream->full) {
-		/* do not write anything if the stream is full */
-		return 0;
 	}
 
 	if (stream->use_buffer) {

sapi/fpm/tests/log-bm-in-shutdown-fn.phpt

@@ -0,0 +1,49 @@
+--TEST--
+FPM: Log message in shutdown function
+--SKIPIF--
+<?php include "skipif.inc"; ?>
+--FILE--
+<?php
+
+require_once "tester.inc";
+
+$cfg = <<<EOT
+[global]
+error_log = {{FILE:LOG}}
+log_limit = 1024
+log_buffering = yes
+[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
+register_shutdown_function(function() {
+    error_log(str_repeat('e', 80));
+});
+EOT;
+
+$tester = new FPM\Tester($cfg, $code);
+$tester->start();
+$tester->expectLogStartNotices();
+$tester->request()->expectEmptyBody();
+$tester->terminate();
+$tester->expectFastCGIErrorMessage('e', 1050, 80);
+$tester->expectLogMessage('NOTICE: PHP message: ' . str_repeat('e', 80), 1050);
+$tester->close();
+
+?>
+Done
+--EXPECT--
+Done
+--CLEAN--
+<?php
+require_once "tester.inc";
+FPM\Tester::clean();
+?>

sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt

@@ -0,0 +1,49 @@
+--TEST--
+FPM: Buffered worker output plain log with msg with flush split in buffer
+--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
+decorate_workers_output = no
+EOT;
+
+$code = <<<EOT
+<?php
+file_put_contents('php://stderr', str_repeat('a', 1021) . "\0fabc");
+EOT;
+
+$tester = new FPM\Tester($cfg, $code);
+$tester->start();
+$tester->expectLogStartNotices();
+$tester->request()->expectEmptyBody();
+$tester->terminate();
+$lines = $tester->getLogLines(2);
+var_dump($lines[0] === str_repeat('a', 1021)  . "\0f\n");
+var_dump($lines[1] === "abc\n");
+$tester->close();
+
+?>
+Done
+--EXPECT--
+bool(true)
+bool(true)
+Done
+--CLEAN--
+<?php
+require_once "tester.inc";
+FPM\Tester::clean();
+?>

sapi/fpm/tests/log-bwp-msg-flush-split-real.phpt

@@ -0,0 +1,46 @@
+--TEST--
+FPM: Buffered worker output plain log with msg with flush split in buffer
+--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
+decorate_workers_output = no
+EOT;
+
+$code = <<<EOT
+<?php
+file_put_contents('php://stderr', str_repeat('a', 1022) . "\0fscf\0");
+EOT;
+
+$tester = new FPM\Tester($cfg, $code);
+$tester->start();
+$tester->expectLogStartNotices();
+$tester->request()->expectEmptyBody();
+$tester->terminate();
+var_dump($tester->getLastLogLine() === str_repeat('a', 1022) . "\n");
+$tester->close();
+
+?>
+Done
+--EXPECT--
+bool(true)
+Done
+--CLEAN--
+<?php
+require_once "tester.inc";
+FPM\Tester::clean();
+?>