Hi All,

"A TAPE ERROR OCCURRED: [the requested volume is in use (drive 0)]." is an issue that's been plaguing me for about a year, so I'd really appreciate any advice you can give.

Backups work fine every other day, when they don't work, they give the 'requested volume is in use' error.

Dec 26
These dumps were to tape tape-04.
The next 2 tapes Amanda expects to use are: tape-05, tape-06.
The next 2 new tapes already labelled are: tape-01, tape-11

Dec 29
*** A TAPE ERROR OCCURRED: [the requested volume is in use (drive 0)].
There are 105466M of dumps left in the holding disk.
They will be flushed on the next run.
The next 2 tapes Amanda expects to use are: tape-05, tape-06.
The next 2 new tapes already labelled are: tape-01, tape-11

Dec 31
These dumps were to tape tape-05.
The next 2 tapes Amanda expects to use are: tape-06, tape-07.
The next 2 new tapes already labelled are: tape-01, tape-11

Jan 2
*** A TAPE ERROR OCCURRED: [the requested volume is in use (drive 0)].
There are 98378M of dumps left in the holding disk.
They will be flushed on the next run.
The next 2 tapes Amanda expects to use are: tape-06, tape-07.
The next 2 new tapes already labelled are: tape-01, tape-11

Jan 5
These dumps were to tape tape-06.
The next 2 tapes Amanda expects to use are: tape-07, tape-08.
The next 2 new tapes already labelled are: tape-01, tape-11

Jan 7
*** A TAPE ERROR OCCURRED: [the requested volume is in use (drive 0)].
There are 105178M of dumps left in the holding disk.
They will be flushed on the next run.
The next 2 tapes Amanda expects to use are: tape-07, tape-08.
The next 2 new tapes already labelled are: tape-01, tape-11

Jan 9
These dumps were to tape tape-07.
The next 2 tapes Amanda expects to use are: tape-08, tape-13.
The next 2 new tapes already labelled are: tape-01, tape-11

Jan 12
*** A TAPE ERROR OCCURRED: [the requested volume is in use (drive 0)].
There are 104287M of dumps left in the holding disk.
They will be flushed on the next run.
The next 2 tapes Amanda expects to use are: tape-08, tape-13.
The next 2 new tapes already labelled are: tape-01, tape-11

sh-3.2$ /usr/sbin/amtape pool show
amtape: scanning all 15 slots in changer:
slot 8: date 20151203000101 label tape-08
slot 9: date 20151217141213 label tape-09
...

[root@backup]# /usr/sbin/mtx -f /dev/sg3 status
Storage Changer /dev/sg3:1 Drives, 16 Slots ( 0 Import/Export )
Data Transfer Element 0:Full (Storage Element 8 Loaded):VolumeTag = 000010L5
Storage Element 1:Full :VolumeTag=000003L5
Storage Element 2:Full :VolumeTag=000005L5
Storage Element 3:Full :VolumeTag=000008L5
Storage Element 4:Full :VolumeTag=000004L5
Storage Element 5:Full :VolumeTag=000009L5
Storage Element 6:Full :VolumeTag=000006L5
Storage Element 7:Full :VolumeTag=000007L5
Storage Element 8:Empty
Storage Element 9:Full :VolumeTag=000011L5
Storage Element 10:Full :VolumeTag=000012L5
Storage Element 11:Full :VolumeTag=000013L5
Storage Element 12:Full :VolumeTag=000014L5
Storage Element 13:Full :VolumeTag=000015L5
Storage Element 14:Full :VolumeTag=000002L5
Storage Element 15:Full :VolumeTag=000001L5
Storage Element 16:Full :VolumeTag=CLNU00L1


From my amanda.conf, I've tried adding a lot of delays and stuff hoping that would be of some help
define changer robot {
tpchanger "chg-robot:/dev/sg3"
property "mtx" "/usr/sbin/mtx"
property "tape-device" "0=tape:/dev/st0"
property "eject-before-unload" "no"
property "use-slots" "1-15"
property "load-poll" "15 s poll 15 s until 360 s"
property "unload-delay" "15 s"
property "status-interval" "65 s"
}
tpchanger "robot"


Here's the taper log from Jan 12:
[root@backup]# cat taper.20160112000102.debug
Tue Jan 12 00:01:02 2016: taper: pid 32760 ruid 10688 euid 10688 version 3.2.0: start at Tue Jan 12 00:01:02 2016
Tue Jan 12 00:01:02 2016: taper: pid 32760 ruid 10688 euid 10688 version 3.2.0: rename at Tue Jan 12 00:01:02 2016
Tue Jan 12 00:01:02 2016: taper: chg-robot: using statefile '/var/amanda/chg-robot-dev-sg3'
Tue Jan 12 00:01:02 2016: taper: Amanda::Taper::Scan::traditional stage 1: search for oldest reusable volume
Tue Jan 12 00:01:02 2016: taper: Amanda::Taper::Scan::traditional oldest reusable volume is 'tape-08'
Tue Jan 12 00:01:02 2016: taper: Amanda::Taper::Scan::traditional stage 1: searching oldest reusable volume 'tape-08'
Tue Jan 12 00:03:20 2016: taper: robot: too early for another 'status' invocation
Tue Jan 12 00:03:20 2016: taper: robot: loading label 'tape-08'
Tue Jan 12 00:03:20 2016: taper: robot: requested volume is already in drive 0
Tue Jan 12 00:03:20 2016: taper: new Amanda::Changer::Error: type='failed', reason='volinuse', message='the requested volume is in use (drive 0)'
Tue Jan 12 00:03:20 2016: taper: Amanda::Taper::Scan::traditional result: error=the requested volume is in use (drive 0)
Tue Jan 12 00:51:53 2016: taper: pid 32760 finish time Tue Jan 12 00:51:53 2016