From 6d9c5218a8f133a52e02aba5635171b1cb0a419e Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Sun, 31 Mar 2019 16:56:17 +0100 Subject: [PATCH 01/10] 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 fde9c9144c2cc..b1204758a55f1 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)); } /* }}} */ @@ -173,10 +175,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 0000000000000..f968bf9f08bcf --- /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 47397a46c8272194ae1d329d7d888391d3c978db Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Sun, 31 Mar 2019 17:55:29 +0100 Subject: [PATCH 02/10] 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 dfc0d8f7413c1..b9ac59d892430 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 83401f1553995..5881f4187fd4d 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 ae38f5e6438dce0709a69f5be3b8d81c5b0a287c Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Sun, 21 Apr 2019 17:39:11 +0100 Subject: [PATCH 03/10] 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 9d9c1fa7cb31f..d755b00e243dd 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 b1204758a55f1..3a44ed3531641 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; @@ -175,21 +201,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); - } } } @@ -237,8 +248,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); } } /* }}} */ @@ -261,12 +270,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; @@ -284,12 +306,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; } /* }}} */ @@ -302,9 +329,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; } /* }}} */ @@ -314,8 +344,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); From afcd21f8058feff773c1abd609b895d1bbb4d259 Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Mon, 27 May 2019 16:24:28 +0100 Subject: [PATCH 04/10] Revert "Create a new IO ctrl pipe for flushing log stream" This reverts commit f6f37a799ebf0c0dc5dcace0dab527a1ff567b77. --- sapi/fpm/fpm/fpm_children.h | 4 +- sapi/fpm/fpm/fpm_stdio.c | 79 +++++++++++-------------------------- 2 files changed, 25 insertions(+), 58 deletions(-) diff --git a/sapi/fpm/fpm/fpm_children.h b/sapi/fpm/fpm/fpm_children.h index d755b00e243dd..9d9c1fa7cb31f 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, ev_ioctrl; + struct fpm_event_s ev_stdout, ev_stderr; int shm_slot_i; - int fd_stdout, fd_stderr, fd_ioctrl; + int fd_stdout, fd_stderr; 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 3a44ed3531641..b1204758a55f1 100644 --- a/sapi/fpm/fpm/fpm_stdio.c +++ b/sapi/fpm/fpm/fpm_stdio.c @@ -21,7 +21,6 @@ static int fd_stdout[2]; static int fd_stderr[2]; -static int fd_ioctrl[2]; int fpm_stdio_init_main() /* {{{ */ { @@ -107,36 +106,11 @@ int fpm_stdio_init_child(struct fpm_worker_pool_s *wp) /* {{{ */ } /* }}} */ -#define FPM_STDIO_CTRL_FLUSH "f" +#define FPM_STDIO_CMD_FLUSH "\0fscf" int fpm_stdio_flush_child() /* {{{ */ { - 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); - } + return write(STDERR_FILENO, FPM_STDIO_CMD_FLUSH, sizeof(FPM_STDIO_CMD_FLUSH)); } /* }}} */ @@ -150,7 +124,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, create_log_stream; + int read_fail = 0, finish_log_stream = 0, create_log_stream; int res; struct zlog_stream *log_stream; @@ -201,6 +175,21 @@ 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); + } } } @@ -248,6 +237,8 @@ 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); } } /* }}} */ @@ -270,25 +261,12 @@ int fpm_stdio_prepare_pipes(struct fpm_child_s *child) /* {{{ */ return -1; } - 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)) { + if (0 > fd_set_blocked(fd_stdout[0], 0) || 0 > fd_set_blocked(fd_stderr[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; @@ -306,17 +284,12 @@ 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; } /* }}} */ @@ -329,12 +302,9 @@ 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; } /* }}} */ @@ -344,11 +314,8 @@ 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_ioctrl[0]); + close(fd_stdout[0]); close(fd_stdout[1]); + close(fd_stderr[0]); close(fd_stderr[1]); } else { /* stdout of parent is always /dev/null */ dup2(STDOUT_FILENO, STDERR_FILENO); From 263577ea010fceb112501f9a5670fc7e2c8fe143 Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Mon, 27 May 2019 16:29:09 +0100 Subject: [PATCH 05/10] Refactor fpm_stdio_child_said --- sapi/fpm/fpm/fpm_stdio.c | 80 ++++++++++++++-------------------------- sapi/fpm/fpm/zlog.c | 8 ++-- 2 files changed, 32 insertions(+), 56 deletions(-) diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c index b1204758a55f1..7f54a3bcdc1c6 100644 --- a/sapi/fpm/fpm/fpm_stdio.c +++ b/sapi/fpm/fpm/fpm_stdio.c @@ -122,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, pos, start; + int read_fail = 0, create_log_stream; struct zlog_stream *log_stream; if (!arg) { @@ -164,59 +162,37 @@ 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; - /* 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); - } + while (1) { + 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; - } 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); + for (start = 0, pos = 0; 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 && + !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; + } + break; } } + if (start < pos) { + zlog_stream_str(log_stream, buf + start, pos - start); + } } if (read_fail) { @@ -237,8 +213,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); } } /* }}} */ diff --git a/sapi/fpm/fpm/zlog.c b/sapi/fpm/fpm/zlog.c index ddfed2aef981d..db2f0db447ee8 100644 --- a/sapi/fpm/fpm/zlog.c +++ b/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) { From 47f84fb7743f6297d40a0f98e2445e5ee4cede87 Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Sat, 29 Jun 2019 16:50:18 +0100 Subject: [PATCH 06/10] Add test for split flush --- sapi/fpm/tests/log-bwp-msg-flush-split.phpt | 48 +++++++++++++++++++ .../tests/log-dwp-limit-1000-msg-2000.phpt | 2 +- 2 files changed, 49 insertions(+), 1 deletion(-) create mode 100644 sapi/fpm/tests/log-bwp-msg-flush-split.phpt diff --git a/sapi/fpm/tests/log-bwp-msg-flush-split.phpt b/sapi/fpm/tests/log-bwp-msg-flush-split.phpt new file mode 100644 index 0000000000000..cbfe3ef47d74e --- /dev/null +++ b/sapi/fpm/tests/log-bwp-msg-flush-split.phpt @@ -0,0 +1,48 @@ +--TEST-- +FPM: Buffered worker output plain log with msg with flush split in buffer +--SKIPIF-- + +--FILE-- +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-- + +--XFAIL-- +Split flush not implemented yet \ No newline at end of file diff --git a/sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt b/sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt index 61cb92331ebb4..d574def28b923 100644 --- a/sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt +++ b/sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt @@ -44,4 +44,4 @@ Done +?> \ No newline at end of file From 7db473c1243c4395f9a3f2b83673aa2a612c243e Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Sun, 21 Jul 2019 19:28:38 +0100 Subject: [PATCH 07/10] Fix flush splitting --- sapi/fpm/fpm/fpm_stdio.c | 29 +++++++++++++++------ sapi/fpm/tests/log-bwp-msg-flush-split.phpt | 2 -- 2 files changed, 21 insertions(+), 10 deletions(-) diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c index 7f54a3bcdc1c6..1dfd602d410b7 100644 --- a/sapi/fpm/fpm/fpm_stdio.c +++ b/sapi/fpm/fpm/fpm_stdio.c @@ -122,7 +122,7 @@ 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 in_buf = 0, pos, start; + int in_buf = 0, cmd_pos = 0, pos, start; int read_fail = 0, create_log_stream; struct zlog_stream *log_stream; @@ -163,6 +163,7 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg) } 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)) { @@ -171,8 +172,15 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg) } break; } - - for (start = 0, pos = 0; pos < in_buf; pos++) { + start = 0; + if (cmd_pos > 0) { + if (!memcmp(buf, &FPM_STDIO_CMD_FLUSH[cmd_pos], sizeof(FPM_STDIO_CMD_FLUSH) - cmd_pos)) { + zlog_stream_finish(log_stream); + start = cmd_pos; + } + cmd_pos = 0; + } + for (pos = 0; pos < in_buf; pos++) { switch (buf[pos]) { case '\n': zlog_stream_str(log_stream, buf + start, pos - start); @@ -180,12 +188,17 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg) start = pos + 1; break; case '\0': - if (pos + sizeof(FPM_STDIO_CMD_FLUSH) <= in_buf && - !memcmp(buf + pos, FPM_STDIO_CMD_FLUSH, sizeof(FPM_STDIO_CMD_FLUSH))) { + 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); - zlog_stream_finish(log_stream); - start = pos + sizeof(FPM_STDIO_CMD_FLUSH); - pos = start - 1; + goto stdio_read; } break; } diff --git a/sapi/fpm/tests/log-bwp-msg-flush-split.phpt b/sapi/fpm/tests/log-bwp-msg-flush-split.phpt index cbfe3ef47d74e..63b2555de76ed 100644 --- a/sapi/fpm/tests/log-bwp-msg-flush-split.phpt +++ b/sapi/fpm/tests/log-bwp-msg-flush-split.phpt @@ -44,5 +44,3 @@ Done require_once "tester.inc"; FPM\Tester::clean(); ?> ---XFAIL-- -Split flush not implemented yet \ No newline at end of file From 7c6f5e1bd02d7ea051f9e6a2fe555378d5373a61 Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Sun, 18 Aug 2019 19:22:02 +0100 Subject: [PATCH 08/10] Add test for split fallback --- .../log-bwp-msg-flush-split-fallback.phpt | 52 +++++++++++++++++++ ...phpt => log-bwp-msg-flush-split-real.phpt} | 0 2 files changed, 52 insertions(+) create mode 100644 sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt rename sapi/fpm/tests/{log-bwp-msg-flush-split.phpt => log-bwp-msg-flush-split-real.phpt} (100%) 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 index 0000000000000..b1485a07424ff --- /dev/null +++ b/sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt @@ -0,0 +1,52 @@ +--TEST-- +FPM: Buffered worker output plain log with msg with flush split in buffer +--SKIPIF-- + +--FILE-- +start(); +$tester->expectLogStartNotices(); +$tester->request()->expectEmptyBody(); +$tester->terminate(); +$lines = $tester->getLogLines(2); +//var_dump($lines); +var_dump($lines[0] === str_repeat('a', 1022) . "\0f\n"); +var_dump($lines[1] === "abc\n"); +$tester->close(); + +?> +Done +--EXPECT-- +bool(true) +bool(true) +Done +--CLEAN-- + +--XFAIL-- +Zero byte is not working in the split for some reason \ No newline at end of file diff --git a/sapi/fpm/tests/log-bwp-msg-flush-split.phpt b/sapi/fpm/tests/log-bwp-msg-flush-split-real.phpt similarity index 100% rename from sapi/fpm/tests/log-bwp-msg-flush-split.phpt rename to sapi/fpm/tests/log-bwp-msg-flush-split-real.phpt From 47bb158f3ba5e6f8244e2dfa432d76796052639d Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Sun, 8 Sep 2019 18:15:27 +0100 Subject: [PATCH 09/10] Fix flush split fallback --- sapi/fpm/fpm/fpm_stdio.c | 2 ++ sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt | 5 +---- 2 files changed, 3 insertions(+), 4 deletions(-) diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c index 1dfd602d410b7..371249fd586ff 100644 --- a/sapi/fpm/fpm/fpm_stdio.c +++ b/sapi/fpm/fpm/fpm_stdio.c @@ -177,6 +177,8 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg) if (!memcmp(buf, &FPM_STDIO_CMD_FLUSH[cmd_pos], sizeof(FPM_STDIO_CMD_FLUSH) - cmd_pos)) { zlog_stream_finish(log_stream); start = cmd_pos; + } else { + zlog_stream_str(log_stream, &FPM_STDIO_CMD_FLUSH[0], cmd_pos); } cmd_pos = 0; } diff --git a/sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt b/sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt index b1485a07424ff..0c152619a923c 100644 --- a/sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt +++ b/sapi/fpm/tests/log-bwp-msg-flush-split-fallback.phpt @@ -32,8 +32,7 @@ $tester->expectLogStartNotices(); $tester->request()->expectEmptyBody(); $tester->terminate(); $lines = $tester->getLogLines(2); -//var_dump($lines); -var_dump($lines[0] === str_repeat('a', 1022) . "\0f\n"); +var_dump($lines[0] === str_repeat('a', 1021) . "\0f\n"); var_dump($lines[1] === "abc\n"); $tester->close(); @@ -48,5 +47,3 @@ Done require_once "tester.inc"; FPM\Tester::clean(); ?> ---XFAIL-- -Zero byte is not working in the split for some reason \ No newline at end of file From 916b3e92824ca93ebbd7054a692707783ae15a87 Mon Sep 17 00:00:00 2001 From: Jakub Zelenka Date: Sun, 17 Nov 2019 15:05:42 +0000 Subject: [PATCH 10/10] Add back removed NL in FPM test log-dwp-limit-1000-msg-2000.phpt --- sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt b/sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt index d574def28b923..61cb92331ebb4 100644 --- a/sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt +++ b/sapi/fpm/tests/log-dwp-limit-1000-msg-2000.phpt @@ -44,4 +44,4 @@ Done \ No newline at end of file +?>