*Analysis:*
in bconsole with a Gary's oldest volume query, Volume
Synology-Local-Inc-0250 shows status of 'purged', no 'lastwritten' date, no
expiry date, and size of 278b.
*query 2
Using Catalog "MyCatalog"
+---------+--------------------------+--------+------------------------------+------+-----------+---------------------+---------------------+-----------+------------+-------------------+
| mediaid | volumename | poolid | pool
| slot | inchanger | firstwritten | lastwritten |
volstatus | expiresin | volbytes |
+---------+--------------------------+--------+------------------------------+------+-----------+---------------------+---------------------+-----------+------------+-------------------+
--->8---
| 251 | Synology-Local-Inc-0251 | 3 | Synology-Local-Inc
| 0 | f | 2025-03-20 23:05:11 | 2025-03-20 23:33:28 | Used
| 15,514,832 | 105,688,435,176 |
--->8---
| 250 | Synology-Local-Inc-0250 | 3 | Synology-Local-Inc
| 0 | f | 2025-03-20 23:05:05 | | Used
| 0 | 278 |
| 7 | Synology-Local-Inc-0007 | 3 | Synology-Local-Inc
| 0 | f | 2025-02-18 12:56:46 | | Used
| 0 | 278 |
| 93 | Synology-Local-Inc-0093 | 3 | Synology-Local-Inc
| 0 | f | 2025-02-26 23:05:06 | | Used
| 0 | 278 |
+---------+--------------------------+--------+------------------------------+------+-----------+---------------------+---------------------+-----------+------------+-------------------+
However, an ls of the volumes in question shows that volume 250 contains
around 389M of data, not 278B.
[gerber@td-bacula ~]$ ls -lah
/mnt/synology/bacula/Synology-Local/Synology-Local-Inc-025[0-1]
-rwxrwx---. 1 root smb_backup 389M Mar 20 23:06
/mnt/synology/bacula/Synology-Local/Synology-Local-Inc-0250
-rwxrwx---. 1 root smb_backup 99G Mar 20 23:33
/mnt/synology/bacula/Synology-Local/Synology-Local-Inc-0251
In bacularis I checked jobs on volumes Synology-Local-Inc-0250 and
Synology-Local-Inc-0251.
Volume Synology-Local-Inc-0250 shows no jobs on volume.
Synology-Local-Inc-025 shows jobs 662 and 663 have data on this volume.
This should not happen because my jobdefs specify only one job per volume.
I check the job bytes for jobs 662 and 663. Volume bytes reported for
volume 251 exactly matches the bytes reported in the joblog for jobid 663.
This would suggest that the data from job 662 is NOT in volume 251.
*list jobs
+-------+-------------------------------------------------+---------------------+------+-------+-----------+-------------------+-----------+
| jobid | name | starttime
| type | level | jobfiles | jobbytes | jobstatus |
+-------+-------------------------------------------------+---------------------+------+-------+-----------+-------------------+-----------+
--->8---
| 662 | Backup-win11-base-fd-job | 2025-03-20
23:05:05 | B | I | 1,538 | 523,164,461 | T |
--->8---
| 663 | Backup-akita-job | 2025-03-20
23:05:11 | B | I | 23,537 | 105,473,900,553 | T |
--->8---
I ran bls against volumes 250 and 251. Volume 250 shows job start lines for
jobid 662, but no job termination lines.
Volume 251 starts with a job termination line for jobid 663, then the
expected job start and job termination lines for jobid 663.
gerber@td-bacula ~]$ bls -c /opt/bacula/etc/bacula-sd.conf
/mnt/synology/bacula/Synology-Local/Synology-Local-Inc-0250 -j
bls: butil.c:300-0 Using device: "/mnt/synology/bacula/Synology-Local"
for reading.
25-Mar 08:44 bls JobId 0: Ready to read from volume
"Synology-Local-Inc-0250" on File device "Synology-Local-001"
(/mnt/synology/bacula/Synology-Local).
Volume Record: File:blk=0:0 SessId=7 SessTime=1742475387 JobId=0
DataLen=234
Begin Job Session Record: File:blk=0:0 SessId=7 SessTime=1742475387
JobId=662
Job=Backup-win11-base-fd-job.2025-03-20_23.05.01_40 Date=20-Mar-2025
23:05:19 Level=I Type=B
25-Mar 08:44 bls JobId 0: End of Volume "Synology-Local-Inc-0250" at
addr=407716118 on device "Synology-Local-001"
(/mnt/synology/bacula/Synology-Local).
[gerber@td-bacula ~]$ bls -c /opt/bacula/etc/bacula-sd.conf
/mnt/synology/bacula/Synology-Local/Synology-Local-Inc-0251 -j
bls: butil.c:300-0 Using device: "/mnt/synology/bacula/Synology-Local"
for reading.
25-Mar 08:44 bls JobId 0: Ready to read from volume
"Synology-Local-Inc-0251" on File device "Synology-Local-001"
(/mnt/synology/bacula/Synology-Local).
Volume Record: File:blk=0:0 SessId=8 SessTime=1742475387 JobId=0
DataLen=234
End Job Session Record: File:blk=0:0 SessId=7 SessTime=1742475387
JobId=662
Date=20-Mar-2025 23:08:45 Level=I Type=B Files=1,538 Bytes=523,539,356
Errors=0 Status=T
Begin Job Session Record: File:blk=0:0 SessId=8 SessTime=1742475387
JobId=663
Job=Backup-akita-job.2025-03-20_23.05.01_41 Date=20-Mar-2025 23:06:42
Level=I Type=B
End Job Session Record: File:blk=0:0 SessId=8 SessTime=1742475387
JobId=663
Date=20-Mar-2025 23:33:11 Level=I Type=B Files=23,537
Bytes=105,479,254,008 Errors=0 Status=T
25-Mar 08:52 bls JobId 0: End of Volume "Synology-Local-Inc-0251" at
addr=105688435176 on device "Synology-Local-001"
(/mnt/synology/bacula/Synology-Local).
bls -v shows that jobid 662 did write a number of files to volume 251.
So my questions:
What happened here?
It appears that for jobid 662, bacula didn't properly close volume file
250, and finished its work in volume 251. It did not mark volume 251 as
used, even though my jobdefs specify one volume per job.
Then jobid 663 went to do things, found something odd about 250 (which
should never have been an option, since it was set to status Used), and
then used volume 251 (which is reasonable, I guess, since volume 251 wasn't
in status 'used').
Additionally, according to the joblogs, jobid 662 didn't actually create
volume 251 itself, but this volume was instead created by jobid 663.
However, bls -v shows that there are a number of (small) files from jobid
662 on volume 251. How could files from jobid 662 be written to a volume
created by later jobid 663?
awk of my bacula.log shows this problem has been occurring a number of
times, periodically.
[gerber@td-bacula ~]$ awk '/Connected to Client/ {prev=$0} /Warning:
Director wanted Volume/ {print prev; print}' /opt/bacula/log/bacula.log
--->8--- (removed various jobs from January - mid-February, before I reset
this system again. I cannot investigate these because the volumes and
bacula database are gone.)
26-Feb 23:05 td-bacula-dir JobId 243: Connected to Client "akita-fd" at
akita.3vlnt:9102 with TLS
26-Feb 23:06 td-bacula-sd JobId 243: Warning: Director wanted Volume
"Synology-Local-Inc-0094".
20-Mar 23:05 td-bacula-dir JobId 663: Connected to Client "akita-fd" at
akita.3vlnt:9102 with TLS
20-Mar 23:06 td-bacula-sd JobId 663: Warning: Director wanted Volume
"Synology-Local-Inc-0251".
another awk for jobs with multiple volumes finds a much more limited scope.
It occurred to me that just because any one job issued a warning like in
the output above, this doesn't mean that the same thing happened before it.
So I searched to find jobs with multiple volumes.
[gerber@td-bacula ~]$ awk '/Start Backup JobId/ {prev=$0} /Volume
name\(s\):.*\|/ {print prev; print}' /opt/bacula/log/bacula.log
--->8--- (removed various jobs from January - mid-February, before I reset
this system again. I cannot investigate these because the volumes and
bacula database are gone.)
26-Feb 23:05 td-bacula-dir JobId 242: Start Backup JobId 242,
Job=Backup-win11-base-fd-job.2025-02-26_23.05.00_56
Volume name(s): Synology-Local-Inc-0093|Synology-Local-Inc-0094
20-Mar 23:05 td-bacula-dir JobId 662: Start Backup JobId 662,
Job=Backup-win11-base-fd-job.2025-03-20_23.05.01_40
Volume name(s): Synology-Local-Inc-0250|Synology-Local-Inc-0251
Regards,
Robert Gerber
402-237-8692
r...@craeon.net
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
