[horde] iPhone AS lockup

Tue Jan 7 00:43:36 UTC 2014

>>>> Very strange lockup happened on my wife's new phone (iPhone 5c, 7.0.4).
>>>
>>> What do you mean by "lockup"? The email app, the entire phone? I  
>>> have an iPod with iOS 7, my wife has a iPhone 5s with iOS 7 as  
>>> well as an iPad Air with iOS 7. I have not experienced this yet.
>>>
>>
>> OK, I will try and explain it better :)
>>
>> The phone remains fully usable, except the battery drains in about  
>> 8 hours and Horde ActiveSync functions no longer sync.
>
> Nothing in the log shows anything that would cause excessive battery  
> drain except for the small heartbeat interval. Normally if  
> ActiveSync is the cause, you'll see a bunch of sync  
> request/responses for the same synckey.

Nothing is logged at all to the Horde device log after that point, so  
I am not seeing any requests or responses... but it is definitely  
ActiveSync on the client that is causing the battery drain. Each time  
it happens the Email client is constantly trying to connect but seems  
to never makes it out of the device - nothing is logged either by  
Apache or Horde, and nothing syncs across Cal, Contacts, Email, Tasks,  
Reminders. Everything else works fine on the phone.

>
>> The calendar exception change made on the iPhone was the last thing  
>> that happened before AS stopped responding on the device. Email  
>> showed a perpetually spinning wheel and the text "Last checked at  
>> 7.21am". Calendar and Contacts do not show a spinning wheel but no  
>> changes are sync'ed in either direction.
>
> Ok, so you are saying that you are editing a recurring event on the  
> client, by creating a exception and this causes the client to crash.

Yes that appears to be the case.

> In the log I see a successful SYNC request FROM the client sending  
> the new event information, followed by the proper status code to  
> indicate success. There is really nothing special or complicated  
> sent from the server to client in this case, so I don't really see  
> how Horde can be screwing up the response - it's just a successful  
> status code being sent, along with the new syncKey. The SENDMAIL  
> request also looks like it succeeded (the "preparing to copy to  
> sent" is only output after the email is successfully sent). If the  
> client is hanging after the change was made, it sounds like a  
> client/software bug. Which I don't seem to be able to replicate no  
> matter how many recurring events/exceptions I try to make.

OK

>>>> It has happened before on other iOS devices, but only occasionally.
>>>>
>>>> First symptom is that battery life plummets. Then checking,  
>>>> notice that email has not updated all day.
>>>>
>>>> This time:
>>>>
>>>> iPhone says email last updated at 7:21am.
>>>
>>> This is the last time an email was updated/sent/deleted on the  
>>> client. According to the log you attached, this is correct.
>>
>> The Calendar exception was sent as a SendMail at 8.36am, and was  
>> received by the server and sent to the recipient successfully.
>>
>> At 8:36:10 in the device log I see:
>>
>> 2014-01-06T08:36:10+10:00 INFO: [24014]  
>> Horde_Core_ActiveSync_Driver::authenticate() attempt for katie
>> 2014-01-06T08:36:10+10:00 INFO: [] SENDMAIL request received for user katie
>> 2014-01-06T08:36:10+10:00 INFO: [24014] Device entry exists for  
>> APPLC8QLF107FL01, updating userAgent and version.
>> 2014-01-06T08:36:10+10:00 INFO: [24014] Request being handled for  
>> device: APPLC8QLF107FL01, Supporting protocol version: 14.1, Using  
>> Horde_ActiveSync v2.10.0
>> 2014-01-06T08:36:10+10:00 INFO: [24014] Handling SENDMAIL command  
>> with Wbxml.
>> 2014-01-06T08:36:10+10:00 DEBUG: [24014] I  <ComposeMail:SendMail>
>> 2014-01-06T08:36:10+10:00 DEBUG: [24014] I   <ComposeMail:ClientId>
>> 2014-01-06T08:36:10+10:00 DEBUG: [24014] I      
>> 3DA6C0F9-9AFD-4104-ABD3-E69CBD40863C
>> 2014-01-06T08:36:10+10:00 DEBUG: [24014] I   </ComposeMail:ClientId>
>> 2014-01-06T08:36:10+10:00 DEBUG: [24014] I   <ComposeMail:SaveInSentItems />
>> 2014-01-06T08:36:10+10:00 DEBUG: [24014] I   <ComposeMail:MIME>
>> 2014-01-06T08:36:10+10:00 DEBUG: [24014] I     [2166 bytes of content]
>> 2014-01-06T08:36:10+10:00 DEBUG: [24014] I   </ComposeMail:MIME>
>> 2014-01-06T08:36:10+10:00 DEBUG: [24014] I  </ComposeMail:SendMail>
>> 2014-01-06T08:36:11+10:00 INFO: [24014] Preparing to copy to 'INBOX/Sent'
>>
>> And process 24014 (which is only just spawned - those are its only  
>> entries in the log) is never seen again.
>
> This would be expected. THe preparing to copy log entry is the last  
> entry that would be made, unless it was a reply/forward and the  
> maillog was in use. Also, the entry right after that in your log:
>
> 2014-01-06T08:36:11+10:00 INFO: [] Maximum memory usage for  
> ActiveSync request: 30796384 bytes.
>
> Is only logged when the php process handling the request successfully ends.
>

OK, good to know that it is completing OK.

>
>> Two more pre-existing processes do further Pings, and then the  
>> phone stops responding to AS.
>
> These can continue to run until the heartbeat expires or a change is  
> detected in one of the monitored collections.

Yes, that is what I figured - appears that the connections that the  
client has already made continue to reconnect, but no new ones can be  
established for some reason, and it dies.

>
>>>> Horde says device last seen at 8:36am.
>>>
>>> Horde displays the last time it has communicated with the device.  
>>> This includes PINGS (the above time from the iPhone does not).  
>>> This is also correct according to the log.
>>>
>>>>
>>>> Apache log for that device for that time:
>>
>> <snip>
>>
>>> These are all normal PING, FOLDERSYNC, SYNC, and SENDMAIL  
>>> requests. It looks like either you have configured the heartbeat  
>>> interval to be around 8 minutes or the iPhone for some reason is  
>>> limiting to this interval. Unless you have a reason for such a  
>>> short interval, you should use something longer. IIRC, the default  
>>> for iOS and Android devices is something like 59 minutes. This  
>>> short of an interval will affect battery life (it's cheaper to  
>>> maintain the open connection then it is to continuously close and  
>>> open a new one).
>>>
>>
>> Didn't think I had changed from default? From conf.xml this looks  
>> like it is default...
>>
>> $conf['activesync']['emailsync'] = true;
>> $conf['activesync']['version'] = '14.1';
>> $conf['activesync']['autodiscovery'] = 'user';
>> $conf['activesync']['outlookdiscovery'] = false;
>> $conf['activesync']['logging']['path'] = '/var/log/hordeas';
>> $conf['activesync']['logging']['type'] = 'custom';
>> $conf['activesync']['ping']['heartbeatmin'] = 60;
>> $conf['activesync']['ping']['heartbeatmax'] = 2700;
>> $conf['activesync']['ping']['heartbeatdefault'] = 480;
>> $conf['activesync']['ping']['deviceping'] = true;
>> $conf['activesync']['ping']['waitinterval'] = 30;
>> $conf['activesync']['enabled'] = true;
>
> Hm. Don't remember making that so low :) I'll adjust the default.
>
> Anyway, that value is only used when the client doesn't specify a hb  
> interval on it's own. Not sure why your client is not doing this.  
> You should set that to a larger value like 2700 or or even 3540.

Do you mean the 'heartbeatdefault' to e.g. 2700 or 3540, or the min or max?

I think what you have as default is actually the same as the MS  
ActiveSync implementation default, that is possibly why you set them  
like that?

> That is most likely the source of your battery drain

No, when the device works fine 99% of the time, the battery lasts over  
2 days with this exact same configuration.

> (if it's actually due to ActiveSync, that is) and a different issue  
> than the lockup. Nothing else in the log looks even remotely wrong.
>
>
>>>> The SendMail is the last entry for that device (12 hours ago).
>>>>
>>>> Device AS log for that period:
>>>>
>>>> http://www.simonandkate.net/5c.txt
>>>>
>>>> The item that was sent was a calendar exception that was sent to  
>>>> me. Coincidentally I was going to look at it this evening anyway,  
>>>> as when I tried to "accept and update" the exception that she  
>>>> sent at the time AS 'lost' the device I got a "cannot be found"  
>>>> error (attached PNG).
>>>
>>> Are there any errors in the webserver or horde log?
>>
>> No.
>>
>>>
>>>> I tried removing in AS admin in Horde (doesn't work),
>>>
>>> Cannot duplicate, and what do you mean by "doesn't work", exactly  
>>> what does happen?
>>
>> Poorly explained on my part. Sorry. Removing the phone in AS in  
>> Horde does not kick the phone AS client into a reset.
>
> When you remove the state, do you see the state disappear in the sync log?

NOTHING appears in the Horde AS device sync log after the "lockup" at  
8.36am, regardless of anything I do, until I restore the phone from  
backup.

>
>
>>>> removing the account in iOS (can't, just never completes).
>>>
>>> Sounds like an issue with your device.
>>
>> It has now happened with 3 x iOS devices - an iPad2, an iPhone 4,  
>> and now the iPhone 5c. I don't believe in that many coincidences :)
>
> I didn't mean just *your* device, I meant with the client software,  
> in general. Something in your data is triggering a bug in the client  
> maybe.

OK, that makes more sense :)

>
>> The AS client appears to just completely hang on something, and  
>> that something survives reboots, airplane mode, etc.
>
> Nothing in your log is incorrect in the data being set TO the  
> device, in fact it's all basically simple status responses - pretty  
> hard to mess up.
>
>>>> I tried turning off Calendar sync in iOS and it also never  
>>>> completes, just hangs for hours.
>>>
>>>
>>>> I have deleted the events in case they are corrupted somehow,  
>>>> reset the phone via backup to prior to this morning, and it is  
>>>> fine, now once again fully updated. That has been my only fix  
>>>> before (this has happened about 4 times over the last 6 to 9  
>>>> months). Has only happened with iOS devices, never Android. I  
>>>> don't know if prior times were triggered by event exceptions.
>>>>
>>>> Is it an issue with the calendar entry that sending an exception  
>>>> is killing it and prompting the error when I try and accept it?
>>>
>>>
>>> You mean an error when accepting it from Kronolith? Would need to  
>>> see the iTip data, error log etc...
>>>
>>>
>>>> Any other ideas?
>>>
>>> No. I don't see any of these issues. My calendar is full of  
>>> exceptions, though I generally don't use iTips to communicate them.
>>>
>>>
>>
>> I now have a spare iPhone 4 - I will recreate some appointments and  
>> create exceptions to try and see if I can replicate it.
>
> If you can provide me with an iCalendar file that reliable triggers  
> the bug I can try to take a look if it's something we can do  
> differently in our code, but otherwise I have no ideas.
>

OK, will work on it.

>
> -- 
> mike

Thanks
Simon.

--
Simon Wilson
M: 0400 12 11 16
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-keys
Size: 1339 bytes
Desc: PGP Public Key
URL: <http://lists.horde.org/archives/horde/attachments/20140107/36340370/attachment-0002.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 198 bytes
Desc: PGP Digital Signature
URL: <http://lists.horde.org/archives/horde/attachments/20140107/36340370/attachment-0003.bin>