Autchanger Script fails

[tilmang...@googlemail.com]

Dear all,

I have ADIC DDS Tape library which no longer cleaner removes the tape from the library. When I issue an umount command, I get an error message. With an older version of bareos, it used to work. Any advice on how I can debug and fix this?

> umount storage=TapeStorage1
Automatically selected Catalog: QtronCatalog
Using Catalog "QtronCatalog"
Connecting to Storage daemon TapeStorage1 at qtron.fritz.box:9103 ...
3307 Issuing autochanger "unload slot 8, drive 0" command.
3995 Bad autochanger "unload slot 8, drive 0": ERR=Child died from signal 15: Termination
Results=Program killed by BAREOS (timeout)

3002 Device ""TapeDrive1" (/dev/nst0)" unmounted

Thanks

Tilman

[spadaj...@gmail.com]

Bareos uses a script called mtx-changer (probably located in /usr/lib/bareos/scripts) which in turn calls mtx.

You can check mtx-changer log (/var/log/bareos/mtx.log) and/or try to manually run mtx manually to see if mtx itself runs ok.

[Andreas Rogge]

Hi Tilman,

are you using Bareos 20 and have data-spooling enabled on the tape drive?
You may have hit a bug that will be fixed in the upcoming 20.0.1, then.

Best Regards,
Andreas

--
Andreas Rogge andrea...@bareos.com
Bareos GmbH & Co. KG Phone: +49 221-630693-86
http://www.bareos.com

Sitz der Gesellschaft: Köln | Amtsgericht Köln: HRA 29646
Komplementär: Bareos Verwaltungs-GmbH
Geschäftsführer: S. Dühr, M. Außendorf, J. Steffens, Philipp Storz

[tilmang...@googlemail.com]

Dear spadaj

I forgot to mention that mtx runs OK. It lives in /usr/sbin/mtx, and the log files are in /var/bareos/working/. The logfiles are however empty.

mtx-changer script lives in /etc/bareos

Dear Andreas

I am using bareos 19.2.6 (self compiled).  I do not think that the drive has a data spooling option as it is a relatively old HP C5683A

Thanks

Tilman

[Spadajspadaj]

If mtx runs fine. I'd try to run the mtx-changer script with bash "debug mode" (bash -x mtx-changer...) and see what is it that the mtx hangs and times out on.

--
You received this message because you are subscribed to the Google Groups "bareos-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to bareos-users...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/bareos-users/ffeeeab8-59bb-4ca5-a051-10f9a9f0a207n%40googlegroups.com.

[tilmang...@googlemail.com]

1) I gave it a try. Using the  mtx-changer script directly (without using bconsole after booting up) seems to work.  I mounted a tape via the script and then umounted it:

./mtx-changer  /dev/changer1 unload  8 /dev/nst0 0

+ test ! -r /etc/bareos//mtx-changer.conf
+ . /etc/bareos//mtx-changer.conf
+ offline=0
+ offline_sleep=0
+ load_sleep=0
+ inventory=0
+ vxa_packetloader=0
+ debug_log=0
+ uname
+ OS=Linux
+ ready=ONLINE
+ test -f /etc/debian_version
+ grep mt-st
+ mt --version
+ test 0 -eq 1
+ MTX=/usr/sbin/mtx
+ test ! -x /usr/sbin/mtx
+ MT=/bin/mt
+ test ! -x /bin/mt
+ dbgfile=/var/bareos/logs/mtx.log
+ test 0 -ne 0
+ check_parm_count 5 5
+ pCount=5
+ pCountNeed=5
+ test 5 -lt 5
+ ctl=/dev/changer1
+ cmd=unload
+ slot=8
+ device=/dev/nst0
+ drive=0
+ debug Parms: /dev/changer1 unload 8 /dev/nst0 0
+ test -f /var/bareos/logs/mtx.log
+ date +%Y%m%d-%H:%M:%S
+ echo 20210307-18:32:02 Parms: /dev/changer1 unload 8 /dev/nst0 0
+ debug Doing mtx -f /dev/changer1 unload 8 0
+ test -f /var/bareos/logs/mtx.log
+ date +%Y%m%d-%H:%M:%S
+ echo 20210307-18:32:02 Doing mtx -f /dev/changer1 unload 8 0
+ test 0 -eq 1
+ test 0 -ne 0
+ make_err_file
+ mktemp /var/bareos/working/mtx.err.XXXXXXXXXX
+ ERRFILE=/var/bareos/working/mtx.err.pJijcI8Tu2
+ test x/var/bareos/working/mtx.err.pJijcI8Tu2 = x
+ /bin/mt -f /dev/nst0 eject
+ sleep 10
+ /usr/sbin/mtx -f /dev/changer1 unload 8 0
Unloading drive 0 into Storage Element 8...done
+ rtn=0
+ cat /var/bareos/working/mtx.err.pJijcI8Tu2
+ rm -f /var/bareos/working/mtx.err.pJijcI8Tu2
+ exit 0

2) mount and unmount a tape and thereby loading and unloading a tape from a freshly booted machine via bconsole works.

3) mount a tape, running a backup job and then trying to umount/unloading the tape does not work and leads to the error message "ERR=Child died from signal 15: ". Unload the tape with mtx_changer works however:  The debug mode of the mtx-changer script shows an error message  "/dev/nst0: No medium found" which is consistent: The previously failing umount command issued an eject command.  The tape is  ejected from the drive but not unloaded into the magazine. When subsequently running the mtx_changer command,the medium is indeed no longer in the drive -- but also not yet in its slot

*status storage=TapeStorage1
Connecting to Storage daemon TapeStorage

Version: 19.2.6 (11 February 2020) Linux-4.15.0-112-generic ubuntu Ubuntu 18.04.4 LTS
Daemon started 07-Mär021 18:55. Jobs: run=2, running=0, self-compiled binary
 Sizes: boffset_t=8 size_t=4 int32_t=4 int64_t=8 bwlimit=0kB/s

Running Jobs:
No Jobs running.
====

Jobs waiting to reserve a drive:
====

Terminated Jobs:
 JobId  Level    Files      Bytes   Status   Finished        Name
===================================================================
 ..
  2730  Full     42,072    16.36 G  OK       07-Mär021 21:25 BackupTgvs2ToTape
====

Device status:
Autochanger "AutoChanger1" with devices:
   "TapeDrive1" (/dev/nst0)

Device "TapeDrive1" (/dev/nst0) is mounted with:
    Volume:      Tgvs2Tape-14
    Pool:        Tgvs2-Tape
    Media type:  DDS-4
    Slot 9 is loaded in drive 0.
    Total Bytes=16,380,499,968 Blocks=253,913 Bytes/block=64,512
    Positioned at File=17 Block=0
==
====

Used Volume status:
Tgvs2Tape-14 on device "TapeDrive1" (/dev/nst0)
    Reader=0 writers=0 reserves=0 volinuse=0
====

====

*umount storage=TapeStorage1

Connecting to Storage daemon TapeStorage1 ...
3307 Issuing autochanger "unload slot 9, drive 0" command.
3995 Bad autochanger "unload slot 9, drive 0": ERR=Child died from signal 15: Termination

Results=Program killed by BAREOS (timeout)

3002 Device ""TapeDrive1" (/dev/nst0)" unmounted.

#> mtx -f /dev/changer1 status
  Storage Changer /dev/changer1:1 Drives, 12 Slots ( 0 Import/Export )
Data Transfer Element 0:Full (Storage Element 9 Loaded)
      Storage Element 1:Full
      Storage Element 2:Full
      Storage Element 3:Full
      Storage Element 4:Full
      Storage Element 5:Full
      Storage Element 6:Full
      Storage Element 7:Full
      Storage Element 8:Full
      Storage Element 9:Empty
      Storage Element 10:Full
      Storage Element 11:Full
      Storage Element 12:Full

#>  ./mtx-changer  /dev/changer1 unload  9 /dev/nst0 0
+ test ! -r /etc/bareos//mtx-changer.conf
+ . /etc/bareos//mtx-changer.conf
+ offline=0
+ offline_sleep=0
+ load_sleep=0
+ inventory=0
+ vxa_packetloader=0
+ debug_log=0
+ uname
+ OS=Linux
+ ready=ONLINE
+ test -f /etc/debian_version
+ grep mt-st
+ mt --version
+ test 0 -eq 1
+ MTX=/usr/sbin/mtx
+ test ! -x /usr/sbin/mtx
+ MT=/bin/mt
+ test ! -x /bin/mt
+ dbgfile=/var/bareos/logs/mtx.log
+ test 0 -ne 0
+ check_parm_count 5 5
+ pCount=5
+ pCountNeed=5
+ test 5 -lt 5
+ ctl=/dev/changer1
+ cmd=unload
+ slot=9
+ device=/dev/nst0
+ drive=0
+ debug Parms: /dev/changer1 unload 9 /dev/nst0 0
+ test -f /var/bareos/logs/mtx.log
+ date +%Y%m%d-%H:%M:%S
+ echo 20210307-21:59:39 Parms: /dev/changer1 unload 9 /dev/nst0 0
+ debug Doing mtx -f /dev/changer1 unload 9 0
+ test -f /var/bareos/logs/mtx.log
+ date +%Y%m%d-%H:%M:%S
+ echo 20210307-21:59:39 Doing mtx -f /dev/changer1 unload 9 0
+ test 0 -eq 1
+ test 0 -ne 0
+ make_err_file
+ mktemp /var/bareos/working/mtx.err.XXXXXXXXXX
+ ERRFILE=/var/bareos/working/mtx.err.Lfbq8DDkK5
+ test x/var/bareos/working/mtx.err.Lfbq8DDkK5 = x
+ /bin/mt -f /dev/nst0 eject
+ sleep 10
+ /usr/sbin/mtx -f /dev/changer1 unload 9 0
Unloading drive 0 into Storage Element 9...done
+ rtn=0
+ cat /var/bareos/working/mtx.err.Lfbq8DDkK5
/dev/nst0: No medium found
+ rm -f /var/bareos/working/mtx.err.Lfbq8DDkK5
+ exit 0

# mtx -f /dev/changer1 status
  Storage Changer /dev/changer1:1 Drives, 12 Slots ( 0 Import/Export )
Data Transfer Element 0:Empty
      Storage Element 1:Full
      Storage Element 2:Full
      Storage Element 3:Full
      Storage Element 4:Full
      Storage Element 5:Full
      Storage Element 6:Full
      Storage Element 7:Full
      Storage Element 8:Full
      Storage Element 9:Full
      Storage Element 10:Full
      Storage Element 11:Full
      Storage Element 12:Full

Thanks

Tilman

[Spadajspadaj]

+ offline=0
+ offline_sleep=0
+ load_sleep=0

Have you tried playing with those values?

It seems a good place to start.

By default they're defined in /etc/bareos/mtx-changer.conf

To view this discussion on the web visit https://groups.google.com/d/msgid/bareos-users/b40be165-230c-4247-a259-95888a5ffc7en%40googlegroups.com.

[tilmang...@googlemail.com]

I have set offline =1 and ran a backup job. I could not mount the drive from bconsole (Fatal error: 3992 Bad autochanger "load slot 12, drive 0": ERR=Child exited with code 1),

so I  did this manually with mtx.

Then I ran the backup job that failed

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

1-Mär 19:15 JobId 2741: Connected File Daemon
21-Mär 19:15JobId 2741: 3304 Issuing autochanger "load slot 12, drive 0" command.
21-Mär 19:15 JobId 2741: Fatal error: 3992 Bad autochanger "load slot 12, drive 0": ERR=Child exited with code 1.
Results=+ test ! -r /etc/bareos//mtx-changer.conf
+ . /etc/bareos//mtx-changer.conf
+ offline=1
+ offline_sleep=2

+ load_sleep=0
+ inventory=0
+ vxa_packetloader=0
+ debug_log=0
+ uname
+ OS=Linux
+ ready=ONLINE
+ test -f /etc/debian_version
+ grep mt-st
+ mt --version
+ test 0 -eq 1
+ MTX=/usr/sbin/mtx
+ test ! -x /usr/sbin/mtx
+ MT=/bin/mt
+ test ! -x /bin/mt
+ dbgfile=/var/bareos/logs/mtx.log
+ test 0 -ne 0
+ check_parm_count 5 5
+ pCount=5
+ pCountNeed=5
+ test 5 -lt 5
+ ctl=/dev/changer1

+ cmd=load
+ slot=12
+ device=/dev/nst0
+ drive=0
+ debug Parms: /dev/changer1 load 12 /dev/nst0 0

+ test -f /var/bareos/logs/mtx.log
+ date +%Y%m%d-%H:%M:%S

+ echo 20210321-19:15:30 Parms: /dev/changer1 load 12 /dev/nst0 0
+ debug Doing mtx -f /dev/changer1 load 12 0

+ test -f /var/bareos/logs/mtx.log
+ date +%Y%m%d-%H:%M:%S

+ echo 20210321-19:15:30 Doing mtx -f /dev/changer1 load 12 0

+ make_err_file
+ mktemp /var/bareos/working/mtx.err.XXXXXXXXXX

+ ERRFILE=/var/bareos/working/mtx.err.qafC0jyzNu
+ test x/var/bareos/working/mtx.err.qafC0jyzNu = x
+ /usr/sbin/mtx -f /dev/changer1 load 12 0
+ rtn=1

+ test 0 -ne 0

+ wait_for_drive /dev/nst0
+ i=0
+ [ 0 -le 300 ]
+ + grep ONLINE
mt -f /dev/nst0 status
+ break
+ cat /var/bareos/working/mtx.err.qafC0jyzNu
Drive 0 Full (Storage Element 12 loaded)
+ rm -f /var/bareos/working/mtx.err.qafC0jyzNu
+ exit 1

21-Mär 19:15 JobId 2741: Fatal error: filed/dir_cmd.cc:2695 Bad response to Append Data command. Wanted 3000 OK data
, got 3903 Error append data

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

The subsequent status storage command reveals an anomaly, as it claims that slot 65535 is loaded.

*status storage=TapeStorage1
Connecting to Storage daemon TapeStorage1

 Version: 19.2.7 (16 April 2020) Linux-3.10.0-1062.18.1.el7.x86_64 ubuntu Ubuntu 16.04.6 LTS
Daemon started 21-Mär021 17:18. Jobs: run=5, running=0, bareos.org build binary

 Sizes: boffset_t=8 size_t=4 int32_t=4 int64_t=8 bwlimit=0kB/s

....

Device status:
Autochanger "AutoChanger1" with devices:
   "TapeDrive1" (/dev/nst0)

Device "TapeDrive1" (/dev/nst0) is not open.
    Slot 65535 was last loaded in drive 0.

==
====

Used Volume status:

Tgvs2Tape-16 on device "TapeDrive1" (/dev/nst0)
    Reader=0 writers=0 reserves=0 volinuse=1
====

It would be helpful to understand how the mtx-changer script is interacting with bareos.

I think the issues are all software related rather than connected with th e hardware. And I am approaching the point where I feel that setting up the machine from scratch is easier than debugging it.

Any advice on how to continue would be appreciated....

Thanks

Tilman

[tilmang...@googlemail.com]

Dear all

I compiled and installed  a new version of bareos.(V20.0.1). The problem of unloading the tape persists. I traced it down offline command in the mtx-changer script, i.e. the command

mt  -f /dev/nst0 offline

hangs and eventually bareos kills the script.

If I run mt from command line, mt will eventually time out and return an error message "/dev/nst0: No medium found". The tape is however loaded.

The issue seems to be related to the tape drive or the scsi driver. The tape drive is a  C5683A from HP.

Removing the offline command also does not work as bareos then complains about the drive still being online.

Did anybody experience and solve this  before?

Thanks

Tilman