[paulblackberry]

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