[horde] iPhone AS lockup

Mon Jan 6 09:49:28 UTC 2014

Very strange lockup happened on my wife's new phone (iPhone 5c, 7.0.4).

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.

Horde says device last seen at 8:36am.

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  
-

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

I tried removing in AS admin in Horde (doesn't work), removing the  
account in iOS (can't, just never completes). 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?

Any other ideas?

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

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

--
Simon Wilson
M: 0400 12 11 16
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Untitled.png
Type: image/png
Size: 3864 bytes
Desc: not available
URL: <http://lists.horde.org/archives/horde/attachments/20140106/4e63607c/attachment-0001.png>
-------------- 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/20140106/4e63607c/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/20140106/4e63607c/attachment-0003.bin>