No need to be private

> #0  0x000055a8f4f64703 in zlog_stream_set_msg_suffix (stream=stream@entry=0x200, suffix=suffix@entry=0x0, final_suffix=final_suffix@entry=0x55a8f4fc37f6 ", pipe is closed")

This looks like something went really wrong as initially reading of the pipe failed and then the stream pointer is 0x200 which looks like the child structure got corrupted maybe.

Could you share your FPM config and possibly a bit more details about the app? Can you see "pipe is closed" in the logs when using 7.2 or 7.1 (just want check if the pipe is getting closed in there as well)?

I'm using exactly the same templates for all 7.1,7.2,7.3 on few servers. I only have issues with 7.3.
My monitoring script finds php73 service down several times a day, sometimes two or three times each hour.

Maybe a coincidence, I don't know. Till RC6 I had no issues or, let say, just 1-2 issues a week (under 100 pools). After 7.3.0 GA, the number of issues increased a lot (number of pools per server on average 200-300). Different servers, different sites, the same issue.
In logs I have no errors, nor "pipe is closed", nor anything else. I have checked the logs before and after the crash, nothing.
With 7.2, for example, I have 1000+ pools on the same server with no crash issues. I have errors in logs like

[07-Jan-2019 20:34:25] ERROR: unable to read what child say: Bad file descriptor (9)
[07-Jan-2019 20:34:25] ERROR: unable to read what child say: Bad file descriptor (9)
[07-Jan-2019 20:35:27] NOTICE: [pool poolname] child 23542 exited with code 0 after 69.601713 seconds from start
[07-Jan-2019 20:35:27] NOTICE: [pool poolname] child 23797 started

but service will not crash.




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 = 15
pm.process_idle_timeout = 4s
pm.max_requests = 30

pm.status_path = /fpmstats

slowlog = /var/log/php-fpm/00000_www-slow.log
request_slowlog_timeout = 60
request_terminate_timeout = 63

chdir = /home/users/domain
catch_workers_output = yes

security.limit_extensions = .php .phtml .phar

php_admin_value[mail.log] = /var/log/php-fpm/php_mail.log
php_admin_value[mail.add_x_header] = On

php_admin_value[error_log] = /var/log/php-fpm/domain.73.log
php_admin_value[doc_root] = "/home/users/domain"
php_admin_value[max_execution_time] = 60
php_admin_value[max_input_time] = 90
php_admin_value[max_input_vars] = 1000
php_admin_value[memory_limit] = 256M
php_admin_value[post_max_size] = 10M
php_admin_value[upload_max_filesize] = 10M
php_admin_value[default_socket_timeout] = 30
php_admin_value[open_basedir] = /home/users/domain/:/tmp/:/usr/share/pear/
php_admin_value[disable_functions] = mail, mb_send_mail, system, exec, shell_exec, passthru, error_log, dl, sys_getloadavg, pfsockopen, openlog, syslog, readlink, symlink, link, leak, popen, escapeshellcmd

I guess it might be related to child restart possibly due request_terminate_timeout and not doing clean up properly but will need to verify it. Thanks for the config.

I have upgraded to Fedora 29 and php 7.3.1. This is a backtrace from a new coredump.

#0  0x000055eb8b44fc73 in zlog_stream_set_msg_suffix (stream=stream@entry=0x100, suffix=suffix@entry=0x0, final_suffix=final_suffix@entry=0x55eb8b4aedf6 ", pipe is closed")
    at /usr/src/debug/php73-php-7.3.1-1.fc29.remi.x86_64/sapi/fpm/fpm/zlog.c:602
#1  0x000055eb8b44d109 in fpm_stdio_child_said (ev=<optimized out>, which=<optimized out>, arg=0x55eb8c536250) at /usr/src/debug/php73-php-7.3.1-1.fc29.remi.x86_64/sapi/fpm/fpm/fpm_stdio.c:199
#2  0x000055eb8b452596 in fpm_event_epoll_wait (queue=<optimized out>, timeout=<optimized out>) at /usr/src/debug/php73-php-7.3.1-1.fc29.remi.x86_64/sapi/fpm/fpm/events/epoll.c:145
#3  0x000055eb8b444e84 in fpm_event_loop (err=err@entry=0) at /usr/src/debug/php73-php-7.3.1-1.fc29.remi.x86_64/sapi/fpm/fpm/fpm_events.c:409
#4  0x000055eb8b43f217 in fpm_run (max_requests=0x7fff9540e34c) at /usr/src/debug/php73-php-7.3.1-1.fc29.remi.x86_64/sapi/fpm/fpm/fpm.c:113
#5  0x000055eb8b21c924 in main (argc=2, argv=0x7fff9540e968) at /usr/src/debug/php73-php-7.3.1-1.fc29.remi.x86_64/sapi/fpm/fpm/fpm_main.c:1864

I reported the exact same issue in 7.3.1 (as released) which NikiC tagged as a duplicate. There aren't necessarily any requests - according to the access-log, the last request was @ 03:43:35 and lasted 50ms (segfault @ 03:43:43).

If you need more input let me know - I have a coredump on a debug-build

I think that I know what the issue is. The event can be received after the child is freed which means that the shared log stream is uninitialized and it can't be used.

Are you able to test the following patch:

diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c
index ba8f6d8213..0ff189c9f0 100644
--- a/sapi/fpm/fpm/fpm_stdio.c
+++ b/sapi/fpm/fpm/fpm_stdio.c
@@ -196,8 +196,10 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg)
        }
 
        if (read_fail) {
-               zlog_stream_set_msg_suffix(log_stream, NULL, ", pipe is closed");
-               zlog_stream_finish(log_stream);
+               if (!child->log_stream) {
+                       zlog_stream_set_msg_suffix(log_stream, NULL, ", pipe is closed");
+                       zlog_stream_finish(log_stream);
+               }
                if (read_fail < 0) {
                        zlog(ZLOG_SYSERROR, "unable to read what child say");
                }

Actually please try this one if you can:

diff --git a/sapi/fpm/fpm/fpm_stdio.c b/sapi/fpm/fpm/fpm_stdio.c
index ba8f6d8213..03d15cbf0d 100644
--- a/sapi/fpm/fpm/fpm_stdio.c
+++ b/sapi/fpm/fpm/fpm_stdio.c
@@ -122,7 +122,7 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg)
        struct fpm_event_s *event;
        int fifo_in = 1, fifo_out = 1;
        int in_buf = 0;
-       int read_fail = 0, finish_log_stream = 0;
+       int read_fail = 0, finish_log_stream = 0, create_log_stream;
        int res;
        struct zlog_stream *log_stream;
 
@@ -138,7 +138,8 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg)
                event = &child->ev_stderr;
        }
 
-       if (!child->log_stream) {
+       create_log_stream = !child->log_stream;
+       if (create_log_stream) {
                log_stream = child->log_stream = malloc(sizeof(struct zlog_stream));
                zlog_stream_init_ex(log_stream, ZLOG_WARNING, STDERR_FILENO);
                zlog_stream_set_decorating(log_stream, child->wp->config->decorate_workers_output);
@@ -196,8 +197,10 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg)
        }
 
        if (read_fail) {
-               zlog_stream_set_msg_suffix(log_stream, NULL, ", pipe is closed");
-               zlog_stream_finish(log_stream);
+               if (create_log_stream) {
+                       zlog_stream_set_msg_suffix(log_stream, NULL, ", pipe is closed");
+                       zlog_stream_finish(log_stream);
+               }
                if (read_fail < 0) {
                        zlog(ZLOG_SYSERROR, "unable to read what child say");
                }

FYI, build including this patch is available in remi-test repository (F28/F29 only)

With the patch "[2019-01-15 20:20 UTC] bukka@php.net"
I faced Bug #77114 "php-fpm master segfaults in fpm_event_epoll_wait/fpm_event_fire"

I have adjusted configuration of pools to make child exit
events frequent enough and provide moderate load to ~30 pools

    pm.process_idle_timeout = 2s
    php_value[error_reporting] = 22519
    pm.max_requests = 2

(gdb) bt
#0  0x0000004200000000 in ?? ()
#1  0x000000000085c1e0 in fpm_event_fire (ev=0x1ce15b0) at /usr/src/debug/sapi/fpm/fpm/fpm_events.c:465
#2  0x000000000086f4f8 in fpm_event_epoll_wait (queue=0x1cea5a0, timeout=1000) at /usr/src/debug/sapi/fpm/fpm/events/epoll.c:145
#3  0x000000000085bf24 in fpm_event_loop (err=0) at /usr/src/debug/sapi/fpm/fpm/fpm_events.c:409
#4  0x000000000085420f in fpm_run (max_requests=0x7ffcc6873c9c) at /usr/src/debug/sapi/fpm/fpm/fpm.c:113
#5  0x00000000008618e9 in main (argc=2, argv=0x7ffcc6873ed8) at /usr/src/debug/sapi/fpm/fpm/fpm_main.c:1873

(gdb) frame 1
#1  0x000000000085c1e0 in fpm_event_fire (ev=0x1ce15b0) at /usr/src/debug/sapi/fpm/fpm/fpm_events.c:465
465	in /usr/src/debug/sapi/fpm/fpm/fpm_events.c
(gdb) p ev
$44 = (struct fpm_event_s *) 0x1ce15b0
(gdb) print epollfds[15]
$45 = {events = 1, data = {ptr = 0x1ce15b0, fd = 30283184, u32 = 30283184, u64 = 30283184}}

(gdb) print *(struct fpm_event_s *)epollfds[14].data.ptr
$41 = {fd = 34, timeout = {tv_sec = 0, tv_usec = 0}, frequency = {tv_sec = 0, tv_usec = 0}, callback = 0x864541 <fpm_pctl_on_socket_accept>, arg = 0x1cd40b0, flags = 10, index = 34, which = 2}
(gdb) print *(struct fpm_event_s *)epollfds[15].data.ptr
$42 = {fd = 0, timeout = {tv_sec = 8822805, tv_usec = 30283040}, frequency = {tv_sec = 356482285570, tv_usec = 2}, callback = 0x4200000000, arg = 0x53, flags = 0, index = 0, which = 0}
(gdb) print *(struct fpm_event_s *)epollfds[16].data.ptr
$43 = {fd = 124, timeout = {tv_sec = 0, tv_usec = 0}, frequency = {tv_sec = 0, tv_usec = 0}, callback = 0x86a015 <fpm_stdio_child_said>, arg = 0x1ce0dd0, flags = 2, index = 124, which = 2}

Callback in epollfds[15].data.ptr (related to fired ev) looks suspicious.

Thanks to updated, recompiled packages from Remi for Fedora 29, I was able to test the patched version. I can now confirm that the issue is gone.
Thank you all!

It's merged and will be part of 7.3.2. It's quite difficult to do a test for this but will think about it as it's a bit more generic issue as noted below.

@claudiu Thanks for testing!

@mnikulin That's a different issue so this fix cannot fix it as it's in completely different place. Will try to take a look on that one later.

My point was that I can not confirm that provided fix works perfectly.
I managed to get a test server with usual time to crash in the range
from several seconds to several minutes.
Without the fix provided for this bug I get crash in zlog_stream_set_msg_suffix.
With the patch I get the crash with the same rate.
I am in doubt if failure in zlog_stream_set_msg_suffix
is eliminated completely or it is just delayed and corrupted
epoll data becomes primary source of failure.

Both bugs are annoying enough and not easy to reproduce.
I was really surprised when I have got another semi-mysterious crash.

I have added some speculations to the Bug #77114.

Thank you for the fix,