FPM. access.log with stderr begins to write logs to error_log after daemon reload

[WoZ]

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.log

With 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 events

Expected 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) = 116

As 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

[bukka]

This is a known issue: see https://bugs.php.net/bug.php?id=73886

[bukka]

Unfortunately this is not considered as a bug because catch_worker_output is 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]

@bukka I saw the ticket you mentioned. I don't think it's the same issue and that catch_worker_output is related to this.

catch_worker_output allows to capture output to std* from PHP scripts (for example). But access.log isn't a part of that logic. FPM worker opens an access.log and writes to it directly, independently of the catch_worker_output.

[bukka]

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_final is 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.

[WoZ]

@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.