[horde] iPhone AS lockup

[Simon Wilson]

>> 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.

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.

>
>> 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. Two more pre-existing  
processes do further Pings, and then the phone stops responding to AS.

>
>>
>> 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;

>> 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.

>
>> 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 :)

The AS client appears to just completely hang on something, and that  
something survives reboots, airplane mode, etc.

>
>> 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.

We were talking about it last night, and the last time it happened (on  
a different device) was when my wife thinks she made a specific  
Kronolith appt exception on 17th December, but I don't have the logs  
to confirm that.

>>
>> Simon
>>

Cheers
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/8e2e7fbe/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/8e2e7fbe/attachment-0003.bin>