php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #71573 Segfault (core dumped) if paramno beyond bound
Submitted: 2016-02-12 07:27 UTC Modified: 2016-05-11 03:11 UTC
Votes:5
Avg. Score:4.4 ± 0.8
Reproduced:5 of 5 (100.0%)
Same Version:1 (20.0%)
Same OS:0 (0.0%)
From: johan at x-tnd dot be Assigned: laruence
Status: Closed Package: PDO PgSQL
PHP Version: 7.0.3 OS: Linux CentoOS 7
Private report: No CVE-ID:
 [2016-02-12 07:27 UTC] johan at x-tnd dot be
Description:
------------
I'm running a symfony2 command line script that sometimes cause a segfault. It sounds like this is related to the pdo pgsql extension. I'm using PHP 7.0.3 and extensions (from Remi's SCL repository) ans PostgreSQL 9.2.14 (from centos updates repository).

Unfortunately, I'm not able to provide a script that reproduce this random issue. My command line script is called every hour, it has failed 6 times on 3 days.

Actually, it seems that I've 2 different backtraces:
1-
 % gdb php70 core.7101
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-80.el7
Copyright (C) 2013 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-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /opt/remi/php70/root/usr/bin/php...Reading symbols
from /usr/lib/debug/opt/remi/php70/root/usr/bin/php.debug...done.
done.

warning: core file may not match specified executable file.
[New LWP 7101]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `php70 -d memory_limit=10G app/console
tadaam:importfeed --no-agencies --source'.
Program terminated with signal 11, Segmentation fault.
#0  resetPQExpBuffer (str=str@entry=0x7fd86bcb5c18) at pqexpbuffer.c:149
149				str->data[0] = '\0';
Missing separate debuginfos, use: debuginfo-install
bzip2-libs-1.0.6-13.el7.x86_64 cyrus-sasl-lib-2.1.26-19.2.el7.x86_64
expat-2.1.0-8.el7.x86_64 fontconfig-2.10.95-7.el7.x86_64
freetype-2.4.11-11.el7.x86_64 gd-last-2.1.1-2.el7.remi.x86_64
glibc-2.17-106.el7_2.1.x86_64 jbigkit-libs-2.0-11.el7.x86_64
keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.13.2-10.el7.x86_64
libX11-1.6.3-2.el7.x86_64 libXau-1.0.8-2.1.el7.x86_64
libXpm-3.5.11-3.el7.x86_64 libcom_err-1.42.9-7.el7.x86_64
libcurl-7.29.0-25.el7.centos.x86_64
libedit-3.0-12.20121213cvs.el7.x86_64 libgcc-4.8.5-4.el7.x86_64
libgcrypt-1.5.3-12.el7_1.1.x86_64 libgpg-error-1.12-3.el7.x86_64
libicu-50.1.2-15.el7.x86_64 libidn-1.28-4.el7.x86_64
libjpeg-turbo-1.2.90-5.el7.x86_64 libmcrypt-2.5.8-13.el7.x86_64
libpng-1.5.13-7.el7_2.x86_64 libselinux-2.2.2-6.el7.x86_64
libssh2-1.4.3-10.el7.x86_64 libstdc++-4.8.5-4.el7.x86_64
libtiff-4.0.3-14.el7.x86_64 libtool-ltdl-2.4.2-20.el7.x86_64
libvpx-1.3.0-5.el7_0.x86_64 libxcb-1.11-4.el7.x86_64
libxml2-2.9.1-6.el7_2.2.x86_64 libxslt-1.1.28-5.el7.x86_64
libzip-last-1.1-1.el7.remi.x86_64
ncurses-libs-5.9-13.20130511.el7.x86_64 nspr-4.10.8-2.el7_1.x86_64
nss-3.19.1-19.el7_2.x86_64 nss-softokn-freebl-3.16.2.3-13.el7_1.x86_64
nss-util-3.19.1-4.el7_1.x86_64 openldap-2.4.40-8.el7.x86_64
openssl-libs-1.0.1e-51.el7_2.2.x86_64 pcre-8.32-15.el7.x86_64
php70-php-pecl-apcu-5.1.3-1.el7.remi.x86_64
php70-php-pecl-apcu-bc-1.0.2-1.el7.remi.x86_64
php70-php-pecl-mysql-1.0.0-0.9.20151007git294ce3b.el7.remi.x86_64
php70-php-pecl-xdebug-2.4.0-0.8.RC4.el7.remi.x86_64
php70-php-pecl-zip-1.13.1-3.el7.remi.x86_64 sqlite-3.7.17-8.el7.x86_64
xz-libs-5.1.2-12alpha.el7.x86_64 zlib-1.2.7-15.el7.x86_64
(gdb) bt
#0  resetPQExpBuffer (str=str@entry=0x7fd86bcb5c18) at pqexpbuffer.c:149
#1  0x00007fd870fed7ba in printfPQExpBuffer
(str=str@entry=0x7fd86bcb5c18, fmt=0x7fd870ff494e "unexpected
asyncStatus: %d\n") at pqexpbuffer.c:237
#2  0x00007fd870fe45b4 in PQgetResult (conn=conn@entry=0x7fd86bcb58c0)
at fe-exec.c:1726
#3  0x00007fd870fe460f in PQexecStart (conn=conn@entry=0x7fd86bcb58c0)
at fe-exec.c:1896
#4  0x00007fd870fe47c1 in PQexec (conn=0x7fd86bcb58c0,
query=0x7fd86be208c0 "DEALLOCATE pdo_stmt_00000005") at fe-exec.c:1805
#5  0x00007fd86e10d698 in pgsql_stmt_dtor (stmt=0x7fd869362540) at
/usr/src/debug/php-7.0.3/ext/pdo_pgsql/pgsql_statement.c:64
#6  0x00007fd871431b6a in php_pdo_free_statement (stmt=0x7fd869362540)
at /usr/src/debug/php-7.0.3/ext/pdo/pdo_stmt.c:2315
#7  0x00007fd8852edbe0 in zend_objects_store_free_object_storage
(objects=objects@entry=0x7fd885691bd0 <executor_globals+816>) at
/usr/src/debug/php-7.0.3/Zend/zend_objects_API.c:103
#8  0x00007fd8852a4ac3 in shutdown_executor () at
/usr/src/debug/php-7.0.3/Zend/zend_execute_API.c:357
#9  0x00007fd8852b395a in zend_deactivate () at
/usr/src/debug/php-7.0.3/Zend/zend.c:967
#10 0x00007fd885253cc1 in php_request_shutdown (dummy=dummy@entry=0x0)
at /usr/src/debug/php-7.0.3/main/main.c:1823
#11 0x00007fd88533c868 in do_cli (argc=10, argv=0x7fd885e1a4a0) at
/usr/src/debug/php-7.0.3/sapi/cli/php_cli.c:1142
#12 0x00007fd88513a26a in main (argc=10, argv=0x7fd885e1a4a0) at
/usr/src/debug/php-7.0.3/sapi/cli/php_cli.c:1345

2-
 % gdb php70 core.6209     
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-80.el7
Copyright (C) 2013 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-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /opt/remi/php70/root/usr/bin/php...Reading symbols from /usr/lib/debug/opt/remi/php70/root/usr/bin/php.debug...done.
done.

warning: core file may not match specified executable file.
[New LWP 6209]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `php70 -d memory_limit=10G app/console tadaam:pige lbc -q --env=console'.
Program terminated with signal 11, Segmentation fault.
#0  resetPQExpBuffer (str=str@entry=0x7f3a5fab5ba8) at pqexpbuffer.c:149
149				str->data[0] = '\0';
Missing separate debuginfos, use: debuginfo-install bzip2-libs-1.0.6-13.el7.x86_64 cyrus-sasl-lib-2.1.26-19.2.el7.x86_64 expat-2.1.0-8.el7.x86_64 fontconfig-2.10.95-7.el7.x86_64 freetype-2.4.11-11.el7.x86_64 gd-last-2.1.1-2.el7.remi.x86_64 glibc-2.17-106.el7_2.1.x86_64 jbigkit-libs-2.0-11.el7.x86_64 keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.13.2-10.el7.x86_64 libX11-1.6.3-2.el7.x86_64 libXau-1.0.8-2.1.el7.x86_64 libXpm-3.5.11-3.el7.x86_64 libcom_err-1.42.9-7.el7.x86_64 libcurl-7.29.0-25.el7.centos.x86_64 libedit-3.0-12.20121213cvs.el7.x86_64 libgcc-4.8.5-4.el7.x86_64 libgcrypt-1.5.3-12.el7_1.1.x86_64 libgpg-error-1.12-3.el7.x86_64 libicu-50.1.2-15.el7.x86_64 libidn-1.28-4.el7.x86_64 libjpeg-turbo-1.2.90-5.el7.x86_64 libmcrypt-2.5.8-13.el7.x86_64 libpng-1.5.13-7.el7_2.x86_64 libselinux-2.2.2-6.el7.x86_64 libssh2-1.4.3-10.el7.x86_64 libstdc++-4.8.5-4.el7.x86_64 libtiff-4.0.3-14.el7.x86_64 libtool-ltdl-2.4.2-20.el7.x86_64 libvpx-1.3.0-5.el7_0.x86_64 libxcb-1.11-4.el7.x86_64 libxml2-2.9.1-6.el7_2.2.x86_64 libxslt-1.1.28-5.el7.x86_64 libzip-last-1.1-1.el7.remi.x86_64 ncurses-libs-5.9-13.20130511.el7.x86_64 nspr-4.10.8-2.el7_1.x86_64 nss-3.19.1-19.el7_2.x86_64 nss-softokn-freebl-3.16.2.3-13.el7_1.x86_64 nss-util-3.19.1-4.el7_1.x86_64 openldap-2.4.40-8.el7.x86_64 openssl-libs-1.0.1e-51.el7_2.2.x86_64 pcre-8.32-15.el7.x86_64 php70-php-pecl-apcu-5.1.3-1.el7.remi.x86_64 php70-php-pecl-apcu-bc-1.0.2-1.el7.remi.x86_64 php70-php-pecl-mysql-1.0.0-0.9.20151007git294ce3b.el7.remi.x86_64 php70-php-pecl-xdebug-2.4.0-0.8.RC4.el7.remi.x86_64 php70-php-pecl-zip-1.13.1-3.el7.remi.x86_64 sqlite-3.7.17-8.el7.x86_64 xz-libs-5.1.2-12alpha.el7.x86_64 zlib-1.2.7-15.el7.x86_64
(gdb) bt
#0  resetPQExpBuffer (str=str@entry=0x7f3a5fab5ba8) at pqexpbuffer.c:149
#1  0x00007f3a64ded7ba in printfPQExpBuffer (str=str@entry=0x7f3a5fab5ba8, fmt=0x7f3a64df494e "unexpected asyncStatus: %d\n") at pqexpbuffer.c:237
#2  0x00007f3a64de45b4 in PQgetResult (conn=conn@entry=0x7f3a5fab5850) at fe-exec.c:1726
#3  0x00007f3a64de460f in PQexecStart (conn=conn@entry=0x7f3a5fab5850) at fe-exec.c:1896
#4  0x00007f3a64de47c1 in PQexec (conn=0x7f3a5fab5850, query=0x7f3a58a5e500 "DEALLOCATE pdo_stmt_00000004") at fe-exec.c:1805
#5  0x00007f3a61f0d698 in pgsql_stmt_dtor (stmt=0x7f3a5fc5d1c0) at /usr/src/debug/php-7.0.3/ext/pdo_pgsql/pgsql_statement.c:64
#6  0x00007f3a65231b6a in php_pdo_free_statement (stmt=0x7f3a5fc5d1c0) at /usr/src/debug/php-7.0.3/ext/pdo/pdo_stmt.c:2315
#7  0x00007f3a7913bfa1 in zend_objects_store_del (object=0x7f3a5fc5d310) at /usr/src/debug/php-7.0.3/Zend/zend_objects_API.c:182
#8  0x00007f3a79137474 in i_zval_ptr_dtor (zval_ptr=0x7f3a5fc19a38) at /usr/src/debug/php-7.0.3/Zend/zend_variables.h:58
#9  zend_object_std_dtor (object=0x7f3a5fc198c0) at /usr/src/debug/php-7.0.3/Zend/zend_objects.c:69
#10 0x00007f3a7913bbe0 in zend_objects_store_free_object_storage (objects=objects@entry=0x7f3a794dfbd0 <executor_globals+816>) at /usr/src/debug/php-7.0.3/Zend/zend_objects_API.c:103
#11 0x00007f3a790f2ac3 in shutdown_executor () at /usr/src/debug/php-7.0.3/Zend/zend_execute_API.c:357
#12 0x00007f3a7910195a in zend_deactivate () at /usr/src/debug/php-7.0.3/Zend/zend.c:967
#13 0x00007f3a790a1cc1 in php_request_shutdown (dummy=dummy@entry=0x0) at /usr/src/debug/php-7.0.3/main/main.c:1823
#14 0x00007f3a7918a868 in do_cli (argc=8, argv=0x7f3a7a1b44a0) at /usr/src/debug/php-7.0.3/sapi/cli/php_cli.c:1142
#15 0x00007f3a78f8826a in main (argc=8, argv=0x7f3a7a1b44a0) at /usr/src/debug/php-7.0.3/sapi/cli/php_cli.c:1345

Let me know if I can provide you more informations on this issue.

Thank you very much!


Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2016-02-18 08:35 UTC] mbeccati@php.net
-Assigned To: +Assigned To: mbeccati
 [2016-02-18 08:35 UTC] mbeccati@php.net
Could you please try running the script using valgrind? It will be much slower, but it might give us a better idea of what's causing the issue.
 [2016-04-01 07:33 UTC] phofstetter at sensational dot ch
I'm also seeing this on Debian Jessie with PHP 7.0.4.

I'll try to make a reduced testcase somehow.
 [2016-04-01 07:36 UTC] mbeccati@php.net
-Status: Assigned +Status: Feedback
 [2016-04-01 07:36 UTC] mbeccati@php.net
Thanks. Waiting for more feedback.
 [2016-04-01 09:30 UTC] phofstetter at sensational dot ch
I have great trouble making a reduced test-case: While the crash is 100% reproducible with a specific request, I'm unsucessful in reducing the testcase, mainly because a lot of things are going on in the request in question.

I'll need a bit more time.

In the mean time, I have run fpm in valgind, where I had to add a ton of error suppresions because of issues in OpenSSL (the request in question is validating a signature).

The errors were 1000s of either

- Conditional jump or move depends on uninitialised value(s)
- Use of uninitialised value of size 8

all of them happening in libcrypto.

Once that's cleaned up, here's the valgrind output of the crash.

Yes, this might look like an issue in libpq (especially as the values passed into PQexec look sensible), but I still suspect PHP as this doesn't happen in 5.6 and I have not seen this crash happen in libpq before.

This is php-7.0.4 (self compiled) and libpq-9.4 (from Debian 8: libpq5_9.4.6-0+deb8u1)

==24783== Memcheck, a memory error detector
==24783== Copyright (C) 2002-2013, and GNU GPL'd, by Julian Seward et al.
==24783== Using Valgrind-3.10.0 and LibVEX; rerun with -h for copyright info
==24783== Command: /opt/php/7.0/sbin/php-fpm --fpm-config /opt/php/7.0/etc/php-fpm.conf -F
==24783==
==24783== Warning: set address range perms: large range [0x14b6f000, 0x2cb6f000) (defined)
[01-Apr-2016 11:24:24] NOTICE: fpm is running, pid 24783
[01-Apr-2016 11:24:24] NOTICE: ready to handle connections
==24784== Invalid write of size 1
==24784==    at 0xEB1F2E8: resetPQExpBuffer (pqexpbuffer.c:154)
==24784==    by 0xEB1025E: PQsendQueryStart (fe-exec.c:1351)
==24784==    by 0xEB0FC59: PQsendQuery (fe-exec.c:1114)
==24784==    by 0xEB10E28: PQexec (fe-exec.c:1828)
==24784==    by 0xE8F7352: pgsql_stmt_dtor (pgsql_statement.c:64)
==24784==    by 0x5D1B79: php_pdo_free_statement (pdo_stmt.c:2316)
==24784==    by 0x7A2EE1: zend_objects_store_del (zend_objects_API.c:182)
==24784==    by 0x77A13E: i_zval_ptr_dtor (zend_variables.h:58)
==24784==    by 0x77A13E: zend_array_destroy (zend_hash.c:1322)
==24784==    by 0x7684E8: i_zval_ptr_dtor (zend_variables.h:58)
==24784==    by 0x7684E8: _zval_dtor_func_for_ptr (zend_variables.c:122)
==24784==    by 0x77A207: i_zval_ptr_dtor (zend_variables.h:58)
==24784==    by 0x77A207: zend_array_destroy (zend_hash.c:1326)
==24784==    by 0x79E20A: i_zval_ptr_dtor (zend_variables.h:58)
==24784==    by 0x79E20A: zend_object_std_dtor (zend_objects.c:69)
==24784==    by 0x7A2BB0: zend_objects_store_free_object_storage (zend_objects_API.c:103)
==24784==  Address 0x0 is not stack'd, malloc'd or (recently) free'd
==24784==
==24784==
==24784== Process terminating with default action of signal 11 (SIGSEGV)
==24784==  Access not within mapped region at address 0x0
==24784==    at 0xEB1F2E8: resetPQExpBuffer (pqexpbuffer.c:154)
==24784==    by 0xEB1025E: PQsendQueryStart (fe-exec.c:1351)
==24784==    by 0xEB0FC59: PQsendQuery (fe-exec.c:1114)
==24784==    by 0xEB10E28: PQexec (fe-exec.c:1828)
==24784==    by 0xE8F7352: pgsql_stmt_dtor (pgsql_statement.c:64)
==24784==    by 0x5D1B79: php_pdo_free_statement (pdo_stmt.c:2316)
==24784==    by 0x7A2EE1: zend_objects_store_del (zend_objects_API.c:182)
==24784==    by 0x77A13E: i_zval_ptr_dtor (zend_variables.h:58)
==24784==    by 0x77A13E: zend_array_destroy (zend_hash.c:1322)
==24784==    by 0x7684E8: i_zval_ptr_dtor (zend_variables.h:58)
==24784==    by 0x7684E8: _zval_dtor_func_for_ptr (zend_variables.c:122)
==24784==    by 0x77A207: i_zval_ptr_dtor (zend_variables.h:58)
==24784==    by 0x77A207: zend_array_destroy (zend_hash.c:1326)
==24784==    by 0x79E20A: i_zval_ptr_dtor (zend_variables.h:58)
==24784==    by 0x79E20A: zend_object_std_dtor (zend_objects.c:69)
==24784==    by 0x7A2BB0: zend_objects_store_free_object_storage (zend_objects_API.c:103)
==24784==  If you believe this happened as a result of a stack
==24784==  overflow in your program's main thread (unlikely but
==24784==  possible), you can try to increase the size of the
==24784==  main thread stack using the --main-stacksize= flag.
==24784==  The main thread stack size used in this run was 8388608.
==24784==
==24784== HEAP SUMMARY:
==24784==     in use at exit: 4,150,545 bytes in 33,595 blocks
==24784==   total heap usage: 70,756 allocs, 37,161 frees, 13,929,319 bytes allocated
==24784==
==24784== LEAK SUMMARY:
==24784==    definitely lost: 208 bytes in 1 blocks
==24784==    indirectly lost: 670 bytes in 25 blocks
==24784==      possibly lost: 3,054,043 bytes in 27,263 blocks
==24784==    still reachable: 1,095,624 bytes in 6,306 blocks
==24784==         suppressed: 0 bytes in 0 blocks
==24784== Rerun with --leak-check=full to see details of leaked memory
==24784==
==24784== For counts of detected and suppressed errors, rerun with: -v
==24784== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 175536 from 2710)
==24784== could not unlink /tmp/vgdb-pipe-from-vgdb-to-24784-by-???-on-???
==24784== could not unlink /tmp/vgdb-pipe-to-vgdb-from-24784-by-???-on-???
==24784== could not unlink /tmp/vgdb-pipe-shared-mem-vgdb-24784-by-???-on-???
[01-Apr-2016 11:24:39] WARNING: [pool www] child 24784 exited on signal 11 (SIGSEGV) after 15.036450 seconds from start
[01-Apr-2016 11:24:39] NOTICE: [pool www] child 25243 started
 [2016-04-01 09:44 UTC] phofstetter at sensational dot ch
now using a rebuilt non-stripped libpq, I started investigating the stack frames a bit more and it definitely looks like the connection object libpq is working on at this point is corrupt:

(gdb) frame 0
#0  0x00007f250d6e2883 in pqGetc (result=0x7ffe6ad53527 "", conn=0x7f250e6ac498) at /home/crazyhat/postgresql-9.4-9.4.6/build/../src/interfaces/libpq/fe-misc.c:104
104		*result = conn->inBuffer[conn->inCursor++];
(gdb) p conn->pghost
$7 = 0x7f250e6ac818 "\340\307j\016%\177"
(gdb) p conn->dbName
$8 = 0x0
(gdb) p conn->last_query
$9 = 0x7f250e7fcab8 "\230\304\177\016%\177"
(gdb) p conn->errorMessage
$10 = {data = 0x7f250e6c4908 "\200<`\016%\177", len = 4294967297, maxlen = 16}
(gdb)

this doesn't look very... correct 😊

Also, that connection doesn't get corrupted inside of libpq - on frame 5 (the last one inside PHP), stuff already looks wahoonie-shaped:

(gdb) frame 5
#5  0x00007f250d6dfe0b in PQexec (conn=0x7f250e6ac498, query=0x7f250e730730 "DEALLOCATE pdo_stmt_00000015")
    at /home/crazyhat/postgresql-9.4-9.4.6/build/../src/interfaces/libpq/fe-exec.c:1826
1826		if (!PQexecStart(conn))
(gdb) p conn->last_query
$12 = 0x7f250e7fcab8 "\230\304\177\016%\177"
(gdb) p conn
$13 = (PGconn *) 0x7f250e6ac498

I'm not too well-versed with valgrind - can you give me some further hints in how I can get more information out of valgrind or with gdb?
 [2016-04-01 09:53 UTC] mbeccati@php.net
Thanks for your help. Nice investigation work. I would try next to set a gdb breakpoint after the connection is initialised, then a watchpoint to see when the connection data is overwritten.
 [2016-04-01 12:28 UTC] phofstetter at sensational dot ch
update: By doing a bit of printf-debugging, I can confirm that this crash happens because a statement destructor runs after the connection destructor has run.

I have added logging to pdo_pgsql_handle_factory when connecting, to pgsql_stmt_dtor just before the call to PQexec that causes the crash and then once more at the beginning of pgsql_handle_closer

Here's a trace: The connection is created with a pdo_pgsql_db_handle of b061d498, then there's a lot of statement destructors being called on the same handle. Then, pgsql_handle_closer is invoked, closing the connection with PQfinish and then, finally, one more statement destructor is running, causing the crash.

I have now also disabled opcache in order to make sure this isn't the problem.

Also, after so many valgrind errors from OpenSSL, I decided to not do the crypto stuff - the trace is still the same.

And, on even better news: I can make this request not crash depending on the input data, so I might soon have a reduced repro (or a fix - who knows).

I'd say: it's getting warmer

[01-Apr-2016 14:16:09] WARNING: [pool www] child 2782 said into stderr: "Connect host=db1 dbname=****** user=**** connect_timeout=30. H=b061d498"
[01-Apr-2016 14:16:09] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:09] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:09] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:09] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:09] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "pgsql_handle_closer dbh=b79f8f00, handle=b061d498"
[01-Apr-2016 14:16:10] WARNING: [pool www] child 2782 said into stderr: "stmt_dtor: deallocate H=b061d498"
 [2016-04-01 12:37 UTC] mbeccati@php.net
-Status: Feedback +Status: Assigned
 [2016-04-01 12:37 UTC] mbeccati@php.net
That's incredibly helpful, thanks. We'll look into it.
 [2016-04-01 14:53 UTC] phofstetter at sensational dot ch
ok. One more update, but that's probably obvious from looking at the callstack:

The application in question is keeping cached PDO statement objects around to reuse them when possible. When I disable that cache, so don't keep an array of cached handles around, then the crash goes away.

so the application checks whether

$cached_handles[md5($query)] exists and if so, it just reuses that handle (the thing is a bit more complicated in that it keeps only up to a certain amount of handles around and only if the query has actual arguments, but that's not relevant here).

Interestingly enough, this works fine in a small test script and only fails on that specific request.

There are cases where the cache is cleaned using

$cached_handles = array();

but there's never an explicit freeing of these handles going on (unless there are more than 50 of them and another one needs to be created).

I can make the problem go away if I manually clean these handles out by calling `closeCursor` and nulling them in the destructor of the class that owns both the cache and the PDO handle.

Still - PHP probably shouldn't be segfaulting if it hits code that's relying on PHP to clean up after itself.

Also, I still can't provide a reduced testcase. All attempts at filling the cache with just the right amount of statements in an easier setup were not successful.
 [2016-04-09 18:46 UTC] mbeccati@php.net
-Assigned To: mbeccati +Assigned To: laruence
 [2016-04-09 18:46 UTC] mbeccati@php.net
Apparently GC-related (see last comments), so I can't do much about it myself. I hope Xinchen can pick it up.
 [2016-04-10 02:28 UTC] laruence@php.net
but if no reproduce script(or scripts), I can not do much thing here :<
 [2016-04-16 20:55 UTC] mfischer@php.net
I'm adding this here too due the similarity of the stacktrace with printfPQExpBuffer I'm getting; however in my case it's on Ubuntu with opcache, specifically opcache.fast_shutdown=1 will reproducible lead to a crash using CakePHP 2.8.3. Unfortunately I'm not able to create a small reproducible script. I originally repoted this at https://github.com/oerdnj/deb.sury.org/issues/322 .

Program received signal SIGSEGV, Segmentation fault.
resetPQExpBuffer (str=str@entry=0x7fb575b5fe10) at /build/postgresql-9.5-DVsMQj/postgresql-9.5-9.5.2/build/../src/interfaces/libpq/pqexpbuffer.c:152
152     /build/postgresql-9.5-DVsMQj/postgresql-9.5-9.5.2/build/../src/interfaces/libpq/pqexpbuffer.c: No such file or directory.
(gdb) bt
#0  resetPQExpBuffer (str=str@entry=0x7fb575b5fe10) at /build/postgresql-9.5-DVsMQj/postgresql-9.5-9.5.2/build/../src/interfaces/libpq/pqexpbuffer.c:152
#1  0x00007fb568e99cf7 in PQsendQueryStart (conn=conn@entry=0x7fb575b5fab8) at /build/postgresql-9.5-DVsMQj/postgresql-9.5-9.5.2/build/../src/interfaces/libpq/fe-exec.c:1352
#2  0x00007fb568e9b6cb in PQsendQuery (conn=conn@entry=0x7fb575b5fab8, query=query@entry=0x7fb575ba2550 "DEALLOCATE pdo_stmt_00000007")
    at /build/postgresql-9.5-DVsMQj/postgresql-9.5-9.5.2/build/../src/interfaces/libpq/fe-exec.c:1115
#3  0x00007fb568e9cd21 in PQexec (conn=0x7fb575b5fab8, query=0x7fb575ba2550 "DEALLOCATE pdo_stmt_00000007")
    at /build/postgresql-9.5-DVsMQj/postgresql-9.5-9.5.2/build/../src/interfaces/libpq/fe-exec.c:1829
#4  0x00007fb5690c0733 in pgsql_stmt_dtor (stmt=0x7fb55dc72380) at /build/php7.0-kNWWO9/php7.0-7.0.5/ext/pdo_pgsql/pgsql_statement.c:64
#5  0x00007fb574f39d6a in php_pdo_free_statement (stmt=0x7fb55dc72380) at /build/php7.0-kNWWO9/php7.0-7.0.5/ext/pdo/pdo_stmt.c:2316
#6  0x00007fb57845b941 in zend_objects_store_del (object=0x7fb55dc724d0) at /build/php7.0-kNWWO9/php7.0-7.0.5/Zend/zend_objects_API.c:182
#7  0x00007fb578421926 in _zval_dtor_func_for_ptr (p=<optimized out>) at /build/php7.0-kNWWO9/php7.0-7.0.5/Zend/zend_variables.c:109
#8  0x00007fb578421959 in i_zval_ptr_dtor (zval_ptr=0x7fb575a98920) at /build/php7.0-kNWWO9/php7.0-7.0.5/Zend/zend_variables.h:58
#9  _zval_dtor_func_for_ptr (p=0x7fb575a98918) at /build/php7.0-kNWWO9/php7.0-7.0.5/Zend/zend_variables.c:122
#10 0x00007fb578457014 in i_zval_ptr_dtor (zval_ptr=0x7fb575a60928) at /build/php7.0-kNWWO9/php7.0-7.0.5/Zend/zend_variables.h:58
#11 zend_object_std_dtor (object=0x7fb575a60800) at /build/php7.0-kNWWO9/php7.0-7.0.5/Zend/zend_objects.c:69
#12 0x00007fb57845b5a0 in zend_objects_store_free_object_storage (objects=0x7fb575b5fe10, objects@entry=0x7fb578804530 <executor_globals+816>)
    at /build/php7.0-kNWWO9/php7.0-7.0.5/Zend/zend_objects_API.c:103
#13 0x00007fb578414913 in shutdown_executor () at /build/php7.0-kNWWO9/php7.0-7.0.5/Zend/zend_execute_API.c:357
#14 0x00007fb5784231c5 in zend_deactivate () at /build/php7.0-kNWWO9/php7.0-7.0.5/Zend/zend.c:967
#15 0x00007fb5783c5ee1 in php_request_shutdown (dummy=<optimized out>) at /build/php7.0-kNWWO9/php7.0-7.0.5/main/main.c:1826
#16 0x00007fb5782b89c6 in main (argc=<optimized out>, argv=<optimized out>) at /build/php7.0-kNWWO9/php7.0-7.0.5/sapi/fpm/fpm/fpm_main.c:1996
 [2016-04-24 09:22 UTC] deadem at gmail dot com
I've got it:

$pdo = new PDO("pgsql:host=localhost;dbname=BASE", "USER", "PASS", []);
$statement = $pdo->prepare('select *, ?, \'?\' from "text"');
$statement->execute([ 'test', 'test', 'test' ]);
 [2016-05-11 03:11 UTC] laruence@php.net
-Summary: Segfault (core dumped) +Summary: Segfault (core dumped) if paramno beyond bound
 [2016-05-11 03:13 UTC] laruence@php.net
Automatic comment on behalf of laruence@gmail.com
Revision: http://git.php.net/?p=php-src.git;a=commit;h=66ad4fc393d687f4ca255dd3788529856942bbaa
Log: Fixed bug #71573 (Segfault (core dumped) if paramno beyond bound)
 [2016-05-11 03:13 UTC] laruence@php.net
-Status: Assigned +Status: Closed
 [2016-05-13 18:02 UTC] caribe at candcsolution dot com
Hi Laurence,

Thanks for working on this bug.  I applied your patch by hand to 7.0.4, and it still seems to be broken for me.  Here's the stack trace I'm seeing in gdb from my most recent crash:

GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-80.el7
Copyright (C) 2013 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-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/lib/php5/bin/php...done.
[New LWP 22169]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Program terminated with signal 11, Segmentation fault.
#0  resetPQExpBuffer (str=str@entry=0x7f7bf2a8ba20) at pqexpbuffer.c:154
154                             str->data[0] = '\0';
(gdb) bt
#0  resetPQExpBuffer (str=str@entry=0x7f7bf2a8ba20) at pqexpbuffer.c:154
#1  0x00007f7c04019bdd in PQsendQueryStart (conn=conn@entry=0x7f7bf2a8b6c8) at fe-exec.c:1351
#2  0x00007f7c0401b561 in PQsendQuery (conn=conn@entry=0x7f7bf2a8b6c8, query=query@entry=0x7f7bf2dc3e60 "DEALLOCATE pdo_stmt_00000003") at fe-exec.c:1114
#3  0x00007f7c0401cab0 in PQexec (conn=0x7f7bf2a8b6c8, query=0x7f7bf2dc3e60 "DEALLOCATE pdo_stmt_00000003") at fe-exec.c:1828
#4  0x0000000000640d03 in pgsql_stmt_dtor (stmt=0x7f7bf2d9dc40) at /home/build/php-7.0.4/ext/pdo_pgsql/pgsql_statement.c:64
#5  0x000000000063c7fa in php_pdo_free_statement (stmt=0x7f7bf2d9dc40) at /home/build/php-7.0.4/ext/pdo/pdo_stmt.c:2316
#6  0x000000000083ce31 in zend_objects_store_free_object_storage (objects=<optimized out>) at /home/build/php-7.0.4/Zend/zend_objects_API.c:103
#7  0x00000000007f102c in shutdown_executor () at /home/build/php-7.0.4/Zend/zend_execute_API.c:357
#8  0x0000000000801313 in zend_deactivate () at /home/build/php-7.0.4/Zend/zend.c:967
#9  0x0000000000795127 in php_request_shutdown (dummy=dummy@entry=0x0) at /home/build/php-7.0.4/main/main.c:1823
#10 0x0000000000892d82 in do_cli (argc=4, argv=0x1e18250) at /home/build/php-7.0.4/sapi/cli/php_cli.c:1142
#11 0x0000000000441f87 in main (argc=4, argv=0x1e18250) at /home/build/php-7.0.4/sapi/cli/php_cli.c:1345

Is this expected with 7.0.4?  This definitely seems to be a GC issue to me as this only happens in my CLI app on shutdown and destruct.  From the digging I was able to do it seemed like things were getting double free()'d somewhere because the crash appears to be on the dtor trying to clean up objects that are already cleaned up.

I'm not anywhere near as versed on the internals of PHP and PDO as you are, but the submitted patch seemed to be angled more toward missing elements of a bound statement in PDO and not toward this apparent GC/destruct issue.
 [2016-07-20 11:31 UTC] davey@php.net
Automatic comment on behalf of laruence@gmail.com
Revision: http://git.php.net/?p=php-src.git;a=commit;h=66ad4fc393d687f4ca255dd3788529856942bbaa
Log: Fixed bug #71573 (Segfault (core dumped) if paramno beyond bound)
 
PHP Copyright © 2001-2017 The PHP Group
All rights reserved.
Last updated: Tue Feb 28 14:01:40 2017 UTC