Bug #77653 [Asn]: php-fpm, operator displayed instead of the real error message

Edit report at https://bugs.php.net/bug.php?id=77653&edit=1 ID: 77653 User updated by: claudiu_beta at yahoo dot com 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: Previous: [01-Apr-2019 04:50:43] WARNING: [pool domainx] child 5247 said into stderr: "^@" With the patch applied: [02-Apr-2019 00:30:46] WARNING: [pool domainx] child 17022 said into stderr: "^@fscf^@" Previous Comments: ------------------------------------------------------------------------ [2019-04-01 14:14:34] claudiu_beta at yahoo dot com Thanks Remi. I have installed 7.3.4~RC1-3. Now I need some time for tests. ------------------------------------------------------------------------ [2019-04-01 12:58:00] remi@php.net @claudiu_beta as you are using packages from my repository, can you please test "7.3.4~RC1-3" from "remi-test" which includes the proposal fix from @bukka ? ------------------------------------------------------------------------ [2019-03-31 16:58:59] bukka@php.net @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. ------------------------------------------------------------------------ [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. ------------------------------------------------------------------------ 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