[Bacula-users] Strange errors: Warning: Director wanted Volume "foo", Current Volume "bar" not acceptable because...

[Rob G. <ro...@cr...>]

[edit]: sending this in several messages because of list message length
limit

I have a problem, and I don't know what to think about it.

Bacula 15.0.2, running on Rocky linux 9.
This is a testing system running in a VM on a synology NAS. Volumes are
stored on the NAS in a samba share.

Occasionally, a job will give me warning messages like this:
      20-Mar 23:06 td-bacula-dir JobId 663: Created new
Volume="Synology-Local-Inc-0251", Pool="Synology-Local-Inc",
MediaType="Synology-Local" in catalog.


*      20-Mar 23:06 td-bacula-sd JobId 663: Warning: Director wanted Volume
"Synology-Local-Inc-0251".          Current Volume
"Synology-Local-Inc-0250" not acceptable because:          1998 Volume
"Synology-Local-Inc-0250" catalog status is Used, but should be Append,
Purged or Recycle.*
      20-Mar 23:06 td-bacula-sd JobId 663: Labeled new Volume
"Synology-Local-Inc-0251" on File device "Synology-Local-004"
(/mnt/synology/bacula/Synology-Local).
      20-Mar 23:06 td-bacula-sd JobId 663: Wrote label to prelabeled Volume
"Synology-Local-Inc-0251" on File device "Synology-Local-004"
(/mnt/synology/bacula/Synology-Local)
      20-Mar 23:06 td-bacula-dir JobId 663: Max Volume jobs=1 exceeded.
Marking Volume "Synology-Local-Inc-0251" as Used.

*bls shows that jobid 662 wrote data to volume 250 AND 251. I have
MaxVolumeJobs=1 set, so this shouldn't have happened. *

According an awk of my bacula.log, this has happened a number of times for
a number of clients since this system was last reset in February (clear
catalog, delete all volumes, rerun all jobs). I get messages like this for
jobs ran against both windows and linux clients. While in this case, the
issues were preceeded by me deleting a job, I don't think that this was the
cause for every time this happened. I could be wrong. I did delete a number
of jobs in error or cancelled state at some previous time.

Full details below. I suspect *the* *most useful information starts after
point 9* in the timeline, *and in the analysis below*. bacula-dir.conf
details after that. Sorry for the huge info dump. Hopefully it's somewhat
readable.

*How can I find out what is going wrong here?* I am concerned that this
could lead to loss of data. At minimum, bacula appears to be confused about
the state of volume 250. It has no lastwritten date, and an erroneous
volume byte count. I did successfully run a restore the morning after I
found these errors, but I have no idea if the data from the restore is good
or not. The restore did pull in volumes 250 and 251, so despite the
confusing output displayed below, bacula did know that it needed data from
those volumes.

*Timeline:*
The time is roughly Mar 20, 18:00
0. I want to test restoring from copy jobs. I create a new text file on
testing system "win11-base".
1. I run JobId 655, local Incremental backup of win11-base. It labels
volume Synology-Local-Inc-0248, marks it used, and backs up successfully.
2. I run Copy-control job with jobid 656, targeting pool uncopied jobs for
Synology-Local-Inc pool.
3. Copy control launches jobid 657, targeting previously ran jobid 655. It
backs up successfully to the cloud, using volume B2-TGU-Inc-0249
4. I ran a restore jobid 658, targeting the local job ran in step 1. I
successfully restore my text file.
5. I verify all jobs listed above completed successfully, and take a
snapshot of the VM bacula is running inside. My goal is to promote jobid
657 from a copy job to a backup job, then restore the text file I created
in step 0. I delete jobid 655, and in bacularis verify that volume
associated with that job, Synology-Local-Inc-0248, now shows no associated
jobs. I click "prune" in bacularis for this volume. I see the volume status
for this volume change from "used" to "purge". I verified in bacularis job
history pane that Jobid 657, copying to the cloud is now of type 'backup'.
6. I ran restore jobid 659, targeting the newly promoted cloud backup with
jobid 657. My text file is successfully restored from the cloud volume.
The time is now Mar 20, 21:36. I am done experimenting for the night.
The time is now Mar 20, 23:05. Regularly scheduled jobs start.
7. Scheduled JobId 660 runs, Job=Synology-shares-job. It recycles the
previously pruned volume Synology-Local-Inc-0248 from jobid 655. This
backup has 0 files/bytes to back up, so it doesn't use a volume.
8. Scheduled JobId 661 runs, Job=td-bacula-job. It also recycles the
previously pruned volume Synology-Local-Inc-0248 from jobid 655. This
backup uses volume Synology-Local-Inc-0248 for itself.
9. Scheduled JobId 662 runs, Job=Backup-win11-base-fd-job. It says:
      20-Mar 23:05 td-bacula-dir JobId 662: Created new
Volume="Synology-Local-Inc-0250", Pool="Synology-Local-Inc",
MediaType="Synology-Local" in catalog.
      20-Mar 23:05 td-bacula-sd JobId 662: Labeled new Volume
"Synology-Local-Inc-0250" on File device "Synology-Local-004"
(/mnt/synology/bacula/Synology-Local).
      20-Mar 23:05 td-bacula-sd JobId 662: Wrote label to prelabeled Volume
"Synology-Local-Inc-0250" on File device "Synology-Local-004"
(/mnt/synology/bacula/Synology-Local)
      20-Mar 23:05 td-bacula-dir JobId 662: Max Volume jobs=1 exceeded.
Marking Volume "Synology-Local-Inc-0250" as Used.
   The joblog only shows this text for a volume being created and used, but
in the status at the end also shows volume Synology-Local-Inc-0251!
      "Volume name(s):
Synology-Local-Inc-0250|Synology-Local-Inc-0251"
10. Scheduled JobId 663 runs, Job=Backup-akita-job. It complains:
      20-Mar 23:06 td-bacula-dir JobId 663: Created new
Volume="Synology-Local-Inc-0251", Pool="Synology-Local-Inc",
MediaType="Synology-Local" in catalog.
      20-Mar 23:06 td-bacula-sd JobId 663: Warning: Director wanted Volume
"Synology-Local-Inc-0251".
          Current Volume "Synology-Local-Inc-0250" not acceptable because:
          1998 Volume "Synology-Local-Inc-0250" catalog status is Used, but
should be Append, Purged or Recycle.
      20-Mar 23:06 td-bacula-sd JobId 663: Labeled new Volume
"Synology-Local-Inc-0251" on File device "Synology-Local-004"
(/mnt/synology/bacula/Synology-Local).
      20-Mar 23:06 td-bacula-sd JobId 663: Wrote label to prelabeled Volume
"Synology-Local-Inc-0251" on File device "Synology-Local-004"
(/mnt/synology/bacula/Synology-Local)
      20-Mar 23:06 td-bacula-dir JobId 663: Max Volume jobs=1 exceeded.
Marking Volume "Synology-Local-Inc-0251" as Used.
    Volumes used shows only volume Synology-Local-Inc-0251.
11. Other scheduled jobs run, first copy control and copy jobs, then cloud
volume part sweeper script, then disaster recovery local and cloud jobs,
then disaster recovery cloud volume part sweeper script. All that appears
to go correctly.
12. I check this in the morning and see the above warning in the bacularis
log.

Regards,
Robert Gerber
402-237-8692
ro...@cr...