Hello:
Weird bacula/autochanger behavior. Perhaps a bug or I'm not
understanding something correctly. Scenario is thus:
1) Start with fresh load of tapes. Autochanger has barcode reader.
Label some tapes:
*label slots=1-3 barcodes
Automatically selected Storage: Autochanger
Connecting to Storage daemon Autochanger at hamlet:9103 ...
Connecting to Storage daemon Autochanger at hamlet:9103 ...
3306 Issuing autochanger "slots" command.
Device "Autochanger" has 12 slots.
Connecting to Storage daemon Autochanger at hamlet:9103 ...
3306 Issuing autochanger "list" command.
The following Volumes will be labeled:
Slot Volume
==============
1 NNE440L2
2 NNE441L2
3 NNE442L2
Do you want to continue? (yes|no): yes
Defined Pools:
1: Default
2: TestPool
Select the Pool (1-2): 1
Connecting to Storage daemon Autochanger at hamlet:9103 ...
Sending label command for Volume "NNE440L2" Slot 1 ...
3301 Issuing autochanger "loaded? drive 0" command.
3302 Autochanger "loaded? drive 0", result: nothing loaded.
3304 Issuing autochanger "load slot 1, drive 0" command.
3305 Autochanger "load slot 1, drive 0", status is OK.
3301 Issuing autochanger "loaded? drive 0" command.
3302 Autochanger "loaded? drive 0", result is Slot 1.
block.c:993 Read error on fd=5 at file:blk 0:0 on device
"Drive-1" (/dev/nsa0). ERR=Operation not permitted. 3000 OK label.
VolBytes=64512 DVD=0 Volume="NNE440L2" Device="Drive-1" (/dev/nsa0)
Catalog record for Volume "NNE440L2", Slot 1 successfully created.
Sending label command for Volume "NNE441L2" Slot 2 ... 3301 Issuing
autochanger "loaded? drive 0" command. 3302 Autochanger "loaded? drive
0", result is Slot 1. 3307 Issuing autochanger "unload slot 1, drive 0"
command. 3304 Issuing autochanger "load slot 2, drive 0" command.
3305 Autochanger "load slot 2, drive 0", status is OK.
3301 Issuing autochanger "loaded? drive 0" command.
3302 Autochanger "loaded? drive 0", result is Slot 2.
block.c:993 Read error on fd=5 at file:blk 0:0 on device
"Drive-1" (/dev/nsa0). ERR=Operation not permitted. 3000 OK label.
VolBytes=64512 DVD=0 Volume="NNE441L2" Device="Drive-1" (/dev/nsa0)
Catalog record for Volume "NNE441L2", Slot 2 successfully created.
Sending label command for Volume "NNE442L2" Slot 3 ... 3301 Issuing
autochanger "loaded? drive 0" command. 3302 Autochanger "loaded? drive
0", result is Slot 2. 3307 Issuing autochanger "unload slot 2, drive 0"
command. 3304 Issuing autochanger "load slot 3, drive 0" command.
3305 Autochanger "load slot 3, drive 0", status is OK.
3301 Issuing autochanger "loaded? drive 0" command.
3302 Autochanger "loaded? drive 0", result is Slot 3.
block.c:993 Read error on fd=5 at file:blk 0:0 on device
"Drive-1" (/dev/nsa0). ERR=Operation not permitted. 3000 OK label.
VolBytes=64512 DVD=0 Volume="NNE442L2" Device="Drive-1" (/dev/nsa0)
Catalog record for Volume "NNE442L2", Slot 3 successfully created.
2) List Volumes:
*list volumes
Pool: Default
+---------+------------+-----------+---------+----------+----------+--------------+---------+------+-----------+-----------+---------------------+
| MediaId | VolumeName | VolStatus | Enabled | VolBytes | VolFiles |
VolRetention | Recycle | Slot | InChanger | MediaType | LastWritten |
+---------+------------+-----------+---------+----------+----------+--------------+---------+------+-----------+-----------+---------------------+
| 1 | NNE440L2 | Append | 1 | 64,512 | 0 |
31,536,000 | 1 | 1 | 1 | LTO-2 | 0000-00-00 00:00:00 |
| 2 | NNE441L2 | Append | 1 | 64,512 | 0 |
31,536,000 | 1 | 2 | 1 | LTO-2 | 0000-00-00 00:00:00 |
| 3 | NNE442L2 | Append | 1 | 64,512 | 0 |
31,536,000 | 1 | 3 | 1 | LTO-2 | 0000-00-00 00:00:00 |
+---------+------------+-----------+---------+----------+----------+--------------+---------+------+-----------+-----------+---------------------+
All three tapes are labeled and marked "InChanger" and associated
w/correct slot. So far, so good....;)
3) Run update slots and list volumes:
*update slots
Automatically selected Storage: Autochanger
Connecting to Storage daemon Autochanger at hamlet:9103 ...
3306 Issuing autochanger "slots" command.
Device "Autochanger" has 12 slots.
Connecting to Storage daemon Autochanger at hamlet:9103 ...
3306 Issuing autochanger "list" command.
Catalog record for Volume "NNE440L2" updated to reference slot 1.
Catalog record for Volume "NNE441L2" updated to reference slot 2.
Volume "NNE443L2" not found in catalog. Slot=4 InChanger set to zero.
Volume "NNE444L2" not found in catalog. Slot=5 InChanger set to zero.
Volume "NNE445L2" not found in catalog. Slot=6 InChanger set to zero.
Volume "NNE446L2" not found in catalog. Slot=7 InChanger set to zero.
Volume "NNE447L2" not found in catalog. Slot=8 InChanger set to zero.
Volume "NNE448L2" not found in catalog. Slot=9 InChanger set to zero.
Volume "NNE449L2" not found in catalog. Slot=10 InChanger set to zero.
Volume "NNE450L2" not found in catalog. Slot=11 InChanger set to zero.
Volume "NNE451L2" not found in catalog. Slot=12 InChanger set to zero.
*list volumes
Pool: Default
+---------+------------+-----------+---------+----------+----------+--------------+---------+------+-----------+-----------+---------------------+
| MediaId | VolumeName | VolStatus | Enabled | VolBytes | VolFiles |
VolRetention | Recycle | Slot | InChanger | MediaType | LastWritten |
+---------+------------+-----------+---------+----------+----------+--------------+---------+------+-----------+-----------+---------------------+
| 1 | NNE440L2 | Append | 1 | 64,512 | 0 |
31,536,000 | 1 | 1 | 1 | LTO-2 | 0000-00-00 00:00:00 |
| 2 | NNE441L2 | Append | 1 | 64,512 | 0 |
31,536,000 | 1 | 2 | 1 | LTO-2 | 0000-00-00 00:00:00 |
| 3 | NNE442L2 | Append | 1 | 64,512 | 0 |
31,536,000 | 1 | 3 | 0 | LTO-2 | 0000-00-00 00:00:00 |
+---------+------------+-----------+---------+----------+----------+--------------+---------+------+-----------+-----------+---------------------+
Slot 3's InChanger flag is now marked "0". Presumably because it's
now in the drive rather than Slot 3?
4) Run backup job:
*run
A job name must be specified.
The defined Job resources are:
1: Client1
2: BackupCatalog
3: RestoreFiles
Select Job resource (1-3): 1
Run Backup job
JobName: Client1
Level: Full
Client: hamlet-fd
FileSet: Full Set
Pool: Default (From Job resource)
Storage: Autochanger (From Job resource)
When: 2007-07-21 20:54:19
Priority: 10
OK to run? (yes/mod/no): now
Job not run.
*run
A job name must be specified.
The defined Job resources are:
1: Client1
2: BackupCatalog
3: RestoreFiles
Select Job resource (1-3): 1
Run Backup job
JobName: Client1
Level: Full
Client: hamlet-fd
FileSet: Full Set
Pool: Default (From Job resource)
Storage: Autochanger (From Job resource)
When: 2007-07-21 23:14:32
Priority: 10
OK to run? (yes/mod/no): yes
Job queued. JobId=1
*messages
21-Jul 23:14 hamlet-dir: Start Backup JobId 1,
Job=Client1.2007-07-21_23.14.43 21-Jul 23:14 hamlet-sd: 3301 Issuing
autochanger "loaded? drive 0" command. 21-Jul 23:14 hamlet-sd: 3302
Autochanger "loaded? drive 0", result is Slot 3. 21-Jul 23:14
hamlet-sd: 3307 Issuing autochanger "unload slot 3, drive 0" command.
21-Jul 23:15 hamlet-sd: 3304 Issuing autochanger "load slot 1, drive 0"
command. 21-Jul 23:16 hamlet-sd: 3305 Autochanger "load slot 1, drive
0", status is OK. 21-Jul 23:16 hamlet-sd: 3301 Issuing autochanger
"loaded? drive 0" command. 21-Jul 23:16 hamlet-sd: 3302 Autochanger
"loaded? drive 0", result is Slot 1. 21-Jul 23:17 hamlet-sd: Wrote
label to prelabeled Volume "NNE440L2" on device "Drive-1" (/dev/nsa0)
5) Backup job completes, no problem. Or does it??
*messages
22-Jul 01:36 hamlet-sd: Job write elapsed time = 02:19:13, Transfer
rate = 17.41 M bytes/second 22-Jul 01:36 hamlet-sd: Alert: smartctl:
not found 22-Jul 01:36 hamlet-sd: 3997 Bad alert command: sh -c
'smartctl -d scsi -H -l error /dev/nsa0': ERR=Child exited with code
127. 22-Jul 01:36 hamlet-dir: Bacula 2.0.3 (06Mar07): 22-Jul-2007
01:36:17 JobId: 1 Job:
Client1.2007-07-21_23.14.43 Backup Level: Full
Client: "hamlet-fd" 2.0.3 (06Mar07)
i386-portbld-freebsd6.2,freebsd,6.2-RELEASE-p5 FileSet:
"Full Set" 2007-07-21 23:14:43 Pool: "Default" (From
Job resource) Storage: "Autochanger" (From Job resource)
Scheduled time: 21-Jul-2007 23:14:32
Start time: 21-Jul-2007 23:14:48
End time: 22-Jul-2007 01:36:17
Elapsed time: 2 hours 21 mins 29 secs
Priority: 10
FD Files Written: 170
SD Files Written: 170
FD Bytes Written: 145,480,874,334 (145.4 GB)
SD Bytes Written: 145,480,891,899 (145.4 GB)
Rate: 17137.6 KB/s
Software Compression: None
VSS: no
Encryption: no
Volume name(s): NNE440L2
Volume Session Id: 1
Volume Session Time: 1185064344
Last Volume Bytes: 145,588,875,264 (145.5 GB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
22-Jul 01:36 hamlet-dir: Begin pruning Jobs.
22-Jul 01:36 hamlet-dir: No Jobs found to prune.
22-Jul 01:36 hamlet-dir: Begin pruning Files.
22-Jul 01:36 hamlet-dir: No Files found to prune.
22-Jul 01:36 hamlet-dir: End auto prune.
Or does it?? Status is reported as "Backup OK" but smartclt issues
warning:
22-Jul 01:36 hamlet-sd: Alert: smartctl: not found
But then bacula finds smartctl:
22-Jul 01:36 hamlet-sd: 3997 Bad alert command: sh -c 'smartctl -d scsi
-H -l error /dev/nsa0': ERR=Child exited with code 127
Cursory googling sheds no light on what code 127 means??
6) Stop and restart storage daemon. List volumes:
*list volumes
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
Pool: Default
+---------+------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------------------+
| MediaId | VolumeName | VolStatus | Enabled | VolBytes | VolFiles |
VolRetention | Recycle | Slot | InChanger | MediaType | LastWritten |
+---------+------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------------------+
| 1 | NNE440L2 | Append | 1 | 145,588,875,264 | 146 |
31,536,000 | 1 | 1 | 1 | LTO-2 | 2007-07-22 01:36:16 |
| 2 | NNE441L2 | Append | 1 | 64,512 | 0 |
31,536,000 | 1 | 2 | 1 | LTO-2 | 0000-00-00 00:00:00 |
| 3 | NNE442L2 | Append | 1 | 64,512 | 0 |
31,536,000 | 1 | 3 | 0 | LTO-2 | 0000-00-00 00:00:00 |
+---------+------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------------------+
Okay, slot 1 is in the drive and slot 3, wh/is now occupied by it's
tape has InChanger flag set to "0". What's up with this?
7) Okay let's update slots:
*update slots
Automatically selected Storage: Autochanger
Connecting to Storage daemon Autochanger at hamlet:9103 ...
3306 Issuing autochanger "slots" command.
Device "Autochanger" has 12 slots.
Connecting to Storage daemon Autochanger at hamlet:9103 ...
3306 Issuing autochanger "list" command.
Catalog record for Volume "NNE441L2" updated to reference slot 2.
Catalog record for Volume "NNE442L2" updated to reference slot 3.
Volume "NNE443L2" not found in catalog. Slot=4 InChanger set to zero.
Volume "NNE444L2" not found in catalog. Slot=5 InChanger set to zero.
Volume "NNE445L2" not found in catalog. Slot=6 InChanger set to zero.
Volume "NNE446L2" not found in catalog. Slot=7 InChanger set to zero.
Volume "NNE447L2" not found in catalog. Slot=8 InChanger set to zero.
Volume "NNE448L2" not found in catalog. Slot=9 InChanger set to zero.
Volume "NNE449L2" not found in catalog. Slot=10 InChanger set to zero.
Volume "NNE450L2" not found in catalog. Slot=11 InChanger set to zero.
Volume "NNE451L2" not found in catalog. Slot=12 InChanger set to zero.
Now bacula knows slot 3's InChanger is set to "1". But... apparently
slot 1's InChanger is set to "0"
8) Run another backup job:
*run
A job name must be specified.
The defined Job resources are:
1: Client1
2: BackupCatalog
3: RestoreFiles
Select Job resource (1-3): 1
Run Backup job
JobName: Client1
Level: Full
Client: hamlet-fd
FileSet: Full Set
Pool: Default (From Job resource)
Storage: Autochanger (From Job resource)
When: 2007-07-22 02:11:10
Priority: 10
OK to run? (yes/mod/no): yes
Job queued. JobId=2
*messages
22-Jul 02:11 hamlet-dir: Start Backup JobId 2,
Job=Client1.2007-07-22_02.11.15 *messages
22-Jul 02:11 hamlet-sd: 3307 Issuing autochanger "unload slot 1, drive
0" command. 22-Jul 02:12 hamlet-sd: 3304 Issuing autochanger "load slot
2, drive 0" command.
Bacula thinks slot 1 tape is not InChanger, even though it's in drive,
and loads slot 2 tape
9) List volumes again to confirm Slot 1 InChanger flag status:
*list volumes
Pool: Default
+---------+------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------------------+
| MediaId | VolumeName | VolStatus | Enabled | VolBytes | VolFiles |
VolRetention | Recycle | Slot | InChanger | MediaType | LastWritten |
+---------+------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------------------+
| 1 | NNE440L2 | Append | 1 | 145,588,875,264 | 146 |
31,536,000 | 1 | 1 | 0 | LTO-2 | 2007-07-22 01:36:16 |
| 2 | NNE441L2 | Append | 1 | 64,512 | 0 |
31,536,000 | 1 | 2 | 1 | LTO-2 | 0000-00-00 00:00:00 |
| 3 | NNE442L2 | Append | 1 | 64,512 | 0 |
31,536,000 | 1 | 3 | 1 | LTO-2 | 0000-00-00 00:00:00 |
+---------+------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------------------+
Any insights as to what is going on here?
--
Best regards,
Ken Gunderson
GPG Key -- 9F5179FD
"Never hold discussions with the monkey when the organ grinder is in
the room." - Sir Winston Churchill
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop.
Now Search log events and configuration files using AJAX and a browser.
Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
