[Bacula-bugs] [Bacula Bug Reports 0002157]: Bacula recycles empty incremental backup volume disrega

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 454-5900

The following issue requires your FEEDBACK. 
====================================================================== 
http://bugs.bacula.org/view.php?id=2157 
====================================================================== 
Reported By:                yasen.mihaylov
Assigned To:                
====================================================================== 
Project:                    Bacula Bug Reports
Issue ID:                   2157
Category:                   Director
Reproducibility:            always
Severity:                   minor
Priority:                   low
Status:                     feedback
====================================================================== 
Date Submitted:             2015-07-30 14:31 BST
Last Modified:              2015-07-30 17:54 BST
====================================================================== 
Summary:                    Bacula recycles empty incremental backup volume
disregarding retention periods.
Description: 
   I have noticed a strange behavior in bacula 5.2.13 included in CentOS 7. I
have set it up to make each backup to a new volume and to recycle them after 40
days. However, if an Incremental volume is empty it gets recycled disregarding
any job, fire or volume retention periods. After the volume is recycled once it
is being kept according to these periods.
   I am attaching my director configuration as well as detailed additional
information.

Steps to Reproduce: 
1) make a full backup
2) make an empty incremental backup (creates empty volume)
3) make another incremental backup (recycles the empty volume)

Additional Information: 
   After some digging I have noticed that there is no record being put in
JobMedia table for the empty volume, so it is considered safe for recycling
since it seems that there are no jobs assosicated to it. However, there is a
record inserted in that table after the volume is recycled.

   It happens in the following way:

   1) A full backup is being done:

30-Jul 08:38 bacula-dir-connectik JobId 1: No prior Full backup Job record
found.
30-Jul 08:38 bacula-dir-connectik JobId 1: No prior or suitable Full backup
found in catalog. Doing FULL backup.
30-Jul 08:38 bacula-dir-connectik JobId 1: Start Backup JobId 1,
Job=backup-local-test.2015-07-30_08.38.12_03
30-Jul 08:38 bacula-dir-connectik JobId 1: Created new Volume "Full0001" in
catalog.
30-Jul 08:38 bacula-dir-connectik JobId 1: Using Device "FileStorage" to write.
30-Jul 08:38 bacula-sd-local JobId 1: Labeled new Volume "Full0001" on device
"FileStorage" (/mnt/vdb1/bacula).
30-Jul 08:38 bacula-sd-local JobId 1: Wrote label to prelabeled Volume
"Full0001" on device "FileStorage" (/mnt/vdb1/bacula)
30-Jul 08:38 bacula-dir-connectik JobId 1: Max Volume jobs=1 exceeded. Marking
Volume "Full0001" as Used.
30-Jul 08:38 bacula-sd-local JobId 1: Elapsed time=00:00:01, Transfer rate=2.921
K Bytes/second
30-Jul 08:38 bacula-dir-connectik JobId 1: Bacula bacula-dir-connectik 5.2.13
(19Jan13):
  Build OS:               x86_64-redhat-linux-gnu unknown unknown
  JobId:                  1
  Job:                    backup-local-test.2015-07-30_08.38.12_03
  Backup Level:           Full (upgraded from Incremental)
  Client:                 "bacula-fd" 5.2.13 (19Jan13)
x86_64-redhat-linux-gnu,unknown,unknown
  FileSet:                "fd-local-fs" 2015-07-30 08:38:12
  Pool:                   "Full" (From Job FullPool override)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "File-local" (From Job resource)
  Scheduled time:         30-Jul-2015 08:38:10
  Start time:             30-Jul-2015 08:38:14
  End time:               30-Jul-2015 08:38:14
  Elapsed time:           0 secs
  Priority:               10
  FD Files Written:       33
  SD Files Written:       33
  FD Bytes Written:       0 (0 B)
  SD Bytes Written:       2,921 (2.921 KB)
  Rate:                   0.0 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         Full0001
  Volume Session Id:      2
  Volume Session Time:    1438177407
  Last Volume Bytes:      3,952 (3.952 KB)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

30-Jul 08:38 bacula-dir-connectik JobId 1: Begin pruning Jobs older than 1 month
10 days .
30-Jul 08:38 bacula-dir-connectik JobId 1: No Jobs found to prune.
30-Jul 08:38 bacula-dir-connectik JobId 1: Begin pruning Files.
30-Jul 08:38 bacula-dir-connectik JobId 1: No Files found to prune.
30-Jul 08:38 bacula-dir-connectik JobId 1: End auto prune.

MariaDB [bacula]> SELECT JobId, Job, Type, Level FROM Job;
+-------+------------------------------------------+------+-------+
| JobId | Job                                      | Type | Level |
+-------+------------------------------------------+------+-------+
|     1 | backup-local-test.2015-07-30_08.38.12_03 | B    | F     |
+-------+------------------------------------------+------+-------+
1 row in set (0.01 sec)

MariaDB [bacula]> SELECT MediaId, VolumeName, MediaType, VolJobs, VolStatus FROM
Media;
+---------+------------+-----------+---------+-----------+
| MediaId | VolumeName | MediaType | VolJobs | VolStatus |
+---------+------------+-----------+---------+-----------+
|       1 | Full0001   | File      |       1 | Used      |
+---------+------------+-----------+---------+-----------+
1 row in set (0.00 sec)

MariaDB [bacula]> SELECT JobMediaId, JobId, MediaId FROM JobMedia;
+------------+-------+---------+
| JobMediaId | JobId | MediaId |
+------------+-------+---------+
|          1 |     1 |       1 |
+------------+-------+---------+
1 row in set (0.00 sec)

  2) A an empty incremental backup is done immediately after the full one:

30-Jul 08:58 bacula-dir-connectik JobId 2: Start Backup JobId 2,
Job=backup-local-test.2015-07-30_08.58.57_04
30-Jul 08:58 bacula-dir-connectik JobId 2: Created new Volume "Incr0002" in
catalog.
30-Jul 08:58 bacula-dir-connectik JobId 2: Using Device "FileStorage" to write.
30-Jul 08:58 bacula-sd-local JobId 2: Labeled new Volume "Incr0002" on device
"FileStorage" (/mnt/vdb1/bacula).
30-Jul 08:58 bacula-sd-local JobId 2: Wrote label to prelabeled Volume
"Incr0002" on device "FileStorage" (/mnt/vdb1/bacula)
30-Jul 08:58 bacula-dir-connectik JobId 2: Max Volume jobs=1 exceeded. Marking
Volume "Incr0002" as Used.
30-Jul 08:58 bacula-sd-local JobId 2: Elapsed time=00:00:01, Transfer rate=0 
Bytes/second
30-Jul 08:58 bacula-dir-connectik JobId 2: Bacula bacula-dir-connectik 5.2.13
(19Jan13):
  Build OS:               x86_64-redhat-linux-gnu unknown unknown
  JobId:                  2
  Job:                    backup-local-test.2015-07-30_08.58.57_04
  Backup Level:           Incremental, since=2015-07-30 08:38:14
  Client:                 "bacula-fd" 5.2.13 (19Jan13)
x86_64-redhat-linux-gnu,unknown,unknown
  FileSet:                "fd-local-fs" 2015-07-30 08:38:12
  Pool:                   "Incr" (From Job IncPool override)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "File-local" (From Job resource)
  Scheduled time:         30-Jul-2015 08:58:56
  Start time:             30-Jul-2015 08:58:59
  End time:               30-Jul-2015 08:58:59
  Elapsed time:           0 secs
  Priority:               10
  FD Files Written:       0
  SD Files Written:       0
  FD Bytes Written:       0 (0 B)
  SD Bytes Written:       0 (0 B)
  Rate:                   0.0 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         
  Volume Session Id:      3
  Volume Session Time:    1438177407
  Last Volume Bytes:      635 (635 B)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

30-Jul 08:58 bacula-dir-connectik JobId 2: Begin pruning Jobs older than 1 month
10 days .
30-Jul 08:58 bacula-dir-connectik JobId 2: No Jobs found to prune.
30-Jul 08:58 bacula-dir-connectik JobId 2: Begin pruning Files.
30-Jul 08:58 bacula-dir-connectik JobId 2: No Files found to prune.
30-Jul 08:58 bacula-dir-connectik JobId 2: End auto prune.

MariaDB [bacula]> SELECT JobId, Job, Type, Level FROM Job;
+-------+------------------------------------------+------+-------+
| JobId | Job                                      | Type | Level |
+-------+------------------------------------------+------+-------+
|     1 | backup-local-test.2015-07-30_08.38.12_03 | B    | F     |
|     2 | backup-local-test.2015-07-30_08.58.57_04 | B    | I     |
+-------+------------------------------------------+------+-------+
2 rows in set (0.00 sec)

MariaDB [bacula]> SELECT MediaId, VolumeName, MediaType, VolJobs, VolStatus FROM
Media;
+---------+------------+-----------+---------+-----------+
| MediaId | VolumeName | MediaType | VolJobs | VolStatus |
+---------+------------+-----------+---------+-----------+
|       1 | Full0001   | File      |       1 | Used      |
|       2 | Incr0002   | File      |       1 | Used      |
+---------+------------+-----------+---------+-----------+
2 rows in set (0.00 sec)

MariaDB [bacula]> SELECT JobMediaId, JobId, MediaId FROM JobMedia;
+------------+-------+---------+
| JobMediaId | JobId | MediaId |
+------------+-------+---------+
|          1 |     1 |       1 |
+------------+-------+---------+
1 row in set (0.00 sec)
!!!) No record here

   3) And the next Incremental backup recycles the volume:

30-Jul 09:01 bacula-dir-connectik JobId 3: Start Backup JobId 3,
Job=backup-local-test.2015-07-30_09.01.13_05
30-Jul 09:01 bacula-dir-connectik JobId 3: There are no more Jobs associated
with Volume "Incr0002". Marking it purged.
30-Jul 09:01 bacula-dir-connectik JobId 3: All records pruned from Volume
"Incr0002"; marking it "Purged"
30-Jul 09:01 bacula-dir-connectik JobId 3: Recycled volume "Incr0002"
30-Jul 09:01 bacula-dir-connectik JobId 3: Using Device "FileStorage" to write.
30-Jul 09:01 bacula-sd-local JobId 3: Recycled volume "Incr0002" on device
"FileStorage" (/mnt/vdb1/bacula), all previous data lost.
30-Jul 09:01 bacula-dir-connectik JobId 3: Max Volume jobs=1 exceeded. Marking
Volume "Incr0002" as Used.
30-Jul 09:01 bacula-sd-local JobId 3: Elapsed time=00:00:01, Transfer rate=0 
Bytes/second
30-Jul 09:01 bacula-dir-connectik JobId 3: Bacula bacula-dir-connectik 5.2.13
(19Jan13):
  Build OS:               x86_64-redhat-linux-gnu unknown unknown
  JobId:                  3
  Job:                    backup-local-test.2015-07-30_09.01.13_05
  Backup Level:           Incremental, since=2015-07-30 08:58:59
  Client:                 "bacula-fd" 5.2.13 (19Jan13)
x86_64-redhat-linux-gnu,unknown,unknown
  FileSet:                "fd-local-fs" 2015-07-30 08:38:12
  Pool:                   "Incr" (From Job IncPool override)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "File-local" (From Job resource)
  Scheduled time:         30-Jul-2015 09:01:12
  Start time:             30-Jul-2015 09:01:15
  End time:               30-Jul-2015 09:01:16
  Elapsed time:           1 sec
  Priority:               10
  FD Files Written:       0
  SD Files Written:       0
  FD Bytes Written:       0 (0 B)
  SD Bytes Written:       0 (0 B)
  Rate:                   0.0 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         Incr0002
  Volume Session Id:      4
  Volume Session Time:    1438177407
  Last Volume Bytes:      635 (635 B)
  Non-fatal FD errors:    0
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Termination:            Backup OK

30-Jul 09:01 bacula-dir-connectik JobId 3: Begin pruning Jobs older than 1 month
10 days .
30-Jul 09:01 bacula-dir-connectik JobId 3: No Jobs found to prune.
30-Jul 09:01 bacula-dir-connectik JobId 3: Begin pruning Files.
30-Jul 09:01 bacula-dir-connectik JobId 3: No Files found to prune.
30-Jul 09:01 bacula-dir-connectik JobId 3: End auto prune.

MariaDB [bacula]> SELECT JobId, Job, Type, Level FROM Job;
+-------+------------------------------------------+------+-------+
| JobId | Job                                      | Type | Level |
+-------+------------------------------------------+------+-------+
|     1 | backup-local-test.2015-07-30_08.38.12_03 | B    | F     |
|     2 | backup-local-test.2015-07-30_08.58.57_04 | B    | I     |
|     3 | backup-local-test.2015-07-30_09.01.13_05 | B    | I     |
+-------+------------------------------------------+------+-------+
3 rows in set (0.00 sec)

MariaDB [bacula]> SELECT MediaId, VolumeName, MediaType, VolJobs, VolStatus FROM
Media;
+---------+------------+-----------+---------+-----------+
| MediaId | VolumeName | MediaType | VolJobs | VolStatus |
+---------+------------+-----------+---------+-----------+
|       1 | Full0001   | File      |       1 | Used      |
|       2 | Incr0002   | File      |       1 | Used      |
+---------+------------+-----------+---------+-----------+
2 rows in set (0.00 sec)

MariaDB [bacula]> SELECT JobMediaId, JobId, MediaId FROM JobMedia;
+------------+-------+---------+
| JobMediaId | JobId | MediaId |
+------------+-------+---------+
|          1 |     1 |       1 |
|          2 |     3 |       2 |
+------------+-------+---------+
2 rows in set (0.00 sec)
!!!) Now we have a record here

====================================================================== 

---------------------------------------------------------------------- 
 (0007134) kern (administrator) - 2015-07-30 17:54
 http://bugs.bacula.org/view.php?id=2157#c7134 
---------------------------------------------------------------------- 
This seems like a sort of nonsense bug to me.  First if you write an empty
Incremental job to a volume, the volume will not be marked Used.  It will still
be left in append mode unless you set Max Vol Jobs to one.  At that point it is
marked Used, and thereafter no matter what the retention period if all the
JobMedia records are gone (removed) or there were none the, the volume can be
recycled.

What is the problem?  This seems to me to be correct behavior. 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2015-07-30 14:31 yasen.mihaylov New Issue                                    
2015-07-30 14:31 yasen.mihaylov File Added: bacula-dir.conf                    
2015-07-30 17:54 kern           Note Added: 0007134                          
2015-07-30 17:54 kern           Status                   new => feedback     
======================================================================

[Bacula-bugs] [Bacula Bug Reports 0002157]: Bacula recycles empty incremental backup volume disrega

[Bacula-bugs] [Bacula Bug Reports 0002157]: Bacula recycles empty incremental backup volume disregarding retention periods.