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

[amutto]

Hi all,

I have a problems trying to make 2 copies of my backups.

For backups where the "media server" is the media, both copies finish OK (0 error) (Windows and VM machines)

For backups where the "media server" is the master, only copy 2 finish OK, the copy 1 finish with error 86. (AIX, oracle machines)

(Note1: "media server" is the column at activity monitor)

(Note2: Media is windows 2008R2 and Master is AIX)

(Note3: Netbackup is 7.7.1 version)

FYI, we have 2 libraries, one with LTO4 drives and the other library with LTO6 drives ... the schedule are setd as copy1 for LTO6 and copy2 for LTO4.

Below you will find the job fetails:

21/07/2016 08:24:43 - requesting resource pm-nbmaster-hcart3-robot-tld-7

21/07/2016 08:24:43 - requesting resource pm-nbmaster.NBU_CLIENT.MAXJOBS.pm-db2

21/07/2016 08:24:43 - requesting resource pm-nbmaster.NBU_POLICY.MAXJOBS.Unix-Power2

21/07/2016 08:24:44 - Waiting for scan drive stop IBM.ULT3580-HH6.074, Media server: pm-nbmaster

21/07/2016 08:24:47 - granted resource  pm-nbmaster.NBU_CLIENT.MAXJOBS.pm-db2

21/07/2016 08:24:47 - granted resource  pm-nbmaster.NBU_POLICY.MAXJOBS.Unix-Power2

21/07/2016 08:24:47 - granted resource  0018L6

21/07/2016 08:24:47 - granted resource  IBM.ULT3580-HH6.074

21/07/2016 08:24:47 - granted resource  pm-nbmaster-hcart3-robot-tld-7

21/07/2016 08:24:48 - started process bpbrm (pid=14746060)

21/07/2016 08:24:49 - Info bpbrm (pid=14746060) starting bptm

21/07/2016 08:24:49 - Info bpbrm (pid=14746060) Started media manager using bpcd successfully

21/07/2016 08:24:51 - Info bpbrm (pid=14746060) pm-db2 is the host to backup data from

21/07/2016 08:24:51 - Info bptm (pid=12058952) using 262144 data buffer size

21/07/2016 08:24:51 - Info bpbrm (pid=14746060) telling media manager to start backup on client

21/07/2016 08:24:51 - Info bptm (pid=12058952) using 32 data buffers

21/07/2016 08:24:52 - Info bpbrm (pid=14746060) spawning a brm child process

21/07/2016 08:24:52 - Info bpbrm (pid=14746060) child pid: 16646566

21/07/2016 08:24:52 - Info bptm (pid=12058952) start backup

21/07/2016 08:24:52 - Info bptm (pid=12058952) Waiting for mount of media id 0018L6 (copy 1) on server pm-nbmaster.

21/07/2016 08:24:52 - mounting 0018L6

21/07/2016 08:24:53 - Info bpbrm (pid=14746060) sending bpsched msg: CONNECTING TO CLIENT FOR pm-db2_1469100287

21/07/2016 08:24:53 - Info bpbrm (pid=14746060) start bpbkar on client

21/07/2016 08:24:53 - Info bpbkar (pid=20644252) Backup started

21/07/2016 08:24:53 - Info bpbrm (pid=14746060) Sending the file list to the client

21/07/2016 08:24:53 - connecting

21/07/2016 08:24:53 - connected; connect time: 0:00:00

21/07/2016 08:25:48 - Info bptm (pid=12058952) media id 0018L6 mounted on drive index 13, drivepath /dev/rmt22.1, drivename IBM.ULT3580-HH6.074, copy 1

21/07/2016 08:25:48 - Info bptm (pid=12058952) Waiting for mount of media id 000191 (copy 2) on server pm-nbmaster.

21/07/2016 08:25:48 - mounted 0018L6; mount time: 0:00:56

21/07/2016 08:26:34 - Info bptm (pid=12058952) media id 000191 mounted on drive index 6, drivepath /dev/rmt2.1, drivename IBM.ULT3580-TD4.022, copy 2

21/07/2016 08:26:34 - Warning bptm (pid=12058952) cannot locate on drive index 13, 0 

21/07/2016 08:26:34 - positioning 0018L6 to file 98

21/07/2016 08:27:45 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/apps/grid/11.2.0.3] is in a different file system from [/apps/grid]. Skipping

21/07/2016 08:27:45 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/apps/grid/11.2.0.4] is in a different file system from [/apps/grid]. Skipping

21/07/2016 08:28:09 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/apps/openv/var/vnetd/bpcd.uds] is a socket special file. Skipping

21/07/2016 08:28:09 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/apps/openv/var/vnetd/terminate_bpcd.uds] is a socket special file. Skipping

21/07/2016 08:28:09 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/apps/openv/var/vnetd/terminate_vnetd.uds] is a socket special file. Skipping

21/07/2016 08:28:09 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/apps/oracle/10.2.0.4.5] is in a different file system from [/apps/oracle]. Skipping

21/07/2016 08:28:09 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/apps/oracle/10.2.0.5.2] is in a different file system from [/apps/oracle]. Skipping

21/07/2016 08:28:09 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/apps/oracle/11.2.0.3.1] is in a different file system from [/apps/oracle]. Skipping

21/07/2016 08:28:09 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/apps/oracle/11.2.0.4] is in a different file system from [/apps/oracle]. Skipping

21/07/2016 08:28:13 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/apps/oracle/oem] is in a different file system from [/apps/oracle]. Skipping

21/07/2016 08:39:15 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/interfaces/bibo] is on file system type NFS. Skipping

21/07/2016 08:39:15 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/interfaces/coam] is on file system type NFS. Skipping

21/07/2016 08:39:31 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/interfaces/sap_lp] is on file system type NFS. Skipping

21/07/2016 08:46:38 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm04prod/dbfiles1/log1] is in a different file system from [/pm04prod/dbfiles1]. Skipping

21/07/2016 08:46:38 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm04prod/dbfiles1/log2] is in a different file system from [/pm04prod/dbfiles1]. Skipping

21/07/2016 08:47:28 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm10prod/dbfiles1/log1] is in a different file system from [/pm10prod/dbfiles1]. Skipping

21/07/2016 08:47:28 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm10prod/dbfiles1/log2] is in a different file system from [/pm10prod/dbfiles1]. Skipping

21/07/2016 08:47:29 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm11prod/dbfiles1/log1] is in a different file system from [/pm11prod/dbfiles1]. Skipping

21/07/2016 08:47:29 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm11prod/dbfiles1/log2] is in a different file system from [/pm11prod/dbfiles1]. Skipping

21/07/2016 08:47:30 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pmrman/dbfiles1/log1] is in a different file system from [/pmrman/dbfiles1]. Skipping

21/07/2016 08:47:30 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pmrman/dbfiles1/log2] is in a different file system from [/pmrman/dbfiles1]. Skipping

21/07/2016 08:54:23 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/var/adm/ras/livedump] is in a different file system from [/var]. Skipping

21/07/2016 08:54:24 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/var/ct/4162511180/soc/mc/RMIBM.ConfigRM.0] is a socket special file. Skipping

21/07/2016 08:54:24 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/var/ct/4162511180/soc/mc/RMIBM.DRM.0] is a socket special file. Skipping

21/07/2016 08:54:24 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/var/ct/4162511180/soc/mc/RMIBM.HostRM.0] is a socket special file. Skipping

21/07/2016 08:54:24 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/var/ct/4162511180/soc/mc/RMIBM.MgmtDomainRM.0] is a socket special file. Skipping

21/07/2016 08:54:24 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/var/ct/4162511180/soc/mc/RMIBM.ServiceRM.0] is a socket special file. Skipping

21/07/2016 08:54:24 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/var/ct/4162511180/soc/mc/clsrv] is a socket special file. Skipping

21/07/2016 08:54:24 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/var/ct/4162511180/soc/mc/rmsrv] is a socket special file. Skipping

21/07/2016 08:54:51 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/var/mmfs/mmpmon/mmpmonSocket] is a socket special file. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/TI] is in a different file system from [/]. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/admin] is in a different file system from [/]. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/apps/grid] is in a different file system from [/]. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/apps/openv] is in a different file system from [/]. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/apps/oracle] is in a different file system from [/]. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/audit] is in a different file system from [/]. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/auditbd/pm04prod] is on file system type NFS. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/auditbd/pm10prod] is on file system type NFS. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/auditbd/pm11prod] is on file system type NFS. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/dev/SRC] is a socket special file. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/dev/log] is a socket special file. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/dev/.SRC-unix/SRC0003211544Namqea] is a socket special file. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/dev/.SRC-unix/SRC0003211544Q7mqee] is a socket special file. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/dev/.SRC-unix/SRC0003211544Tamqeb] is a socket special file. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/dev/.SRC-unix/SRC0003211544Temqec] is a socket special file. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/dev/.SRC-unix/SRC0003211544bimqef] is a socket special file. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/dev/.SRC-unix/SRC0003211544c7mqeg] is a socket special file. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/dev/.SRC-unix/SRC0003211544d7mqei] is a socket special file. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/dev/.SRC-unix/SRC0003211544dEmqej] is a socket special file. Skipping

21/07/2016 08:55:02 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/dev/.SRC-unix/SRC0003211544dumqeh] is a socket special file. Skipping

21/07/2016 08:55:53 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/home] is in a different file system from [/]. Skipping

21/07/2016 08:55:53 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/interfaces] is in a different file system from [/]. Skipping

21/07/2016 08:55:54 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/oem/datafiles] is in a different file system from [/]. Skipping

21/07/2016 08:55:54 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/oem/dbfiles/log1] is in a different file system from [/]. Skipping

21/07/2016 08:55:54 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/oem/dbfiles/log2] is in a different file system from [/]. Skipping

21/07/2016 08:55:54 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/oem/redo_arch] is in a different file system from [/]. Skipping

21/07/2016 08:55:54 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/opt] is in a different file system from [/]. Skipping

21/07/2016 08:55:54 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/oracss1] is in a different file system from [/]. Skipping

21/07/2016 08:55:54 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/oracss2] is in a different file system from [/]. Skipping

21/07/2016 08:55:54 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/oracss3] is in a different file system from [/]. Skipping

21/07/2016 08:55:54 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/oraocr1] is in a different file system from [/]. Skipping

21/07/2016 08:55:54 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/oraocr2] is in a different file system from [/]. Skipping

21/07/2016 08:55:54 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/oraocr3] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm04prod/dbfiles1] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm04prod/export] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm04prod/redo_arch] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm10prod/dbfiles1] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm10prod/dbfiles2] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm10prod/export] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm10prod/redo_arch] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm11prod/dbfiles1] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm11prod/export] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pm11prod/redo_arch] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pmrman/dbfiles1] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pmrman/export] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/pmrman/redo_arch] is in a different file system from [/]. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/proc] is on file system type PROC. Skipping

21/07/2016 08:56:00 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/scratch] is in a different file system from [/]. Skipping

21/07/2016 08:56:01 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/tmp] is in a different file system from [/]. Skipping

21/07/2016 08:56:01 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/usr] is in a different file system from [/]. Skipping

21/07/2016 08:56:01 - Info bpbrm (pid=16646566) from client pm-db2: TRV - [/var] is in a different file system from [/]. Skipping

21/07/2016 08:56:06 - Info bpbrm (pid=14746060) media manager for backup id pm-db2_1469100287 exited with status 0: the requested operation was successfully completed

[Marianne]

Are all LTO6 drives on the master giving this error on any LTO6 tape or just certain LTO drives and/or certain LTO6 media?

Have you confirmed that the tape driver on AIX master actually supports these specific make/model LTO6 drives? Is variable block length configured at OS-level?

While you are troubleshooting, create a test policy where you are only selecting the master server STU for LTO6 drives. (No dual copy backups)

Ensure bptm log folder exists on the master server and increase logging level for bptm on the master to 3.

Run a couple of test backups to small test policy with different schedules and retention levels to ensure different tapes are used for each attempt.

What is the result of the tests?
If same tape drive is used each time, you can DOWN all but one LTO6 on the master.
Repeat test for all drives.

Check bptm log on the master for error, check /usr/openv/netbackup/db/media/errors for errors logged against LTO6 drives and media.
Check OS for errors - use errpt and check /var/adm/messages (provided syslog is enabled).

[amutto]

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

[Marianne]

Why can you not attach log files?
Have you tried to copy the bptm log to bptm.txt and use the 'choose file' button to upload the log?

From your description, I think that the failure and the copy number are not related.
All of the NBU logs and the OS logs that I mentioned in the previous post need to be looked at to determine if you have a drive issue or faulty piece of media.

[amutto]

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

[Marianne]

Please Please PLEASE copy logs to .txt files and use 'Choose file' to upload as attachment.

You need to find out where this is coming from:

"io_write_media_header: allow overwrite scsi command failed"

Do you have write protected tapes in the robot?

[amutto]

Hi Marianne !!!

I'm new with VOX, sorry ... but where in the screenshot below I can attach the text file ? maybe I'm still sleepy !! (in Argentina is 8:00 AM) jejeje.

Thanks a lot !

Alex

[Marianne]

Is there no "Choose File" at the bottom of your screen?

We are ALL new to VOX.... 

I am using the same link to attach a screenshot....

[amutto]

Nop :(

Currently I use chrome but I already tried with IE and there is not button "Choose file" as you show me ...

mmmmm maybe java?  I'm looking for a solution inside veritas.

Thanks

[mph999]

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.