[timread]

I have a BES user with an 8300 BB.

They're normally based in Melbourne, Australia but this week they're in NZ. They've reported that the BB was working for the first day or two, but is now not synchronizing with Outlook.

Looking at the MAGT logs, I'm seeing a lot of SLOW_SYNC events for this user. Is this normal? They wiped & activated their BB about 2 weeks ago, but had a lot of problems before that.

[40000] (05/21 13:41:31.560):{0x1130} {user@BES} UserControl::ProcessSLOW_SYNC - Normal SlowSync Mode - Requesting 2 from device, sending 8 to device
[40000] (05/21 13:41:31.560):{0x1130} {user@BES}-will request 8 simple or exception appointments
[40000] (05/21 13:41:31.560):{0x1130} {user@BES}-Server requests simple appointment UID=-290723032 from device
[40000] (05/21 13:41:31.560):{0x1130} {user@BES}-Server requests simple appointment UID=-1703816444 from device
[40000] (05/21 13:41:31.560):{0x1130} {user@BES} Sending CICAL_SLOW_SYNC_REQUEST_EVENTS to device. SessionId=1211239573, Total UID requested=2, size=36
[40583] (05/21 13:41:31.560):{0x1130} {user@BES} Sending packet to device, Size=71, Tag=603522, TransactionId=-936577424
[40279] (05/21 13:41:31.560):{0x1130} {user@BES} SubmitToRelaySendQ, Tag=603522
[30249] (05/21 13:41:31.560):{0x1130} {user@BES} Sending 8 calendar entries to the device, size=1687
[40583] (05/21 13:41:31.560):{0x1130} {user@BES} Sending packet to device, Size=1723, Tag=603523, TransactionId=-936577423
[40279] (05/21 13:41:31.560):{0x1130} {user@BES} SubmitToRelaySendQ, Tag=603523
[40000] (05/21 13:41:31.560):{0x1130} {user@BES} Sending CAL_SLOW_SYNC_DONE to device. SessionID=1211239573, Record counts=8
[40583] (05/21 13:41:31.560):{0x1130} {user@BES} Sending packet to device, Size=53, Tag=603524, TransactionId=-936577422
[40279] (05/21 13:41:31.560):{0x1130} {user@BES} SubmitToRelaySendQ, Tag=603524
[40000] (05/21 13:41:31.560):{0x1130} {user@BES}-UserControl::SlowSyncComplete-Entering SessID=48320c95
[40000] (05/21 13:41:31.560):{0x1130} {user@BES}-UserControl::SlowSyncComplete-Waiting for 2 calendar items from device
[40000] (05/21 13:41:31.560):{0x1130} {user@BES}-UserControl::SlowSyncComplete-Exits result=OK
[40000] (05/21 13:41:31.560):{0x1130} {user@BES}-UserControl::ProcessSLOW_SYNC-Complete Slow Sync-Purge received records
[40000] (05/21 13:41:31.560):{0x1130} {user@BES}-UserControl::ProcessSLOW_SYNC-Exits-bSuccess=OK
[40000] (05/21 13:41:31.560):{0x1130} HandleCicalSlowSyncCommand-Exits result=OK
[40279] (05/21 13:41:31.560):{0x1130} {user@BES} SubmitToRelaySendQ, Tag=613073
[40000] (05/21 13:41:31.560):{0xB1C} [BIPP] Send data, Tag=603522
[40000] (05/21 13:41:31.560):{0xB1C} [BIPP] Send data, Tag=603523
[40000] (05/21 13:41:31.560):{0xB1C} [BIPP] Send data, Tag=603524
[40000] (05/21 13:41:31.560):{0xB1C} [BIPP] Send status DATA_ACCEPTED, Tag=613073
[40700] (05/21 13:41:31.669):{0x7F4} {user@BES} Receiving packet from device, size=2855, TransactionId=-1186728102, Tag=613074, content type=CICAL, cmd=0x3
[40753] (05/21 13:41:31.669):{0x7F4} {user@BES} Receiving CICAL_SLOW_SYNC request from device, Tag=613074, TransactionId=-1186728102
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES}-UserControl::ProcessSLOW_SYNC-Entering
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES}-ParseSlowSyncRecords-Entering
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} Session ID=0x48320c95
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} Hash Version=0x10
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} Total Record Count=121
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} Slow Sync Start Date=Sat Apr 19 19:26:13 2008
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} Slow Sync End Date=Mon Jan 18 22:14:07 2038
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} UID=-290723032 Received UIDCount=1
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} Event flag=0x0
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} Key Hash=165907094c2e
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} Record Hash=0xf3ce15f3
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} UID=-580989655 Received UIDCount=2
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} Event flag=0x0
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} Key Hash=53207bf9ede7
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} Record Hash=0x9cbb67e9
[40000] (05/21 13:41:31.669):{0x7F4} {user@BES} UID=-42786373 Received UIDCount=3
....
The UID count gets up to 120, and then completes with:

[40000] (05/21 20:43:19.131):{0x1560} {user@BES}-ParseSlowSyncRecords-Exits -Received records=121 bSuccess=OK
[40000] (05/21 20:43:19.131):{0x1560} {user@BES}-CheckSlowSyncCorrelation-Entering, Total Rec Count=121, SessID=0x48320c95, Start Date=Sat Apr 19 19:26:13 2008, Payload=0
[40000] (05/21 20:43:19.131):{0x1560} {user@BES}-Prv SessID=0x0, Current SessID=0x48320c95, Outstanding Rec Counts=0
[40000] (05/21 20:43:19.131):{0x1560} {user@BES}-current received=121, Previous received=0
[40000] (05/21 20:43:19.131):{0x1560} {user@BES}-This is a new SlowSync SessID=0x48320c95
[40000] (05/21 20:43:19.131):{0x1560} {user@BES} CheckSlowSyncCorrelation - Normal SlowSync mode - Exchanges of appts between device and OutLook
[40000] (05/21 20:43:19.131):{0x1560} {user@BES}-CheckSlowSyncCorrelation-Exits-bSuccess=OK
[40000] (05/21 20:43:19.131):{0xB1C} [BIPP] Send status DATA_ACCEPTED, Tag=614768
[40000] (05/21 20:43:19.131):{0xB1C} [BIPP] Send status DATA_ACCEPTED, Tag=614789

[timread]

I'm also the following logged against this user:

[40000] (05/21 20:45:20.963):{0x1560} {user@BES}-GetTZIndexByTZName-Unrecognized time zone string GMT +1000 (Standard) / GMT +1000 (Daylight)
[30000] (05/21 20:45:20.963):{0x1560} {user@BES}-GetRIMCalendar(EntryID)- GetTZIndexByTZName() failed Entry tag =1580801

Is this because they've not updated the timezone information on their BB, being that they are currently in a different timezone from usual?

[Headbolt]

Do you have mailboxes on more than 1 server.

If you have a small number of threads and a lot of servers it can sometimes take a while for the thread to pick up the mails

[timread]

Yes, we have 160 users on the BES Server, accessing user mailboxes on 3 Exchange 2007 mailbox servers (two EXCH 2007 mailbox servers in the US in different sites, which covers most of the users, and about 40 users on an EXCH 2007 mailbox server in the UK).

Blackberry dispatcher and MAGT logs show that the BES server has been communicating regularly with the user's BB over the course of this week, but as at yesterday the user was still reporting not receiving any mail on the device.

How do I find out how many threads the BB server has dedicated?

[dege13]

The CICAL_SLOW_SYNC took under 2 min to read the calendar, that's not too bad.
How many times has it done the CICAL_SLOW_SYNC fro this user?

It is the device requesting the CICAL_SLOW_SYNC. So either calendar is being disabled and re-enabled over and over again on the device, or there is some other reason the device keeps requesting a CICAL_SLOW_SYNC.

Get device event logs, and look for "net.rim.calendar.ota data:SYNC". This is the start of a slow sync request for calendar on the device.

[timread]

Just an update, thanks for your suggestions all - the user's BB eventually sprang into action when they travelled to a different city in NZ - it wasn't working at all in Wellington, but starting working when they arrived in Palmerston North.