Exchange 2010/2013 Database restore to Recovery Database succeeds but size is wrong

Article:TECH213326  |  Created: 2013-12-14  |  Updated: 2014-05-22  |  Article URL http://www.symantec.com/docs/TECH213326
Article Type
Technical Solution


Issue



Restore is successful (status 0), database does mount but size is wrong. Original backup was taken with client properties of the exchange node set to Continue with backup if consistency check fails. This caused a status 1 during backup but shows the original database size in the restore GUI.


Error



bpbrm exits with status 0 (success):
16:02:29.571 [13874] <2> bpbrm main: INITIATING (VERBOSE = 5): version NetBackup 7.5 2013061020
16:02:30.135 [13874] <2> bpbrm read_selected_restore_filelist: /Microsoft Exchange Database Availability Groups/[DAG Name]/Microsoft Information Store/[Mailbox Database Name]/ has been selected for restore by the user
16:02:43.297 [13874] <2> write_file_names: buffering file name '/Microsoft Exchange Database Availability Groups/[DAG Name]/Microsoft Information Store/[Mailbox Database Name]/' for output
16:02:43.297 [13874] <2> set_job_details: Tfile (2794331): LOG 1380744163 4 bpbrm 13874 bptm pid: 13892

****** restore in progress
16:08:42.302 [13874] <2> bpbrm wait_for_child: start
16:08:42.389 [13874] <2> bpbrm main: from client [Dag Node]: INF - There are no jobs remaining for this restore request. Exchange database recovery will be performed.
16:08:42.390 [13874] <2> bpbrm main: from client [Dag Node]: INF - After restoring a Microsoft Exchange LCR, CCR, or DAG database, you must use the Exchange Management Shell to resume replication.
16:08:48.499 [13874] <2> bpbrm main: from client [Dag Node]: INF - Database RDB2 mounted successfully.
16:08:48.682 [13874] <2> bpbrm main: from client [Dag Node]: INF - TAR RESTORED 6 OF 6 FILES SUCCESSFULLY
16:08:48.689 [13874] <2> bpbrm main: from client [Dag Node]: INF - TAR KEPT 0 EXISTING FILES
16:08:48.689 [13874] <2> bpbrm main: from client [Dag Node]: INF - TAR PARTIALLY RESTORED 0 FILES
16:08:48.689 [13874] <2> bpbrm main: from client [Dag Node]: INF - TAR EXITING WITH STATUS = 0 - the requested operation was successfully completed

bptm:
**** start restore database
16:06:28.664 [13895] <2> get_next_file: [13892] received string: (22547 46549747 886 0 0 84 144772554 /Microsoft Exchange Database Availability Groups/[DAG Name]/Microsoft Information Store/[Mailbox Database Name]/Database)
16:06:28.664 [13895] <2> write_bytes: [13892] writing 1536 data bytes, input length was 1398, SAVE_BYTES = 0, file = /Microsoft Exchange Database Availability Groups/[DAG Name]/Microsoft Information Store/[Mailbox Database Name]/Database

**** start restoring logs
16:06:28.664 [13895] <2> get_next_file: [13892] received string: (22549 46549762 269766720 6 0 6 269766386 /Microsoft Exchange Database Availability Groups/[DAG Name]/Microsoft Information Store/[Mailbox Database Name]/Logs_1379466789)
16:06:28.664 [13895] <2> write_bytes: [13892] writing 269767680 data bytes, input length was 269767232, SAVE_BYTES = 0, file = /Microsoft Exchange Database Availability Groups/[DAG Name]/Microsoft Information Store/[Mailbox Database Name]/Logs_1379466789

**** restore complete
16:08:42.238 [13892] <2> bptm: EXITING with status 0 <----------

tar:
4:07:05.262 PM: [4776.4348] <2> ov_log::V_GlobalLog: INF - Informational: Completed IVssBackupComponents::AddNewTarget for Component f82dc497-a02b-4a50-be96-5c0285e14484, OriginalFilePath G:\Exchange Server\V14\Mailbox\[Mailbox Database Name]\, OriginalFileSpec [Mailbox Database Name].edb, AlterNatePath G:\RDB2\ in SHADOW::PerformPreCustomRestoreMethods
**** start restore database
4:07:05.714 PM: [4776.4348] <2> tar_base::V_vTarMsgM: TAR - Microsoft Exchange Database Availability Groups:\[DAG Name]\Microsoft Information Store\[Mailbox Database Name]\Database
4:07:05.714 PM: [4776.4348] <2> tar_base::V_vTarMsgM: MNR - The file was renamed to the following:
4:07:05.714 PM: [4776.4348] <2> tar_base::V_vTarMsgM: UTF - Microsoft Information Store:\RDB2\Database

**** start restoring logs
4:07:05.917 PM: [4776.4348] <2> tar_base::V_vTarMsgM: TAR - Microsoft Exchange Database Availability Groups:\[DAG Name]\Microsoft Information Store\[Mailbox Database Name]\Logs_1379466789
4:07:05.917 PM: [4776.4348] <2> tar_base::V_vTarMsgM: MNR - The file was renamed to the following:
4:07:05.917 PM: [4776.4348] <2> tar_base::V_vTarMsgM: UTF - Microsoft Information Store:\RDB2\Logs_1379466789

**** restore complete
4:08:48.550 PM: [4776.4348] <2> tar_base::backup_finish: TAR - restore: 6 files
4:08:48.550 PM: [4776.4348] <2> tar_base::backup_finish: TAR - restore: file data: 269974170 bytes 6 gigabytes
4:08:48.550 PM: [4776.4348] <2> tar_base::backup_finish: TAR - restore: image data: 269993984 bytes 6 gigabytes
4:08:48.550 PM: [4776.4348] <2> tar_base::backup_finish: TAR - restore: elapsed time: 365 secs 18390260 bps
4:08:48.613 PM: [4776.4348] <2> tar_base::V_vTarMsgW: INF - TAR EXITING WITH STATUS = 0
4:08:48.613 PM: [4776.4348] <2> tar_base::V_vTarMsgW: INF - TAR RESTORED 6 OF 6 FILES SUCCESSFULLY
4:08:48.613 PM: [4776.4348] <2> tar_base::V_vTarMsgW: INF - TAR KEPT 0 EXISTING FILES
4:08:48.613 PM: [4776.4348] <2> tar_base::V_vTarMsgW: INF - TAR PARTIALLY RESTORED 0 FILES

bpdbm:
*** find image
16:02:08.768 [18633] <2> ImageListFiles::executeQuery: pattern = /Microsoft Exchange Database Availability Groups/[DAG Name]/Microsoft Information Store/[Mailbox Database Name]/
...
16:02:08.779 [18633] <2> strcmp_match_file_list: pattern:/Microsoft Exchange Database Availability Groups/[DAG Name]/Microsoft Information Store/[Mailbox Database Name]/ level:1002 path_independent:0 fl_option:0x5800082
...
16:08:50.333 [18633] <16> readNextPattern: db_FLISTreceive failed: premature eof encountered (233)
16:08:50.335 [18633] <2> process_request: request complete: exit status 233 premature eof encountered; query type: 79


Environment



Master: NetBackup 7.1.0.x, 7.5.0.x or 7.6
Client: Windows 2008, 2008 R2, 2012


Cause



The image was retained due to client setting Continue with backup if consistency check fails. Our database (bpdbm) recorded the image on media to be smaller than actual database size. When this size was sent from bptm to tar on client, the client received the smaller size file and claimed success. After the restore completed, then bpdbm repored status 233 (premature eof encountered). This was after the job ended so was not reported in detailed status.

*** summary of bptm:
example of bad bptm:
16:06:28.664 [13895] <2> get_next_file: [13892] received string: (22547 46549747 886 0 0 84 144772554 /Microsoft Exchange Database Availability Groups/[DAG Name]/Microsoft Information Store/[Mailbox Database Name]/Database)
COMPRESSED_SIZE 886
              <---- notice this size is much smaller then next parameter (cause of the issue)
ORIGINAL_SIZE 144772554

16:06:28.664 [13895] <2> get_next_file: [13892] received string: (22549 46549762 269766720 6 0 6 269766386 /Microsoft Exchange Database Availability Groups/[DAG Name]/Microsoft Information Store/[Mailbox Database Name]/Logs_1379466789)
COMPRESSED_SIZE 269766720
        <---- this is larger then original due to additional header detail added
ORIGINAL_SIZE 269766386

example of good bptm:
09:29:43.097 [1692.1808] <2> get_next_file: [3872] received string: (5 172 142677050 0 0 0 142676734 /Microsoft Exchange Database Availability Groups/v4w8re8m1e10dag/Microsoft Information Store/Dag2-Mbx 001/Database)
COMPRESSED_SIZE   142677050
STAT_SIZE   142676734

09:30:22.128 [1692.1808] <2> get_next_file: [3872] received string: (9 285170 22046572 0 0 0 22046240 /Microsoft Exchange Database Availability Groups/v4w8re8m1e10dag/Microsoft Information Store/Dag2-Mbx 001/Logs_1385497577)
COMPRESSED_SIZE   22046572
STAT_SIZE   22046240


Solution



Disable the client setting Continue with backup if consistency check fails. A fix for this behavior is scheduled for 7.6.0.2 via Etrack 3363088 A change to the restore gui was created to display blank size if the size on media is not greater than original size. This fix is available for 7.5.0.6 using Java in Etrack 3350227 and Windows in Etrack 3358567.




Article URL http://www.symantec.com/docs/TECH213326


Terms of use for this information are found in Legal Notices