Error 86 : Warning bptm cannot locate on drive index. Using "Multiple Copies"

Create the following empty file:

 /usr/openv/netbackup/db/config/DISABLE_APPEND_MODE

Does it now work, or at the very least fail in a different way.

errpt and messages fles would be necessary as well - I don't know why it is failing, but the 'allow overwrite' feature is scsi related so I suspect that this issue will comedown to a tape driver/ firmware / OS  issue as opposed to NBU.

Hola Marianne, thank you very much for your support!!

I forgot mention that all LTO6 is working OK (with master and media) also the same policy without “multiple copies” backing up on the same LTO6 drive working OK. The problem appear when I configure multiple copies and the 2nd copy to the LTO4. In this case 1st copy finish with error 86 and 2nd copy finish OK.
On the other hand, if I set the 1st copy and 2nd to LTO6 drives the backup finish OK.

According to the picture of “activity monitor” attached: (some tests)
The JOB marked (1) : the “media server” is the media and 1st copy to LTO6 and 2nd copy to LTO4 and both finish OK.
The JOB marked (2) : the “media server” is the master and 1st copy to LTO6 and 2nd copy to LTO6 and be sure the backup will be finish OK, but I stop in order to no use space in tape. You will see that both copies run and both already wrote kilobytes. (See the job (3) that 1st copy never wrote any kilobytes).
The JOB marked (3) : the “media server” is the master and 1st copy to LTO6 and 2nd copy to LTO4 and only 2nd copy finish OK, the 1st copy finish with error 86.I cannot attached the log; also, neither copy the log because the message exceed 20000 characters. :((
Also on the activity monitor you will see other jobs using the master o media as “media server” and the storage unit LTO6 finishing OK.

Today, I tested multiple copies using master as “media server” and 1st copy to LTO4 and the 2nd copy to LTO4 and both finish OK.
Other test was test multiple copies using master as “media server” and 1st copy to LTO6 and 2nd copy to LTO4 but different LTO6 drive (other library) and different retention level and 2nd copy finish OK, 1st copy error86.

Thanks in advance !!!
Alex

Hi Marianne, thanks for your help !!!!

All LTO6 drives give this error if the backups is dual using LTO4 and LTO6. In this case does not care LTO6 drives or media. As I wrote before for backups “no dual” all LTO6 works OK.

I do not confirmed if the tape driver on Master is supported or not yet but I suppose yes because for “no dual” backups is working OK…. (is my thinking right?)

I already create a small policy in order to test your suggests, changing schedules and retention levels and the LTO6 drives and media was different but the error was 86 and the other test 84.

Below you will find the bptm log … (master at level 3)

Last error on /usr/openv/netbackup/db/media/errors was 2 month ago.

Bptm log 1st Part: (1st test)

09:59:48.336 [15270292] <2> manage_drive_attributes: report_attr, fl1 0x00030049, fl2 0x0000000c

09:59:48.337 [15270292] <2> manage_drive_attributes: Matching medium manufacturer [FUJIFILM], sn [094K114558]

09:59:48.337 [15270292] <2> manage_drive_attributes: Host Attributes: Vendor [SYMANTEC], Name [NetBackup BPTM], Version [7.7.1]

09:59:48.337 [15270292] <2> manage_drive_attributes: DateLabeled [201607241100], Barcode [000491L4], Owninghost [pm-nbmaster]

09:59:48.337 [15270292] <2> manage_drive_attributes: MediaPool [NetBackup], MediaLabel [MEDIA=000491;]

09:59:48.348 [15270292] <2> manage_drive_attributes: encryption status: nexus scope 1, key scope 1

09:59:48.348 [15270292] <2> manage_drive_attributes: encryp mode 0x0, decryp mode 0x0, algorithm index 1, key instance 14

09:59:48.369 [15270292] <2> io_open: SCSI RESERVE

09:59:48.371 [15270292] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.021 successfully opened (mode 2)

09:59:48.371 [15270292] <2> write_backup: media id 000491 mounted on drive index 2, drivepath /dev/rmt12.1, drivename IBM.ULT3580-TD4.021, copy 2

09:59:48.371 [15270292] <4> report_throughput: VBRT 1 15270292 1 2 IBM.ULT3580-HH6.062 IBM.ULT3580-TD4.021 0058L6 000491 0 0 1 0 0  0 (bptm.c.18581)

09:59:48.371 [15270292] <2> io_read_media_header: drive index 17, reading media header, buflen = 65536, buff = 0x110642df0, copy 1

09:59:48.371 [15270292] <2> io_ioctl: command (6)MTREW 1 0x0 from (bptm.c.8362) on drive index 17

09:59:48.383 [15270292] <2> io_ioctl: command (11)MTFSF 1 0x0 from (bptm.c.8614) on drive index 17

09:59:48.398 [15270292] <2> io_read_media_header: drive index 2, reading media header, buflen = 65536, buff = 0x110642df0, copy 2

09:59:48.398 [15270292] <2> io_ioctl: command (6)MTREW 1 0x0 from (bptm.c.8362) on drive index 2

09:59:48.410 [15270292] <2> io_ioctl: command (11)MTFSF 1 0x0 from (bptm.c.8614) on drive index 2

09:59:48.431 [15270292] <2> io_position_for_write: position media id 0058L6, copy 1, current number images = 467

09:59:48.431 [15270292] <2> io_position_for_write: locating to absolute block number 13446085, copy 1

09:59:48.431 [15270292] <8> io_position_for_write: cannot locate on drive index 17, 0

09:59:48.431 [15270292] <2> io_ioctl: command (6)MTREW 1 0x0 from (bptm.c.7178) on drive index 17

09:59:48.436 [15270292] <2> io_position_for_write: cannot read position on drive index 17, 0

09:59:48.436 [15270292] <2> check_error_history: just tpunmount: called from bptm line 23017, EXIT_Status = 86

09:59:48.436 [15270292] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-HH6.062, from bptm.c.16737

09:59:48.436 [15270292] <2> drivename_write: Called with mode 1

09:59:48.436 [15270292] <2> drivename_unlock: unlocked

09:59:48.436 [15270292] <2> drivename_close: Called for file IBM.ULT3580-HH6.062

09:59:48.436 [15270292] <2> tpunmount: NOP: MEDIA_DONE 0 729466 0 0058L6 4001183 0 {6CD363BA-5267-11E6-B17E-3358A6AA0000}

09:59:48.437 [15270292] <16> terminate_twin: INF - media position error (86), cannot continue with copy 1

09:59:48.437 [15270292] <2> check_if_query_requires_authentication: need authentication = AUTH_PROHIBITED,for query type = 64

09:59:48.437 [15270292] <2> ConnectionCache::connectAndCache: Acquiring new connection for host pm-nbmaster, query type 64

09:59:48.437 [15270292] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4720] Local [strong] check, using interface  ANY

09:59:48.437 [15270292] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4720] Local [strong] check, using interface  ANY

09:59:48.437 [15270292] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4720] Local [strong] check, using interface  ANY

09:59:48.437 [15270292] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4720] Local [strong] check, using interface  ANY

09:59:48.437 [15270292] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4720] Local [strong] check, using interface  ANY

09:59:48.437 [15270292] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4720] Local [strong] check, using interface  ANY

09:59:48.438 [15270292] <2> vnet_pbxConnect: pbxConnectEx Succeeded

09:59:48.438 [15270292] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO pm-nbmaster 10.130.1.154 bpdbm VIA pbx

09:59:48.438 [15270292] <2> logconnections: BPDBM CONNECT FROM 10.130.1.154.59217 TO 10.130.1.154.1556 fd = 20

09:59:48.441 [15270292] <2> db_end: Need to collect reply

09:59:48.676 [15270292] <2> check_error_history: just tpunmount: called from bptm line 3908, EXIT_Status = 86

09:59:48.676 [15270292] <2> tpunmount: NOP: MEDIA_DONE 0 729466 0 0058L6 4001183 0 {6CD363BA-5267-11E6-B17E-3358A6AA0000}

09:59:48.676 [15270292] <2> io_position_for_write: position media id 000491, copy 2, current number images = 1

09:59:48.676 [15270292] <2> io_position_for_write: locating to absolute block number 678425, copy 2

2nd Part (2nd Test)

10:10:11.718 [18547188] <2> manage_drive_attributes: report_attr, fl1 0x00230049, fl2 0x00000004

10:10:11.718 [18547188] <2> manage_drive_attributes: Reported medium manufacturer [FUJIFILM], sn [EU85WDUMAR]

10:10:11.728 [18547188] <2> manage_drive_attributes: encryption status: nexus scope 1, key scope 1

10:10:11.728 [18547188] <2> manage_drive_attributes: encryp mode 0x0, decryp mode 0x0, algorithm index 3, key instance 52

10:10:11.728 [18547188] <2> manage_drive_attributes: Media is protected with APPEND_ONLY

10:10:11.736 [18547188] <2> io_open: SCSI RESERVE

10:10:11.738 [18547188] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-HH6.063 successfully opened (mode 2)

10:10:11.738 [18547188] <2> write_backup: media id 0070L6 mounted on drive index 12, drivepath /dev/rmt21.1, drivename IBM.ULT3580-HH6.063, copy 1

10:10:11.738 [18547188] <4> report_throughput: VBRT 1 18547188 1 2 IBM.ULT3580-HH6.063 IBM.ULT3580-TD4.022 0070L6 000307 0 0 1 0 0  0 (bptm.c.18581)

10:10:11.738 [18547188] <2> mount_open_media: Waiting for mount of media id 000307 (copy 2) on server pm-nbmaster.

10:10:11.739 [18547188] <4> create_tpreq_file: symlink to path /dev/rmt2.1

10:10:11.743 [18547188] <2> manage_drive_before_load: SCSI RESERVE

10:10:11.746 [18547188] <2> manage_drive_before_load: report_attr, fl1 0x00000001, fl2 0x00000000

10:10:11.751 [18547188] <4> expandpath: /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.022

10:10:12.290 [18547188] <2> tapelib: wait_for_ltid, Mount, timeout 0

10:11:04.810 [18547188] <2> manage_drive_attributes: report_attr, fl1 0x00030049, fl2 0x0000000c

10:11:04.810 [18547188] <2> manage_drive_attributes: Matching medium manufacturer [FUJIFILM], sn [EP96RUFREX]

10:11:04.810 [18547188] <2> manage_drive_attributes: Host Attributes: Vendor [SYMANTEC], Name [NetBackup BPTM], Version [7.7.1]

10:11:04.810 [18547188] <2> manage_drive_attributes: DateLabeled [201606181832], Barcode [000307L4], Owninghost [pm-nbmedia]

10:11:04.810 [18547188] <2> manage_drive_attributes: MediaPool [NetBackup], MediaLabel [MEDIA=000307;]

10:11:04.823 [18547188] <2> manage_drive_attributes: encryption status: nexus scope 1, key scope 1

10:11:04.823 [18547188] <2> manage_drive_attributes: encryp mode 0x0, decryp mode 0x0, algorithm index 1, key instance 21

10:11:04.845 [18547188] <2> io_open: SCSI RESERVE

10:11:04.847 [18547188] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.022 successfully opened (mode 2)

10:11:04.847 [18547188] <2> write_backup: media id 000307 mounted on drive index 6, drivepath /dev/rmt2.1, drivename IBM.ULT3580-TD4.022, copy 2

10:11:04.848 [18547188] <4> report_throughput: VBRT 1 18547188 1 2 IBM.ULT3580-HH6.063 IBM.ULT3580-TD4.022 0070L6 000307 0 0 1 0 0  0 (bptm.c.18581)

10:11:04.848 [18547188] <2> io_read_media_header: drive index 12, reading media header, buflen = 65536, buff = 0x110643e70, copy 1

10:11:04.848 [18547188] <2> io_ioctl: command (6)MTREW 1 0x0 from (bptm.c.8362) on drive index 12

10:11:04.860 [18547188] <2> io_read_media_header: read error on media id 0070L6, drive index 12, reading header block, There is an input or output error.

10:11:04.860 [18547188] <2> io_read_media_header: drive index 6, reading media header, buflen = 65536, buff = 0x110643e70, copy 2

10:11:04.860 [18547188] <2> io_ioctl: command (6)MTREW 1 0x0 from (bptm.c.8362) on drive index 6

10:11:04.873 [18547188] <2> io_write_media_header: drive index 12, writing media header

10:11:04.873 [18547188] <2> io_ioctl: command (6)MTREW 1 0x0 from (bptm.c.9796) on drive index 12

10:11:04.879 [18547188] <4> io_write_media_header: allow overwrite scsi command failed

10:11:04.880 [18547188] <16> io_write_media_header: allow overwrite operation failed to media id 0070L6, drive index 12, address 0

10:11:04.880 [18547188] <2> check_error_history: just tpunmount: called from bptm line 22852, EXIT_Status = 84

10:11:04.880 [18547188] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-HH6.063, from bptm.c.16737

10:11:04.880 [18547188] <2> drivename_write: Called with mode 1

10:11:04.880 [18547188] <2> drivename_unlock: unlocked

10:11:04.880 [18547188] <2> drivename_close: Called for file IBM.ULT3580-HH6.063

10:11:04.880 [18547188] <2> tpunmount: NOP: MEDIA_DONE 0 729469 0 0070L6 4001195 0 {EFAB1EC6-5268-11E6-AC84-355A86510000}

10:11:04.880 [18547188] <16> terminate_twin: INF - media write error (84), cannot continue with copy 1

10:11:04.880 [18547188] <2> check_if_query_requires_authentication: need authentication = AUTH_PROHIBITED,for query type = 64

10:11:04.880 [18547188] <2> ConnectionCache::connectAndCache: Acquiring new connection for host pm-nbmaster, query type 64

10:11:04.880 [18547188] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4720] Local [strong] check, using interface  ANY

10:11:04.880 [18547188] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4720] Local [strong] check, using interface  ANY

10:11:04.881 [18547188] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4720] Local [strong] check, using interface  ANY

10:11:04.881 [18547188] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4720] Local [strong] check, using interface  ANY

10:11:04.881 [18547188] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4720] Local [strong] check, using interface  ANY

10:11:04.881 [18547188] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4720] Local [strong] check, using interface  ANY

10:11:04.881 [18547188] <2> vnet_pbxConnect: pbxConnectEx Succeeded

10:11:04.882 [18547188] <2> connect_to_service: connect succeeded STATUS (0) SUCCESS FROM 0.0.0.0 TO pm-nbmaster 10.130.1.154 bpdbm VIA pbx

10:11:04.882 [18547188] <2> logconnections: BPDBM CONNECT FROM 10.130.1.154.59386 TO 10.130.1.154.1556 fd = 20

10:11:04.885 [18547188] <2> db_end: Need to collect reply

10:11:05.123 [18547188] <2> check_error_history: just tpunmount: called from bptm line 3908, EXIT_Status = 84

10:11:05.123 [18547188] <2> tpunmount: NOP: MEDIA_DONE 0 729469 0 0070L6 4001195 0 {EFAB1EC6-5268-11E6-AC84-355A86510000}

10:11:05.123 [18547188] <2> io_write_media_header: drive index 6, writing media header

10:11:05.123 [18547188] <2> io_ioctl: command (6)MTREW 1 0x0 from (bptm.c.9796) on drive index 6

10:11:05.140 [18547188] <2> io_close: closing /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.022, from bptm.c.9824

10:11:05.156 [18547188] <2> io_open: SCSI RESERVE

10:11:05.158 [18547188] <2> io_open: file /usr/openv/netbackup/db/media/tpreq/drive_IBM.ULT3580-TD4.022 successfully opened (mode 2)

10:11:05.214 [18547188] <2> io_ioctl: command (10)MTWEOF 1 0x0 from (bptm.c.9860) on drive index 6

10:11:09.992 [18547188] <2> io_write_host_attributes: Successfully wrote host attributes to media

10:11:09.997 [18547188] <2> io_write_media_header: report_density, 0x46 [LTO-CVE U-416]

10:11:09.997 [18547188] <2> send_MDS_msg: VOL_UPDATE 0 99055 000307 4000483 FUJIFILM EP96RUFREX 4 70

10:11:09.997 [18547188] <2> EndpointSelector_R2::select_endpoint: epsr2: EPS Honoring Server List(Endpoint_Selector.cpp:560)

10:11:09.997 [18547188] <2> EndpointSelector_R2::endpoint_from_profile: epsr2: Reusing endpoint, target: 10.130.1.154, source: ANY(Endpoint_Selector.cpp:738)

10:11:09.997 [18547188] <2> EndpointSelector_R2::performCallUsingEndpoint: epsr2: insecure invocation->perform_call(...) to host 10.130.1.154 SUCCESS(Endpoint_Selector.cpp:1256)

10:11:10.004 [18547188] <2> emmlib_handleMessage: (0) CORBA call returned 0

10:11:10.004 [18547188] <2> send_MDS_msg: MEDIADB 1 99055 000307 4000483 *NULL* 6 1469452134 1469452134 1470056934 0 0 0 0 0 1 0 0 1024 0 0 0

10:11:10.004 [18547188] <2> EndpointSelector_R2::select_endpoint: epsr2: EPS Honoring Server List(Endpoint_Selector.cpp:560)

10:11:10.004 [18547188] <2> EndpointSelector_R2::endpoint_from_profile: epsr2: Reusing endpoint, target: 10.130.1.154, source: ANY(Endpoint_Selector.cpp:738)

10:11:10.004 [18547188] <2> EndpointSelector_R2::performCallUsingEndpoint: epsr2: insecure invocation->perform_call(...) to host 10.130.1.154 SUCCESS(Endpoint_Selector.cpp:1256)

10:11:10.011 [18547188] <2> emmlib_handleMessage: (0) CORBA call returned 0

10:11:10.011 [18547188] <4> write_backup: begin writing backup id pm-db1_1469452134, copy 2, fragment 1, to media id 000307 on drive IBM.ULT3580-TD4.022 (index 6)

10:11:10.012 [18547188] <2> process_brm_msg: no pending message from bpbrm

10:11:10.012 [18547188] <4> write_backup: waiting for client data or brm message

10:11:10.012 [18547188] <2> send_brm_msg: MEDIA READY

10:11:10.012 [18547188] <2> write_data: twin_index: 1 active: 2 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 0 delay_brm: 0

10:11:10.012 [18547188] <2> write_data: Total Kbytes transferred 0

10:11:10.014 [18547188] <2> write_data: absolute block position prior to writing backup header(s) is 2, copy 2

10:11:10.014 [18547188] <2> io_write_back_header: drive index 6, pm-db1_1469452134, file num = 1, mpx_headers = 1, copy 2

10:11:10.018 [18547188] <2> write_data: completed writing backup header, start writing data when first buffer is available, copy 2

10:11:10.018 [18547188] <2> ndmp_setup_for_write: CINDEX 0, TWIN_INDEX 1, IS_NDMP 0, is_tir 0

10:11:10.018 [18547188] <2> write_data: first write, twin_index: 1 cindex: 0 dont_process: 1 wrote_backup_hdr: 1 finished_buff: 0

10:11:10.018 [18547188] <2> write_data: received first buffer (262144 bytes), begin writing data