Menu
▾
▴
[Bacula-bugs] [bacula 0001019]: bacula uses volume from scratch pool instead pruning/recycling old volume
|
From: <bac...@li...> - 2007-11-30 10:00:34
|
A NOTE has been added to this issue. ====================================================================== http://bugs.bacula.org/view.php?id=1019 ====================================================================== Reported By: RalfGross Assigned To: Dan Langille ====================================================================== Project: bacula Issue ID: 1019 Category: Director Reproducibility: always Severity: major Priority: normal Status: feedback ====================================================================== Date Submitted: 11-22-2007 14:50 UTC Last Modified: 11-30-2007 10:00 UTC ====================================================================== Summary: bacula uses volume from scratch pool instead pruning/recycling old volume Description: This happend today after issuing 'status dir days=4'. You have messages. *mess 22-Nov 13:46 VU0EM005-dir JobId 0: Max configured use duration exceeded. Marking Volume "06D137L3" as Used. 22-Nov 13:46 VU0EM005-dir JobId 0: Using Volume "06D141L3" from 'Scratch' pool. The first message is ok, but the second makes no sense to me. Volume 06D141L3 was moved by bacula from the Scratch pool to the Differential pool. This already happend last week with an other volume from the Scratch pool that was then moved to the Full pool. At this time I was running bacula 2.0.3, I updated this monday to 2.2.6. 1. why does bacula want to 'use' a volume 4 days before the next differential backup. I know that the status command triggers the pruning/recycling algorithm, but it makes no sense to me to choose a volume from a pool several days before the next backup needs a volume from this pool. 2. why did bacula not prune the records of one of the existing volumes in the Differential pool and just recycle this volume. from the manual: [...] # Prune volumes applying Volume retention period (Volumes with VolStatus Full, Used, or Append are pruned). # Search the Pool for a Volume with VolStatus=Purged # If InChanger was set, go back to the first step above, but this second time, ignore the InChanger flag in step 2. # Attempt to create a new Volume if automatic labeling enabled If Python is enabled, a Python NewVolume even is generated before the Label Format check is used. # If a Pool named "Scratch" exists, search for a Volume and if found move it to the current Pool for the Job and use it. [...] The above is definitly not happening in the right order here (I think). Pool: Differential +---------+------------+-----------+---------+----------------+----------+--------------+---------+------+-----------+-----------+---------------------+ | mediaid | volumename | volstatus | enabled | volbytes | volfiles | volretention | recycle | slot | inchanger | mediatype | lastwritten | +---------+------------+-----------+---------+----------------+----------+--------------+---------+------+-----------+-----------+---------------------+ | 6 | 06D125L3 | Used | 1 | 9,816,468,480 | 11 | 2,678,400 | 1 | 6 | 1 | LTO3 | 2007-10-14 00:25:18 | | 7 | 06D126L3 | Used | 1 | 18,565,585,920 | 20 | 2,678,400 | 1 | 7 | 1 | LTO3 | 2007-10-21 00:33:04 | | 8 | 06D127L3 | Used | 1 | 29,770,094,592 | 31 | 2,678,400 | 1 | 8 | 1 | LTO3 | 2007-10-28 00:46:41 | | 19 | 06D137L3 | Used | 1 | 74,883,142,656 | 76 | 2,678,400 | 1 | 18 | 1 | LTO3 | 2007-11-18 01:10:57 | | 37 | 06D124L3 | Used | 1 | 10,923,623,424 | 12 | 2,678,400 | 1 | 5 | 1 | LTO3 | 2007-11-11 00:31:07 | | 49 | 06D141L3 | Append | 1 | 64,512 | 0 | 2,678,400 | 1 | 22 | 1 | LTO3 | | +---------+------------+-----------+---------+----------------+----------+--------------+---------+------+-----------+-----------+---------------------+ The last written date of volume 06D125L3 is 2007-10-14 and the volume retention time is 31 days. The volume was not yet pruned and I don't know why not. This is the volume I expected to be pruned/recycled: * llist volumes Pool=Differential mediaid: 6 volumename: 06D125L3 slot: 6 poolid: 5 mediatype: LTO3 firstwritten: 2007-10-14 00:07:06 lastwritten: 2007-10-14 00:25:18 labeldate: 2007-10-14 00:07:06 voljobs: 3 volfiles: 11 volblocks: 152,164 volmounts: 6 volbytes: 9,816,468,480 volerrors: 0 volwrites: 1,480,258 volcapacitybytes: 0 volstatus: Used enabled: 1 recycle: 1 volretention: 2,678,400 voluseduration: 345,600 maxvoljobs: 0 maxvolfiles: 0 maxvolbytes: 0 inchanger: 1 endfile: 10 endblock: 13,870 volparts: 0 labeltype: 0 storageid: 2 deviceid: 0 locationid: 0 recyclecount: 0 initialwrite: scratchpoolid: 0 recyclepoolid: 0 comment: Some additional information. If you need any more info let me know. Client: name=VU0EM003 address=10.60.1.252 FDport=9102 MaxJobs=1 JobRetention=6 months FileRetention=3 months AutoPrune=1 --> Catalog: name=MyCatalog address=*None* DBport=0 db_name=bacula db_user=bacula MutliDBConn=0 Job: name=VU0EM003 JobType=66 level= Priority=10 Enabled=1 MaxJobs=1 Resched=0 Times=0 Interval=1,800 Spool=1 WritePartAfterJob=1 --> Client: name=VU0EM003 address=10.60.1.252 FDport=9102 MaxJobs=1 JobRetention=6 months FileRetention=3 months AutoPrune=1 --> Catalog: name=MyCatalog address=*None* DBport=0 db_name=bacula db_user=bacula MutliDBConn=0 --> FileSet: name=VU0EM003 O e RD .*000_KEIN_BACKUP.* WD /public/? N O AM N I / I /public I /home I /server N E /server/projekte/alte_projekte E /cdrom E /media E /lost+found E /mnt E /dev E /sys E /proc E /tmp E /.journal E /.fsck N --> Schedule: name=Regular Backup VU0EM003 --> Run Level=Incremental hour=0 mday=0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 month=0 1 2 3 4 5 6 7 8 9 10 11 wday=2 3 4 5 6 wom=0 1 2 3 4 woy=0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 mins=6 --> Pool: name=Incremental PoolType=Backup use_cat=1 use_once=0 cat_files=1 max_vols=0 auto_prune=1 VolRetention=14 days VolUse=0 secs recycle=1 LabelFormat=*None* CleaningPrefix=*None* LabelType=0 RecyleOldest=1 PurgeOldest=0 MaxVolJobs=0 MaxVolFiles=0 MaxVolBytes=0 MigTime=0 secs MigHiBytes=0 MigLoBytes=0 --> Run Level=Differential hour=0 mday=0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 month=0 1 2 3 4 5 6 7 8 9 10 11 wday=0 wom=1 2 3 4 woy=0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 mins=6 --> Pool: name=Differential PoolType=Backup use_cat=1 use_once=0 cat_files=1 max_vols=0 auto_prune=1 VolRetention=1 month 1 day VolUse=0 secs recycle=1 LabelFormat=*None* CleaningPrefix=*None* LabelType=0 RecyleOldest=0 PurgeOldest=0 MaxVolJobs=0 MaxVolFiles=0 MaxVolBytes=0 MigTime=0 secs MigHiBytes=0 MigLoBytes=0 --> Messages: name=Regular Backup mailcmd=/opt/bacula/sbin/bsmtp -h localhost -f "(Bacula) %r" -s "Bacula: %t %e of %c %l" %r Pool: name=Full PoolType=Backup use_cat=1 use_once=0 cat_files=1 max_vols=0 auto_prune=1 VolRetention=6 months VolUse=4 days recycle=1 LabelFormat=*None* CleaningPrefix=*None* LabelType=0 RecyleOldest=1 PurgeOldest=0 MaxVolJobs=0 MaxVolFiles=0 MaxVolBytes=0 MigTime=0 secs MigHiBytes=0 MigLoBytes=0 Pool: name=Differential PoolType=Backup use_cat=1 use_once=0 cat_files=1 max_vols=0 auto_prune=1 VolRetention=1 month 1 day VolUse=4 days recycle=1 LabelFormat=*None* CleaningPrefix=*None* LabelType=0 RecyleOldest=1 PurgeOldest=0 MaxVolJobs=0 MaxVolFiles=0 MaxVolBytes=0 MigTime=0 secs MigHiBytes=0 MigLoBytes=0 Pool: name=Incremental PoolType=Backup use_cat=1 use_once=0 cat_files=1 max_vols=0 auto_prune=1 VolRetention=14 days VolUse=0 secs recycle=1 LabelFormat=*None* CleaningPrefix=*None* LabelType=0 RecyleOldest=1 PurgeOldest=0 MaxVolJobs=0 MaxVolFiles=0 MaxVolBytes=0 MigTime=0 secs MigHiBytes=0 MigLoBytes=0 Pool: name=Scratch PoolType=Backup use_cat=1 use_once=0 cat_files=1 max_vols=0 auto_prune=1 VolRetention=1 year VolUse=0 secs recycle=1 LabelFormat=*None* CleaningPrefix=*None* LabelType=0 RecyleOldest=0 PurgeOldest=0 MaxVolJobs=0 MaxVolFiles=0 MaxVolBytes=0 MigTime=0 secs MigHiBytes=0 MigLoBytes=0 ====================================================================== ---------------------------------------------------------------------- RalfGross - 11-22-07 15:12 ---------------------------------------------------------------------- For testing I deleted the Scratch pool to see if then a volume with state Used gets recycled. Afer a fresh 'status dir days=4' no records were pruned and no volume was recycled. Let's see what happens on sunday when the next differential backup needs a recycled volume. ---------------------------------------------------------------------- Dan Langille - 11-22-07 16:20 ---------------------------------------------------------------------- I've been working with Ralf via IRC on this one. It appears to be a configuration issue. I'll close this bug when that is confirmed. ---------------------------------------------------------------------- Dan Langille - 11-22-07 17:03 ---------------------------------------------------------------------- We'll close this for now, until we can confirm things offline. ---------------------------------------------------------------------- RalfGross - 11-22-07 18:40 ---------------------------------------------------------------------- I'm sorry for reopening this bug, but there seems to be no other way to add additional information to it. I just wanted to show there are volumes in the same pool, with the same retention times that were correctly recycled in the past: 30-Aug 18:05 VU0EM005-dir: Pruned 3 Jobs on Volume "06D126L3" from catalog. 30-Aug 18:05 VU0EM005-dir: Recycled volume "06D126L3" 18-Okt 18:05 VU0EM005-dir: Pruned 3 Jobs on Volume "06D126L3" from catalog. 18-Okt 18:05 VU0EM005-dir: Recycled volume "06D126L3" 18-Okt 18:05 VU0EM005-dir: Pruned 3 Jobs on Volume "06D127L3" from catalog. 25-Okt 18:05 VU0EM005-dir: Recycled volume "06D127L3" 20-Sep 18:05 VU0EM005-dir: Pruned 3 Jobs on Volume "06D137L3" from catalog. 27-Sep 18:05 VU0EM005-dir: Recycled volume "06D137L3" 01-Nov 18:05 VU0EM005-dir: Pruned 3 Jobs on Volume "06D137L3" from catalog. 15-Nov 18:05 VU0EM005-dir: Recycled volume "06D137L3" And even the volume which is part of my bug report was recycled before: 04-Jul 18:05 VU0EM005: Pruned 3 Jobs on Volume "06D125L3" from catalog. 12-Jul 18:05 VU0EM005: Recycled volume "06D125L3" 16-Aug 18:05 VU0EM005-dir: Pruned 3 Jobs on Volume "06D125L3" from catalog. 23-Aug 18:05 VU0EM005-dir: Recycled volume "06D125L3" 04-Okt 18:05 VU0EM005-dir: Pruned 3 Jobs on Volume "06D125L3" from catalog. 04-Okt 18:05 VU0EM005-dir: Recycled volume "06D125L3" The only change regarding retention times in the last few months was the change of the File Retention time from 30 to 90 days. But this was back in may or june. File Retention = 30 days # 30 days Job Retention = 6 months # six months File Retention = 90 days # 90 days Job Retention = 6 months # six months ---------------------------------------------------------------------- RalfGross - 11-23-07 12:15 ---------------------------------------------------------------------- I downgraded from 2.2.6 (update last monday) to 2.0.3 which was running the last few months. Now it's working as expected again, an in my opinion as described in the manual. http://www.bacula.org/rel-manual/Automatic_Volume_Recycling.html * (step 5) Prune volumes applying Volume retention period (Volumes with VolStatus Full, Used, or Append are pruned). Note, even if all the File and Job records are pruned from a Volume, the Volume will not be marked Purged until the Volume retention period expires. * (step 7) If a Pool named "Scratch" exists, search for a Volume and if found move it to the current Pool for the Job and use it. Note, when the Scratch Volume is moved into the current Pool, the basic Pool defaults are applied as if it is a newly labeled Volume (equivalent to an update volume from pool command). *status dir days=3 Scheduled Jobs: Level Type Pri Scheduled Name Volume =================================================================================== Differential Backup 10 25-Nov-07 00:05 SMTCZB0003 06D125L3 Differential Backup 10 25-Nov-07 00:06 VU0EM003 06D125L3 Full Backup 10 25-Nov-07 00:07 BackupCatalog 06D125L3 ==== You have messages. *mess 23-Nov 08:51 VU0EM005-dir: Pruned 3 Jobs on Volume "06D126L3" from catalog. 23-Nov 08:51 VU0EM005-dir: Pruned 3 Jobs on Volume "06D125L3" from catalog. 23-Nov 08:51 VU0EM005-dir: Recycled volume "06D125L3" No Scratch pool volume was used, pruning happend as expected and the volume 06D125L3 was recycled. Great! http://sourceforge.net/mailarchive/forum.php?thread_name=200708111036.55201.kern%40sibbald.com&forum_name=bacula-announce I'm not sure which of the two points from the 2.2 annoncement is responsibel for the new behaviour. - Volumes are pruned only when absolutely necessary -- this may cause your database to grow compared to prior Bacula versions. [...] - Volumes are no longer pruned during 'status dir' The second point maybe explains why a Scratch pool volume was used. The 'state dir' command didn't prune the volume, but it still tried to find out what volume will be needed for the next backup. It didn't find any volume and choose to take one of the Scratch pool. It would have been interesting to see, what volume bacula would have choosen at backup start time - without the 'status dir' command before. To me it makes no sense to move a volume from th Scratch pool to the Differential pool _at that moment_. If bacula does not prune volumes during 'status dir' it should not assign volumes from the Scatch pool to a different pool at that moment. I my opinion pruning/recycling and the decision to use a volume of the scratch pool has to be done at the same time. ---------------------------------------------------------------------- RalfGross - 11-30-07 10:00 ---------------------------------------------------------------------- It happend again this week. Even though the purged volume 06D126L3 is in the Differential pool, bacula decided to move the scratch pool volume 06D141L3 to the Differential pool after issuing 'status dir days=3'. *mess 30-Nov 10:54 VU0EM005-dir JobId 0: Using Volume "06D141L3" from 'Scratch' pool. At the moment the only way to solve the problem is either to remove the whole scratch pool, or never issue the 'status dir' command. There is something going wrong after the changes in 2.2.x which makes the scratch pool unusable. Pool: Differential +---------+------------+-----------+---------+----------------+----------+--------------+---------+------+-----------+-----------+---------------------+ | mediaid | volumename | volstatus | enabled | volbytes | volfiles | volretention | recycle | slot | inchanger | mediatype | lastwritten | +---------+------------+-----------+---------+----------------+----------+--------------+---------+------+-----------+-----------+---------------------+ | 6 | 06D125L3 | Append | 1 | 47,974,929,408 | 49 | 2,678,400 | 1 | 6 | 1 | LTO3 | 2007-11-25 13:39:02 | | 7 | 06D126L3 | Purged | 1 | 18,565,585,920 | 20 | 2,678,400 | 1 | 7 | 1 | LTO3 | 2007-10-21 00:33:04 | | 8 | 06D127L3 | Used | 1 | 29,770,094,592 | 31 | 2,678,400 | 1 | 8 | 1 | LTO3 | 2007-10-28 00:46:41 | | 19 | 06D137L3 | Used | 1 | 74,883,142,656 | 76 | 2,678,400 | 1 | 18 | 1 | LTO3 | 2007-11-18 01:10:57 | | 37 | 06D124L3 | Used | 1 | 10,923,623,424 | 12 | 2,678,400 | 1 | 5 | 1 | LTO3 | 2007-11-11 00:31:07 | +---------+------------+-----------+---------+----------------+----------+--------------+---------+------+-----------+-----------+---------------------+ Issue History Date Modified Username Field Change ====================================================================== 11-22-07 14:50 RalfGross New Issue 11-22-07 15:12 RalfGross Note Added: 0002963 11-22-07 16:19 Dan Langille Status new => assigned 11-22-07 16:19 Dan Langille Assigned To => Dan Langille 11-22-07 16:20 Dan Langille Note Added: 0002964 11-22-07 17:03 Dan Langille Status assigned => closed 11-22-07 17:03 Dan Langille Note Added: 0002965 11-22-07 17:03 Dan Langille Resolution open => not a bug 11-22-07 18:40 RalfGross Status closed => feedback 11-22-07 18:40 RalfGross Resolution not a bug => reopened 11-22-07 18:40 RalfGross Note Added: 0002966 11-23-07 08:03 RalfGross Note Added: 0002972 11-23-07 12:12 RalfGross Note Edited: 0002972 11-23-07 12:15 RalfGross Note Edited: 0002972 11-30-07 10:00 RalfGross Note Added: 0003000 ====================================================================== |