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

WoZ · 2022-06-28T14:48:15Z

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

The text was updated successfully, but these errors were encountered:

bukka · 2022-06-29T21:58:35Z

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

bukka · 2022-06-29T22:03:04Z

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 · 2022-07-01T10:24:17Z

@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 · 2022-07-02T22:36:34Z

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.

…aemon reload (phpGH-8885)

WoZ · 2022-07-03T11:15:35Z

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

…aemon reload (phpGH-8885)

WoZ · 2022-07-03T13:27:33Z

Some details of testing.

php-fpm_1  | 11:38:22.821769 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>
php-fpm_1  | 11:38:22.822200 fcntl(3</usr/local/var/log/php-fpm.log>, F_GETFD) = 0
php-fpm_1  | 11:38:22.822299 fcntl(3</usr/local/var/log/php-fpm.log>, F_SETFD, FD_CLOEXEC) = 0
php-fpm_1  | 11:38:22.822389 open("/dev/stderr", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 4<pipe:[2249786]>
php-fpm_1  | 11:38:22.822556 close(4<pipe:[2249786]>) = 0
php-fpm_1  | 11:38:22.822600 open("/proc/self/fd/2", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 4<pipe:[2249786]>
php-fpm_1  | 11:38:22.822822 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 11:38:22.822781] DEBUG: pid 9, fpm_log_open(), line 48: open access log (/proc/self/fd/2)\n", 103) = 103
php-fpm_1  | 11:38:22.822888 fcntl(4<pipe:[2249786]>, F_GETFD) = 0
php-fpm_1  | 11:38:22.822935 fcntl(4<pipe:[2249786]>, F_SETFD, FD_CLOEXEC) = 0

Then code in PR calls dup and makes a record about this.

php-fpm_1  | 11:38:22.853432 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 11:38:22.853414] DEBUG: pid 9, fpm_stdio_save_original_stderr(), line 97: saving original STDERR fd: dup()\n", 120) = 120
php-fpm_1  | 11:38:22.853490 dup(2<pipe:[2249786]>)  = 9<pipe:[2249786]>
php-fpm_1  | 11:38:22.853524 dup2(3</usr/local/var/log/php-fpm.log>, 2<pipe:[2249786]>) = 2</usr/local/var/log/php-fpm.log>

The last line is generated by the fpm_stdio_init_final.

Then I launch teststdio.php to check access.log and catch_worker_output.

<?php

file_put_contents('php://stdout', 'To stdout');
file_put_contents('php://stderr', 'To stderr');

php-fpm_1  | [pid    10] 11:45:08.482581 write(6<pipe:[2246488]>, "To stdout", 9) = 9
php-fpm_1  | [pid     9] 11:45:08.482764 read(10<pipe:[2246488]>, "To stdout", 1023) = 9
php-fpm_1  | [pid     9] 11:45:08.484961 write(2</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 11:45:08.482880] WARNING: pid 9, (null)(), line 0: [pool www] child 10 said into stdout: \"To stdout\"\n", 114) = 114
php-fpm_1  | [pid    10] 11:45:08.484666 write(6<pipe:[2246491]>, "To stderr", 9) = 9
php-fpm_1  | [pid     9] 11:45:08.485150 read(12<pipe:[2246491]>, "To stderr", 1023) = 9
php-fpm_1  | [pid     9] 11:45:08.485398 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 11:45:08.485375] DEBUG: pid 9, fpm_event_loop(), line 440: event module triggered 1 events\n", 104) = 104
php-fpm_1  | [pid    10] 11:45:08.486668 write(php-fpm_1  | [pid     9] 11:45:08.485398 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 11:45:08.485375] DEBUG: pid 9, fpm_event_loop(), line 440: event module triggered 1 events\n", 104) = 104
php-fpm_1  | [pid    10] 11:45:08.486668 write(4<pipe:[2249786]>, "172.16.2.3 - 03/Jul/2022:11:45:08 +0000 \"GET /teststdio.php\" 200 /var/www/html/public/teststdio.php 0.115 2097152 0.00\n", 119172.16.2.3 - 03/Jul/2022:11:45:08 +0000 "GET /teststdio.php" 200 /var/www/html/public/teststdio.php 0.115 2097152 0.00
, "172.16.2.3 - 03/Jul/2022:11:45:08 +0000 \"GET /teststdio.php\" 200 /var/www/html/public/teststdio.php 0.115 2097152 0.00\n", 119172.16.2.3 - 03/Jul/2022:11:45:08 +0000 "GET /teststdio.php" 200 /var/www/html/public/teststdio.php 0.115 2097152 0.00

4<pipe:[2249786]> is the original STDERR fd.

Then run kill -USR2 9.

php-fpm_1  | 11:49:18.460185 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 11:49:18.459848] DEBUG: pid 9, fpm_pctl_exec(), line 81: Blocking some signals before reexec\n", 106) = 106
php-fpm_1  | 11:49:18.461207 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 11:49:18.460871] DEBUG: pid 9, fpm_stdio_restore_original_stderr(), line 105: restoring original STDERR fd: dup2()\n", 128) = 128
php-fpm_1  | 11:49:18.461741 dup2(9<pipe:[2249786]>, 2</usr/local/var/log/php-fpm.log>) = 2<pipe:[2249786]>
php-fpm_1  | 11:49:18.462696 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 11:49:18.462376] NOTICE: pid 9, fpm_pctl_exec(), line 90: reloading: execvp(\"php-fpm\", {\"php-fpm\"})\n", 113) = 113
php-fpm_1  | 11:49:18.462910 close(8<anon_inode:[eventpoll]>) = 0
php-fpm_1  | 11:49:18.507940 execve("/usr/local/sbin/php-fpm", ["php-fpm"], 0x7f3434d2e370 /* 16 vars */) = 0
php-fpm_1  | 11:49:18.517098 open("/lib/libreadline.so.8", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No suc

stderr fd was restored.

php-fpm_1  | 11:49:18.843150 open("/dev/stderr", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 4<pipe:[2249786]>
php-fpm_1  | 11:49:18.843416 close(4<pipe:[2249786]>) = 0
php-fpm_1  | 11:49:18.843452 open("/proc/self/fd/2", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 4<pipe:[2249786]>
php-fpm_1  | 11:49:18.843530 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 11:49:18.843504] DEBUG: pid 9, fpm_log_open(), line 48: open access log (/proc/self/fd/2)\n", 103) = 103

Let's launch teststdio.php one more time...

php-fpm_1  | [pid    20] 11:53:48.127531 write(6<pipe:[2256068]>, "To stdout", 9) = 9
php-fpm_1  | [pid     9] 11:53:48.128094 read(11<pipe:[2256068]>,  <unfinished ...>
php-fpm_1  | [pid    20] 11:53:48.128144 close(6<pipe:[2256068]> <unfinished ...>
php-fpm_1  | [pid     9] 11:53:48.128207 <... read resumed>"To stdout", 1023) = 9
php-fpm_1  | [pid    20] 11:53:48.128285 <... close resumed>) = 0
php-fpm_1  | [pid    20] 11:53:48.128452 dup(2<pipe:[2256069]>) = 6<pipe:[2256069]>
php-fpm_1  | [pid     9] 11:53:48.129587 read(11<pipe:[2256068]>, 0x7fffd0f69be0, 1023) = -1 EAGAIN (Resource temporarily unavailable)
php-fpm_1  | [pid    20] 11:53:48.130013 write(6<pipe:[2256069]>, "To stderr", 9) = 9
php-fpm_1  | [pid    20] 11:53:48.130277 close(6<pipe:[2256069]>) = 0
php-fpm_1  | [pid     9] 11:53:48.130580 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 11:53:48.130187] DEBUG: pid 9, fpm_event_loop(), line 440: event module triggered 1 events\n", 104) = 104
php-fpm_1  | [pid    20] 11:53:48.131620 write(4<pipe:[2249786]>, "172.16.2.3 - 03/Jul/2022:11:53:48 +0000 \"GET /teststdio.php\" 200 /var/www/html/public/teststdio.php 0.017 2097152 0.00\n", 119172.16.2.3 - 03/Jul/2022:11:53:48 +0000 "GET /teststdio.php" 200 /var/www/html/public/teststdio.php 0.017 2097152 0.00
php-fpm_1  | ) = 119

All looks good.

USR1

It's a new process! fds and pids have changed!

kill -USR1 9

The error_log:

[03-Jul-2022 12:33:54.277128] DEBUG: pid 9, fpm_got_signal(), line 106: received SIGUSR1
[03-Jul-2022 12:33:54.277266] DEBUG: pid 9, fpm_stdio_restore_original_stderr(), line 105: restoring original STDERR fd: dup2()
[03-Jul-2022 12:33:54.277415] DEBUG: pid 9, fpm_stdio_restore_original_stderr(), line 107: restoring original STDERR fd: dup2()
[03-Jul-2022 12:33:54.278961] NOTICE: pid 9, fpm_got_signal(), line 115: error log file re-opened
[03-Jul-2022 12:33:54.279426] DEBUG: pid 9, fpm_log_open(), line 48: open access log (/proc/self/fd/2)
[03-Jul-2022 12:33:54.280016] DEBUG: pid 9, fpm_pctl_kill_all(), line 167: [pool www] sending signal 3 SIGQUIT to child 10
[03-Jul-2022 12:33:54.280381] DEBUG: pid 9, fpm_pctl_kill_all(), line 178: 1 child(ren) still alive
[03-Jul-2022 12:33:54.281174] NOTICE: pid 9, fpm_got_signal(), line 122: access log file re-opened
[03-Jul-2022 12:33:54.281586] DEBUG: pid 9, fpm_stdio_save_original_stderr(), line 97: saving original STDERR fd: dup()
[03-Jul-2022 12:33:54.282345] DEBUG: pid 9, fpm_event_loop(), line 440: event module triggered 1 events
[03-Jul-2022 12:33:54.338557] DEBUG: pid 9, fpm_event_loop(), line 440: event module triggered 2 events
[03-Jul-2022 12:33:54.339063] DEBUG: pid 9, fpm_got_signal(), line 82: received SIGCHLD
[03-Jul-2022 12:33:54.339563] DEBUG: pid 9, fpm_event_loop(), line 440: event module triggered 1 events
[03-Jul-2022 12:33:54.339798] NOTICE: pid 9, fpm_children_bury(), line 259: [pool www] child 10 exited with code 0 after 88.178503 seconds from start
[03-Jul-2022 12:33:54.340255] DEBUG: pid 9, fpm_children_make(), line 407: blocking signals before child birth
[03-Jul-2022 12:33:54.340791] DEBUG: pid 9, fpm_children_make(), line 431: unblocking signals, child born
[03-Jul-2022 12:33:54.341291] NOTICE: pid 9, fpm_children_make(), line 437: [pool www] child 25 started

strace:

php-fpm_1  | 13:16:13.927831 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>
php-fpm_1  | 13:16:13.928655 fcntl(3</usr/local/var/log/php-fpm.log>, F_GETFD) = 0
php-fpm_1  | 13:16:13.928709 fcntl(3</usr/local/var/log/php-fpm.log>, F_SETFD, FD_CLOEXEC) = 0
php-fpm_1  | 13:16:13.928738 open("/dev/stderr", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 4<pipe:[2454604]>


# 4<pipe:[2454604]> is the original stderr

php-fpm_1  | 13:16:13.928850 close(4<pipe:[2454604]>) = 0
php-fpm_1  | 13:16:13.928888 open("/proc/self/fd/2", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 4<pipe:[2454604]>
php-fpm_1  | 13:16:13.929008 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 13:16:13.928982] DEBUG: pid 9, fpm_log_open(), line 48: open access log (/proc/self/fd/2)\n", 103) = 103


php-fpm_1  | 13:16:13.932867 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 13:16:13.932850] DEBUG: pid 9, fpm_stdio_save_original_stderr(), line 97: saving original STDERR fd: dup()\n", 120) = 120
php-fpm_1  | 13:16:13.932946 dup(2<pipe:[2454604]>)  = 9<pipe:[2454604]>


# 9<pipe:[2454604]> is a copy of the original stderr

#after fpm_stdio_init_final...
php-fpm_1  | 13:16:13.932979 dup2(3</usr/local/var/log/php-fpm.log>, 2<pipe:[2454604]>) = 2</usr/local/var/log/php-fpm.log>
php-fpm_1  | 13:16:13.933042 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 13:16:13.933019] NOTICE: pid 9, fpm_init(), line 83: fpm is running, pid 9\n", 88) = 88


# 2<pipe:[2454604]> is closed and reopened, tied to error_log fd==3

# after a launch of the `teststdio.php`
php-fpm_1  | [pid    10] 13:16:13.934042 write(6<pipe:[2454634]>, "To stdout", 9) = 9
php-fpm_1  | [pid    10] 13:16:13.934315 write(6<pipe:[2454634]>, "To stderr", 9) = 9
...
php-fpm_1  | [pid     9] 13:16:13.934339 write(2</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 13:16:13.934042] WARNING: pid 9, (null)(), line 0: [pool www] child 10 said into stdout: \"To stdout\"\n", 114) = 114
php-fpm_1  | [pid     9] 13:16:13.934381 write(2</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 13:16:13.934315] WARNING: pid 9, (null)(), line 0: [pool www] child 10 said into stderr: \"To stderr\"\n", 114) = 114

php-fpm_1  | [pid    10] 12:56:07.614788 write(4<pipe:[2454604]>, "172.16.2.3 - 03/Jul/2022:13:16:13 +0000 \"GET /teststdio.php\" 200 /var/www/html/public/teststdio.php 0.016 2097152 0.00\n", 119172.16.2.3 - 03/Jul/2022:12:56:07 +0000 "GET /teststdio.php" 200 /var/www/html/public/teststdio.php 0.016 2097152 0.00

# it's still stderr

# reloading...

php-fpm_1  | [pid     9] 13:16:21.401541 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 13:16:21.401508] DEBUG: pid 9, fpm_got_signal(), line 106: received SIGUSR1\n", 89) = 89
php-fpm_1  | [pid     9] 13:16:21.401870 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 13:16:21.401700] DEBUG: pid 9, fpm_stdio_restore_original_stderr(), line 105: restoring original STDERR fd: dup2()\n", 128) = 128
php-fpm_1  | [pid     9] 13:16:21.402142 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 13:16:21.402077] DEBUG: pid 9, fpm_stdio_restore_original_stderr(), line 107: restoring original STDERR fd: dup2()\n", 128) = 128
php-fpm_1  | [pid     9] 13:16:21.402200 dup2(9<pipe:[2454604]>, 2</usr/local/var/log/php-fpm.log>) = 2<pipe:[2454604]>
php-fpm_1  | [pid     9] 13:16:21.402371 open("/usr/local/var/log/php-fpm.log", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 11</usr/local/var/log/php-fpm.log>
php-fpm_1  | [pid     9] 13:16:21.402498 dup2(11</usr/local/var/log/php-fpm.log>, 3</usr/local/var/log/php-fpm.log>) = 3</usr/local/var/log/php-fpm.log>
php-fpm_1  | [pid     9] 13:16:21.402788 close(11</usr/local/var/log/php-fpm.log>) = 0
php-fpm_1  | [pid     9] 13:16:21.402854 fcntl(3</usr/local/var/log/php-fpm.log>, F_GETFD) = 0
php-fpm_1  | [pid     9] 13:16:21.402916 fcntl(3</usr/local/var/log/php-fpm.log>, F_SETFD, FD_CLOEXEC) = 0
php-fpm_1  | [pid     9] 13:16:21.403031 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 13:16:21.402977] NOTICE: pid 9, fpm_got_signal(), line 115: error log file re-opened\n", 98) = 98
php-fpm_1  | [pid     9] 13:16:21.403109 open("/proc/self/fd/2", O_WRONLY|O_CREAT|O_APPEND|O_LARGEFILE, 0600) = 11<pipe:[2454604]>
php-fpm_1  | [pid     9] 13:16:21.403352 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 13:16:21.403301] DEBUG: pid 9, fpm_log_open(), line 48: open access log (/proc/self/fd/2)\n", 103) = 103
php-fpm_1  | [pid     9] 13:16:21.403412 dup2(11<pipe:[2454604]>, 4<pipe:[2454604]>) = 4<pipe:[2454604]>
php-fpm_1  | [pid     9] 13:16:21.403547 close(11<pipe:[2454604]>) = 0
php-fpm_1  | [pid     9] 13:16:21.403712 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 13:16:21.403621] DEBUG: pid 9, fpm_pctl_kill_all(), line 167: [pool www] sending signal 3 SIGQUIT to child 10\n", 123) = 123


php-fpm_1  | [pid     9] 13:16:21.404776 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 13:16:21.404603] NOTICE: pid 9, fpm_got_signal(), line 122: access log file re-opened\n", 99) = 99
php-fpm_1  | [pid     9] 13:16:21.404870 write(3</usr/local/var/log/php-fpm.log>, "[03-Jul-2022 13:16:21.404848] DEBUG: pid 9, fpm_stdio_save_original_stderr(), line 97: saving original STDERR fd: dup()\n", 120) = 120
php-fpm_1  | [pid     9] 13:16:21.404937 dup(2<pipe:[2454604]>) = 11<pipe:[2454604]>
php-fpm_1  | [pid     9] 13:16:21.406326 dup2(3</usr/local/var/log/php-fpm.log>, 2<pipe:[2454604]>) = 2</usr/local/var/log/php-fpm.log>

All looks fine.

Other bugs

These bugs aren't related to this ticket, but it worth to mention them.

There is a small time frame when zlog.c static int launched is not set during php-fpm reload. So, some messages may appear in stderr instead of error_log. error_log is opened at this point in time.
Duplicated debug records fpm_stdio_restore_original_stderr(), line 105: restoring original STDERR fd: dup2(). The reason is duplicated fragment of code in vzlog function in the zlog.c.

…aemon reload (phpGH-8885)

…aemon reload (phpGH-8885). Tests.

WoZ added Bug Status: Needs Triage labels Jun 28, 2022

WoZ changed the title ~~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 Jun 28, 2022

cmb69 added the SAPI: fpm label Jun 28, 2022

Girgias assigned bukka Jun 29, 2022

bukka removed Status: Needs Triage Bug labels Jun 29, 2022

WoZ added a commit to WoZ/php-src that referenced this issue Jul 3, 2022

FPM. access.log with stderr begins to write logs to error_log after d…

2d74d3b

…aemon reload (phpGH-8885)

WoZ mentioned this issue Jul 3, 2022

FPM. access.log with stderr begins to write logs to error_log after daemon reload (GH-8885) #8913

Closed

WoZ added a commit to WoZ/php-src that referenced this issue Jul 3, 2022

FPM. access.log with stderr begins to write logs to error_log after d…

c56ca02

…aemon reload (phpGH-8885)

WoZ added a commit to WoZ/php-src that referenced this issue Jul 3, 2022

FPM. access.log with stderr begins to write logs to error_log after d…

16a1b2a

…aemon reload (phpGH-8885)

WoZ added a commit to WoZ/php-src that referenced this issue Jul 3, 2022

FPM. access.log with stderr begins to write logs to error_log after d…

f3a5ef3

…aemon reload (phpGH-8885)

WoZ added a commit to WoZ/php-src that referenced this issue Jul 4, 2022

FPM. access.log with stderr begins to write logs to error_log after d…

59d0075

…aemon reload (phpGH-8885)

WoZ added a commit to WoZ/php-src that referenced this issue Jul 4, 2022

FPM. access.log with stderr begins to write logs to error_log after d…

c76be3c

…aemon reload (phpGH-8885)

WoZ added a commit to WoZ/php-src that referenced this issue Jul 4, 2022

FPM. access.log with stderr begins to write logs to error_log after d…

37014d4

…aemon reload (phpGH-8885). Tests.

bukka closed this as completed in f92505c Aug 29, 2022

bukka added a commit that referenced this issue Aug 29, 2022

Fix GH-8885 tests on MacOS

bcdd987

bukka added a commit that referenced this issue Aug 29, 2022

Re-add fixed tests for GH-8885

986e731

bukka mentioned this issue Sep 21, 2022

Rework FPM tests logging for better debugging #9588

Closed

chrillep mentioned this issue Oct 31, 2022

rebuild images, update from 8.1.10 to php 8.1.13 lando/php#46

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

WoZ commented Jun 28, 2022 •

edited

Loading

bukka commented Jun 29, 2022

bukka commented Jun 29, 2022 •

edited

Loading

WoZ commented Jul 1, 2022

bukka commented Jul 2, 2022

WoZ commented Jul 3, 2022 •

edited

Loading

WoZ commented Jul 3, 2022

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

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

Comments

WoZ commented Jun 28, 2022 • edited Loading

Description

Details

PHP Version

Operating System

bukka commented Jun 29, 2022

bukka commented Jun 29, 2022 • edited Loading

WoZ commented Jul 1, 2022

bukka commented Jul 2, 2022

WoZ commented Jul 3, 2022 • edited Loading

WoZ commented Jul 3, 2022

USR1

Other bugs

WoZ commented Jun 28, 2022 •

edited

Loading

bukka commented Jun 29, 2022 •

edited

Loading

WoZ commented Jul 3, 2022 •

edited

Loading