[horde] PHP7 : Memory eater bug? -> infinite recursion, getting closer :)

Michael J Rubinsky mrubinsk at horde.org
Fri Feb 17 18:38:15 UTC 2017 

Quoting Torben Dannhauer <torben at dannhauer.info>:

> Zitat von Michael J Rubinsky <mrubinsk at horde.org>:
>
>> Quoting Torben Dannhauer <torben at dannhauer.info>:
>>
>>> Zitat von Michael J Rubinsky <mrubinsk at horde.org>:
>>>
>>>> Quoting Torben Dannhauer <torben at dannhauer.info>:
>>>>
>>>>> Zitat von Torben Dannhauer <torben at dannhauer.info>:
>>>>>
>>>>>> Hi,
>>>>>>
>>>>>>
>>>>>>
>>>>>> Yesterday I discovered a lot of errors thrown by PHP7 due to my memory
>>>>>> limit.
>>>>>>
>>>>>>
>>>>>>
>>>>>> I get lots of errors like this:
>>>>>>
>>>>>> <snip>
>>>>>>
>>>>>> [13-Feb-2017 09:57:35 Europe/Berlin] PHP Fatal error:  Allowed  
>>>>>> memory size
>>>>>> of 1073741824 bytes exhausted (tried to allocate 20480 bytes) in
>>>>>> /var/www/torben/web/ssl-dannhauer.de/horde/mnemo/lib/Mnemo.php  
>>>>>> on line 537
>>>>>>
>>>>>> [13-Feb-2017 09:57:35 Europe/Berlin] PHP Fatal error:  Allowed  
>>>>>> memory size
>>>>>> of 1073741824 bytes exhausted (tried to allocate 20480 bytes) in
>>>>>> /usr/share/php/Horde/ErrorHandler.php on line 193
>>>>>>
>>>>>> [13-Feb-2017 09:58:08 Europe/Berlin] PHP Fatal error:  Allowed  
>>>>>> memory size
>>>>>> of 1073741824 bytes exhausted (tried to allocate 20480 bytes) in
>>>>>> /var/www/torben/web/ssl-dannhauer.de/horde/mnemo/lib/Mnemo.php  
>>>>>> on line 537
>>>>>>
>>>>>> [13-Feb-2017 09:58:08 Europe/Berlin] PHP Fatal error:  Allowed  
>>>>>> memory size
>>>>>> of 1073741824 bytes exhausted (tried to allocate 20480 bytes) in
>>>>>> /usr/share/php/Horde/ErrorHandler.php on line 193
>>>>>>
>>>>>> <snap>
>>>>>>
>>>>>>
>>>>>>
>>>>>> It doesn't matter whether my limit is configured as 512M, 2G or  
>>>>>> 3G. Anyway,
>>>>>> a limit exceed in that order of memory is very likely to be a bug.
>>>>>>
>>>>>> Unfortunatly I do not have a clue how to start debugging here.  
>>>>>> The System
>>>>>> itself shows of course only the processes, not the memory consumption of
>>>>>> every running script.
>>>>>>
>>>>>>
>>>>>>
>>>>>> Any hints whjere to start?
>>>>>>
>>>>>>
>>>>>>
>>>>>> Many thanks,
>>>>>>
>>>>>> Torben
>>>>>>
>>>>>
>>>>>
>>>>>
>>>>> I'm getting closer to the problem.
>>>>>
>>>>> I installed xdebug to dive deeper into the issue and discovered  
>>>>> that the error does not longer occur as long als xdebug is  
>>>>> loaded into PHP.
>>>>> Screening the tons of logs produced by xdebug, I sawthat xedebug  
>>>>> cancels the execution due to the max_nesting level. So the error  
>>>>> still DOES occur, but is catched by xdebug and announced in the  
>>>>> loggs with different message.
>>>>> Here is the full log, it indicates an endless recursion in mnemo  
>>>>> - whit fits perfect to the picture of this issue:
>>>>>
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP Fatal error:  Maximum  
>>>>> function nesting level of '256' reached, aborting! in  
>>>>> /usr/share/php/Horde/ErrorHandler.php on line 193
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP Stack trace:
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP   1. {main}()  
>>>>> <webroot>/horde/rpc.php:0
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP   2.  
>>>>> Horde_Rpc_ActiveSync->getResponse() <webroot>/horde/rpc.php:160
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP   3.  
>>>>> Horde_ActiveSync->handleRequest()  
>>>>> /usr/share/php/Horde/Rpc/ActiveSync.php:143
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP   4.  
>>>>> Horde_ActiveSync_Request_Base->handle()  
>>>>> /usr/share/php/Horde/ActiveSync.php:834
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP   5.  
>>>>> Horde_ActiveSync_Request_Ping->_handle()  
>>>>> /usr/share/php/Horde/ActiveSync/Request/Base.php:253
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP   6.  
>>>>> Horde_ActiveSync_Collections->pollForChanges()  
>>>>> /usr/share/php/Horde/ActiveSync/Request/Ping.php:222
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP   7.  
>>>>> Horde_ActiveSync_Collections->getCollectionChangeCount()  
>>>>> /usr/share/php/Horde/ActiveSync/Collections.php:1222
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP   8.  
>>>>> Horde_ActiveSync_Collections->getCollectionChanges()  
>>>>> /usr/share/php/Horde/ActiveSync/Collections.php:1417
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP   9.  
>>>>> Horde_ActiveSync_State_Base->getChanges()  
>>>>> /usr/share/php/Horde/ActiveSync/Collections.php:1401
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP  10.  
>>>>> Horde_Core_ActiveSync_Driver->getServerChanges()  
>>>>> /usr/share/php/Horde/ActiveSync/State/Base.php:437
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP  11.  
>>>>> Horde_Core_ActiveSync_Connector->getChanges()  
>>>>> /usr/share/php/Horde/Core/ActiveSync/Driver.php:1112
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP  12.  
>>>>> Horde_Registry_Caller->getChangesByModSeq()  
>>>>> /usr/share/php/Horde/Core/ActiveSync/Connector.php:1098
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP  13.  
>>>>> Horde_Registry_Caller->__call()  
>>>>> /usr/share/php/Horde/Core/ActiveSync/Connector.php:1098
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP  14.  
>>>>> Horde_Registry->call() /usr/share/php/Horde/Registry/Caller.php:41
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP  15.  
>>>>> Horde_Registry->callByPackage()  
>>>>> /usr/share/php/Horde/Registry.php:1088
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP  16.  
>>>>> Mnemo_Api->getChangesByModSeq()  
>>>>> /usr/share/php/Horde/Registry.php:1131
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP  17.  
>>>>> Mnemo_Api->getChanges() <webroot>/horde/mnemo/lib/Api.php:135
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP  18.  
>>>>> Mnemo_Api->listBy() <webroot>/horde/mnemo/lib/Api.php:117
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP  19.  
>>>>> Mnemo_Api->listBy() <webroot>/horde/mnemo/lib/Api.php:158
>>>>> [.... and so on...]
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP 252.  
>>>>> Mnemo_Api->listBy() <webroot>/horde/mnemo/lib/Api.php:158
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP 253.  
>>>>> Mnemo_Api->listBy() <webroot>/horde/mnemo/lib/Api.php:158
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP 254.  
>>>>> Mnemo::getSyncNotepads() <webroot>/horde/mnemo/lib/Api.php:155
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP 255.  
>>>>> Horde_Prefs->getValue() <webroot>/horde/mnemo/lib/Mnemo.php:538
>>>>> [16-Feb-2017 13:20:50 Europe/Berlin] PHP 256.  
>>>>> Horde_Prefs->_getScope() /usr/share/php/Horde/Prefs.php:289
>>>>>
>>>>> I'm happy to get any hint what might be the reason. I assume  
>>>>> something to do with PHP7 ;)
>>>>
>>>> Can you see what Mnemo::getSyncNotepads(); returns? Easiest way  
>>>> would be to use admin->phpshell from within horde, be sure to  
>>>> choose the Mnemo scope from the drop down menu.
>>>>
>>>
>>> Oh, have never thought to use the Horde build in shell to debug :)
>>> Anyway, I enhanced the loggin in the file since not every  
>>> access/client triogfgers the issue, it happens only occassionally.
>>>
>>> The function  listBy($action, $timestamp, $notepad = null, $end =  
>>> null, $isModSeq = false)
>>> if called with the parameters action:add timestamp:50855 notepad:  
>>> end:51055 isModSeq:1
>>> in the recursive loop. The queried array is then.
>>> Array
>>> (
>>>   [0] =>
>>> )
>>>
>>> What is the intented logic if an empty array is returned?
>>
>> First, I'm assuming that the above parameters were supplied to the  
>> function, when it's called from line 158?
>
> Yes, I extenced the function to this:
>  public function listBy($action, $timestamp, $notepad = null, $end =  
> null, $isModSeq = false)
>     {
> Horde::log('action:'.$action.' timestamp:'.$timestamp.'  
> notepad:'.$notepad.' end:'.$end.' isModSeq:'.$isModSeq, 'ERR');
>         /* Make sure we have a valid notepad. */
>         if (empty($notepad)) {
>             $notepads = Mnemo::getSyncNotepads();
> Horde::log('notepads: '.print_r($notepads, true) ,'ERR');
>             $results = array();
>             foreach ($notepads as $notepad) {
>                 $results = array_merge($results,  
> $this->listBy($action, $timestamp, $notepad, $end, $isModSeq));
>             }
>             return $results;
>         }
>
>         $filter = array(array('op' => '=', 'field' => 'action',  
> 'value' => $action));
>         if (!empty($end) && !$isModSeq) {
>             $filter[] = array('op' => '<', 'field' => 'ts', 'value' => $end);
>         }
>         $history = $GLOBALS['injector']->getInstance('Horde_History');
>         if (!$isModSeq) {
>             $histories = $history->getByTimestamp('>', $timestamp,  
> $filter, 'mnemo:' . $notepad);
>         } else {
>             $histories = $history->getByModSeq($timestamp, $end,  
> $filter, 'mnemo:' . $notepad);
>         }
>
>         // Strip leading mnemo:username:.
>         return preg_replace('/^([^:]*:){2}/', '', array_keys($histories));
>     }
>
> The corresponding log in the endless loop is:
> <snip>
> 2017-02-17T13:38:08+01:00 ERR: HORDE [mnemo] action:add  
> timestamp:50855 notepad: end:51055 isModSeq:1 [pid 29265 on line 153  
> of "<webroot>/horde/mnemo/lib/Api.php"]
> 2017-02-17T13:38:08+01:00 ERR: HORDE [mnemo] notepads: Array
> (
>     [0] =>
> )
>  [pid 29265 on line 157 of "<webroot>/horde/mnemo/lib/Api.php"]
> 2017-02-17T13:38:08+01:00 ERR: HORDE [mnemo] action:add  
> timestamp:50855 notepad: end:51055 isModSeq:1 [pid 29265 on line 153  
> of "<webroot>/horde/mnemo/lib/Api.php"]
> 2017-02-17T13:38:08+01:00 ERR: HORDE [mnemo] notepads: Array
> (
>     [0] =>
> )
>  [pid 29265 on line 157 of "<webroot>/horde/mnemo/lib/Api.php"]
> 2017-02-17T13:38:08+01:00 ERR: HORDE [mnemo] action:add  
> timestamp:50855 notepad: end:51055 isModSeq:1 [pid 29265 on line 153  
> of "<webroot>/horde/mnemo/lib/Api.php"]
> 2017-02-17T13:38:08+01:00 ERR: HORDE [mnemo] notepads: Array
> (
>     [0] =>
> )
>  [pid 29265 on line 157 of "<webroot>/horde/mnemo/lib/Api.php"]
> <snap>
>
>
>>
>> An empty array would simply mean that there were no matches for  
>> that type of change. I.e., no new notes added, or changed etc...  
>> However, that's not technically an empty array, it's an array with  
>> an empty first element. That really shouldn't happen there. Even  
>> though that's not expected, if that gets sent back up to  
>> ActiveSync, it would probaly lead to some "item not found" message  
>> in the log, at least that's what it looks like should happen after  
>> a quick glance at the code.
>>
>> The bigger question is why is there no notepad being passed in the  
>> $notepad parameter? THAT is the cause of the loop:
>
> For sure. It seems (several users, the loog is flooded by the debug  
> messages and I have to seperate it be the PID), that it directly  
> called with an empty $notepad. So it seems _not_ to "become empty"  
> during the recursive iteration.
>
> The stack trace of the erroneous situation is:
>
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP Stack trace:
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP   1. {main}()  
> <webroot>/horde/rpc.php:0
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP   2.  
> Horde_Rpc_ActiveSync->getResponse() <webroot>/horde/rpc.php:160
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP   3.  
> Horde_ActiveSync->handleRequest()  
> /usr/share/php/Horde/Rpc/ActiveSync.php:143
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP   4.  
> Horde_ActiveSync_Request_Base->handle()  
> /usr/share/php/Horde/ActiveSync.php:834
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP   5.  
> Horde_ActiveSync_Request_Ping->_handle()  
> /usr/share/php/Horde/ActiveSync/Request/Base.php:253
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP   6.  
> Horde_ActiveSync_Collections->pollForChanges()  
> /usr/share/php/Horde/ActiveSync/Request/Ping.php:222
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP   7.  
> Horde_ActiveSync_Collections->getCollectionChangeCount()  
> /usr/share/php/Horde/ActiveSync/Collections.php:1222
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP   8.  
> Horde_ActiveSync_Collections->getCollectionChanges()  
> /usr/share/php/Horde/ActiveSync/Collections.php:1417
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP   9.  
> Horde_ActiveSync_State_Base->getChanges()  
> /usr/share/php/Horde/ActiveSync/Collections.php:1401
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  10.  
> Horde_Core_ActiveSync_Driver->getServerChanges()  
> /usr/share/php/Horde/ActiveSync/State/Base.php:437
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  11.  
> Horde_Core_ActiveSync_Connector->getChanges()  
> /usr/share/php/Horde/Core/ActiveSync/Driver.php:1112
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  12.  
> Horde_Registry_Caller->getChangesByModSeq()  
> /usr/share/php/Horde/Core/ActiveSync/Connector.php:1098
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  13.  
> Horde_Registry_Caller->__call()  
> /usr/share/php/Horde/Core/ActiveSync/Connector.php:1098
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  14. Horde_Registry->call()  
> /usr/share/php/Horde/Registry/Caller.php:41
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  15.  
> Horde_Registry->callByPackage() /usr/share/php/Horde/Registry.php:1088
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  16.  
> Mnemo_Api->getChangesByModSeq() /usr/share/php/Horde/Registry.php:1131
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  17.  
> Mnemo_Api->getChanges() <webroot>/horde/mnemo/lib/Api.php:135
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  18. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:117
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  19. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  20. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  21. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  22. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  23. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  24. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  25. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  26. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  27. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  28. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  29. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  30. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  31. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  32. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  33. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  34. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  35. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  36. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
> [17-Feb-2017 17:39:54 Europe/Berlin] PHP  37. Mnemo_Api->listBy()  
> <webroot>/horde/mnemo/lib/Api.php:161
>
>
>>
>> First entry into listBy with empty $notepad eventually causes the  
>> recursive call to listBy(). This is supposed to be called with the  
>> actual $notepad parameter obtained by iterating over the results of  
>> the Mnemo::getSyncNotepads() call.
>> My guess is that this is returning a corrupt, or at least some  
>> unexpected, value. That's why I asked for the return of that method  
>> :)
>>
>
> AS I wrote, the return of the Method Mnemo::getSyncNotepads() if  
> this faulty Array ( [0] => )

Ah. Sorry. I misunderstood your last email. I thought that was the  
return value of the listBY() call.


> I'll dive into every trace step and look whats causing the null notepad call.
>
> One further question: If  listBy(...) is not able to handle  
> $notepad==null correctly, why is null specified as default parameter  
> for "notepad?

listBy() is SUPPOSED to handle $notepad=null correctly. When that is  
the case, it loads all of the available notepads (the return from  
getSyncNotepads()) and then calls itself again once for each available  
notepad. The problem is THAT method is never supposed to return an  
empty value, and because it does, the same code path is executed over  
and over.

Off the top of my head, it sounds like it might be something wrong  
with their sync_notepads (or whatever it's called - I'm not in front  
of code at the moment) preference. You could try to re-set the value  
of this preference for one of the affected users to see if that helps.


> Thanks for your help,
> Torben
>
>
>
>
>
>>
>>> Thanks,
>>> Torben
>>>
>>>
>>>
>>>
>>>
>>>>
>>>>> Thanks,
>>>>> Torben
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> -- 
>>>>> Horde mailing list
>>>>> Frequently Asked Questions: http://horde.org/faq/
>>>>> To unsubscribe, mail: horde-unsubscribe at lists.horde.org
>>>>
>>>>
>>>>
>>>> -- 
>>>> mike
>>>> The Horde Project
>>>> http://www.horde.org
>>>> https://www.facebook.com/hordeproject
>>>> https://www.twitter.com/hordeproject
>>>
>>>
>>>
>>> -- 
>>> Horde mailing list
>>> Frequently Asked Questions: http://horde.org/faq/
>>> To unsubscribe, mail: horde-unsubscribe at lists.horde.org
>>
>>
>>
>> -- 
>> mike
>> The Horde Project
>> http://www.horde.org
>> https://www.facebook.com/hordeproject
>> https://www.twitter.com/hordeproject
>
>
>
> -- 
> Horde mailing list
> Frequently Asked Questions: http://horde.org/faq/
> To unsubscribe, mail: horde-unsubscribe at lists.horde.org



-- 
mike
The Horde Project
http://www.horde.org
https://www.facebook.com/hordeproject
https://www.twitter.com/hordeproject
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 3282 bytes
Desc: S/MIME Signature
URL: <https://lists.horde.org/archives/horde/attachments/20170217/46197378/attachment.bin>

More information about the horde mailing list