]> granicus.if.org Git - php/commitdiff
Fix bug #77653 (operator displayed instead of the real error message)
authorJakub Zelenka <bukka@php.net>
Sun, 9 Feb 2020 19:40:25 +0000 (19:40 +0000)
committerJakub Zelenka <bukka@php.net>
Sun, 23 Feb 2020 18:29:10 +0000 (18:29 +0000)
NEWS
sapi/fpm/fpm/fpm_main.c
sapi/fpm/fpm/fpm_request.c
sapi/fpm/fpm/fpm_stdio.c
sapi/fpm/fpm/zlog.c
sapi/fpm/tests/log-bm-in-shutdown-fn.phpt [new file with mode: 0644]
sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt [new file with mode: 0644]
sapi/fpm/tests/log-bwp-msg-flush-split-real.phpt [new file with mode: 0644]

diff --git a/NEWS b/NEWS
index 56d1b12f93912ba8a95b8b7ec540cd1f175f6323..7a1fdd32b90e592074bd2de47c787c30b98affe8 100644 (file)
--- a/NEWS
+++ b/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)
index bc3c145ca0b2ac163156a9fe4eaaaabf19c76bd9..b4daa4e4ca8b1b13b8bc04ce17a2c7605cb21c30 100644 (file)
@@ -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);
index e480256a012350a4f60ab42ddfd18c4ed760300a..c80aa144628fc33390708a429fba338f707a9d9b 100644 (file)
@@ -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();
 }
 /* }}} */
 
index fde9c9144c2ccae1b7a08558d8b273fe396a6ec0..ddedfb48c7cfc25316cf4f10bd164fd0c681f83a 100644 (file)
@@ -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,49 +162,53 @@ 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;
-                               }
-                       } 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--;
-                               }
+       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;
                }
-
-               if (fifo_out) {
-                       if (in_buf == 0) {
-                               fifo_out = 0;
+               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 {
-                               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_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);
-                                       /* 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;
-                               }
+                                       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 (start < pos) {
+                       zlog_stream_str(log_stream, buf + start, pos - start);
+               }
        }
 
        if (read_fail) {
@@ -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);
        }
 }
 /* }}} */
index ddfed2aef981dde8480eec9bbda9a6a2daab06c8..db2f0db447ee8965938060f16accaea8a8418ec5 100644 (file)
@@ -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) {
diff --git a/sapi/fpm/tests/log-bm-in-shutdown-fn.phpt b/sapi/fpm/tests/log-bm-in-shutdown-fn.phpt
new file mode 100644 (file)
index 0000000..f968bf9
--- /dev/null
@@ -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();
+?>
diff --git a/sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt b/sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt
new file mode 100644 (file)
index 0000000..0c15261
--- /dev/null
@@ -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();
+?>
diff --git a/sapi/fpm/tests/log-bwp-msg-flush-split-real.phpt b/sapi/fpm/tests/log-bwp-msg-flush-split-real.phpt
new file mode 100644 (file)
index 0000000..63b2555
--- /dev/null
@@ -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();
+?>