ActiveSync randomly stops working Blackberry 10 since 1.8.17 upgrade

[Jay]

Bad news guys.

After a few hours my phone sync'd all of my sent items to the beginning of time again. This time it was able to sync ALL of them instead of hanging when it got to 2009. It's still downloading message bodies from the looks of the debug log which I can provide if you'd like.

Could you send us logs from first synchronization until the first "zero day" (""device asking for changes with a time window of: 0 days"") for an email folder (no contacts or tasks) ?


Regards,
Jay

[FiZi]

Logs e-mailed.

[Jay]

Hi FiZi,

I prepared another custom build, now we don't change the time window to default (0) unless the device explicitly ask for it, yet in the BB simulator i saw the device asking explicitly for different time windows for the calendar folder without any option change, hope it's not an issue in a real device, you can download this build here md5: 1ab91809990e592911b83a6407ab5261.

Regards,
Jay

[FiZi]

Hi FiZi,

I prepared another custom build, now we don't change the time window to default (0) unless the device explicitly ask for it, yet in the BB simulator i saw the device asking explicitly for different time windows for the calendar folder without any option change, hope it's not an issue in a real device, you can download this build here md5: 1ab91809990e592911b83a6407ab5261.

Regards,
Jay

I've installed the new version you linked, removed the sync relationship with my phone and setup my account from scratch on my phone.

I only sync Contacts and Mail for this account. No Calendar. I set the sync window to 14 days and enabled push as before.

[FiZi]

So goodish news.

My phone was working fine until about ~11:00am 2014-08-27 and then went high-cpu usage as before and e-mail stopped syncing on my account.

My phone has not sync'd the entire backlog of sent items though which is progress. At this point syncing just appears to have stopped.

At 13:15 2014-08-27 I rebooted my phone and syncing resumed.

I will send you a log shortly.

[Jay]

Hi FiZi,

I can't see anything suspicious in the logs, time window didn't change over time and the synchronization seems to be flawless, but after 10:07:25 the device asks if any folder has changed the server reply 'no changes', since then the device went asleep until 13:18:28, when you probably rebooted the phone.

Nothing unsual happened before the phone stopped syncing, either the connection went down or there a bug in the device triggered by the stress we've put it recently.

Let me know if it happens again.

Regards,
Jay

[FiZi]

Hi FiZi,

I can't see anything suspicious in the logs, time window didn't change over time and the synchronization seems to be flawless, but after 10:07:25 the device asks if any folder has changed the server reply 'no changes', since then the device went asleep until 13:18:28, when you probably rebooted the phone.

Nothing unsual happened before the phone stopped syncing, either the connection went down or there a bug in the device triggered by the stress we've put it recently.

Let me know if it happens again.

Regards,
Jay

I noticed the same thing. It's like the phone just got stuck processing a message from the account (or something) and stopped syncing.

I've updated the OS on my phone. Hopefully that will resolve it.

[FiZi]

The issue occurred again overnight.

This is what Apache saw:

192.168.xxx.xxx - - [28/Aug/2014:23:51:57 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myemail&40mydomain.com&DeviceId=XXXXXXXXXX HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [28/Aug/2014:23:59:58 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [28/Aug/2014:23:59:58 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=FolderSync&DeviceType=BlackBerry&User=myemail&40mydomain.com&DeviceId=XXXXXXXXXX HTTP/1.1" 200 63 "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [29/Aug/2014:00:06:34 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myemail&40mydomain.com&DeviceId=XXXXXXXXXX HTTP/1.1" 200 85 "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [29/Aug/2014:00:06:42 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myemail&40mydomain.com&DeviceId=XXXXXXXXXX HTTP/1.1" 200 85 "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [29/Aug/2014:00:06:46 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myemail&40mydomain.com&DeviceId=XXXXXXXXXX HTTP/1.1" 200 67 "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [29/Aug/2014:08:04:56 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myemail&40mydomain.com&DeviceId=XXXXXXXXXX HTTP/1.1" 200 57829 "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [29/Aug/2014:08:05:07 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myemail&40mydomain.com&DeviceId=XXXXXXXXXX HTTP/1.1" 200 27472 "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [29/Aug/2014:08:05:11 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myemail&40mydomain.com&DeviceId=XXXXXXXXXX HTTP/1.1" 200 67 "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [29/Aug/2014:08:05:21 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myemail&40mydomain.com&DeviceId=XXXXXXXXXX HTTP/1.1" 200 85 "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [29/Aug/2014:08:05:25 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myemail&40mydomain.com&DeviceId=XXXXXXXXXX HTTP/1.1" 200 67 "-" "RIM-Q10-SQN100-3/10.2.1.3247"

I have ActiveSync debug logs I can e-mail if you'd like.

It looks like the connection crapped out right after it sent an OPTIONS via HTTP.

I'm going to check my other logs and see if there is a pattern there.

[FiZi]

Looks like the OPTIONS command is sent semi-often

182.168.xxx.xxx - - [24/Aug/2014:08:07:09 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
182.168.xxx.xxx - - [24/Aug/2014:08:27:12 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
182.168.xxx.xxx - - [24/Aug/2014:08:28:52 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
182.168.xxx.xxx - - [25/Aug/2014:08:34:40 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
142.xxx.xxx.xxx - - [26/Aug/2014:09:44:16 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
142.xxx.xxx.xxx - - [26/Aug/2014:09:44:44 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
142.xxx.xxx.xxx - - [26/Aug/2014:09:44:50 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
142.xxx.xxx.xxx - - [26/Aug/2014:10:04:06 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
142.xxx.xxx.xxx - - [27/Aug/2014:10:07:25 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
142.xxx.xxx.xxx - - [27/Aug/2014:13:18:24 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
182.168.xxx.xxx - - [27/Aug/2014:22:07:33 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
182.168.xxx.xxx - - [27/Aug/2014:22:36:28 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
182.168.xxx.xxx - - [27/Aug/2014:23:57:31 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
182.168.xxx.xxx - - [28/Aug/2014:23:59:58 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"

and an OPTIONS command matches the time you'd noted early when things crapped out at 10:07:25 on August 27th, 2014.

[FiZi]

And again this morning, at 10:07am e-mail stopped.

192.168.xxx.xxx - - [30/Aug/2014:09:10:18 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myname%40mydomain.com&DeviceId=BB2AD68B48 HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [30/Aug/2014:09:18:19 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myname%40mydomain.com&DeviceId=BB2AD68B48 HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [30/Aug/2014:09:26:20 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myname%40mydomain.com&DeviceId=BB2AD68B48 HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [30/Aug/2014:09:34:21 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 - "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [30/Aug/2014:10:07:10 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myname%40mydomain.com&DeviceId=BB2AD68B48 HTTP/1.1" 200 67 "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [30/Aug/2014:10:07:17 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myname%40mydomain.com&DeviceId=BB2AD68B48 HTTP/1.1" 200 67 "-" "RIM-Q10-SQN100-3/10.2.1.3247"
192.168.xxx.xxx - - [30/Aug/2014:10:07:20 -0700] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=myname%40mydomain.com&DeviceId=BB2AD68B48 HTTP/1.1" 200 67 "-" "RIM-Q10-SQN100-3/10.2.1.3247"

Odd that 10:07 would come up twice. No OPTIONS post this time though.

Below are the Zimbra apache logs (above are my Apache logs for mod_proxy)

192.168.xxx.xxx -  -  [30/Aug/2014:07:04:38 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=eric%40fizi.ca&DeviceId=BB2AD68B48 HTTP/1.1" 200 234 "-" "RIM-Q10-SQN100-3/10.2.1.3247" 52
192.168.xxx.xxx -  -  [30/Aug/2014:07:15:43 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=eric%40fizi.ca&DeviceId=BB2AD68B48 HTTP/1.1" 200 234 "-" "RIM-Q10-SQN100-3/10.2.1.3247" 39
192.168.xxx.xxx -  -  [30/Aug/2014:07:33:59 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=eric%40fizi.ca&DeviceId=BB2AD68B48 HTTP/1.1" 200 234 "-" "RIM-Q10-SQN100-3/10.2.1.3247" 40
192.168.xxx.xxx -  -  [30/Aug/2014:07:41:46 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=eric%40fizi.ca&DeviceId=BB2AD68B48 HTTP/1.1" 200 98 "-" "RIM-Q10-SQN100-3/10.2.1.3247" 164
192.168.xxx.xxx -  -  [30/Aug/2014:07:41:49 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=eric%40fizi.ca&DeviceId=BB2AD68B48 HTTP/1.1" 200 67 "-" "RIM-Q10-SQN100-3/10.2.1.3247" 32
192.168.xxx.xxx -  -  [30/Aug/2014:08:23:05 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=eric%40fizi.ca&DeviceId=BB2AD68B48 HTTP/1.1" 200 234 "-" "RIM-Q10-SQN100-3/10.2.1.3247" 45
192.168.xxx.xxx -  -  [30/Aug/2014:16:34:21 +0000] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 0 "-" "RIM-Q10-SQN100-3/10.2.1.3247" 2
192.168.xxx.xxx -  -  [30/Aug/2014:17:07:10 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=eric%40fizi.ca&DeviceId=BB2AD68B48 HTTP/1.1" 200 67 "-" "RIM-Q10-SQN100-3/10.2.1.3247" 58
192.168.xxx.xxx -  -  [30/Aug/2014:17:07:17 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=eric%40fizi.ca&DeviceId=BB2AD68B48 HTTP/1.1" 200 67 "-" "RIM-Q10-SQN100-3/10.2.1.3247" 48
192.168.xxx.xxx -  -  [30/Aug/2014:17:07:20 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=Sync&DeviceType=BlackBerry&User=eric%40fizi.ca&DeviceId=BB2AD68B48 HTTP/1.1" 200 67 "-" "RIM-Q10-SQN100-3/10.2.1.3247" 25