From 33074bae289220010ba86fa17736fdab73b37224 Mon Sep 17 00:00:00 2001 From: Tsuyoshi Sadakata Date: Thu, 25 Jul 2019 23:22:45 +0900 Subject: [PATCH] fix fpm log prefix message for pid & stdout/stderr --- sapi/fpm/fpm/fpm_stdio.c | 13 ++++- sapi/fpm/fpm/fpm_stdio.h | 2 + sapi/fpm/fpm/zlog.c | 20 ++++++-- sapi/fpm/fpm/zlog.h | 4 ++ .../log-bwd-multiple-msgs-stdout-stderr.phpt | 50 +++++++++++++++++++ sapi/fpm/tests/logtool.inc | 7 +-- sapi/fpm/tests/tester.inc | 4 +- 7 files changed, 91 insertions(+), 9 deletions(-) create mode 100644 sapi/fpm/tests/log-bwd-multiple-msgs-stdout-stderr.phpt diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c index 03d15cbf0d7ca..fde9c9144c2cc 100644 --- a/sapi/fpm/fpm/fpm_stdio.c +++ b/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) { diff --git a/sapi/fpm/fpm/fpm_stdio.h b/sapi/fpm/fpm/fpm_stdio.h index 7ebe80e66e735..ef96508459c9f 100644 --- a/sapi/fpm/fpm/fpm_stdio.h +++ b/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); diff --git a/sapi/fpm/fpm/zlog.c b/sapi/fpm/fpm/zlog.c index 09193fd5ac85d..ddfed2aef981d 100644 --- a/sapi/fpm/fpm/zlog.c +++ b/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; diff --git a/sapi/fpm/fpm/zlog.h b/sapi/fpm/fpm/zlog.h index 6e96048d09cdf..679996041b32e 100644 --- a/sapi/fpm/fpm/zlog.h +++ b/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))); diff --git a/sapi/fpm/tests/log-bwd-multiple-msgs-stdout-stderr.phpt b/sapi/fpm/tests/log-bwd-multiple-msgs-stdout-stderr.phpt new file mode 100644 index 0000000000000..376a972bacac0 --- /dev/null +++ b/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-- + +--FILE-- +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-- + diff --git a/sapi/fpm/tests/logtool.inc b/sapi/fpm/tests/logtool.inc index 678f11ca46df9..78523635d0018 100644 --- a/sapi/fpm/tests/logtool.inc +++ b/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) { diff --git a/sapi/fpm/tests/tester.inc b/sapi/fpm/tests/tester.inc index 70c03ad70f1c5..001b7d6a54eae 100644 --- a/sapi/fpm/tests/tester.inc +++ b/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); } /**