Forum Discussion

Kuldeep_Singh_R's avatar
Kuldeep_Singh_R
Level 3
12 years ago

Status Code 85 on 1st Phase of import

Hi all,

 

I'm getting status code 85 on running the 1st Phase of import....

 

Environment:

Master Server:

HARDWARE SOLARIS 10

VERSION NetBackup 7.1.0.3

 

Media Server:

 

HARDWARE LINUX_RH_X86 (RHEL 5.5 (Tikanga)

VERSION NetBackup 7.1.0.1

 

-Tape and drive density are same (HCART3)

-Tapes are encrypted with ORACLE KMS 

-1st Phase of import fails with status code 85

BPTM TRACE :

 

11:43:45.221 [13518] <2> resourcesAvailable: m_allocationSeq.length() == 1
11:43:45.221 [13518] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 7
11:43:45.221 [13518] <2> resourcesAvailable: MEDIADB 1 19089311 A000000 4020550 ------ 6 0 0 0 0 0 0 0 -1 1 0 0 0 0 0 0
11:43:45.221 [13518] <2> resourcesAvailable: VOLUME 1 A000000 4020550 A000000 NetBackup *NULL* *NULL* 6 8 18 13 0 \{00000000-0000-0000-0000-000000000000\} 0
11:43:45.221 [13518] <2> resourcesAvailable: DRIVE 3 TLD-018-2 2003192 1310268100 /dev/nst0 -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0
11:43:45.221 [13518] <2> resourcesAvailable: STORAGE 1 *NULL* 0 0 0 0 0 0 test-media-01-b test-media-01-b *NULL*
11:43:45.221 [13518] <2> resourcesAvailable: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
11:43:45.221 [13518] <2> resourcesAvailable: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
11:43:45.221 [13518] <2> resourcesAvailable: DISKMOUNTPOINT 0 6 *NULL*
11:43:45.222 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1370: 0: found in cache name: 10.179.123.250
11:43:45.222 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1371: 0: found in cache service: NULL
11:43:45.224 [13518] <2> packageInitialResourceRequestResult: totalNumberOfAllocations == 1
11:43:45.224 [13518] <2> packageInitialResourceRequestResult: m_allocationSeq.length=1
11:43:45.224 [13518] <2> packageInitialResourceRequestResult: found MediaAllocation : reqNum == 0
11:43:45.224 [13518] <2> packageInitialResourceRequestResult: \tab matched MediaAllocation to a initialMediaSelect
11:43:45.224 [13518] <2> packageInitialResourceRequestResult: retVal =\tab 0
11:43:45.224 [13518] <2> RequestInitialResources: retVal = 0\tab emmStatus = 0
11:43:45.224 [13518] <2> RequestInitialResources: returning
11:43:45.225 [13518] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 19089311 A000000 4020550 ------ 6 0 0 0 0 0 0 0 -1 1 0 0 0 0 0 0], length 73
11:43:45.225 [13518] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 A000000 4020550 A000000 NetBackup *NULL* *NULL* 6 8 18 13 0 \{00000000-0000-0000-0000-000000000000\} 0], length 107
11:43:45.225 [13518] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 3 TLD-018-2 2003192 1310268100 /dev/nst0 -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0], length 111
11:43:45.225 [13518] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 1 *NULL* 0 0 0 0 0 0 test-media-01-b test-media-01-b *NULL*], length 73
11:43:45.225 [13518] <2> populateBptmOpaqueStrings: packaging bptm string [DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*], length 38
11:43:45.225 [13518] <2> populateBptmOpaqueStrings: packaging bptm string [DISKVOLUME 0 6 *NULL* 6 *NULL* 0], length 32
11:43:45.225 [13518] <2> populateBptmOpaqueStrings: packaging bptm string [DISKMOUNTPOINT 0 6 *NULL*], length 25
11:43:45.225 [13518] <2> populateBptmOpaqueStrings: retVal  = 0
11:43:45.225 [13518] <2> parse_resource_strings: MEDIADB 1 19089311 A000000 4020550 ------ 6 0 0 0 0 0 0 0 -1 1 0 0 0 0 0 0
11:43:45.225 [13518] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
11:43:45.225 [13518] <2> parse_resource_strings: VOLUME 1 A000000 4020550 A000000 NetBackup *NULL* *NULL* 6 8 18 13 0 \{00000000-0000-0000-0000-000000000000\} 0
11:43:45.225 [13518] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
11:43:45.225 [13518] <2> parse_resource_strings: DRIVE 3 TLD-018-2 2003192 1310268100 /dev/nst0 -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0
11:43:45.225 [13518] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
11:43:45.225 [13518] <2> parse_resource_strings: STORAGE 1 *NULL* 0 0 0 0 0 0 test-media-01-b test-media-01-b *NULL*
11:43:45.225 [13518] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
11:43:45.225 [13518] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
11:43:45.225 [13518] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
11:43:45.225 [13518] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
11:43:45.225 [13518] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
11:43:45.225 [13518] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
11:43:45.225 [13518] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
11:43:45.225 [13518] <2> nbjm_media_request: Job control returned to BPTM
11:43:45.225 [13518] <2> drivename_open: Called with Create 1, file TLD-018-2
11:43:45.225 [13518] <2> drivename_lock: lock established
11:43:45.225 [13518] <2> drivename_write: Called with mode 3
11:43:45.226 [13518] <2> mount_open_media: Waiting for mount of media id A000000 (copy 1) on server test-media-01-b.
11:43:45.226 [13518] <2> set_job_details: Tfile (3961243): LOG 1346841825 4 bptm 13518 Waiting for mount of media id A000000 (copy 1) on server test-media-01-b.

11:43:45.226 [13518] <2> set_job_details: Tfile (3961243): PROCESS 1346841825 13518 bptm

11:43:45.226 [13518] <2> set_job_details: Tfile (3961243): MOUNTING 1346841825 A000000

11:43:45.226 [13518] <2> set_job_details: Tfile (3961243): LOG 1346841825 4 bptm 13518 INF - Waiting for mount of media id A000000 on server test-media-01-b for reading.

11:43:45.226 [13518] <4> create_tpreq_file: symlink to path /dev/nst0
11:43:45.228 [13518] <2> manage_drive_before_load: SCSI RESERVE
11:43:45.229 [13518] <2> manage_drive_before_load: report_attr, fl1 0x00000001, fl2 0x00000000
11:43:45.229 [13518] <4> expandpath: /usr/openv/netbackup/db/media/tpreq/drive_TLD-018-2
11:43:46.192 [13518] <2> tapelib: wait_for_ltid, Mount, timeout 0
11:44:12.775 [13561] <2> bptm: INITIATING (VERBOSE = 5): -rptdrv -jobid -1342211437 -jm
11:44:12.775 [13561] <2> bptm: PORT_STATUS = 0x00000000
11:44:12.775 [13561] <2> drivename_open: Called with Create 0, file TLD-018-2
11:44:12.775 [13561] <2> drivename_checklock: Called
11:44:12.775 [13561] <2> drivename_checklock: PID 13518 has lock
11:44:12.775 [13561] <2> report_drives: DRIVE = TLD-018-2 LOCK = TRUE CURTIME = 1346841852
11:44:12.775 [13561] <2> report_drives: MODE = 3
11:44:12.775 [13561] <2> report_drives: TIME = 1346841825
11:44:12.775 [13561] <2> report_drives: MASTER = test-master-01
11:44:12.775 [13561] <2> report_drives: SR_KEY = 0 1
11:44:12.775 [13561] <2> report_drives: PATH = /dev/nst0
11:44:12.775 [13561] <2> report_drives: MEDIA = A000000
11:44:12.775 [13561] <2> report_drives: REQID = 3961243
11:44:12.775 [13561] <2> report_drives: ALOCID = 19089311
11:44:12.775 [13561] <2> report_drives: RBID = \{570D13BC-F746-11E1-8EA6-001517006EBE\}
11:44:12.775 [13561] <2> report_drives: PID = 13518
11:44:12.775 [13561] <2> report_drives: FILE = /usr/openv/netbackup/db/media/tpreq/drive_TLD-018-2
11:44:12.775 [13561] <2> main: Sending [EXIT STATUS 0] to NBJM
11:44:12.775 [13561] <2> bptm: EXITING with status 0 <----------
11:44:31.705 [13518] <2> io_open: SCSI RESERVE
11:44:31.720 [13518] <2> manage_drive_attributes: report_attr, fl1 0x00030049, fl2 0x0000000c
11:44:31.720 [13518] <2> manage_drive_attributes: Reported medium manufacturer [HP], sn [2130848259]
11:44:31.720 [13518] <2> manage_drive_attributes: Host Attributes: Vendor [SYMANTEC], Name [NetBackup BPTM], Version [6.5]
11:44:31.720 [13518] <2> manage_drive_attributes: DateLabeled [201206040915], Barcode [A000000], Owninghost [gbin5005]
11:44:31.720 [13518] <2> manage_drive_attributes: MediaPool [testpool], MediaLabel [MEDIA=A000000;]
11:44:31.727 [13518] <2> manage_drive_attributes: encryption status: nexus scope 1, key scope 1
11:44:31.727 [13518] <2> manage_drive_attributes: encryp mode 0x0, decryp mode 0x0, algorithm index 1, key instance 271
11:44:31.731 [13518] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_TLD-018-2 successfully opened (mode 0)
11:44:31.731 [13518] <2> set_job_details: Tfile (3961243): MOUNTED 1346841871 A000000

11:44:31.731 [13518] <2> load_media: media id A000000 mounted on drive index 31
11:44:31.732 [13518] <2> io_read_media_header: drive index 31, reading media header, buflen = 65536, buff = 0x0xc811680, copy 1
11:44:31.732 [13518] <2> io_ioctl: command (6)MTREW 1 0x0 from (bptm.c.8177) on drive index 31
11:44:31.829 [13518] <2> set_job_details: Tfile (3961243): LOG 1346841871 16 bptm 13518 read error on media id A000000, drive index 31, reading header block, Input/output error

11:44:31.829 [13518] <2> ConnectionCache::connectAndCache: Acquiring new connection for host test-master-01, query type 1
11:44:31.829 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1370: 0: found in cache name: test-master-01
11:44:31.829 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1371: 0: found in cache service: NULL
11:44:31.829 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1370: 0: found in cache name: localhost
11:44:31.829 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1371: 0: found in cache service: NULL
11:44:31.829 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1370: 0: found in cache name: test-master-01
11:44:31.829 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1371: 0: found in cache service: NULL
11:44:31.829 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1370: 0: found in cache name: test-master-01
11:44:31.829 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1371: 0: found in cache service: veritas_pbx
11:44:31.829 [13518] <2> vnet_sortaddrs: ../../libvlibs/vnet_addrinfo.c.4037: 0: sorted addrs:: 1 0x00000001
11:44:31.830 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1370: 0: found in cache name: 10.179.123.250
11:44:31.830 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1371: 0: found in cache service: NULL
11:44:31.830 [13518] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.4893: 0: using interface : ANY
11:44:31.830 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1370: 0: found in cache name: test-master-01
11:44:31.830 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1371: 0: found in cache service: vnetd
11:44:31.830 [13518] <2> vnet_sortaddrs: ../../libvlibs/vnet_addrinfo.c.4037: 0: sorted addrs:: 1 0x00000001
11:44:31.830 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1370: 0: found in cache name: 10.179.123.250
11:44:31.830 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1371: 0: found in cache service: NULL
11:44:31.830 [13518] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.4893: 0: using interface : ANY
11:44:31.830 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1370: 0: found in cache name: test-master-01
11:44:31.830 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1371: 0: found in cache service: bpdbm
11:44:31.830 [13518] <2> vnet_sortaddrs: ../../libvlibs/vnet_addrinfo.c.4037: 0: sorted addrs:: 1 0x00000001
11:44:31.830 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1370: 0: found in cache name: 10.179.123.250
11:44:31.830 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1371: 0: found in cache service: NULL
11:44:31.830 [13518] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.4893: 0: using interface : ANY
11:44:31.830 [13518] <2> vnet_async_connect: ../../libvlibs/vnet_connect.c.1200: 0: connect in progress: 1 0x00000001
11:44:31.833 [13518] <2> vnet_pbxConnect: pbxConnectEx Succeeded
11:44:31.834 [13518] <2> do_pbx_service: ../../libvlibs/vnet_connect.c.1784: 0: via PBX: bpdbm CONNECT FROM 10.179.123.251.36428 TO 10.179.123.250.1556 fd = 19
11:44:31.834 [13518] <2> vnet_async_connect: ../../libvlibs/vnet_connect.c.1367: 0: connect: async CONNECT FROM 10.179.123.251.36428 TO 10.179.123.250.1556 fd = 19
11:44:31.834 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1370: 0: found in cache name: test-master-01
11:44:31.834 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1371: 0: found in cache service: NULL
11:44:31.834 [13518] <2> logconnections: BPDBM CONNECT FROM 10.179.123.251.36428 TO 10.179.123.250.1556 fd = 19
11:44:31.834 [13518] <2> vnet_check_vxss_client_magic_with_info: ../../libvlibs/vnet_vxss_helper.c.871: 0: Ignoring VxSS authentication: 2 0x00000002
11:44:31.874 [13518] <2> db_end: Need to collect reply
11:44:32.107 [13518] <16> io_read_media_header: read error on media id A000000, drive index 31, reading header block, Input/output error
11:44:32.107 [13518] <2> check_error_history: just tpunmount: called from bptm line 2404, EXIT_Status = 85
11:44:32.107 [13518] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_TLD-018-2, from bptm.c.16250
11:44:32.107 [13518] <2> drivename_write: Called with mode 1
11:44:32.107 [13518] <2> drivename_unlock: unlocked
11:44:32.107 [13518] <2> drivename_close: Called for file TLD-018-2
11:44:32.107 [13518] <2> tpunmount: NOP: MEDIA_DONE 0 3961243 0 A000000 4020550 0 \{570D13BC-F746-11E1-8EA6-001517006EBE\}
11:44:32.107 [13518] <2> bptm: Calling tpunmount for media A000000
11:44:32.107 [13518] <2> send_MDS_msg: MEDIA_DONE 0 3961243 0 A000000 4020550 0 \{570D13BC-F746-11E1-8EA6-001517006EBE\}
11:44:32.107 [13518] <2> JobInst::sendIrmMsg: starting
11:44:32.107 [13518] <2> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 3961243 0 A000000 4020550 0 \{570D13BC-F746-11E1-8EA6-001517006EBE\})
11:44:32.107 [13518] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid 3961243 copyNum 0 mediaId A000000 mediaKey 4020550 unloadDelay 0 allocId \{570D13BC-F746-11E1-8EA6-001517006EBE\}
11:44:32.107 [13518] <2> packageBptmResourceDoneMsg: returns 0
11:44:32.107 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1370: 0: found in cache name: 10.179.123.250
11:44:32.107 [13518] <2> vnet_cached_getaddrinfo_and_update: ../../libvlibs/vnet_addrinfo.c.1371: 0: found in cache service: NULL
11:44:32.123 [13518] <2> JobInst::sendIrmMsg: returning
11:44:32.123 [13518] <2> bptm: EXITING with status 85 <----------
11:44:32.123 [13518] <2> set_job_details: Tfile (3961243): LOG 1346841872 4 bptm 13518 EXITING with status 85 <----------

11:44:36.023 [14264] <2> bptm: INITIATING (VERBOSE = 5): -unload -dn TLD-018-2 -dp /dev/nst0 -dk 2003192 -m A000000 -mk 4020550 -mds 24 -alocid 19089311 -jobid -1342211438 -jm
11:44:36.023 [14264] <2> bptm: PORT_STATUS = 0x00000000
11:44:36.023 [14264] <2> vnet_same_host: ../../libvlibs/vnet_addrinfo.c.2926: 0: name2 is empty: 0 0x00000000
11:44:36.023 [14264] <4> bptm: emmserver_name = test-master-01
11:44:36.023 [14264] <4> bptm: emmserver_port = 1556

 

------------------------

 

In any encryption 1st phase of import should complete ...

 

Any Suggestions ..........

 

Thanks in Advance

 

 

 

 

 

 

7.1.x and Earlier
Backup and Recovery
Basics
NetBackup
  • Kuldeep_Singh_R's avatar
    Kuldeep_Singh_R
    12 years ago

    Spoke to Symantec Support they informed that Oracle KMS is not supported with NetBackup :(

    Thanks to all for providing suggestion

7 Replies

Sort By
  • Will_Restore's avatar
    Will_Restore
    Level 6
    12 years ago

    <16> io_read_media_header: read error on media id A000000, drive index 31, reading header block, Input/output error
     

    bad tape?

    dirty drive heads?

     

  • Kuldeep_Singh_R's avatar
    Kuldeep_Singh_R
    Level 3
    12 years ago

    mph999 ....

     

    Do we need encryption key in place for the 1st Phase of import or that comes to picture when we run 2nd Phase of import ..

     

    Thanks

  • Will_Restore's avatar
    Will_Restore
    Level 6
    12 years ago

    from the Security & Encryption guide:

     

    About importing KMS encrypted images

    Importing KMS encrypted images is a two-phase operation. In phase one, the

    media header and each fragment backup header is read. This data is never

    encrypted. However, the backup headers indicate if the fragments file data is

    encrypted with KMS or not. In summary, phase one does not require a key.

     

    Phase two rebuilds the catalog .f file, which requires it to read the encrypted

    data. The key-tag (KAD in SCSI terms) is stored on the tape by the hardware. The

    NBU/BPTM reads the key-tag from the drive, and sends it to KMS for a key lookup.

    If KMS has a key, then the phase two processes continues to read the encrypted

    data. If KMS has no key, the data is not readable until the KMS has the key

    recreated. This is when the pass phrase is important.

     

    If you do not destroy keys, then KMS contains all the keys ever used and you can

    import any encrypted tape. Move the keystore to yourDRsite and you do not need

    to recreate it.

  • Kuldeep_Singh_R's avatar
    Kuldeep_Singh_R
    Level 3
    12 years ago

    Thanks wr ...

    In my case i'm not able to complete the 1st Phase only .....these tapes were encrypted with Oracle KMS so not sure whats their functionality is ....

    But as of now the situation is that Netbackup is not able to read these encrypted tapes even for the 1st Phase ...

     

    Thanks

  • Kuldeep_Singh_R's avatar
    Kuldeep_Singh_R
    Level 3
    12 years ago

    Spoke to Symantec Support they informed that Oracle KMS is not supported with NetBackup :(

    Thanks to all for providing suggestion