[BUG]: Segfault coming from Phalcon\Mvc\Model\Query::_getQualified #15555

StudioMaX · 2021-06-25T11:35:16Z

Describe the bug
Periodically, we have a strange bug on our production, when during the execution of a simple SELECT query through the query builder there is segfault. This is somehow related to Query::_getQualified and Zephir.

To Reproduce
It will be problematic to provide the code of the Models since they are too complex, but for example, the Query Builder is:

$qb = $this->modelsManager->createBuilder();
$qb
    ->from(['pi' => PurchasedItem::class])
    ->join(Order::class, '[pi].BasketRef = [o].BasketRef', 'o')
    ->where('[o].customer_id = :customer_id:', ['customer_id' => $this->getCustomer()->getId()])
;
$query = $qb->getQuery();
/** @var PurchasedItem[] $results */
$results = $query->execute();

Segfault occurs during the execute method.
Full trace:

Program received signal SIGSEGV, Segmentation fault.
zend_hash_index_find_bucket (h=0, ht=0x7f7325218e38) at ./Zend/zend_hash.c:693
693     ./Zend/zend_hash.c: No such file or directory.
(gdb) bt
#0  zend_hash_index_find_bucket (h=0, ht=0x7f7325218e38) at ./Zend/zend_hash.c:693
#1  zend_hash_index_find (h=0, ht=0x7f7325218e38) at ./Zend/zend_hash.c:2263
#2  zend_hash_index_find (ht=ht@entry=0x7f7325218e38, h=0) at ./Zend/zend_hash.c:2247
#3  0x00007f7346aef9dc in zend_hash_index_exists (h=<optimized out>, ht=0x7f7325218e38) at /usr/include/php/20190902/Zend/zend_hash.h:224
#4  zephir_array_isset (arr=<optimized out>, index=0x7fffcc3ce4a0) at ./build/php7/64bits/phalcon.zep.c:6309
#5  0x00007f7346d8373a in zim_Phalcon_Mvc_Model_Query__getQualified (execute_data=<optimized out>, return_value=0x7fffcc3cecd0) at ./build/php7/64bits/phalcon.zep.c:149052
#6  0x000055d0171530d2 in zend_call_function (fci=fci@entry=0x7fffcc3ce9c0, fci_cache=<optimized out>) at ./Zend/zend_execute_API.c:833
#7  0x00007f7346aec45b in zephir_call_user_function (object_pp=object_pp@entry=0x7f734ac13990, obj_ce=obj_ce@entry=0x55d0181875a0, type=type@entry=zephir_fcall_method, function_name=function_name@entry=0x7fffcc3cebb0, retval_ptr=retval_ptr@entry=0x7fffcc3cecd0, cache_entry=0x7fffcc3ce968, cache_entry@entry=0x0, cache_slot=<optimized out>, param_count=<optimized out>, params=0x7fffcc3cf300) at ./build/php7/64bits/phalcon.zep.c:8731
#8  0x00007f7346aeccbb in zephir_call_class_method_aparams (return_value=0x7fffcc3cecd0, ce=0x55d0181875a0, type=zephir_fcall_method, object=0x7f734ac13990, method_name=0x7f7346fe5c7e "_getqualified", method_len=<optimized out>, cache_entry=0x0, cache_slot=476, param_count=1, params=0x7fffcc3cf300) at ./build/php7/64bits/phalcon.zep.c:8869
#9  0x00007f7346dea727 in zim_Phalcon_Mvc_Model_Query__getExpression (execute_data=<optimized out>, return_value=0x7fffcc3cf7e0) at /usr/include/php/20190902/Zend/zend_types.h:441
#10 0x000055d0171530d2 in zend_call_function (fci=fci@entry=0x7fffcc3cf510, fci_cache=<optimized out>) at ./Zend/zend_execute_API.c:833
#11 0x00007f7346aec45b in zephir_call_user_function (object_pp=object_pp@entry=0x7f734ac13930, obj_ce=obj_ce@entry=0x55d0181875a0, type=type@entry=zephir_fcall_method, function_name=function_name@entry=0x7fffcc3cf700, retval_ptr=retval_ptr@entry=0x7fffcc3cf7e0, cache_entry=0x7fffcc3cf4b8, cache_entry@entry=0x0, cache_slot=<optimized out>, param_count=<optimized out>, params=0x7fffcc3cfe50) at ./build/php7/64bits/phalcon.zep.c:8731
#12 0x00007f7346aeccbb in zephir_call_class_method_aparams (return_value=0x7fffcc3cf7e0, ce=0x55d0181875a0, type=zephir_fcall_method, object=0x7f734ac13930, method_name=0x7f7346fe4075 "_getexpression", method_len=<optimized out>, cache_entry=0x0, cache_slot=474, param_count=2, params=0x7fffcc3cfe50) at ./build/php7/64bits/phalcon.zep.c:8869
#13 0x00007f7346dea81b in zim_Phalcon_Mvc_Model_Query__getExpression (execute_data=<optimized out>, return_value=0x7fffcc3d0770) at /usr/include/php/20190902/Zend/zend_types.h:441
#14 0x000055d0171530d2 in zend_call_function (fci=fci@entry=0x7fffcc3d0050, fci_cache=<optimized out>) at ./Zend/zend_execute_API.c:833
#15 0x00007f7346aec45b in zephir_call_user_function (object_pp=object_pp@entry=0x7f734ac138d0, obj_ce=obj_ce@entry=0x55d0181875a0, type=type@entry=zephir_fcall_method, function_name=function_name@entry=0x7fffcc3d0240, retval_ptr=retval_ptr@entry=0x7fffcc3d0770, cache_entry=0x7fffcc3cfff8, cache_entry@entry=0x7fffcc3d0390, cache_slot=<optimized out>, param_count=<optimized out>, params=0x7fffcc3d0b00) at ./build/php7/64bits/phalcon.zep.c:8731
#16 0x00007f7346aeccbb in zephir_call_class_method_aparams (return_value=0x7fffcc3d0770, ce=0x55d0181875a0, type=zephir_fcall_method, object=0x7f734ac138d0, method_name=0x7f7346fe4075 "_getexpression", method_len=<optimized out>, cache_entry=0x7fffcc3d0390, cache_slot=474, param_count=1, params=0x7fffcc3d0b00) at ./build/php7/64bits/phalcon.zep.c:8869
#17 0x00007f7346d4c62e in zim_Phalcon_Mvc_Model_Query__getJoins (execute_data=<optimized out>, return_value=0x7fffcc3d13c0) at /usr/include/php/20190902/Zend/zend_types.h:441
#18 0x000055d0171530d2 in zend_call_function (fci=fci@entry=0x7fffcc3d0d10, fci_cache=<optimized out>) at ./Zend/zend_execute_API.c:833
#19 0x00007f7346aec45b in zephir_call_user_function (object_pp=object_pp@entry=0x7f734ac13880, obj_ce=obj_ce@entry=0x55d0181875a0, type=type@entry=zephir_fcall_method, function_name=function_name@entry=0x7fffcc3d0f00, retval_ptr=retval_ptr@entry=0x7fffcc3d13c0, cache_entry=cache_entry@entry=0x0, cache_slot=<optimized out>, param_count=<optimized out>, params=0x7fffcc3d19e0) at ./build/php7/64bits/phalcon.zep.c:8731
#20 0x00007f7346aeccbb in zephir_call_class_method_aparams (return_value=0x7fffcc3d13c0, ce=0x55d0181875a0, type=zephir_fcall_method, object=0x7f734ac13880, method_name=0x7f7346fe678e "_getjoins", method_len=<optimized out>, cache_entry=0x0, cache_slot=484, param_count=1, params=0x7fffcc3d19e0) at ./build/php7/64bits/phalcon.zep.c:8869
#21 0x00007f7346de483c in zim_Phalcon_Mvc_Model_Query__prepareSelect (execute_data=<optimized out>, return_value=0x7fffcc3d1ea0) at /usr/include/php/20190902/Zend/zend_types.h:441
#22 0x000055d0171530d2 in zend_call_function (fci=fci@entry=0x7fffcc3d1bd0, fci_cache=<optimized out>) at ./Zend/zend_execute_API.c:833
#23 0x00007f7346aec45b in zephir_call_user_function (object_pp=object_pp@entry=0x7f734ac13830, obj_ce=obj_ce@entry=0x55d0181875a0, type=type@entry=zephir_fcall_method, function_name=function_name@entry=0x7fffcc3d1dc0, retval_ptr=retval_ptr@entry=0x7fffcc3d1ea0, cache_entry=0x7fffcc3d1b78, cache_entry@entry=0x0, cache_slot=<optimized out>, param_count=<optimized out>, params=0x7fffcc3d1f20) at ./build/php7/64bits/phalcon.zep.c:8731
#24 0x00007f7346aeccbb in zephir_call_class_method_aparams (return_value=0x7fffcc3d1ea0, ce=0x55d0181875a0, type=zephir_fcall_method, object=0x7f734ac13830, method_name=0x7f7346fe6891 "_prepareselect", method_len=<optimized out>, cache_entry=0x0, cache_slot=479, param_count=0, params=0x7fffcc3d1f20) at ./build/php7/64bits/phalcon.zep.c:8869
#25 0x00007f7346e33be8 in zim_Phalcon_Mvc_Model_Query_parse (execute_data=<optimized out>, return_value=0x7fffcc3d2490) at /usr/include/php/20190902/Zend/zend_types.h:441
#26 0x000055d0171530d2 in zend_call_function (fci=fci@entry=0x7fffcc3d2100, fci_cache=<optimized out>) at ./Zend/zend_execute_API.c:833
#27 0x00007f7346aec45b in zephir_call_user_function (object_pp=object_pp@entry=0x7f734ac137e0, obj_ce=obj_ce@entry=0x55d0181875a0, type=type@entry=zephir_fcall_method, function_name=function_name@entry=0x7fffcc3d22f0, retval_ptr=retval_ptr@entry=0x7fffcc3d2490, cache_entry=0x7fffcc3d20a8, cache_entry@entry=0x0, cache_slot=<optimized out>, param_count=<optimized out>, params=0x7fffcc3d2530) at ./build/php7/64bits/phalcon.zep.c:8731
#28 0x00007f7346aeccbb in zephir_call_class_method_aparams (return_value=0x7fffcc3d2490, ce=0x55d0181875a0, type=zephir_fcall_method, object=0x7f734ac137e0, method_name=0x7f7346fe0741 "parse", method_len=<optimized out>, cache_entry=0x0, cache_slot=0, param_count=0, params=0x7fffcc3d2530) at ./build/php7/64bits/phalcon.zep.c:8869
#29 0x00007f7346d5c73f in zim_Phalcon_Mvc_Model_Query_execute (execute_data=<optimized out>, return_value=0x7f734ac137a0) at /usr/include/php/20190902/Zend/zend_types.h:441
#30 0x000055d0171e7c3a in ZEND_DO_FCALL_SPEC_RETVAL_USED_HANDLER () at ./Zend/zend_vm_execute.h:1730
#31 execute_ex (ex=0x7f7325218e38) at ./Zend/zend_vm_execute.h:53901
#32 0x000055d0171531f6 in zend_call_function (fci=fci@entry=0x7fffcc3d2720, fci_cache=<optimized out>, fci_cache@entry=0x7fffcc3d2700) at ./Zend/zend_execute_API.c:820
#33 0x00007f7346aea883 in zephir_call_user_func_array_noex (return_value=0x7fffcc3d32d0, handler=<optimized out>, params=0x7fffcc3d27c0) at ./build/php7/64bits/phalcon.zep.c:8927
#34 0x00007f7346b331ec in zephir_call_user_func_array (params=0x7fffcc3d27c0, handler=0x7fffcc3d27d0, return_value=0x7fffcc3d32d0) at ./build/php7/64bits/phalcon.zep.c:49056
#35 zim_Phalcon_Dispatcher_AbstractDispatcher_callActionMethod (execute_data=<optimized out>, return_value=0x7fffcc3d32d0) at ./build/php7/64bits/phalcon.zep.c:49056
#36 0x000055d0171530d2 in zend_call_function (fci=fci@entry=0x7fffcc3d2a10, fci_cache=<optimized out>) at ./Zend/zend_execute_API.c:833
#37 0x00007f7346aec45b in zephir_call_user_function (object_pp=object_pp@entry=0x7f734ac13220, obj_ce=obj_ce@entry=0x55d01815a1b0, type=type@entry=zephir_fcall_method, function_name=function_name@entry=0x7fffcc3d2c00, retval_ptr=retval_ptr@entry=0x7fffcc3d32d0, cache_entry=cache_entry@entry=0x7fffcc3d2dc8, cache_slot=<optimized out>, param_count=<optimized out>, params=0x7fffcc3d3430) at ./build/php7/64bits/phalcon.zep.c:8731
#38 0x00007f7346aeccbb in zephir_call_class_method_aparams (return_value=0x7fffcc3d32d0, ce=0x55d01815a1b0, type=zephir_fcall_method, object=0x7f734ac13220, method_name=0x7f7346fe61be "callactionmethod", method_len=<optimized out>, cache_entry=0x7fffcc3d2dc8, cache_slot=0, param_count=3, params=0x7fffcc3d3430) at ./build/php7/64bits/phalcon.zep.c:8869
#39 0x00007f7346dbaed6 in zim_Phalcon_Dispatcher_AbstractDispatcher_dispatch (execute_data=<optimized out>, return_value=0x7fffcc3d39d0) at /usr/include/php/20190902/Zend/zend_types.h:441
#40 0x000055d0171530d2 in zend_call_function (fci=fci@entry=0x7fffcc3d3630, fci_cache=<optimized out>) at ./Zend/zend_execute_API.c:833
#41 0x00007f7346aec45b in zephir_call_user_function (object_pp=object_pp@entry=0x7fffcc3d3940, obj_ce=obj_ce@entry=0x55d01815a1b0, type=type@entry=zephir_fcall_method, function_name=function_name@entry=0x7fffcc3d3820, retval_ptr=retval_ptr@entry=0x7fffcc3d39d0, cache_entry=cache_entry@entry=0x0, cache_slot=<optimized out>, param_count=<optimized out>, params=0x7fffcc3d3cb0) at ./build/php7/64bits/phalcon.zep.c:8731
#42 0x00007f7346aeccbb in zephir_call_class_method_aparams (return_value=0x7fffcc3d39d0, ce=0x55d01815a1b0, type=zephir_fcall_method, object=0x7fffcc3d3940, method_name=0x7f7346fe5e2c "dispatch", method_len=<optimized out>, cache_entry=0x0, cache_slot=0, param_count=0, params=0x7fffcc3d3cb0) at ./build/php7/64bits/phalcon.zep.c:8869
#43 0x00007f7346ef1040 in zim_Phalcon_Mvc_Application_handle (execute_data=<optimized out>, return_value=0x7f734ac13170) at /usr/include/php/20190902/Zend/zend_types.h:441
#44 0x000055d0171e7c3a in ZEND_DO_FCALL_SPEC_RETVAL_USED_HANDLER () at ./Zend/zend_vm_execute.h:1730
#45 execute_ex (ex=0x7f7325218e38) at ./Zend/zend_vm_execute.h:53901
#46 0x000055d0171e8aa1 in zend_execute (op_array=0x7f734ac571c0, return_value=<optimized out>) at ./Zend/zend_vm_execute.h:57993
#47 0x000055d017161af3 in zend_execute_scripts (type=type@entry=8, retval=0x7f734ac130e0, retval@entry=0x0, file_count=file_count@entry=3) at ./Zend/zend.c:1679
#48 0x000055d017100ec0 in php_execute_script (primary_file=<optimized out>) at ./main/main.c:2634
#49 0x000055d016fc9789 in main (argc=<optimized out>, argv=<optimized out>) at ./sapi/fpm/fpm/fpm_main.c:1939
(gdb)

I was able to track the last executed methods from the trace, which led to line 211 (which is #4 in the trace):

cphalcon/phalcon/Mvc/Model/Query.zep

Lines 206 to 215 in ae581a3

    
                   let nestingLevel = this->nestingLevel; 
        
                   /** 
        
                    * Check if the qualified name is a column alias 
        
                    */ 
        
                   if isset this->sqlColumnAliases[nestingLevel] { 
        
                       let sqlColumnAliases = this->sqlColumnAliases[nestingLevel]; 
        
                   } else { 
        
                       let sqlColumnAliases = []; 
        
                   }

Apparently there is something wrong with an array this->sqlColumnAliases. Since I did not find any obvious problems with this method and my code I added some debugging in this method (dirty hack, don't judge me) :

--- a/phalcon/Mvc/Model/Query.zep	(revision ae581a3587f8dac9e87b7ff92f787a1b6067d149)
+++ b/phalcon/Mvc/Model/Query.zep	(date 1624603932977)
@@ -198,12 +198,19 @@
     {
         var columnName, nestingLevel, sqlColumnAliases, metaData, sqlAliases,
             source, sqlAliasesModelsInstances, realColumnName, columnDomain,
-            model, models, columnMap, hasModel, className;
+            model, models, columnMap, hasModel, className, debugVars, debugsqlColumnAliases, debugnestingLevel;
         int number;
 
         let columnName = expr["name"];
 
         let nestingLevel = this->nestingLevel;
+        ob_start();
+        let debugsqlColumnAliases = ["sqlColumnAliases", this->sqlColumnAliases];
+        let debugnestingLevel = ["nestingLevel", nestingLevel];
+        var_dump(debugsqlColumnAliases);
+        var_dump(debugnestingLevel);
+        let debugVars = ob_get_clean();
+        trigger_error("Debug of _getQualified: " . debugVars, E_USER_WARNING);
 
         /**
          * Check if the qualified name is a column alias

After that, by logs, I realized that almost always this method is executed successfully, and mostly these variables are as follows:

PHP Warning:  Debug of _getQualified: array(2) {
  [0]=>
  string(16) "sqlColumnAliases"
  [1]=>
  array(0) {
  }
}
array(2) {
  [0]=>
  string(12) "nestingLevel"
  [1]=>
  int(0)
}

So, the this->sqlColumnAliases property is always an empty array. But in the case of segfault, this array contains a single nested empty array (actually this may not be true, since this is not a valid php code, but a C/extension, so there may be invalid pointer or something else):

PHP Warning:  Debug of _getQualified: array(2) {
  [0]=>
  string(16) "sqlColumnAliases"
  [1]=>
  array(1) {
    [0]=>
    array(0) {
    }
  }
}
array(2) {
  [0]=>
  string(12) "nestingLevel"
  [1]=>
  int(0)
}

Currently I tested the extension from the Packagecloud, Phalcon 4.1.2. I suggested that this error may be related to Zephir. Therefore, I tried to compile manually and see how the same code will work (I have not changed anything in my PHP project).

PHP 7.4, Phalcon 4.1.2, PSR 1.0.1, Zephir Parser 1.3.6, Zephir 0.12.21 - segfault
PHP 7.4, Phalcon 4.1.2, PSR 1.0.1, Zephir Parser 1.3.6, Zephir 0.13.0 - segfault
PHP 7.4, Phalcon 4.1.2, PSR 1.0.1, Zephir Parser 1.3.6, Zephir 0.13.1 - segfault
PHP 7.4, Phalcon 4.1.2, PSR 1.0.1, Zephir Parser 1.3.6, Zephir 0.13.2 - segfault
PHP 7.4, Phalcon 4.1.2, PSR 1.0.1, Zephir Parser 1.3.6, Zephir 0.13.3 - Works!

As I understood, there was some kind of bug with the Zephir 0.12.21 (used by default with Phalcon 4.1.2), this bug was still in Zephir 0.13.2, but was fixed in 0.13.3. This led me to commits zephir-lang/zephir@0ca7737 and zephir-lang/zephir@0ca7737 from PR zephir-lang/zephir#2222, not sure if they are related.

So, please confirm my guess:
There is a bug in Phalcon 4.1.2 due to Zephir 0.12.21 (current default), and this bug was fixed by Zephir 0.13.3?

Expected behavior
Segfault does not occur.
If my guesses are right, then need to either backport the changes from Zephir 0.13.3 to 0.12.x, and then use Zephir 0.12.x in the current stable Phalcon 4.1.x. Or switch to Zephir 0.13.x in Phalcon 4.1.x.
I think that this is an important bug to fix it in the current/latest stable version of Phalcon 4.1.x, and not to postpone it up to 5.0 which is still in alpha and is unknown when it will be released.

Details

Phalcon version: 4.1.2
PHP Version: 7.4.20
Operating System: Docker / Debian 10 (buster)
Installation type: Compiling from source AND installing via package manager
Zephir version (if any): 0.12.21-8a412a1 (used by default in extension)
Server: Apache
Other related info (Database, table schema):

The text was updated successfully, but these errors were encountered:

StudioMaX · 2021-07-01T10:12:47Z

Could you please at least confirm if Phalcon 4.1.2 can be used with Zephir 0.13.5? Or no one checked this case (even with CI/tests) and there is no guarantee of compatibility?

Jeckerson · 2021-09-09T18:41:20Z

@StudioMaX ~~Did you tried to compile with Zephir 0.13.x?~~

Yes you tried. Zephir v0.13.x is supported for PHP >= 7.4, so if you have compatible PHP version, then you can compile Phalcon v4 with it.

StudioMaX · 2021-09-09T18:54:29Z

Yes, we have been using this in production since July. And yes, we use PHP 7.4. In fact, we had no choice, since this segfault occurred every few minutes.

Version => 4.1.2
Build Date => Jul 2 2021 11:53:58
Powered by Zephir => Version 0.13.5-1232784

niden · 2021-09-09T18:56:25Z

@StudioMaX This is really outstanding bug hunting!! Kudos!

Jeckerson · 2021-09-09T19:02:41Z

Closing, as it won't be fixed in Zephir v0.12.x due mass changes in v0.13.x. Already fixed in Phalcon v5.

StudioMaX added bug A bug report status: unverified Unverified labels Jun 25, 2021

Jeckerson added external dependency This issue depends on external issue to be resolved. 5.0 The issues we want to solve in the 5.0 release and removed status: unverified Unverified labels Sep 9, 2021

Jeckerson closed this as completed Sep 9, 2021

Jeckerson mentioned this issue Sep 9, 2021

[BUG]: Failing to execute a code that fetches 3000 records from the MySQL Database. #15653

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[BUG]: Segfault coming from Phalcon\Mvc\Model\Query::_getQualified #15555

[BUG]: Segfault coming from Phalcon\Mvc\Model\Query::_getQualified #15555

StudioMaX commented Jun 25, 2021

StudioMaX commented Jul 1, 2021

Jeckerson commented Sep 9, 2021 •

edited

Loading

StudioMaX commented Sep 9, 2021

niden commented Sep 9, 2021

Jeckerson commented Sep 9, 2021

[BUG]: Segfault coming from Phalcon\Mvc\Model\Query::_getQualified #15555

[BUG]: Segfault coming from Phalcon\Mvc\Model\Query::_getQualified #15555

Comments

StudioMaX commented Jun 25, 2021

StudioMaX commented Jul 1, 2021

Jeckerson commented Sep 9, 2021 • edited Loading

StudioMaX commented Sep 9, 2021

niden commented Sep 9, 2021

Jeckerson commented Sep 9, 2021

Jeckerson commented Sep 9, 2021 •

edited

Loading