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?

 

[V4]

can we have tar log pls seems something wrong in restore configuration . could be incorrect path 

[Mark_Solutions]

Do you have the Microsoft Messaging API and Collaboration Data Objects installed on your exchange nodes - as well as the NFS and everything else you need that installed to actually do the restores of individual items

[V4]

mark i guess for ex2010 CDO is not required...

[Ziggy1941]

Hi Mark, Jack!

At first, we have a problem with GRT restore only from VMware-Policy Exchange server. When we backup Exchange with traditional MS-Exchange-Policy - we can GRT restore without any troubles.

And secondly, sorry I can't to provide TAR logs for the our original problem. Now we have another one. :(

May be problem in big size our exchange database (about 1.5 Tb). Now we can't to view the content of VMware-Policy archives. Some strange error (look to Clipboard01.jpg in attach). But at the same time all looks good with MS-Exchange-Policy archives (look to Clipboard02.jpg in attach).

P.S.: Sorry for my bad english (

[Mark_Solutions]

OK - not exactly going to help with this restore but a few things that may help you here:

1. Increase the client read timeout on your media servers - maybe 3600 to allow plenty of time for the system to mount and read the databases

2. Reduce your fragment size on you storage unit - 5000MB works well for GRT restores / duplications - it helps the system locate the blocks in needs much quicker - it may also prevent the timeout you are getting when doing the browse / restore

3. Set the media server to be the GRT proxy server (exchange servers host properties - windows - exchange) so that all of the work takes place on the media server and not the exchange server

I know you wont be able to test this until you have run a new backup with the new fragment size but hopefully it will help for future restores

There are lots of pre-requisites as well so it is worth just double checking everything in the guide

You can also catalog a GRT exchange backup to make browsing the contents quicker - the bpduplicate -bc option is used for that.

[Ziggy1941]

> 1. Increase the client read timeout on your media servers 

Alrady done. "Client connect timeout" and "Client read timeout" both set to 3600.

> 2. Reduce your fragment size on you storage unit - 5000MB 

Alrady done.

Unfortunately both (1 & 2) did not help.

> 3. Set the media server to be the GRT proxy server (exchange 

> servers host properties - windows - exchange) so that all of 

> the work takes place on the media server and not the exchange server

Does this mean that I need to have the same versions OS and MS Exchange software on Exchange server and on media server (Exchange GRT proxy host)?

> You can also catalog a GRT exchange backup to make browsing 

> the contents quicker - the bpduplicate -bc option is used for that.

Do you mean "bpduplicate -bc_only" command? 

I thought about it. Will try. But I think it will take too much time.

[Mark_Solutions]

Apologies - it was the -bc_only switch

The media server should be the same O/S version as the Exchange Server according to the latest docs - whether that just means "Windows" or a lot deeper i am unsure to be honest - you could give it a try anyway - that would work with existing images so easy to test

[Ziggy1941]

> You can also catalog a GRT exchange backup to make browsing 

> the contents quicker - the bpduplicate -bc option is used for that.

Unfortunately did not help also.

ziggy:~$ bpduplicate -bc_only

INF - db_IMAGE() failed: database system error (220)

And Job details:

24.12.2013 17:02:18 - begin Duplicate

24.12.2013 17:02:19 - requesting resource @aaaab

24.12.2013 17:02:19 - granted resource MediaID=@aaaab;DiskVolume=PureDiskVolume;DiskPool=pd_pool;Path=PureDiskVolume;StorageServer=nbu-s2.ussc.ru;MediaServer=nbu-s2.ussc.ru

24.12.2013 17:11:00 - Error bpduplicate(pid=6376) db_IMAGE() failed: database system error (220)       

[Mark_Solutions]

AH! - Hitting a 10 minute timeout somewhere (though looks like 9 minutes!) - same as the issue when browsing

If all timeouts have been increased then it may be that the new hardcoded timeouts for bpcd and bpdbm that were increase in 7.5.0.4 (I think) may have crept back into 7.6

Worth double checking all of your client read timeouts - including for the Master Server though

[Ziggy1941]

> Worth double checking all of your client read timeouts - including for the Master Server though

Hmmm... Look to attach - timeout settings for Master server, Media server (the same host that Master) and Client.

[Mark_Solutions]

OK - could be the old harcoded timeout has crept back in then.

I dont see anything the the 7.6.0.1 notes to say it was fixed from 7.6 FA

May be worth raising a case

[Ziggy1941]

OK

Will try the last option - with media server host as GRT proxy host in client's settings...

[Mark_Solutions]

There is a section saying that the O/S must be supported - so if the media servers are 2008 you should be fine

[Ziggy1941]

Unfortunately again, did not help. The same error: status 220 database system error. :(

bpdbm log:

10:45:01.539 [2412.5860] <2> logconnections: BPDBM ACCEPT FROM 192.168.12.62.55244 TO 192.168.12.62.13721 fd = 556

10:45:01.539 [2412.5860] <4> bpdbm: VERBOSE = 1

10:45:01.554 [2412.5860] <2> process_request: request complete: exit status 0  ; query type: 98

10:46:45.170 [5212.5956] <2> job_monitoring_exex: ACK disconnect

10:46:45.170 [5212.5956] <2> job_disconnect: Disconnected

10:46:45.341 [5212.5956] <2> bpcr_disconnect_rqst: bpcr received the following message: 

10:46:45.341 [5212.5956] <2> bpcr_disconnect_rqst: bpcr received the following message: 

10:46:45.341 [5212.5956] <2> jmcomm_ReleaseAllResourcesForJob: releaseAllResources returns [0]

10:46:45.341 [5212.5956] <2> jmcomm_ReleaseAllResourcesForJob: returning

10:46:45.404 [5212.5956] <2> process_request: request complete: exit status 220 database system error; query type: 79

Full today log in attach. Restore session start at 10:38.

[V4]

Did you had chance to upgrade your environment to 7.6.0.1 (its GA now). As error in last log was resolved in 7506. Wondering its poping up again in 7.6 FA

Get hold of support and check if there is EEB which can be helpful

[styunin]

Hello,

Have you resolved this issue? Did you find some solution?

[Ziggy1941]

Unfortunately we have not found ((

[Ziggy1941]

I have found another strange symptom.

ncflbc log on exchange server side:

0,51216,158,351,30,1389936741329,4252,10192,0:,44:Device Name : C: (../SubContextBEDS.cpp:182),14:_dumpDLEInfo(),1

0,51216,158,351,31,1389936741329,4252,10192,0:,44:Device Name : E: (../SubContextBEDS.cpp:182),14:_dumpDLEInfo(),1

0,51216,158,351,32,1389936741329,4252,10192,0:,44:Device Name : F: (../SubContextBEDS.cpp:182),14:_dumpDLEInfo(),1

0,51216,158,351,33,1389936741329,4252,10192,0:,62:Device Name : EFI>System>Partition (../SubContextBEDS.cpp:182),14:_dumpDLEInfo(),1

0,51216,158,351,34,1389936741329,4252,10192,0:,69:Device Name : Microsoft Terminal Services (../SubContextBEDS.cpp:182),14:_dumpDLEInfo(),1

0,51216,158,351,35,1389936741329,4252,10192,0:,67:Device Name : Microsoft Windows Network (../SubContextBEDS.cpp:182),14:_dumpDLEInfo(),1

0,51216,158,351,36,1389936741329,4252,10192,0:,53:Device Name : NFS Network (../SubContextBEDS.cpp:182),14:_dumpDLEInfo(),1

0,51216,158,351,37,1389936741329,4252,10192,0:,81:Device Name : \\EXCHANGE\Microsoft Exchange Mailboxes (../SubContextBEDS.cpp:182),14:_dumpDLEInfo(),1

0,51216,158,351,38,1389936741329,4252,10192,0:,86:Device Name : \\EXCHANGE\Microsoft Exchange Public Folders (../SubContextBEDS.cpp:182),14:_dumpDLEInfo(),1

0,51216,158,351,39,1389936741329,4252,10192,0:,54:Device Name : System?State (../SubContextBEDS.cpp:182),14:_dumpDLEInfo(),1

0,51216,158,351,40,1389936741329,4252,10192,0:,75:Device Name : Active Directory Application Mode (../SubContextBEDS.cpp:182),14:_dumpDLEInfo(),1

0,51216,158,351,41,1389936741329,4252,10192,0:,80:Device Name : \\EXCHANGE\Microsoft Information Store (../SubContextBEDS.cpp:182),14:_dumpDLEInfo(),1

0,51216,158,351,42,1389936741329,4252,10192,0:,112:1 Child Device Name : \\EXCHANGE\Microsoft Information Store\Administration_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,43,1389936741329,4252,10192,0:,101:2 Child Device Name : \\EXCHANGE\Microsoft Information Store\DIB_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,44,1389936741329,4252,10192,0:,101:3 Child Device Name : \\EXCHANGE\Microsoft Information Store\DIS_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,45,1389936741329,4252,10192,0:,102:4 Child Device Name : \\EXCHANGE\Microsoft Information Store\DITS_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,46,1389936741329,4252,10192,0:,101:5 Child Device Name : \\EXCHANGE\Microsoft Information Store\DOR_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,47,1389936741329,4252,10192,0:,102:6 Child Device Name : \\EXCHANGE\Microsoft Information Store\DOR_database2 (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,48,1389936741329,4252,10192,0:,102:7 Child Device Name : \\EXCHANGE\Microsoft Information Store\OMiP_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,49,1389936741329,4252,10192,0:,101:8 Child Device Name : \\EXCHANGE\Microsoft Information Store\Pub_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,50,1389936999754,4252,10192,0:,203: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),28:ResourceChildBEDS::_attach(),1

[Ziggy1941]

I have found another symptom in ncflbc log on the exchange server client side.

When I try to browse VMware policy backup, in the logs I  I see the following:

0,51216,158,351,41,1389936741329,4252,10192,0:,80:Device Name : \\EXCHANGE\Microsoft Information Store (../SubContextBEDS.cpp:182),14:_dumpDLEInfo(),1

0,51216,158,351,42,1389936741329,4252,10192,0:,112:1 Child Device Name : \\EXCHANGE\Microsoft Information Store\Administration_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,43,1389936741329,4252,10192,0:,101:2 Child Device Name : \\EXCHANGE\Microsoft Information Store\DIB_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,44,1389936741329,4252,10192,0:,101:3 Child Device Name : \\EXCHANGE\Microsoft Information Store\DIS_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,45,1389936741329,4252,10192,0:,102:4 Child Device Name : \\EXCHANGE\Microsoft Information Store\DITS_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,46,1389936741329,4252,10192,0:,101:5 Child Device Name : \\EXCHANGE\Microsoft Information Store\DOR_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,47,1389936741329,4252,10192,0:,102:6 Child Device Name : \\EXCHANGE\Microsoft Information Store\DOR_database2 (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,48,1389936741329,4252,10192,0:,102:7 Child Device Name : \\EXCHANGE\Microsoft Information Store\OMiP_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,49,1389936741329,4252,10192,0:,101:8 Child Device Name : \\EXCHANGE\Microsoft Information Store\Pub_database (../SubContextBEDS.cpp:108),19:_dumpChildDLEInfo(),1

0,51216,158,351,50,1389936999754,4252,10192,0:,203: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),28:ResourceChildBEDS::_attach(),1

May be GRT restore and VMware policy Exchange backup are incompatible? ))