Bacula-users

Re: [Bacula-users] autochanger woes

2014-09-20 17:27:50
Subject: Re: [Bacula-users] autochanger woes
From: "RAT" <robert3t AT netzero DOT net>
To: rsvancara AT gmail DOT com, bacula-users AT lists.sourceforge DOT net
Date: Sat, 20 Sep 2014 21:19:09 GMT
I think you're correct.  Although I'm not sure exactly how to remedy. 

[root@bacula1 sbin]# vi /usr/libexec/bacula/mtx-changer
[root@bacula1 sbin]# ./bconsole 
Connecting to Director localhost:9101
1000 OK: bacula-dir Version: 5.2.13 (19 February 2013)
Enter a period to cancel a command.
*label barcodes
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
The defined Storage resources are:
     1: File
     2: DL4000
Select Storage resource (1-2): 2
Connecting to Storage daemon DL4000 at bacula1.usi.edu:9103 ...
Enter autochanger drive[0]: 4
Connecting to Storage daemon DL4000 at bacula1.usi.edu:9103 ...
3306 Issuing autochanger "slots" command.
Device "Drive1" has 48 slots.
Connecting to Storage daemon DL4000 at bacula1.usi.edu:9103 ...
3306 Issuing autochanger "list" command.
The following Volumes will be labeled:
Slot  Volume
==============
  10  000047L6
  11  000038L6
  14  000039L6
  15  000053L6
  18  000023L6
  19  000059L6
Do you want to label these Volumes? (yes|no): yes
Defined Pools:
     1: Default
     2: File
     3: Scratch
Select the Pool (1-3): 3
Connecting to Storage daemon DL4000 at bacula1.usi.edu:9103 ...
Sending label command for Volume "000047L6" Slot 10 ...
3307 Issuing autochanger "unload slot 19, drive 0" command.
3995 Bad autochanger "unload slot 19, drive 0": ERR=Child exited with code 1
Results=Unloading drive 0 into Storage Element 19...mtx: Request Sense: Long 
Report=yes
mtx: Request Sense: Valid Residual=no
mtx: Request Sense: Error Code=70 (Current)
mtx: Request Sense: Sense Key=Illegal Request
mtx: Request Sense: FileMark=no
mtx: Request Sense: EOM=no
mtx: Request Sense: ILI=no
mtx: Request Sense: Additional Sense Code = 53
mtx: Request Sense: Additional Sense Qualifier = 03
mtx: Request Sense: BPV=no
mtx: Request Sense: Error in CDB=no
mtx: Request Sense: SKSV=no
MOVE MEDIUM from Element Address 256 to 4114 Failed

Label command failed for Volume 000047L6.
Sending label command for Volume "000038L6" Slot 11 ...
3307 Issuing autochanger "unload slot 19, drive 0" command.
3995 Bad autochanger "unload slot 19, drive 0": ERR=Child exited with code 1
Results=Unloading drive 0 into Storage Element 19...mtx: Request Sense: Long 
Report=yes
mtx: Request Sense: Valid Residual=no
mtx: Request Sense: Error Code=70 (Current)
mtx: Request Sense: Sense Key=Illegal Request
mtx: Request Sense: FileMark=no
mtx: Request Sense: EOM=no
mtx: Request Sense: ILI=no
mtx: Request Sense: Additional Sense Code = 53
mtx: Request Sense: Additional Sense Qualifier = 03
mtx: Request Sense: BPV=no
mtx: Request Sense: Error in CDB=no
mtx: Request Sense: SKSV=no
MOVE MEDIUM from Element Address 256 to 4114 Failed

Label command failed for Volume 000038L6.
Sending label command for Volume "000039L6" Slot 14 ...
3307 Issuing autochanger "unload slot 19, drive 0" command.
3995 Bad autochanger "unload slot 19, drive 0": ERR=Child exited with code 1
Results=Unloading drive 0 into Storage Element 19...mtx: Request Sense: Long 
Report=yes
mtx: Request Sense: Valid Residual=no
mtx: Request Sense: Error Code=70 (Current)
mtx: Request Sense: Sense Key=Illegal Request
mtx: Request Sense: FileMark=no
mtx: Request Sense: EOM=no
mtx: Request Sense: ILI=no
mtx: Request Sense: Additional Sense Code = 53
mtx: Request Sense: Additional Sense Qualifier = 03
mtx: Request Sense: BPV=no
mtx: Request Sense: Error in CDB=no
mtx: Request Sense: SKSV=no
MOVE MEDIUM from Element Address 256 to 4114 Failed

Label command failed for Volume 000039L6.
Sending label command for Volume "000053L6" Slot 15 ...
3307 Issuing autochanger "unload slot 19, drive 0" command.
3995 Bad autochanger "unload slot 19, drive 0": ERR=Child exited with code 1
Results=Unloading drive 0 into Storage Element 19...mtx: Request Sense: Long 
Report=yes
mtx: Request Sense: Valid Residual=no
mtx: Request Sense: Error Code=70 (Current)
mtx: Request Sense: Sense Key=Illegal Request
mtx: Request Sense: FileMark=no
mtx: Request Sense: EOM=no
mtx: Request Sense: ILI=no
mtx: Request Sense: Additional Sense Code = 53
mtx: Request Sense: Additional Sense Qualifier = 03
mtx: Request Sense: BPV=no
mtx: Request Sense: Error in CDB=no
mtx: Request Sense: SKSV=no
MOVE MEDIUM from Element Address 256 to 4114 Failed

Label command failed for Volume 000053L6.
Sending label command for Volume "000023L6" Slot 18 ...
3307 Issuing autochanger "unload slot 19, drive 0" command.
3995 Bad autochanger "unload slot 19, drive 0": ERR=Child exited with code 1
Results=Unloading drive 0 into Storage Element 19...mtx: Request Sense: Long 
Report=yes
mtx: Request Sense: Valid Residual=no
mtx: Request Sense: Error Code=70 (Current)
mtx: Request Sense: Sense Key=Illegal Request
mtx: Request Sense: FileMark=no
mtx: Request Sense: EOM=no
mtx: Request Sense: ILI=no
mtx: Request Sense: Additional Sense Code = 53
mtx: Request Sense: Additional Sense Qualifier = 03
mtx: Request Sense: BPV=no
mtx: Request Sense: Error in CDB=no
mtx: Request Sense: SKSV=no
MOVE MEDIUM from Element Address 256 to 4114 Failed

Label command failed for Volume 000023L6.
Sending label command for Volume "000059L6" Slot 19 ...
3910 Unable to open device ""Drive1" (/dev/st0)": ERR=dev.c:513 Unable to open 
device "Drive1" (/dev/st0): ERR=No medium found

Label command failed for Volume 000059L6.

I also tried this test with Bacula off:

Changed nst2,3,6,7 to st0,1,2,3 Per lsscli output

Turned off Bacula & tested drives:

[root@bacula1 sbin]# lsscsi
[0:2:0:0]    disk    DELL     PERC H710P       3.13  /dev/sda 
[0:2:1:0]    disk    DELL     PERC H710P       3.13  /dev/sdb 
[1:0:0:0]    tape    IBM      ULT3580-HH6      D8E5  /dev/st0 
[1:0:1:0]    tape    IBM      ULT3580-HH6      D8E5  /dev/st1 
[1:0:1:1]    mediumx IBM      3573-TL          C.30  /dev/sch0
[6:0:0:0]    cd/dvd  TSSTcorp DVD-ROM SN-108FB D150  /dev/sr0 
[8:0:0:0]    tape    IBM      ULT3580-HH6      D8E5  /dev/st2 
[8:0:1:0]    tape    IBM      ULT3580-HH6      D8E5  /dev/st3 
[root@bacula1 sbin]# ./btape -c /etc/bacula/bacula-sd.conf /dev/st0
Tape block granularity is 1024 bytes.
btape: butil.c:290-0 Using device: "/dev/st0" for writing.
20-Sep 16:04 btape: Fatal Error at device.c:298 because:
dev open failed: dev.c:513 Unable to open device "Drive1" (/dev/st0): ERR=No 
medium found

20-Sep 16:04 btape JobId 0: Fatal error: butil.c:195 Cannot open "Drive1" 
(/dev/st0)
[root@bacula1 sbin]# ./btape -c /etc/bacula/bacula-sd.conf /dev/st1
Tape block granularity is 1024 bytes.
btape: butil.c:290-0 Using device: "/dev/st1" for writing.
btape: btape.c:477-0 open device "Drive2" (/dev/st1): OK
*test

=== Write, rewind, and re-read test ===

I'm going to write 10000 records and an EOF
then write 10000 records and an EOF, then rewind,
and re-read the data to verify that it is correct.

This is an *essential* feature ...

btape: btape.c:1157-0 Wrote 10000 blocks of 64412 bytes.
btape: btape.c:609-0 Wrote 1 EOF to "Drive2" (/dev/st1)
btape: btape.c:1173-0 Wrote 10000 blocks of 64412 bytes.
btape: btape.c:609-0 Wrote 1 EOF to "Drive2" (/dev/st1)
btape: btape.c:1215-0 Rewind OK.
10000 blocks re-read correctly.
Got EOF on tape.
10000 blocks re-read correctly.
=== Test Succeeded. End Write, rewind, and re-read test ===

btape: btape.c:1283-0 Block position test
btape: btape.c:1295-0 Rewind OK.
Reposition to file:block 0:4
Block 5 re-read correctly.
Reposition to file:block 0:200
Block 201 re-read correctly.
Reposition to file:block 0:9999
Block 10000 re-read correctly.
Reposition to file:block 1:0
Block 10001 re-read correctly.
Reposition to file:block 1:600
Block 10601 re-read correctly.
Reposition to file:block 1:9999
Block 20000 re-read correctly.
=== Test Succeeded. End Write, rewind, and re-read test ===



=== Append files test ===

This test is essential to Bacula.

I'm going to write one record  in file 0,
                   two records in file 1,
             and three records in file 2

btape: btape.c:579-0 Rewound "Drive2" (/dev/st1)
btape: btape.c:1914-0 Wrote one record of 64412 bytes.
btape: btape.c:1916-0 Wrote block to device.
btape: btape.c:609-0 Wrote 1 EOF to "Drive2" (/dev/st1)
btape: btape.c:1914-0 Wrote one record of 64412 bytes.
btape: btape.c:1916-0 Wrote block to device.
btape: btape.c:1914-0 Wrote one record of 64412 bytes.
btape: btape.c:1916-0 Wrote block to device.
btape: btape.c:854-0 Backspaced over EOF OK.
btape: btape.c:859-0 Backspace record OK.
btape: btape.c:877-0 
Block re-read correct. Test succeeded!
=== End Write, backup, and re-read test ===



=== Forward space files test ===

This test is essential to Bacula.

I'm going to write five files then test forward spacing

btape: btape.c:579-0 Rewound "Drive2" (/dev/st1)
btape: btape.c:1914-0 Wrote one record of 64412 bytes.
btape: btape.c:1916-0 Wrote block to device.
btape: btape.c:609-0 Wrote 1 EOF to "Drive2" (/dev/st1)
btape: btape.c:1914-0 Wrote one record of 64412 bytes.
btape: btape.c:1916-0 Wrote block to device.
btape: btape.c:1914-0 Wrote one record of 64412 bytes.
btape: btape.c:1916-0 Wrote block to device.
btape: btape.c:609-0 Wrote 1 EOF to "Drive2" (/dev/st1)
btape: btape.c:1914-0 Wrote one record of 64412 bytes.
btape: btape.c:1916-0 Wrote block to device.
btape: btape.c:1914-0 Wrote one record of 64412 bytes.
btape: btape.c:1916-0 Wrote block to device.
btape: btape.c:1914-0 Wrote one record of 64412 bytes.
btape: btape.c:1916-0 Wrote block to device.
btape: btape.c:609-0 Wrote 1 EOF to "Drive2" (/dev/st1)
btape: btape.c:1914-0 Wrote one record of 64412 bytes.
btape: btape.c:1916-0 Wrote block to device.
btape: btape.c:1914-0 Wrote one record of 64412 bytes.
btape: btape.c:1916-0 Wrote block to device.
btape: btape.c:609-0 Wrote 1 EOF to "Drive2" (/dev/st1)
btape: btape.c:1914-0 Wrote one record of 64412 bytes.
btape: btape.c:1916-0 Wrote block to device.
btape: btape.c:609-0 Wrote 1 EOF to "Drive2" (/dev/st1)
btape: btape.c:579-0 Rewound "Drive2" (/dev/st1)
btape: btape.c:1641-0 Now forward spacing 1 file.
We should be in file 1. I am at file 1. This is correct!
btape: btape.c:1653-0 Now forward spacing 2 files.
We should be in file 3. I am at file 3. This is correct!
btape: btape.c:579-0 Rewound "Drive2" (/dev/st1)
btape: btape.c:1666-0 Now forward spacing 4 files.
We should be in file 4. I am at file 4. This is correct!

btape: btape.c:1684-0 Now forward spacing 1 more file.
We should be in file 5. I am at file 5. This is correct!

=== End Forward space files test ===


Ah, I see you have an autochanger configured.
To test the autochanger you must have a blank tape
 that I can write on in Slot 1.

Do you wish to continue with the Autochanger test? (y/n): *y
btape: btape.c:2939-0 "y" is an invalid command
*yes    
btape: btape.c:2939-0 "yes" is an invalid command
*n
btape: btape.c:2939-0 "n" is an invalid command
*auto

Ah, I see you have an autochanger configured.
To test the autochanger you must have a blank tape
 that I can write on in Slot 1.

Do you wish to continue with the Autochanger test? (y/n): y


=== Autochanger test ===

3301 Issuing autochanger "loaded" command.
Nothing loaded in the drive. OK.
3303 Issuing autochanger "load 1 1" command.
3993 Bad autochanger command: /usr/libexec/bacula/mtx-changer /dev/sg4 load 1 
/dev/st1 1
3993 result="Loading media from Storage Element 1 into drive 1...Source Element 
Address 4096 is Empty
": ERR=Child exited with code 1
You must correct this error or the Autochanger will not work.

None of the other "drives" tested at all.  I assume I accidentally, somehow, 
had a tape in the 2nd drive.

[root@bacula1 sbin]# ./btape -c /etc/bacula/bacula-sd.conf /dev/st2
Tape block granularity is 1024 bytes.
btape: butil.c:290-0 Using device: "/dev/st2" for writing.
20-Sep 16:10 btape: Fatal Error at device.c:298 because:
dev open failed: dev.c:513 Unable to open device "Drive3" (/dev/st2): ERR=No 
medium found

20-Sep 16:10 btape JobId 0: Fatal error: butil.c:195 Cannot open "Drive3" 
(/dev/st2)
[root@bacula1 sbin]# ./btape -c /etc/bacula/bacula-sd.conf /dev/st3
Tape block granularity is 1024 bytes.
btape: butil.c:290-0 Using device: "/dev/st3" for writing.
20-Sep 16:10 btape: Fatal Error at device.c:298 because:
dev open failed: dev.c:513 Unable to open device "Drive4" (/dev/st3): ERR=No 
medium found

20-Sep 16:10 btape JobId 0: Fatal error: butil.c:195 Cannot open "Drive4" 
(/dev/st3)


Robert Threet
http://yesistilluseperl.blogspot.com/

Please note: message attached

From: Randall Svancara <rsvancara AT gmail DOT com>
To: RAT <robert3t AT netzero DOT net>
Subject: Re: [Bacula-users] autochanger woes
Date: Thu, 18 Sep 2014 15:44:58 -0700
____________________________________________________________
The End of the &#34;Made-In-China&#34; Era
The impossible &#40;but real&#41; technology that could make you impossibly 
rich.
http://thirdpartyoffers.netzero.net/TGL3231/541defb7b65ca6fb7082cst03duc
--- Begin Message ---
Subject: Re: [Bacula-users] autochanger woes
From: Randall Svancara <rsvancara AT gmail DOT com>
To: RAT <robert3t AT netzero DOT net>
Date: Thu, 18 Sep 2014 15:44:58 -0700
One think I had to do in the changer script, mtx-changer is eject the tape before I could move it.  However, bacula simply provides a wrapper script around the mtx and mt commands.

So you should try to use those commands to move tapes around in your library first and then make adjustments from there.  For me, it was simply adding 

mt -f $device eject 

in the unload routine of the mtx-changer script because the qualstar tape library would not implicitly eject the tape before unloading operation.  Other tape libraries I have worked with will.



On Thu, Sep 18, 2014 at 2:43 PM, RAT <robert3t AT netzero DOT net> wrote:
Still having issues (I took 10 days off for another project).

I've tried a lot of things:

I added bacula to the tape group, chown bacula:tape /dev/nst* & /dev/sg*, I've ran the SELinux recommend:

[root@bacula1 sbin]# grep bacula-sd /var/log/audit/audit.log | audit2allow -M mypol
******************** IMPORTANT ***********************
To make this policy package active, execute:
semodule -i mypol.pp

I set SELinux to permissive, restarted bacula many times...  No dice.

Config looks like this (but I've tried using sg devices for Drive-*)

Autochanger {
  Name = DL4000
  Device = Drive1
  Device = Drive2
  Device = Drive3
  Device = Drive4
  Changer Command = "/usr/libexec/bacula/mtx-changer %c %o %S %a %d"
  Changer Device = /dev/sg4
}

Device {
  Name = Drive1                      #
  Drive Index = 0
  Media Type = LTO-6-Drive
  Archive Device = /dev/nst2
  AutomaticMount = yes;               # when device opened, read it
  AlwaysOpen = yes;
  RemovableMedia = yes;
  RandomAccess = no;
  AutoChanger = yes
#  #
#  # Enable the Alert command only if you have the mtx package loaded
#  # Note, apparently on some systems, tapeinfo resets the SCSI controller
#  #  thus if you turn this on, make sure it does not reset your SCSI
#  #  controller.  I have never had any problems, and smartctl does
#  #  not seem to cause such problems.
#  #
#  Alert Command = "sh -c 'tapeinfo -f %c |grep TapeAlert|cat'"
#  If you have smartctl, enable this, it has more info than tapeinfo
  Alert Command = "sh -c 'smartctl -H -l error %c'"
}

My errors:

[root@bacula1 sbin]# ./bconsole
Connecting to Director localhost:9101
1000 OK: bacula-dir Version: 5.2.13 (19 February 2013)
Enter a period to cancel a command.
*label barcodes
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
The defined Storage resources are:
     1: File
     2: DL4000
Select Storage resource (1-2): 2
Enter autochanger drive[0]: 4
Connecting to Storage daemon DL4000 at bacula1.usi.edu:9103 ...
^C
[root@bacula1 sbin]# ./bconsole
Connecting to Director localhost:9101
1000 OK: bacula-dir Version: 5.2.13 (19 February 2013)
Enter a period to cancel a command.
*label barcodes
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
The defined Storage resources are:
     1: File
     2: DL4000
Select Storage resource (1-2): 2
Connecting to Storage daemon DL4000 at bacula1.usi.edu:9103 ...
Enter autochanger drive[0]: 4
Connecting to Storage daemon DL4000 at bacula1.usi.edu:9103 ...
3306 Issuing autochanger "slots" command.
Device "Drive1" has 48 slots.
Connecting to Storage daemon DL4000 at bacula1.usi.edu:9103 ...
3306 Issuing autochanger "list" command.
The following Volumes will be labeled:
Slot  Volume
==============
  10  000047L6
  11  000038L6
  14  000039L6
  15  000053L6
  18  000023L6
  19  000059L6
Do you want to label these Volumes? (yes|no): yes
Defined Pools:
     1: Default
     2: File
     3: Scratch
Select the Pool (1-3): 3
Connecting to Storage daemon DL4000 at bacula1.usi.edu:9103 ...
Sending label command for Volume "000047L6" Slot 10 ...
3307 Issuing autochanger "unload slot 14, drive 0" command.
3304 Issuing autochanger "load slot 10, drive 0" command.
3992 Bad autochanger "load slot 10, drive 0": ERR=Child died from signal 15: Termination.
Results=Program killed by Bacula (timeout)

Label command failed for Volume 000047L6.
Sending label command for Volume "000038L6" Slot 11 ...
3307 Issuing autochanger "unload slot 10, drive 0" command.
3304 Issuing autochanger "load slot 11, drive 0" command.
3992 Bad autochanger "load slot 11, drive 0": ERR=Child died from signal 15: Termination.
Results=Program killed by Bacula (timeout)

Label command failed for Volume 000038L6.
Sending label command for Volume "000039L6" Slot 14 ...
3307 Issuing autochanger "unload slot 11, drive 0" command.
3304 Issuing autochanger "load slot 14, drive 0" command.
3992 Bad autochanger "load slot 14, drive 0": ERR=Child died from signal 15: Termination.
Results=Program killed by Bacula (timeout)

Label command failed for Volume 000039L6.
Sending label command for Volume "000053L6" Slot 15 ...
3307 Issuing autochanger "unload slot 14, drive 0" command.
3304 Issuing autochanger "load slot 15, drive 0" command.
3992 Bad autochanger "load slot 15, drive 0": ERR=Child died from signal 15: Termination.
Results=Program killed by Bacula (timeout)

Label command failed for Volume 000053L6.
Sending label command for Volume "000023L6" Slot 18 ...
3307 Issuing autochanger "unload slot 15, drive 0" command.
3304 Issuing autochanger "load slot 18, drive 0" command.
3992 Bad autochanger "load slot 18, drive 0": ERR=Child died from signal 15: Termination.
Results=Program killed by Bacula (timeout)

Label command failed for Volume 000023L6.
Sending label command for Volume "000059L6" Slot 19 ...
3307 Issuing autochanger "unload slot 18, drive 0" command.
3304 Issuing autochanger "load slot 19, drive 0" command.
3992 Bad autochanger "load slot 19, drive 0": ERR=Child died from signal 15: Termination.
Results=Program killed by Bacula (timeout)

Label command failed for Volume 000059L6.

*

Robert Threet
http://yesistilluseperl.blogspot.com/

____________________________________________________________
NetZero now offers 4G mobile broadband. Sign up now.
http://www.netzero.net/?refcd=NZINTISP0512T4GOUT1

------------------------------------------------------------------------------
Slashdot TV.  Video for Nerds.  Stuff that Matters.
http://pubads.g.doubleclick.net/gampad/clk?id=160591471&iu=/4140/ostg.clktrk
_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users



--
Randall Svancara


--- End Message ---
------------------------------------------------------------------------------
Slashdot TV.  Video for Nerds.  Stuff that Matters.
http://pubads.g.doubleclick.net/gampad/clk?id=160591471&iu=/4140/ostg.clktrk
_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users