Edit report at https://bugs.php.net/bug.php?id=71573&edit=1
ID: 71573
Comment by: phofstetter at sensational dot ch
Reported by: johan at x-tnd dot be
Summary: Segfault (core dumped)
Status: Feedback
Type: Bug
Package: PDO PgSQL
Operating System: Linux CentoOS 7
PHP Version: 7.0.3
Assigned To: mbeccati
Block user comment: N
Private report: N
New Comment:
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"
Previous Comments:
------------------------------------------------------------------------
[2016-04-01 09:53:34] 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 09:44:19] 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:30:44] 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 07:36:53] mbeccati@php.net
Thanks. Waiting for more feedback.
------------------------------------------------------------------------
[2016-04-01 07:33:35] 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.
------------------------------------------------------------------------
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=71573
--
Edit this bug report at https://bugs.php.net/bug.php?id=71573&edit=1