[horde] iPhone AS lockup

Mon Jan 6 15:38:31 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.

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

>
> 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:
>
> 192.168.1.155 - katie [06/Jan/2014:07:21:08 +1000] "POST  
> /Microsoft-Server-ActiveSync?User=katie&DeviceId=ApplC8QLF107FL01&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200  
> 13
> 192.168.1.155 - katie [06/Jan/2014:07:29:14 +1000] "POST  
> /Microsoft-Server-ActiveSync?User=katie&DeviceId=ApplC8QLF107FL01&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200  
> 13
> 192.168.1.155 - katie [06/Jan/2014:07:37:19 +1000] "POST  
> /Microsoft-Server-ActiveSync?User=katie&DeviceId=ApplC8QLF107FL01&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200  
> 13
> 192.168.1.155 - katie [06/Jan/2014:07:45:24 +1000] "POST  
> /Microsoft-Server-ActiveSync?User=katie&DeviceId=ApplC8QLF107FL01&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200  
> 13
> 192.168.1.155 - katie [06/Jan/2014:07:53:29 +1000] "POST  
> /Microsoft-Server-ActiveSync?User=katie&DeviceId=ApplC8QLF107FL01&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200  
> 13
> 192.168.1.155 - katie [06/Jan/2014:08:01:34 +1000] "POST  
> /Microsoft-Server-ActiveSync?User=katie&DeviceId=ApplC8QLF107FL01&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200  
> 13
> 192.168.1.155 - katie [06/Jan/2014:08:09:39 +1000] "POST  
> /Microsoft-Server-ActiveSync?User=katie&DeviceId=ApplC8QLF107FL01&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200  
> 13
> 192.168.1.155 - katie [06/Jan/2014:08:17:44 +1000] "POST  
> /Microsoft-Server-ActiveSync?User=katie&DeviceId=ApplC8QLF107FL01&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200  
> 13
> 192.168.1.155 - katie [06/Jan/2014:08:25:48 +1000] "POST  
> /Microsoft-Server-ActiveSync?User=katie&DeviceId=ApplC8QLF107FL01&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200  
> 13
> 192.168.1.155 - katie [06/Jan/2014:08:35:56 +1000] "POST  
> /Microsoft-Server-ActiveSync?User=katie&DeviceId=ApplC8QLF107FL01&DeviceType=iPhone&Cmd=FolderSync HTTP/1.1" 200  
> 63
> 192.168.1.155 - katie [06/Jan/2014:08:35:57 +1000] "POST  
> /Microsoft-Server-ActiveSync?User=katie&DeviceId=ApplC8QLF107FL01&DeviceType=iPhone&Cmd=Sync HTTP/1.1" 200  
> 77
> 192.168.1.155 - katie [06/Jan/2014:08:36:10 +1000] "POST  
> /Microsoft-Server-ActiveSync?User=katie&DeviceId=ApplC8QLF107FL01&DeviceType=iPhone&Cmd=SendMail HTTP/1.1"  
> 200

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

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

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

> removing the account in iOS (can't, just never completes).

Sounds like an issue with your device.

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

>
> Simon
>
> ~~~~~~~~~~~~~~~~~~~~~~~~
> Other info:
>
> The Horde / Apache logs have the following through this time (ish)  
> but I don't think they are connected:
>
> Horde error:
> [Mon Jan 06 07:24:34 2014] [error] [client 192.168.1.155] PHP Fatal  
> error:  Uncaught exception 'Horde_Imap_Client_Exception' with  
> message 'Mail server closed the connection unexpectedly.' in  
> /usr/share/pear/Horde/Imap/Client/Socket/Connection/Socket.php:119\nStack  
> trace:\n#0 /usr/share/pear/Horde/Imap/Client/Socket.php(4138):  
> Horde_Imap_Client_Socket_Connection_Socket->read()\n#1  
> /usr/share/pear/Horde/Imap/Client/Socket.php(3941):  
> Horde_Imap_Client_Socket->_getLine(Object(Horde_Imap_Client_Interaction_Pipeline))\n#2 /usr/share/pear/Horde/Imap/Client/Socket.php(3871): Horde_Imap_Client_Socket->_sendCmdChunk(Object(Horde_Imap_Client_Interaction_Pipeline), Array)\n#3 /usr/share/pear/Horde/Imap/Client/Socket.php(825): Horde_Imap_Client_Socket->_sendCmd(Object(Horde_Imap_Client_Interaction_Command))\n#4 /usr/share/pear/Horde/Imap/Client/Base.php(830): Horde_Imap_Client_Socket->_logout()\n#5 /usr/share/pear/Horde/Imap/Client/Base.php(344): Horde_Imap_Client_Base->logout()\n#6 [internal function]: Horde_Imap_Client_Base->shutdown()\n#7 {main}\n  thrown in /usr/share/pear/Horde/Imap/Client/Socket/Connection/Socket.php on line  
> 119

Looks like an issue in the imap client or imap server during the  
logout process, but not sure.

> Apache request (I think):
> 192.168.1.155 - simon at simonandkate.net [06/Jan/2014:07:24:33 +1000]  
> "POST  
> /Microsoft-Server-ActiveSync?User=simon at simonandkate.net&DeviceId=ApplDLXFT5X3DFJ2&DeviceType=iPad&Cmd=Ping HTTP/1.1" 200  
> -
>
>
> Horde error:
> [Mon Jan 06 10:16:42 2014] [error] [client 192.168.1.155] PHP Fatal  
> error:  Call to a member function getType() on a non-object in  
> /usr/share/pear/Horde/Mime/Viewer/Images.php on line 61
>
> Apache requests:
> 192.168.1.155 - - [06/Jan/2014:10:16:41 +1000] "GET  
> /imp/view.php?ctype=image%2F%2A&id=1.11&imp_img_view=data&actionID=view_attach&muid=%7B5%7DINBOX57765&view_token=jiDVC87A8_vM_JS_LeuZcg1 HTTP/1.1" 500  
> 26
> 192.168.1.155 - - [06/Jan/2014:10:16:41 +1000] "GET  
> /imp/view.php?ctype=image%2F%2A&id=1.8&imp_img_view=data&actionID=view_attach&muid=%7B5%7DINBOX57765&view_token=jiDVC87A8_vM_JS_LeuZcg1 HTTP/1.1" 500  
> 26
> 192.168.1.155 - - [06/Jan/2014:10:16:41 +1000] "GET  
> /imp/view.php?ctype=image%2F%2A&id=1.9&imp_img_view=data&actionID=view_attach&muid=%7B5%7DINBOX57765&view_token=jiDVC87A8_vM_JS_LeuZcg1 HTTP/1.1" 500  
> 26
> 192.168.1.155 - - [06/Jan/2014:10:16:41 +1000] "GET  
> /imp/view.php?ctype=image%2F%2A&id=1.2&imp_img_view=data&actionID=view_attach&muid=%7B5%7DINBOX57765&view_token=jiDVC87A8_vM_JS_LeuZcg1 HTTP/1.1" 500  
> 26
> 192.168.1.155 - - [06/Jan/2014:10:16:41 +1000] "GET  
> /imp/view.php?ctype=image%2F%2A&id=1.6&imp_img_view=data&actionID=view_attach&muid=%7B5%7DINBOX57765&view_token=jiDVC87A8_vM_JS_LeuZcg1 HTTP/1.1" 500  
> 26
>
> I don't think they are related though...

These are definitely not, no.

-- 
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/e0b58d62/attachment-0001.bin>