Repository navigation
FPM. access.log with stderr begins to write logs to error_log after daemon reload #8885
Description
Description
Configuration:
[global]
pid = /usr/local/var/run/php-fpm.pid
error_log = /usr/local/var/log/php-fpm.log
log_level = debug
log_limit = 8192
daemonize = no
[www]
user = www-data
group = www-data
listen = 9000
pm = static
pm.max_children = 1
access.log = /proc/self/fd/2
access.format = "%R - %t \"%m %r%Q%q\" %s %f %{seconds}d %{bytes}M %{total}C"
slowlog = /dev/stderr
request_slowlog_timeout = 1s
request_slowlog_trace_depth = 20
request_terminate_timeout = 2s
request_terminate_timeout_track_finished = yes
catch_workers_output = yes
decorate_workers_output = yes
clear_env = no
php_value[fastcgi.logging] = 1
php_value[error_log] = /tmp/fpm-php.www.logWith this configuration records that are expected to be in the stderr appear in the stderr, but till the first reload with SIGUSR2 command. After reload they appear in the error_log file configured in the php-fpm.conf. php-fpm is launched in docker container (official one), foreground mode, without --force-stderr.
Actual result:
Record in the file configured in the php-fpm error_log
172.16.2.3 - 28/Jun/2022:12:13:28 +0000 "HEAD /phpinfo.php" 200 /var/www/html/public/phpinfo.php 0.004 2097152 0.00
[28-Jun-2022 12:13:28.683913] DEBUG: pid 1, fpm_event_loop(), line 430: event module triggered 1 eventsExpected result: access log record appears in the stderr.
Details
I prepared the demo setup. https://github.com/WoZ/php-fpm-issue-8885
You may use it to reproduce the issue. Check my repo and you may find instructions in the README.md.
Also, I added strace output and some analysis I did.
# this is an error_log settings, php-fpm master process
12:33:29.003325 open("/usr/local/var/log/php-fpm.log", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 3</usr/local/var/log/php-fpm.log>
12:33:29.004759 open("/dev/stderr", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 4<pipe:[47154]>
12:33:29.005140 close(4<pipe:[47154]>) = 0
# this is an access.log settings, php-fpm master process
12:33:29.005341 open("/proc/self/fd/2", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 4<pipe:[47154]>
12:33:29.005848 write(3</usr/local/var/log/php-fpm.log>, "[28-Jun-2022 12:33:29.005606] DEBUG: pid 9, fpm_log_open(), line 48: open access log (/proc/self/fd/2)\n", 103) = 103
12:33:29.006094 fcntl(4<pipe:[47154]>, F_GETFD) = 0
12:33:29.006284 fcntl(4<pipe:[47154]>, F_SETFD, FD_CLOEXEC) = 0
# Block with an issue
12:33:29.014762 open("/usr/local/var/run/php-fpm.pid", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0644) = 9</usr/local/var/run/php-fpm.pid>
12:33:29.015091 write(9</usr/local/var/run/php-fpm.pid>, "9", 1) = 1
12:33:29.015323 close(9</usr/local/var/run/php-fpm.pid>) = 0
# dup2 closes fd=2 (/proc/self/fd/2) and reopens it. This call breaks expected behaviour.
# https://stackoverflow.com/questions/24538470/what-does-dup2-do-in-c
12:33:29.015667 dup2(3</usr/local/var/log/php-fpm.log>, 2<pipe:[47154]>) = 2</usr/local/var/log/php-fpm.log>
12:33:29.016162 write(3</usr/local/var/log/php-fpm.log>, "[28-Jun-2022 12:33:29.015948] NOTICE: pid 9, fpm_init(), line 83: fpm is running, pid 9\n", 88) = 88
12:33:29.016365 pipe([9<pipe:[42549]>, 10<pipe:[42549]>]) = 0
# after child born... curl request before reload, writes to fd=4 that points to (/proc/self/fd/2)
[pid 10] 12:39:44.504798 read(3<TCPv6:[[::ffff:172.16.2.2]:9000->[::ffff:172.16.2.3]:34100]>, "\1\4\0\1\0\0\0\0", 8) = 8
[pid 10] 12:39:44.511915 open("/var/www/html/public/phpinfo.php", O_RDONLY|O_LARGEFILE) = 5</var/www/html/public/phpinfo.php>
[pid 10] 12:39:44.513938 read(5</var/www/html/public/phpinfo.php>, "<?php\nphpinfo();", 16) = 16
[pid 10] 12:39:44.515274 close(5</var/www/html/public/phpinfo.php>) = 0
[pid 10] 12:39:44.517943 write(4<pipe:[47154]>, "172.16.2.3 - 28/Jun/2022:12:39:44 +0000 \"HEAD /phpinfo.php\" 200 /var/www/html/public/phpinfo.php 0.014 2097152 0.00\n", 116172.16.2.3 - 28/Jun/2022:12:39:44 +0000 "HEAD /phpinfo.php" 200 /var/www/html/public/phpinfo.php 0.014 2097152 0.00
) = 116
[pid 10] 12:39:44.518439 write(3<TCPv6:[[::ffff:172.16.2.2]:9000->[::ffff:172.16.2.3]:34100]>, "\1\6\0\1\0D\4\0X-Powered-By: PHP/7.4.29\r\nContent-type: text/html; charset=UTF-8\r\n\r\n\0\0\0\0\1\3\0\1\0\10\0\0\0\0\0\0\0\0\0\0", 96) = 96
# reload...
[pid 9] 12:49:25.770552 write(3</usr/local/var/log/php-fpm.log>, "[28-Jun-2022 12:49:25.770507] DEBUG: pid 9, fpm_got_signal(), line 123: received SIGUSR2\n", 89) = 89
...
[pid 10] 12:49:25.776421 +++ killed by SIGTERM +++
...
12:49:25.786318 execve("/usr/local/sbin/php-fpm", ["php-fpm"], 0x7f87eeed6d60 /* 16 vars */) = 0
...
12:49:25.860843 open("/usr/local/var/log/php-fpm.log", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 3</usr/local/var/log/php-fpm.log>
...
# here we see that /dev/stderr is relinked to /usr/local/var/log/php-fpm.log
12:49:25.860995 open("/dev/stderr", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 4</usr/local/var/log/php-fpm.log>
12:49:25.861057 close(4</usr/local/var/log/php-fpm.log>) = 0
# now /proc/self/fd/2 points to /usr/local/var/log/php-fpm.log
12:49:25.861091 open("/proc/self/fd/2", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 4</usr/local/var/log/php-fpm.log>
12:49:25.861169 write(3</usr/local/var/log/php-fpm.log>, "[28-Jun-2022 12:49:25.861140] DEBUG: pid 9, fpm_log_open(), line 48: open access log (/proc/self/fd/2)\n", 103) = 103
...
[pid 18] 13:22:13.000553 write(4</usr/local/var/log/php-fpm.log>, "172.16.2.3 - 28/Jun/2022:13:22:12 +0000 \"HEAD /phpinfo.php\" 200 /var/www/html/public/phpinfo.php 0.009 2097152 0.00\n", 116) = 116As I see, the method that does dup2 is fpm_stdio_init_final and it's called from fpm_init.
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) {
/* 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
}
zlog_set_launched();
return 0;
}
PHP Version
All versions are affected
Operating System
Alpine, but actually all OSes are affected
Activity
[-]FPM. access.log with stderr begins write logs to error_log after daemon reload[/-][+]FPM. access.log with stderr begins to write logs to error_log after daemon reload[/+]bukka commentedon Jun 29, 2022
This is a known issue: see https://bugs.php.net/bug.php?id=73886
bukka commentedon Jun 29, 2022
Unfortunately this is not considered as a bug because
catch_worker_outputis catching everything by design. However the plan is to introduce an option that would allow this separation with additional file descriptor. It's quite higher on my TODO list so it should get to PHP 8.3 hopefully.WoZ commentedon Jul 1, 2022
@bukka I saw the ticket you mentioned. I don't think it's the same issue and that
catch_worker_outputis related to this.catch_worker_outputallows to capture output to std* from PHP scripts (for example). Butaccess.logisn't a part of that logic. FPM worker opens anaccess.logand writes to it directly, independently of thecatch_worker_output.bukka commentedon Jul 2, 2022
Ok I looked a bit more into this. First of all I agree that this is a different issue and it looks really like a bug.
The reason for this is that initially the access log is open before
fpm_stdio_init_finalis called so it all works but after the reload (execvp), the stderr stays pointing the file so it's then open again but this time pointing to the file. I think we should probably somehow store original stderr and then reset it before the reload or before re-opening access log after receiving SIGUSR1 which is another place where I expect you would see this issue.FPM. access.log with stderr begins to write logs to error_log after d…
WoZ commentedon Jul 3, 2022
@bukka I prepared PR, please, check it. Some test has failed. That's because of changes in log output and some flow of processing. I will fix them after the principal agreement on this approach. Thank you.
FPM. access.log with stderr begins to write logs to error_log after d…
WoZ commentedon Jul 3, 2022
Some details of testing.
Then code in PR calls dup and makes a record about this.
The last line is generated by the
fpm_stdio_init_final.Then I launch
teststdio.phpto check access.log andcatch_worker_output.4<pipe:[2249786]>is the original STDERR fd.Then run
kill -USR2 9.stderr fd was restored.
Let's launch
teststdio.phpone more time...All looks good.
USR1
kill -USR1 9The error_log:
strace:
All looks fine.
Other bugs
These bugs aren't related to this ticket, but it worth to mention them.
fpm_stdio_restore_original_stderr(), line 105: restoring original STDERR fd: dup2(). The reason is duplicated fragment of code invzlogfunction in thezlog.c.FPM. access.log with stderr begins to write logs to error_log after d…
FPM. access.log with stderr begins to write logs to error_log after d…
FPM. access.log with stderr begins to write logs to error_log after d…
FPM. access.log with stderr begins to write logs to error_log after d…
FPM. access.log with stderr begins to write logs to error_log after d…
Fix GH-8885: access.log with stderr writes logs to error_log after re…
Fix GH-8885 tests on MacOS
Re-add fixed tests for GH-8885