Exchange 2010 GRT error restore

[Ziggy1941]

I have MS Exchange 2010 standalone installation in VMware 5.1 virtual infrastructure. Also I have NBU 7.6 FA master standalone server in virtual machine too.

All configs I done according to the documentation "Symantec NetBackup for Microsoft Exchange Server Administrator’s Guide for Windows Release 7.6". All versions - master server and client - is the same. OS version on client side is MS 2008 R2.

I try to backup with VMware Policy and GRT restore individual messages with MS-Exchange Policy. Backup process looks fine:

01.12.2013 21:10:48 - Info nbjm (pid=3612) starting backup job (jobid=194) for client exchange.mydomain.ru, policy exchange.mydomain.ru, schedule Full
01.12.2013 21:10:48 - estimated 1817082459 kbytes needed
01.12.2013 21:10:48 - Info nbjm (pid=3612) started backup (backupid=exchange.mydomain.ru_1385910648) job for client exchange.mydomain.ru, policy exchange.mydomain.ru, schedule Full on storage unit pd_unit
01.12.2013 21:10:48 - started process bpbrm (pid=5596)
01.12.2013 21:10:49 - Info bpbrm (pid=5596) exchange.mydomain.ru is the host to backup data from
01.12.2013 21:10:49 - Info bpbrm (pid=5596) reading file list for client
01.12.2013 21:10:49 - Info bpbrm (pid=5596) accelerator enabled
01.12.2013 21:10:51 - Info bpbrm (pid=5596) starting bpbkar32 on client
01.12.2013 21:10:51 - connecting
01.12.2013 21:10:51 - connected; connect time: 0:00:00
01.12.2013 21:10:53 - Info bpbkar32 (pid=2036) Backup started
01.12.2013 21:10:53 - Info bpbkar32 (pid=2036) accelerator enabled backup, archive bit processing:<disabled>
01.12.2013 21:10:53 - Info bptm (pid=2324) start
01.12.2013 21:10:53 - Info bptm (pid=2324) using 262144 data buffer size
01.12.2013 21:10:53 - Info bptm (pid=2324) setting receive network buffer to 1049600 bytes
01.12.2013 21:10:53 - Info bptm (pid=2324) using 30 data buffers
01.12.2013 21:10:54 - Info bptm (pid=2324) start backup
01.12.2013 21:10:54 - begin writing
01.12.2013 21:12:59 - Info bpbkar32 (pid=2036) INF - Transport Type =  hotadd
01.12.2013 21:30:25 - Info bptm (pid=2324) waited for full buffer 1938 times, delayed 11314 times
01.12.2013 21:30:26 - Info bpbkar32 (pid=2036) accelerator sent 27545917952 bytes out of 1533192415232 bytes to server, optimization 98.2%
01.12.2013 21:30:26 - Info bpbkar32 (pid=2036) bpbkar waited 10850 times for empty buffer, delayed 13733 times.
01.12.2013 21:30:30 - Info bptm (pid=2324) EXITING with status 0 <----------
01.12.2013 21:30:30 - Info nbu-s2.mydomain.ru (pid=2324) StorageServer=PureDisk:nbu-s2.mydomain.ru; Report=PDDO Stats for (nbu-s2.mydomain.ru): scanned: 1497303482 KB, CR sent: 16996502 KB, CR sent over FC: 0 KB, dedup: 98.9%, cache disabled
01.12.2013 21:30:30 - Info bpbrm (pid=5596) validating image for client exchange.mydomain.ru
01.12.2013 21:30:31 - Info bpbkar32 (pid=2036) done. status: 0: the requested operation was successfully completed
01.12.2013 21:30:31 - end writing; write time: 0:19:37
the requested operation was successfully completed  (0)

But when I try to restore individual messages from existing mailbox to the same path, I have error:

02.12.2013 12:18:30 - begin Restore
02.12.2013 12:18:31 - restoring from image exchange.mydomain.ru_1385910032
02.12.2013 12:18:31 - Info bprd (pid=1368) Restoring from copy 1 of image created 12/01/13 21:00:32 from policy exchange.mydomain.ru
02.12.2013 12:18:31 - Info bprd (pid=1368) Granular restore has started, this may take a while....
02.12.2013 12:18:34 - Info bpbrm (pid=2324) EXCHANGE is the host to restore to
02.12.2013 12:18:34 - Info bpbrm (pid=2324) reading file list for client
02.12.2013 12:18:35 - connecting
02.12.2013 12:18:35 - Info bpbrm (pid=2324) start nbfsd on client
02.12.2013 12:18:37 - Info bpbrm (pid=2324) start nbgre on client
02.12.2013 12:18:44 - Info tar32 (pid=0) Restore started
02.12.2013 12:18:44 - connected; connect time: 0:00:00
02.12.2013 12:28:18 - Error bpbrm (pid=2324) from client EXCHANGE: ERR - Unable to restore. Skipping file: Microsoft Information Store\DOR_database2\Database\testbackup [testbackup97c]\Top of Information Store\Inbox\RE: ???????? <00000000fb55387cbb3d8340ad5c531f736769a2070095c55a2cfd692643b3815f4e23f784760000004ea413000095c55a2cfd692643b3815f4e23f784760000004ecd900000>
02.12.2013 12:28:19 - Info tar32 (pid=0) done. status 103
02.12.2013 12:28:19 - Info tar32 (pid=0) done. status: 103
02.12.2013 12:28:19 - Info tar32 (pid=0) done. status: 103: error occurred during initialization, check configuration file
02.12.2013 12:28:19 - Error bpbrm (pid=2324) client restore EXIT STATUS 103: error occurred during initialization, check configuration file
02.12.2013 12:28:19 - restored from image exchange.mydomain.ru_1385910032; restore time: 0:09:48
02.12.2013 12:28:19 - end Restore; elapsed time 0:09:49
MS-Exchange policy restore error  (2810)

And error in bpbrm.log:

12:28:18.902 [2324.6184] <16> bpbrm main: from client EXCHANGE: ERR - Unable to restore. S
kipping file: Microsoft Information Store\DOR_database2\Database\testbackup [testbackup97c
]\Top of Information Store\Inbox\RE: Oaiuaiea <00000000fb55387cbb3d8340ad5c531f736769a2070
095c55a2cfd692643b3815f4e23f784760000004ea413000095c55a2cfd692643b3815f4e23f784760000004ec
d900000>
12:28:18.918 [2324.6184] <4> db_error_add_to_file: from client EXCHANGE: ERR - Unable to r
estore. Skipping file: Microsoft Information Store\DOR_database2\Database\testbackup [test
backup97c]\Top of Information Store\Inbox\RE: Oaiuaiea <00000000fb55387cbb3d8340ad5c531f73
6769a2070095c55a2cfd692643b3815f4e23f784760000004ea413000095c55a2cfd692643b3815f4e23f78476
0000004ecd900000>
12:28:18.934 [2324.6184] <2> read_client: ?

...

12:28:19.027 [2324.6184] <2> bpbrm write_msg_to_progress_file: (232.001) ERR - Unable to r
estore. Skipping file: Microsoft Information Store\DOR_database2\Database\testbackup [test
backup97c]\Top of Information Store\Inbox\RE: Oaiuaiea <00000000fb55387cbb3d8340ad5c531f73
6769a2070095c55a2cfd692643b3815f4e23f784760000004ea413000095c55a2cfd692643b3815f4e23f78476
0000004ecd900000>

12:28:19.121 [2324.6184] <2> bpbrm write_msg_to_progress_file: (232.001) INF - GRE EXITING
 WITH STATUS = 103

12:28:19.121 [2324.6184] <2> bpbrm main: from client EXCHANGE: INF - GRE RESTORED 0 OF 1 S
UCCESSFULLY
12:28:19.136 [2324.6184] <2> job_monitoring_exex: ACK disconnect
12:28:19.136 [2324.6184] <2> job_disconnect: Disconnected
12:28:19.136 [2324.6184] <2> bpbrm write_msg_to_progress_file: (232.001) INF - GRE RESTORE
D 0 OF 1 FILES SUCCESSFULLY

Can anyone to point me what can I do to resolve this problem?

 

[rawilde]

This is a supported configuration. Can you produce a verbose ncflbc and get it to me?  By verbose I mean general=2 and verbose=5 on the client wher ethe GRT browse should be reunning.  See if you can get that log to me.

[Ziggy1941]

Hi, Rawilde! Thanks for your replay.

Ncflbc log with level 2 in attach. Do you need log level 5 too?

[rawilde]

Ziggy1941

There is over a 3minute gap until the error is reported in the log you uploaded.  The VDDK traces do not appear unless we have more verbose logging.  So on the target client, you can use the BAR gui to set general=2 and verbose=5.

1/19/2014 22:45:50.766 V-309-28 [_nbfs_mount_validate_thread()] INF - validating mount

1/19/2014 22:49:01.565 [ResourceChildBEDS::_attach()] FS_AttachToDLE() Failed! (0xE0009741:Failed to mount one or more virtual disk images. Restores that use Granular Recovery Technology may not be available from this backup set.) (../ResourceChild.cpp:667)

1/19/2014 22:49:01.565 [Warning] V-158-3 unable to successfully enumerate: Microsoft Information Store\DOR_database2\Database

[Ziggy1941]

Hi Rawilde!

I have no local access to the exchange server console and BAR. I set "verbose = 5" in NetBackup administration console, in Client Properties / Logging / Global logging level = 5. Not the same as what you mean?

New log on attach.

[rawilde · Accepted solution]

That log is verbose enough. Perfect.

Looks like its an issue with the virtfile driver.

I see this in the log:

1/21/2014 22:30:08.159 [                    ] <from Producer::iterateResource> !FilterLoad FILE_NOT_FOUND error. (../BEDSContext.cpp:164)

1/21/2014 22:30:08.159 [                    ] <from Producer::iterateResource> !Unable to load VirtFile (../BEDSContext.cpp:164)

1/21/2014 22:30:08.159 [                    ] <from Producer::iterateResource> !FilterConnectCommunicationPort FILE_NOT_FOUND error. (../BEDSContext.cpp:164)

This can hopefully be fixed fairly easy.  Type this in at the CMD box of the Exchange server:

"c:\sc query virtfile"

You probably either see an error that its not installed or stopped.  In Windows explorer, go to the Netbackup install bin directory and then virtfile, such as:  C:\Program Files\Veritas\NetBackup\bin\VirtFile

Right click on the virtfile.inf file and select install. Running the "sc query" command again should show the driver as running.  If this all looks good, try the GRT browse again.

[Ziggy1941]

Hooray! You're right, the whole thing in this service (virtfile).

Now all working fine (browsing and GRT restoring).

Thanks very much for your help!!!

[rawilde]

Good to hear.