NDMP restore issue

[Henning_General]

Hello People,

I want to restore old LTO3 tapes(written by an EMC Cellera) to same EMC Cellera

The ndmp host is configured. 

I have got a new Windows Server 2008R2 with NBU 7.5 installed. It´s my first time to restore with NDMP

In the Restore Manger I filled in the following configuration:

Server: My master server

Source Client: the ndmp filer 

Destination Client: the ndmp host, which is already configurated

Policy: NDMP

When I try to start the restore everything to differnt location, than this error will apear. Unable to connect to Netbackup host "myNdmphost"

Thanks for your help!

Henning

[Marianne]

We normally see this when NBU believes it needs to restore to 'normal' NBU client with NBU software installed.

So, somewhere somehow there is an incorrect configuration.

Can you configure a backup policy for this filer and try to backup one volume?
No need to wait for backup to start - the moment the backup starts writing to tape or other destination, kill the backup.
This will confirm all is well with NDMP config.

To troubleshoot the restore:
Do you have bprd log folder on the master server?
If not, please create the folder under ...netbackup\logs and restart NBU.

After next failed restore attempt, please find this section in bprd log and post here:

.... <2> restorefiles:    browse_client =
.... <2> restorefiles:    requesting_client =
.... <2> restorefiles:    destination_client =
.... <2> restorefiles:    requesting_client_hostname =
.... <2> restorefiles:    destination_client_hostname =
.... <2> restorefiles:    requesting_user =
.... <2> restorefiles:    requesting_group =
.... <2> restorefiles:    progress_file =
.... <2> restorefiles:    rename_file =
.... <2> restorefiles:    policy =
.... <2> restorefiles:    client_type =

[Henning_General]

Hi Marianne,

I have got this folder, but there is no text file with information. What can I do that there NBU will create a file ?

I can´t do a backup, I haven´t got a tape.

When I try to restore everything to its original location I get the following error message:

11/9/2015 3:11:05 PM - Info ndmpagent(pid=4160) INF - Restoring NDMP files from /root_vdm_4/...  
11/9/2015 3:12:20 PM - Error ndmpagent(pid=4160) ndmp_data_connect_v3 failed, status = -1 (-1)       
11/9/2015 3:12:20 PM - Error ndmpagent(pid=4160) NDMP restore failed from path /root_vdm_4/...
11/9/2015 3:12:20 PM - Info bpbrm(pid=6276) child done, status 25         
11/9/2015 3:12:20 PM - Info bpbrm(pid=6276) sending message to media manager: STOP RESTORE "_1230568092"     
11/9/2015 3:12:21 PM - Info bpbrm(pid=6276) got ERROR 5 from media manager       
11/9/2015 3:12:21 PM - restored image "_1230568092" - (the restore failed to recover the requested files(5)); restore time 00:03:31
11/9/2015 3:12:21 PM - end Restore; elapsed time: 00:03:33
Restore error(2850)

[Marianne]

NetBackup needs to be restarted on the master to enable bprd log.
Please double-check that the folder is in the correct location.
A text file will be created immediately after restarting NBU.

Please share the lines in Activity Monitor above the ones you posted?

[Henning_General]

Hi,

here are the complete lines :

11/9/2015 3:08:48 PM - begin Restore
11/9/2015 3:08:49 PM - 1 images required
11/9/2015 3:08:49 PM - media 000399 required
11/9/2015 3:08:50 PM - restoring image defmoa_1230568092
11/9/2015 3:08:50 PM - Info bpbrm(pid=6276) defmoa is the host to restore to      
11/9/2015 3:08:50 PM - Info bpbrm(pid=6276) telling media manager to start restore on client     
11/9/2015 3:08:51 PM - Info bpbrm(pid=5936) defmoa is the host to restore to      
11/9/2015 3:08:51 PM - Info bpbrm(pid=5936) start tar32 on client         
11/9/2015 3:08:51 PM - Info tar32(pid=4160) Restore started.           
11/9/2015 3:08:51 PM - connected
11/9/2015 3:08:52 PM - Info bptm(pid=748) Waiting for mount of media id 000399 (copy 1) on server ge-2008. 
11/9/2015 3:08:52 PM - started process bptm (748)
11/9/2015 3:08:52 PM - mounting 000399
11/9/2015 3:08:52 PM - Info bptm(pid=748) INF - Waiting for mount of media id 000399 on server ge-2008 for reading.
11/9/2015 3:08:52 PM - requesting resource 000399
11/9/2015 3:08:52 PM - granted resource 000399
11/9/2015 3:08:52 PM - granted resource HP.ULTRIUM3-SCSI.001
11/9/2015 3:09:33 PM - mounted; mount time: 00:00:41
11/9/2015 3:09:33 PM - Info bptm(pid=748) 000399            
11/9/2015 3:09:33 PM - Info bptm(pid=748) INF - Waiting for positioning of media id 000399 on server ge-2008 for reading.
11/9/2015 3:09:33 PM - positioning 000399 to file 7
11/9/2015 3:11:03 PM - positioned 000399; position time: 00:01:30
11/9/2015 3:11:03 PM - begin reading
11/9/2015 3:11:05 PM - Info ndmpagent(pid=4160) INF - Restoring NDMP files from /root_vdm_4/DEP5/Blizz   
11/9/2015 3:12:20 PM - Error ndmpagent(pid=4160) ndmp_data_connect_v3 failed, status = -1 (-1)       
11/9/2015 3:12:20 PM - Error ndmpagent(pid=4160) NDMP restore failed from path /root_vdm_4/DEP5/Blizz      
11/9/2015 3:12:20 PM - Info bpbrm(pid=6276) child done, status 25         
11/9/2015 3:12:20 PM - Info bpbrm(pid=6276) sending message to media manager: STOP RESTORE defmoa_1230568092     
11/9/2015 3:12:21 PM - Info bpbrm(pid=6276) got ERROR 5 from media manager       
11/9/2015 3:12:21 PM - restored image defmoa_1230568092 - (the restore failed to recover the requested files(5)); restore time 00:03:31
11/9/2015 3:12:21 PM - end Restore; elapsed time: 00:03:33
Restore error(2850)

[Marianne]

This is wrong for NDMP restore:

11/9/2015 3:08:51 PM - Info bpbrm(pid=5936) start tar32 on client  
11/9/2015 3:08:51 PM - Info tar32(pid=4160) Restore started.           
11/9/2015 3:08:51 PM - connected 

As there is no client installed on a filer, NBU should not even try to connect to the filer.

The restore setup in bprd log will hopefully point us in the right direction. (The 'restorefiles' section.)

If the 'Client_Name' on the master was accidently changed to defmoa, then NBU will select the master server as destination.

If this is not the case and all configured correctly, check and verify that port 1000 is open between the master/media server and the filer.

Here bpbrm log on media server will be needed to troubleshoot.

[Henning_General]

This is the other document on bprd 

15:44:02.104 [7512.2168] <2> job_connect: SO_KEEPALIVE set on socket 580 for client ge-2008
15:44:02.104 [7512.2168] <2> logconnections: BPJOBD CONNECT FROM 192.168.100.32.65254 TO 192.168.100.32.13723 fd = 580
15:44:02.104 [7512.2168] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
15:44:02.104 [7512.2168] <2> job_connect: Connected to the host ge-2008 contype 53 jobid <0> socket <580>
15:44:02.104 [7512.2168] <2> job_connect: Connected on port 65254
15:44:02.322 [7512.2168] <2> process_msgQ_msg: Got is mpx main up request from pid 2904
15:44:02.431 [7512.2168] <2> process_msgQ_msg: Got new restore request from pid 2904
15:44:02.431 [7512.2168] <2> read_needed_images_from_file: reading C:\Program Files\Veritas\NetBackup\bin\bprd.d\neededimage.2904 for work to do
15:44:02.431 [7512.2168] <2> read_image_info_from_file: frag 1 file 7 of 000399 is the first need fragment for defmoa07psge_1230568092
15:44:02.431 [7512.2168] <2> add_to_tape_list: 000399 ge-2008
15:44:02.431 [7512.2168] <2> open_checkpoint_file: open restore job ckpts C:\Program Files\Veritas\NetBackup\db\jobs\restart\27.ckpts for a+
15:44:02.431 [7512.2168] <2> group_tapes_in_frag_lists: Setting brm_pid = 0 for defmoa07psge_1230568092 restfiles pid 2904
15:44:02.431 [7512.2168] <2> run_restores: Non-MPX image restore
15:44:02.462 [7512.2168] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:594)
15:44:02.462 [7512.2168] <2> Orb::init: initializing ORB EMMlib_Orb with: bprd -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:825)
15:44:02.478 [7512.2168] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:840)
15:44:02.478 [7512.2168] <2> Orb::setOrbConnectTimeout: timeout seconds: 60(Orb.cpp:1481)
15:44:02.478 [7512.2168] <2> Orb::setOrbRequestTimeout: timeout seconds: 1800(Orb.cpp:1490)
15:44:02.494 [7512.2168] <2> get_media_server_version: NBU version of ge-2008 is 750000
15:44:02.494 [7512.2168] <2> start_mpx_group: media server ge-2008 version from db = 0x000b71b0 
15:44:02.494 [7512.2168] <2> start_mpx_group: /usr/openv/netbackup/bin/bpbrm bpbrm -restore -mpx_restore -S ge-2008 -mt 2 -to 0 -mud 180 -mediasvr ge-2008 -masterversion 750000
15:44:02.494 [7512.2168] <2> logconnections: BPCD CONNECT FROM 192.168.100.32.65258 TO 192.168.100.32.13782 fd = 604
15:44:02.603 [7512.2168] <2> start_mpx_group: bpbrm stdout from bpcr = 604
15:44:02.603 [7512.2168] <2> start_mpx_group: bpbrm stderr from bpcr = 620
15:44:02.696 [7512.2168] <2> read_bpbrm_msg: (pid 0) PID of bpbrm = 3668

15:44:02.696 [7512.2168] <2> start_mpx_group: bpbrm pid = 3668
15:44:02.696 [7512.2168] <2> set_mpx_group_image_brm_pid: Setting brm_pid = 3668 for defmoa07_1230568092 restfiles pid 2904
15:44:02.696 [7512.2168] <2> next_image_using_first_blks: returning backup_id = defmoa07_1230568092, tape = 000399, fileno = 7, firstblk = 0
15:44:02.696 [7512.2168] <2> start_image_restore: Sending listen msg to restfiles 2904 for image with backup time 1230568092
15:44:02.806 [7512.2168] <2> process_msgQ_msg: Setting portnum = 0 for defmoa07_1230568092
15:44:02.806 [7512.2168] <2> start_image_restore: restfiles pid 2904 brm pid 3668 defmoa07_1230568092
15:44:02.821 [7512.2168] <2> logconnections: BPCD CONNECT FROM 192.168.100.32.65263 TO 192.168.100.32.13782 fd = 612
15:44:02.884 [7512.2168] <2> start_indep_grp: active_mpx_groups = 1
15:44:02.884 [7512.2168] <2> start_indep_grp: p_active_restore_for_first_grp = NULL
15:44:02.884 [7512.2168] <2> start_indep_grp: p_first_mpx_group_for_restore = NULL
15:46:15.234 [7512.2168] <2> read_bpbrm_msg: (pid 3668) CURRENT POSITION 000399 7
15:46:15.234 [7512.2168] <2> send_bpbrm_msg: (pid 3668) CONTINUE RESTORE
15:47:32.376 [7512.2168] <2> read_bpbrm_msg: (pid 3668) ERROR 5
15:47:32.376 [7512.2168] <2> handle_image_status: defmoa07_1230568092 restfiles pid 2904 bpbrm pid 3668 status = 5
15:47:32.376 [7512.2168] <2> remove_completed_restore: unlink record with restfiles pid 2904
15:47:32.376 [7512.2168] <2> remove_completed_restore: no more active restores
15:47:32.376 [7512.2168] <2> done_with_bpbrm: bpbrm pid 3668 has no more images to process
15:47:32.376 [7512.2168] <2> send_bpbrm_msg: (pid 3668) TERMINATE
15:47:32.376 [7512.2168] <2> start_indep_grp: active_mpx_groups = -1
15:47:32.376 [7512.2168] <2> start_indep_grp: p_active_restore_for_first_grp = NULL
15:47:32.376 [7512.2168] <2> start_indep_grp: p_first_mpx_group_for_restore = NULL

[Marianne]

This is not what we need.

Have you restarted NBU on the master server?

If so, restore details will be logged in the bprd log.

I need to see the restore setup as per previous request.

[Henning_General]

Hello, 

I opend Port 10.000 (not 1000) on the firewall is that right ?

Yes I restarted the nbu master server. There is nothing written the brpd file after the error  Unable to connect to Netbackup host "myNdmphost":\

What can I do ?

[Marianne]

You are 100% correct. NDMP agent uses port 10000. bprd should be a folder (not a file) under veritas\netbackup\logs. If the folder exists when NBU is started, a text file called 'date'.log will be created.

[Henning_General]

Yes in the folder is a document with the today date, but when I open the document, there is nothing in :(

What can I do ?

[mnolan]

11/9/2015 3:12:20 PM - Error ndmpagent(pid=4160) ndmp_data_connect_v3 failed, status = -1 (-1)       

The tapes are hosted by a netbackup media server, the filer has no connections, so the media server will open an ndmp server for the filer to connect to and this is what is failing.

By default this is using the SERVER_PORT_WINDOW which is a range from 1024-5000 and is random on one of these ports, please ensure your firewall is open for this.

[Henning_General]

Hi mnolan,

it´s not possible to open the ports 1024-5000. 

Can we change the defaults ports to an open port for example 10080. 

[Henning_General]

Hi mnolan,

it´s not psoiible to open all ports :\

Can we use a single (open) Port for this ? 

Thanks,

Henning

[Marianne]

I have no idea what else to suggest without seeing bprd log first.

Please confirm that you have done the following:

• Stop NBU from cmd using 'bpdown' command.
• Confirm that all processes are stopped with 'bpps' command.
• Use Windows Explorer to confirm bprd folder exists under <Install-path>\veritas\netbackup\logs
  You can run mklogdir.bat but I never recommend this as too many unnecessary folders are created.
  (Best to rename if there is a file in the bprd folder with current date to ensure new file is created when NBU is started.)
• Start NBU in cmd using 'bpup'.
• Retry the restore.
• Check bprd log for browse and restore actions.

You can copy the log to bprd.txt and upload here as File Attachment.

bprd log will point to next log that may be needed (e.g. bpbrm on the media server) 

[Henning_General]

Hi Marianne,

Now NBU created a file. Have a look in the appendix.

Thx

[Marianne]

I can see browsing attempt:

11:08:08.172 [2652.4604] <2> fileslist:    client = defmoa07psge
11:08:08.172 [2652.4604] <2> fileslist:    sched_type = 12
11:08:08.172 [2652.4604] <2> fileslist:    starttime = 1230568092
11:08:08.172 [2652.4604] <2> fileslist:    endtime = 1230568092
11:08:08.172 [2652.4604] <2> fileslist:    filepath = /root_vdm_4/DEP5/
....
... 
11:08:08.265 [2652.4604] <2> fileslist: criteria sent to db mgr
11:08:08.359 [2652.4604] <2> process_request: EXIT STATUS 0

Followed by bprd (NBU?) being stopped:

11:10:39.071 [6812.7080] <2> terminate_daemon: termination begun...error code = 0
11:10:39.071 [6812.7080] <2> terminate_daemon: bprd TERMINATED

No record of any restore attempt.

[Henning_General]

Hi Marianne, 

Now I started the restore job two times. 

Have a look again to this file.

Many Thanks,

Henning

[Marianne]

All the names in the restore setup is fine. This is what I wanted to see:

11:31:49.240 [808.1900] <2> process_request: requesting_clnt_hostname = ccname ge-2008
11:31:49.240 [808.1900] <2> restorefiles:    mpx_restore_possible = 1
11:31:49.256 [808.1900] <2> restorefiles:    browse_client = defmoa07psge
11:31:49.256 [808.1900] <2> restorefiles:    requesting_client = ge-2008
11:31:49.256 [808.1900] <2> restorefiles:    destination_client = defmoa07psge
11:31:49.256 [808.1900] <2> restorefiles:    requesting_client_hostname = ge-2008
11:31:49.256 [808.1900] <2> restorefiles:    destination_client_hostname = defmoa07psge
.....
11:31:49.256 [808.1900] <2> restorefiles:    client_type = 19

We now see the restore process being handed off to bpbrm on the master/media server:

11:31:51.908 [164.6732] <2> start_mpx_group: media server ge-2008 version from db = 0x000b71b0 
11:31:51.908 [164.6732] <2> start_mpx_group: /usr/openv/netbackup/bin/bpbrm bpbrm -restore -mpx_restore -S ge-2008 -mt 2 -to 0 -mud 180 -mediasvr ge-2008 -masterversion 750000 

We need to see bpbrm log as well as ndmpagent log that covers the same period.

Copy files to bpbrm.txt and ndpmagent.txt and please upload?

[Henning_General]

Hi Marianne,

in the appendix is the ndmpagend log from today. I can´t find the bpbrm folder in the install_path\NetBackup\logs\.

regrads