PHP :: Bug #71821 :: php-fpm7 crashes due to unknown entry 'log

Bug #71821	php-fpm7 crashes due to unknown entry 'log_level' in config
Submitted:	2016-03-14 12:01 UTC	Modified:	2016-03-18 20:42 UTC
From:	contact at sshilko dot com	Assigned:
Status:	Closed	Package:	mongodb (PECL)
PHP Version:	7.0.4	OS:	Ubuntu 14.04.3
Private report:	No	CVE-ID:	None

View Developer Edit

[2016-03-14 12:01 UTC] contact at sshilko dot com

Description:
------------
$ /usr/lib/php/php7.0-fpm-checkconf
Segmentation fault (core dumped)

# gdb /usr/sbin/php-fpm7.0
GNU gdb (Ubuntu 7.7.1-0ubuntu5~14.04.2) 7.7.1
Copyright (C) 2014 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/sbin/php-fpm7.0...(no debugging symbols found)...done.
(gdb) run
Starting program: /usr/sbin/php-fpm7.0
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[14-Mar-2016 11:56:02] ERROR: [/etc/php/7.0/fpm/php-fpm.conf:420] unknown entry 'log_level'
[14-Mar-2016 11:56:02] ERROR: failed to load configuration file '/etc/php/7.0/fpm/php-fpm.conf'
[14-Mar-2016 11:56:02] ERROR: FPM initialization failed
zend_mm_heap corrupted
[Inferior 1 (process 3842) exited with code 01]


PHP 7.0.4-5+deb.sury.org~trusty+1 (cli) ( NTS )
Copyright (c) 1997-2016 The PHP Group
Zend Engine v3.0.0, Copyright (c) 1998-2016 Zend Technologies
    with Zend OPcache v7.0.6-dev, Copyright (c) 1999-2016, by Zend Technologies

Test script:
---------------
echo 'log_level=warning' >> /etc/php/7.0/fpm/php-fpm.conf

$ /usr/lib/php/php7.0-fpm-checkconf
Segmentation fault (core dumped)

Patches

Pull Requests

History

AllCommentsChangesGit/SVN commitsRelated reports

[2016-03-14 12:13 UTC] ondrej@php.net

And that said script is just a simple wrapper around `php-fpm -t`:

$ cat debian/php-fpm-checkconf 
#!/bin/sh
set -e
CONFFILE=${1:-/etc/php/@PHP_VERSION@/fpm/php-fpm.conf}
errors=$(/usr/sbin/php-fpm@PHP_VERSION@ --fpm-config "$CONFFILE" -t 2>&1 | grep "\[ERROR\]" || true);
if [ -n "$errors" ]; then
    echo "Please fix your configuration file..."
    echo $errors
    exit 1
fi
exit 0

[2016-03-14 12:28 UTC] ondrej@php.net

Sergei,

what other modules do you have installed?  Could you perhaps attach output of:

php -r 'phpinfo();'

I can't reproduce it with just php-fpm and neither with basic set of modules installed nor with full php7.0-* set of external modules as provided in the PPA.  Re-running under valgrind also doesn't reveal anything suspicious.

Correctly ends with:
```
[14-Mar-2016 12:26:22] ERROR: [/etc/php/7.0/fpm/php-fpm.conf:415] unknown entry 'log_level'
[14-Mar-2016 12:26:22] ERROR: failed to load configuration file '/etc/php/7.0/fpm/php-fpm.conf'
[14-Mar-2016 12:26:22] ERROR: FPM initialization failed
[Inferior 1 (process 74801) exited with code 0116]
```

Any PECL modules (php-* packages)?

Or anything under /usr/local?  What does `ldd /usr/sbin/php-fpm7.0` output?

Can you reproduce this on clean system?  (And if not, what's the difference between the two systems?)

[2016-03-14 12:41 UTC] contact at sshilko dot com

This is a clean system i'm installing via puppet/vagrant script.
Only change i have is PHP version, i updated from 5.5 to 5.6 to 7.0.1-5+deb.sury.org~trusty+1 to 7.0.2-2+deb.sury.org~trusty+1 and now tried

7.0.4-5+deb.sury.org~trusty+1

but it failed immediattely due to log_level, after uncommenting it works.

modules & info
https://gist.github.com/sshilko/5dce14eccd90f43dea33

[2016-03-14 12:51 UTC] contact at sshilko dot com

It's Amazon AWS EC2 instance ami-b82176d2 as a base (Ubuntu 14.04.03 LTS)
ubuntu/images/ebs/ubuntu-trusty-14.04-amd64-server-20151218 - ami-b82176d2

[2016-03-15 09:23 UTC] laruence@php.net

-Status: Open +Status: Feedback

[2016-03-15 09:23 UTC] laruence@php.net

Thank you for this bug report. To properly diagnose the problem, we
need a backtrace to see what is happening behind the scenes. To
find out how to generate a backtrace, please read
http://bugs.php.net/bugs-generating-backtrace.php for *NIX and
http://bugs.php.net/bugs-generating-backtrace-win32.php for Win32

Once you have generated a backtrace, please submit it to this bug
report and change the status back to "Open". Thank you for helping
us make PHP better.

I can not reproduce this.

[2016-03-15 11:03 UTC] ondrej@php.net

I was able to reproduce it and it's a mongodb extension loaded that's causing the segfault.

root@lettie:~# echo 'log_level=warning' >> /etc/php/7.0/fpm/php-fpm.conf
root@lettie:~# php-fpm7.0 -t
[15-Mar-2016 11:01:34] ERROR: [/etc/php/7.0/fpm/php-fpm.conf:415] unknown entry 'log_level'
[15-Mar-2016 11:01:34] ERROR: failed to load configuration file '/etc/php/7.0/fpm/php-fpm.conf'
[15-Mar-2016 11:01:34] ERROR: FPM initialization failed
zend_mm_heap corrupted
root@lettie:~# phpdismod mongodb
root@lettie:~# php-fpm7.0 -t
[15-Mar-2016 11:01:41] ERROR: [/etc/php/7.0/fpm/php-fpm.conf:415] unknown entry 'log_level'
[15-Mar-2016 11:01:41] ERROR: failed to load configuration file '/etc/php/7.0/fpm/php-fpm.conf'
[15-Mar-2016 11:01:41] ERROR: FPM initialization failed
root@lettie:~# phpenmod mongodb
root@lettie:~# php-fpm7.0 -t
[15-Mar-2016 11:01:47] ERROR: [/etc/php/7.0/fpm/php-fpm.conf:415] unknown entry 'log_level'
[15-Mar-2016 11:01:47] ERROR: failed to load configuration file '/etc/php/7.0/fpm/php-fpm.conf'
[15-Mar-2016 11:01:47] ERROR: FPM initialization failed
Segmentation fault (core dumped)

I'll try to reproduce on Ubuntu Xenial, where I have dbgsym packages with debug symbols available.

[2016-03-15 11:06 UTC] ondrej@php.net

JFTR It's not caused by log_level=warning.  That just makes PHP FPM to stop early.

I can reproduce the error with mongodb loaded on every php-fpm7.0 -t run.

root@lettie:~# php-fpm7.0 -t
[15-Mar-2016 11:04:16] NOTICE: configuration file /etc/php/7.0/fpm/php-fpm.conf test is successful

Segmentation fault (core dumped)
root@lettie:~# php-fpm7.0 -t
[15-Mar-2016 11:04:17] NOTICE: configuration file /etc/php/7.0/fpm/php-fpm.conf test is successful

zend_mm_heap corrupted
root@lettie:~#

[2016-03-15 11:20 UTC] contact at sshilko dot com

-Status: Feedback +Status: Open

[2016-03-15 11:20 UTC] contact at sshilko dot com

Seems so, thanks Ondrej, i tested again

PHP 7.0.4-5+deb.sury.org~trusty+1

[11:15 AM]-[ubuntu]-[~]
$ sudo /usr/sbin/php-fpm7.0 -t; php -m |grep mongo
[15-Mar-2016 11:15:53] NOTICE: configuration file /etc/php/7.0/fpm/php-fpm.conf test is successful

zend_mm_heap corrupted
22:mongodb

[11:15 AM]-[ubuntu]-[~]
$ sudo /usr/sbin/php-fpm7.0 -t; php -m |grep mongo
[15-Mar-2016 11:15:54] NOTICE: configuration file /etc/php/7.0/fpm/php-fpm.conf test is successful

22:mongodb


its crashes every now and then with configtest,

$ sudo /usr/sbin/php-fpm7.0 -t
[15-Mar-2016 11:18:29] ERROR: [/etc/php/7.0/fpm/php-fpm.conf:421] unknown entry 'log_level'
[15-Mar-2016 11:18:29] ERROR: failed to load configuration file '/etc/php/7.0/fpm/php-fpm.conf'
[15-Mar-2016 11:18:29] ERROR: FPM initialization failed

$ grep 'log_level' /etc/php/7.0/fpm/php-fpm.conf
42:;log_level = notice
127:log_level=notice


The issue that php-fpm doesnt like "log_level" is a separate issue by itself and randomly crashes are caused by mongodb extension in 
/usr/sbin/php-fpm7.0 -t

alho the main php-fpm process works fine with mongodb extension (i dont see segfaults in syslog for past few days or so)

[2016-03-15 11:31 UTC] contact at sshilko dot com

I filed a dummy bugreport to mongodb extension jira bugtracker
https://jira.mongodb.org/browse/PHPC-632

[2016-03-15 11:35 UTC] ondrej@php.net

Ok, so this is a definitely mongodb fault. Running under valgrind reveals:

==26905== Invalid read of size 8
==26905==    at 0x3370BA: _efree (in /usr/sbin/php-fpm7.0)
==26905==    by 0xD68FB8A: digestmd5_common_mech_free (in /usr/lib/x86_64-linux-gnu/sasl2/libdigestmd5.so.2.0.25)
==26905==    by 0xC230468: client_done (in /usr/lib/x86_64-linux-gnu/libsasl2.so.2.0.25)
==26905==    by 0xC2305A9: sasl_client_done (in /usr/lib/x86_64-linux-gnu/libsasl2.so.2.0.25)
==26905==    by 0xBFE26DD: _mongoc_do_cleanup (in /usr/lib/php/20151012/mongodb.so)
==26905==    by 0x6E304E8: __pthread_once_slow (pthread_once.c:116)
==26905==    by 0x400F8C6: _dl_fini (in /lib/x86_64-linux-gnu/ld-2.22.so)
==26905==    by 0x6AB3E07: __run_exit_handlers (in /lib/x86_64-linux-gnu/libc-2.22.so)
==26905==    by 0x6AB3E54: exit (in /lib/x86_64-linux-gnu/libc-2.22.so)
==26905==    by 0x3F00B1: fpm_init (in /usr/sbin/php-fpm7.0)
==26905==    by 0x1E1D2F: main (in /usr/sbin/php-fpm7.0)
==26905==  Address 0xa200000 is 288 bytes inside a block of size 552 free'd
==26905==    at 0x4C2AE6B: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==26905==    by 0x6AE6662: fclose@@GLIBC_2.2.5 (in /lib/x86_64-linux-gnu/libc-2.22.so)
==26905==    by 0x376D15: zend_file_handle_dtor (in /usr/sbin/php-fpm7.0)
==26905==    by 0x32E9C6: zend_parse_ini_file (in /usr/sbin/php-fpm7.0)
==26905==    by 0x301D71: php_init_config (in /usr/sbin/php-fpm7.0)
==26905==    by 0x2F9FA7: php_module_startup (in /usr/sbin/php-fpm7.0)
==26905==    by 0x3F7984: ??? (in /usr/sbin/php-fpm7.0)
==26905==    by 0x1E1CD6: main (in /usr/sbin/php-fpm7.0)
==26905==  Block was alloc'd at
==26905==    at 0x4C29C0F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==26905==    by 0x6AE6F1C: __fopen_internal (in /lib/x86_64-linux-gnu/libc-2.22.so)
==26905==    by 0x301D2E: php_init_config (in /usr/sbin/php-fpm7.0)
==26905==    by 0x2F9FA7: php_module_startup (in /usr/sbin/php-fpm7.0)
==26905==    by 0x3F7984: ??? (in /usr/sbin/php-fpm7.0)
==26905==    by 0x1E1CD6: main (in /usr/sbin/php-fpm7.0)
==26905== 
==26905== Invalid read of size 4
==26905==    at 0x3370BD: _efree (in /usr/sbin/php-fpm7.0)
==26905==    by 0xD68FB8A: digestmd5_common_mech_free (in /usr/lib/x86_64-linux-gnu/sasl2/libdigestmd5.so.2.0.25)
==26905==    by 0xC230468: client_done (in /usr/lib/x86_64-linux-gnu/libsasl2.so.2.0.25)
==26905==    by 0xC2305A9: sasl_client_done (in /usr/lib/x86_64-linux-gnu/libsasl2.so.2.0.25)
==26905==    by 0xBFE26DD: _mongoc_do_cleanup (in /usr/lib/php/20151012/mongodb.so)
==26905==    by 0x6E304E8: __pthread_once_slow (pthread_once.c:116)
==26905==    by 0x400F8C6: _dl_fini (in /lib/x86_64-linux-gnu/ld-2.22.so)
==26905==    by 0x6AB3E07: __run_exit_handlers (in /lib/x86_64-linux-gnu/libc-2.22.so)
==26905==    by 0x6AB3E54: exit (in /lib/x86_64-linux-gnu/libc-2.22.so)
==26905==    by 0x3F00B1: fpm_init (in /usr/sbin/php-fpm7.0)
==26905==    by 0x1E1D2F: main (in /usr/sbin/php-fpm7.0)
==26905==  Address 0xa20065c is 4 bytes after a block of size 40 free'd
==26905==    at 0x4C2AE6B: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==26905==    by 0x32E657: ini_parse (in /usr/sbin/php-fpm7.0)
==26905==    by 0x32E9BC: zend_parse_ini_file (in /usr/sbin/php-fpm7.0)
==26905==    by 0x301D71: php_init_config (in /usr/sbin/php-fpm7.0)
==26905==    by 0x2F9FA7: php_module_startup (in /usr/sbin/php-fpm7.0)
==26905==    by 0x3F7984: ??? (in /usr/sbin/php-fpm7.0)
==26905==    by 0x1E1CD6: main (in /usr/sbin/php-fpm7.0)
==26905==  Block was alloc'd at
==26905==    at 0x4C29C0F: malloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==26905==    by 0x3377F8: __zend_malloc (in /usr/sbin/php-fpm7.0)
==26905==    by 0x32F0BC: ini_lex (in /usr/sbin/php-fpm7.0)
==26905==    by 0x32DECE: ini_parse (in /usr/sbin/php-fpm7.0)
==26905==    by 0x32E9BC: zend_parse_ini_file (in /usr/sbin/php-fpm7.0)
==26905==    by 0x301D71: php_init_config (in /usr/sbin/php-fpm7.0)
==26905==    by 0x2F9FA7: php_module_startup (in /usr/sbin/php-fpm7.0)
==26905==    by 0x3F7984: ??? (in /usr/sbin/php-fpm7.0)
==26905==    by 0x1E1CD6: main (in /usr/sbin/php-fpm7.0)

You'll have to report this directly to mongodb folks (they have some JIRA setup).

[2016-03-15 18:36 UTC] contact at sshilko dot com

Cross linking with
https://github.com/mongodb/mongo-php-driver/issues/209

[2016-03-16 09:51 UTC] laruence@php.net

-Package: FPM related +Package: mongo

[2016-03-18 15:47 UTC] derick@php.net

-Package: mongo +Package: mongodb

[2016-03-18 20:42 UTC] contact at sshilko dot com

-Status: Open +Status: Closed

[2016-03-18 20:42 UTC] contact at sshilko dot com

mongodb 1.1.5 released with a fix

	php.net \| support \| documentation \| report a bug \| advanced search \| search howto \| statistics \| random bug \| login
go to bug id or search bugs for


Copyright © 2001-2024 The PHP Group All rights reserved.	Last updated: Sat Nov 23 02:01:31 2024 UTC