[horde] Active Sync makes a rather slow impression

[Jens Hellermann]

Am 11.09.2015 um 16:02 schrieb Michael J Rubinsky:
>
> Quoting Michael J Rubinsky <mrubinsk at horde.org>:
>
>> Quoting Jens Hellermann <hellermann at we-do.com>:
>>
>>> Am 10.09.2015 um 10:06 schrieb Jens Hellermann:
>>>> Am 08.09.2015 um 14:05 schrieb Michael J Rubinsky:
>>>>>
>>>>> Quoting Jens Hellermann <hellermann at we-do.com>:
>>>>>
>>>>>> Am 07.09.2015 um 18:54 schrieb Michael J Rubinsky:
>>>>>>>
>>>>>>> Quoting Jens Hellermann <hellermann at we-do.com>:
>>>>>>>
>>>>>>>> Dear Horde List Members,
>>>>>>>>
>>>>>>>> I have to sync several really large (>16GB +) Outlook accounts 
>>>>>>>> via Activesync into Outlook, and I would like to know if it is 
>>>>>>>> possible to give some Horde Processes a higher priority or 
>>>>>>>> myabe asign more workers for certain processes.
>>>>>>>> Because a  16GB Mail folder with over 50 Subfolders and sub, 
>>>>>>>> sub, sub Folders is taking really long (more than 8 hours 
>>>>>>>> definitly). Still the Server seems to be running idle most of 
>>>>>>>> the time, hardly any network taffic, minimal CPU Usage same for 
>>>>>>>> memory.
>>>>>>>>
>>>>>>>> Does anyone have an idea, how to fix this issue? Kind regards, 
>>>>>>>> Jens.
>>>>>>>
>>>>>>>
>>>>>>> The slowdown is most likely NOT due to any server resource usage 
>>>>>>> - as you can see by your server stats. This is probably due to 
>>>>>>> OL's speed in parsing and/or requesting each set of mail 
>>>>>>> messages. IIRC, I've seen OL request between 5 and 50 messages 
>>>>>>> per request and new requests are not made immediately after the 
>>>>>>> previous one finishes (probably to improve responsiveness of OL 
>>>>>>> during the long initial sync while still allowing NEW email 
>>>>>>> messages to arrive before the intial sync is finished). As far 
>>>>>>> as I know there is no way to change this behavior. You can 
>>>>>>> verify this by following the sync log of an attached OL client.
>>>>>>>
>>>>>> Hello Michael, first things first thanks a lot for your quick 
>>>>>> response. I understand that Outlook needs some time to 
>>>>>> synchronize, but my impression is that the system became slower 
>>>>>> with every new mail account I synchronize. What makes it 
>>>>>> difficult for me to analyze the situation is that I have problems 
>>>>>> setting up Activesync for logging per device (or single file at 
>>>>>> the moment). This weekend I upgraded everything to the newest 
>>>>>> version of Horde 5.2.10 . Maybe logging is a little buggy (or 
>>>>>> me!). The entries in the gui result in these entries in the 
>>>>>> conf.php:
>>>>>>
>>>>>> $conf['activesync']['logging']['path'] = '/var/log/activesync';
>>>>>> $conf['activesync']['logging']['level'] = '2';
>>>>>> $conf['activesync']['logging']['type'] = 'perdevice';
>>>>>>
>>>>>> The folder has been given the right permissions but even after a 
>>>>>> reboot no files ever show up in it. If I give folder path 
>>>>>> '/var/log/activesync/' I kill horde more or less completely.
>>>>>>
>>>>>> Can you confim this behaviour,
>>>>>
>>>>> No. Logging works fine for me, with those exact same settings 
>>>>> (assuming the /var/log/activesync directory exists).
>>>>
>>>> Hi Michael, OK it just takes some time until it activates (even 
>>>> after restarting lighttpd). So now I can logg per device and that 
>>>> client which made such a slow impression stops syncing after ~8GB 
>>>> and the last message in the log reads:
>>>>
>>>> 2015-09-10T09:53:10+02:00 INFO: [2036] Maximum memory usage for 
>>>> ActiveSync request: 64225280 bytes.
>>>>
>>>> This Email-Account has more than 50 folders and subfolders. So 
>>>> should I raise the maximum Memory for ActiveSync requests? If yes, 
>>>> where could I do so? Kind regards, Jens.
>>
>> This is not an error about being out of memory, it's a normal INFO 
>> log indicating the maximum amount of memory that the request used. 
>> That is output after EVERY request.
>>
>>
>>> Ok, a little update: the sync often stops with these messages in the 
>>> ActiveSync log:
>>>
>>> 2015-09-10T12:30:26+02:00 DEBUG: [2031] O     Fffd7569a
>>> 2015-09-10T12:30:26+02:00 DEBUG: [2031] O </Ping:Folder>
>>> 2015-09-10T12:30:26+02:00 DEBUG: [2031] O <Ping:Folder>
>>> 2015-09-10T12:30:26+02:00 DEBUG: [2031] O     Fdd65d674
>>> 2015-09-10T12:30:26+02:00 DEBUG: [2031] O </Ping:Folder>
>>> 2015-09-10T12:30:26+02:00 DEBUG: [2031] O </Ping:Folders>
>>> 2015-09-10T12:30:26+02:00 DEBUG: [2031] O  </Ping:Ping>
>>> 2015-09-10T12:30:26+02:00 INFO: [2031] Maximum memory usage for 
>>> ActiveSync request: 60293120 bytes.
>>>
>>> It stops for several minutes then, even though I set the send and 
>>> receive interval on 3 minutes, it can take longer.
>>
>> Correct. This is a normal PING response. It's up to the client to 
>> initiate the next request. There is nothing Horde can do to trigger 
>> it to do so sooner.
>>
>>> So this explains, why the sync is so slow, server and client are 
>>> just in an idle state, until I press send and receive again.
>>
>> This is exactly what I was talking about when I said that OL 
>> sometimes doesn't send the next request immediately after the 
>> previous one has completed.
>>
>>
>>
>>> Sometimes it also stops with a message like this:
>>>
>>> 2015-09-10T12:03:18+02:00 INFO: [2035] Updating state during change
>>> 2015-09-10T12:03:18+02:00 INFO: [2035] Peak memory usage after 
>>> message: 60555264
>>> 2015-09-10T12:03:18+02:00 INFO: [2035] 
>>> Horde_Core_ActiveSync_Driver::getMessage(INBOX,
>>>
>>> 19464)
>>> 2015-09-10T12:03:18+02:00 INFO: [2035] Sending MIME Message.
>>> 2015-09-10T12:03:18+02:00 INFO: [2035] Checking MIMETRUNCATION: , 
>>> ServerData: 10153
>>> 2015-09-10T12:03:18+02:00 ERR: Attribute "DTEND" Not Found
>>> 2015-09-10T12:03:18+02:00 INFO: [2035] Fetching verb for 
>>> <001a11342f28e1e3b5050c9b57b6 at google.com>.
>>>
>>> Message from syslogd at Horde at Sep 10 12:03:18 ...
>>> HORDE: Call to a member function getvEvent() on a non-object [pid 
>>> 2035 on line 1412 of "/usr/share/php/Horde/Core/ActiveSync/Driver.php"]
>>>
>>> I know that it's true that some schedules don't have dtstart and 
>>> dtend entries,
>>
>> DTSTART may or may not be required, but it depends on the METHOD of 
>> the request. DTEND is always optional, yes. The error you see 
>> *SHOULD* only prevent that one email from being transmitted 
>> correctly, not kill the entire sync. The ERR should be corrected 
>> though, and will look at it later this weekend.
>>
>>
>>> and it seems here they come from a google calendar. So some of my 
>>> users seem to use google calendar to send schedules to our internal 
>>> calendar. Similar users use their apple calendars parallely. I'll 
>>> find ways to surpress this futurely (junk filter).
>>
>> Are the users showing the problem the users using Google and the 
>> other users do not have the problem?
>>
>>> But do you think there is a way to keep the ActiveSync traffic 
>>> alive, when these circumstances appear?
>>
>> In the unlikely event it's due to the DTEND issue above, then fixing 
>> the issue may make OL more response. Otherwise, no. As stated before 
>> there is nothing the server can do to force the client to initiate 
>> connections more rapidly.
>
>
> This part has been fixed in Git and will be in the next bug fix 
> release of Horde_ActiveSync.
Wow, that was quick! Thank you very much. These schedules turned out to 
be tasks from Thunderbird. No wonder Outlook snaps in that case. Best 
regards, Jens.