I just tested the "Unable to open primary script" by removing read permission for the primary script and it works fine for me with 7.3. I got fallowing:

[24-Feb-2019 15:38:41] WARNING: [pool unconfined] child 28113 said into stderr: "NOTICE: PHP message: PHP Warning:  Unknown: failed to open stream: Permission denied in Unknown on line 0"
[24-Feb-2019 15:38:41] WARNING: [pool unconfined] child 28113 said into stderr: "Unknown(0) : Warning - Unknown: failed to open stream: Permission denied"
[24-Feb-2019 15:38:41] WARNING: [pool unconfined] child 28113 said into stderr: "ERROR: Unable to open primary script: /home/jakub/prog/php/tests/fpm/log-no-script/test.php (Permission denied)"

It means I need a bit more info from you. Could you pls paste your fpm config. Does it happen for all logged messages from the worker or is it just for some entries. Also can you add a bit more info about the app and what's being logged.

I'm running multiple php versions using software collection from Remi repo.
Similar configuration for all versions. I only have issues with 7.3.

Installed packages
-------------------------
php73-php-debuginfo-7.3.1~RC1-1.fc28.remi.x86_64
php73-php-mbstring-7.3.3~RC1-1.fc29.remi.x86_64
php73-runtime-2.0-1.fc29.remi.x86_64
php73-2.0-1.fc29.remi.x86_64
php73-php-gmp-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-xmlrpc-7.3.3~RC1-1.fc29.remi.x86_64
php73-build-2.0-1.fc29.remi.x86_64
php73-php-mysqlnd-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-fpm-debuginfo-7.3.1~RC1-1.fc28.remi.x86_64
php73-php-process-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-bcmath-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-soap-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-pecl-msgpack-2.0.3-1.fc29.remi.x86_64
php73-php-pecl-imagick-3.4.3-13.fc29.remi.x86_64
php73-php-pecl-igbinary-3.0.0-1.fc29.remi.x86_64
php73-php-common-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-intl-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-pear-1.10.8-1.fc29.remi.noarch
php73-php-ioncube-loader-10.3.2-1.fc29.remi.x86_64
php73-php-pecl-zip-1.15.4-1.fc29.remi.x86_64
php73-php-cli-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-json-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-imap-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-pdo-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-fpm-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-pecl-memcached-3.1.3-1.fc29.remi.x86_64
php73-php-xml-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-devel-7.3.3~RC1-1.fc29.remi.x86_64
php73-php-gd-7.3.3~RC1-1.fc29.remi.x86_64

php-fpm.conf
------------------
include=/etc/opt/remi/php73/php-fpm.d/*.conf

[global]
pid = /var/opt/remi/php73/run/php-fpm/php-fpm.pid
error_log = /var/log/php-fpm/master73.log
syslog.ident = php-fpm73
daemonize = yes
rlimit_files = 30000
------------------------------------

And a pool.
------------
[poolname]

user = apache
group = apache

listen = /var/opt/remi/php73/run/php-fpm/pool.sock
listen.acl_users = apache
listen.allowed_clients = 127.0.0.1

pm = ondemand
pm.max_children = 20
pm.process_idle_timeout = 5s
pm.max_requests = 40

pm.status_path = /fpmstats

slowlog = /var/log/php-fpm/www-slow.log
request_slowlog_timeout = 200
request_terminate_timeout = 203

chdir = /home/user
catch_workers_output = yes

security.limit_extensions = .php .phtml .phar

php_admin_value[doc_root] = "/home/user"
============================================

For grep I must add -a, because that ^Q visible in console is binary content.

grep -a stderr  /var/log/php-fpm/master73.log
------------------

[22-Feb-2019 04:56:01] WARNING: [pool poolA] child 9662 said into stderr: "^@"
[22-Feb-2019 04:57:01] WARNING: [pool poolA] child 9963 said into stderr: "^@"
[22-Feb-2019 04:57:59] WARNING: [pool poolA] child 10262 said into stderr: "^@"
[22-Feb-2019 05:01:02] WARNING: [pool poolA] child 11205 said into stderr: "^@"
[22-Feb-2019 05:04:01] WARNING: [pool poolA] child 12168 said into stderr: "^@"
[22-Feb-2019 05:17:00] WARNING: [pool poolA] child 17024 said into stderr: "^@"
[22-Feb-2019 05:18:02] WARNING: [pool poolA] child 17347 said into stderr: "^@"
[22-Feb-2019 05:23:00] WARNING: [pool poolA] child 19405 said into stderr: "^@"
[22-Feb-2019 05:28:01] WARNING: [pool poolA] child 21458 said into stderr: "^@"
[22-Feb-2019 05:46:01] WARNING: [pool poolA] child 28293 said into stderr: "^@"
[22-Feb-2019 05:48:00] WARNING: [pool poolA] child 29068 said into stderr: "^@"
[22-Feb-2019 05:50:59] WARNING: [pool poolA] child 30215 said into stderr: "^@"
[22-Feb-2019 05:53:02] WARNING: [pool poolA] child 31052 said into stderr: "^@"
[21-Feb-2019 14:19:58] WARNING: [pool poolB] child 9011 said into stderr: "ERROR: Unable to open primary script: /home/user/index.php (Permission denied)"
[21-Feb-2019 15:23:34] WARNING: [pool poolC] child 4159 said into stderr: "^@"
[21-Feb-2019 15:25:52] WARNING: [pool poolC] child 5151 said into stderr: "^@"
[22-Feb-2019 03:34:08] WARNING: [pool poolC] child 11060 said into stderr: "^@"
[22-Feb-2019 03:56:00] WARNING: [pool poolA] child 19510 said into stderr: "^@"
[22-Feb-2019 04:16:01] WARNING: [pool poolA] child 26999 said into stderr: "^@"
[22-Feb-2019 04:18:00] WARNING: [pool poolA] child 27707 said into stderr: "^@"
[22-Feb-2019 04:30:00] WARNING: [pool poolA] child 32308 said into stderr: "^@"
[22-Feb-2019 04:34:01] WARNING: [pool poolA] child 1579 said into stderr: "^@"
[22-Feb-2019 04:46:02] WARNING: [pool poolA] child 6239 said into stderr: "^@"
[22-Feb-2019 04:51:01] WARNING: [pool poolA] child 8030 said into stderr: "^@"
[22-Feb-2019 04:56:01] WARNING: [pool poolA] child 9662 said into stderr: "^@"
[22-Feb-2019 04:57:01] WARNING: [pool poolA] child 9963 said into stderr: "^@"
[22-Feb-2019 04:57:59] WARNING: [pool poolA] child 10262 said into stderr: "^@"
[22-Feb-2019 05:01:02] WARNING: [pool poolA] child 11205 said into stderr: "^@"
[22-Feb-2019 05:04:01] WARNING: [pool poolA] child 12168 said into stderr: "^@"
[22-Feb-2019 05:17:00] WARNING: [pool poolA] child 17024 said into stderr: "^@"
[22-Feb-2019 05:18:02] WARNING: [pool poolA] child 17347 said into stderr: "^@"
[22-Feb-2019 05:23:00] WARNING: [pool poolA] child 19405 said into stderr: "^@"
[22-Feb-2019 05:28:01] WARNING: [pool poolA] child 21458 said into stderr: "^@"
[22-Feb-2019 05:46:01] WARNING: [pool poolA] child 28293 said into stderr: "^@"
[22-Feb-2019 05:48:00] WARNING: [pool poolA] child 29068 said into stderr: "^@"
[22-Feb-2019 05:50:59] WARNING: [pool poolA] child 30215 said into stderr: "^@"
[22-Feb-2019 05:53:02] WARNING: [pool poolA] child 31052 said into stderr: "^@"
[22-Feb-2019 05:56:02] WARNING: [pool poolA] child 31911 said into stderr: "^@"
[22-Feb-2019 05:58:01] WARNING: [pool poolA] child 32449 said into stderr: "^@"
[22-Feb-2019 06:02:59] WARNING: [pool poolA] child 1854 said into stderr: "^@"
[22-Feb-2019 06:05:01] WARNING: [pool poolA] child 2804 said into stderr: "^@"
[22-Feb-2019 06:15:01] WARNING: [pool poolA] child 6377 said into stderr: "^@"
[22-Feb-2019 06:20:02] WARNING: [pool poolA] child 8086 said into stderr: "^@"
[22-Feb-2019 06:23:01] WARNING: [pool poolA] child 9356 said into stderr: "^@"
[22-Feb-2019 06:44:02] WARNING: [pool poolA] child 17610 said into stderr: "^@"
[22-Feb-2019 06:50:02] WARNING: [pool poolA] child 19670 said into stderr: "^@"
[22-Feb-2019 06:55:01] WARNING: [pool poolA] child 21604 said into stderr: "^@"
[22-Feb-2019 07:00:01] WARNING: [pool poolA] child 23429 said into stderr: "^@"
[22-Feb-2019 07:04:01] WARNING: [pool poolA] child 25114 said into stderr: "^@"
[22-Feb-2019 07:06:01] WARNING: [pool poolA] child 25821 said into stderr: "^@"
[22-Feb-2019 07:07:01] WARNING: [pool poolA] child 26061 said into stderr: "^@"
[22-Feb-2019 07:08:00] WARNING: [pool poolA] child 26293 said into stderr: "^@"
[22-Feb-2019 07:13:02] WARNING: [pool poolA] child 27602 said into stderr: "^@"
[22-Feb-2019 07:23:02] WARNING: [pool poolA] child 30443 said into stderr: "^@"
[22-Feb-2019 07:24:03] WARNING: [pool poolA] child 30788 said into stderr: "^@"
[22-Feb-2019 07:26:02] WARNING: [pool poolA] child 31286 said into stderr: "^@"
[22-Feb-2019 07:34:00] WARNING: [pool poolA] child 1427 said into stderr: "^@"
[22-Feb-2019 07:35:00] WARNING: [pool poolA] child 1686 said into stderr: "^@"
[22-Feb-2019 07:36:02] WARNING: [pool poolA] child 2044 said into stderr: "^@"
[22-Feb-2019 07:43:02] WARNING: [pool poolA] child 3962 said into stderr: "^@"
[22-Feb-2019 07:44:01] WARNING: [pool poolA] child 4216 said into stderr: "^@"
[22-Feb-2019 07:54:01] WARNING: [pool poolA] child 7335 said into stderr: "^@"
[22-Feb-2019 07:57:01] WARNING: [pool poolA] child 8178 said into stderr: "^@"
[22-Feb-2019 08:05:01] WARNING: [pool poolA] child 10447 said into stderr: "^@"
[22-Feb-2019 08:06:01] WARNING: [pool poolA] child 10816 said into stderr: "^@"
[22-Feb-2019 08:09:01] WARNING: [pool poolA] child 11720 said into stderr: "^@"
[22-Feb-2019 08:11:05] WARNING: [pool poolA] child 12570 said into stderr: "^@"
[22-Feb-2019 08:17:00] WARNING: [pool poolA] child 14056 said into stderr: "^@"
[22-Feb-2019 08:25:00] WARNING: [pool poolA] child 16595 said into stderr: "^@"
[22-Feb-2019 08:28:01] WARNING: [pool poolA] child 17291 said into stderr: "^@"
[22-Feb-2019 08:29:00] WARNING: [pool poolA] child 17527 said into stderr: "^@"
[22-Feb-2019 08:49:01] WARNING: [pool poolA] child 22856 said into stderr: "^@"
[22-Feb-2019 08:52:02] WARNING: [pool poolA] child 23818 said into stderr: "^@"
[22-Feb-2019 08:54:01] WARNING: [pool poolA] child 24670 said into stderr: "^@"
[22-Feb-2019 09:00:01] WARNING: [pool poolA] child 26495 said into stderr: "^@"
[22-Feb-2019 09:03:00] WARNING: [pool poolA] child 27733 said into stderr: "^@"
[23-Feb-2019 14:34:34] WARNING: [pool poolB] child 32366 said into stderr: "ERROR: Unable to open primary script: /home/user/index.php (Permission denied)"
[24-Feb-2019 01:17:10] WARNING: [pool poolB] child 13089 said into stderr: "ERROR: Unable to open primary script: /home/user/index.php (Permission denied)"
[24-Feb-2019 08:27:13] WARNING: [pool poolB] child 9651 said into stderr: "ERROR: Unable to open primary script: /home/user/index.php (Permission denied)"
[24-Feb-2019 17:53:02] WARNING: [pool poolB] child 30341 said into stderr: "ERROR: Unable to open primary script: /home/user/index.php (Permission denied)"

=================================

Probably my "working" example including "Unable to open primary script:" was not a good one, because in this case error seems to be displayed correctly. Other errors are not displayed.

error_reporting = E_ALL & ~E_NOTICE & ~E_DEPRECATED

Please note that I'm running ~500 php7.3 pools with the same pool configuration, except the path. This is a very rare incident, because, as you can see, starting with Feb 22, from 500+ pools only 2 display the error wrongly and one displays the error correctly.

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: "")?

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.

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.

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

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

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

Thanks Remi. I have installed 7.3.4~RC1-3. Now I need some time for tests.

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^@"

A new example with php 7.3.4 and patch applied, thanks to Remi.
Now the binary content ^@ is mixed with this text "fscf".

[04-Apr-2019 07:15:40] WARNING: [pool otherdomain] child 19148 said into stderr: "^@fscf^@^@fscf^@^@fscf^@"

Thanks for testing! It looks like reusing output pipe for signalling request end is not a really good solution. I need to address it in a better way.

I have changed the PR and used its own pipe to signal a log stream flush. I asked Remi to create an RPM so it can be tested.

@claudiu_beta as you are using packages from my repository, can you please test "7.3.5-2" from "remi-test" which includes the proposal fix from @bukka ?

I have installed "7.3.5-2" from Remi, but I need few days to test it, to be sure the result is accurate.

With this patch, now I have other bug and sites are completely down until php-fpm restart. A lot of lines like these. I never had this before. I have ~1000 pools using php7.3.


[05-May-2019 09:05:37] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:05:42] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:05:44] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:05:44] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:05:45] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:05:45] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:05:49] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:05:54] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:05:58] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:02] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:03] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:03] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:18] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:20] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:24] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:24] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:25] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:31] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:35] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:40] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:45] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:49] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:55] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:06:58] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:07:01] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:07:17] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:07:25] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:07:25] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:07:26] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:07:41] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:07:49] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:08:12] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:08:18] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:08:39] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:08:49] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:09:04] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:09:26] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:09:33] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:09:39] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:09:42] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:09:47] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:09:49] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:09:52] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:10:04] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:10:08] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:10:18] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:10:37] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:10:49] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:11:03] ERROR: failed to prepare the stderr pipe: Too many open files (24)
[05-May-2019 09:11:08] ERROR: failed to prepare the stderr pipe: Too many open files (24)

Ok thanks again for testing! Indeed it will result in quite a few new open file descriptor - basically one for each child in the master process which might be quite a lot if you are using around 1000 pools which means even more children. So this is not probably good idea either.

So it seems like the markers in the output are the only possible solution for flushing. I think there are some issues in the logic atm. - the whole read loop is a bit messy so I will try to improve it and see if it addresses the issue. The thing that it definitely goes through that logic as the message is still decorated by zlog...

I just pushed another attempt to fix this to the PR. I also pinged Remi if he could kindly create another RPM to test.

@claudiu_beta as you are using packages from my repository, can you please test "7.3.6-2" from "remi-test" which includes the new proposal fix from @bukka ?

@bukka sorry for the delay... quite busy these days.

(P.S. build available for F29, F30 and EL7)

I will install this test version from Remi's repo for few days, then I will post the result.

Likely related, we regularly see sapi/fpm/tests/log-bwd-multiple-msgs.phpt failing on Azure with:

001+ ERROR: The actual string(43) does not match expected string(21):
002+ - EXPECT: 'msg 1 - msg 2 - msg 3'
003+ - ACTUAL: 'msg 1 - msg 2 - msg 3[[0x00]]msg 1 - msg 2 - msg 3'
004+ ERROR: Unexpected line: [05-Jun-2019 13:38:23] NOTICE: Terminating ...
005+

I have tested the patched version from Remi for few days and I no longer have those binary error messages. Actually, I don't have errors anymore, with or without binary content, for pools where they appeared in the past. Maybe these error messages are completely suppressed to show nothing when they should?

Thanks again for testing! What kind of errors? If it's just the empty string logs, then I think it should disappear. You should still see the massages though. What exactly is different before and after the patch?

The incidence of this error is very rare, at least with this latest 7.3.6 version. For this reason, my tests may not be very accurate.

I have some observations though:

1. I no longer have any "strange" error in binary format.

2. In the past, I had errors like
[26-May-2019 12:57:11] WARNING: [pool www.xyz] child 6697 said into stderr: "^@"
and lots of " said into stderr: ... (Permission denied)" errors.

For the last 10 days, I only have few lines with errors displayed correctly
said into stderr: "ERROR: Unable to open primary script: xxxxxxxxxxx (Permission denied)"

Nothing more and not a single trace about the old error.


My conclusion:
1. Issues causing the errors have been solved in the meantime and patch is correct.
2. Or maybe till now the errors were logged in "error" and patch is ok.
3. Or maybe all related errors are now completely suppressed and patch is just hiding the errors.

All the "^@" should disappear as they were supposed to be used just for flushing but due to incorrect logic fpm_stdio, they were visible. So it's good that they are not visible now.

The permission error should be unrelated but as you can still see some, then I don't think it hides them.

I need to fix one small case in the PR when the flush character is in between two buffers but then I think it seems good so I will probably merge it.

Finally found some time to fix the case with the flush split. It works with a quick test but still needs a bit more testing. Hopefully not far from merging...