Bug #71821 [Com]: php-fpm7 crashes due to unknown entry 'log_level' in config

Edit report at https://bugs.php.net/bug.php?id=71821&edit=1 ID: 71821 Comment by: contact at sshilko dot com Reported by: contact at sshilko dot com Summary: php-fpm7 crashes due to unknown entry 'log_level' in config Status: Open Type: Bug Package: FPM related Operating System: Ubuntu 14.04.3 PHP Version: 7.0.4 Block user comment: N Private report: N New Comment: Cross linking with https://github.com/mongodb/mongo-php-driver/issues/209 Previous Comments: ------------------------------------------------------------------------ [2016-03-15 11:35:21] 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 11:31:13] 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:20:43] 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:06:22] 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:03:10] 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. ------------------------------------------------------------------------ The remainder of the comments for this report are too long. To view the rest of the comments, please view the bug report online at https://bugs.php.net/bug.php?id=71821 -- Edit this bug report at https://bugs.php.net/bug.php?id=71821&edit=1