|
php.net | support | documentation | report a bug | advanced search | search howto | statistics | random bug | login |
[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.
PatchesPull RequestsHistoryAllCommentsChangesGit/SVN commits
|
|||||||||||||||||||||||||||
Copyright © 2001-2025 The PHP GroupAll rights reserved. |
Last updated: Sun Oct 26 01:00:01 2025 UTC |
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(); ?>