Hello folks
I have a copy job which copies my full backups to a USB drive using
vchanger once a week.
Recently, the backups have been exceeding the 1TB size of a single USB
drive, which would be fine, I'll just use more than one drive.
What isn't fine is that bacula is recycling its volumes too quickly.
What I expect to happen is that it will fill up the USB drive, (run
out of volumes) then wait for another USB drive to be attached,
instead of recycling/purging the volumes it just wrote. Here's a log
snippet:
23-Sep 09:55 ghback01-sd JobId 3433: Recycled volume "c1_0011_0012" on
device "usb-changer-drive-0" (/var/lib/bacula/c1/0/drive0), all
previous data lost.
23-Sep 09:55 ghback01-sd JobId 3433: New volume "c1_0011_0012" mounted
on device "usb-changer-drive-0" (/var/lib/bacula/c1/0/drive0) at
23-Sep-2013 09:55.
23-Sep 09:55 ghback01-sd JobId 3433: Elapsed time=00:05:43, Transfer
rate=35.71 M Bytes/second
23-Sep 09:55 ghback01-dir JobId 3433: Bacula ghback01-dir 5.2.13 (19Jan13):
Build OS: x86_64-redhat-linux-gnu redhat Enterprise release
Prev Backup JobId: 2319
Prev Backup Job: BackupCatalog.2013-08-26_23.10.00_57
New Backup JobId: 3434
Current JobId: 3433
Current Job: CopyDiskToUSBFullBackups.2013-09-23_07.50.28_06
Backup Level: Full
Client: None
FileSet: "None" 2013-06-02 21:05:42
Read Pool: "FullPool" (From Job resource)
Read Storage: "FullFileStorage" (From Pool resource)
Write Pool: "Offsite" (From Job Pool's NextPool resource)
Write Storage: "c1" (From Storage from Pool's NextPool resource)
Catalog: "MyCatalog" (From Client resource)
Start time: 23-Sep-2013 09:49:23
End time: 23-Sep-2013 09:55:48
Elapsed time: 6 mins 25 secs
Priority: 6
SD Files Written: 1
SD Bytes Written: 12,251,161,810 (12.25 GB)
Rate: 31821.2 KB/s
Volume name(s): c1_0011_0011|c1_0011_0012
Volume Session Id: 1
Volume Session Time: 1379926155
Last Volume Bytes: 1,522,869,694 (1.522 GB)
SD Errors: 0
SD termination status: OK
Termination: Copying OK
23-Sep 09:55 ghback01-dir JobId 3433: Begin pruning Jobs older than 6 months .
23-Sep 09:55 ghback01-dir JobId 3433: No Jobs found to prune.
23-Sep 09:55 ghback01-dir JobId 3433: Begin pruning Files.
23-Sep 09:55 ghback01-dir JobId 3433: Pruned Files from 27 Jobs for
client None from catalog.
23-Sep 09:55 ghback01-dir JobId 3433: End auto prune.
23-Sep 07:50 ghback01-dir JobId 3435: Copying using JobId=2342
Job=BackupCatalog.2013-08-27_23.10.00_24
23-Sep 07:50 ghback01-dir JobId 3435: Bootstrap records written to
/var/spool/bacula/ghback01-dir.restore.3.bsr
23-Sep 09:55 ghback01-dir JobId 3435: Start Copying JobId 3435,
Job=CopyDiskToUSBFullBackups.2013-09-23_07.50.29_08
23-Sep 09:55 ghback01-dir JobId 3435: Using Device "FileDev1" to read.
23-Sep 09:55 ghback01-dir JobId 3435: Using Device
"usb-changer-drive-0" to write.
23-Sep 09:55 ghback01-sd JobId 3435: Ready to read from volume
"FULL_0135" on device "FileDev1" (/baculaVolumes/local).
23-Sep 09:55 ghback01-sd JobId 3435: Volume "c1_0011_0012" previously
written, moving to end of data.
23-Sep 09:55 ghback01-sd JobId 3435: Ready to append to end of Volume
"c1_0011_0012" size=1522869694
That shows volume c1_0011_0012 being recycled for the first time on
23-Sep, 09:55 , this is correct. That volume was over two weeks old.
But later ...
24-Sep 00:32 ghback01-sd JobId 3525: 3307 Issuing autochanger "unload
slot 11, drive 0" command.
24-Sep 00:32 ghback01-dir JobId 3525: There are no more Jobs
associated with Volume "c1_0011_0012". Marking it purged.
24-Sep 00:32 ghback01-dir JobId 3525: All records pruned from Volume
"c1_0011_0012"; marking it "Purged"
24-Sep 00:32 ghback01-dir JobId 3525: Recycled volume "c1_0011_0012"
24-Sep 00:32 ghback01-sd JobId 3525: 3304 Issuing autochanger "load
slot 12, drive 0" command.
24-Sep 00:32 ghback01-sd JobId 3525: 3305 Autochanger "load slot 12,
drive 0", status is OK.
24-Sep 00:32 ghback01-sd JobId 3525: Recycled volume "c1_0011_0012" on
device "usb-changer-drive-0" (/var/lib/bacula/c1/0/drive0), all
previous data lost.
24-Sep 00:32 ghback01-sd JobId 3525: New volume "c1_0011_0012" mounted
on device "usb-changer-drive-0" (/var/lib/bacula/c1/0/drive0) at
24-Sep-2013 00:32.
Why did it get pruned/recycled ?
I've only picked on one volume here to illustrate, but it happens with
about a dozen of them, basically as many as it takes to copy all the
jobs. I want it to wait for a new drive.
vchanger is configured to have 86 10GB files on a 1TB drive, which
basically fills it to within 2GB of fullness.
Here is my vchanger config:
changer_name = c1
virtual_drives = 2
slots_per_magazine = 86
magazine_bays = 1
automount_dir = /mnt/vchanger
logfile = /var/lib/bacula/vchanger.log
magazine = UUID:45506fef-3c8f-4aa5-b0a1-c334a46bedbd
magazine = UUID:c86c7a51-90aa-4fc9-b059-186bfdcf6d65
magazine = UUID:dcc85c72-734b-426c-b193-910722a0bece
magazine = UUID:72b1511a-c329-4948-b4d8-c0d2ffcdd19a
magazine = UUID:fbba8042-e309-43b0-9b5d-da7195edfd0d
#eof
And the relevant SD:
#---- local virtual autochanger with USB drive "magazines"
Autochanger {
Name = usb-changer
Device = usb-changer-drive-0
Device = usb-changer-drive-1
Changer Command = "/usr/local/bin/vchanger %c %o %S %a %d"
Changer Device = "/etc/bacula/c1.conf"
}
#--- drive 0 of the usb-changer autochanger
Device {
Name = usb-changer-drive-0
DriveIndex = 0
Autochanger = yes;
DeviceType = File
MediaType = File
ArchiveDevice = /var/lib/bacula/c1/0/drive0
RemovableMedia = no;
RandomAccess = yes;
}
#--- drive 1 of the usb-changer autochanger
Device {
Name = usb-changer-drive-1
DriveIndex = 1
Autochanger = yes;
DeviceType = File
MediaType = File
ArchiveDevice = /var/lib/bacula/c1/1/drive1
RemovableMedia = no;
RandomAccess = yes;
}# ...
# eof
And the director:
Pool {
Name = FullPool
Pool Type = Backup
Recycle = yes # Bacula can automatically recycle Volumes
Recycle Pool = FullPool
AutoPrune = yes # Prune expired volumes
Storage = FullFileStorage # full dev
Volume Retention = 3 weeks
Maximum Volume Bytes = 100G
Maximum Volumes = 40
LabelFormat = "FULL_"
Next Pool = Offsite
Action On Purge = Truncate
}
Pool {
Name = Offsite
Pool Type = Backup
Recycle = yes
AutoPrune = yes
Storage = c1
Volume Retention = 14 days # two weeks
Maximum Volume Bytes = 10G
Maximum Volumes = 650
LabelFormat = "OFFSITE_" # not used
Action On Purge = Truncate
}
If I've missed any important configs or can provide more info please
let me know, but I'd really appreciate some pointers as to what is
going on here.
Looking at my pasted logs, is it this?
23-Sep 09:55 ghback01-dir JobId 3433: Begin pruning Files.
23-Sep 09:55 ghback01-dir JobId 3433: Pruned Files from 27 Jobs for
client None from catalog.
23-Sep 09:55 ghback01-dir JobId 3433: End auto prune.
Have we pruned everything we just wrote? Or is this a red herring?
All of this is happening on Bacula 5.2.13 on RHEL 6.4 (OEL)
Thanks
------------------------------------------------------------------------------
October Webinars: Code for Performance
Free Intel webinars can help you accelerate application performance.
Explore tips for MPI, OpenMP, advanced profiling, and more. Get the most from
the latest Intel processors and coprocessors. See abstracts and register >
http://pubads.g.doubleclick.net/gampad/clk?id=60133471&iu=/4140/ostg.clktrk
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
