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

Torben Dannhauer torben at dannhauer.info
Fri Feb 17 17:11:19 UTC 2017 

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] => )

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?

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

More information about the horde mailing list