Re: Failure with VirtualFull causing next job to be a Full???

Martin Simmons <[email protected]>
Newsgroups gmane.comp.bacula.user
Message-ID <[email protected]>
"No prior or suitable Full backup found in catalog. Doing FULL backup" means
that it didn't find a Full backup for some reason.

The output from the following SQL command might be useful (maybe some other
Name= if you have a more recent example for a different job):

SELECT StartTime, JobID, Job, PriorJob, JobStatus, Type, Level, ClientId FROM Job WHERE Name='Taco-Data-E' ORDER BY StartTime DESC;

__Martin


>>>>> On Thu, 12 Jun 2025 14:42:24 -0400, John Lockard said:
> 
> My Fulls have a 60 day lifespan.
> Full was last run May 18.
> Fileset was last modified May 2.
> Bacula version on DIR, SD and FD are all 15.0.3
> 
> Log from the new, elevated job.
> +---------------------+----------------------------------------------------------------------------------------------------+
> | time                | logtext                                                                                              |
> +---------------------+----------------------------------------------------------------------------------------------------+
> | 2025-06-12 10:24:38 | bacula-dir JobId 4129: No prior or suitable Full backup found in catalog. Doing FULL backup.         |
> | 2025-06-12 10:24:40 | bacula-dir JobId 4129: Start Backup JobId 4129, Job=Taco-Data-E.2025-06-12_10.24.38_27               |
> | 2025-06-12 10:24:40 | bacula-dir JobId 4129: Connected to Storage "FileChanger" at "http://si-scott.miserver.it.umich.edu:9103/"si-scott.miserver.it.umich.edu:9103 with TLS |
> | 2025-06-12 10:24:40 | bacula-dir JobId 4129: Using Device "FileChanger-Dev7" to write.                                     |
> | 2025-06-12 10:24:40 | bacula-dir JobId 4129: Connected to Client "taco" at "http://taco.si.umich.edu:9102/"taco.si.umich.edu:9102 with TLS                 |
> | 2025-06-12 10:24:40 | taco JobId 4129: Connected to Storage at "http://si-scott.miserver.it.umich.edu:9103/"si-scott.miserver.it.umich.edu:9103 with TLS                |
> | 2025-06-12 10:24:42 | bacula-sd JobId 4129: Recycled volume "Taco-F-0803" on File device "FileChanger-Dev7" (/mnt/nfs/locker/umsi-locker-backups/storage/), all previous data lost. |
> | 2025-06-12 10:24:42 | bacula-dir JobId 4129: Max Volume jobs=1 exceeded. Marking Volume "Taco-F-0803" as Used.             |
> | 2025-06-12 10:41:11 | bacula-sd JobId 4129: End of medium on Volume "Taco-F-0803" Bytes=107,374,159,824 Blocks=1,664,406 at 12-Jun-2025 10:41. |
> | 2025-06-12 10:41:13 | bacula-sd JobId 4129: Recycled volume "Taco-F-0806" on File device "FileChanger-Dev7" (/mnt/nfs/locker/umsi-locker-backups/storage/), all previous data lost. |
> | 2025-06-12 10:41:13 | bacula-dir JobId 4129: Max Volume jobs=1 exceeded. Marking Volume "Taco-F-0806" as Used.             |
> | 2025-06-12 10:41:13 | bacula-sd JobId 4129: New volume "Taco-F-0806" mounted on device "FileChanger-Dev7" (/mnt/nfs/locker/umsi-locker-backups/storage/) at 12-Jun-2025 10:41. |
> | 2025-06-12 10:57:33 | bacula-sd JobId 4129: End of medium on Volume "Taco-F-0806" Bytes=107,374,159,833 Blocks=1,664,406 at 12-Jun-2025 10:57. |
> | 2025-06-12 10:57:34 | bacula-sd JobId 4129: Recycled volume "Taco-F-0808" on File device "FileChanger-Dev7" (/mnt/nfs/locker/umsi-locker-backups/storage/), all previous data lost. |
> | 2025-06-12 10:57:34 | bacula-dir JobId 4129: Max Volume jobs=1 exceeded. Marking Volume "Taco-F-0808" as Used.             |
> | 2025-06-12 10:57:34 | bacula-sd JobId 4129: New volume "Taco-F-0808" mounted on device "FileChanger-Dev7" (/mnt/nfs/locker/umsi-locker-backups/storage/) at 12-Jun-2025 10:57. |
> | 2025-06-12 11:25:13 | bacula-sd JobId 4129: End of medium on Volume "Taco-F-0808" Bytes=107,374,158,154 Blocks=1,664,406 at 12-Jun-2025 11:25. |
> | 2025-06-12 11:25:14 | bacula-sd JobId 4129: Recycled volume "Taco-F-0810" on File device "FileChanger-Dev7" (/mnt/nfs/locker/umsi-locker-backups/storage/), all previous data lost. |
> | 2025-06-12 11:25:14 | bacula-dir JobId 4129: Max Volume jobs=1 exceeded. Marking Volume "Taco-F-0810" as Used.             |
> | 2025-06-12 11:25:14 | bacula-sd JobId 4129: New volume "Taco-F-0810" mounted on device "FileChanger-Dev7" (/mnt/nfs/locker/umsi-locker-backups/storage/) at 12-Jun-2025 11:25. |
> | 2025-06-12 11:57:59 | bacula-sd JobId 4129: End of medium on Volume "Taco-F-0810" Bytes=107,374,157,610 Blocks=1,664,406 at 12-Jun-2025 11:57. |
> | 2025-06-12 11:58:01 | bacula-sd JobId 4129: Recycled volume "Taco-F-0813" on File device "FileChanger-Dev7" (/mnt/nfs/locker/umsi-locker-backups/storage/), all previous data lost. |
> | 2025-06-12 11:58:01 | bacula-dir JobId 4129: Max Volume jobs=1 exceeded. Marking Volume "Taco-F-0813" as Used.             |
> | 2025-06-12 11:58:01 | bacula-sd JobId 4129: New volume "Taco-F-0813" mounted on device "FileChanger-Dev7" (/mnt/nfs/locker/umsi-locker-backups/storage/) at 12-Jun-2025 11:58. |
> +---------------------+----------------------------------------------------------------------------------------------------+
> 
> Log from previous, failed, VirtualFull job.
> +---------------------+----------------------------------------------------------------------------------------------------+
> | time                | logtext                                                                                              |
> +---------------------+----------------------------------------------------------------------------------------------------+
> | 2025-06-12 06:38:42 | bacula-dir JobId 4126: Start Virtual Backup JobId 4126, Job=Taco-Data-E.2025-06-11_21.15.00_22       |
> | 2025-06-12 06:38:42 | bacula-dir JobId 4126: Consolidating JobIds=3331,3627,3647,3707,3736,3763,3790,3817                  |
> | 2025-06-12 06:39:09 | bacula-dir JobId 4126: Found 1499732 files to consolidate into Virtual Full.                         |
> | 2025-06-12 06:39:09 | bacula-dir JobId 4126: Connected to Storage "FileChanger" at "http://si-scott.miserver.it.umich.edu:9103/"si-scott.miserver.it.umich.edu:9103 with TLS |
> | 2025-06-12 06:39:09 | bacula-dir JobId 4126: Using Device "FileChanger-Dev1" to read.                                      |
> | 2025-06-12 06:39:09 | bacula-dir JobId 4126: There are no more Jobs associated with Volume "Taco-F-0782". Marking it purged. |
> | 2025-06-12 06:39:09 | bacula-dir JobId 4126: All records pruned from Volume "Taco-F-0782"; marking it "Purged"             |
> | 2025-06-12 06:39:09 | bacula-dir JobId 4126: Recycled volume "Taco-F-0782"                                                 |
> | 2025-06-12 06:39:09 | bacula-dir JobId 4126: Using Device "FileChanger-Dev4" to write.                                     |
> | 2025-06-12 06:39:09 | bacula-sd JobId 4126: Ready to read from volume "Taco-F-0803" on File device "FileChanger-Dev1" (/mnt/nfs/locker/umsi-locker-backups/storage/). |
> | 2025-06-12 06:39:10 | bacula-sd JobId 4126: Recycled volume "Taco-F-0782" on File device "FileChanger-Dev4" (/mnt/nfs/locker/umsi-locker-backups/storage/), all previous data lost. |
> | 2025-06-12 06:39:10 | bacula-dir JobId 4126: Max Volume jobs=1 exceeded. Marking Volume "Taco-F-0782" as Used.             |
> | 2025-06-12 06:39:10 | bacula-sd JobId 4126: Forward spacing Volume "Taco-F-0803" to addr=268                               |
> | 2025-06-12 06:50:50 | bacula-sd JobId 4126: End of Volume "Taco-F-0803" at addr=107374159765 on device "FileChanger-Dev1" (/mnt/nfs/locker/umsi-locker-backups/storage/). |
> | 2025-06-12 06:50:50 | bacula-sd JobId 4126: Ready to read from volume "Taco-F-0806" on File device "FileChanger-Dev1" (/mnt/nfs/locker/umsi-locker-backups/storage/). |
> | 2025-06-12 06:50:50 | bacula-sd JobId 4126: Forward spacing Volume "Taco-F-0806" to addr=268                               |
> | 2025-06-12 06:50:50 | bacula-sd JobId 4126: End of medium on Volume "Taco-F-0782" Bytes=107,374,159,749 Blocks=1,664,406 at 12-Jun-2025 06:50. |
> | 2025-06-12 06:50:54 | bacula-dir JobId 4126: There are no more Jobs associated with Volume "Taco-F-0786". Marking it purged. |
> | 2025-06-12 06:50:54 | bacula-dir JobId 4126: All records pruned from Volume "Taco-F-0786"; marking it "Purged"             |
> | 2025-06-12 06:50:54 | bacula-dir JobId 4126: Recycled volume "Taco-F-0786"                                                 |
>                                           |
> ...some equally similar lines removed...
>                                                |
> | 2025-06-12 07:44:34 | bacula-sd JobId 4126: Recycled volume "Taco-F-0801" on File device "FileChanger-Dev4" (/mnt/nfs/locker/umsi-locker-backups/storage/), all previous data lost. |
> | 2025-06-12 07:44:34 | bacula-dir JobId 4126: Max Volume jobs=1 exceeded. Marking Volume "Taco-F-0801" as Used.             |
> | 2025-06-12 07:44:34 | bacula-sd JobId 4126: New volume "Taco-F-0801" mounted on device "FileChanger-Dev4" (/mnt/nfs/locker/umsi-locker-backups/storage/) at 12-Jun-2025 07:44. |
> | 2025-06-12 07:50:37 | bacula-sd JobId 4126: End of Volume "Taco-F-0817" at addr=107374155839 on device "FileChanger-Dev1" (/mnt/nfs/locker/umsi-locker-backups/storage/). |
> | 2025-06-12 07:50:37 | bacula-sd JobId 4126: Ready to read from volume "Taco-F-0819" on File device "FileChanger-Dev1" (/mnt/nfs/locker/umsi-locker-backups/storage/). |
> | 2025-06-12 07:50:37 | bacula-sd JobId 4126: Forward spacing Volume "Taco-F-0819" to addr=268                               |
> | 2025-06-12 07:55:05 | bacula-sd JobId 4126: End of medium on Volume "Taco-F-0801" Bytes=107,374,156,038 Blocks=1,664,406 at 12-Jun-2025 07:55. |
> | 2025-06-12 07:55:12 | bacula-sd JobId 4126: Job Taco-Data-E.2025-06-11_21.15.00_22 is waiting. Cannot find any appendable volumes.
> Please use the "label" command to create a new Volume for:
>     Storage:      "FileChanger-Dev4" (/mnt/nfs/locker/umsi-locker-backups/storage/)
>     Pool:         Taco-Full
>     Media type:   File |
> | 2025-06-12 08:55:15 | bacula-sd JobId 4126: Job Taco-Data-E.2025-06-11_21.15.00_22 is waiting. Cannot find any appendable volumes.
> Please use the "label" command to create a new Volume for:
>     Storage:      "FileChanger-Dev4" (/mnt/nfs/locker/umsi-locker-backups/storage/)
>     Pool:         Taco-Full
>     Media type:   File |
> | 2025-06-12 10:24:13 | bacula-sd JobId 4126: askdir.c:878 Job was stopped by the user.                                      |
> | 2025-06-12 10:24:13 | bacula-dir JobId 4126: Error: Unable to copy objects ERR=                                            |
> | 2025-06-12 10:24:13 | bacula-dir JobId 4126: Bacula bacula-dir 15.0.3 (25Mar25):
>   Build OS:               x86_64-pc-linux-gnu ubuntu 24.04
>   JobId:                  4126
>   Job:                    Taco-Data-E.2025-06-11_21.15.00_22
>   Backup Level:           Virtual Full
>   Client:                 "taco" 15.0.3 (25Mar25) x86_64-pc-linux-gnu,ubuntu,22.04
>   FileSet:                "Taco-Data-E" 2025-05-16 16:19:24
>   Pool:                   "Taco-Full" (From Pool's NextPool resource)
>   Catalog:                "MyCatalog" (From Client resource)
>   Storage:                "FileChanger" (From Pool's NextPool resource)
>   Scheduled time:         11-Jun-2025 21:15:00
>   Start time:             03-Jun-2025 23:47:44
>   End time:               03-Jun-2025 23:49:31
>   Elapsed time:           3 hours 45 mins 4 secs
>   Priority:               10
>   SD Files Written:       0
>   SD Bytes Written:       0 (0 B)
>   Rate:                   0.0 KB/s
>   Volume name(s):         Taco-F-0782|Taco-F-0786|Taco-F-0789|Taco-F-0791|Taco-F-0796|Taco-F-0798|Taco-F-0801
>   Volume Session Id:      79
>   Volume Session Time:    1749606283
>   Last Volume Bytes:      107,374,156,038 (107.3 GB)
>   SD Errors:              0
>   SD termination status:  Canceled
>   Termination:            Backup Canceled |
> +---------------------+----------------------------------------------------------------------------------------------------+
> 
> On Thu, Jun 12, 2025 at 12:13 PM Bill Arlofski via Bacula-users <"mailto:[email protected]"[email protected]> wrote:
> 
> On 6/12/25 9:24 AM, John Lockard wrote:
> 
>  >
> 
> > I've seen this a couple of times, and haven't created a small job to test, but it appears that when I'm running a
> > VirtualFull, and it fails for whatever reason, the next time a job for that FileSet runs it gets elevated to a Full and
> > states that there is no previous Full.
> >
> > Is this a normal reaction to a Failed Virtual Full?
> 
> >
> 
> > Thanks,
> 
> > -John
> 
> Hello John,
> 
> My first guess is that your original Full may have simply fallen out of its retention period, and it is just a coincidence
> that you get this backup level upgrade after a failed VFull. :)
> A failed VFull does nothing to the original Full in the catalog, so this is strange.
> What is the exact message about the job being upgraded?
> Any chance the Fileset had been edited in this timeline too?
> If you are using a semi-recent version of Bacula, the job summary has some details about the last time a fileset was modified.
> I guess I am saying we will need some
> more information. :)
> 
> Best regards,
> 
> Bill
> 
> --
> 
> Bill Arlofski
> "mailto:[email protected]"[email protected]
> 
> _______________________________________________
> 
> Bacula-users mailing list
> "mailto:[email protected]"[email protected]
> "https://lists.sourceforge.net/lists/listinfo/bacula-users"https://lists.sourceforge.net/lists/listinfo/bacula-users
> 
> 


_______________________________________________
Bacula-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/bacula-users
lmpx.com only provides a reader for public news (NNTP) servers. It is not affiliated with the servers or forums shown here and is not responsible for the content of articles, which is written by their respective authors.