From 2d74d3b526dd4e631b66b46a7bc3b5e182f52f94 Mon Sep 17 00:00:00 2001 From: Dmitry Menshikov Date: Sun, 3 Jul 2022 14:12:55 +0300 Subject: [PATCH 1/7] FPM. access.log with stderr begins to write logs to error_log after daemon reload (GH-8885) --- sapi/fpm/fpm/fpm_events.c | 10 ++++++++++ sapi/fpm/fpm/fpm_process_ctl.c | 5 +++++ sapi/fpm/fpm/fpm_stdio.c | 28 ++++++++++++++++++++++++++++ 3 files changed, 43 insertions(+) diff --git a/sapi/fpm/fpm/fpm_events.c b/sapi/fpm/fpm/fpm_events.c index dfbd5bd58c495..5f98c9852bbda 100644 --- a/sapi/fpm/fpm/fpm_events.c +++ b/sapi/fpm/fpm/fpm_events.c @@ -104,6 +104,13 @@ static void fpm_got_signal(struct fpm_event_s *ev, short which, void *arg) /* {{ break; case '1' : /* SIGUSR1 */ zlog(ZLOG_DEBUG, "received SIGUSR1"); + + /* fpm_stdio_init_final tied STDERR fd with error_log fd. This affects logging to the + * access.log if it was configured to write to the stderr. Check #8885. */ + if (0 > fpm_stdio_restore_original_stderr()) { + zlog(ZLOG_SYSERROR, "failed to restore original STDERR descriptor, access.log records may appear in the error_log"); + } + if (0 == fpm_stdio_open_error_log(1)) { zlog(ZLOG_NOTICE, "error log file re-opened"); } else { @@ -118,6 +125,9 @@ static void fpm_got_signal(struct fpm_event_s *ev, short which, void *arg) /* {{ } /* else no access log are set */ + /* We need to tie stderr with error_log in the master process after log files reload. Check #8885. */ + fpm_stdio_init_final(); + break; case '2' : /* SIGUSR2 */ zlog(ZLOG_DEBUG, "received SIGUSR2"); diff --git a/sapi/fpm/fpm/fpm_process_ctl.c b/sapi/fpm/fpm/fpm_process_ctl.c index 97b96e5e3ea76..c894c01fea77d 100644 --- a/sapi/fpm/fpm/fpm_process_ctl.c +++ b/sapi/fpm/fpm/fpm_process_ctl.c @@ -18,6 +18,7 @@ #include "fpm_worker_pool.h" #include "fpm_scoreboard.h" #include "fpm_sockets.h" +#include "fpm_stdio.h" #include "zlog.h" @@ -82,6 +83,10 @@ static void fpm_pctl_exec(void) /* {{{ */ zlog(ZLOG_WARNING, "concurrent reloads may be unstable"); } + if (0 > fpm_stdio_restore_original_stderr()) { + zlog(ZLOG_SYSERROR, "failed to restore original STDERR descriptor, access.log and slowlog records may appear in error_log"); + } + zlog(ZLOG_NOTICE, "reloading: execvp(\"%s\", {\"%s\"" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c index e920923b009bc..31954a088747e 100644 --- a/sapi/fpm/fpm/fpm_stdio.c +++ b/sapi/fpm/fpm/fpm_stdio.c @@ -20,6 +20,7 @@ #include "fpm_stdio.h" #include "zlog.h" +static int fd_stderr_original = -1; static int fd_stdout[2]; static int fd_stderr[2]; @@ -67,6 +68,12 @@ int fpm_stdio_init_final() /* {{{ */ /* prevent duping if logging to syslog */ if (fpm_globals.error_log_fd > 0 && fpm_globals.error_log_fd != STDERR_FILENO) { + /* php-fpm loses STDERR fd after call of the dup2 below. Check #8555. */ + if (0 > fpm_stdio_save_original_stderr()) { + zlog(ZLOG_SYSERROR, "failed to save original STDERR descriptor, access.log records may appear in error_log"); + return -1; + } + /* there might be messages to stderr from other parts of the code, we need to log them all */ if (0 > dup2(fpm_globals.error_log_fd, STDERR_FILENO)) { zlog(ZLOG_SYSERROR, "failed to init stdio: dup2()"); @@ -85,6 +92,27 @@ int fpm_stdio_init_final() /* {{{ */ } /* }}} */ +int fpm_stdio_save_original_stderr(void) /* {{{ */ +{ + zlog(ZLOG_DEBUG, "saving original STDERR fd: dup()"); + fd_stderr_original = dup(STDERR_FILENO); + return fd_stderr_original; +} +/* }}} */ + +int fpm_stdio_restore_original_stderr(void) /* {{{ */ +{ + zlog(ZLOG_DEBUG, "restoring original STDERR fd: dup2()"); + if (-1 != fd_stderr_original) { + if (0 > dup2(fd_stderr_original, STDERR_FILENO)) { + return -1; + } + } + + return 0; +} +/* }}} */ + int fpm_stdio_init_child(struct fpm_worker_pool_s *wp) /* {{{ */ { #ifdef HAVE_SYSLOG_H From c56ca025703f8fd348374381cd71b6b8eab87e6f Mon Sep 17 00:00:00 2001 From: Dmitry Menshikov Date: Sun, 3 Jul 2022 15:23:36 +0300 Subject: [PATCH 2/7] FPM. access.log with stderr begins to write logs to error_log after daemon reload (GH-8885) --- sapi/fpm/fpm/fpm_events.c | 14 ++++++------ sapi/fpm/fpm/fpm_process_ctl.c | 6 ++--- sapi/fpm/fpm/fpm_stdio.c | 40 +++++++++++++++++----------------- 3 files changed, 30 insertions(+), 30 deletions(-) diff --git a/sapi/fpm/fpm/fpm_events.c b/sapi/fpm/fpm/fpm_events.c index 5f98c9852bbda..65b29391deecb 100644 --- a/sapi/fpm/fpm/fpm_events.c +++ b/sapi/fpm/fpm/fpm_events.c @@ -105,11 +105,11 @@ static void fpm_got_signal(struct fpm_event_s *ev, short which, void *arg) /* {{ case '1' : /* SIGUSR1 */ zlog(ZLOG_DEBUG, "received SIGUSR1"); - /* fpm_stdio_init_final tied STDERR fd with error_log fd. This affects logging to the - * access.log if it was configured to write to the stderr. Check #8885. */ - if (0 > fpm_stdio_restore_original_stderr()) { - zlog(ZLOG_SYSERROR, "failed to restore original STDERR descriptor, access.log records may appear in the error_log"); - } + /* fpm_stdio_init_final tied STDERR fd with error_log fd. This affects logging to the + * access.log if it was configured to write to the stderr. Check #8885. */ + if (0 > fpm_stdio_restore_original_stderr()) { + zlog(ZLOG_SYSERROR, "failed to restore original STDERR descriptor, access.log records may appear in the error_log"); + } if (0 == fpm_stdio_open_error_log(1)) { zlog(ZLOG_NOTICE, "error log file re-opened"); @@ -125,8 +125,8 @@ static void fpm_got_signal(struct fpm_event_s *ev, short which, void *arg) /* {{ } /* else no access log are set */ - /* We need to tie stderr with error_log in the master process after log files reload. Check #8885. */ - fpm_stdio_init_final(); + /* We need to tie stderr with error_log in the master process after log files reload. Check #8885. */ + fpm_stdio_init_final(); break; case '2' : /* SIGUSR2 */ diff --git a/sapi/fpm/fpm/fpm_process_ctl.c b/sapi/fpm/fpm/fpm_process_ctl.c index c894c01fea77d..b08bb9614124f 100644 --- a/sapi/fpm/fpm/fpm_process_ctl.c +++ b/sapi/fpm/fpm/fpm_process_ctl.c @@ -83,9 +83,9 @@ static void fpm_pctl_exec(void) /* {{{ */ zlog(ZLOG_WARNING, "concurrent reloads may be unstable"); } - if (0 > fpm_stdio_restore_original_stderr()) { - zlog(ZLOG_SYSERROR, "failed to restore original STDERR descriptor, access.log and slowlog records may appear in error_log"); - } + if (0 > fpm_stdio_restore_original_stderr()) { + zlog(ZLOG_SYSERROR, "failed to restore original STDERR descriptor, access.log and slowlog records may appear in error_log"); + } zlog(ZLOG_NOTICE, "reloading: execvp(\"%s\", {\"%s\"" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c index 31954a088747e..7c8793e34ff96 100644 --- a/sapi/fpm/fpm/fpm_stdio.c +++ b/sapi/fpm/fpm/fpm_stdio.c @@ -68,11 +68,11 @@ int fpm_stdio_init_final() /* {{{ */ /* prevent duping if logging to syslog */ if (fpm_globals.error_log_fd > 0 && fpm_globals.error_log_fd != STDERR_FILENO) { - /* php-fpm loses STDERR fd after call of the dup2 below. Check #8555. */ - if (0 > fpm_stdio_save_original_stderr()) { - zlog(ZLOG_SYSERROR, "failed to save original STDERR descriptor, access.log records may appear in error_log"); - return -1; - } + /* php-fpm loses STDERR fd after call of the dup2 below. Check #8555. */ + if (0 > fpm_stdio_save_original_stderr()) { + zlog(ZLOG_SYSERROR, "failed to save original STDERR descriptor, access.log records may appear in error_log"); + return -1; + } /* there might be messages to stderr from other parts of the code, we need to log them all */ if (0 > dup2(fpm_globals.error_log_fd, STDERR_FILENO)) { @@ -94,22 +94,26 @@ int fpm_stdio_init_final() /* {{{ */ int fpm_stdio_save_original_stderr(void) /* {{{ */ { - zlog(ZLOG_DEBUG, "saving original STDERR fd: dup()"); - fd_stderr_original = dup(STDERR_FILENO); - return fd_stderr_original; + zlog(ZLOG_DEBUG, "saving original STDERR fd: dup()"); + fd_stderr_original = dup(STDERR_FILENO); + return fd_stderr_original; } /* }}} */ int fpm_stdio_restore_original_stderr(void) /* {{{ */ { - zlog(ZLOG_DEBUG, "restoring original STDERR fd: dup2()"); - if (-1 != fd_stderr_original) { - if (0 > dup2(fd_stderr_original, STDERR_FILENO)) { - return -1; - } - } - - return 0; + zlog(ZLOG_DEBUG, "restoring original STDERR fd: dup2()"); + if (-1 != fd_stderr_original) { + zlog(ZLOG_DEBUG, "restoring original STDERR fd: dup2()"); + if (0 > dup2(fd_stderr_original, STDERR_FILENO)) { + return -1; + } + } else { + zlog(ZLOG_DEBUG, "original STDERR fd is not restored, maybe function is called from a child: dup2()"); + return -1; + } + + return 0; } /* }}} */ @@ -364,10 +368,6 @@ int fpm_stdio_open_error_log(int reopen) /* {{{ */ } if (reopen) { - if (fpm_use_error_log()) { - dup2(fd, STDERR_FILENO); - } - dup2(fd, fpm_globals.error_log_fd); close(fd); fd = fpm_globals.error_log_fd; /* for FD_CLOSEXEC to work */ From 16a1b2a8092ffa884c31cc1c98bc31074463a80a Mon Sep 17 00:00:00 2001 From: Dmitry Menshikov Date: Sun, 3 Jul 2022 16:31:53 +0300 Subject: [PATCH 3/7] FPM. access.log with stderr begins to write logs to error_log after daemon reload (GH-8885) --- sapi/fpm/fpm/fpm_stdio.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c index 7c8793e34ff96..20b1e80079d86 100644 --- a/sapi/fpm/fpm/fpm_stdio.c +++ b/sapi/fpm/fpm/fpm_stdio.c @@ -107,6 +107,8 @@ int fpm_stdio_restore_original_stderr(void) /* {{{ */ zlog(ZLOG_DEBUG, "restoring original STDERR fd: dup2()"); if (0 > dup2(fd_stderr_original, STDERR_FILENO)) { return -1; + } else { + close(fd_stderr_original); } } else { zlog(ZLOG_DEBUG, "original STDERR fd is not restored, maybe function is called from a child: dup2()"); From f3a5ef386d9f9ca3fb95319b610ee4382516f734 Mon Sep 17 00:00:00 2001 From: Dmitry Menshikov Date: Sun, 3 Jul 2022 16:37:14 +0300 Subject: [PATCH 4/7] FPM. access.log with stderr begins to write logs to error_log after daemon reload (GH-8885) --- sapi/fpm/fpm/fpm_stdio.h | 2 ++ 1 file changed, 2 insertions(+) diff --git a/sapi/fpm/fpm/fpm_stdio.h b/sapi/fpm/fpm/fpm_stdio.h index c0ff94d3cb609..05b30ed6adbd3 100644 --- a/sapi/fpm/fpm/fpm_stdio.h +++ b/sapi/fpm/fpm/fpm_stdio.h @@ -16,5 +16,7 @@ void fpm_stdio_child_use_pipes(struct fpm_child_s *child); int fpm_stdio_parent_use_pipes(struct fpm_child_s *child); int fpm_stdio_discard_pipes(struct fpm_child_s *child); int fpm_stdio_open_error_log(int reopen); +int fpm_stdio_save_original_stderr(void); +int fpm_stdio_restore_original_stderr(void); #endif From 59d0075fd90b55e628d0e58e2969a053707777e7 Mon Sep 17 00:00:00 2001 From: Dmitry Menshikov Date: Mon, 4 Jul 2022 11:19:49 +0300 Subject: [PATCH 5/7] FPM. access.log with stderr begins to write logs to error_log after daemon reload (GH-8885) --- sapi/fpm/fpm/fpm_conf.c | 4 ++ sapi/fpm/fpm/fpm_events.c | 6 +-- sapi/fpm/fpm/fpm_process_ctl.c | 7 ++-- sapi/fpm/fpm/fpm_stdio.c | 77 +++++++++++++++++++++------------- sapi/fpm/fpm/fpm_stdio.h | 2 +- 5 files changed, 59 insertions(+), 37 deletions(-) diff --git a/sapi/fpm/fpm/fpm_conf.c b/sapi/fpm/fpm/fpm_conf.c index 197c5b1c2b26e..230f518b11e36 100644 --- a/sapi/fpm/fpm/fpm_conf.c +++ b/sapi/fpm/fpm/fpm_conf.c @@ -1294,6 +1294,10 @@ static int fpm_conf_post_process(int force_daemon) /* {{{ */ fpm_evaluate_full_path(&fpm_global_config.error_log, NULL, PHP_LOCALSTATEDIR, 0); } + if (0 > fpm_stdio_save_original_stderr()) { + return -1; + } + if (0 > fpm_stdio_open_error_log(0)) { return -1; } diff --git a/sapi/fpm/fpm/fpm_events.c b/sapi/fpm/fpm/fpm_events.c index 65b29391deecb..3b364e48db6a5 100644 --- a/sapi/fpm/fpm/fpm_events.c +++ b/sapi/fpm/fpm/fpm_events.c @@ -107,9 +107,7 @@ static void fpm_got_signal(struct fpm_event_s *ev, short which, void *arg) /* {{ /* fpm_stdio_init_final tied STDERR fd with error_log fd. This affects logging to the * access.log if it was configured to write to the stderr. Check #8885. */ - if (0 > fpm_stdio_restore_original_stderr()) { - zlog(ZLOG_SYSERROR, "failed to restore original STDERR descriptor, access.log records may appear in the error_log"); - } + fpm_stdio_restore_original_stderr(0); if (0 == fpm_stdio_open_error_log(1)) { zlog(ZLOG_NOTICE, "error log file re-opened"); @@ -126,7 +124,7 @@ static void fpm_got_signal(struct fpm_event_s *ev, short which, void *arg) /* {{ /* else no access log are set */ /* We need to tie stderr with error_log in the master process after log files reload. Check #8885. */ - fpm_stdio_init_final(); + fpm_stdio_redirect_stderr_to_error_log(); break; case '2' : /* SIGUSR2 */ diff --git a/sapi/fpm/fpm/fpm_process_ctl.c b/sapi/fpm/fpm/fpm_process_ctl.c index b08bb9614124f..07f1c67f23f17 100644 --- a/sapi/fpm/fpm/fpm_process_ctl.c +++ b/sapi/fpm/fpm/fpm_process_ctl.c @@ -83,10 +83,6 @@ static void fpm_pctl_exec(void) /* {{{ */ zlog(ZLOG_WARNING, "concurrent reloads may be unstable"); } - if (0 > fpm_stdio_restore_original_stderr()) { - zlog(ZLOG_SYSERROR, "failed to restore original STDERR descriptor, access.log and slowlog records may appear in error_log"); - } - zlog(ZLOG_NOTICE, "reloading: execvp(\"%s\", {\"%s\"" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" "%s%s%s" @@ -105,6 +101,9 @@ static void fpm_pctl_exec(void) /* {{{ */ ); fpm_cleanups_run(FPM_CLEANUP_PARENT_EXEC); + + fpm_stdio_restore_original_stderr(1); + execvp(saved_argv[0], saved_argv); zlog(ZLOG_SYSERROR, "failed to reload: execvp() failed"); exit(FPM_EXIT_SOFTWARE); diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c index 20b1e80079d86..0c83bfbf4fa25 100644 --- a/sapi/fpm/fpm/fpm_stdio.c +++ b/sapi/fpm/fpm/fpm_stdio.c @@ -64,51 +64,42 @@ static inline int fpm_use_error_log(void) { /* {{{ */ /* }}} */ int fpm_stdio_init_final() /* {{{ */ { - if (fpm_use_error_log()) { - /* prevent duping if logging to syslog */ - if (fpm_globals.error_log_fd > 0 && fpm_globals.error_log_fd != STDERR_FILENO) { + if (0 > fpm_stdio_redirect_stderr_to_error_log() || + 0 > fpm_stdio_redirect_stderr_to_dev_null_for_syslog()) { - /* php-fpm loses STDERR fd after call of the dup2 below. Check #8555. */ - if (0 > fpm_stdio_save_original_stderr()) { - zlog(ZLOG_SYSERROR, "failed to save original STDERR descriptor, access.log records may appear in error_log"); - return -1; - } - - /* there might be messages to stderr from other parts of the code, we need to log them all */ - if (0 > dup2(fpm_globals.error_log_fd, STDERR_FILENO)) { - zlog(ZLOG_SYSERROR, "failed to init stdio: dup2()"); - return -1; - } - } -#ifdef HAVE_SYSLOG_H - else if (fpm_globals.error_log_fd == ZLOG_SYSLOG) { - /* dup to /dev/null when using syslog */ - dup2(STDOUT_FILENO, STDERR_FILENO); - } -#endif + return -1; } + zlog_set_launched(); return 0; } /* }}} */ -int fpm_stdio_save_original_stderr(void) /* {{{ */ +int fpm_stdio_save_original_stderr(void) { + /* php-fpm loses STDERR fd after call of the fpm_stdio_init_final(). Check #8555. */ zlog(ZLOG_DEBUG, "saving original STDERR fd: dup()"); fd_stderr_original = dup(STDERR_FILENO); - return fd_stderr_original; + if (0 > fd_stderr_original) { + zlog(ZLOG_SYSERROR, "failed to save original STDERR fd, access.log records may appear in error_log: dup()"); + return -1; + } + + return 0; } -/* }}} */ -int fpm_stdio_restore_original_stderr(void) /* {{{ */ +int fpm_stdio_restore_original_stderr(int close_after_restore) { - zlog(ZLOG_DEBUG, "restoring original STDERR fd: dup2()"); + /* php-fpm loses STDERR fd after call of the fpm_stdio_init_final(). Check #8555. */ if (-1 != fd_stderr_original) { zlog(ZLOG_DEBUG, "restoring original STDERR fd: dup2()"); if (0 > dup2(fd_stderr_original, STDERR_FILENO)) { + zlog(ZLOG_SYSERROR, "failed to restore original STDERR fd, access.log records may appear in error_log: dup2()"); return -1; } else { - close(fd_stderr_original); + if (close_after_restore) { + close(fd_stderr_original); + } } } else { zlog(ZLOG_DEBUG, "original STDERR fd is not restored, maybe function is called from a child: dup2()"); @@ -117,7 +108,37 @@ int fpm_stdio_restore_original_stderr(void) /* {{{ */ return 0; } -/* }}} */ + +int fpm_stdio_redirect_stderr_to_error_log(void) +{ + if (fpm_use_error_log()) { + /* prevent duping if logging to syslog */ + if (fpm_globals.error_log_fd > 0 && fpm_globals.error_log_fd != STDERR_FILENO) { + + /* there might be messages to stderr from other parts of the code, we need to log them all */ + if (0 > dup2(fpm_globals.error_log_fd, STDERR_FILENO)) { + zlog(ZLOG_SYSERROR, "failed to tie stderr fd with error_log fd: dup2()"); + return -1; + } + } + } + + return 0; +} + +int fpm_stdio_redirect_stderr_to_dev_null_for_syslog(void) +{ + if (fpm_use_error_log()) { +#ifdef HAVE_SYSLOG_H + if (fpm_globals.error_log_fd == ZLOG_SYSLOG) { + /* dup to /dev/null when using syslog */ + dup2(STDOUT_FILENO, STDERR_FILENO); + } +#endif + } + + return 0; +} int fpm_stdio_init_child(struct fpm_worker_pool_s *wp) /* {{{ */ { diff --git a/sapi/fpm/fpm/fpm_stdio.h b/sapi/fpm/fpm/fpm_stdio.h index 05b30ed6adbd3..c3927f26a092b 100644 --- a/sapi/fpm/fpm/fpm_stdio.h +++ b/sapi/fpm/fpm/fpm_stdio.h @@ -17,6 +17,6 @@ int fpm_stdio_parent_use_pipes(struct fpm_child_s *child); int fpm_stdio_discard_pipes(struct fpm_child_s *child); int fpm_stdio_open_error_log(int reopen); int fpm_stdio_save_original_stderr(void); -int fpm_stdio_restore_original_stderr(void); +int fpm_stdio_restore_original_stderr(int close_after_restore); #endif From c76be3cf0304f5777597ccbb181b89f1ab71069d Mon Sep 17 00:00:00 2001 From: Dmitry Menshikov Date: Mon, 4 Jul 2022 11:46:28 +0300 Subject: [PATCH 6/7] FPM. access.log with stderr begins to write logs to error_log after daemon reload (GH-8885) --- sapi/fpm/fpm/fpm_stdio.h | 2 ++ 1 file changed, 2 insertions(+) diff --git a/sapi/fpm/fpm/fpm_stdio.h b/sapi/fpm/fpm/fpm_stdio.h index c3927f26a092b..49be50de562d9 100644 --- a/sapi/fpm/fpm/fpm_stdio.h +++ b/sapi/fpm/fpm/fpm_stdio.h @@ -18,5 +18,7 @@ int fpm_stdio_discard_pipes(struct fpm_child_s *child); int fpm_stdio_open_error_log(int reopen); int fpm_stdio_save_original_stderr(void); int fpm_stdio_restore_original_stderr(int close_after_restore); +int fpm_stdio_redirect_stderr_to_dev_null_for_syslog(void); +int fpm_stdio_redirect_stderr_to_error_log(void); #endif From 37014d4607544ebefd8b0e7a2217fc6098ee233c Mon Sep 17 00:00:00 2001 From: Dmitry Menshikov Date: Mon, 4 Jul 2022 15:55:03 +0300 Subject: [PATCH 7/7] FPM. access.log with stderr begins to write logs to error_log after daemon reload (GH-8885). Tests. --- .../tests/bug8885-stderr-fd-reload-usr1.phpt | 92 +++++++++++++++++++ .../tests/bug8885-stderr-fd-reload-usr2.phpt | 92 +++++++++++++++++++ sapi/fpm/tests/tester.inc | 17 +++- 3 files changed, 199 insertions(+), 2 deletions(-) create mode 100644 sapi/fpm/tests/bug8885-stderr-fd-reload-usr1.phpt create mode 100644 sapi/fpm/tests/bug8885-stderr-fd-reload-usr2.phpt diff --git a/sapi/fpm/tests/bug8885-stderr-fd-reload-usr1.phpt b/sapi/fpm/tests/bug8885-stderr-fd-reload-usr1.phpt new file mode 100644 index 0000000000000..37524a4bafec2 --- /dev/null +++ b/sapi/fpm/tests/bug8885-stderr-fd-reload-usr1.phpt @@ -0,0 +1,92 @@ +--TEST-- +FPM: bug8885 - access.log with stderr begins to write logs to error_log after daemon reload (GH-8885) +--SKIPIF-- + +--FILE-- + true]); +// getPrefixedFile('err.log') is the same path that returns processTemplate('{{FILE:LOG}}') +$errorLogFile = $tester->getPrefixedFile('err.log'); + +$tester->start(); +$tester->expectNoLogMessages(); + +$content = file_get_contents($errorLogFile); +assert($content !== false && strlen($content) > 0, 'File must not be empty'); + +$errorLogLines = explode("\n", $content); +array_pop($errorLogLines); + +assert(count($errorLogLines) === 2, 'Expected 2 records in the error_log file'); +assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid')); +assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections')); + +$tester->ping('{{ADDR}}'); +$stderrLines = $tester->getLogLines(-1); +assert(count($stderrLines) === 1, 'Expected 1 record in the stderr output (access.log)'); +$stderrLine = $stderrLines[0]; +assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLine), 'Incorrect format of access.log record'); + +$tester->signal('USR1'); +$tester->expectNoLogMessages(); + +$content = file_get_contents($errorLogFile); +assert($content !== false && strlen($content) > 0, 'File must not be empty'); +$errorLogLines = explode("\n", $content); +array_pop($errorLogLines); + +assert(count($errorLogLines) >= 4, 'Expected at least 4 records in the error_log file'); +assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid')); +assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections')); +assert(strpos($errorLogLines[2], 'NOTICE: error log file re-opened')); +assert(strpos($errorLogLines[3], 'NOTICE: access log file re-opened')); + + +$tester->ping('{{ADDR}}'); +$stderrLines = $tester->getLogLines(-1); +assert(count($stderrLines) === 1, 'Must be only 1 record in the access.log'); +assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLines[0]), 'Incorrect format of access.log record'); + +$tester->terminate(); +$stderrLines = $tester->expectNoLogMessages(); + +$content = file_get_contents($errorLogFile); +assert($content !== false && strlen($content) > 0, 'File must not be empty'); +$errorLogLines = explode("\n", $content); +array_pop($errorLogLines); +$errorLogLastLine = array_pop($errorLogLines); +assert(strpos($errorLogLastLine, 'NOTICE: exiting, bye-bye')); + +$tester->close(); +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/bug8885-stderr-fd-reload-usr2.phpt b/sapi/fpm/tests/bug8885-stderr-fd-reload-usr2.phpt new file mode 100644 index 0000000000000..16aea8afb828c --- /dev/null +++ b/sapi/fpm/tests/bug8885-stderr-fd-reload-usr2.phpt @@ -0,0 +1,92 @@ +--TEST-- +FPM: bug8885 - access.log with stderr begins to write logs to error_log after daemon reload (GH-8885) +--SKIPIF-- + +--FILE-- + true]); +// getPrefixedFile('err.log') is the same path that returns processTemplate('{{FILE:LOG}}') +$errorLogFile = $tester->getPrefixedFile('err.log'); + +$tester->start(); +$tester->expectNoLogMessages(); + +$content = file_get_contents($errorLogFile); +assert($content !== false && strlen($content) > 0, 'File must not be empty'); + +$errorLogLines = explode("\n", $content); +array_pop($errorLogLines); + +assert(count($errorLogLines) === 2, 'Expected 2 records in the error_log file'); +assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid')); +assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections')); + +$tester->ping('{{ADDR}}'); +$stderrLines = $tester->getLogLines(-1); +assert(count($stderrLines) === 1, 'Expected 1 record in the stderr output (access.log)'); +$stderrLine = $stderrLines[0]; +assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLine), 'Incorrect format of access.log record'); + +$tester->signal('USR2'); +$tester->expectLogNotice('using inherited socket fd=\d+, "127.0.0.1:\d+"'); + +$content = file_get_contents($errorLogFile); +assert($content !== false && strlen($content) > 0, 'File must not be empty'); +$errorLogLines = explode("\n", $content); +array_pop($errorLogLines); + +assert(count($errorLogLines) >= 5, 'Expected at least 5 records in the error_log file'); +assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid')); +assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections')); +assert(strpos($errorLogLines[2], 'NOTICE: Reloading in progress')); +assert(strpos($errorLogLines[3], 'NOTICE: reloading: execvp')); +assert(strpos($errorLogLines[4], 'NOTICE: using inherited socket')); + +$tester->ping('{{ADDR}}'); +$stderrLines = $tester->getLogLines(-1); +assert(count($stderrLines) === 1, 'Must be only 1 record in the access.log'); +assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLines[0]), 'Incorrect format of access.log record'); + +$tester->terminate(); +$stderrLines = $tester->expectNoLogMessages(); + +$content = file_get_contents($errorLogFile); +assert($content !== false && strlen($content) > 0, 'File must not be empty'); +$errorLogLines = explode("\n", $content); +array_pop($errorLogLines); +$errorLogLastLine = array_pop($errorLogLines); +assert(strpos($errorLogLastLine, 'NOTICE: exiting, bye-bye')); + +$tester->close(); +?> +Done +--EXPECT-- +Done +--CLEAN-- + diff --git a/sapi/fpm/tests/tester.inc b/sapi/fpm/tests/tester.inc index e607035df1b31..d9674f495e9e0 100644 --- a/sapi/fpm/tests/tester.inc +++ b/sapi/fpm/tests/tester.inc @@ -35,6 +35,11 @@ class Tester */ const FILE_EXT_PID = 'pid'; + /** + * Name for the option to manage php-fpm --force-stderr flag + */ + const PHP_FPM_DISABLE_FORCE_STDERR = 'disable-force-stderr'; + /** * @var array */ @@ -365,7 +370,15 @@ class Tester { $configFile = $this->createConfig(); $desc = $this->outDesc ? [] : [1 => array('pipe', 'w'), 2 => array('redirect', 1)]; - $cmd = [self::findExecutable(), '-F', '-O', '-y', $configFile]; + + $cmd = [self::findExecutable(), '-F', '-y', $configFile]; + + if (!(isset($this->options[self::PHP_FPM_DISABLE_FORCE_STDERR]) && + $this->options[self::PHP_FPM_DISABLE_FORCE_STDERR] === true) + ) { + $cmd[] = '-O'; + } + if (getenv('TEST_FPM_RUN_AS_ROOT')) { $cmd[] = '--allow-to-run-as-root'; } @@ -1138,7 +1151,7 @@ class Tester * @param string $prefix * @return string */ - private function getPrefixedFile(string $extension, string $prefix = null) + public function getPrefixedFile(string $extension, string $prefix = null) { $fileName = rtrim($this->fileName, '.'); if (!is_null($prefix)) {