[php-src] Issue #8885: FPM. access.log with stderr begins write logs to error_log after daemon reload

Issue: https://github.com/php/php-src/issues/8885 Author: WoZ ### Description Configuration: ```ini [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 ```shell 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. 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. ```shell # 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