[horde] PHP7 : Memory eater bug? -> infinite recursion, getting closer :)
Torben Dannhauer
torben at dannhauer.info
Fri Feb 17 20:02:03 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 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.
Thanks!
To sum up:
a) we should investigate and fix it that returned value of
getSyncNotepads() is _not_empty.
>
> 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.
b) I already log the usernames of all affected accounts and will try
to fix it on this side als well.
Thanks for your valuable input today!
regards,
Torben
>
>
>> Thanks for your help,
>> Torben
>>
>>
>>
>>
>
More information about the horde
mailing list