Every once in a while, my backup server running Bacula 5.2 on CentOS 6 with an HP 1x8 LTO-3 Autoloader (no barcode reader) shows the following strange behaviour: before continuing to use the current, still appendable tape, it recycles the oldest tape in the pool, emits a "Cannot find any appendable volumes" message, and sits idle for five minutes. Then it mounts and uses the tape it should have used in the first place.
Latest Example:
- Previous backup was to volume "Daily_2", loaded in slot 3.
- During the day, the tape in slot 8 had been used for a restore.
- Volume "Daily_1" is loaded in slot 2, and IIRC was in state
"Purged" before this job started.
Job log:
06-Jun 22:05 backup-dir JobId 2571: Start Backup JobId 2571,
Job=backup.2012-06-06_22.05.00_17
06-Jun 22:05 backup-dir JobId 2571: Recycled volume "Daily_1"
06-Jun 22:05 backup-dir JobId 2571: Using Device "LTO-3"
06-Jun 22:05 bacula-sd JobId 2571: Job backup.2012-06-06_22.05.00_17 is
waiting. Cannot find any appendable volumes.
Please use the "label" command to create a new Volume for:
Storage: "LTO-3" (/dev/nst0)
Pool: Daily
Media type: LTO-3
06-Jun 22:10 bacula-sd JobId 2571: 3307 Issuing autochanger "unload slot
8, drive 0" command.
06-Jun 22:11 bacula-sd JobId 2571: 3304 Issuing autochanger "load slot
3, drive 0" command.
06-Jun 22:11 bacula-sd JobId 2571: 3305 Autochanger "load slot 3, drive
0", status is OK.
06-Jun 22:11 bacula-sd JobId 2571: Volume "Daily_2" previously written,
moving to end of data.
06-Jun 22:12 bacula-sd JobId 2571: Ready to append to end of Volume
"Daily_2" at file=310.
06-Jun 22:12 bacula-sd JobId 2571: Spooling data ...
06-Jun 22:14 backup-fd JobId 2571: /var/lib/nfs/rpc_pipefs is a
different filesystem. Will not descend from / into it.
06-Jun 22:14 backup-fd JobId 2571: /dev is a different filesystem.
Will not descend from / into it.
06-Jun 22:14 backup-fd JobId 2571: /sys is a different filesystem.
Will not descend from / into it.
06-Jun 22:15 bacula-sd JobId 2571: Job write elapsed time = 00:02:37,
Transfer rate = 25.85 M Bytes/second
06-Jun 22:15 bacula-sd JobId 2571: Committing spooled data to Volume
"Daily_2". Despooling 4,063,652,689 bytes ...
06-Jun 22:16 bacula-sd JobId 2571: Despooling elapsed time = 00:01:07,
Transfer rate = 60.65 M Bytes/second
06-Jun 22:16 bacula-sd JobId 2571: Sending spooled attrs to the
Director. Despooling 40,993 bytes ...
06-Jun 22:16 backup-dir JobId 2571: Bacula backup-dir 5.2.7 (02Jun12):
Build OS: x86_64-redhat-linux-gnu redhat Enterprise release
JobId: 2571
Job: backup.2012-06-06_22.05.00_17
Backup Level: Incremental, since=2012-06-05 22:05:02
Client: "backup-fd" 5.2.7 (02Jun12)
x86_64-redhat-linux-gnu,redhat,Enterprise release
FileSet: "SelfBackupSet" 2012-01-05 22:05:00
Pool: "Daily" (From Run pool override)
Catalog: "MyCatalog" (From Client resource)
Storage: "LTO-3" (From Job resource)
Scheduled time: 06-Jun-2012 22:05:00
Start time: 06-Jun-2012 22:05:02
End time: 06-Jun-2012 22:16:47
Elapsed time: 11 mins 45 secs
Priority: 10
FD Files Written: 161
SD Files Written: 161
FD Bytes Written: 4,059,863,476 (4.059 GB)
SD Bytes Written: 4,059,881,749 (4.059 GB)
Rate: 5758.7 KB/s
Software Compression: None
VSS: no
Encryption: no
Accurate: no
Volume name(s): Daily_2
Volume Session Id: 7
Volume Session Time: 1338979655
Last Volume Bytes: 430,312,458,240 (430.3 GB)
Non-fatal FD errors: 0
SD Errors: 0
FD termination status: OK
SD termination status: OK
Termination: Backup OK
06-Jun 22:16 backup-dir JobId 2571: Begin pruning Jobs older than 12
months .
06-Jun 22:16 backup-dir JobId 2571: No Jobs found to prune.
06-Jun 22:16 backup-dir JobId 2571: Begin pruning Files.
06-Jun 22:16 backup-dir JobId 2571: No Files found to prune.
06-Jun 22:16 backup-dir JobId 2571: End auto prune.
Status of pool "Daily" after this and the following jobs:
[ts@backup ~]$ echo li media pool=Daily | bconsole
Connecting to Director backup.phnxsoft.com:9101
1000 OK: backup-dir Version: 5.2.7 (02 June 2012)
Enter a period to cancel a command.
li media pool=Daily
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
+---------+------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------------------+
| MediaId | VolumeName | VolStatus | Enabled | VolBytes |
VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType |
LastWritten |
+---------+------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------------------+
| 18 | Daily_0 | Used | 1 | 539,735,325,696 |
397 | 518,400 | 1 | 1 | 1 | LTO-3 | 2012-05-10
23:06:36 |
| 34 | Daily_1 | Recycle | 1 | 1 |
0 | 518,400 | 1 | 2 | 1 | LTO-3 | 2012-04-05
23:31:58 |
| 35 | Daily_2 | Append | 1 | 470,371,249,152 |
335 | 518,400 | 1 | 3 | 1 | LTO-3 | 2012-06-06
23:25:29 |
+---------+------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------------------+
You have messages.
[ts@backup ~]$
How can Bacula tell me it cannot find an appendable volume
when there is one sitting in the pool in plain sight and it
has just recycled another one itself?
signature.asc
Description: OpenPGP digital signature
------------------------------------------------------------------------------ Live Security Virtual Conference Exclusive live event will cover all the ways today's security and threat landscape has changed and how IT managers can respond. Discussions will include endpoint security, mobile security and the latest in malware threats. http://www.accelacomm.com/jaw/sfrnl04242012/114/50122263/
_______________________________________________ Bacula-users mailing list Bacula-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/bacula-users
