From 06dd1d78a7ec1678b53ef657033c2021f4dc902f Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Sun, 31 Mar 2019 16:56:17 +0100 Subject: [PATCH 1/3] Fix logging in shutdown function --- sapi/fpm/fpm/fpm_stdio.c | 20 +++++++-- sapi/fpm/tests/log-bm-in-shutdown-fn.phpt | 49 +++++++++++++++++++++++ 2 files changed, 65 insertions(+), 4 deletions(-) create mode 100644 sapi/fpm/tests/log-bm-in-shutdown-fn.phpt diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c index 03d15cbf0d7c..75c4d8e9c262 100644 --- a/sapi/fpm/fpm/fpm_stdio.c +++ b/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)); } /* }}} */ @@ -162,10 +164,20 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg) } } else { in_buf += res; - /* if buffer ends with \0, then the stream will be finished */ - if (!buf[in_buf - 1]) { + /* check if buffer should be flushed */ + if (!buf[in_buf - 1] && in_buf >= sizeof(FPM_STDIO_CMD_FLUSH) && + !memcmp(buf + in_buf - sizeof(FPM_STDIO_CMD_FLUSH), + FPM_STDIO_CMD_FLUSH, sizeof(FPM_STDIO_CMD_FLUSH))) { + /* if buffer ends with flush cmd, then the stream will be finished */ + finish_log_stream = 1; + in_buf -= sizeof(FPM_STDIO_CMD_FLUSH); + } else if (!buf[0] && in_buf > sizeof(FPM_STDIO_CMD_FLUSH) && + !memcmp(buf, FPM_STDIO_CMD_FLUSH, sizeof(FPM_STDIO_CMD_FLUSH))) { + /* if buffer starts with flush cmd, then the stream will be finished */ finish_log_stream = 1; - in_buf--; + in_buf -= sizeof(FPM_STDIO_CMD_FLUSH); + /* move data behind the flush cmd */ + memmove(buf, buf + sizeof(FPM_STDIO_CMD_FLUSH), in_buf); } } } 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 index 000000000000..f968bf9f08bc --- /dev/null +++ b/sapi/fpm/tests/log-bm-in-shutdown-fn.phpt @@ -0,0 +1,49 @@ +--TEST-- +FPM: Log message in shutdown function +--SKIPIF-- + +--FILE-- +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-- + From 72c010309bb0a7bb032677ca599424ceb2ad4883 Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Sun, 31 Mar 2019 17:55:29 +0100 Subject: [PATCH 2/3] Move stdio flush behind request shutdown --- sapi/fpm/fpm/fpm_main.c | 3 +++ sapi/fpm/fpm/fpm_request.c | 2 -- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/sapi/fpm/fpm/fpm_main.c b/sapi/fpm/fpm/fpm_main.c index 483fabe9d850..bfd82a1c2e11 100644 --- a/sapi/fpm/fpm/fpm_main.c +++ b/sapi/fpm/fpm/fpm_main.c @@ -90,6 +90,7 @@ int __riscosify_control = __RISCOSIFY_STRICT_UNIX_SPECS; #include "fpm.h" #include "fpm_request.h" #include "fpm_status.h" +#include "fpm_stdio.h" #include "fpm_conf.h" #include "fpm_php.h" #include "fpm_log.h" @@ -1977,6 +1978,8 @@ consult the installation file that came with this distribution, or visit \n\ php_request_shutdown((void *) 0); + fpm_stdio_flush_child(); + requests++; if (UNEXPECTED(max_requests && (requests == max_requests))) { fcgi_request_set_keep(request, 0); diff --git a/sapi/fpm/fpm/fpm_request.c b/sapi/fpm/fpm/fpm_request.c index 65f9c4ae441c..2aa503891ed9 100644 --- a/sapi/fpm/fpm/fpm_request.c +++ b/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(); } /* }}} */ From f6f37a799ebf0c0dc5dcace0dab527a1ff567b77 Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Sun, 21 Apr 2019 17:39:11 +0100 Subject: [PATCH 3/3] Create a new IO ctrl pipe for flushing log stream --- sapi/fpm/fpm/fpm_children.h | 4 +- sapi/fpm/fpm/fpm_stdio.c | 79 ++++++++++++++++++++++++++----------- 2 files changed, 58 insertions(+), 25 deletions(-) diff --git a/sapi/fpm/fpm/fpm_children.h b/sapi/fpm/fpm/fpm_children.h index 9d9c1fa7cb31..d755b00e243d 100644 --- a/sapi/fpm/fpm/fpm_children.h +++ b/sapi/fpm/fpm/fpm_children.h @@ -22,9 +22,9 @@ struct fpm_child_s { struct fpm_child_s *prev, *next; struct timeval started; struct fpm_worker_pool_s *wp; - struct fpm_event_s ev_stdout, ev_stderr; + struct fpm_event_s ev_stdout, ev_stderr, ev_ioctrl; int shm_slot_i; - int fd_stdout, fd_stderr; + int fd_stdout, fd_stderr, fd_ioctrl; void (*tracer)(struct fpm_child_s *); struct timeval slow_logged; int idle_kill; diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c index 75c4d8e9c262..0b41d1d8c676 100644 --- a/sapi/fpm/fpm/fpm_stdio.c +++ b/sapi/fpm/fpm/fpm_stdio.c @@ -21,6 +21,7 @@ static int fd_stdout[2]; static int fd_stderr[2]; +static int fd_ioctrl[2]; int fpm_stdio_init_main() /* {{{ */ { @@ -106,11 +107,36 @@ int fpm_stdio_init_child(struct fpm_worker_pool_s *wp) /* {{{ */ } /* }}} */ -#define FPM_STDIO_CMD_FLUSH "\0fscf" +#define FPM_STDIO_CTRL_FLUSH "f" int fpm_stdio_flush_child() /* {{{ */ { - return write(STDERR_FILENO, FPM_STDIO_CMD_FLUSH, sizeof(FPM_STDIO_CMD_FLUSH)); + return write(fd_ioctrl[1], FPM_STDIO_CTRL_FLUSH, sizeof(FPM_STDIO_CTRL_FLUSH)); +} +/* }}} */ + +static void fpm_stdio_child_ctrl(struct fpm_event_s *ev, short which, void *arg) /* {{{ */ +{ + static const int max_buf_size = 16; + int fd = ev->fd; + char buf[max_buf_size]; + struct fpm_child_s *child; + int res; + + if (!arg) { + return; + } + child = (struct fpm_child_s *)arg; + + res = read(fd, buf, max_buf_size); + + if (res <= 0) { + return; + } + + if (!memcmp(buf, FPM_STDIO_CTRL_FLUSH, sizeof(FPM_STDIO_CTRL_FLUSH)) && child->log_stream) { + zlog_stream_finish(child->log_stream); + } } /* }}} */ @@ -124,7 +150,7 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg) 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 read_fail = 0, create_log_stream; int res; struct zlog_stream *log_stream; @@ -164,21 +190,6 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg) } } else { in_buf += res; - /* check if buffer should be flushed */ - if (!buf[in_buf - 1] && in_buf >= sizeof(FPM_STDIO_CMD_FLUSH) && - !memcmp(buf + in_buf - sizeof(FPM_STDIO_CMD_FLUSH), - FPM_STDIO_CMD_FLUSH, sizeof(FPM_STDIO_CMD_FLUSH))) { - /* if buffer ends with flush cmd, then the stream will be finished */ - finish_log_stream = 1; - in_buf -= sizeof(FPM_STDIO_CMD_FLUSH); - } else if (!buf[0] && in_buf > sizeof(FPM_STDIO_CMD_FLUSH) && - !memcmp(buf, FPM_STDIO_CMD_FLUSH, sizeof(FPM_STDIO_CMD_FLUSH))) { - /* if buffer starts with flush cmd, then the stream will be finished */ - finish_log_stream = 1; - in_buf -= sizeof(FPM_STDIO_CMD_FLUSH); - /* move data behind the flush cmd */ - memmove(buf, buf + sizeof(FPM_STDIO_CMD_FLUSH), in_buf); - } } } @@ -226,8 +237,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); } } /* }}} */ @@ -250,12 +259,25 @@ int fpm_stdio_prepare_pipes(struct fpm_child_s *child) /* {{{ */ return -1; } - if (0 > fd_set_blocked(fd_stdout[0], 0) || 0 > fd_set_blocked(fd_stderr[0], 0)) { + if (0 > pipe(fd_ioctrl)) { + zlog(ZLOG_SYSERROR, "failed to prepare the IO control pipe"); + close(fd_stdout[0]); + close(fd_stdout[1]); + close(fd_stderr[0]); + close(fd_stderr[1]); + return -1; + } + + if (0 > fd_set_blocked(fd_stdout[0], 0) || + 0 > fd_set_blocked(fd_stderr[0], 0) || + 0 > fd_set_blocked(fd_ioctrl[0], 0)) { zlog(ZLOG_SYSERROR, "failed to unblock pipes"); close(fd_stdout[0]); close(fd_stdout[1]); close(fd_stderr[0]); close(fd_stderr[1]); + close(fd_ioctrl[0]); + close(fd_ioctrl[1]); return -1; } return 0; @@ -273,12 +295,17 @@ int fpm_stdio_parent_use_pipes(struct fpm_child_s *child) /* {{{ */ child->fd_stdout = fd_stdout[0]; child->fd_stderr = fd_stderr[0]; + child->fd_ioctrl = fd_ioctrl[0]; fpm_event_set(&child->ev_stdout, child->fd_stdout, FPM_EV_READ, fpm_stdio_child_said, child); fpm_event_add(&child->ev_stdout, 0); fpm_event_set(&child->ev_stderr, child->fd_stderr, FPM_EV_READ, fpm_stdio_child_said, child); fpm_event_add(&child->ev_stderr, 0); + + fpm_event_set(&child->ev_ioctrl, child->fd_ioctrl, FPM_EV_READ, fpm_stdio_child_ctrl, child); + fpm_event_add(&child->ev_ioctrl, 0); + return 0; } /* }}} */ @@ -291,9 +318,12 @@ int fpm_stdio_discard_pipes(struct fpm_child_s *child) /* {{{ */ close(fd_stdout[1]); close(fd_stderr[1]); + close(fd_ioctrl[1]); close(fd_stdout[0]); close(fd_stderr[0]); + close(fd_ioctrl[0]); + return 0; } /* }}} */ @@ -303,8 +333,11 @@ void fpm_stdio_child_use_pipes(struct fpm_child_s *child) /* {{{ */ if (child->wp->config->catch_workers_output) { dup2(fd_stdout[1], STDOUT_FILENO); dup2(fd_stderr[1], STDERR_FILENO); - close(fd_stdout[0]); close(fd_stdout[1]); - close(fd_stderr[0]); close(fd_stderr[1]); + close(fd_stdout[0]); + close(fd_stdout[1]); + close(fd_stderr[0]); + close(fd_stderr[1]); + close(fd_ioctrl[0]); } else { /* stdout of parent is always /dev/null */ dup2(STDOUT_FILENO, STDERR_FILENO);