From: php at very dot puzzling dot org
Operating system: Linux
PHP version: master-Git-2018-11-22 (Git)
Package: Reproducible crash
Bug Type: Bug
Bug description:Use-after-free in FPM master event handling
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.
--
Edit bug report at https://bugs.php.net/bug.php?id=77185&edit=1
--
Try a snapshot (PHP 5.4): https://bugs.php.net/fix.php?id=77185&r=trysnapshot54
Try a snapshot (PHP 5.5): https://bugs.php.net/fix.php?id=77185&r=trysnapshot55
Try a snapshot (trunk): https://bugs.php.net/fix.php?id=77185&r=trysnapshottrunk
Fixed in SVN: https://bugs.php.net/fix.php?id=77185&r=fixed
Fixed in release: https://bugs.php.net/fix.php?id=77185&r=alreadyfixed
Need backtrace: https://bugs.php.net/fix.php?id=77185&r=needtrace
Need Reproduce Script: https://bugs.php.net/fix.php?id=77185&r=needscript
Try newer version: https://bugs.php.net/fix.php?id=77185&r=oldversion
Not developer issue: https://bugs.php.net/fix.php?id=77185&r=support
Expected behavior: https://bugs.php.net/fix.php?id=77185&r=notwrong
Not enough info: https://bugs.php.net/fix.php?id=77185&r=notenoughinfo
Submitted twice: https://bugs.php.net/fix.php?id=77185&r=submittedtwice
register_globals: https://bugs.php.net/fix.php?id=77185&r=globals
PHP 4 support discontinued: https://bugs.php.net/fix.php?id=77185&r=php4
Daylight Savings: https://bugs.php.net/fix.php?id=77185&r=dst
IIS Stability: https://bugs.php.net/fix.php?id=77185&r=isapi
Install GNU Sed: https://bugs.php.net/fix.php?id=77185&r=gnused
Floating point limitations: https://bugs.php.net/fix.php?id=77185&r=float
No Zend Extensions: https://bugs.php.net/fix.php?id=77185&r=nozend
MySQL Configuration Error: https://bugs.php.net/fix.php?id=77185&r=mysqlcfg