php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #77185 Use-after-free in FPM master event handling
Submitted: 2018-11-22 04:35 UTC Modified: 2019-07-22 08:40 UTC
From: php at very dot puzzling dot org Assigned: nikic (profile)
Status: Closed Package: Reproducible crash
PHP Version: master-Git-2018-11-22 (Git) OS: Linux
Private report: No CVE-ID: None
 [2018-11-22 04:35 UTC] php at very dot puzzling dot org
Description:
------------
The FPM master may crash when handling a worker process exiting. This is due
to a use-after-free bug in the handling of epoll events.

### Steps to reproduce

1. Set up a minimal FPM config:

   $ cat example.conf
   [global]
   error_log = syslog

   syslog.facility = daemon
   syslog.ident = php-fpm

   [example]
   listen = /tmp/socket

   pm = static
   pm.max_children = 10

   catch_workers_output = true

2. Load FPM into GDB. We also set an environment variable telling Glibc to
   poison freed memory with a clearly recognizable bit pattern:

   $ GLIBC_TUNABLES=glibc.malloc.perturb=0xa5 gdb --args ./php-fpm --nodaemonize --fpm-config example.conf
   ...

3. Tell GDB to not intercept SIGUSR2 signals:

   (gdb) handle SIGUSR2 nostop noprint
   Signal        Stop      Print   Pass to program Description
   SIGUSR2       No        No      Yes             User defined signal 2

4. Run FPM:

   Starting program: .../php-fpm --nodaemonize --fpm-config example.conf
   [Thread debugging using libthread_db enabled]
   Using host libthread_db library "/lib64/libthread_db.so.1".
   Detaching after fork from child process 3679.
   Detaching after fork from child process 3680.
   Detaching after fork from child process 3681.
   Detaching after fork from child process 3682.
   Detaching after fork from child process 3683.
   Detaching after fork from child process 3684.
   Detaching after fork from child process 3685.
   Detaching after fork from child process 3686.
   Detaching after fork from child process 3687.
   Detaching after fork from child process 3688.

5. In another shell, signal the FPM process to reload (its PID will have
   been logged to syslog):

   $ kill -USR2 3675

6. Keep repeating the previous step until FPM crashes. In my tests, it
   crashes about half the time:

   Program received signal SIGSEGV, Segmentation fault.
   0x0000000000718816 in fpm_event_fire (ev=0x1199c60)
       at .../fpm_events.c:465
   465             (*ev->callback)( (struct fpm_event_s *) ev, ev->which, ev->arg);

7. Observe that the struct fpm_event_s had been freed and its callback
   field poisoned:

   (gdb) print ev
   $1 = (struct fpm_event_s *) 0x1199c60
   (gdb) print ev->callback
   $2 = (void (*)(struct fpm_event_s *, short, void *)) 0xa5a5a5a5a5a5a5a5

   The backtrace at this location is:

   (gdb) bt
   #0  0x0000000000718816 in fpm_event_fire (ev=0x1199c60)
       at .../fpm_events.c:465
   #1  0x0000000000724bf6 in fpm_event_epoll_wait (queue=<optimized out>, timeout=<optimized out>)
       at .../events/epoll.c:145
   #2  0x0000000000718a99 in fpm_event_loop (err=err@entry=0)
       at .../fpm_events.c:409
   #3  0x00000000007132f7 in fpm_run (max_requests=max_requests@entry=0x7fffffffd55c)
       at .../fpm.c:113
   #4  0x000000000043b1c5 in main (argc=4, argv=0x7fffffffdb78)
       at .../fpm_main.c:1864

Valgrind can also be used to demonstrate the bug. When the bug is hit, a
variety of "invalid read" and "invalid write" traces will be generated,
e.g.:

  ==14508== Invalid read of size 8
  ==14508==    at 0x718805: fpm_event_fire (fpm_events.c:461)
  ==14508==    by 0x724CB5: fpm_event_epoll_wait (epoll.c:145)
  ==14508==    by 0x718A98: fpm_event_loop (fpm_events.c:409)
  ==14508==    by 0x7132F6: fpm_run (fpm.c:113)
  ==14508==    by 0x43B1C4: main (fpm_main.c:1864)
  ==14508==  Address 0x8554e98 is 152 bytes inside a block of size 248 free'd
  ==14508==    at 0x4C2DD18: free (vg_replace_malloc.c:530)
  ==14508==    by 0x713A00: fpm_children_bury (fpm_children.c:260)
  ==14508==    by 0x71823D: fpm_got_signal (fpm_events.c:75)
  ==14508==    by 0x724CB5: fpm_event_epoll_wait (epoll.c:145)
  ==14508==    by 0x718A98: fpm_event_loop (fpm_events.c:409)
  ==14508==    by 0x7132F6: fpm_run (fpm.c:113)
  ==14508==    by 0x43B1C4: main (fpm_main.c:1864)
  ==14508==  Block was alloc'd at
  ==14508==    at 0x4C2EA1E: calloc (vg_replace_malloc.c:711)
  ==14508==    by 0x7134B2: fpm_child_alloc (fpm_children.c:45)
  ==14508==    by 0x7134B2: fpm_resources_prepare (fpm_children.c:308)
  ==14508==    by 0x7134B2: fpm_children_make (fpm_children.c:397)
  ==14508==    by 0x7132BF: fpm_run (fpm.c:99)
  ==14508==    by 0x43B1C4: main (fpm_main.c:1864)

### Analysis

When an FPM worker process exits, and that worker has been configured with
catch_workers_output = true, fpm_event_epoll_wait() is expected to handle
three events:

1. The worker's stdout stream becomes readable, since it's at EOF.
2. The worker's stderr stream becomes readable, since it's at EOF.
3. The signal fd becomes readable, since the signal handler will have written 'C'
   to it upon handling the SIGCHLD signal.

The problem is there is no guarantee that they will be returned in this
order.

Consider the case when signal fd event is returned first. This will free the
fpm_child_s structure representing the exited child via:

  fpm_event_epoll_wait()
    -> fpm_got_signal()
      -> fpm_children_bury()
        -> fpm_child_close(child)    # closes child's file descriptors
          -> fpm_child_free(child)
            -> free(child)

Next, one of the other events will be processed, however that event's
fpm_event_s is embedded _within_ the child structure that was just freed.
There's a few ways things can go wrong at this point:

- If the memory has been overwritten by some other object (or by being
  deliberately poisoned, e.g. by using the glibc tunable demonstrated
  above), the master will crash.

- If you get lucky and the memory has _not_ been overwritten,
  fpm_stdio_child_said() will attempt to read from the worker's stream. This
  will have already been closed by fpm_child_free(), and it may still be
  closed (leading to an "unable to read what child say: Bad file descriptor"
  errors in the log)... or worse yet it may have been opened for use by a
  completely different worker.

### Further comments

I have not been able to determine when this bug was introduced. As far as I
can tell, it has had this problem from the start. Certainly, I suspect the
segfault in bug #61558 was due to this bug, and that's been open since 2012.

It may have gone unnoticed for so long since in many cases there's a
reasonable chance that the freed memory is still intact. However, in my
tests I have found that using error_log = syslog (at least with glibc) makes
this considerably less likely: glibc performs a few memory allocations when
syslogging, and this is enough to change the memory allocation patterns such
that the use-after-free causes a crash rather than going undetected.



Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2018-11-23 00:16 UTC] php at very dot puzzling dot org
I have confirmed that this has been a bug as far back as PHP 5.3.9, and have indeed reproduced the problem on that version.

Specifically, the bug was introduced in commit 1034cbc758. This was when ondemand was implemented and FPM switched out its php_poll2-based event loop with a bunch of others including epoll.

Prior to this commit, the event loop would iterate over the linked fpm_child_s structures, so it wouldn't match the readable file descriptor for the just-freed child. Prior to PHP 5.3.4, FPM used libevent, and libevent ensures that a deleted event is never dispatched.
 [2018-11-24 06:26 UTC] php at very dot puzzling dot org
Here is a sample test case that will trigger the bug reasonably reliably. All it does is start FPM with some static children, then reloads FPM a few times. Larger values for $children and $loops are more likely to hit the bug.

When the bug is hit, FPM will either log "ERROR: unable to read what child say: Bad file descriptor (9)" or will segfault altogether.

--TEST--
FPM: bug77185 - Reload robustness
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php

require_once "tester.inc";

$workers = 10;
$loops   = 10;

$cfg = <<<EOT
[global]
error_log = {{FILE:LOG}}
pid = {{FILE:PID}}
[unconfined]
listen = {{ADDR}}
pm = static
pm.max_children = $workers
catch_workers_output = true
EOT;

$tester = new FPM\Tester($cfg);
$tester->start();
$tester->expectLogStartNotices();
for ($i = 0; $i < $loops; $i++) {
	$tester->signal('USR2');
	$tester->expectLogNotice('Reloading in progress ...');
	$tester->expectLogNotice('reloading: .*');
	$tester->expectLogNotice('using inherited socket fd=\d+, "127.0.0.1:\d+"');
	$tester->expectLogStartNotices();
}
$tester->terminate();
$tester->expectLogTerminatingNotices();
$tester->close();

?>
Done
--EXPECT--
Done
--CLEAN--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>
 [2018-11-26 06:42 UTC] php at very dot puzzling dot org
This might actually be a duplicate of bug #65398. I am not convinced, however, that the patch offered there is entirely correct: it is possible for a child to close its stdout or stderr _without_ exiting, and if that were to happen the master would then loop continually (since the event is level-triggered, not edge-triggered).
 [2019-01-22 07:39 UTC] mnikulin at plesk dot com
Looks like this bug is similar to
Bug #77114 php-fpm master segfaults in fpm_event_epoll_wait/fpm_event_fire
that is not specific to reload. I have reproduced scenario
for this bug for php-fpm 7.3.1. The patch with delayed fpm_children_bury
for #77114 helps in the case of reload as well.

I believed that in the case of reload other other bugs happen more frequently.
 [2019-07-22 08:40 UTC] nikic@php.net
-Status: Open +Status: Closed -Assigned To: +Assigned To: nikic
 
PHP Copyright © 2001-2019 The PHP Group
All rights reserved.
Last updated: Sun Nov 17 07:01:34 2019 UTC