Synchronizing Service Desktop at 0% for Several Hours
 

Hello, I wonder if anyone could offer advice concerning a problem we're having. We're having difficulty activating a user on our BES network and wonder if anyone can kindly offer advice concerning how to troubleshoot the issue.

To set the scene, below is a description of our BB infrastructure:

A. BB device: Model 8807 with O/S v4.22.208
B. BES server: Located in Hong Kong; Windows Server 2003 Standard Edition SP1 w/ BB Manager v4.1.2.25
C. Exchange server: Located in Tokyo; Windows Server 2003 Standard Edition SP1 w/ Exchange Server 2003 SP2
D. Outlook client: Windows XP SP2 w/ Outlook 2003 SP2
E. The BB user's mailbox size is about 500MB with about 15,500 items
F. Traceroute from the BES server to the Exchange server takes four hops (though with a few timeouts), but the pings are going through. From the Exchange server to the BES server takes seven hops.

Here's a description of what's happening with the activation process:

1. On the BES Server's BB Manager, the user's status is Running; our default IT policy has been applied successfully. However, the SIM ID, Last Result, and some other fields are blank.

2. One the BB device itself, below is what appears on the activation screen; it has been in this state for four hours now:

Activation-0%
Synchronizing service desktop
Email filters Initializing
Email settings Initializing
Key store options Initializing
Memos Initializing
Profiles Initializing
Quick contacts Initializing
Spell check options Initializing

I've posted some MAGT log entries below. There seems to be a cycle of calendar entries being sent to the device, the sync completing, then a request from the device to abort the sync, then a check of slow sync results, then queuing new mail and "filtering old exception appointment", then "worker thread-no response" logs appear, and finally the reappearance of "Sending CICAL_SLOW_SYNC_REQUEST_EVENTS" entries.

(Log entries follow)

[40000] (03/12 13:48:30.343):{0x1D6C} {xxx@yyy.com} UserControl::ProcessSLOW_SYNC - Normal SlowSync Mode - Requesting 0 from device, sending 209 to device
[40000] (03/12 13:48:30.343):{0x1D6C} {xxx@yyy.com} Sending CICAL_SLOW_SYNC_REQUEST_EVENTS to device. SessionId=1236824187, Total UID requested=0, size=24
[40583] (03/12 13:48:30.343):{0x1D6C} {xxx@yyy.com} Sending packet to device, Size=58, Tag=1140464, TransactionId=-910660198
[40279] (03/12 13:48:30.343):{0x1D6C} {xxx@yyy.com} SubmitToRelaySendQ, Tag=1140464
[30249] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com} Sending 95 calendar entries to the device, size=15886
[40583] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com} Sending packet to device, Size=15921, Tag=1140465, TransactionId=-910660197
[40279] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com} SubmitToRelaySendQ, Tag=1140465
[30249] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com} Sending 102 calendar entries to the device, size=15939
[40583] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com} Sending packet to device, Size=15974, Tag=1140466, TransactionId=-910660196
[40279] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com} SubmitToRelaySendQ, Tag=1140466
[30249] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com} Sending 12 calendar entries to the device, size=1434
[40583] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com} Sending packet to device, Size=1469, Tag=1140467, TransactionId=-910660195
[40279] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com} SubmitToRelaySendQ, Tag=1140467
[40000] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com} Sending CAL_SLOW_SYNC_DONE to device. SessionID=1236824187, Record counts=209
[40583] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com} Sending packet to device, Size=52, Tag=1140468, TransactionId=-910660194
[40279] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com} SubmitToRelaySendQ, Tag=1140468
[40000] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com}-UserControl::SlowSyncComplete-Entering SessID=49b8707b
[40000] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com}-UserControl::SlowSyncComplete-Exits result=OK
[40000] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com}-UserControl::ProcessSLOW_SYNC-Complete Slow Sync-Purge received records
[40000] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com}-UserControl::ProcessSLOW_SYNC-Exits-bSuccess=OK
[40000] (03/12 13:48:30.358):{0x1D6C} HandleCicalSlowSyncCommand-Exits result=OK
[40279] (03/12 13:48:30.358):{0x1D6C} {xxx@yyy.com} SubmitToRelaySendQ, Tag=3148935
40724] (03/12 13:48:30.468):{0x1D6C} {xxx@yyy.com} Get record key for this MAPI object, EntryId=102486
[40435] (03/12 13:48:30.937):{0x1D6C} {xxx@yyy.com} Queuing new mail through notification. EntryId=102486. Msgs Pending 0
[40487] (03/12 13:48:30.937):{0x1D6C} {xxx@yyy.com} Not requeuing calendar item EntryId=110701 - same source key as DuplicateEntryId=102482
[40700] (03/12 13:48:30.937):{0x1820} {xxx@yyy.com} Receiving packet from device, size=40, TransactionId=-812242610, Tag=3148937, content type=CMIME, cmd=0x3
[40698] (03/12 13:48:30.937):{0x1820} {xxx@yyy.com} Receiving OTAFM request from device, Tag=3148937, TransactionId=-812242610
[30264] (03/12 13:48:30.937):{0x1820} {xxx@yyy.com} Received FOLDER_LIST_REQUEST from device
[40699] (03/12 13:48:30.937):{0x1820} {xxx@yyy.com} OTAFM request from device processed
[40279] (03/12 13:48:30.937):{0x1820} {xxx@yyy.com} SubmitToRelaySendQ, Tag=3148937
[40000] (03/12 13:48:30.937):{0x1A64} [BIPP] Send status DATA_ACCEPTED, Tag=3148937
[40700] (03/12 13:48:31.140):{0x17FC} {xxx@yyy.com} Receiving packet from device, size=55, TransactionId=-812242609, Tag=3148941, content type=CICAL, cmd=0x3
[40753] (03/12 13:48:31.140):{0x17FC} {xxx@yyy.com} Receiving CICAL_SLOW_SYNC request from device, Tag=3148941, TransactionId=-812242609
[30000] (03/12 13:48:31.140):{0x17FC} {xxx@yyy.com} Received CICAL_SYNC_ABORT from device. SessionId=1236827127, Reason=0x0C
[40000] (03/12 13:48:31.140):{0x17FC} HandleCicalSlowSyncCommand-Exits result=OK
[40279] (03/12 13:48:31.140):{0x17FC} {xxx@yyy.com} SubmitToRelaySendQ, Tag=3148941
[40000] (03/12 13:48:31.140):{0x1A64} [BIPP] Send status DATA_ACCEPTED, Tag=3148941
[40700] (03/12 13:48:31.234):{0x1C18} {xxx@yyy.com} Receiving packet from device, size=55, TransactionId=-812242608, Tag=3148943, content type=CICAL, cmd=0x3
[40753] (03/12 13:48:31.234):{0x1C18} {xxx@yyy.com} Receiving CICAL_SLOW_SYNC request from device, Tag=3148943, TransactionId=-812242608
[30000] (03/12 13:48:31.234):{0x1C18} {xxx@yyy.com} Received CICAL_SYNC_ABORT from device. SessionId=1236824187, Reason=0x04
[40000] (03/12 13:48:31.234):{0x1C18} HandleCicalSlowSyncCommand-Exits result=OK
[40279] (03/12 13:48:31.234):{0x1C18} {xxx@yyy.com} SubmitToRelaySendQ, Tag=3148943
[40000] (03/12 13:48:31.234):{0x1A64} [BIPP] Send status DATA_ACCEPTED, Tag=3148943
[40700] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com} Receiving packet from device, size=70, TransactionId=-812242607, Tag=3148951, content type=CICAL, cmd=0x3
[40753] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com} Receiving CICAL_SLOW_SYNC request from device, Tag=3148951, TransactionId=-812242607
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com}-UserControl::ProcessSLOW_SYNC-Entering
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com}-ParseSlowSyncRecords-Entering
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com} Session ID=0x49b87786
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com} Hash Version=0x10
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com} Total Record Count=0
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com} Slow Sync Start Date=Tue Feb 10 10:46:30 2009
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com} Slow Sync End Date=Tue Jan 19 11:14:07 2038
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com}-ParseSlowSyncRecords-Exits -Received records=0 bSuccess=OK
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com}-CheckSlowSyncCorrelation-Entering, Total Rec Count=0, SessID=0x49b87786, Start Date=Tue Feb 10 10:46:30 2009, Payload=0
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com}-Prv SessID=0x0, Current SessID=0x49b87786, Outstanding Rec Counts=0
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com}-current received=0, Previous received=0
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com}-Session ID=0x49b87786 has zero record counts
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com}-This is a new SlowSync SessID=0x49b87786
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com} CheckSlowSyncCorrelation - Normal SlowSync mode - Exchanges of appts between device and OutLook
[40000] (03/12 13:48:31.234):{0xA18} {xxx@yyy.com}-CheckSlowSyncCorrelation-Exits-bSuccess=OK
[40000] (03/12 13:48:34.078):{0x175C} [BIPP] Received status DELIVERED, Tag=1140464
[40000] (03/12 13:48:34.813):{0x175C} [BIPP] Received datagram, Tag=3149333
[40000] (03/12 13:48:35.610):{0x175C} [BIPP] Received status DELIVERED, Tag=1140465
[40000] (03/12 13:48:37.298):{0x175C} [BIPP] Received status DELIVERED, Tag=1140466
[40000] (03/12 13:48:37.688):{0x175C} [BIPP] Received status DELIVERED, Tag=1140467
[40000] (03/12 13:48:37.688):{0x175C} [BIPP] Received status DELIVERED, Tag=1140468
[40423] (03/12 13:48:48.457):{0x11D8} {xxx@yyy.com} Queuing new mail through notification (external). EntryId=112235
[40608] (03/12 13:50:20.151):{0xA18} {xxx@yyy.com} MAPIMailbox::SpecifyExceptionsToSend - Filtering old exception appointment
<snip; numerous messages of the above type>
[30038] (03/12 14:02:53.865):{0x1450} Worker Thread: *** No Response *** Thread Id=0xA18, Handle=0x288, WaitCount=1, WorkingTime=14 min, LastActivity=14 min, Event: NEW_MESSAGE, User: , Server: tokyo_exchange_server, Activity: Parse Slow Sync Records
[40423] (03/12 14:03:39.861):{0x11D8} {xxx@yyy.com} Queuing new mail through notification (external). EntryId=112979
[30038] (03/12 14:12:54.011):{0x1450} Worker Thread: *** No Response *** Thread Id=0xA18, Handle=0x288, WaitCount=2, WorkingTime=24 min, LastActivity=24 min, Event: NEW_MESSAGE, User: , Server: tokyo_exchange_server, Activity: Parse Slow Sync Records
[40423] (03/12 14:15:28.611):{0x11D8} {xxx@yyy.com} Queuing new mail through notification (external). EntryId=113368
[40230] (03/12 14:17:27.531):{0x11D8} {xxx@yyy.com} Queuing notification of modified appointment (external). EntryId=113397
[30038] (03/12 14:22:54.157):{0x1450} Worker Thread: *** No Response *** Thread Id=0xA18, Handle=0x288, WaitCount=3, WorkingTime=34 min, LastActivity=34 min, Event: NEW_MESSAGE, User: , Server: tokyo_exchange_server, Activity: Parse Slow Sync Records
[40000] (03/12 14:26:41.806):{0xA18} {xxx@yyy.com} UserControl::ProcessSLOW_SYNC - Normal SlowSync Mode - Requesting 0 from device, sending 209 to device
[40000] (03/12 14:26:41.806):{0xA18} {xxx@yyy.com} Sending CICAL_SLOW_SYNC_REQUEST_EVENTS to device. SessionId=1236825990, Total UID requested=0, size=24
[40000] (03/12 14:26:41.806):{0xA18} {xxx@yyy.com} Sending CICAL_SLOW_SYNC_REQUEST_EVENTS to device. SessionId=1236825990, Total UID requested=0, size=24
[40583] (03/12 14:26:41.806):{0xA18} {xxx@yyy.com} Sending packet to device, Size=58, Tag=1140499, TransactionId=-910660193
[40279] (03/12 14:26:41.806):{0xA18} {xxx@yyy.com} SubmitToRelaySendQ, Tag=1140499
[30249] (03/12 14:26:41.806):{0xA18} {xxx@yyy.com} Sending 95 calendar entries to the device, size=15886
[40583] (03/12 14:26:41.806):{0xA18} {xxx@yyy.com} Sending packet to device, Size=15921, Tag=1140500, TransactionId=-910660192
[40279] (03/12 14:26:41.806):{0xA18} {xxx@yyy.com} SubmitToRelaySendQ, Tag=1140500
[30249] (03/12 14:26:41.822):{0xA18} {xxx@yyy.com} Sending 102 calendar entries to the device, size=15939
[40583] (03/12 14:26:41.822):{0xA18} {xxx@yyy.com} Sending packet to device, Size=15974, Tag=1140501, TransactionId=-910660191
[40279] (03/12 14:26:41.822):{0xA18} {xxx@yyy.com} SubmitToRelaySendQ, Tag=1140501
[30249] (03/12 14:26:41.822):{0xA18} {xxx@yyy.com} Sending 12 calendar entries to the device, size=1434
[40583] (03/12 14:26:41.822):{0xA18} {xxx@yyy.com} Sending packet to device, Size=1469, Tag=1140502, TransactionId=-910660190
[40279] (03/12 14:26:41.822):{0xA18} {xxx@yyy.com} SubmitToRelaySendQ, Tag=1140502
[40000] (03/12 14:26:41.822):{0xA18} {xxx@yyy.com} Sending CAL_SLOW_SYNC_DONE to device. SessionID=1236825990, Record counts=209

Assuming a) other users are fine and b) you tried wiping BB, removing and readding user first, what is the ping time between BES and Exch? Ping time is more useful than hops but although RIM want it to be below 35, we all know it will work with a lot higher.

I have >215 between US BES and Aus Exchange and while sync works fine, OTA activation is a nightmare.

Thanks for your comment. That's correct; no users have reported problems with blackberry service and we did try wiping the device and removing/readding the user.

The ping time between the BES server and the Exchange server is about 100ms. What kinds of times are you looking at in terms of activation?

BTW, I called our provider's BB support center and, per their advice, deleted and undeleted the desktop [sync] service book, then cancelled and restarted activation. As a result, the Enterprise Activation screen shows "synchronizing service desktop" (though with no percentage indicator) and many more services appear in an initializing state. Occasionally more services appear.

Support also advised me that, if there is no percentage indicator after some time (didn't specify a time), then I should cancel activation, shut down the BB device, remove the battery for a minute, then replace the battery, turn on the device, and restart activation.

I am not very knowledgable about BB (but am learning!), so I wonder if there's anything I can do to hasten the synchronization process.

Well it's a tough one coz it can take forever and pulling the battery could just restart the 5 hrs+ time but if you aren't seeing log entries showing that it's Busy Working, maybe it's time to cut your losses:

[30399] (03/09 13:24:30.301):{0x13B0} Worker Thread: *** Busy Working *** Thread Id=0x15BC, Handle=0xA4C, BusyCount=9, WorkingTime=92 min, LastActivity=0

(this is what I usually see during a slow sync where BB shows no real progress but work is happening). TBH I think that even though 0% is showing, if you aren't seeing more detail down the list on a particular service book going through it's own progress (like x of y items under Cal for example) it's safe to assume nothing it happening and start again.

Thanks. I didn't see any activity in terms of x of y items so I went ahead and cancelled the activation, took out the battery, etc, and restarted activation. (I had another user's BB to use for testing purposes and, while not exactly the same scenario, his BB did not show any percentage activity either).

The first time the sync failed with a "cannot connect to server"-type message, so I rebooted the BES server and tried to sync again. This time, this message appeared: "an error occurred; please contact your system administrator". Exchange server showed a couple of messages being sent to etp at the same time. I am trying a third time to reactivate the device. Any ideas (like, deleting the user from the BES server)?

Third time is a charm it seems..."the e-mail address is now enabled" with activation at 0%.

That message is significant as it usually means services need restarting, so that's cool.

Yeah that's cool, it means that contact is there and it's just getting confused and probably deleting old keys (logs will show). It will all work soon.....8-)

Cool yeah that's what I thought would happen after your last post. OK so now slow sync is happening and you will be able to monitor that from the logs and eventually the BB (you will probably see the x/y figures against calendar). This bit can take hours so as long as you see progress there and/or busy working entries in the log, just sit back and drink tea 8-)

Much obliged, stuwhite ...and sure enough I can see in event viewer:

(TIME)-followed my description
//////////
(2100)-{username} Old OTAKEYGEN packet is cancelled, Tag=4592359
(2108)-{username} Old OTAKEYGEN packet is cancelled, Tag=4592415
(2108)-[AUDIT] (user's e-mail address) - User activated on the BES
///

but then this warning appears:

(2109)-{username, PIN=(PINNUMBER, UserId=249}RequestHandler::HandleSERVICE_BOOKDataC ommand - Incomplete ACK data for SERVICE_BOOK request

I can also see messages have arrived with timestamps of from 2100 to 2103.

Is that service book warning a cause for concern?

TBH I don't know but I wouldn't worry for now. Once fully activated, check it all works and if it does, it's cool. If you still get this message you can resend the service book later and see if it cures it. So many error messages are pointless and can be ignored that I only worry when something doesn't actually work and there is an error message (but someone might come along later and say it is cause for concern 8-)).

Thanks stuwhite, I found a link that suggested resending the service book; I tried that and it went fine. Well, I can see a lot of activity in the MAGT log so I'll come back to it tomorrow and see what progress has been made. I'll keep posting here with what I find. Again, thanks! ;-)

No worries mate. TBH these days with dodgy activations I just retry a few times, then wipe and delete user and evetually it always works. The trick is knowing after how many hours to call it a day and pull that battery, I still haven't worked that bit out 8-)

Wow, pings times over 215. It's a wonder you're still working. By the way, RIM does not want it below 35, Microsoft does. MAPI is not designed to handle high ping times, so RIM has to follow Microsoft specs on that.

It's no surprise that EA takes a long time, especially with users that have large mailboxes.

But, as long as the users don't see any issues and you don get blocked worker threads yet. I will warn you though, I don't know how long this setup has been working but at some point it will more than likely break. It always has in my experience, just don't call RIM because the only thing they will tell you to do is place the BES closer to Exchange.

Well RIM told us "35 but we let you get away with up to 75", but either way we sort of blow that out of the water 8-). I know it is unsupported by RIM but most of what we do is in some way <g>.

Oh yeah I know it's not good but it's been there for about 4 years and still doing the do. I will put a BES over there at some point but we just don't get enough complaints to justify it. Once they are running, their BBs generally fly :-o

Just to let you know stuwhite that the BB did sync overnight after all. Though the address book sync is incomplete, everything else is fine. Thanks very much for your guidance :smile:

Anytime mate, I didn't really do much this time though 8-)