[horde] PHP7 : Memory eater bug? -> infinite recursion, getting closer :)
Michael J Rubinsky
mrubinsk at horde.org
Fri Feb 17 14:44:55 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 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?
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:
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 :)
> 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
-------------- 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/86042445/attachment.bin>
More information about the horde
mailing list