Strange Reconciliation

whyerd · #1 (**permalink**) 04-03-2009, 04:20 PM

So this one has me baffled. We are running BES 4.1.6 MR3 with Exchange 2003. The BES now seems to think that at some point all messages on the users Inbox have been moved and reconciliation removes the message from the handheld. This is only affecting the Inbox items so I know it's not a memory issue on the handheld (some have over 12MB free). I have confirmed through OWA that the message are in fact still in the user's mailbox. I have opened a ticket with RIM and they claim that the message was moved (according to the logs). The logs do in fact state the message has been moved when on Exchange it has not. This is happening across handheld devices/OS's/wireless providers. I am coming back to the BES as the problem. For further testing I have asked the affected users to not move or delete any messages from their mailboxes for the next 48 hours (this has been a daily occurance). I am also moving Exchange servers for another user. So far the only fix is to have the user disable reconciliation.

Has anyone else come across this?

Thanks for the time.

hdawg · #2 (**permalink**) 04-06-2009, 08:14 AM

To be honest I've not heard of something like this.

Does it happen with all users? When did it start happening? Were there any upgrades / changes during the time this started happening?

Is BES on its own machine?

Otto · #3 (**permalink**) 04-06-2009, 10:16 AM

Can you also paste some of the log lines of the message move here, as well? I'd be curious if it specifies an actual folder ID for the move. Also, do you have 'hard delete' reconciliation support enabled?

whyerd · #4 (**permalink**) 04-06-2009, 02:59 PM

Otto, I think you are on to something. It does seem rather strange on why this is happening. I have included a segment of our Agent logs that pertain to this issue. Thanks for the help and insight. The upoad of the file isn't working so sorry for the long post due to the logs.

[40708] (04/06 04:51:01.298):{0x580} {First.Last@company.com} Queuing notification of created folder
[40908] (04/06 04:51:01.845):{0x26B8} {First.Last@company.com} GetAndCreateFolderInfo - Search folder notification, not syncing to device
[40602] (04/06 04:51:01.845):{0x26B8} {First.Last@company.com} Created folder not sent to device
[40178] (04/06 04:51:05.298):{0x580} {First.Last@company.com} MAPIMailbox::OnNotify - search complete event
[40233] (04/06 04:51:05.298):{0x580} {First.Last@company.com} Queuing notification of deleted folder
[40724] (04/06 04:51:05.298):{0x3794} {First.Last@company.com} Get record key for this MAPI object, EntryId=4509
[40405] (04/06 04:51:05.298):{0x3794} {First.Last@company.com} MAPIMailbox::OpenMessage - OpenEntry (0x8004010f) failed
[40719] (04/06 04:51:05.298):{0x26B8} {First.Last@company.com} GetFolderIDFromList No folder ID in list for EntryID
[40603] (04/06 04:51:05.298):{0x26B8} {First.Last@company.com} Deleted folder not sent to device. FolderId=0
[40708] (04/06 04:51:06.314):{0x580} {First.Last@company.com} Queuing notification of created folder
[40908] (04/06 04:51:07.564):{0x3794} {First.Last@company.com} GetAndCreateFolderInfo - Search folder notification, not syncing to device
[40602] (04/06 04:51:07.564):{0x3794} {First.Last@company.com} Created folder not sent to device
[40178] (04/06 04:51:09.298):{0x580} {First.Last@company.com} MAPIMailbox::OnNotify - search complete event
[40233] (04/06 04:51:10.298):{0x580} {First.Last@company.com} Queuing notification of deleted folder
[40724] (04/06 04:51:10.298):{0x3794} {First.Last@company.com} Get record key for this MAPI object, EntryId=4511
[40405] (04/06 04:51:10.298):{0x3794} {First.Last@company.com} MAPIMailbox::OpenMessage - OpenEntry (0x8004010f) failed
[40719] (04/06 04:51:10.298):{0x3794} {First.Last@company.com} GetFolderIDFromList No folder ID in list for EntryID
[40603] (04/06 04:51:10.298):{0x3794} {First.Last@company.com} Deleted folder not sent to device. FolderId=0
[40708] (04/06 04:51:11.298):{0x580} {First.Last@company.com} Queuing notification of created folder
[40178] (04/06 04:51:11.298):{0x580} {First.Last@company.com} MAPIMailbox::OnNotify - search complete event
[40908] (04/06 04:51:11.298):{0x26B8} {First.Last@company.com} GetAndCreateFolderInfo - Search folder notification, not syncing to device
[40602] (04/06 04:51:11.298):{0x26B8} {First.Last@company.com} Created folder not sent to device
[40233] (04/06 04:51:13.298):{0x580} {First.Last@company.com} Queuing notification of deleted folder
[40724] (04/06 04:51:13.298):{0x26B8} {First.Last@company.com} Get record key for this MAPI object, EntryId=4513
[40405] (04/06 04:51:13.298):{0x26B8} {First.Last@company.com} MAPIMailbox::OpenMessage - OpenEntry (0x8004010f) failed
[40719] (04/06 04:51:13.298):{0x26B8} {First.Last@company.com} GetFolderIDFromList No folder ID in list for EntryID
[40603] (04/06 04:51:13.298):{0x26B8} {First.Last@company.com} Deleted folder not sent to device. FolderId=0
[40702] (04/06 04:51:15.689):{0x3794} {First.Last@company.com} Starting message rescan
[40703] (04/06 04:51:15.689):{0x3794} {First.Last@company.com} Message rescan completed
[40000] (04/06 04:52:00.314):{0x3358} [BIPP] Ping 510 sent
[40000] (04/06 04:52:00.314):{0x30FC} [BIPP] PingResponse 510 received
[40853] (04/06 04:52:22.564):{0x3794} {Keith.Cassettari@company.com} Starting Tasks rescan
[40891] (04/06 04:52:22.564):{0x3794} {Keith.Cassettari@company.com} No changes detected, rescan complete (type=Tasks)
[40000] (04/06 04:53:00.314):{0x3358} [BIPP] Ping 511 sent
[40000] (04/06 04:53:00.314):{0x30FC} [BIPP] PingResponse 511 received
[40694] (04/06 04:53:31.298):{0x3794} {First.Last@company.com} Starting reload folders
[40708] (04/06 04:53:31.329):{0x3794} {First.Last@company.com} Queuing notification of created folder
[40717] (04/06 04:53:31.392):{0x3794} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-61, ParentFolderID=-60, FolderNameHash=10568351, SyncInProgress=true, Redirected=0
[40707] (04/06 04:53:31.407):{0x3794} {First.Last@company.com} Queuing notification of modified folder
[40707] (04/06 04:53:31.439):{0x3794} {First.Last@company.com} Queuing notification of modified folder
[40707] (04/06 04:53:31.501):{0x3794} {First.Last@company.com} Queuing notification of modified folder
[40707] (04/06 04:53:31.501):{0x3794} {First.Last@company.com} Queuing notification of modified folder
[40707] (04/06 04:53:31.548):{0x3794} {First.Last@company.com} Queuing notification of modified folder
[40707] (04/06 04:53:31.548):{0x3794} {First.Last@company.com} Queuing notification of modified folder
[40707] (04/06 04:53:31.548):{0x3794} {First.Last@company.com} Queuing notification of modified folder
[40707] (04/06 04:53:31.548):{0x3794} {First.Last@company.com} Queuing notification of modified folder
[40718] (04/06 04:53:31.657):{0x3794} {First.Last@company.com} SetSubFolderIDs - Saved SubFolders State. FolderID=-61, NumOfSubFolders=8
[40718] (04/06 04:53:31.907):{0x3794} {First.Last@company.com} SetSubFolderIDs - Saved SubFolders State. FolderID=-60, NumOfSubFolders=7
[40233] (04/06 04:53:31.907):{0x3794} {First.Last@company.com} Queuing notification of deleted folder
[41079] (04/06 04:53:32.298):{0x3794} {First.Last@company.com} PagerImp::SaveChanges: changed items = 60 Size = 4
[40865] (04/06 04:53:32.298):{0x3794} {First.Last@company.com} Queuing SEND_FOLDER_CHANGE for device folderID=-61, parentfolderID=-60, redirected=1
[40695] (04/06 04:53:32.298):{0x3794} {First.Last@company.com} Reload folders completed
[30251] (04/06 04:53:32.298):{0x26B8} {First.Last@company.com} Queuing DELETE_FOLDER for device folderID=-59, deletebitmask = 3
[30253] (04/06 04:53:32.298):{0x3794} {First.Last@company.com} Queuing CREATE_FOLDER for device folderID=-61, parentfolderID=-60
[40717] (04/06 04:53:32.439):{0x3794} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-31, ParentFolderID=-59, FolderNameHash=2545728, SyncInProgress=true, Redirected=0
[30252] (04/06 04:53:32.454):{0x3794} {First.Last@company.com} Queuing MODIFY_FOLDER for device folderID=-31, parentfolderID=-61
[40717] (04/06 04:53:32.454):{0x26B8} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-21, ParentFolderID=-59, FolderNameHash=3922949, SyncInProgress=true, Redirected=0
[30252] (04/06 04:53:32.454):{0x26B8} {First.Last@company.com} Queuing MODIFY_FOLDER for device folderID=-21, parentfolderID=-61
[40717] (04/06 04:53:32.454):{0x3794} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-4, ParentFolderID=-59, FolderNameHash=11472819, SyncInProgress=true, Redirected=0
[30252] (04/06 04:53:32.454):{0x3794} {First.Last@company.com} Queuing MODIFY_FOLDER for device folderID=-4, parentfolderID=-61
[40717] (04/06 04:53:32.470):{0x26B8} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-5, ParentFolderID=-59, FolderNameHash=8698316, SyncInProgress=true, Redirected=0
[30252] (04/06 04:53:32.470):{0x26B8} {First.Last@company.com} Queuing MODIFY_FOLDER for device folderID=-5, parentfolderID=-61
[40717] (04/06 04:53:32.470):{0x3794} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-6, ParentFolderID=-59, FolderNameHash=664711, SyncInProgress=true, Redirected=0
[30252] (04/06 04:53:32.470):{0x3794} {First.Last@company.com} Queuing MODIFY_FOLDER for device folderID=-6, parentfolderID=-61
[40717] (04/06 04:53:32.486):{0x26B8} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-7, ParentFolderID=-59, FolderNameHash=11934456, SyncInProgress=true, Redirected=0
[30252] (04/06 04:53:32.486):{0x26B8} {First.Last@company.com} Queuing MODIFY_FOLDER for device folderID=-7, parentfolderID=-61
[40717] (04/06 04:53:32.486):{0x3794} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-20, ParentFolderID=-59, FolderNameHash=14969136, SyncInProgress=true, Redirected=0
[30252] (04/06 04:53:32.486):{0x3794} {First.Last@company.com} Queuing MODIFY_FOLDER for device folderID=-20, parentfolderID=-61
[40717] (04/06 04:53:32.501):{0x26B8} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-32, ParentFolderID=-59, FolderNameHash=12205266, SyncInProgress=true, Redirected=0
[30252] (04/06 04:53:32.501):{0x26B8} {First.Last@company.com} Queuing MODIFY_FOLDER for device folderID=-32, parentfolderID=-61
[40865] (04/06 04:53:32.517):{0x3794} {First.Last@company.com} Queuing SEND_FOLDER_CHANGE for device folderID=-61, parentfolderID=-60, redirected=0
[40865] (04/06 04:53:32.517):{0x3794} {First.Last@company.com} Queuing SEND_FOLDER_CHANGE for device folderID=-61, parentfolderID=-60, redirected=1
[30066] (04/06 04:53:32.517):{0x3794} Total Msgs Pending 11
[40442] (04/06 04:53:32.517):{0x3794} User settings: email=First.Last@company.com, routing=S1390478, service=AMERIBB2, device=246304B6, calendar=1, MDS=1, userOTAFM=63, incradle=0, SMIME=0, sentItems=1, dir=JENNIFER CROWLEY, server=BOSEXCH14
[30290] (04/06 04:53:32.517):{0x26B8} {First.Last@company.com} sending OTAFM command to device, transactionId=-908506797, Tag=2750152, size=64
[40279] (04/06 04:53:32.517):{0x26B8} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750152
[30066] (04/06 04:53:32.517):{0x26B8} Total Msgs Pending 13
[40000] (04/06 04:53:32.517):{0x3358} [BIPP] Send data, Tag=2750152
[30290] (04/06 04:53:32.517):{0x3794} {First.Last@company.com} sending OTAFM command to device, transactionId=-908506796, Tag=2750153, size=48
[40279] (04/06 04:53:32.517):{0x3794} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750153
[40000] (04/06 04:53:32.517):{0x3358} [BIPP] Send data, Tag=2750153
[30290] (04/06 04:53:32.517):{0x26B8} {First.Last@company.com} sending OTAFM command to device, transactionId=-908506795, Tag=2750154, size=64
[40279] (04/06 04:53:32.517):{0x26B8} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750154
[40000] (04/06 04:53:32.517):{0x3358} [BIPP] Send data, Tag=2750154
[30290] (04/06 04:53:32.517):{0x3794} {First.Last@company.com} sending OTAFM command to device, transactionId=-908506794, Tag=2750155, size=66
[40279] (04/06 04:53:32.517):{0x3794} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750155
[40000] (04/06 04:53:32.517):{0x3358} [BIPP] Send data, Tag=2750155
[30290] (04/06 04:53:32.517):{0x26B8} {First.Last@company.com} sending OTAFM command to device, transactionId=-908506793, Tag=2750156, size=80
[40279] (04/06 04:53:32.517):{0x26B8} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750156
[40000] (04/06 04:53:32.517):{0x3358} [BIPP] Send data, Tag=2750156
[40000] (04/06 04:53:33.829):{0x30FC} [BIPP] Received status DELIVERED, Tag=2750152
[30267] (04/06 04:53:33.829):{0x3794} {First.Last@company.com} OTAFM command has been DELIVERED to device, Tag=2750152
[40717] (04/06 04:53:33.845):{0x3794} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-61, ParentFolderID=-60, FolderNameHash=10568351, SyncInProgress=false, Redirected=1
[30066] (04/06 04:53:33.845):{0x3794} Total Msgs Pending 12
[30290] (04/06 04:53:33.845):{0x26B8} {First.Last@company.com} sending OTAFM command to device, transactionId=-908506792, Tag=2750157, size=68
[40279] (04/06 04:53:33.845):{0x26B8} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750157
[40000] (04/06 04:53:33.845):{0x3358} [BIPP] Send data, Tag=2750157
[40000] (04/06 04:53:35.361):{0x30FC} [BIPP] Received status DELIVERED, Tag=2750153
[30267] (04/06 04:53:35.361):{0x26B8} {First.Last@company.com} OTAFM command has been DELIVERED to device, Tag=2750153
[40718] (04/06 04:53:35.361):{0x26B8} {First.Last@company.com} SetSubFolderIDs - Saved SubFolders State. FolderID=-60, NumOfSubFolders=6
[30066] (04/06 04:53:35.361):{0x26B8} Total Msgs Pending 11
[30290] (04/06 04:53:35.361):{0x3794} {First.Last@company.com} sending OTAFM command to device, transactionId=-908506791, Tag=2750158, size=86
[40279] (04/06 04:53:35.361):{0x3794} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750158
[40000] (04/06 04:53:35.361):{0x3358} [BIPP] Send data, Tag=2750158
[40000] (04/06 04:53:35.392):{0x30FC} [BIPP] Received status DELIVERED, Tag=2750154
[30267] (04/06 04:53:35.392):{0x3794} {First.Last@company.com} OTAFM command has been DELIVERED to device, Tag=2750154
[40717] (04/06 04:53:35.392):{0x3794} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-61, ParentFolderID=-60, FolderNameHash=10568351, SyncInProgress=false, Redirected=1
[30066] (04/06 04:53:35.392):{0x3794} Total Msgs Pending 10
[30290] (04/06 04:53:35.392):{0x26B8} {First.Last@company.com} sending OTAFM command to device, transactionId=-908506790, Tag=2750159, size=74
[40279] (04/06 04:53:35.392):{0x26B8} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750159
[40000] (04/06 04:53:35.392):{0x3358} [BIPP] Send data, Tag=2750159
[40000] (04/06 04:53:35.423):{0x30FC} [BIPP] Received status DELIVERED, Tag=2750155
[30267] (04/06 04:53:35.423):{0x26B8} {First.Last@company.com} OTAFM command has been DELIVERED to device, Tag=2750155
[40717] (04/06 04:53:35.439):{0x26B8} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-31, ParentFolderID=-61, FolderNameHash=2545728, SyncInProgress=false, Redirected=0
[30066] (04/06 04:53:35.439):{0x26B8} Total Msgs Pending 9
[30290] (04/06 04:53:35.439):{0x3794} {First.Last@company.com} sending OTAFM command to device, transactionId=-908506789, Tag=2750160, size=69
[40279] (04/06 04:53:35.439):{0x3794} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750160
[40000] (04/06 04:53:35.439):{0x3358} [BIPP] Send data, Tag=2750160
[40000] (04/06 04:53:35.751):{0x30FC} [BIPP] Received status DELIVERED, Tag=2750156
[30267] (04/06 04:53:35.751):{0x3794} {First.Last@company.com} OTAFM command has been DELIVERED to device, Tag=2750156
[40717] (04/06 04:53:35.767):{0x3794} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-21, ParentFolderID=-61, FolderNameHash=3922949, SyncInProgress=false, Redirected=0
[30066] (04/06 04:53:35.767):{0x3794} Total Msgs Pending 8
[30290] (04/06 04:53:35.767):{0x26B8} {First.Last@company.com} sending OTAFM command to device, transactionId=-908506788, Tag=2750161, size=73
[40279] (04/06 04:53:35.767):{0x26B8} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750161
[40000] (04/06 04:53:35.767):{0x3358} [BIPP] Send data, Tag=2750161
[40000] (04/06 04:53:35.798):{0x30FC} [BIPP] Received status DELIVERED, Tag=2750157
[30267] (04/06 04:53:35.798):{0x26B8} {First.Last@company.com} OTAFM command has been DELIVERED to device, Tag=2750157
[40717] (04/06 04:53:35.798):{0x26B8} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-4, ParentFolderID=-61, FolderNameHash=11472819, SyncInProgress=false, Redirected=0
[30066] (04/06 04:53:35.798):{0x26B8} Total Msgs Pending 7
[30290] (04/06 04:53:35.798):{0x3794} {First.Last@company.com} sending OTAFM command to device, transactionId=-908506787, Tag=2750162, size=73
[40279] (04/06 04:53:35.798):{0x3794} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750162
[40000] (04/06 04:53:35.798):{0x3358} [BIPP] Send data, Tag=2750162
[40000] (04/06 04:53:35.845):{0x30FC} [BIPP] Received status DELIVERED, Tag=2750158
[30267] (04/06 04:53:35.845):{0x3794} {First.Last@company.com} OTAFM command has been DELIVERED to device, Tag=2750158
[40717] (04/06 04:53:35.861):{0x3794} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-5, ParentFolderID=-61, FolderNameHash=8698316, SyncInProgress=false, Redirected=0
[30066] (04/06 04:53:35.861):{0x3794} Total Msgs Pending 6
[30290] (04/06 04:53:35.861):{0x26B8} {First.Last@company.com} sending OTAFM command to device, transactionId=-908506786, Tag=2750163, size=64
[40279] (04/06 04:53:35.861):{0x26B8} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750163
[40000] (04/06 04:53:35.861):{0x3358} [BIPP] Send data, Tag=2750163
[40000] (04/06 04:53:35.939):{0x30FC} [BIPP] Received status DELIVERED, Tag=2750159
[30267] (04/06 04:53:35.939):{0x26B8} {First.Last@company.com} OTAFM command has been DELIVERED to device, Tag=2750159
[40717] (04/06 04:53:35.939):{0x26B8} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-6, ParentFolderID=-61, FolderNameHash=664711, SyncInProgress=false, Redirected=0
[30066] (04/06 04:53:35.939):{0x26B8} Total Msgs Pending 5
[30290] (04/06 04:53:35.939):{0x3794} {First.Last@company.com} sending OTAFM command to device, transactionId=-908506785, Tag=2750164, size=64
[40279] (04/06 04:53:35.939):{0x3794} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750164
[40000] (04/06 04:53:35.939):{0x3358} [BIPP] Send data, Tag=2750164
[40000] (04/06 04:53:36.017):{0x30FC} [BIPP] Received status DELIVERED, Tag=2750160
[30267] (04/06 04:53:36.017):{0x3794} {First.Last@company.com} OTAFM command has been DELIVERED to device, Tag=2750160
[40717] (04/06 04:53:36.017):{0x3794} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-7, ParentFolderID=-61, FolderNameHash=11934456, SyncInProgress=false, Redirected=0
[30066] (04/06 04:53:36.017):{0x3794} Total Msgs Pending 4
[40000] (04/06 04:53:36.251):{0x30FC} [BIPP] Received status DELIVERED, Tag=2750161
[30267] (04/06 04:53:36.251):{0x3794} {First.Last@company.com} OTAFM command has been DELIVERED to device, Tag=2750161
[40717] (04/06 04:53:36.267):{0x3794} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-20, ParentFolderID=-61, FolderNameHash=14969136, SyncInProgress=false, Redirected=0
[30066] (04/06 04:53:36.267):{0x3794} Total Msgs Pending 3
[40000] (04/06 04:53:36.470):{0x30FC} [BIPP] Received status DELIVERED, Tag=2750162
[30267] (04/06 04:53:36.470):{0x3794} {First.Last@company.com} OTAFM command has been DELIVERED to device, Tag=2750162
[40000] (04/06 04:53:36.470):{0x30FC} [BIPP] Received status DELIVERED, Tag=2750163
[40000] (04/06 04:53:36.470):{0x30FC} [BIPP] Received status DELIVERED, Tag=2750164
[40717] (04/06 04:53:36.486):{0x3794} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-32, ParentFolderID=-61, FolderNameHash=12205266, SyncInProgress=false, Redirected=0
[30066] (04/06 04:53:36.486):{0x3794} Total Msgs Pending 2
[30267] (04/06 04:53:36.486):{0x26B8} {First.Last@company.com} OTAFM command has been DELIVERED to device, Tag=2750163
[40717] (04/06 04:53:36.486):{0x26B8} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-61, ParentFolderID=-60, FolderNameHash=10568351, SyncInProgress=false, Redirected=1
[30066] (04/06 04:53:36.486):{0x26B8} Total Msgs Pending 1
[30267] (04/06 04:53:36.486):{0x3794} {First.Last@company.com} OTAFM command has been DELIVERED to device, Tag=2750164
[40717] (04/06 04:53:36.486):{0x3794} {First.Last@company.com} SetFolderState - Saved Folder State. FolderID=-61, ParentFolderID=-60, FolderNameHash=10568351, SyncInProgress=false, Redirected=1
[30066] (04/06 04:53:36.486):{0x3794} Total Msgs Pending 0
[30247] (04/06 04:54:19.064):{0x36C8} Server stats - Msgs: Forwarded 65597613, Sent 3228115, Pending 3338, Expired 2716, Filtered 2315723
[40000] (04/06 04:54:36.470):{0x3358} [BIPP] Ping 512 sent
[40000] (04/06 04:54:36.470):{0x30FC} [BIPP] PingResponse 512 received
[40267] (04/06 04:54:37.314):{0x3794} {Keith.Cassettari@company.com} Starting calendar rescan
[40701] (04/06 04:54:37.314):{0x3794} {Keith.Cassettari@company.com} Calendar rescan completed
[40692] (04/06 04:55:05.689):{0x26B8} {First.Last@company.com} Starting message moved rescan
[40586] (04/06 04:55:05.986):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-752687044
[40586] (04/06 04:55:06.001):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-446378813
[40586] (04/06 04:55:06.017):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-140070582
[40586] (04/06 04:55:06.032):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1981245998
[40586] (04/06 04:55:06.079):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-615497131
[40586] (04/06 04:55:06.142):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-309188900
[40586] (04/06 04:55:06.173):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-2880669
[40586] (04/06 04:55:06.204):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1844056085
[40586] (04/06 04:55:06.204):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1537747854
[40586] (04/06 04:55:06.220):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1231439623
[40586] (04/06 04:55:06.236):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-275313424
[40586] (04/06 04:55:06.251):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-2116488840
[40586] (04/06 04:55:06.267):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1810180609
[40586] (04/06 04:55:06.282):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1503872378
[40586] (04/06 04:55:06.282):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1197564147
[40586] (04/06 04:55:06.345):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-891255916
[40586] (04/06 04:55:06.376):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-584947685
[40586] (04/06 04:55:06.392):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-278639454
[40586] (04/06 04:55:06.423):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1507198408
[40586] (04/06 04:55:06.423):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1200890177
[40586] (04/06 04:55:06.439):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-588273715
[40586] (04/06 04:55:06.439):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-281965484
[40586] (04/06 04:55:06.439):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1816832669
[40586] (04/06 04:55:06.439):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-591599745
[40586] (04/06 04:55:06.439):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-2126466930
[40586] (04/06 04:55:06.454):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1513850468
[40586] (04/06 04:55:06.454):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-2129792960
[40586] (04/06 04:55:06.470):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1210868267
[40586] (04/06 04:55:06.470):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1826810759
[40586] (04/06 04:55:06.501):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-2139771050
[40586] (04/06 04:55:06.501):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1220846357
[40586] (04/06 04:55:06.501):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-301921664
[40586] (04/06 04:55:06.501):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1836788849
[40586] (04/06 04:55:06.517):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - New Move detected, queueing for RefId=-1530480618
[40542] (04/06 04:55:06.517):{0x26B8} {First.Last@company.com} FindAndQueueAllMovedMessages - Queuing request to send OTAFM batch
[40693] (04/06 04:55:06.517):{0x26B8} {First.Last@company.com} Message moved rescan completed
[30262] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Preparing OTAFM Batch
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-2139771050, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-2129792960, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-2126466930, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-2116488840, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1981245998, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1844056085, status=0, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1836788849, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1826810759, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1816832669, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1810180609, status=0, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1537747854, status=0, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1530480618, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1513850468, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1507198408, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1503872378, status=0, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1231439623, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1220846357, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1210868267, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1200890177, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-1197564147, status=0, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-891255916, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-752687044, status=0, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-615497131, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-591599745, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-588273715, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-584947685, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-446378813, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-309188900, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-301921664, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-281965484, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-278639454, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-275313424, status=0, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-140070582, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[40561] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} Batching Move for RefId=-2880669, status=1, current folder=-61, previous folder=0, TransactionID=-908506784
[30289] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} 34 OTAFM commands sent in batch for TransactionId=-908506784, Tag=2750165, size=820
[40279] (04/06 04:55:06.517):{0x3794} {First.Last@company.com} SubmitToRelaySendQ, Tag=2750165
[40000] (04/06 04:55:06.517):{0x3358} [BIPP] Send data, Tag=2750165

Otto · #5 (**permalink**) 04-06-2009, 04:41 PM

Although I've never seen these log entries in a log file, I would have to say that I would first recommend looking at permissions and then secondly at possible corruption of the MAPI profile on the server.

1 - Validate permissions in both Active Directory and Exchange System Manager per installation guide.

2 - Follow KB10285

Those are two rather quick fixes, assuming you can have some downtime for the latter to take place. The previous folder=0 seems rather odd, as I'm not really aware of a Folder ID being assigned the number 0.

You may also want to back up and remove any rules one of these users has in Outlook, in addition to removing folder redirection on all sub-folders (or any folder that's not the Inbox only).

Otherwise, I believe the log excerpt you've posted is more than sufficient to tell RIM that something is actually wrong and that these moves are falsely detected due to that underlying issue.

Follow Us On

Forum Sponsors

Google Advertisements