Skip to content

Commit f92505c

Browse files
WoZbukka
WoZ
authored and
bukka
committed
Fix GH-8885: access.log with stderr writes logs to error_log after reload
This fix allows restoring the the original stderr so the logs are correctly written.
1 parent 4135e60 commit f92505c

File tree

9 files changed

+282
-9
lines changed

9 files changed

+282
-9
lines changed

‎NEWS

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,10 @@ PHP NEWS
1212
. Fixed bug #79451 (DOMDocument->replaceChild on doctype causes double free).
1313
(Nathan Freeman)
1414

15+
- FPM:
16+
. Fixed bug GH-8885 (FPM access.log with stderr begins to write logs to
17+
error_log after daemon reload). (Dmitry Menshikov)
18+
1519
- Streams:
1620
. Fixed bug GH-9316 ($http_response_header is wrong for long status line).
1721
(cmb, timwolla)

‎sapi/fpm/fpm/fpm_conf.c

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1282,6 +1282,10 @@ static int fpm_conf_post_process(int force_daemon) /* {{{ */
12821282
fpm_evaluate_full_path(&fpm_global_config.error_log, NULL, PHP_LOCALSTATEDIR, 0);
12831283
}
12841284

1285+
if (0 > fpm_stdio_save_original_stderr()) {
1286+
return -1;
1287+
}
1288+
12851289
if (0 > fpm_stdio_open_error_log(0)) {
12861290
return -1;
12871291
}

‎sapi/fpm/fpm/fpm_events.c

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -104,6 +104,11 @@ static void fpm_got_signal(struct fpm_event_s *ev, short which, void *arg) /* {{
104104
break;
105105
case '1' : /* SIGUSR1 */
106106
zlog(ZLOG_DEBUG, "received SIGUSR1");
107+
108+
/* fpm_stdio_init_final tied STDERR fd with error_log fd. This affects logging to the
109+
* access.log if it was configured to write to the stderr. Check #8885. */
110+
fpm_stdio_restore_original_stderr(0);
111+
107112
if (0 == fpm_stdio_open_error_log(1)) {
108113
zlog(ZLOG_NOTICE, "error log file re-opened");
109114
} else {
@@ -118,6 +123,9 @@ static void fpm_got_signal(struct fpm_event_s *ev, short which, void *arg) /* {{
118123
}
119124
/* else no access log are set */
120125

126+
/* We need to tie stderr with error_log in the master process after log files reload. Check #8885. */
127+
fpm_stdio_redirect_stderr_to_error_log();
128+
121129
break;
122130
case '2' : /* SIGUSR2 */
123131
zlog(ZLOG_DEBUG, "received SIGUSR2");

‎sapi/fpm/fpm/fpm_process_ctl.c

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@
1818
#include "fpm_worker_pool.h"
1919
#include "fpm_scoreboard.h"
2020
#include "fpm_sockets.h"
21+
#include "fpm_stdio.h"
2122
#include "zlog.h"
2223

2324

@@ -99,6 +100,9 @@ static void fpm_pctl_exec(void)
99100
);
100101

101102
fpm_cleanups_run(FPM_CLEANUP_PARENT_EXEC);
103+
104+
fpm_stdio_restore_original_stderr(1);
105+
102106
execvp(saved_argv[0], saved_argv);
103107
zlog(ZLOG_SYSERROR, "failed to reload: execvp() failed");
104108
exit(FPM_EXIT_SOFTWARE);

‎sapi/fpm/fpm/fpm_stdio.c

Lines changed: 59 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919
#include "fpm_stdio.h"
2020
#include "zlog.h"
2121

22+
static int fd_stderr_original = -1;
2223
static int fd_stdout[2];
2324
static int fd_stderr[2];
2425

@@ -59,25 +60,80 @@ static inline int fpm_use_error_log(void) {
5960
}
6061

6162
int fpm_stdio_init_final(void)
63+
{
64+
if (0 > fpm_stdio_redirect_stderr_to_error_log() ||
65+
0 > fpm_stdio_redirect_stderr_to_dev_null_for_syslog()) {
66+
67+
return -1;
68+
}
69+
70+
zlog_set_launched();
71+
return 0;
72+
}
73+
/* }}} */
74+
75+
int fpm_stdio_save_original_stderr(void)
76+
{
77+
/* php-fpm loses STDERR fd after call of the fpm_stdio_init_final(). Check #8555. */
78+
zlog(ZLOG_DEBUG, "saving original STDERR fd: dup()");
79+
fd_stderr_original = dup(STDERR_FILENO);
80+
if (0 > fd_stderr_original) {
81+
zlog(ZLOG_SYSERROR, "failed to save original STDERR fd, access.log records may appear in error_log: dup()");
82+
return -1;
83+
}
84+
85+
return 0;
86+
}
87+
88+
int fpm_stdio_restore_original_stderr(int close_after_restore)
89+
{
90+
/* php-fpm loses STDERR fd after call of the fpm_stdio_init_final(). Check #8555. */
91+
if (-1 != fd_stderr_original) {
92+
zlog(ZLOG_DEBUG, "restoring original STDERR fd: dup2()");
93+
if (0 > dup2(fd_stderr_original, STDERR_FILENO)) {
94+
zlog(ZLOG_SYSERROR, "failed to restore original STDERR fd, access.log records may appear in error_log: dup2()");
95+
return -1;
96+
} else {
97+
if (close_after_restore) {
98+
close(fd_stderr_original);
99+
}
100+
}
101+
} else {
102+
zlog(ZLOG_DEBUG, "original STDERR fd is not restored, maybe function is called from a child: dup2()");
103+
return -1;
104+
}
105+
106+
return 0;
107+
}
108+
109+
int fpm_stdio_redirect_stderr_to_error_log(void)
62110
{
63111
if (fpm_use_error_log()) {
64112
/* prevent duping if logging to syslog */
65113
if (fpm_globals.error_log_fd > 0 && fpm_globals.error_log_fd != STDERR_FILENO) {
66114

67115
/* there might be messages to stderr from other parts of the code, we need to log them all */
68116
if (0 > dup2(fpm_globals.error_log_fd, STDERR_FILENO)) {
69-
zlog(ZLOG_SYSERROR, "failed to init stdio: dup2()");
117+
zlog(ZLOG_SYSERROR, "failed to tie stderr fd with error_log fd: dup2()");
70118
return -1;
71119
}
72120
}
121+
}
122+
123+
return 0;
124+
}
125+
126+
int fpm_stdio_redirect_stderr_to_dev_null_for_syslog(void)
127+
{
128+
if (fpm_use_error_log()) {
73129
#ifdef HAVE_SYSLOG_H
74-
else if (fpm_globals.error_log_fd == ZLOG_SYSLOG) {
130+
if (fpm_globals.error_log_fd == ZLOG_SYSLOG) {
75131
/* dup to /dev/null when using syslog */
76132
dup2(STDOUT_FILENO, STDERR_FILENO);
77133
}
78134
#endif
79135
}
80-
zlog_set_launched();
136+
81137
return 0;
82138
}
83139

@@ -331,10 +387,6 @@ int fpm_stdio_open_error_log(int reopen) /* {{{ */
331387
}
332388

333389
if (reopen) {
334-
if (fpm_use_error_log()) {
335-
dup2(fd, STDERR_FILENO);
336-
}
337-
338390
dup2(fd, fpm_globals.error_log_fd);
339391
close(fd);
340392
fd = fpm_globals.error_log_fd; /* for FD_CLOSEXEC to work */

‎sapi/fpm/fpm/fpm_stdio.h

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -16,5 +16,9 @@ void fpm_stdio_child_use_pipes(struct fpm_child_s *child);
1616
int fpm_stdio_parent_use_pipes(struct fpm_child_s *child);
1717
int fpm_stdio_discard_pipes(struct fpm_child_s *child);
1818
int fpm_stdio_open_error_log(int reopen);
19+
int fpm_stdio_save_original_stderr(void);
20+
int fpm_stdio_restore_original_stderr(int close_after_restore);
21+
int fpm_stdio_redirect_stderr_to_dev_null_for_syslog(void);
22+
int fpm_stdio_redirect_stderr_to_error_log(void);
1923

2024
#endif

‎sapi/fpm/tests/bug8885-stderr-fd-reload-usr1.phpt

Lines changed: 92 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,92 @@
1+
--TEST--
2+
FPM: bug8885 - access.log with stderr begins to write logs to error_log after daemon reload (GH-8885)
3+
--SKIPIF--
4+
<?php
5+
include "skipif.inc";
6+
FPM\Tester::skipIfRoot();
7+
?>
8+
--FILE--
9+
<?php
10+
11+
require_once "tester.inc";
12+
13+
$cfg = <<<EOT
14+
[global]
15+
error_log = {{FILE:LOG}}
16+
pid = {{FILE:PID}}
17+
[unconfined]
18+
listen = {{ADDR}}
19+
access.log=/proc/self/fd/2
20+
ping.path = /ping
21+
ping.response = pong
22+
pm = dynamic
23+
pm.max_children = 5
24+
pm.start_servers = 1
25+
pm.min_spare_servers = 1
26+
pm.max_spare_servers = 3
27+
EOT;
28+
29+
// php-fpm must not be launched with --force-stderr option
30+
$tester = new FPM\Tester($cfg, '', [FPM\Tester::PHP_FPM_DISABLE_FORCE_STDERR => true]);
31+
// getPrefixedFile('err.log') is the same path that returns processTemplate('{{FILE:LOG}}')
32+
$errorLogFile = $tester->getPrefixedFile('err.log');
33+
34+
$tester->start();
35+
$tester->expectNoLogMessages();
36+
37+
$content = file_get_contents($errorLogFile);
38+
assert($content !== false && strlen($content) > 0, 'File must not be empty');
39+
40+
$errorLogLines = explode("\n", $content);
41+
array_pop($errorLogLines);
42+
43+
assert(count($errorLogLines) === 2, 'Expected 2 records in the error_log file');
44+
assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
45+
assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
46+
47+
$tester->ping('{{ADDR}}');
48+
$stderrLines = $tester->getLogLines(-1);
49+
assert(count($stderrLines) === 1, 'Expected 1 record in the stderr output (access.log)');
50+
$stderrLine = $stderrLines[0];
51+
assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLine), 'Incorrect format of access.log record');
52+
53+
$tester->signal('USR1');
54+
$tester->expectNoLogMessages();
55+
56+
$content = file_get_contents($errorLogFile);
57+
assert($content !== false && strlen($content) > 0, 'File must not be empty');
58+
$errorLogLines = explode("\n", $content);
59+
array_pop($errorLogLines);
60+
61+
assert(count($errorLogLines) >= 4, 'Expected at least 4 records in the error_log file');
62+
assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
63+
assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
64+
assert(strpos($errorLogLines[2], 'NOTICE: error log file re-opened'));
65+
assert(strpos($errorLogLines[3], 'NOTICE: access log file re-opened'));
66+
67+
68+
$tester->ping('{{ADDR}}');
69+
$stderrLines = $tester->getLogLines(-1);
70+
assert(count($stderrLines) === 1, 'Must be only 1 record in the access.log');
71+
assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLines[0]), 'Incorrect format of access.log record');
72+
73+
$tester->terminate();
74+
$stderrLines = $tester->expectNoLogMessages();
75+
76+
$content = file_get_contents($errorLogFile);
77+
assert($content !== false && strlen($content) > 0, 'File must not be empty');
78+
$errorLogLines = explode("\n", $content);
79+
array_pop($errorLogLines);
80+
$errorLogLastLine = array_pop($errorLogLines);
81+
assert(strpos($errorLogLastLine, 'NOTICE: exiting, bye-bye'));
82+
83+
$tester->close();
84+
?>
85+
Done
86+
--EXPECT--
87+
Done
88+
--CLEAN--
89+
<?php
90+
require_once "tester.inc";
91+
FPM\Tester::clean();
92+
?>

‎sapi/fpm/tests/bug8885-stderr-fd-reload-usr2.phpt

Lines changed: 92 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,92 @@
1+
--TEST--
2+
FPM: bug8885 - access.log with stderr begins to write logs to error_log after daemon reload (GH-8885)
3+
--SKIPIF--
4+
<?php
5+
include "skipif.inc";
6+
FPM\Tester::skipIfRoot();
7+
?>
8+
--FILE--
9+
<?php
10+
11+
require_once "tester.inc";
12+
13+
$cfg = <<<EOT
14+
[global]
15+
error_log = {{FILE:LOG}}
16+
pid = {{FILE:PID}}
17+
[unconfined]
18+
listen = {{ADDR}}
19+
access.log=/proc/self/fd/2
20+
ping.path = /ping
21+
ping.response = pong
22+
pm = dynamic
23+
pm.max_children = 5
24+
pm.start_servers = 1
25+
pm.min_spare_servers = 1
26+
pm.max_spare_servers = 3
27+
EOT;
28+
29+
// php-fpm must not be launched with --force-stderr option
30+
$tester = new FPM\Tester($cfg, '', [FPM\Tester::PHP_FPM_DISABLE_FORCE_STDERR => true]);
31+
// getPrefixedFile('err.log') is the same path that returns processTemplate('{{FILE:LOG}}')
32+
$errorLogFile = $tester->getPrefixedFile('err.log');
33+
34+
$tester->start();
35+
$tester->expectNoLogMessages();
36+
37+
$content = file_get_contents($errorLogFile);
38+
assert($content !== false && strlen($content) > 0, 'File must not be empty');
39+
40+
$errorLogLines = explode("\n", $content);
41+
array_pop($errorLogLines);
42+
43+
assert(count($errorLogLines) === 2, 'Expected 2 records in the error_log file');
44+
assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
45+
assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
46+
47+
$tester->ping('{{ADDR}}');
48+
$stderrLines = $tester->getLogLines(-1);
49+
assert(count($stderrLines) === 1, 'Expected 1 record in the stderr output (access.log)');
50+
$stderrLine = $stderrLines[0];
51+
assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLine), 'Incorrect format of access.log record');
52+
53+
$tester->signal('USR2');
54+
$tester->expectLogNotice('using inherited socket fd=\d+, "127.0.0.1:\d+"');
55+
56+
$content = file_get_contents($errorLogFile);
57+
assert($content !== false && strlen($content) > 0, 'File must not be empty');
58+
$errorLogLines = explode("\n", $content);
59+
array_pop($errorLogLines);
60+
61+
assert(count($errorLogLines) >= 5, 'Expected at least 5 records in the error_log file');
62+
assert(strpos($errorLogLines[0], 'NOTICE: fpm is running, pid'));
63+
assert(strpos($errorLogLines[1], 'NOTICE: ready to handle connections'));
64+
assert(strpos($errorLogLines[2], 'NOTICE: Reloading in progress'));
65+
assert(strpos($errorLogLines[3], 'NOTICE: reloading: execvp'));
66+
assert(strpos($errorLogLines[4], 'NOTICE: using inherited socket'));
67+
68+
$tester->ping('{{ADDR}}');
69+
$stderrLines = $tester->getLogLines(-1);
70+
assert(count($stderrLines) === 1, 'Must be only 1 record in the access.log');
71+
assert(preg_match('/127.0.0.1 .* "GET \/ping" 200$/', $stderrLines[0]), 'Incorrect format of access.log record');
72+
73+
$tester->terminate();
74+
$stderrLines = $tester->expectNoLogMessages();
75+
76+
$content = file_get_contents($errorLogFile);
77+
assert($content !== false && strlen($content) > 0, 'File must not be empty');
78+
$errorLogLines = explode("\n", $content);
79+
array_pop($errorLogLines);
80+
$errorLogLastLine = array_pop($errorLogLines);
81+
assert(strpos($errorLogLastLine, 'NOTICE: exiting, bye-bye'));
82+
83+
$tester->close();
84+
?>
85+
Done
86+
--EXPECT--
87+
Done
88+
--CLEAN--
89+
<?php
90+
require_once "tester.inc";
91+
FPM\Tester::clean();
92+
?>

‎sapi/fpm/tests/tester.inc

Lines changed: 15 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,11 @@ class Tester
3535
*/
3636
const FILE_EXT_PID = 'pid';
3737

38+
/**
39+
* Name for the option to manage php-fpm --force-stderr flag
40+
*/
41+
const PHP_FPM_DISABLE_FORCE_STDERR = 'disable-force-stderr';
42+
3843
/**
3944
* @var array
4045
*/
@@ -365,7 +370,15 @@ class Tester
365370
{
366371
$configFile = $this->createConfig();
367372
$desc = $this->outDesc ? [] : [1 => array('pipe', 'w'), 2 => array('redirect', 1)];
368-
$cmd = [self::findExecutable(), '-F', '-O', '-y', $configFile];
373+
374+
$cmd = [self::findExecutable(), '-F', '-y', $configFile];
375+
376+
if (!(isset($this->options[self::PHP_FPM_DISABLE_FORCE_STDERR]) &&
377+
$this->options[self::PHP_FPM_DISABLE_FORCE_STDERR] === true)
378+
) {
379+
$cmd[] = '-O';
380+
}
381+
369382
if (getenv('TEST_FPM_RUN_AS_ROOT')) {
370383
$cmd[] = '--allow-to-run-as-root';
371384
}
@@ -1138,7 +1151,7 @@ class Tester
11381151
* @param string $prefix
11391152
* @return string
11401153
*/
1141-
private function getPrefixedFile(string $extension, string $prefix = null)
1154+
public function getPrefixedFile(string $extension, string $prefix = null)
11421155
{
11431156
$fileName = rtrim($this->fileName, '.');
11441157
if (!is_null($prefix)) {

0 commit comments

Comments
 (0)