[horde] Maximum execution time of 29 seconds exceeded
Gian Franco Bagdadi Barcellini
gian at unicamp.br
Thu Aug 13 18:36:42 UTC 2015
Citando Gian Franco Bagdadi Barcellini <gian at unicamp.br>:
> Citando Michael J Rubinsky <mrubinsk at horde.org>:
>
>> Quoting Gian Franco Bagdadi Barcellini <gian at unicamp.br>:
>>
>>> Hi,
>>>
>>> I am having problems with timeout execution of apache/PHP process
>>> and cpu load rises high values (loop?)
>>> Process HTTP do not timeout, only php ($conf['max_exec_time'] = 29;);
>>
>>
>> This is too low for ActiveSync use. You need it to be AT LEAST as
>> long as the maximum heartbeat interval any of your clients might
>> use. The maximum for ActiveSync is something like 59 minutes.
>> Though this is a separate issue to the high CPU load.
>>
>>
>>
>>> Currently we have a base with approximately of 100 users activesync
>>>
>>> My versions and softwares are:
>>>
>>> Horde Groupware 5.2.10
>>> Horde_ActiveSync 2.28.6
>>>
>>> Apache 2.2.29 with mod_php
>>> PHP-5.6.10
>>> MySQL 5.6.20
>>>
>>> We have proxies with this configuration:
>>>
>>> # conexoes Mobile ActiveSync Microsoft
>>> ProxyPass /Microsoft-Server-ActiveSync
>>> https://xxxx.yyyy.br/Microsoft-Server-ActiveSync
>>> connectiontimeout=600 timeout=4000
>>> ProxyPassReverse /Microsoft-Server-ActiveSync
>>> https://xxxx.yyyy.br/Microsoft-Server-ActiveSync
>>>
>>> and ActiveSYnc:
>>>
>>> $conf['activesync']['params']['driverconfig'] = 'horde';
>>> $conf['activesync']['storage'] = 'Sql';
>>> $conf['activesync']['emailsync'] = true;
>>> $conf['activesync']['version'] = '14.1';
>>> $conf['activesync']['auth']['type'] = 'basic';
>>> $conf['activesync']['autodiscovery'] = 'user';
>>> $conf['activesync']['outlookdiscovery'] = false;
>>> $conf['activesync']['logging']['type'] = false;
>>> $conf['activesync']['ping']['heartbeatmin'] = 60;
>>> $conf['activesync']['ping']['heartbeatmax'] = 2700;
>>
>> This line is setting the maximum heartbeat to 2700 seconds == 45
>> minutes. You should have your max_execution be AT LEAST this long,
>> preferably a bit longer since it's possible for the actual
>> connection to need longer if changes are found at the very end of
>> the heartbeat.
>>
>>> $conf['activesync']['ping']['heartbeatdefault'] = 480;
>>> $conf['activesync']['ping']['deviceping'] = true;
>>> $conf['activesync']['ping']['waitinterval'] = 15;
>>> $conf['activesync']['enabled'] = true;
>>>
>>>
>>> I'm getting this errors quite often from log horde, in debug mode:
>>>
>>> ...
>>>
>>> 2015-08-11T16:39:45-03:00 NOTICE: HORDE PHP ERROR: Only variable
>>> references should be returned by reference [pid 26763 on line 111
>>> of "/usr/local/lib/php/Horde/ActiveSy nc/Imap/Message.php"]
>>> 26725 2015-08-11T16:39:45-03:00 DEBUG: HORDE 1.
>>> Horde_Rpc_ActiveSync->getResponse()
>>> /www/httpd-2.2.29/htdocs/horde-5.2.10/rpc.php:160
>>> 26726 2. Horde_ActiveSync->handleRequest()
>>> /usr/local/lib/php/Horde/Rpc/ActiveSync.php:143
>>> 26727 3. Horde_ActiveSync_Request_Base->handle()
>>> /usr/local/lib/php/Horde/ActiveSync.php:803
>>> 26728 4. Horde_ActiveSync_Request_Sync->_handle()
>>> /usr/local/lib/php/Horde/ActiveSync/Request/Base.php:253
>>> 26729 5. Horde_ActiveSync_Connector_Exporter->sendNextChange()
>>> /usr/local/lib/php/Horde/ActiveSync/Request/Sync.php:508
>>> 26730 6. Horde_ActiveSync_Connector_Exporter->_sendNextChange()
>>> /usr/local/lib/php/Horde/ActiveSync/Connector/Exporter.php:156
>>> 26731 7. Horde_Core_ActiveSync_Driver->getMessage()
>>> /usr/local/lib/php/Horde/ActiveSync/Connector/Exporter.php:205
>>> 26732 8. Horde_ActiveSync_Imap_Adapter->getMessages()
>>> /usr/local/lib/php/Horde/Core/ActiveSync/Driver.php:1352
>>> 26733 9. Horde_ActiveSync_Imap_Adapter->_buildMailMessage()
>>> /usr/local/lib/php/Horde/ActiveSync/Imap/Adapter.php:653
>>> 26734 10. Horde_ActiveSync_Imap_Message->getAttachmentsMimeParts()
>>> /usr/local/lib/php/Horde/ActiveSync/Imap/Adapter.php:1153
>>> 26735 11. Horde_ActiveSync_Imap_Message->getMimePart()
>>> /usr/local/lib/php/Horde/ActiveSync/Imap/Message.php:398
>>> 26736 12. Horde_ActiveSync_Imap_Message->getBodyPart()
>>> /usr/local/lib/php/Horde/ActiveSync/Imap/Message.php:457
>>> 26737 13. Horde_ActiveSync_Imap_Message->__get()
>>> /usr/local/lib/php/Horde/ActiveSync/Imap/Message.php:583
>>> 26738 14. Horde_ErrorHandler::errorHandler()
>>> /usr/local/lib/php/Horde/ActiveSync/Imap/Message.php:111
>>
>>
>> This is harmless and has already been fixed in Git.
>>
>>
>>> ...
>>>
>>> 2015-08-11T16:40:25-03:00 NOTICE: HORDE PHP ERROR: Undefined
>>> offset: 124981 [pid 26763 on line 1078 of
>>> "/usr/local/lib/php/Math/BigInteger.php"]
>>> 2592237 2015-08-11T16:40:25-03:00 DEBUG: HORDE 1.
>>> Horde_Rpc_ActiveSync->getResponse()
>>> /www/httpd-2.2.29/htdocs/horde-5.2.10/rpc.php:160
>>> 2592238 2. Horde_ActiveSync->handleRequest()
>>> /usr/local/lib/php/Horde/Rpc/ActiveSync.php:143
>>> 2592239 3. Horde_ActiveSync_Request_Base->handle()
>>> /usr/local/lib/php/Horde/ActiveSync.php:803
>>> 2592240 4. Horde_ActiveSync_Request_Sync->_handle()
>>> /usr/local/lib/php/Horde/ActiveSync/Request/Base.php:253
>>> 2592241 5. Horde_ActiveSync_Connector_Exporter->sendNextChange()
>>> /usr/local/lib/php/Horde/ActiveSync/Request/Sync.php:508
>>> 2592242 6. Horde_ActiveSync_Connector_Exporter->_sendNextChange()
>>> /usr/local/lib/php/Horde/ActiveSync/Connector/Exporter.php:156
>>> 2592243 7. Horde_Core_ActiveSync_Driver->getMessage()
>>> /usr/local/lib/php/Horde/ActiveSync/Connector/Exporter.php:205
>>> 2592244 8. Horde_ActiveSync_Imap_Adapter->getMessages()
>>> /usr/local/lib/php/Horde/Core/ActiveSync/Driver.php:1352
>>> 2592245 9. Horde_ActiveSync_Imap_Adapter->_buildMailMessage()
>>> /usr/local/lib/php/Horde/ActiveSync/Imap/Adapter.php:653
>>> 2592246 10.
>>> Horde_ActiveSync_Imap_Message->getAttachmentsMimeParts()
>>> /usr/local/lib/php/Horde/ActiveSync/Imap/Adapter.php:1153
>>> 2592247 11. Horde_ActiveSync_Imap_Message->_decodeTnefData()
>>> /usr/local/lib/php/Horde/ActiveSync/Imap/Message.php:412
>>> 2592248 12. Horde_Compress_Tnef->decompress()
>>> /usr/local/lib/php/Horde/ActiveSync/Imap/Message.php:361
>>> 2592249 13. Horde_Compress_Tnef->_decodeMessageProperty()
>>> /usr/local/lib/php/Horde/Compress/Tnef.php:285
>>> 2592250 14. Horde_Mapi::filetimeToUnixtime()
>>> /usr/local/lib/php/Horde/Compress/Tnef.php:663
>>> 2592251 15. Horde_Mapi::_win64ToUnix()
>>> /usr/local/lib/php/Horde/Mapi.php:145
>>> 2592252 16. Math_BigInteger->subtract()
>>> /usr/local/lib/php/Horde/Mapi.php:193
>>> 2592253 17. Math_BigInteger->_subtract()
>>> /usr/local/lib/php/Math/BigInteger.php:991
>>> 2592254 18. Horde_ErrorHandler::errorHandler()
>>> /usr/local/lib/php/Math/BigInteger.php:1078
>>> 2592255
>>> 2592256 2015-08-11T16:40:25-03:00 NOTICE: HORDE PHP ERROR:
>>> Undefined offset: 124982 [pid 26763 on line 1078 of
>>> "/usr/local/lib/php/Math/BigInteger.php"]
>>> 2592257 2015-08-11T16:40:25-03:00 EMERG: HORDE Maximum execution
>>> time of 29 seconds exceeded [pid 26763 on line 140 of
>>> "/usr/local/lib/php/Horde/Support/Backtrace.php"]
>>> 2592258 2015-08-11T16:40:25-03:00 DEBUG: HORDE 1.
>>> Horde_ErrorHandler::catchFatalError()
>>> ...
>>>
>>> where the value ranges 1 to 124981(?)
>>>
>>> Any help about this? necessary more information?
>>>
>>> Thanks in advance
>>> Gian
>>
>>
>> This is related to a date field in some Microsoft TNEF attachment
>> in one of the emails being synchronized. Impossible to say what the
>> actual issue is without access to the attachment causing the error.
>>
>> --
>> mike
>> The Horde Project
>> http://www.horde.org
>> https://www.facebook.com/hordeproject
>> https://www.twitter.com/hordeproject
>
> ok Mike
> we will investigate this attachments
>
> best regards
> Gian
> --
> Gian Franco B Barcellini
> Analista de Suporte de Software
> Diretoria de Suporte de Software / CCUEC
>
> --
> Horde mailing list
> Frequently Asked Questions: http://horde.org/faq/
> To unsubscribe, mail: horde-unsubscribe at lists.horde.org
Mike
after to modify $conf['max_exec_time'] = 3000; I get the four cpus at
100% (look attachment)
I did a command strace in one of the processes apache executing, see below:
======================
[root@ horde]# strace -e trace=write -s 999 -p 27257
Process 27257 attached - interrupt to quit
write(21, "[13-Aug-2015 15:04:14 America/Sao_Paulo] PHP Fatal error:
Allowed memory size of 524288000 bytes exhausted (tried to allocate
2009 bytes) in /usr/local/lib/php/Horde/Core/Log/Logger.php on line
59\n", 198) = 198
write(16, "2015-08-13T15:04:14-03:00 EMERG: HORDE Allowed memory size
of 524288000 bytes exhausted (tried to allocate 2009 bytes) [pid 27257
on line 59 of \"/usr/local/lib/php/Horde/Core/Log/Logger.php\"]\n",
192) = 192
write(18, "\25\3\1\0
a'\246\256\206JL(Sg\211\21\240\"\0'0LB\254\275\327j\263\252\n(\377\234\355\236\347", 37) =
37
write(20, "\25\3\1\0
\vu\365\326\324ss\356\247Z|\261\200R\240\230g\364\326B\20\322-\244\23\311\377p\376\275h\212", 37) =
37
write(11, "143.106.10.174 - 143.106.147.242 - XXXXXXXX at unicamp.br
[13/Aug/2015:14:54:49 -0300] TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384
\"POST
/Microsoft-Server-ActiveSync?Cmd=Sync&User=XXXXXX%40unicamp.br&DeviceId=SEC1B6B11EFD67E8&DeviceType=SAMSUNGGTI9192 HTTP/1.1\" 500 172 \"-\" \"SAMSUNG-GT-I9192/101.40402\"\n", 294) =
294
Only some devices have this problem, windowsoutlook15 or samsung ...
The cpu level on quickly and the performance of our environment falls
quite
Therefore, undo changes to 29seconds ...
Gian
--
Gian Franco B Barcellini
Analista de Suporte de Software
Diretoria de Suporte de Software / CCUEC
-------------- next part --------------
A non-text attachment was scrubbed...
Name: screen-cpu.gif
Type: image/gif
Size: 35965 bytes
Desc: not available
URL: <http://lists.horde.org/archives/horde/attachments/20150813/bbefa5fa/attachment.gif>
More information about the horde
mailing list