Hi,
I think I stumbled upon a problem with multiple drives and concurrent jobs.
I read the changelog for 2.2.8 and there were some changes, but apparently
the following was not fixed.
- Debian 4.0 i386 / Bacula 2.2.8 / MySQL
- an autochanger with 2 drives:
Drive-1 = /dev/nst0 = mtx-changer "drive 0"
Drive-2 = /dev/nst1 = mtx-changer "drive 1"
- tapes in question are in the same pool
There seems to be a race condition of some sort for tapes, which ends in
bacula being unable to select an unused tape:
07:05 b1-dir JobId 255: Start Backup JobId 255,
Job=NameRemoved.2008-02-03_07.05.42
07:05 b1-sd JobId 255: 3307 Issuing autochanger "unload slot 4, drive 0"
command.
07:05 b1-dir JobId 256: Start Backup JobId 256,
Job=NameRemoved2.2008-02-03_07.05.43
07:06 b1-dir JobId 255: Using Device "Drive-1"
07:06 b1-dir JobId 256: Using Device "Drive-2"
07:06 b1-sd JobId 255: 3301 Issuing autochanger "loaded? drive 0" command.
07:07 b1-sd JobId 255: 3302 Autochanger "loaded? drive 0", result: nothing
loaded.
07:07 b1-sd JobId 256: 3307 Issuing autochanger "unload slot 1, drive 1"
command.
07:08 b1-sd JobId 256: 3304 Issuing autochanger "load slot 4, drive 1" command.
07:10 b1-sd JobId 256: 3305 Autochanger "load slot 4, drive 1", status is OK.
07:10 b1-sd JobId 256: 3301 Issuing autochanger "loaded? drive 1" command.
07:10 b1-sd JobId 255: Warning: Volume "000041" is in use by device "Drive-2"
(/dev/nst1)
07:10 b1-sd JobId 256: 3302 Autochanger "loaded? drive 1", result is Slot 4.
07:10 b1-sd JobId 255: 3301 Issuing autochanger "loaded? drive 0" command.
07:10 b1-sd JobId 256: Volume "000044" previously written, moving to end of
data.
07:11 b1-sd JobId 255: 3302 Autochanger "loaded? drive 0", result: nothing
loaded.
07:11 b1-sd JobId 255: 3301 Issuing autochanger "loaded? drive 0" command.
07:11 b1-sd JobId 256: Ready to append to end of Volume "000044" at file=79.
07:11 b1-sd JobId 256: Job write elapsed time = 00:00:01, Transfer rate = 641.0
K bytes/second
07:11 b1-sd JobId 255: 3302 Autochanger "loaded? drive 0", result: nothing
loaded.
07:11 b1-sd JobId 255: 3301 Issuing autochanger "loaded? drive 0" command.
07:11 b1-dir JobId 256: Bacula b1-dir 2.2.8 (26Jan08): 03-Feb-2008 07:11:44
[...]
JobId: 256
Job: NameRemoved2.2008-02-03_07.05.43
[...]
Scheduled time: 03-Feb-2008 07:05:00
Start time: 03-Feb-2008 07:06:55
End time: 03-Feb-2008 07:11:44
[...]
Volume name(s): 000044
Volume Session Id: 214
Volume Session Time: 1201689983
[...]
FD termination status: OK
SD termination status: OK
Termination: Backup OK
07:11 b1-dir JobId 257: Start Backup JobId 257,
Job=NameRemoved3.2008-02-03_07.05.44
07:11 b1-dir JobId 257: Using Device "Drive-2"
07:12 b1-sd JobId 255: 3302 Autochanger "loaded? drive 0", result: nothing
loaded.
07:12 b1-sd JobId 257: 3307 Issuing autochanger "unload slot 4, drive 1"
command.
07:13 b1-sd JobId 257: 3304 Issuing autochanger "load slot 1, drive 1" command.
07:14 b1-sd JobId 257: 3305 Autochanger "load slot 1, drive 1", status is OK.
07:14 b1-sd JobId 257: 3301 Issuing autochanger "loaded? drive 1" command.
07:15 b1-sd JobId 255: Warning: Volume "000044" is in use by device "Drive-2"
(/dev/nst1)
07:15 b1-sd JobId 255: Please mount Volume "000044" or label a new one for:
Job: NameRemoved.2008-02-03_07.05.42
Storage: "Drive-1" (/dev/nst0)
Pool: DailyPoolA
Media type: LTO3
07:15 b1-sd JobId 257: 3302 Autochanger "loaded? drive 1", result is Slot 1.
07:15 b1-sd JobId 257: Volume "000041" previously written, moving to end of
data.
--
Leszek "Tygrys" Urbanski, SCSA, SCNA
"UN and OAS, they have their place, I guess,
But first, send the Marines!" -- Tom Lehrer
http://cygnus.moo.pl/ -- Cygnus High Altitude Balloon
-------------------------------------------------------------------------
This SF.net email is sponsored by: Microsoft
Defy all challenges. Microsoft(R) Visual Studio 2008.
http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
