NDMP restore: Error bpbrm (pid=5768) could not open event Global\NetBackup BPBRM Media Ready Event 8284, The system cannot find the file specified.

[Noor_Toorabal1]

Hello,

Any help or hint to troubleshoot will be greatly appreciated. I have the error while NDMP NAS restore.

I have the following setup:

• NDMP NAS configured on a AIX 7.1 master server Netbackup 7.6.1.2
• NDMP NAS is HNAS 3100(Hitachi)
• NDMP backup/restore use the remote NDMP infrastructure.
• Media server that performed the NDMP backup is on Windows 2008.

The situation I am experiencing is as follows:

• Backup works fine without error
• Restore works fine without error when restoration is done to alternate location on the NDMP NAS
• Restore to original location end with status 0 with all files restored, however I have an error logged in the job details(in bold below):

2016-03-11 15:16:30 - Info ndmpagent (pid=9616) INF - Restoring NDMP files from /__VOLUME__/fsDR_APP-PRD

2016-03-11 15:16:34 - Info ndmpagent (pid=9616) DAR enabled

2016-03-11 15:16:38 - Info ndmpagent (pid=9616) mtpfi4345.prod.mrq: NDMP(420): Starting (destination end) Recovery of files to /fsDR_APP-PRD/rbDR_APP-PRD/rbAPP-PRD/APP-PRD/TestAV/HCS/TEST/testfile.

2016-03-11 15:16:40 - Info ndmpagent (pid=9616) mtpfi4345.prod.mrq: NDMP(420): Recovery to /fsDR_APP-PRD/rbDR_APP-PRD/rbAPP-PRD/APP-PRD/TestAV/HCS/TEST/testfile complete (destination end) (0 warning(s), 0 error(s)).

2016-03-11 15:16:42 - Info ndmpagent (pid=9616) NDMP restore successful from path /__VOLUME__/fsDR_APP-PRD

2016-03-11 15:16:45 - Info ndmpagent (pid=9616) done. status: 0: the requested operation was successfully completed

2016-03-11 15:16:45 - Error bpbrm (pid=5768) could not open event Global\NetBackup BPBRM Media Ready Event 8284, The system cannot find the file specified.

2016-03-11 15:16:45 - Info bpbrm (pid=5768) media manager for backup id mtpfi4345.prod.mrq_1457725592 exited with status 0: the requested operation was successfully completed

2016-03-11 15:16:45 - end reading; read time: 0:00:19

2016-03-11 15:16:45 - Error bpbrm (pid=5768) could not open event Global\NetBackup BPBRM Normal Exit Event 8284, The system cannot find the file specified.

2016-03-11 15:16:46 - restored from image mtpfi4345.prod.mrq_1457725592; restore time: 0:01:53

2016-03-11 15:16:46 - Info bpbrm (pid=5768) child done, status 0

2016-03-11 15:16:48 - end Restore; elapsed time 0:02:31

the requested operation was successfully completed  (0)

[RamNagalla]

My primary concernt will be about the restored data? does it resored correctly and data looks good?

could you attached the restore log located in master server /usr/openv/netbackup/logs/user_ops/<userid>/logs

[Marianne]

The next log to check will be bpbrm on the media server. You will probably need to increase logging level to 3 or higher. You may also want to log a Support call with Veritas. They will need level 5 logs of bpbrm (and probably a bunch of other logs as well) including ndmpagent. PS: I have tried to Google the error 'Media Ready Event 8732' but cannot find anything. I think you should log a Support call with Veritas.

[Noor_Toorabal1]

Hello RamNagalla,

The restored data looks good, but that error pops up everytime a restore to original location is performed. I have attached the log if that could tell you anything(jbp-29544457979919999800000000024-VExaay.txt).

Strangely the error does not appear in the user_ops log you requested but is present in the activity monitor job details as follows:

2016-03-14 14:25:23 - begin Restore
2016-03-14 14:25:25 - number of images required: 1
2016-03-14 14:25:25 - media needed: 500500
2016-03-14 14:26:00 - restoring from image NASYYY_1457725592
2016-03-14 14:26:00 - Info bpbrm (pid=5984) NASYYY is the host to restore to
2016-03-14 14:26:00 - Info bpbrm (pid=5984) telling media manager to start restore on client
2016-03-14 14:26:03 - Info bpbrm (pid=8732) NASYYY is the host to restore to
2016-03-14 14:26:03 - Info bpbrm (pid=8732) start tar32 on client
2016-03-14 14:26:03 - Info tar32 (pid=7044) Restore started.
2016-03-14 14:26:05 - requesting resource 500500
2016-03-14 14:26:05 - Waiting for scan drive stop LTO5_B03, Media server: MEDIA_SERVERYYY
2016-03-14 14:26:07 - Info bptm (pid=5496) Waiting for mount of media id 500500 (copy 1) on server MEDIA_SERVERYYY.
2016-03-14 14:26:07 - started process bptm (pid=5496)
2016-03-14 14:26:07 - mounting 500500
2016-03-14 14:26:07 - granted resource  500500
2016-03-14 14:26:07 - granted resource  LTO5_B03
2016-03-14 14:26:09 - Info bptm (pid=5496) INF - Waiting for mount of media id 500500 on server MEDIA_SERVERYYY for reading.
2016-03-14 14:26:38 - mounted 500500; mount time: 0:00:31
2016-03-14 14:26:38 - Info bptm (pid=5496) 500500
2016-03-14 14:26:39 - Info bptm (pid=5496) INF - Waiting for positioning of media id 500500 on server MEDIA_SERVERYYY for reading.
2016-03-14 14:26:39 - positioning 500500 to file 666
2016-03-14 14:27:33 - positioned 500500; position time: 0:00:54
2016-03-14 14:27:33 - begin reading
2016-03-14 14:27:37 - Info ndmpagent (pid=7044) INF - Restoring NDMP files from /__VOLUME__/fsDR_APP-PRD
2016-03-14 14:27:41 - Info ndmpagent (pid=7044) DAR enabled
2016-03-14 14:27:45 - Info ndmpagent (pid=7044) NASYYY: NDMP(433): Starting (destination end) Recovery of files to /fsDR_APP-PRD/rbDR_APP-PRD/rbAPP-PRD/APP-PRD/TestAV/HCS/TEST/testfile.
2016-03-14 14:27:47 - Info ndmpagent (pid=7044) NASYYY: NDMP(433): Recovery to /fsDR_APP-PRD/rbDR_APP-PRD/rbAPP-PRD/APP-PRD/TestAV/HCS/TEST/testfile complete (destination end) (0 warning(s), 0 error(s)).
2016-03-14 14:27:49 - Info ndmpagent (pid=7044) NDMP restore successful from path /__VOLUME__/fsDR_APP-PRD
2016-03-14 14:27:52 - Info ndmpagent (pid=7044) done. status: 0: the requested operation was successfully completed
2016-03-14 14:27:52 - end reading; read time: 0:00:19
2016-03-14 14:27:53 - Error bpbrm (pid=5984) could not open event Global\NetBackup BPBRM Media Ready Event 8732, The system cannot find the file specified.
2016-03-14 14:27:53 - Info bpbrm (pid=5984) media manager for backup id NASYYY_1457725592 exited with status 0: the requested operation was successfully completed
2016-03-14 14:27:53 - Error bpbrm (pid=5984) could not open event Global\NetBackup BPBRM Normal Exit Event 8732, The system cannot find the file specified.
2016-03-14 14:27:53 - restored from image NASYYY_1457725592; restore time: 0:01:53
2016-03-14 14:27:53 - Info bpbrm (pid=5984) child done, status 0
2016-03-14 14:27:55 - end Restore; elapsed time 0:02:32
the requested operation was successfully completed  (0)

[Noor_Toorabal1]

Hello Marianne,

The bpbrm on the media server does not say much either, below are the lines: (I have attached the full log (031516.txt) in case someone could find something else)

11:43:20.034 [10168.6240] <2> bpbrm read_media_msg: read from media manager: MEDIA NOT READY

11:43:20.034 [10168.6240] <2> bpbrm signal_bpbrm_child: sending Media Ready to bpbrm child 6844

11:43:20.034 [10168.6240] <16> bpbrm signal_bpbrm_child: could not open event Global\NetBackup BPBRM Media Ready Event 6844, The system cannot find the file specified. 

11:43:20.034 [10168.6240] <2> set_job_details: Tfile (370086): LOG 1458056600 16 bpbrm 10168 could not open event Global\NetBackup BPBRM Media Ready Event 6844, The system cannot find the file specified. 

11:43:20.034 [10168.6240] <2> send_job_file: job ID 370086, ftype = 3 msg len = 142, msg = LOG 1458056600 16 bpbrm 10168 could not open event Global\NetBackup BPBRM Media Ready Event 6844, The system cannot find the file specified. 

[RamNagalla]

"11:43:20.049 [10168.6240] <2> bpbrm read_media_msg: read from media manager: EXIT NASYYY_1457725592 0
11:43:20.049 [10168.6240] <2> bpbrm process_media_msg: media manager for backup id NASYYY_1457725592 exited with status 0: the requested operation was successfully completed
11:43:20.049 [10168.6240] <2> set_job_details: Tfile (370086): LOG 1458056600 4 bpbrm 10168 media manager for backup id NASYYY_1457725592 exited with status 0: the requested operation was successfully completed

11:43:20.049 [10168.6240] <2> send_job_file: job ID 370086, ftype = 3 msg len = 160, msg = LOG 1458056600 4 bpbrm 10168 media manager for backup id NASYYY_1457725592 exited with status 0: the requested operation was successfully completed

11:43:20.049 [10168.6240] <2> bpbrm signal_bpbrm_child: sending Normal Exit to bpbrm child 6844
11:43:20.049 [10168.6240] <16> bpbrm signal_bpbrm_child: could not open event Global\NetBackup BPBRM Normal Exit Event 6844, The system cannot find the file specified. 
11:43:20.049 [10168.6240] <2> set_job_details: Tfile (370086): LOG 1458056600 16 bpbrm 10168 could not open event Global\NetBackup BPBRM Normal Exit Event 6844, The system cannot find the file specified. 

11:43:20.049 [10168.6240] <2> send_job_file: job ID 370086, ftype = 3 msg len = 142, msg = LOG 1458056600 16 bpbrm 10168 could not open event Global\NetBackup BPBRM Normal Exit Event 6844, The system cannot find the file specified. "

bpbrm exit with staus 0 , and  then (in my guess) it is trying to post some event on Windows and not able to find it

[Noor_Toorabal1]

I have found some lines in the bptm logs that indicate that the error may be related to multiplexing:

11:43:21.017 [8144.4260] <2> mpx_check_msg_pending: could not open msg pending event, The system cannot find the file specified.
 

11:43:19.987 [8144.4260] <2> logconnections: BPDBM CONNECT FROM 172.20.32.15.59003 TO 172.20.225.22.1556 fd = 1240
11:43:20.003 [8144.4260] <2> db_end: Need to collect reply
11:43:20.003 [8144.4260] <4> report_throughput: VBRT 1 8144 0 1 LTO5_A01 500500 0 1 0 512  512 (mpxrestore.c.3058)
11:43:20.003 [8144.4260] <2> send_brm_msg: MEDIA NOT READY
11:43:20.003 [8144.4260] <2> send_brm_msg: EXIT NASYYY_1457725592 0
11:43:20.003 [8144.4260] <2> bct_clear_active: Set BCTable entry 0 to inactive, ACTIVE_GC count decremented to 0
11:43:20.003 [8144.4260] <2> io_close: closing C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_LTO5_A01, from mpxrestore.c.3135
11:43:20.003 [8144.4260] <2> mpx_waiting_term: waiting for TERMINATE or another START RESTORE
11:43:21.017 [8144.4260] <2> mpx_check_msg_pending: could not open msg pending event, The system cannot find the file specified.
11:43:21.017 [8144.4260] <2> read_brm_msg: TERMINATE
11:43:21.017 [8144.4260] <2> openTpreqFile: tpreq_file: C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_LTO5_A01, serial_num: 00078A17F0
11:43:21.032 [8144.4260] <2> get_drive_path: SCSI coordinates {7,0,13,0}, dos_path \\.\Tape4801110, pnp_path \\?\scsi#sequential&ven_ibm&prod_ult3580-td5#5&159d884d&0&000d00#{53f5630b-b6bf-11d0-94f2-00a0c91efb...}
11:43:21.032 [8144.4260] <2> check_serial_num: serial number match for drive with SCSI coordinates {7,0,13,0}, dos_path \\.\Tape4801110, drive serial number 00078A17F0, expected serial number 00078A17F0
11:43:21.048 [8144.4260] <2> init_tape: \\.\Tape4801110 (SCSI coordinates {7,0,13,0}) configured with blocksize 0
11:43:21.048 [8144.4260] <2> init_tape: \\.\Tape4801110 (SCSI coordinates {7,0,13,0}) has compression enabled
11:43:21.063 [8144.4260] <2> io_open: SCSI RESERVE
11:43:21.063 [8144.4260] <2> io_open: file C:\Program Files\Veritas\NetBackup\db\media\tpreq\drive_LTO5_A01 successfully opened (mode 2)

[watsons]

I googled around your error:

2016-03-11 15:16:45 - Error bpbrm (pid=5768) could not open event Global\NetBackup BPBRM Normal Exit Event 8284, The system cannot find the file specified.

and found that the event ID could be random, but mostly the solution points to permission issue during restore. Try to check in your system logs (of the Hitachi filer) and see if there is anything stand out.

Also check the successfully-restored files to see if their permissions are all right (or different from the original) .

[Noor_Toorabal1]

Thank you watsons,

No event in the NAS except the following:

Information

NAS

2016-03-15    13:55:57 (UTC-0400)

NDMP(440): Starting operation for client MEDIA_YYY, standard NDMP user.

The permissions are all right I did a test with a testfile as below.

NAS[EVS1]:$ ls -l
-r-xr-xr-x    -  1        0        0        0 2016-03-11 14:35:17-04:00 testfile
NAS[EVS1]:$ rm testfile
NAS[EVS1]:$ ls -l

Restore to original location from Netbackup

NAS[EVS1]:$ ls -l
-r-xr-xr-x    -  1        0        0        0 2016-03-11 14:35:17-04:00 testfile

I wonder why the error occurs only when restore to original location is performed and not when I restore to al alternate location on the same filesystem on the same NAS.