Today’s backup and restore operations require close coordination between backup applications, the line-of-business application being backed up (for example, Exchange 2010), and the storage management hardware and software. The Volume Shadow Copy Service (VSS) in Windows Server 2008, which was first introduced in Windows Server 2003, facilitates the conversation between these components to allow them to work together. When all of the components support VSS, you can use them to back up your application data, such as mailbox and public folder databases.

VSS coordinates the actions that are required to create a consistent shadow copy (also known as a snapshot or a point-in-time copy) of the data that is to be backed up. Shadow copies use differential copy-on-write technology to maintain consistency during the lifecycle of the snapshot.  For more information on how this works, see http://en.wikipedia.org/wiki/Shadow_Copy and http://en.wikipedia.org/wiki/Snapshot_(computer_storage).

There are three primary VSS components: providers, requestors, and writers. The provider is the system-level component that performs the actual work of creating and representing shadow copies. The requestor is the backup application, such as Windows Server Backup, System Center Data Protection Manager, etc., that requests a backup from the provider. And the writer is application (or component within an application) that coordinates its I/O operations with VSS shadow copy and shadow copy related operations (such as backups and restores) so that their data contained on the shadow copied volume is in a consistent state.

Before choosing a VSS-based backup application for Exchange, I recommend that you check with the vendor to determine which provider their application (the requestor) uses, and specifically, what differential block sizes are used. This is important because the block size used impacts how efficiently storage will be utilized.

Let me explain why.

The built-in provider in Windows, which leverages VOLSNAP.sys, uses a differential block size of 16K.

If a snapshot has been created, VOLSNAP.sys begins to intercept writes to the volume.  If a single byte in 16K has changed, VOLSNAP.sys moves the original 16K to differential storage and allows the new write to proceed to the volume. 

If a write happens to span more than one 16K block then all blocks that are changed are moved to differential storage.

Let’s look at how this might impact an application like Exchange.  Exchange writes in a static page size. 

• Exchange 2003 – 4K
• Exchange 2007 – 8K
• Exchange 2010 – 32K

In the Exchange 2007 example, if a single write of 8K was located on a single 16K differential block size, only 16K is moved to differential storage.  If the 8K spanned two 16K differential blocks then 32K would be moved to differential storage. 

Most VSS-based backup applications leverage the built-in VSS provider.  However, it is not a requirement to do so, and some vendors instead implement their own providers.  In these cases, the vendor may also choose to implement a larger or smaller differential block size.

Let’s look at the example of a hardware-based provider that implements a VSS solution with a block size of 1024K.  In this example, if a single byte changes in a 1024K differential block, then 1024K of data is moved to differential storage.  For applications like Exchange that write data in static pages, this can have can negative consequences.

For example, Exchange 2007 writes an 8K page to a single 1024K differential block.  This results in 1024K being written to shadow storage.  Therefore, 1 MB of storage is used to store 8K of data change.

Worse, if the write of 8K spans two 1024K differential blocks this results in 2048K being written to shadow storage.  In this case, 2 MB of storage is used to store 8K of data change.

In some cases, the custom block size used by a vendor’s custom provider has a range of configurations.  And in some cases, it cannot be configured at all. Before implementing a solution, consult with the vendor to determine which provider they use. If they use a custom provider, verify that it works efficiently with your version of Exchange.

*I want to thank Scott Schnoll and Dennis Middleton for tech reviewing and editing this post.

http://blogs.technet.com/b/exchange/archive/2011/05/31/exchange-2010-high-availability-misconceptions-addressed.aspx

http://blogs.technet.com/b/exchange/archive/2011/05/06/exchange-2010-mailbox-moves-and-mailbox-resiliency.aspx

Restore-DatabaseAvailabilityGroup is one of the cmdlets used as part of the datacenter switchover process.  The purpose of Restore-DatabaseAvailabilityGroup is to read the DAG’s list of stopped servers and evict the listed servers from the DAG’s underlying cluster.  The list of servers in this scenario typically includes all DAG members in the failed primary datacenter. This allows the DAG and the cluster to shrink, and because it now has fewer members, it requires fewer servers to maintain quorum and perform DAG operations.

Restore-DatabaseAvailabilityGroup:

1)  Starts a surviving node in the second datacenter using /forceQuourm.

2)  Forcibly evicts each server listed on the stopped servers list.

I have worked support cases where this eviction process fails with an exception.  In these cases, restore-databaseAvailabilityGroup issued the eviction while the Cluster service was still initializing (even though service control manager reported the service as started).  When the Cluster service is initializing it is unable to process eviction requests.  As a result, the commands failed.  For a few customers, the error is consistently reproducible necessitating the use of a workaround in order for restore-databaseAvailabiltyGroup to work.

Note: Customers upgrade to Exchange 2010 Service Pack 1 before following these instructions. These instructions will only work with Exchange 2010 SP1.

Prior to SP1, the Cluster service must be found in a stopped state in order to utilize restore-databaseAvailabilityGroup.  After SP1, the Cluster service no longer needs to be in a stopped state in order to proceed.

The following error may be noted when running

restore-databaseAvailabilityGroup –site <DRSite>

WARNING: Server ‘PrimarySiteServer’ was marked as stopped in database availability
group ‘DAG’ but couldn’t be removed from the cluster. Error: A server-side
database availability group administrative operation failed. Error: The
operation failed. CreateCluster errors may result from incorrectly configured
static addresses. Error: An error occurred while attempting a cluster
operation. Error: Cluster API
‘"EvictClusterNodeEx(node.domain.com) failed with 0x46.
Error: The remote server has been paused or is in the process of being
started"’ failed. [Server: DRSiteServer.domain.com]
WARNING: The operation wasn’t successful because an error was encountered. You
may find more details in log file
"C:ExchangeSetupLogsDagTasksdagtask_2010-09-02_14-54-39.766_restore-databaseavailabilitygroup.log".

The error 0x46 translates to

  ERROR_SHARING_PAUSED                                           winerror.h
# The remote server has been paused or is in the process of
# being started.

Upon further review, the Service Control Manager reported the Cluster service as started, and Failover Cluster Manager will connect to the cluster service.  Despite the error message, the attempt to start the Cluster service by using /forceQuorum was successful.

So the solution is simply to re-run restore-databaseAvailabilityGroup and the stopped DAG members will be successfully evicted.

When using continuous replication in Exchange 2007, an operation that sometimes needs to be performed is a database seed.  This operation is first performed as part of enabling replication, and thereafter it is performed infrequently as part of the process for recovering from divergence.

There are a few ways to perform a database seed, but seeding is most often performed by using the Update-StorageGroupCopy cmdlet. With this cmdlet, an ESE streaming backup is performed on the source database and the backup copy is then copied to the target.

Another way to seed a database copy is to perform a manual offline seeding. In this operation, the source database is dismounted, verified to be in a clean shutdown state, and then manually copied offline to the target. This can obviously be inconvenient, since the source database has to be down while the copy procedure is being performed.

A third method is to use a VSS backup of the database to seed the database copy, which I discuss in my previous post, Exchange 2007 – Using VSS to perform an online offline database seed.

Finally, yet another method is to utilize LCR as an SCR seeding source. In this blog post, I’ll show you how to do that.

====================================

The first step is to enable LCR for the source database by using the Enable-DatabaseCopy and Enable-StorageGroupCopy cmdlets.

(LCR)
Enable-DatabaseCopy –Identity <ServerNameDatabaseName> –CopyEdbFilePath “pathdatabase.edb”

If you have already enabled continuous replication for the storage group, proceed to the second step.

====================================

The second step is to enable standby continuous replication on the storage groups by using the Enable-StorageGroupCopy cmdlet.

(SCR)
Enable-StorageGroupCopy –Identity <ServerNameStorageGroupName> –StandbyMachine <SCRTargetName> –SeedingPostponed

For more information on enabling SCR, please see my blog post at http://blogs.technet.com/timmcmic/archive/2009/01/22/inconsistent-results-when-enabling-standby-continuous-replication-scr-in-exchange-2007-sp1.aspx

If you have already enabled continuous replication for the storage group, proceed to the third step.

====================================

The third step is to suspend the storage group copy.  Storage group copies can be suspended either in bulk or one at a time.  The following are example commands:

(All Storage Groups)
Get-StorageGroup –Server <SourceServerName> | Suspend-StorageGroupCopy –StandbyMachine <TargetMachineName>

(Single Storage Group)
Suspend-StorageGroupCopy –Identity <ServerNameStorageGroupName> –StandbyMachine <TargetMachineName>

It is important that in the SCR environment these commands are run on both the source and target servers.  All servers should indicate a suspended status, reflecting that both Active Directory replication and the Microsoft Exchange Replication service configuration updates occurred successfully.

====================================

The fourth step is to note the important paths that are necessary to complete the rest of these steps. Specifically, we are interested in the storage group log file path, the system folder path and copy system folder path, and the log file prefix.  For the mailbox database we are interested in the database file path and copy database file paths.

To get all paths for all storage groups on the source, use the following command:

Get-StorageGroup –Server <ServerName> | fl Name,LogFolderPath,SystemFolderPath,CopyLogFolderPath,CopySystemFolderPath,LogFilePrefix

This will give you a formatted list of storage group names, log paths, and system paths.

To get the paths for all mailbox databases, use the following command:

Get-MailboxDatabase –Server <ServerName> | fl Name,EdbFilePath,CopyEdbFilePath

This will give you a formatted list of mailbox database names and mailbox database paths.

Here is an example of the output you can expect to see (copy path attributes will only be populated if you are utilizing LCR):

Name            : Mailbox Database LCR
EdbFilePath     : d:SG1DB1.edb
CopyEdbFilePath : d:SG1-LCRDB1.edb

Name            : Mailbox Database CCR or SCR
EdbFilePath     : d:SG2DB2.edb
CopyEdbFilePath :

Name                 : Storage Group LCR
LogFolderPath        : d:SG1
SystemFolderPath     : d:SG1
CopyLogFolderPath    : d:SG1-LCR
CopySystemFolderPath : d:SG1-LCR
LogFilePrefix        : E00

Name                 : Storage Group CCR or SCR
LogFolderPath        : d:SG2
SystemFolderPath     : d:SG2
CopyLogFolderPath    :
CopySystemFolderPath :
LogFilePrefix        : E01

====================================

The fifth step is to verify that the source log file sequence is in order.  If the source log file sequence has been manually manipulated, and if any log file gaps are present, this results in a failure of the seed operation.  This step ensures that log files are in sequence on the source machine.

To ensure that the log sequence on the source machine is in the correct order, perform the following operations:

1. Open a command prompt and navigate to the log directory of the storage group.  This path can be found from the output gathered in step 3 above.

2. Run the following eseutil command:

eseutil /ml <LogFilePrefix>

The log file prefix can be found from the output gathered in step 3.

When you run this command it will scan every log file found in the source directory.  If any gaps or errors are identified, you cannot continue with these steps.  If the command completes and errors on the last log file in the series this is expected, as the Exx.log is currently open for writing and cannot be scanned.  The following is sample output that you should receive for a storage group that is online.

Extensible Storage Engine Utilities for Microsoft(R) Exchange Server
Version 08.02
Copyright (C) Microsoft Corporation. All Rights Reserved.
Initiating FILE DUMP mode…

Verifying log files…
     Base name: e00

      Log file: d:SG1E0000001353.log – OK
      Log file: d:SG1E0000001354.log – OK
      Log file: d:SG1E0000001355.log – OK
      Log file: d:SG1E0000001356.log – OK
      Log file: d:SG1E0000001357.log – OK
      Log file: d:SG1E0000001358.log – OK
      Log file: d:SG1E0000001359.log – OK
      Log file: d:SG1E000000135A.log – OK
      Log file: d:SG1E000000135B.log – OK
      Log file: d:SG1E000000135C.log – OK
      Log file: d:SG1E000000135D.log – OK
      Log file: d:SG1E000000135E.log – OK
      Log file: d:SG1E000000135F.log – OK
      Log file: d:SG1E0000001360.log – OK
      Log file: d:SG1E0000001361.log – OK
      Log file: d:SG1E0000001362.log – OK
      Log file: d:SG1E0000001363.log – OK
      Log file: d:SG1E0000001364.log – OK
      Log file: d:SG1E0000001365.log – OK
      Log file: d:SG1E0000001366.log – OK
      Log file: d:SG1E0000001367.log – OK
      Log file: d:SG1E0000001368.log – OK
      Log file: d:SG1E0000001369.log – OK
      Log file: d:SG1E00.log
                ERROR: Cannot open log file (d:SG1E00.log). Error -1032.

Operation terminated with error -1032 (JET_errFileAccessDenied, Cannot access file, the file is locked or in use) after 368.625 seconds.

====================================

The sixth step is to prepare the LCR copies for use in the SCR seeding process.  This starts by verifying the health of the LCR copies.

To verify the health of the LCR copies, on the server hosting the LCR databases run get-storagegroupcopystatus.  If any database shows a status of other than healthy this will need to be corrected before continuing with these instructions.

Get-StorageGroupCopyStatus

Name                      SummaryCopySt CopyQueueLeng ReplayQueueL LastInspecte
                          atus          th            ength        dLogTime
—-                      ————- ————- ———— ————
MBX-1-SG1                 Healthy       0             0            3/6/2011 …

====================================

The seventh step is to ensure that the target paths are ready to have the database moved in place.  The paths referenced in these steps can be obtained from the output gathered in step 3.

For SCR – ensure that the logFolderPath, systemFolderPath, and edbFilePath are empty on the SCR target.

At this point the destination paths are empty and ready for the database to be moved.

We now need to create the directory structure where logs, system, and database files will be copied.

For SCR – create the log, system, and database folder.  In our example logs, system, and database files are located at d:SG1.  Therefore on the SCR target or CCR passive node I would create the directory structure d:SG1.

If you are using nested folders you need to create the entire directory structure.

====================================

The eighth step is to move the restored database to the target directory.  This can be accomplished a few different ways, but I will make a recommendation below.

To being the LCR database copies need to be suspended.  This can be performed in bulk

get-storagegroup –server <LCRHost> | suspend-storagegroupcopy

The success of this command can be verified using get-storagegroupcopystatus.

Get-StorageGroupCopyStatus

Name                      SummaryCopySt CopyQueueLeng ReplayQueueL LastInspecte
                          atus          th            ength        dLogTime
—-                      ————- ————- ———— ————
MBX-1-SG1                 Suspended     0             0            3/6/2011 …

The LCR database file can be located at the CopyEdbFile path noted in step four.  Using a command prompt navigate to this location.

The SCR target location can be mapped as a network drive.  We will assume for this example that the network drive Y is utilized. 

Use eseutil to copy the database from the source directory to the target directory.  The command using our example is:

eseutil /y SG1-DB1.edb /d y:SG1-DB1.edb

Here is the expected output from this command:

Extensible Storage Engine Utilities for Microsoft(R) Exchange Server
Version 08.02
Copyright (C) Microsoft Corporation. All Rights Reserved.

Initiating COPY FILE mode…
     Source File: SG1-DB1.edb

Destination File: y:SG1-DB1.edb

                      Copy Progress (% complete)

          0    10   20   30   40   50   60   70   80   90  100

          |—-|—-|—-|—-|—-|—-|—-|—-|—-|—-|

          ……………………………………………

Operation completed successfully in 13.281 seconds.

At this point the copy has been seeded on the target server.

When the copy is completed the LCR replication can be resumed using

get-storagegroup –server <LCRHost> | resume-storagegroupcopy

Information on the usage of Eseutil can be found here.  http://technet.microsoft.com/en-us/library/aa998249(EXCHG.80).aspx

====================================

The ninth step is to verify the health of the copied database.  We need to ensure that the database was not damaged as a part of the copy process.

Log on locally to the SCR target, open a command prompt, and navigate to the database directory.  In our example this would be d:SG1.

Use Eseutil /k to perform a checksum of the database:

eseutil /k SG1-DB1.edb

The following output will be observed when the command completes:

Extensible Storage Engine Utilities for Microsoft(R) Exchange Server
Version 08.02
Copyright (C) Microsoft Corporation. All Rights Reserved.

Initiating CHECKSUM mode…
        Database: SG1-DB1.edb
  Temp. Database: TEMPCHKSUM3888.EDB

File: SG1-DB1.edb

                     Checksum Status (% complete)

          0    10   20   30   40   50   60   70   80   90  100

          |—-|—-|—-|—-|—-|—-|—-|—-|—-|—-|

          ……………………………………………

514 pages seen
0 bad checksums
0 correctable checksums
129 uninitialized pages
0 wrong page numbers
0x4676 highest dbtime (pgno 0x86)
65 reads performed
4 MB read
1 seconds taken
4 MB/second
2755 milliseconds used
42 milliseconds per read
78 milliseconds for the slowest read
15 milliseconds for the fastest read

Operation completed successfully in 0.140 seconds.

We are interested in ensuring that there are 0 bad checksums (bolded line above).

====================================

The last step in the process is to resume the storage group copy:

Get-StorageGroup –Server <SourceServerName> | Resume-StorageGroupCopy –StandbyMachne <SCRTargetName>

(Note:  This command resumes storage group copy for all storage groups.  If you have a storage group that is suspended for another reason it may be necessary to resume storage groups individually).

When replication has resumed successfully, you can note the following events in the Application event log indicating that replication began copying log files.

Event Type:    Information
Event Source: MSExchangeRepl
Event Category:   Action
Event ID:    2084
Date:        3/16/2010
Time:        10:12:50 AM
User:        N/A
Computer:    SERVER
Description: Replication for storage group SERVERStorage Group SCR or CCR has been resumed.

For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.

Event Type:    Information
Event Source:    MSExchangeRepl
Event Category:   Service
Event ID:    2114
Date:        3/16/2010
Time:        10:13:19 AM
User:        N/A
Computer:    SERVER
Description: The replication instance for storage group SERVERStorage Group SCR or CCR has started copying transaction log files. The first log file successfully copied was generation 31201.

For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.

====================================

The following are links to references from this post.

· Enable-StorageGroupCopy (http://technet.microsoft.com/en-us/library/aa996389(EXCHG.80).aspx)

· Enable-DatabaseCopy (http://technet.microsoft.com/en-us/library/aa996389(EXCHG.80).aspx)

· Suspend-StorageGroupCopy (http://technet.microsoft.com/en-us/library/aa998182(EXCHG.80).aspx)

· Get-StorageGroup (http://technet.microsoft.com/en-us/library/aa998331(EXCHG.80).aspx)

· Get-MailboxDatabase (http://technet.microsoft.com/en-us/library/bb124924(EXCHG.80).aspx)

· ESEUTIL (http://technet.microsoft.com/en-us/library/aa998249(EXCHG.80).aspx)

· Resume-StorageGroupCopy (http://technet.microsoft.com/en-us/library/bb124529(EXCHG.80).aspx)

====================================

Updates

6/26/11 – removed LCR enable step in step 1 that included seedingPostponed.  This was not necessary.

====================================

In Exchange 2010 the out of box behavior for a database availability group (DAG) is to utilize native replication based on log shipping.  Some customers choose to leverage solutions provided by vendors that support the third party replication API thereby replacing the inbox replication mechanism.

Recently I worked with a customer leveraging the third party replication API and had a move mailbox performance issue.  Overall move mailboxes were under performing what was expected.  After investigation we were able to determine that the databases hosted on the DAG had the default DataMoveReplicationConstraint property specified.  By default this property is set to secondCopy.  The purpose of this property is to allow the mailbox replication service on a client access server to throttle move mailbox based on the replication status of the target database.  In the case of the third party replication API it is not necessary to set this constraint.  By default all vendors leveraging the third party replication API must support synchronous replication, therefore writes are automatically throttled based on the ability to replicate synchronously thereby making it not necessary to utilize the DataMoveReplicationConstraint.

When using the third party replication API it is recommended to disable the DataMoveReplicationConstraint using the set-mailboxdatabase commandlet to a value of NONE.

================================

Update 10/25/2011

Corrected mis-spelling of the DataMoveReplicationConstraint

================================

Recently I was presented with an interesting case regarding the inability to mount databases.  The history preceding the event was fairly unremarkable and only noted after running patch maintenance on the server and rebooting.  Post reboot every time the customer attempted to mount a public folder database, the following active manager error occurred:

Couldn’t mount the database that you specified. Specified database: Public Folder Store NAME; Error code: An Active Manager operation failed. Error: The database action failed. Error: Operation failed with message: Error 0x721 (A security package specific error occurred) from cli_AmMountDatabaseDirectEx [Database: Public Folder Store NAME, Serve r: server.child.domain.local].
    + CategoryInfo          : InvalidOperation: (Public Folder Store NAME:ADObjectId) [Mount-Database], InvalidOperationException
    + FullyQualifiedErrorId : F34E87D0,Microsoft.Exchange.Management.SystemConfigurationTasks.MountDatabase

Also when reviewing the application log the following event was noted:

Log Name: Application

Source: MSExchange Configuration Cmdlet – Remote Management

Date: 11/7/2010 9:46:17 AM

Event ID: 4

Task Category: General

Level: Error

Keywords: Classic

User: N/A

Computer: SERVER.child.domain.local

Description:

(PID 6364, Thread 43) Task Mount-Database writing error when processing record of index 0. Error: System.InvalidOperationException: Couldn’t mount the database that you specified. Specified database: Public Folder Store NAME; Error code: An Active Manager operation failed. Error: The database action failed. Error: Operation failed with message: Error 0x721 (A security package specific error occurred) from cli_AmMountDatabaseDirectEx [Database: Public Folder Store NAME, Server: SERVER.child.domain.local]. —> Microsoft.Exchange.Cluster.Replay.AmDbActionWrapperException: An Active Manager operation failed. Error: The database action failed. Error: Operation failed with message: Error 0x721 (A security package specific error occurred) from cli_AmMountDatabaseDirectEx —> Microsoft.Exchange.Data.Storage.AmOperationFailedException: An Active Manager operation failed. Error: Operation failed with message: Error 0x721 (A security package specific error occurred) from cli_AmMountDatabaseDirectEx —> Microsoft.Exchange.Rpc.RpcException: Error 0x721 (A security package specific error occurred) from cli_AmMountDatabaseDirectEx

at ThrowRpcException(Int32 rpcStatus, String message)

at Microsoft.Exchange.Rpc.RpcClientBase.ThrowRpcException(Int32 rpcStatus, String routineName)

at Microsoft.Exchange.Rpc.ActiveManager.AmRpcClient.MountDatabaseDirectEx(Guid guid, AmMountArg arg)

at Microsoft.Exchange.Data.Storage.ActiveManager.AmRpcClientHelper.<>c__DisplayClass26.<MountDatabaseDirectEx>b__25(String )

at Microsoft.Exchange.Data.Storage.ActiveManager.AmRpcClientHelper.<>c__DisplayClass4e.<RunRpcOperationWithAuth>b__4c()

at Microsoft.Exchange.Data.Storage.Cluster.HaRpcExceptionWrapperBase`2.ClientRetryableOperation(String serverName, RpcClientOperation rpcOperation)

— End of inner exception stack trace —

at Microsoft.Exchange.Data.Storage.Cluster.HaRpcExceptionWrapperBase`2.ClientHandleRpcException(RpcException ex, String serverName)

at Microsoft.Exchange.Data.Storage.Cluster.HaRpcExceptionWrapperBase`2.ClientRetryableOperation(String serverName, RpcClientOperation rpcOperation)

at Microsoft.Exchange.Data.Storage.ActiveManager.AmRpcClientHelper.RunRpcOperationWithAuth(AmRpcOperationHint rpcOperationHint, String serverName, String databaseName, NetworkCredential networkCredential, Nullable`1 timeoutMs, AmRpcClient& rpcClient, InternalRpcOperation rpcOperation)

at Microsoft.Exchange.Data.Storage.ActiveManager.AmRpcClientHelper.MountDatabaseDirectEx(String serverToRpc, Guid dbGuid, AmMountArg mountArg)

at Microsoft.Exchange.Cluster.ActiveManagerServer.AmDbAction.MountDatabaseDirect(AmServerName serverName, AmServerName lastMountedServerName, Guid dbGuid, MountFlags flags, AmDbActionCode actionCode)

at Microsoft.Exchange.Cluster.ActiveManagerServer.AmDbPamAction.RunMountDatabaseDirect(AmServerName serverToMount, MountFlags mountFlags, Boolean fLossyMountEnabled)

at Microsoft.Exchange.Cluster.ActiveManagerServer.AmDbPamAction.<>c__DisplayClass3.<AttemptMountOnServer>b__1(Object , EventArgs )

at Microsoft.Exchange.Cluster.ActiveManagerServer.AmHelper.HandleKnownExceptions(EventHandler ev)

— End of inner exception stack trace (Microsoft.Exchange.Data.Storage.AmOperationFailedException) —

at Microsoft.Exchange.Cluster.ActiveManagerServer.AmDbOperation.Wait(TimeSpan timeout)

at Microsoft.Exchange.Cluster.ActiveManagerServer.ActiveManagerCore.MountDatabase(Guid mdbGuid, MountFlags flags, DatabaseMountDialOverride mountDialOverride, AmDbActionCode actionCode)

at Microsoft.Exchange.Cluster.ActiveManagerServer.AmRpcServer.<>c__DisplayClass4.<MountDatabase>b__3()

at Microsoft.Exchange.Data.Storage.Cluster.HaRpcExceptionWrapperBase`2.RunRpcServerOperation(String databaseName, RpcServerOperation rpcOperation)

— End of stack trace on server (SERVER.child.domain.local) —

at Microsoft.Exchange.Data.Storage.Cluster.HaRpcExceptionWrapperBase`2.ClientRethrowIfFailed(String databaseName, String serverName, RpcErrorExceptionInfo errorInfo)

at Microsoft.Exchange.Data.Storage.ActiveManager.AmRpcClientHelper.RunDatabaseRpcWithReferral(AmRpcOperationHint rpcOperationHint, Database database, String targetServer, AmRpcClient& rpcClient, InternalRpcOperation rpcOperation)

at Microsoft.Exchange.Data.Storage.ActiveManager.AmRpcClientHelper.MountDatabase(Database database, Int32 flags, Int32 mountDialOverride)

at Microsoft.Exchange.Management.SystemConfigurationTasks.MountDatabase.InternalProcessRecord()

— End of inner exception stack trace —

The error message and event unto themselves are not very telling as to what the issue was.  The important part of the event, which is not unique to Exchange and has been seen with other shell commands, is the security package error:

# for hex 0x721 / decimal 1825
  RPC_S_SEC_PKG_ERROR                                            winerror.h
# A security package specific error occurred.

After some investigation we were able to determine that the active directory forest where Exchange was installed contained a multiple domain structure.  In this case we searched the entire directory, and found that there were two ENABLED machine accounts with the same name residing in two different domain naming contexts in the same forest.  After identifying the machine account that was not being used (in this case the one in a child domain where Exchange servers were not installed) and deleting it – our mount commands proceeded successfully with no issues noted.

In recent weeks I’ve had several peers and customers present with concerns that when using Local Continuous Replication (LCR), Cluster Continuous Replication (CCR), Standby Continuous Replication (SCR), of the Database Availability Group (DAG)  passive database copies appear in a dirty shutdown state.

In general a database has two states – Clean Shutdown and Dirty Shutdown.  A clean shutdown state indicates that the database has had all outstanding transaction logs committed to it and the database can now stand on its own.  A dirty shutdown database indicates that the database requires additional transaction logs to be committed in order for the database to stand on its own.

Here is a eseutil /mh dump of a database that has been dismounted and therefore should be in a clean shutdown state.

Extensible Storage Engine Utilities for Microsoft(R) Exchange Server

Version 08.03

Copyright (C) Microsoft Corporation. All Rights Reserved.

Initiating FILE DUMP mode…
         Database: MBX-1-SG1-DB1.edb

        File Type: Database
   Format ulMagic: 0x89abcdef
   Engine ulMagic: 0x89abcdef
Format ulVersion: 0x620,12
Engine ulVersion: 0x620,12
Created ulVersion: 0x620,12
     DB Signature: Create time:06/30/2010 09:18:04 Rand:205158 Computer:
         cbDbPage: 8192
           dbtime: 49856 (0xc2c0)
            State: Clean Shutdown
     Log Required: 0-0 (0x0-0x0)
    Log Committed: 0-0 (0x0-0x0)
   Streaming File: No
         Shadowed: Yes
       Last Objid: 135
     Scrub Dbtime: 0 (0x0)
       Scrub Date: 00/00/1900 00:00:00
     Repair Count: 0
      Repair Date: 00/00/1900 00:00:00
Old Repair Count: 0
  Last Consistent: (0x30,102,19E)  12/05/2010 11:33:55
      Last Attach: (0x2F,9,86)  12/05/2010 09:23:20
      Last Detach: (0x30,102,19E)  12/05/2010 11:33:55
             Dbid: 1
    Log Signature: Create time:06/30/2010 09:18:03 Rand:202227 Computer:
       OS Version: (6.0.6002 SP 2 NLS 500100.50100)

Previous Full Backup:
        Log Gen: 15-32 (0xf-0x20) – OSSnapshot
           Mark: (0x21,8,16)
           Mark: 07/06/2010 21:08:21

Previous Incremental Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00

Previous Copy Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00

Previous Differential Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00

Current Full Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00

Current Shadow copy backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00

     cpgUpgrade55Format: 0
    cpgUpgradeFreePages: 0
cpgUpgradeSpaceMapPages: 0

       ECC Fix Success Count: none
   Old ECC Fix Success Count: none
         ECC Fix Error Count: none
     Old ECC Fix Error Count: none
    Bad Checksum Error Count: none
Old bad Checksum Error Count: none

Operation completed successfully in 0.15 seconds.

This particular database is enabled for LCR.  With the source database mounted and with storage group copy suspended, here is an eseutil /mh dump of the database.  (We should expect the same for a CCR passive, SCR passive, or DAG passive database)

Extensible Storage Engine Utilities for Microsoft(R) Exchange Server

Version 08.03

Copyright (C) Microsoft Corporation. All Rights Reserved.

Initiating FILE DUMP mode…
         Database: MBX-1-SG1-DB1.edb

        File Type: Database
   Format ulMagic: 0x89abcdef
   Engine ulMagic: 0x89abcdef
Format ulVersion: 0x620,12
Engine ulVersion: 0x620,12
Created ulVersion: 0x620,12
     DB Signature: Create time:06/30/2010 09:18:04 Rand:205158 Computer:
         cbDbPage: 8192
           dbtime: 49856 (0xc2c0)
            State: Dirty Shutdown
     Log Required: 50-50 (0x32-0x32)
    Log Committed: 0-50 (0x0-0x32)
   Streaming File: No
         Shadowed: Yes
       Last Objid: 135
     Scrub Dbtime: 0 (0x0)
       Scrub Date: 00/00/1900 00:00:00
     Repair Count: 0
      Repair Date: 00/00/1900 00:00:00
Old Repair Count: 0
  Last Consistent: (0x30,102,19E)  12/05/2010 11:33:56
      Last Attach: (0x32,9,86)  12/05/2010 11:38:05
      Last Detach: (0x0,0,0)  00/00/1900 00:00:00
             Dbid: 1
    Log Signature: Create time:06/30/2010 09:18:03 Rand:202227 Computer:
       OS Version: (6.0.6002 SP 2 NLS 500100.50100)

Previous Full Backup:
        Log Gen: 15-32 (0xf-0x20) – OSSnapshot
           Mark: (0x21,8,16)
           Mark: 07/06/2010 21:08:21

Previous Incremental Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00

Previous Copy Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00

Previous Differential Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00

Current Full Backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00

Current Shadow copy backup:
        Log Gen: 0-0 (0x0-0x0)
           Mark: (0x0,0,0)
           Mark: 00/00/1900 00:00:00

     cpgUpgrade55Format: 0
    cpgUpgradeFreePages: 0
cpgUpgradeSpaceMapPages: 0

       ECC Fix Success Count: none
   Old ECC Fix Success Count: none
         ECC Fix Error Count: none
     Old ECC Fix Error Count: none
    Bad Checksum Error Count: none
Old bad Checksum Error Count: none

Operation completed successfully in 0.63 seconds.

In this case a state of dirty shutdown is expected.  When a database is enabled for replication we utilize a special replay process called Replay Without Undo.  Essentially we know that if the source database is mounted, and that there is a copy, we will encounter incomplete transactions in a log stream that will eventually be completed in logs that are either being generated or in the process of copying to the target.  With this in mind we do not want to undo these logical transactions, but rather hold them open and wait for subsequent logs that will complete them.

With this in mind administrators should not be immediately concerned that their passive database copies show a state of dirty shutdown.

In Exchange 2010 administrators may attempt to move either log files or database files using the command move-DatabasePath.  In some instances the command may fail containing an InvalidOperationException.  Here are some examples of the errors (note that verbose output is utilized):

========================================================

Move-DatabasePath –identity <name> –logFolderPath <path> –verbose

[PS] C:>Move-DatabasePath MBX-1-DB0 -LogFolderPath T:NewPath -Verbose
VERBOSE: [17:29:43.342 GMT] Move-DatabasePath : Active Directory session
settings for ‘Move-DatabasePath’ are: View Entire Forest: ‘False’, Default
Scope: ‘home.domain.com’, Configuration Domain Controller:
‘DC-1.home.domain.com’, Preferred Global Catalog:
‘DC-2.home.domain.com’, Preferred Domain Controllers: ‘{
DC-2.home.domain.com }’
VERBOSE: [17:29:43.342 GMT] Move-DatabasePath : Runspace context: Executing
user: home.domain.com/Users/Administrator, Executing user organization: ,
Current organization: , RBAC-enabled: Enabled.
VERBOSE: [17:29:43.342 GMT] Move-DatabasePath : Beginning processing &
VERBOSE: [17:29:43.342 GMT] Move-DatabasePath : Instantiating handler with
index 0 for cmdlet extension agent "Admin Audit Log Agent".
VERBOSE: [17:29:43.420 GMT] Move-DatabasePath : Current ScopeSet is: {
Recipient Read Scope: {{, }}, Recipient Write Scopes: {{, }}, Configuration
Read Scope: {{, }}, Configuration Write Scope(s): {{, }, }, Exclusive Recipient
Scope(s): {}, Exclusive Configuration Scope(s): {} }
VERBOSE: [17:29:44.124 GMT] Move-DatabasePath : Searching objects "MBX-1-DB0"
of type "Database" under the root "$null".
VERBOSE: [17:29:44.155 GMT] Move-DatabasePath : Previous operation run on
domain controller ‘DC-1.home.domain.com’.
VERBOSE: [17:29:44.217 GMT] Move-DatabasePath : Processing object "MBX-1-DB0".
VERBOSE: [17:29:45.186 GMT] Move-DatabasePath : Searching objects
"MBX-1.home.domain.com" of type "Server" under the root "$null".
VERBOSE: [17:29:45.280 GMT] Move-DatabasePath : Previous operation run on
domain controller ‘DC-1.home.domain.com’.
VERBOSE: [17:29:46.873 GMT] Move-DatabasePath : Verifying that the path
"T:NewPath" on the server "MBX-1.home.domain.com" is located on a fixed
or network drive.
VERBOSE: [17:29:49.529 GMT] Move-DatabasePath : Verifying that the log location
"T:NewPath" on server "MBX-1.home.domain.com" has not been occupied by
an existing file or directory.
VERBOSE: [17:29:50.326 GMT] Move-DatabasePath : Checking the existence of log
files under directory "d:MBX-1MBX-1-DB0MBX-1-DB0-Logs" on Server
"MBX-1.home.domain.com".
VERBOSE: [17:33:05.815 GMT] Move-DatabasePath : Admin Audit Log: Entered
Handler:Validate.
VERBOSE: [17:33:05.815 GMT] Move-DatabasePath : Admin Audit Log: Entered
ClassFactory:InitializeConfig.
VERBOSE: [17:33:05.924 GMT] Move-DatabasePath : Admin Audit Log: Exited
ClassFactory:InitializeConfig.
VERBOSE: [17:33:07.190 GMT] Move-DatabasePath : Admin Audit Log: Exited
Handler:Validate.

Confirm
Are you sure you want to perform this action?

Moving database path "MBX-1-DB0".
[Y] Yes  [A] Yes to All  [N] No  [L] No to All  [?] Help (default is "Y"): a
VERBOSE: [17:33:52.375 GMT] Move-DatabasePath : Resolved current organization:
.
VERBOSE: [17:33:52.594 GMT] Move-DatabasePath : The Admin RPC connection is
being established with server "MBX-1.home.domain.com".

Confirm
To perform the move operation, database "MBX-1-DB0" must be temporarily
dismounted, which will make it inaccessible to all users. Do you want to
continue?
[Y] Yes  [A] Yes to All  [N] No  [L] No to All  [?] Help (default is "Y"): a
VERBOSE: [17:34:04.422 GMT] Move-DatabasePath : Reading new object
"9d654028-b845-43fc-9b3b-a011c442c9e6" of type "Server".
VERBOSE: [17:34:04.422 GMT] Move-DatabasePath : Dismounting the database,
"MBX-1-DB0".
VERBOSE: [17:34:05.297 GMT] Move-DatabasePath : Copying the database Log files
under directory "d:MBX-1MBX-1-DB0MBX-1-DB0-Logs" to the target directory
"T:NewPath" on Server "MBX-1".
VERBOSE: [17:34:05.344 GMT] Move-DatabasePath : Checking the existence of
directory "T:NewPath" on Server "MBX-1.home.domain.com".
VERBOSE: [17:34:05.359 GMT] Move-DatabasePath : Set access control for
directory "T:NewPath" on server "MBX-1.home.domain.com".
VERBOSE: [17:34:05.359 GMT] Move-DatabasePath : Checking the existence of
directory "d:MBX-1MBX-1-DB0MBX-1-DB0-Logs" on Server
"MBX-1.home.domain.com".
VERBOSE: [17:34:05.406 GMT] Move-DatabasePath : Copying the files from
directory "d:MBX-1MBX-1-DB0MBX-1-DB0-Logs" to target directory "T:NewPath"
on server "MBX-1.home.domain.com".
VERBOSE: [17:35:54.090 GMT] Move-DatabasePath : Reading new object
"9d654028-b845-43fc-9b3b-a011c442c9e6" of type "Server".
VERBOSE: [17:35:54.105 GMT] Move-DatabasePath : The task is attempting to
communicate with the Microsoft Exchange Replication service on server
"MBX-1.home.domain.com" to obtain updated configuration changes for
database "MBX-1-DB0".
VERBOSE: [17:35:54.965 GMT] Move-DatabasePath : Mounting database "MBX-1-DB0".
VERBOSE: [17:35:56.199 GMT] Move-DatabasePath : Admin Audit Log: Entered
Handler:OnComplete.
VERBOSE: [17:36:03.902 GMT] Move-DatabasePath : Admin Audit Log: Exited
Handler:OnComplete.
Failed to move database log files from "d:MBX-1MBX-1-DB0MBX-1-DB0-Logs" to "
T:NewPath".
    + CategoryInfo          : InvalidOperation: (MBX-1-DB0:ADObjectId) [Move-DatabasePath], InvalidOperationException
    + FullyQualifiedErrorId : 7280D023,Microsoft.Exchange.Management.SystemConfigurationTasks.MoveDatabasePath
VERBOSE: [17:36:04.074 GMT] Move-DatabasePath : Ending processing &
[PS] C:>

========================================================

Move-DatabasePath –identity <name> –logFolderPath <path> –edbFilePath <pathname.edb> –verbose

[PS] C:>Move-DatabasePath -Identity MBX-1-DB0 -EdbFilePath t:NewPathMBX-1-DB0.edb

Confirm
Are you sure you want to perform this action?

Moving database path "MBX-1-DB0".
[Y] Yes  [A] Yes to All  [N] No  [L] No to All  [?] Help (default is "Y"): a

Confirm
To perform the move operation, database "MBX-1-DB0" must be temporarily
dismounted, which will make it inaccessible to all users. Do you want to
continue?
[Y] Yes  [A] Yes to All  [N] No  [L] No to All  [?] Help (default is "Y"): a
[PS] C:>Move-DatabasePath -Identity MBX-1-DB0 -EdbFilePath "E:MBX-1MBX-1-DB0MBX-1-DB0-DatabaseMBX-1-DB0.edb"

Confirm
Are you sure you want to perform this action?

Moving database path "MBX-1-DB0".
[Y] Yes  [A] Yes to All  [N] No  [L] No to All  [?] Help (default is "Y"): a

Confirm
To perform the move operation, database "MBX-1-DB0" must be temporarily
dismounted, which will make it inaccessible to all users. Do you want to
continue?
[Y] Yes  [A] Yes to All  [N] No  [L] No to All  [?] Help (default is "Y"): a
[PS] C:>       Move-DatabasePath MBX-1-DB0 -LogFolderPath T:NewPath -EdbFilePath t:NewPathMBX-1-DB0.edb -Verbose
VERBOSE: [17:43:42.454 GMT] Move-DatabasePath : Active Directory session
settings for ‘Move-DatabasePath’ are: View Entire Forest: ‘False’, Default
Scope: ‘home.domain.com’, Configuration Domain Controller:
‘DC-1.home.domain.com’, Preferred Global Catalog:
‘DC-2.home.domain.com’, Preferred Domain Controllers: ‘{
DC-2.home.domain.com }’
VERBOSE: [17:43:42.454 GMT] Move-DatabasePath : Runspace context: Executing
user: home.domain.com/Users/Administrator, Executing user organization: ,
Current organization: , RBAC-enabled: Enabled.
VERBOSE: [17:43:42.454 GMT] Move-DatabasePath : Beginning processing &
VERBOSE: [17:43:42.454 GMT] Move-DatabasePath : Instantiating handler with
index 0 for cmdlet extension agent "Admin Audit Log Agent".
VERBOSE: [17:43:42.470 GMT] Move-DatabasePath : Current ScopeSet is: {
Recipient Read Scope: {{, }}, Recipient Write Scopes: {{, }}, Configuration
Read Scope: {{, }}, Configuration Write Scope(s): {{, }, }, Exclusive Recipient
Scope(s): {}, Exclusive Configuration Scope(s): {} }
VERBOSE: [17:43:42.470 GMT] Move-DatabasePath : Searching objects "MBX-1-DB0"
of type "Database" under the root "$null".
VERBOSE: [17:43:42.486 GMT] Move-DatabasePath : Previous operation run on
domain controller ‘DC-1.home.domain.com’.
VERBOSE: [17:43:42.486 GMT] Move-DatabasePath : Processing object "MBX-1-DB0".
VERBOSE: [17:43:42.501 GMT] Move-DatabasePath : Searching objects
"MBX-1.home.domain.com" of type "Server" under the root "$null".
VERBOSE: [17:43:42.533 GMT] Move-DatabasePath : Previous operation run on
domain controller ‘DC-1.home.domain.com’.
VERBOSE: [17:43:42.595 GMT] Move-DatabasePath : Verifying that EDB file path
"t:NewPathMBX-1-DB0.edb" is available for use.
VERBOSE: [17:43:42.704 GMT] Move-DatabasePath : Checking the existence of file
"E:MBX-1MBX-1-DB0MBX-1-DB0-DatabaseMBX-1-DB0.edb" on server "MBX-1".
VERBOSE: [17:43:42.783 GMT] Move-DatabasePath : Verifying that the path
"t:NewPathMBX-1-DB0.edb" on the server "MBX-1" is located on a fixed or
network drive.
VERBOSE: [17:43:42.783 GMT] Move-DatabasePath : Checking the existence of file
"t:NewPathMBX-1-DB0.edb" on server "MBX-1".
VERBOSE: [17:43:42.814 GMT] Move-DatabasePath : Checking the existence of
directory "t:NewPathMBX-1-DB0.edb" on Server "MBX-1".
VERBOSE: [17:43:42.845 GMT] Move-DatabasePath : Checking the existence of
directory "t:NewPath" on Server "MBX-1.home.domain.com".
VERBOSE: [17:43:42.845 GMT] Move-DatabasePath : Set access control for
directory "t:NewPath" on server "MBX-1.home.domain.com".
VERBOSE: [17:43:42.845 GMT] Move-DatabasePath : Checking the existence of
directory
"e:mbx-1mbx-1-db0mbx-1-db0-databasecatalogdata-ed71935d-a14f-4937-b20d-50b3
7e136797-9d654028-b845-43fc-9b3b-a011c442c9e6" on Server "MBX-1".
VERBOSE: [17:43:42.845 GMT] Move-DatabasePath : Verifying that the path
"T:NewPath" on the server "MBX-1.home.domain.com" is located on a fixed
or network drive.
VERBOSE: [17:43:42.861 GMT] Move-DatabasePath : Verifying that the log location
"T:NewPath" on server "MBX-1.home.domain.com" has not been occupied by
an existing file or directory.
VERBOSE: [17:43:42.923 GMT] Move-DatabasePath : Checking the existence of log
files under directory "d:MBX-1MBX-1-DB0MBX-1-DB0-Logs" on Server
"MBX-1.home.domain.com".
VERBOSE: [17:46:51.018 GMT] Move-DatabasePath : Admin Audit Log: Entered
Handler:Validate.
VERBOSE: [17:46:51.034 GMT] Move-DatabasePath : Admin Audit Log: Exited
Handler:Validate.

Confirm
Are you sure you want to perform this action?

Moving database path "MBX-1-DB0".
[Y] Yes  [A] Yes to All  [N] No  [L] No to All  [?] Help (default is "Y"): a
VERBOSE: [17:51:35.320 GMT] Move-DatabasePath : Resolved current organization:
.
VERBOSE: [17:51:35.351 GMT] Move-DatabasePath : The Admin RPC connection is
being established with server "MBX-1.home.domain.com".

Confirm
To perform the move operation, database "MBX-1-DB0" must be temporarily
dismounted, which will make it inaccessible to all users. Do you want to
continue?
[Y] Yes  [A] Yes to All  [N] No  [L] No to All  [?] Help (default is "Y"): a
VERBOSE: [17:51:37.586 GMT] Move-DatabasePath : Reading new object
"9d654028-b845-43fc-9b3b-a011c442c9e6" of type "Server".
VERBOSE: [17:51:37.586 GMT] Move-DatabasePath : Dismounting the database,
"MBX-1-DB0".
VERBOSE: [17:51:37.851 GMT] Move-DatabasePath : The file is being copied from
"E:MBX-1MBX-1-DB0MBX-1-DB0-DatabaseMBX-1-DB0.edb" to
"t:NewPathMBX-1-DB0.edb" on server "MBX-1.home.domain.com".
VERBOSE: [17:53:03.177 GMT] Move-DatabasePath : Copying the database Log files
under directory "d:MBX-1MBX-1-DB0MBX-1-DB0-Logs" to the target directory
"T:NewPath" on Server "MBX-1".
VERBOSE: [17:53:03.209 GMT] Move-DatabasePath : Checking the existence of
directory "T:NewPath" on Server "MBX-1.home.domain.com".
VERBOSE: [17:53:03.209 GMT] Move-DatabasePath : Set access control for
directory "T:NewPath" on server "MBX-1.home.domain.com".
VERBOSE: [17:53:03.209 GMT] Move-DatabasePath : Checking the existence of
directory "d:MBX-1MBX-1-DB0MBX-1-DB0-Logs" on Server
"MBX-1.home.domain.com".
VERBOSE: [17:53:03.271 GMT] Move-DatabasePath : Copying the files from
directory "d:MBX-1MBX-1-DB0MBX-1-DB0-Logs" to target directory "T:NewPath"
on server "MBX-1.home.domain.com".
VERBOSE: [17:56:19.237 GMT] Move-DatabasePath : Deleting the file
"t:NewPathMBX-1-DB0.edb" on server "MBX-1".
VERBOSE: [17:56:19.378 GMT] Move-DatabasePath : Reading new object
"9d654028-b845-43fc-9b3b-a011c442c9e6" of type "Server".
VERBOSE: [17:56:19.378 GMT] Move-DatabasePath : The task is attempting to
communicate with the Microsoft Exchange Replication service on server
"MBX-1.home.domain.com" to obtain updated configuration changes for
database "MBX-1-DB0".
VERBOSE: [17:56:19.503 GMT] Move-DatabasePath : Mounting database "MBX-1-DB0".
VERBOSE: [17:56:21.487 GMT] Move-DatabasePath : Admin Audit Log: Entered
Handler:OnComplete.
VERBOSE: [17:56:21.831 GMT] Move-DatabasePath : Admin Audit Log: Exited
Handler:OnComplete.
Failed to move database log files from "d:MBX-1MBX-1-DB0MBX-1-DB0-Logs" to "
T:NewPath".
    + CategoryInfo          : InvalidOperation: (MBX-1-DB0:ADObjectId) [Move-DatabasePath], InvalidOperationException
    + FullyQualifiedErrorId : 7280D023,Microsoft.Exchange.Management.SystemConfigurationTasks.MoveDatabasePath
VERBOSE: [17:56:22.003 GMT] Move-DatabasePath : Ending processing &
[PS] C:>

========================================================

The issue that causes this error is due to the way free space is determined when a mount point is utilized.  In this case we have the following disk layout:

Disk T: –> 8 megs free space.

Disk T:NewPath –>  NewPath is a mount point created from a folder residing on the T volume.  NewPath has 127 gig of free space.

In this case the first check that is performed is a WMI query to determine if the destination has enough free space to accommodate the log files being moved.  Unfortunately the WMI call utilized checks the free space of the mount point root disk, and not the mount point itself.  This results in the destination being preceived as not having enough disk space and the move operation returning failed with an exception.

Note:  This issue only happens when moving log files or moving log files with a database.  If only the database path is adjusted this issue does not occur.

To correct this issue the log files can be moved by hand.  The following steps will work around this condition:

1)  Dismount the database that you want to move log files for.

Dismount-Database –identity <NAME> -verbose

[PS] C:>Dismount-Database -Identity MBX-1-DB0 -Verbose
VERBOSE: [18:12:18.536 GMT] Dismount-Database : Active Directory session
settings for ‘Dismount-Database’ are: View Entire Forest: ‘False’, Default
Scope: ‘home.domain.com’, Configuration Domain Controller:
‘DC-1.home.domain.com’, Preferred Global Catalog:
‘DC-2.home.domain.com’, Preferred Domain Controllers: ‘{
DC-2.home.domain.com }’
VERBOSE: [18:12:18.536 GMT] Dismount-Database : Runspace context: Executing
user: home.domain.com/Users/Administrator, Executing user organization: ,
Current organization: , RBAC-enabled: Enabled.
VERBOSE: [18:12:18.536 GMT] Dismount-Database : Beginning processing &
VERBOSE: [18:12:18.536 GMT] Dismount-Database : Instantiating handler with
index 0 for cmdlet extension agent "Admin Audit Log Agent".
VERBOSE: [18:12:18.583 GMT] Dismount-Database : Current ScopeSet is: {
Recipient Read Scope: {{, }}, Recipient Write Scopes: {{, }}, Configuration
Read Scope: {{, }}, Configuration Write Scope(s): {{, }, }, Exclusive Recipient
Scope(s): {}, Exclusive Configuration Scope(s): {} }
VERBOSE: [18:12:18.583 GMT] Dismount-Database : Searching objects "MBX-1-DB0"
of type "Database" under the root "$null".
VERBOSE: [18:12:18.598 GMT] Dismount-Database : Previous operation run on
domain controller ‘DC-1.home.domain.com’.
VERBOSE: [18:12:18.598 GMT] Dismount-Database : Processing object "MBX-1-DB0".
VERBOSE: [18:12:18.645 GMT] Dismount-Database : Admin Audit Log: Entered
Handler:Validate.
VERBOSE: [18:12:18.645 GMT] Dismount-Database : Admin Audit Log: Exited
Handler:Validate.

Confirm
Are you sure you want to perform this action?

Dismounting database "MBX-1-DB0". This may result in reduced availability for
mailboxes in the database.
[Y] Yes  [A] Yes to All  [N] No  [L] No to All  [?] Help (default is "Y"): a
VERBOSE: [18:12:20.458 GMT] Dismount-Database : Resolved current organization:
.
VERBOSE: [18:12:20.489 GMT] Dismount-Database : The Admin RPC connection is
being established with server "MBX-1.home.domain.com".
VERBOSE: [18:12:20.489 GMT] Dismount-Database : Dismounting the database,
"MBX-1-DB0".
VERBOSE: [18:12:20.817 GMT] Dismount-Database : Admin Audit Log: Entered
Handler:OnComplete.
VERBOSE: [18:12:20.880 GMT] Dismount-Database : Admin Audit Log: Exited
Handler:OnComplete.
VERBOSE: [18:12:20.895 GMT] Dismount-Database : Ending processing &
[PS] C:>

2)  Move the log file path using the configuration only switch which will simply write the new path to the active directory. 

Move-DatabasePath –identity <NAME> –logFolderPath <path> –configurationOnly:$TRUE –verbose

[PS] C:>Move-DatabasePath -Identity MBX-1-DB0 -LogFolderPath T:NewPath -ConfigurationOnly:$TRUE -Verbose
VERBOSE: [18:18:12.047 GMT] Move-DatabasePath : Active Directory session
settings for ‘Move-DatabasePath’ are: View Entire Forest: ‘False’, Default
Scope: ‘home.domain.com’, Configuration Domain Controller:
‘DC-1.home.domain.com’, Preferred Global Catalog:
‘DC-2.home.domain.com’, Preferred Domain Controllers: ‘{
DC-2.home.domain.com }’
VERBOSE: [18:18:12.063 GMT] Move-DatabasePath : Runspace context: Executing
user: home.domain.com/Users/Administrator, Executing user organization: ,
Current organization: , RBAC-enabled: Enabled.
VERBOSE: [18:18:12.063 GMT] Move-DatabasePath : Beginning processing &
VERBOSE: [18:18:12.063 GMT] Move-DatabasePath : Instantiating handler with
index 0 for cmdlet extension agent "Admin Audit Log Agent".
VERBOSE: [18:18:12.063 GMT] Move-DatabasePath : Current ScopeSet is: {
Recipient Read Scope: {{, }}, Recipient Write Scopes: {{, }}, Configuration
Read Scope: {{, }}, Configuration Write Scope(s): {{, }, }, Exclusive Recipient
Scope(s): {}, Exclusive Configuration Scope(s): {} }
VERBOSE: [18:18:12.079 GMT] Move-DatabasePath : Searching objects "MBX-1-DB0"
of type "Database" under the root "$null".
VERBOSE: [18:18:12.360 GMT] Move-DatabasePath : Previous operation run on
domain controller ‘DC-1.home.domain.com’.
VERBOSE: [18:18:12.360 GMT] Move-DatabasePath : Processing object "MBX-1-DB0".
VERBOSE: [18:18:12.391 GMT] Move-DatabasePath : Searching objects
"MBX-1.home.domain.com" of type "Server" under the root "$null".
VERBOSE: [18:18:12.391 GMT] Move-DatabasePath : Previous operation run on
domain controller ‘DC-1.home.domain.com’.

Confirm
This operation will skip the safety check and make the change to Active
Directory directly. Do you want to continue?
[Y] Yes  [A] Yes to All  [N] No  [L] No to All  [?] Help (default is "Y"): a
VERBOSE: [18:18:14.798 GMT] Move-DatabasePath : Admin Audit Log: Entered
Handler:Validate.
VERBOSE: [18:18:14.798 GMT] Move-DatabasePath : Admin Audit Log: Exited
Handler:Validate.

Confirm
Are you sure you want to perform this action?

Moving database path "MBX-1-DB0".
[Y] Yes  [A] Yes to All  [N] No  [L] No to All  [?] Help (default is "Y"): a
VERBOSE: [18:18:16.110 GMT] Move-DatabasePath : Resolved current organization:
.
VERBOSE: [18:18:16.126 GMT] Move-DatabasePath : The Admin RPC connection is
being established with server "MBX-1.home.domain.com".
VERBOSE: [18:18:16.126 GMT] Move-DatabasePath : Saving object "MBX-1-DB0" of
type "Database" and state "Changed".
VERBOSE: [18:18:16.126 GMT] Move-DatabasePath : Previous operation run on
domain controller ‘DC-1.home.domain.com’.
VERBOSE: [18:18:16.126 GMT] Move-DatabasePath : Getting the name of the domain
controller to be used to double write the configurable object’s changes. Double
write is the mechanism to make sure that the changes are persisted in the
domain controller used by the store service on server
"MBX-1.home.domain.com".
VERBOSE: [18:18:16.141 GMT] Move-DatabasePath : Reading new object "MBX-1-DB0"
of type "Database".
VERBOSE: [18:18:16.141 GMT] Move-DatabasePath : Previous operation run on
domain controller ‘DC-1.home.domain.com’.
VERBOSE: [18:18:16.141 GMT] Move-DatabasePath : Double writing changes of the
configurable object, "MBX-1-DB0", on domain controller
"DC-1.home.domain.com".
VERBOSE: [18:18:16.141 GMT] Move-DatabasePath : Previous operation run on
domain controller ‘DC-1.home.domain.com’.
VERBOSE: [18:18:16.141 GMT] Move-DatabasePath : The task is attempting to
communicate with the Microsoft Exchange Replication service on server
"MBX-1.home.domain.com" to obtain updated configuration changes for
database "MBX-1-DB0".
VERBOSE: [18:18:16.298 GMT] Move-DatabasePath : Admin Audit Log: Entered
Handler:OnComplete.
VERBOSE: [18:18:16.313 GMT] Move-DatabasePath : Admin Audit Log: Exited
Handler:OnComplete.
VERBOSE: [18:18:16.313 GMT] Move-DatabasePath : Ending processing &
[PS] C:>

3)  Using ROBOCopy – which is included with Windows 2008 and Windows 2008 R2 – mirror the current log directory to the new location. 

Note:  This command will MOVE the files – that is copy them to the new directory and then delete the original file.

Note:  This command assumes that only log files exist in the directory.  If the database and catalog files exist in the directory they should be skipped.

ROBOCOPY <SOURCE-DIR> <TARGET-DIR> /MOVE /XD *Catalog* /XF *.edb

[PS] C:>robocopy "D:MBX-1MBX-1-DB0MBX-1-DB0-Logs" "T:NewPath" /MOVE /XD *Catalog* /XF *.edb

——————————————————————————-
   ROBOCOPY     ::     Robust File Copy for Windows

——————————————————————————-

  Started : Mon Sep 27 14:50:08 2010

   Source : D:MBX-1MBX-1-DB0MBX-1-DB0-Logs
     Dest : T:NewPath

    Files : *.*

Exc Files : *.edb

Exc Dirs : *Catalog*

  Options : *.* /COPY:DAT /MOVE /R:1000000 /W:30

——————————————————————————

100%        New File               1.0 m        E00res00005.jrs
100%        New File               1.0 m        E00res00006.jrs
100%        New File               1.0 m        E00res00007.jrs
100%        New File               1.0 m        E00res00008.jrs
100%        New File               1.0 m        E00res00009.jrs
100%        New File               1.0 m        E00res0000A.jrs
100%        New File                   0        E00tmp.log

——————————————————————————

               Total    Copied   Skipped  Mismatch    FAILED    Extras
    Dirs :         2         0         2         0         0         1
   Files :      6430      6429         1         0         0         0
   Bytes :   9.158 g   6.275 g   2.882 g         0         0         0
   Times :   0:04:03   0:03:40                       0:00:00   0:00:22

   Speed :            30539839 Bytes/sec.
   Speed :            1747.503 MegaBytes/min.

   Ended : Mon Sep 27 14:44:39 2010
[PS] C:>

3)  Optional:  Move the database file to the new location.

Move-DatabasePath –identity <NAME> –edbFilePath <TargetPathName.edb> –verbose

4)  Mount the database post all move operations (allow sufficient time for AD replication to occur)

Mount-Database –identity <NAME> –verbose

[PS] C:>Mount-Database -Identity MBX-1-DB0 -Verbose
VERBOSE: [19:06:06.471 GMT] Mount-Database : Active Directory session settings
for ‘Mount-Database’ are: View Entire Forest: ‘False’, Default Scope:
‘home.domain.com’, Configuration Domain Controller:
‘DC-1.home.domain.com’, Preferred Global Catalog:
‘DC-2.home.domain.com’, Preferred Domain Controllers: ‘{
DC-2.home.domain.com }’
VERBOSE: [19:06:06.486 GMT] Mount-Database : Runspace context: Executing user:
home.domain.com/Users/Administrator, Executing user organization: ,
Current organization: , RBAC-enabled: Enabled.
VERBOSE: [19:06:06.486 GMT] Mount-Database : Beginning processing &
VERBOSE: [19:06:06.486 GMT] Mount-Database : Instantiating handler with index 0
for cmdlet extension agent "Admin Audit Log Agent".
VERBOSE: [19:06:07.033 GMT] Mount-Database : Current ScopeSet is: { Recipient
Read Scope: {{, }}, Recipient Write Scopes: {{, }}, Configuration Read Scope:
{{, }}, Configuration Write Scope(s): {{, }, }, Exclusive Recipient Scope(s):
{}, Exclusive Configuration Scope(s): {} }
VERBOSE: [19:06:07.033 GMT] Mount-Database : Searching objects "MBX-1-DB0" of
type "Database" under the root "$null".
VERBOSE: [19:06:07.049 GMT] Mount-Database : Previous operation run on domain
controller ‘DC-1.home.domain.com’.
VERBOSE: [19:06:07.065 GMT] Mount-Database : Processing object "MBX-1-DB0".
VERBOSE: [19:06:07.111 GMT] Mount-Database : Admin Audit Log: Entered
Handler:Validate.
VERBOSE: [19:06:07.111 GMT] Mount-Database : Admin Audit Log: Exited
Handler:Validate.
VERBOSE: Mounting database "MBX-1-DB0".
VERBOSE: [19:06:07.127 GMT] Mount-Database : Resolved current organization: .
VERBOSE: [19:06:07.158 GMT] Mount-Database : Searching objects
"home.domain.com/Microsoft Exchange System
Objects/SystemMailbox{ed71935d-a14f-4937-b20d-50b37e136797}" of type
"ADRecipient" under the root "$null".
VERBOSE: [19:06:07.752 GMT] Mount-Database : Mounting database "MBX-1-DB0".
VERBOSE: [19:06:08.971 GMT] Mount-Database : Admin Audit Log: Entered
Handler:OnComplete.
VERBOSE: [19:06:09.065 GMT] Mount-Database : Admin Audit Log: Exited
Handler:OnComplete.
VERBOSE: [19:06:09.065 GMT] Mount-Database : Ending processing &
[PS] C:>

At this time we expect this issue to be resolved in Exchange 2010 Service Pack 2.

Recently some customers have experienced an issue where database copies do not display when using the Exchange Management Console after upgrading to Exchange 2010 Service Pack 1.  When attempting to view database copies using the Exchange Management Shell no issue is displayed. 

Database copies can be viewed in two locations. 

The first location is under Organization Configuration –> Mailbox –> Database Management.  In this view when an administrator selects a database from the list, the Database Copies displayed in the bottom portion of the display are missing ALL or SOME copies for a given database.  Here is an example of a 4 node DAG with a database replicated to all 4 members:

All Database Copies Missing:

Some Database Copies Missing:

Expected output showing all database copies:

The second location is under Server Configuration –> Mailbox.  By selecting a server with the mailbox role you can view the individual database copies assigned to that server.  Here is an example of database copies missing from the server:

Whether all database copies are missing <or> some database copies are missing the Exchange Management Shell command Get-MailboxDatabaseCopyStatus always returns accurate information.  Here is a copy of Get-MailboxDatabaseCopyStatus *:

When any Exchange role is installed on the server (with exception of Edge transport) the hostname of the server is written into the Exchange configuration container within Active Directory.  In this case the server name was established with a lower case.  It was established in the container with a lower case because the hostname of the server, which was established during setup, was established with a lower case name (or a portion of the name lowercase).

In reference customers running HOSTNAME <or> reviewing the full computer name in server management showed that all or a portion of the name was lower case.

The Exchange Management Console code incorrectly compares case when comparing a database copy against a server name.  This causes the console to not display all the valid database copies.

Let’s step through an example.

In this example there is a four node DAG.  The server names are as follows:

Dag-1

dag-2

DAG-3

DAG-4

You can verify these server names by running get-databaseavailabilitygroup –identity <DAGName> | fl name,servers

[PS] D:>Get-DatabaseAvailabilityGroup -Identity DAG | fl name,servers

Name    : DAG
Servers : {DAG-4, DAG-3, dag-2, Dag-1}

When looking in the management console, and selecting any database replicated to all four members, the only copies that will be displayed are on nodes DAG-4 and DAG-3.

When the Exchange Management Console draws the database copies pane, it compares the host server name of a database copy to the server name of a database copy status.  This comparison is case sensitive.  Let’s take a look at a database copy that fails to display when viewing the copies for DAG-1.

(Get-MailboxDatabase –identity <NAME>).databasecopies | fl hostservername

[PS] D:>(Get-MailboxDatabase DAG-DB0).databasecopies | fl hostservername

HostServerName : Dag-1

HostServerName : DAG-3

HostServerName : DAG-4

HostServerName : dag-2

(Get-MailboxDatabaseCopyStatus <NAME><Server>).mailboxserver

[PS] D:>(Get-MailboxDatabaseCopyStatus DAG-DB0DAG-1).mailboxServer
DAG-1

In this case DAG-1 != Dag-1 and therefore the copy does not display in the management console.

Let’s take a look at a copy that does display.

(Get-MailboxDatabase –identity <NAME>).databasecopies | fl hostservername

[PS] D:>(Get-MailboxDatabase DAG-DB0).databasecopies | fl hostservername

HostServerName : Dag-1

HostServerName : DAG-3

HostServerName : DAG-4

HostServerName : dag-2

(Get-MailboxDatabaseCopyStatus <NAME><Server>).mailboxserver

[PS] D:>(Get-MailboxDatabaseCopyStatus DAG-DB0DAG-4).mailboxServer
DAG-4

In this case DAG-4 == DAG-4 and therefore the copy does display in the management console.

Unfortunately at this time we can only recommend that database copies for missing servers be managed using the Exchange Management Shell.  It is not recommended to attempt to modify the active directory at this time to overcome this issue.

At this time we are filing the necessary bugs to get this permanently corrected without modifying server names.  I will update this blog as this process progresses.

=======================================

Update 10/10/2010

This issue is currently scheduled to be corrected in Exchange 2010 SP1 Rollup Update 3.  

=======================================