10-13-2015 07:15 AM
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.
10-13-2015 09:48 AM
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.
10-13-2015 10:44 AM
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
10-14-2015 04:53 AM
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.
10-14-2015 05:56 AM
I can, but just FYI, this is a MS-Windows type backup on a RDM, so it's already a standard backup....
10-14-2015 06:17 AM
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.
10-14-2015 10:12 PM
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)
10-15-2015 05:17 AM
Yes, all the same version