Edit report at https://bugs.php.net/bug.php?id=77653&edit=1
ID: 77653
Updated by: bukka@php.net
Reported by: claudiu_beta at yahoo dot com
Summary: php-fpm, operator displayed instead of the real
error message
Status: Assigned
Type: Bug
Package: FPM related
Operating System: Fedora 29
PHP Version: 7.3.3RC1
Assigned To: bukka
Block user comment: N
Private report: N
New Comment:
@nikic Ah good spot. Seems like I didn't realised that the log IO can get appended so the extra
\0 can be at the beginning. It's definitely a bug and might be also the cause of this report.
The flushing is important if multiple messages without new line at the end are logged. It can be
seen in this test: https://github.com/php/php-src/blob/06dd1d78a7ec1678b53ef657033c2021f4dc902f/sapi/fpm/tests/log-bwd-multiple-msgs.phpt
. If it wasn't flushed, then part of the unfinished string could be carried on to the next
request.
I just created a PR which introduced a bit more flexible way of flushing where it's checked at
beginning and the end of the logged data in the event. I also moved the flush after shutdown which
should probably have the main effect.
Previous Comments:
------------------------------------------------------------------------
[2019-03-31 16:00:54] bukka@php.net
The following pull request has been associated:
Patch Name: Fix logging in shutdown function
On GitHub: https://github.com/php/php-src/pull/4007
Patch: https://github.com/php/php-src/pull/4007.patch
------------------------------------------------------------------------
[2019-03-22 13:20:00] nikic@php.net
@bukka: Probably not *quite* what is happening here, but likely related: You are calling
fpm_stdio_flush_child() as part of fpm_request_end(), which is run before php_request_shutdown().
This means that the finalizing NUL is written, but there may still be output to stderr afterwards
due to shutdown functions and destructors. Here is a test case, basically
log-bm-limit-1024-msg-80.phpt wrapped in a register_shutdown_function():
--TEST--
FPM: Log message in shutdown function
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
log_limit = 1024
log_buffering = yes
[unconfined]
listen = {{ADDR}}
pm = dynamic
pm.max_children = 5
pm.start_servers = 1
pm.min_spare_servers = 1
pm.max_spare_servers = 3
catch_workers_output = yes
EOT;
$code = <<<EOT
<?php
register_shutdown_function(function() {
error_log(str_repeat('e', 80));
});
EOT;
$tester = new FPM\Tester($cfg, $code);
$tester->start();
$tester->expectLogStartNotices();
$tester->request()->expectEmptyBody();
$tester->terminate();
$tester->expectFastCGIErrorMessage('e', 1050, 80);
$tester->expectLogMessage('NOTICE: PHP message: ' . str_repeat('e', 80),
1050);
$tester->close();
?>
Done
--EXPECT--
Done
--CLEAN--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>
It produces this diff:
ERROR: The actual string(102) does not match expected string(101):
- EXPECT: 'NOTICE: PHP message:
eeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeee'
- ACTUAL: '^@NOTICE: PHP message:
eeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeee'
Done
I don't really understand what the purpose of the fpm_stdio_flush_child() is (why is an
explicit NUL necessary, rather than just a closed stream?) but at least the current place where it
is called isn't right.
------------------------------------------------------------------------
[2019-03-10 17:27:57] bukka@php.net
I'm afraid I don't have any changes that would fix your issue as I don't know what
the real issue is. I need to be able to recreate it. Basically I will need a minimal app that shows
the issue. Ideally something like the following that I used for another issue:
https://github.com/bukka/php-util/tree/master/tests/fpm/pools-reload
Of course the configuration should be different and mainly the input script should behave in a way
that I can see the issue.
If you are able to provide something like that, I should be able to fix it hopefully but otherwise I
can't really do much. I will be quite busy in the next 3 weeks but then should be able to take
a look if you manage to extract it.
------------------------------------------------------------------------
[2019-03-03 23:36:05] claudiu_beta at yahoo dot com
I don't think it has something to do with killed children, because the issue is happening with
the same sites (1 site = 1 pool). Always the same error output (child xxxx said into stderr:
"^@") and never a normal error message for these pools.
As for the 7.2 log, I don't see empty error messages "", all are filled with data.
Also, I have checked few pools and they do not ever have entries in slow.log.
Would be great if you can include those changes with the next 7.3.3 release, so I can test and see
if bug was solved or not.
Sadly, I don't compile php from sources and I can't test before the public release. I only
use rpm packages for Fedora 29.
And on a local server I can't reproduce the error myself, so any test is useless.
I'm running php 7.3 on few servers. From 500+ pools, on each server, I have the same 3-4-5
pools always displaying the error output in binary format and few others displaying errors without
problem.
Sites are not connected each other. I have checked the sites to see a link between them: one is
Chinese, one is English US, one Spanish etc. I thought it may be a foreign language, but it's
happening with sites in English too.
I have checked few pools for errors in master log and also the individual log set in pool conf with
php_admin_value[error_log] = xxxxx.log
[pool example]
I have in master log
[01-Mar-2019 21:08:30] WARNING: [pool example2] child 21835 said into stderr: "^@"
[01-Mar-2019 21:08:30] WARNING: [pool example2] child 21835 said into stderr: "^@"
but nothing recent in example.log
[21-Feb-2019 18:33:50 Europe/Paris] PHP Parse error: syntax error, unexpected ';' in
/path/to/wstsczona.php on line 15
[21-Feb-2019 18:34:45 Europe/Paris] PHP Parse error: syntax error, unexpected '$conexion'
(T_VARIABLE) in /path/to/wstsczona.php on line 17
so php code errors and php-fpm warnings seems to not be related.
------------------------------------------------------------------------
[2019-03-03 17:18:08] bukka@php.net
Ok so it happens rarely just for some pools, right? I'm wondering if it could be somehow
related to the killed children. Maybe something related to request_slowlog_timeout and
request_terminate_timeout? Could you also get result from the scoreboard and compare it with other
working pools. And looking to www-slow.log could help too.
One of the things that changed in 7.3 is that binary content logging is supported better and
technically strings starting with '\0' could still be logged (not really tested but I
replaced strchr with memchr and changed the logic a bit so it might work). It would be interesting
to know if the binary content starts with '\0' and if you had some empty log entries in
7.2 (...said into stderr: "")?
------------------------------------------------------------------------
The remainder of the comments for this report are too long. To view
the rest of the comments, please view the bug report online at
https://bugs.php.net/bug.php?id=77653
--
Edit this bug report at https://bugs.php.net/bug.php?id=77653&edit=1