Bug #64827 [Asn->Fbk]: Segfault in zval_mark_grey (zend_gc.c)

Edit report at https://bugs.php.net/bug.php?id=64827&edit=1 ID: 64827 Updated by: cmb@php.net Reported by: odoucet@php.net Summary: Segfault in zval_mark_grey (zend_gc.c) -Status: Assigned +Status: Feedback Type: Bug Package: opcache Operating System: Linux PHP Version: 5.4.15 -Assigned To: laruence +Assigned To: cmb Block user comment: N Private report: N New Comment: Does this still happen with any of the actively supported PHP versions[1]? [1] <https://www.php.net/supported-versions.php> Previous Comments: ------------------------------------------------------------------------ [2016-06-18 05:31:40] ta-sdz at deshammer dot net Hello everybody on this long outstanding bug. I think I'm onto something there. I had this SIG11 regularly and reproducibly enough to reliably get coredumps in an application too huge to be shared publicly. Here's one backtrace of them on a 5.6.22 installation: (gdb) bt full #0 0x00007f58457a9a6d in zval_mark_grey (pz=<optimized out>) at /usr/src/debug/php-5.6.22/Zend/zend_gc.c:420 p = 0x7f585ca80790 #1 0x00007f58457aab19 in zobj_mark_grey (obj=<optimized out>, pz=<optimized out>) at /usr/src/debug/php-5.6.22/Zend/zend_gc.c:454 i = 0 n = 4 table = 0x7f585ca75f00 p = <optimized out> get_gc = <optimized out> #2 gc_mark_roots () at /usr/src/debug/php-5.6.22/Zend/zend_gc.c:488 z = {value = {lval = 140015933864297, dval = 6.917706279272916e-310, str = {val = 0x7f5800003969 <Address 0x7f5800003969 out of bounds>, len = 1169556032}, ht = 0x7f5800003969, obj = {handle = 14697, handlers = 0x7f5845b60240 <std_object_handlers>}, ast = 0x7f5800003969}, refcount__gc = 1, type = 88 'X', is_ref__gc = 0 '\000'} obj = <optimized out> current = 0x7f5844a1be50 #3 gc_collect_cycles () at /usr/src/debug/php-5.6.22/Zend/zend_gc.c:790 p = <optimized out> q = <optimized out> orig_free_list = <optimized out> orig_next_to_free = <optimized out> count = 0 #4 0x00007f58457aae02 in gc_zval_possible_root (zv=0x7f58582723d8) at /usr/src/debug/php-5.6.22/Zend/zend_gc.c:163 newRoot = <optimized out> #5 0x00007f5845797f48 in zend_hash_destroy (ht=0x7f585ca81008) at /usr/src/debug/php-5.6.22/Zend/zend_hash.c:548 p = 0x7f585ca7ea00 q = 0x7f585ca805d8 #6 0x00007f58457b127c in zend_object_std_dtor (object=0x7f585ca7e7b8) at /usr/src/debug/php-5.6.22/Zend/zend_objects.c:44 No locals. #7 0x00007f58457b1309 in zend_objects_free_object_storage (object=0x7f585ca7e7b8) at /usr/src/debug/php-5.6.22/Zend/zend_objects.c:137 No locals. #8 0x00007f58457b75ec in zend_objects_store_del_ref_by_handle_ex (handle=14702, handlers=<optimized out>) at /usr/src/debug/php-5.6.22/Zend/zend_objects_API.c:226 __orig_bailout = 0x7ffc1fc46590 __bailout = {{__jmpbuf = {140017488351064, -2743026434694212569, 140016688292440, 140017400377624, 140016688292440, 0, -2835498401476668377, -2742977752702544857}, __mask_was_saved = 0, __saved_mask = {__val = {140017099424667, 140017103407076, 140017086683120, 206158430224, 140720841449808, 140720841449600, 13176172747737717760, 140017103407076, 140017099629640, 140720841449824, 140720841449820, 1, 140017086682768, 8, 4, 140017099310240}}}} ---Type <return> to continue, or q <return> to quit---q Quit (gdb) frame 0 #0 0x00007f58457a9a6d in zval_mark_grey (pz=<optimized out>) at /usr/src/debug/php-5.6.22/Zend/zend_gc.c:420 420 pz = *(zval**)p->pData; (gdb) print p $1 = (Bucket *) 0x7f585ca80790 (gdb) print *(zval**) p $2 = (zval *) 0x7f585c102478 (gdb) print *(zval**) p->pData Cannot access memory at address 0x0 (gdb) print p->pData $3 = (void *) 0x0 (gdb) Now look at that! p->pData is a NULL-Pointer which should reference something. Well - nothing simplier than that - I thought - catch the NULL and be fine. But ... after catching the (p->pData==NULL) some more came up. Core was generated by `/usr/sbin/httpd -DFOREGROUND'. Program terminated with signal 11, Segmentation fault. #0 zval_mark_grey (pz=0x0) at /usr/src/debug/php-5.6.22/Zend/zend_gc.c:422 422 if (Z_TYPE_P(pz) != IS_ARRAY || Z_ARRVAL_P(pz) != &EG(symbol_table)) { (gdb) print pz $1 = (zval *) 0x0 (gdb) So there is (pz==NULL) and this gave the operations on pz in line 422 the creeps. Well then - let's catch (pz==NULL) as well ... I thought again - or at least I tried. After catching (p->pData==NULL) and (pz==NULL) the SIG11 wandered into the zval_scan_black() function: Program terminated with signal 11, Segmentation fault. #0 0x00007f8e76ac4cbd in zval_scan_black (pz=<optimized out>) at /usr/src/debug/php-5.6.22/Zend/zend_gc.c:313 313 pz = *(zval**)p->pData; (gdb) print p $1 = (Bucket *) 0x7f8e8e05e1e0 (gdb) print p->pData $2 = (void *) 0x0 (gdb) print *p $3 = {h = 140250165711864, nKeyLength = 2382165776, pData = 0x0, pDataPtr = 0x0, pListNext = 0x0, pListLast = 0x7f8e8e05e3f0, pNext = 0x0, pLast = 0x0, arKey = 0x7f8e5d205fd8 "hackLanguageID"} (gdb) and so on and so on - until any loop over p which referenced p->pData or pz was enclosed with a null pointer catch. After that there were no more SIG11s. I'm fully aware that this patch should have remedied the cause of the p->pData==NULL and the pz==NULL and not the symptom but this was way over my head. As well as the part of "TODO: Maybe some logging here". Well - here's the patch which I wanted you to review and maybe add some logging to it: --- php-5.6.22/Zend/zend_gc.c 2016-05-26 03:08:57.000000000 +0200 +++ php-5.6.22-patched/Zend/zend_gc.c 2016-06-17 21:27:32.226425023 +0200 @@ -310,16 +310,25 @@ } } while (p != NULL) { - pz = *(zval**)p->pData; - if (Z_TYPE_P(pz) != IS_ARRAY || Z_ARRVAL_P(pz) != &EG(symbol_table)) { - pz->refcount__gc++; - } - if (GC_ZVAL_GET_COLOR(pz) != GC_BLACK) { - if (p->pListNext == NULL) { - goto tail_call; + if (p->pData != NULL) { + pz = *(zval**)p->pData; + if (pz != NULL) { + if (Z_TYPE_P(pz) != IS_ARRAY || Z_ARRVAL_P(pz) != &EG(symbol_table)) { + pz->refcount__gc++; + } + if (GC_ZVAL_GET_COLOR(pz) != GC_BLACK) { + if (p->pListNext == NULL) { + goto tail_call; + } else { + zval_scan_black(pz TSRMLS_CC); + } + } } else { - zval_scan_black(pz TSRMLS_CC); + /* Now this is really odd ... we've got a p->pData which references a NULL pointer */ } + } else { + /* shall we log something when encountering a p->pData == NULL */ + } p = p->pListNext; } @@ -353,12 +362,20 @@ } p = props->pListHead; while (p != NULL) { - pz = *(zval**)p->pData; - if (Z_TYPE_P(pz) != IS_ARRAY || Z_ARRVAL_P(pz) != &EG(symbol_table)) { - pz->refcount__gc++; - } - if (GC_ZVAL_GET_COLOR(pz) != GC_BLACK) { - zval_scan_black(pz TSRMLS_CC); + if (p->pData != NULL) { + pz = *(zval**)p->pData; + if (pz != NULL) { + if (Z_TYPE_P(pz) != IS_ARRAY || Z_ARRVAL_P(pz) != &EG(symbol_table)) { + pz->refcount__gc++; + } + if (GC_ZVAL_GET_COLOR(pz) != GC_BLACK) { + zval_scan_black(pz TSRMLS_CC); + } + } else { + /* pz is NULL - maybe there should be some logging? */ + } + } else { + /* p->pData is NULL - maybe there should be some logging? */ } p = p->pListNext; } @@ -417,14 +434,23 @@ } } while (p != NULL) { - pz = *(zval**)p->pData; - if (Z_TYPE_P(pz) != IS_ARRAY || Z_ARRVAL_P(pz) != &EG(symbol_table)) { - pz->refcount__gc--; - } - if (p->pListNext == NULL) { - goto tail_call; + if (p->pData != NULL) { + pz = *(zval**)p->pData; + if (pz != NULL) { + if (Z_TYPE_P(pz) != IS_ARRAY || Z_ARRVAL_P(pz) != &EG(symbol_table)) { + pz->refcount__gc--; + } + if (p->pListNext == NULL) { + goto tail_call; + } else { + zval_mark_grey(pz TSRMLS_CC); + } + } else { + /* Now this is odd - we have a valid pz and a pData which is NULL */ + + } } else { - zval_mark_grey(pz TSRMLS_CC); + /* Some logging maybe? p->pData is NULL */ } p = p->pListNext; } @@ -459,11 +485,19 @@ } p = props->pListHead; while (p != NULL) { - pz = *(zval**)p->pData; - if (Z_TYPE_P(pz) != IS_ARRAY || Z_ARRVAL_P(pz) != &EG(symbol_table)) { - pz->refcount__gc--; + if (p->pData != NULL) { + pz = *(zval**)p->pData; + if (pz != NULL) { + if (Z_TYPE_P(pz) != IS_ARRAY || Z_ARRVAL_P(pz) != &EG(symbol_table)) { + pz->refcount__gc--; + } + zval_mark_grey(pz TSRMLS_CC); + } else { + /* TODO: Some logging maybe? */ + } + } else { + /* TODO: Some logging maybe? */ } - zval_mark_grey(pz TSRMLS_CC); p = p->pListNext; } } ------------------------------------------------------------------------ [2015-04-21 16:01:42] justin at eblah dot com @laruence -- I saw back in 2013 where you requested access to a box where this is happening. I may be able to give you a cloned box to work with if that'd help, but I'd have to talk to some people first. Let me know if interested. ------------------------------------------------------------------------ [2015-04-21 15:56:25] justin at eblah dot com I'm also seeing this, but can't reproduce it easily. I can add an additional echo somewhere in the script, and the problem goes away, so I don't know how to reproduce it code wise. #0 zval_mark_grey (pz=0x7f2b76f7d268) at /usr/src/debug/php-5.6.8/Zend/zend_gc.c:421 #1 0x00000000005e008d in gc_mark_roots () at /usr/src/debug/php-5.6.8/Zend/zend_gc.c:501 #2 gc_collect_cycles () at /usr/src/debug/php-5.6.8/Zend/zend_gc.c:795 #3 0x00000000005e0192 in gc_zobj_possible_root (zv=<value optimized out>) at /usr/src/debug/php-5.6.8/Zend/zend_gc.c:221 #4 0x000000000063f828 in gc_zval_check_possible_root (execute_data=0x7f2b95bb87a0) at /usr/src/debug/php-5.6.8/Zend/zend_gc.h:183 #5 zend_assign_to_variable (execute_data=0x7f2b95bb87a0) at /usr/src/debug/php-5.6.8/Zend/zend_execute.c:930 #6 ZEND_ASSIGN_SPEC_CV_VAR_HANDLER (execute_data=0x7f2b95bb87a0) at /usr/src/debug/php-5.6.8/Zend/zend_vm_execute.h:37448 #7 0x000000000062dbe8 in execute_ex (execute_data=0x7f2b95bb87a0) at /usr/src/debug/php-5.6.8/Zend/zend_vm_execute.h:363 #8 0x00000000005af8ce in dtrace_execute_ex (execute_data=0x7f2b95bb87a0) at /usr/src/debug/php-5.6.8/Zend/zend_dtrace.c:73 #9 0x00007f2b7f5cdd4d in nr_php_execute_enabled () at /home/hudson/slave-workspace/workspace/PHP_Release_Agent/label/centos5-64-nrcamp/agent/php_execute.c:1099 #10 0x00007f2b7f5ce362 in nr_php_execute () at /home/hudson/slave-workspace/workspace/PHP_Release_Agent/label/centos5-64-nrcamp/agent/php_execute.c:1210 #11 0x000000000063e6bc in zend_do_fcall_common_helper_SPEC (execute_data=<value optimized out>) at /usr/src/debug/php-5.6.8/Zend/zend_vm_execute.h:592 #12 0x000000000062dbe8 in execute_ex (execute_data=0x7f2b95bb8638) at /usr/src/debug/php-5.6.8/Zend/zend_vm_execute.h:363 #13 0x00000000005af8ce in dtrace_execute_ex (execute_data=0x7f2b95bb8638) at /usr/src/debug/php-5.6.8/Zend/zend_dtrace.c:73 #14 0x00007f2b7f5cdd4d in nr_php_execute_enabled () at /home/hudson/slave-workspace/workspace/PHP_Release_Agent/label/centos5-64-nrcamp/agent/php_execute.c:1099 #15 0x00007f2b7f5ce362 in nr_php_execute () at /home/hudson/slave-workspace/workspace/PHP_Release_Agent/label/centos5-64-nrcamp/agent/php_execute.c:1210 #16 0x000000000063e6bc in zend_do_fcall_common_helper_SPEC (execute_data=<value optimized out>) at /usr/src/debug/php-5.6.8/Zend/zend_vm_execute.h:592 #17 0x000000000062dbe8 in execute_ex (execute_data=0x7f2b95bb8448) at /usr/src/debug/php-5.6.8/Zend/zend_vm_execute.h:363 #18 0x00000000005af8ce in dtrace_execute_ex (execute_data=0x7f2b95bb8448) at /usr/src/debug/php-5.6.8/Zend/zend_dtrace.c:73 #19 0x00007f2b7f5cdf75 in nr_php_execute_enabled () at /home/hudson/slave-workspace/workspace/PHP_Release_Agent/label/centos5-64-nrcamp/agent/php_execute.c:947 #20 0x00007f2b7f5ce362 in nr_php_execute () at /home/hudson/slave-workspace/workspace/PHP_Release_Agent/label/centos5-64-nrcamp/agent/php_execute.c:1210 #21 0x000000000062d581 in ZEND_INCLUDE_OR_EVAL_SPEC_TMP_HANDLER (execute_data=0x7f2b95bb8150) at /usr/src/debug/php-5.6.8/Zend/zend_vm_execute.h:8390 #22 0x000000000062dbe8 in execute_ex (execute_data=0x7f2b95bb8150) at /usr/src/debug/php-5.6.8/Zend/zend_vm_execute.h:363 #23 0x00000000005af8ce in dtrace_execute_ex (execute_data=0x7f2b95bb8150) at /usr/src/debug/php-5.6.8/Zend/zend_dtrace.c:73 #24 0x00007f2b7f5cdf75 in nr_php_execute_enabled () at /home/hudson/slave-workspace/workspace/PHP_Release_Agent/label/centos5-64-nrcamp/agent/php_execute.c:947 #25 0x00007f2b7f5ce362 in nr_php_execute () at /home/hudson/slave-workspace/workspace/PHP_Release_Agent/label/centos5-64-nrcamp/agent/php_execute.c:1210 #26 0x00000000005bef5c in zend_execute_scripts (type=8, retval=0x0, file_count=3) at /usr/src/debug/php-5.6.8/Zend/zend.c:1341 #27 0x000000000055d77a in php_execute_script (primary_file=0x7fff6856ab30) at /usr/src/debug/php-5.6.8/main/main.c:2597 #28 0x0000000000665ae3 in do_cli (argc=4, argv=0x265c9d0) at /usr/src/debug/php-5.6.8/sapi/cli/php_cli.c:994 #29 0x00000000006662e8 in main (argc=4, argv=0x265c9d0) at /usr/src/debug/php-5.6.8/sapi/cli/php_cli.c:1378 ------------------------------------------------------------------------ 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=64827 -- Edit this bug report at https://bugs.php.net/bug.php?id=64827&edit=1