[horde] iPhone AS lockup
Michael J Rubinsky
mrubinsk at horde.org
Tue Jan 7 00:15:04 UTC 2014
Quoting Simon Wilson <simon at simonandkate.net>:
>>> 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.
> 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.
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.
>>> 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.
> 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.
>>> 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. That is
most likely the source of your battery drain (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?
>>> 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.
> 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.
--
mike
The Horde Project (www.horde.org)
mrubinsk at horde.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 5849 bytes
Desc: S/MIME Signature
URL: <http://lists.horde.org/archives/horde/attachments/20140106/74ce115d/attachment.bin>
More information about the horde
mailing list