cancel
Showing results for 
Search instead for 
Did you mean: 

OpsCenter Restore Error 92

jmjudge
Level 3

I am running OpsCenter 7.6.1.2 on a Windows server.  My environments is all Windows servers with NetBackup 7.6.1.2 Media and master servers.

I am trying to do a restore using the OpsCenter Search feature, but everytime I initialize a restore it fails with an error 92 "media manager detected image that was not in tar format".  I can search and find the files with no issues as well as add the files to my Restore Cart and start the restore. I can restore the file with no issues using the NetBackup restore tool from the master server.

And just FYI, I need the OpsCenter Restore Search screen to work because I am giving our help desk the ability to do basic restores.  Policy will not allow the java client be used by them.  OpsCenter is the only approved interface for them but the Search tab needs to work for the restores for them.

Just more FYI.  The users are set up with a Restore Only view into OpsCenter (although the same error occours trying to restore from the admin account of OpsCenter).  Our target for backups, and obviously restores, are a pair of DataDomains, which we have zero issues with.

 

NBU92.jpg

7 REPLIES 7

RiaanBadenhorst
Moderator
Moderator
Partner    VIP    Accredited Certified

Please perform both the operations from opscenter and then from BAR. Then post the bptm log from tjhe media server in question. And details of the jobs in activity monitor.

jmjudge
Level 3

Output from FAILED job:

10/13/2015 12:27:39 PM - begin Restore

10/13/2015 12:27:40 PM - restoring image XXXXXXXXX_1444482735

10/13/2015 12:27:40 PM - Info bprd(pid=15072) Found (3,100,249) files in (1) images for Restore Job ID 681208.xxx 

10/13/2015 12:27:40 PM - Info bprd(pid=15072) Restoring from copy 1 of image created 10/10/15 08:12:15 from policy MHMH-vm_rdm

10/13/2015 12:27:40 PM - requesting resource @aaaai

10/13/2015 12:27:40 PM - granted resource MediaID=@aaaai;DiskVolume=XxXxXxXxX86001-lsu;DiskPool=XxXxXxXxX86001-dp;Path=XxXxXxXxX86001-lsu;StorageServer=XxXxXxXxX86001.XxxxxX.XxxxxX.XxxxxX;MediaServer=XxXxXxXxXx01

10/13/2015 12:27:44 PM - Info bpbrm(pid=4196) XXXXXXXXX is the host to restore to     

10/13/2015 12:27:44 PM - Info bpbrm(pid=4196) reading file list for client       

10/13/2015 12:27:45 PM - connecting

10/13/2015 12:27:45 PM - Info bpbrm(pid=4196) starting bptm          

10/13/2015 12:27:49 PM - Info tar32(pid=1432) Restore started          

10/13/2015 12:27:49 PM - connected; connect time: 0:00:04

10/13/2015 12:27:49 PM - Info bptm(pid=4864) start           

10/13/2015 12:27:49 PM - started process bptm (4864)

10/13/2015 12:27:50 PM - Info bptm(pid=4864) reading backup image         

10/13/2015 12:27:50 PM - Info bptm(pid=4864) using 30 data buffers        

10/13/2015 12:27:50 PM - Info bptm(pid=4864) spawning a child process        

10/13/2015 12:27:50 PM - Info bptm(pid=4864) child pid: 5780         

10/13/2015 12:27:50 PM - Info bptm(pid=5780) start           

10/13/2015 12:27:50 PM - started process bptm (5780)

10/13/2015 12:27:52 PM - begin reading

10/13/2015 12:27:53 PM - Error bptm(pid=5780) backup id XXXXXXXXX_1444482735 is not a tar formatted image   

10/13/2015 12:27:58 PM - Info tar32(pid=1432) done. status 0         

10/13/2015 12:27:58 PM - Info bptm(pid=4864) EXITING with status 92 <----------       

10/13/2015 12:27:58 PM - restored image XXXXXXXXX_1444482735 - (media manager detected image that was not in tar format(92)); restore time 0:00:18

10/13/2015 12:27:58 PM - Warning bprd(pid=15072) Restore must be resumed prior to first image expiration on 12/11/2015 7:12:15 AM

10/13/2015 12:27:58 PM - end Restore; elapsed time: 0:00:19

media manager detected image that was not in tar format (92)

10/13/2015 12:27:58 PM - Info tar32(pid=1432) done. status: 0         

10/13/2015 12:27:59 PM - Info tar32(pid=1432) done. status: 92: media manager detected image that was not in tar format

10/13/2015 12:27:59 PM - Error bpbrm(pid=4196) client restore EXIT STATUS 92: media manager detected image that was not in tar format

 

Output from SUCCESSFUL job:

10/13/2015 12:28:40 PM - begin Restore

10/13/2015 12:28:40 PM - restoring image XXXXXXXXX_1444482735

10/13/2015 12:28:40 PM - requesting resource @aaaai

10/13/2015 12:28:40 PM - granted resource MediaID=@aaaai;DiskVolume=XxXxXxXxX86001-lsu;DiskPool=XxXxXxXxX86001-dp;Path=XxXxXxXxX86001-lsu;StorageServer=XxXxXxXxX86001.XxxxxX.XxxxxX.XxxxxX;MediaServer=XxXxXxXxXx01

10/13/2015 12:28:41 PM - Info bprd(pid=3696) Found (3,100,249) files in (1) images for Restore Job ID 681209.xxx 

10/13/2015 12:28:41 PM - Info bprd(pid=3696) Restoring from copy 1 of image created 10/10/15 08:12:15 from policy MHMH-vm_rdm

10/13/2015 12:28:44 PM - Info bpbrm(pid=5828) XxXxXxXxX is the host to restore to     

10/13/2015 12:28:44 PM - Info bpbrm(pid=5828) reading file list for client       

10/13/2015 12:28:46 PM - connecting

10/13/2015 12:28:46 PM - Info bpbrm(pid=5828) starting bptm          

10/13/2015 12:28:49 PM - Info tar32(pid=664) Restore started          

10/13/2015 12:28:49 PM - connected; connect time: 0:00:03

10/13/2015 12:28:50 PM - Info bptm(pid=4084) start           

10/13/2015 12:28:50 PM - started process bptm (4084)

10/13/2015 12:28:50 PM - Info bptm(pid=4084) reading backup image         

10/13/2015 12:28:50 PM - Info bptm(pid=4084) using 30 data buffers        

10/13/2015 12:28:50 PM - Info bptm(pid=4084) spawning a child process        

10/13/2015 12:28:50 PM - Info bptm(pid=4084) child pid: 2184         

10/13/2015 12:28:50 PM - Info bptm(pid=2184) start           

10/13/2015 12:28:50 PM - started process bptm (2184)

10/13/2015 12:28:55 PM - begin reading

10/13/2015 12:28:57 PM - Info tar32(pid=664) done. status 0         

10/13/2015 12:28:57 PM - Info bptm(pid=4084) waited for empty buffer 1 times, delayed 1 times   

10/13/2015 12:28:57 PM - end reading; read time: 0:00:02

10/13/2015 12:28:57 PM - Info bptm(pid=4084) completed reading backup image        

10/13/2015 12:28:57 PM - Info bptm(pid=4084) EXITING with status 0 <----------       

10/13/2015 12:28:57 PM - Info tar32(pid=664) done. status: 0         

10/13/2015 12:28:57 PM - restored image XXXXXXXXX_1444482735 - (the requested operation was successfully completed(0)); restore time 0:00:17

10/13/2015 12:28:57 PM - end Restore; elapsed time: 0:00:17

the requested operation was successfully completed (0)

10/13/2015 12:28:57 PM - Info tar32(pid=664) done. status: 0: the requested operation was successfully completed    

RiaanBadenhorst
Moderator
Moderator
Partner    VIP    Accredited Certified

Hi,

 

Can you check something for me.

 

I see you're restoring a file from vmware backup. Can you try and perform a restore of a regular file from a standard/windows-nt backup as a test.

jmjudge
Level 3

I can, but just FYI, this is a MS-Windows type backup on a RDM, so it's already a standard backup.... 

jmjudge
Level 3

Interesting that a restore to a regular physical server backup was successful from the OpsCenter.  I say interesting since the backup I was trying to restore from before was a Windows style backup of an RDM.  Most of the restores that we do will be these RDM type backups.

RiaanBadenhorst
Moderator
Moderator
Partner    VIP    Accredited Certified

I noticed that offsets were diiferent between your sucessful and failed restores. Same images, but the file location in the images was reported differently. I"d open a case with support to check why this is happening. Are you using the same versions on opscenter,  master, media?

 

12:27:52.750 [4864.3944] <2> io_open_disk: file XxXxXxXxX_1444482735_C1_F57 successfully opened
<SNIP>
12:27:52.906 [4864.3944] <4> read_backup: begin reading backup id XxXxXxXxX_1444482735 (restore), copy 1, fragment 57, from media id @aaaai on drive  (index -1)
12:27:52.906 [4864.3944] <2> bptm: Created stop_db_restore_event is <BPTM_STOP_DB_RESTORE_EVENT_4864>
12:27:52.906 [4864.3944] <2> read_backup: ********** Using Fragment **************************
12:27:52.906 [4864.3944] <2> read_backup: fragment_num = 57
12:27:52.906 [4864.3944] <2> read_backup: Kbytes = 10413824
12:27:52.906 [4864.3944] <2> read_backup: remainder = 0
12:27:52.906 [4864.3944] <2> read_backup: id = @aaaai
12:27:52.906 [4864.3944] <2> read_backup: file_num = 0
12:27:52.906 [4864.3944] <2> read_backup: block_size = 262144
12:27:52.906 [4864.3944] <2> read_backup: offset = 0
12:27:52.906 [4864.3944] <2> read_backup: data_format = 1
12:27:52.906 [4864.3944] <2> read_backup: ****************************************************
12:27:52.906 [4864.3944] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 9385569, opt_remainder = 0
12:27:52.906 [4864.3944] <2> read_data: Total Kbytes transferred 0
12:27:52.906 [4864.3944] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0
12:27:52.906 [4864.3944] <2> set_job_details: Tfile (681208): BEGIN_READING 1444757272

12:27:52.906 [4864.3944] <2> send_job_file: job ID 681208, ftype = 3 msg len = 25, msg = BEGIN_READING 1444757272

12:27:52.906 [4864.3944] <2> 681208:bptm:4864:XxXxXxXxXx01: C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspiDataDomain.dll:stspi_read_image image handle =0000000002E32170 fd =155373570 length =262144 offset =1052933632
12:27:52.906 [4864.3944] <4> 681208:bptm:4864:XxXxXxXxXx01: [1300:F68] vrapid_nfs_connect: ifgroup disabled
12:27:52.906 [4864.3944] <4> 681208:bptm:4864:XxXxXxXxXx01: [1300:F68] ddcl_new_client_buffers created private pool with 776 DDCL buffers
12:27:52.906 [4864.3944] <2> 681208:bptm:4864:XxXxXxXxXx01: [1300:F68] ddcl_establish_file_buffer_pool Setting: file_buffers=776
12:27:52.906 [4864.3944] <4> 681208:bptm:4864:XxXxXxXxXx01: [1300:F68] Allocated read_ctx_pool of size 204864
12:27:52.906 [4864.3944] <4> 681208:bptm:4864:XxXxXxXxXx01: [1300:F68] JOB START  IMAGE_READ ip=XxX.XxX.XxX.201 pid=4864 cd=0
12:27:52.906 [4864.3944] <2> 681208:bptm:4864:XxXxXxXxXx01: [1300:F68] ddcl_get_readahead_data():  ra->offset=1052933632 ra->count=0 offset=1052933632 err=<NONE> count_done=0
12:27:52.906 [4864.3944] <2> 681208:bptm:4864:XxXxXxXxXx01: [1300:F68] waiting for context offset 1052933632  ra->offset=1052933632 ra->count=0 offset=1052933632 cd=0
12:27:53.498 [4864.3944] <2> 681208:bptm:4864:XxXxXxXxXx01: [1300:F68] ddcl_get_readahead_data():  ra->offset=1052933632 ra->count=262144 offset=1052933632 err=<NONE> count_done=0
12:27:53.498 [4864.3944] <2> 681208:bptm:4864:XxXxXxXxXx01: [1300:F68] ddcl_get_readahead_data(): Got buffer: file->ra_offset=1055030784 file->ra_count=1835008  ra->offset=1053195776 ra->count=0, count_done=262144 count=262144  cd=0
12:27:53.498 [4864.3944] <2> 681208:bptm:4864:XxXxXxXxXx01: [1300:F68] ddcl_get_readahead_data(): Done with context;  file size=10663755776, offset+count_done=1053195776 ra_list=7
12:27:53.498 [4864.3944] <2> 681208:bptm:4864:XxXxXxXxXx01: C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspiDataDomain.dll:stspi_read_image STS_EOK image handle =0000000002E32170 fd =155373570 bytes read =262144
12:27:53.498 [4864.3944] <2> 681208:bptm:4864:XxXxXxXxXx01: C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspiDataDomain.dll:stspi_read_image image handle =0000000002E32170 fd =155373570 length =262144 offset =1053195776
12:27:53.498 [4864.3944] <2> 681208:bptm:4864:XxXxXxXxXx01: [1300:F68] ddcl_get_readahead_data():  ra->offset=1053195776 ra->count=0 offset=1053195776 err=<NONE> count_done=0
12:27:53.498 [4864.3944] <2> 681208:bptm:4864:XxXxXxXxXx01: [1300:F68] waiting for context offset 1053195776  ra->offset=1053195776 ra->count=0 offset=1053195776 cd=0
12:27:53.514 [5780.5180] <2> filter_image: [4864] Min_records before frag switch is 90000, locate available = 1
12:27:53.514 [5780.5180] <2> get_next_file: [4864] received string: (1774415 1525213503 14124 0 0 0 13952 /D/SHRHome/QNI7821/ESX_Orphaned_LUNs.xlsx)
12:27:53.514 [5780.5180] <2> set_job_details: Tfile (681208): LOG 1444757273 16 bptm 5780 backup id XxXxXxXxX_1444482735 is not a tar formatted image

12:27:53.514 [5780.5180] <2> send_job_file: job ID 681208, ftype = 3 msg len = 88, msg = LOG 1444757273 16 bptm 5780 backup id XxXxXxXxX_1444482735 is not a tar formatted image

Success

 

12:28:52.857 [4084.5668] <2> io_open_disk: file XxXxXxXxX_1444482735_C1_F174 successfully opened
<SNIP)
12:28:55.259 [4084.5668] <4> read_backup: begin reading backup id XxXxXxXxX_1444482735 (restore), copy 1, fragment 174, from media id @aaaai on drive  (index -1)
12:28:55.259 [4084.5668] <2> bptm: Created stop_db_restore_event is <BPTM_STOP_DB_RESTORE_EVENT_4084>
12:28:55.259 [4084.5668] <2> read_backup: ********** Using Fragment **************************
12:28:55.259 [4084.5668] <2> read_backup: fragment_num = 174
12:28:55.259 [4084.5668] <2> read_backup: Kbytes = 19167232
12:28:55.259 [4084.5668] <2> read_backup: remainder = 0
12:28:55.259 [4084.5668] <2> read_backup: id = @aaaai
12:28:55.259 [4084.5668] <2> read_backup: file_num = 0
12:28:55.259 [4084.5668] <2> read_backup: block_size = 262144
12:28:55.259 [4084.5668] <2> read_backup: offset = 0
12:28:55.259 [4084.5668] <2> read_backup: data_format = 1
12:28:55.259 [4084.5668] <2> read_backup: ****************************************************
12:28:55.259 [4084.5668] <2> read_data: last_frag = 0, opt_bytes_left = 0, tape_Kbytes_left = 15223649, opt_remainder = 0
12:28:55.259 [4084.5668] <2> read_data: Total Kbytes transferred 0
12:28:55.259 [4084.5668] <2> ndmp_setup_for_read: CINDEX 0, TWIN_INDEX 0 is_tir 0 IS_NDMP 0
12:28:55.259 [4084.5668] <2> set_job_details: Tfile (681209): BEGIN_READING 1444757335

12:28:55.259 [4084.5668] <2> send_job_file: job ID 681209, ftype = 3 msg len = 25, msg = BEGIN_READING 1444757335

12:28:55.259 [4084.5668] <2> 681209:bptm:4084:XxXxXxXxXx01: C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspiDataDomain.dll:stspi_read_image image handle =0000000002DF2170 fd =624939010 length =262144 offset =4038229504
12:28:55.259 [4084.5668] <4> 681209:bptm:4084:XxXxXxXxXx01: [FF4:1624] vrapid_nfs_connect: ifgroup disabled
12:28:55.259 [4084.5668] <4> 681209:bptm:4084:XxXxXxXxXx01: [FF4:1624] ddcl_new_client_buffers created private pool with 776 DDCL buffers
12:28:55.259 [4084.5668] <2> 681209:bptm:4084:XxXxXxXxXx01: [FF4:1624] ddcl_establish_file_buffer_pool Setting: file_buffers=776
12:28:55.259 [4084.5668] <4> 681209:bptm:4084:XxXxXxXxXx01: [FF4:1624] Allocated read_ctx_pool of size 204864
12:28:55.259 [4084.5668] <4> 681209:bptm:4084:XxXxXxXxXx01: [FF4:1624] JOB START  IMAGE_READ ip=XxX.XxX.XxX.201 pid=4084 cd=0
12:28:55.259 [4084.5668] <2> 681209:bptm:4084:XxXxXxXxXx01: [FF4:1624] ddcl_get_readahead_data():  ra->offset=4038229504 ra->count=0 offset=4038229504 err=<NONE> count_done=0
12:28:55.259 [4084.5668] <2> 681209:bptm:4084:XxXxXxXxXx01: [FF4:1624] waiting for context offset 4038229504  ra->offset=4038229504 ra->count=0 offset=4038229504 cd=0
12:28:55.462 [4084.5668] <2> 681209:bptm:4084:XxXxXxXxXx01: [FF4:1624] ddcl_get_readahead_data():  ra->offset=4038229504 ra->count=262144 offset=4038229504 err=<NONE> count_done=0
12:28:55.462 [4084.5668] <2> 681209:bptm:4084:XxXxXxXxXx01: [FF4:1624] ddcl_get_readahead_data(): Got buffer: file->ra_offset=4040326656 file->ra_count=1835008  ra->offset=4038491648 ra->count=0, count_done=262144 count=262144  cd=0
12:28:55.462 [4084.5668] <2> 681209:bptm:4084:XxXxXxXxXx01: [FF4:1624] ddcl_get_readahead_data(): Done with context;  file size=19627245568, offset+count_done=4038491648 ra_list=7
12:28:55.462 [4084.5668] <2> 681209:bptm:4084:XxXxXxXxXx01: C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspiDataDomain.dll:stspi_read_image STS_EOK image handle =0000000002DF2170 fd =624939010 bytes read =262144
12:28:55.462 [4084.5668] <2> 681209:bptm:4084:XxXxXxXxXx01: C:\Program Files\Veritas\NetBackup\bin\\ost-plugins\libstspiDataDomain.dll:stspi_read_image image handle =0000000002DF2170 fd =624939010 length =262144 offset =4038491648
12:28:55.462 [4084.5668] <2> 681209:bptm:4084:XxXxXxXxXx01: [FF4:1624] ddcl_get_readahead_data():  ra->offset=4038491648 ra->count=0 offset=4038491648 err=<NONE> count_done=0
12:28:55.462 [4084.5668] <2> 681209:bptm:4084:XxXxXxXxXx01: [FF4:1624] waiting for context offset 4038491648  ra->offset=4038491648 ra->count=0 offset=4038491648 cd=0
12:28:55.478 [2184.5232] <2> filter_image: [4084] Min_records before frag switch is 90000, locate available = 1
12:28:55.478 [2184.5232] <2> get_next_file: [4084] received string: (1774415 5820180799 14124 0 0 0 13952 /D/SHRHome/QNI7821/ESX_Orphaned_LUNs.xlsx)
12:28:55.478 [2184.5232] <2> save_block: [4084] Allocated SAVE_BUF to 262144 bytes.
12:28:55.478 [2184.5232] <2> save_block: [4084] saving 1024 bytes, input length was 644, SAVE_BYTES = 0
12:28:55.478 [2184.5232] <2> write_bytes: [4084] writing 1024 saved bytes
12:28:55.478 [2184.5232] <2> write_bytes: [4084] writing 14848 data bytes, input length was 14636, SAVE_BYTES = 0, file = /D/SHRHome/QNI7821/ESX_Orphaned_LUNs.xlsx
12:28:55.478 [2184.5232] <2> get_next_file: [4084] received string: (EXIT STATUS 0)

 

 

jmjudge
Level 3

Yes, all the same version