Freigeben über

Office 365: Move requests return status of Completed with Errors.

  • Artikel

When migrating mailboxes to Office 365 administrators have the opportunity to have the move batch immediately completed or manually complete the batch at a later time.  The move to Office 365 for the majority of mailboxes is an online move – allowing the end user full access to their mailbox while the move process occurs.

 

An online move to Office 365 occurs in multiple stages:

 

  • Enumerating and synchronization of initial folders.
  • Transfer and subsequent completion of the initial synchronization.
    • If the move is not finalized incremental synchronizations will occur daily.
  • Finalization of the move by detecting delta differences, locking the source and target mailboxes, migrating final changes, and completing required recipient object updates.
    • This process may occur automatically if the batch is selected to complete or manually when the administrator completes the batch.

 

The time to completion of the finalization of the move is largely dependent on the number of changes that have occurred between the initial seeding and incremental synchronization.  Some factors that may contribute to this:

 

  • How much time elapsed between the initial synchronization and when the batch was manually completed?
  • How long did it take to move the original mailbox data before finalization automatically occurred?
  • What type of usage does the mailbox experience while the move is in progress?
  • Were there other processes responsible for changing large numbers of messages?
    • For example, retention policies / archiving / etc.
  • The latency between the Office 365 datacenter and the on premises endpoint used for migration.

 

In Office 365 migration batches are handled by the migration service.  This is the service responsible for creating the underlying move requests and monitoring their status. 

 

Let’s take a look at an example of how this affects a move.  A migration batch is initiated for a single mailbox.  This results in the associated move request being created by the migration service.  The move request is picked up by the appropriate mailbox replication service.

​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​​

2/18/2015 10:59:08 PM [CO1PR06MB111] '' created move request.
2/18/2015 10:59:08 PM [CO1PR06MB111] '' allowed a large amount of data loss when moving the mailbox (50 bad items, 50 large items).
2/18/2015 10:59:23 PM [BLUPR06MB580] The Microsoft Exchange Mailbox Replication service 'BLUPR06MB580.namprd06.prod.outlook.com' (15.1.87.18 caps:1FFF) is examining the request.

 

Connections are created between the target and source mailboxes.

 

2/18/2015 10:59:23 PM [BLUPR06MB580] Connected to target mailbox 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)', database 'NAMPR06DG037-db096', Mailbox server 'BLUPR06MB580.namprd06.prod.outlook.com' Version 15.1 (Build 87.0).
2/18/2015 10:59:23 PM [BLUPR06MB580] Connected to target mailbox 'TENANT.onmicrosoft.com\TARGET-ARCHIVE-GUID (Archive)', database 'NAMPR06DG037-db096', Mailbox server 'BLUPR06MB580.namprd06.prod.outlook.com' Version 15.1 (Build 87.0).
2/18/2015 10:59:26 PM [BLUPR06MB580] Connected to source mailbox 'TENANT.onmicrosoft.com\SOURCE-PRIMARY-GUID (Primary)', database 'SOURCEDB', Mailbox server 'SERVER.DOMAIN.com' Version 14.3 (Build 123.0), proxy server 'HYBRID.DOMAIN.com' 14.3.123.2 caps:05FFFF.
2/18/2015 10:59:29 PM [BLUPR06MB580] Connected to source mailbox 'TENANT.onmicrosoft.com\SOURCE-ARCHIVE-GUID (Archive)', database 'SOURCEDB', Mailbox server 'SERVER.DOMAIN.com' Version 14.3 (Build 123.0), proxy server 'HYBRID.DOMAIN.com' 14.3.123.2 caps:05FFFF.

 

The folder hierarchy for the remote mailbox is completed.  At this stage the mailbox hierarchy is synchronized from the source mailbox to the target mailbox.

 

2/18/2015 10:59:46 PM [BLUPR06MB580] Initializing folder hierarchy from mailbox 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)': 239 folders total.
2/18/2015 10:59:47 PM [BLUPR06MB580] Folder creation progress: 0 folders created in mailbox 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)'.
2/18/2015 11:04:48 PM [BLUPR06MB580] Folder creation progress: 103 folders created in mailbox 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)'.
2/18/2015 11:09:51 PM [BLUPR06MB580] Folder creation progress: 218 folders created in mailbox 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)'.
2/18/2015 11:10:37 PM [BLUPR06MB580] Folder hierarchy initialized for mailbox 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)': 238 folders created.

 

At this stage the initial synchronization of data is started.

 

2/18/2015 11:13:12 PM [BLUPR06MB580] Stage: CreatingInitialSyncCheckpoint. Percent complete: 15.
2/18/2015 11:13:16 PM [BLUPR06MB580] Initial sync checkpoint progress: 0/239 folders processed. Currently processing mailbox 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)'.
2/18/2015 11:18:16 PM [BLUPR06MB580] Initial sync checkpoint progress: 185/239 folders processed. Currently processing mailbox 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)'.
2/18/2015 11:21:09 PM [BLUPR06MB580] Initial sync checkpoint completed: 288 folders processed.
2/18/2015 11:21:09 PM [BLUPR06MB580] Stage: LoadingMessages. Percent complete: 20.
2/18/2015 11:31:08 PM [BLUPR06MB580] Messages have been enumerated successfully. 211371 items loaded. Total size: 17.26 GB (18,528,022,914 bytes).
2/18/2015 11:31:08 PM [BLUPR06MB580] Stage: CopyingMessages. Percent complete: 25.
2/18/2015 11:31:08 PM [BLUPR06MB580] Copy progress: 0/211371 messages, 0 B (0 bytes)/17.26 GB (18,528,022,914 bytes), 7/63 folders completed.
2/18/2015 11:36:27 PM [BLUPR06MB580] Stage: CopyingMessages. Percent complete: 25.
2/18/2015 11:36:27 PM [BLUPR06MB580] Copy progress: 911/211371 messages, 10.6 MB (11,117,242 bytes)/17.26 GB (18,528,022,914 bytes), 7/63 folders completed.
2/18/2015 11:45:16 PM [BLUPR06MB580] Stage: CopyingMessages. Percent complete: 25.
2/18/2015 11:45:16 PM [BLUPR06MB580] Copy progress: 1183/211371 messages, 34.57 MB (36,247,647 bytes)/17.26 GB (18,528,022,914 bytes), 7/63 folders completed.
2/18/2015 11:52:26 PM [BLUPR06MB580] Stage: CopyingMessages. Percent complete: 25.

 

The synchronization of messages will continue until all messages from the initial synchronization state have been migrated.

 

2/24/2015 2:50:17 AM [BLUPR06MB580] Initial seeding completed, 213714 items copied, total size 17.26 GB (18,529,584,134 bytes).

 

When the initial seeding is completed the mailbox move status is at 95%.  If the administrator has selected to manually complete the batch the moves will remain until completed.  If the administrator selected the option to immediately finalize the move the incremental synchronization process will automatically start.

 

2/24/2015 2:50:17 AM [BLUPR06MB580] Initial seeding completed, 213714 items copied, total size 17.26 GB (18,529,584,134 bytes).
2/24/2015 2:50:17 AM [BLUPR06MB580] Stage: IncrementalSync. Percent complete: 95.

 

Once the incremental synchronization process has commenced we begin by enumerating all changes that have occurred since the initial synchronization.

 

2/24/2015 3:02:51 AM [BLUPR06MB580] Content changes reported for mailbox 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)': New 0, Changed 2514, Deleted 112207, Read 0, Unread 0, Total 114721 .
2/24/2015 3:10:10 AM [BLUPR06MB580] Applying changes to 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)': 100/2514 changed items processed.
2/24/2015 3:16:13 AM [BLUPR06MB580] Applying changes to 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)': 300/2514 changed items processed.
2/24/2015 3:21:39 AM [BLUPR06MB580] Applying changes to 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)': 1400/2514 changed items processed.
2/24/2015 3:29:14 AM [BLUPR06MB580] Total content changes applied to mailbox 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)': New 0, Changed 2514, Deleted 112209, Read 0, Unread 0, Skipped 0, Total 114723.

 

After determining the change set the changes are synchronized to the mailbox.

 

2/24/2015 3:10:10 AM [BLUPR06MB580] Applying changes to 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)': 100/2514 changed items processed.
2/24/2015 3:16:13 AM [BLUPR06MB580] Applying changes to 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)': 300/2514 changed items processed.
2/24/2015 3:21:39 AM [BLUPR06MB580] Applying changes to 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)': 1400/2514 changed items processed.
2/24/2015 3:29:14 AM [BLUPR06MB580] Total content changes applied to mailbox 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)': New 0, Changed 2514, Deleted 112209, Read 0, Unread 0, Skipped 0, Total 114723.

 

Additionally this mailbox had an archive mailbox which uses the same process above.  After synchronization of the primary mailbox the new items in the archive mailbox is performed.

 

2/24/2015 3:51:32 AM [BLUPR06MB580] Applying changes to 'TENANT.onmicrosoft.com\TARGET-ARCHIVE-GUID (Archive)': 700/112156 changed items processed.
2/24/2015 3:58:10 AM [BLUPR06MB580] Applying changes to 'TENANT.onmicrosoft.com\TARGET-ARCHIVE-GUID (Archive)': 1100/112156 changed items processed.
2/24/2015 4:03:11 AM [BLUPR06MB580] Applying changes to 'TENANT.onmicrosoft.com\TARGET-ARCHIVE-GUID (Archive)': 1300/112156 changed items processed.
2/24/2015 4:12:59 AM [BLUPR06MB580] Applying changes to 'TENANT.onmicrosoft.com\TARGET-ARCHIVE-GUID (Archive)': 1600/112156 changed items processed.
2/24/2015 4:20:40 AM [BLUPR06MB580] Applying changes to 'TENANT.onmicrosoft.com\TARGET-ARCHIVE-GUID (Archive)': 1900/112156 changed items processed.
2/24/2015 4:28:09 AM [BLUPR06MB580] Applying changes to 'TENANT.onmicrosoft.com\TARGET-ARCHIVE-GUID (Archive)': 2000/112156 changed items processed.

 

Approximately 5 hours later the move request is automatically suspended, we remain at 95% completed, and the move request enters a Completed with Error state.

 

2/24/2015 7:50:45 AM [CO1PR06MB111] '' suspended move request.
2/24/2015 7:55:23 AM [BLUPR06MB580] Applying changes to 'TENANT.onmicrosoft.com\TARGET-ARCHIVE-GUID (Archive)': 8400/112156 changed items processed.
2/24/2015 7:55:23 AM [BLUPR06MB580] Suspending job.
2/24/2015 7:55:23 AM [BLUPR06MB580] Stage: IncrementalSync. Percent complete: 95.
2/24/2015 7:55:26 AM [BLUPR06MB580] Relinquishing job.

 

In this particular case resuming the request will result in the same failure repeatedly. Why did this occur?  In this particular example you’ll note that there was a large degree of delta change between the initial mailbox seeding and the incremental sync. 

 

2/24/2015 3:29:14 AM [BLUPR06MB580] Total content changes applied to mailbox 'TENANT.onmicrosoft.com\TARGET-PRIMARY-GUID (Primary)': New 0, Changed 2514, Deleted 112209, Read 0, Unread 0, Skipped 0, Total 114723.

2/24/2015 3:43:45 AM [BLUPR06MB580] Content changes reported for mailbox 'TENANT.onmicrosoft.com\TARGET-ARCHIVE-GUID (Archive)': New 0, Changed 112156, Deleted 0, Read 0, Unread 0, Total 112156 .

 

Specifically a large number of new messages committed to the archive mailbox.  In this particular case there was a retention policy responsible for moving items from the primary mailbox to the archive mailbox.  Therefore the items in the archive mailbox were new, arrived after the original synchronization set was determined, and would need to be moved during incremental synchronization.   During the incremental synchronization the move request was timed out within the service and the job suspended.  The time out that is applied to incremental synchronization is subject to change. 

 

To correct this condition we suspended all retention activities against the mailbox.  This kept the delta change set to only those items generated by the end user and normal mail flow activity.  The migration batch was removed and a new migration batch completed.  In this instance both the migration of the primary and archive mailbox completed without any issue.

Comments

  • Anonymous
    March 04, 2015
    Always interesting...
  • Anonymous
    June 17, 2015
    Great article! How many content changes should be considered safe? Thank you!
  • Anonymous
    June 17, 2015
    @Cosmin:

    Although there's no specific value that I'm aware of i'd say that a single days normal transactions. In this particular instance there was something that caused a significant number of transactions to occur between delta syncs.

    TIMMCMIC