>>>>> On Tue, 28 Jan 2025 09:09:47 +0000, Brian Candler said: > > # grep '9292[56]' /var/log/bacula/bacula.log > 26-Jan 02:05 store.nsrc.org-dir JobId 92926: Start Backup JobId 92926, > Job=drupal.nsrc.org.2025-01-25_21.00.00_35 > 26-Jan 02:05 store.nsrc.org-dir JobId 92926: Error: bsockcore.c:400 Source > address bind error. proto=2. ERR=Invalid argument > 26-Jan 02:05 store.nsrc.org-dir JobId 92926: Connected to Storage > "FileStorage0" at store.nsrc.org:9103 with TLS > 26-Jan 02:05 store.nsrc.org-dir JobId 92926: Using Device "FileDev0" to write. > 26-Jan 02:05 store.nsrc.org-dir JobId 92926: Storage "FileStorage0" was > selected out of group of 2 available storages. StorageGroupPolicy > "ListedOrder" used > 26-Jan 02:05 store.nsrc.org-dir JobId 92926: Error: bsockcore.c:400 Source > address bind error. proto=2. ERR=Invalid argument > 26-Jan 02:05 store.nsrc.org-dir JobId 92926: Connected to Client > "drupal.nsrc.org-fd" at drupal.nsrc.org:9102 without encryption > 26-Jan 02:05 store.nsrc.org-sd JobId 92926: Labeled new Volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-26" on File device "FileDev0" > (/backup/bacula). > 26-Jan 02:05 store.nsrc.org-sd JobId 92926: Wrote label to prelabeled Volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-26" on File device "FileDev0" > (/backup/bacula) > 26-Jan 02:05 store.nsrc.org-dir JobId 92926: Volume used once. Marking Volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-26" as Used. > 26-Jan 02:20 store.nsrc.org-sd JobId 92926: Elapsed time=00:15:12, Transfer > rate=7.316 M Bytes/second > 26-Jan 02:20 store.nsrc.org-sd JobId 92926: Sending spooled attrs to the > Director. Despooling 29,199,872 bytes ... > 26-Jan 02:20 store.nsrc.org-dir JobId 92926: Bacula store.nsrc.org-dir 13.0.4 > (12Feb24): > JobId: 92926 > Volume name(s): 92925-director.nsrc.org-fd-Full-Full-2025-01-26 > 26-Jan 02:20 store.nsrc.org-dir JobId 92926: Begin pruning Jobs older than 1 > year . > 26-Jan 02:20 store.nsrc.org-dir JobId 92926: No Jobs found to prune. > 26-Jan 02:20 store.nsrc.org-dir JobId 92926: Begin pruning Files. > 26-Jan 02:20 store.nsrc.org-dir JobId 92926: No Files found to prune. > 26-Jan 02:20 store.nsrc.org-dir JobId 92926: End auto prune. > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Start Backup JobId 92925, > Job=director.nsrc.org.2025-01-25_21.00.00_34 > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Error: bsockcore.c:400 Source > address bind error. proto=2. ERR=Invalid argument > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Connected to Storage > "FileStorage0" at store.nsrc.org:9103 with TLS > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Created new > Volume="92925-director.nsrc.org-fd-Full-Full-2025-01-26", Pool="Full", > MediaType="File0" in catalog. > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Storage daemon "FileStorage0" > didn't accept Device "FileDev0" because: 3924 Device "FileDev0" not in SD > Device resources or no matching Media Type or is disabled. > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Error: bsockcore.c:400 Source > address bind error. proto=2. ERR=Invalid argument > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Connected to Storage > "FileStorage1" at store.nsrc.org:9103 with TLS > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Error: sql_create.c:430 Volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-26" already exists. > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Using Device "FileDev1" to write. > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Storage "FileStorage1" was > selected out of group of 2 available storages. StorageGroupPolicy > "ListedOrder" used > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Error: bsockcore.c:400 Source > address bind error. proto=2. ERR=Invalid argument > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Connected to Client > "director.nsrc.org-fd" at director.nsrc.org:9102 without encryption > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Error: sql_create.c:430 Volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-26" already exists. > 26-Jan 02:04 store.nsrc.org-dir JobId 92925: Error: sql_create.c:430 Volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-26" already exists. > 26-Jan 02:04 store.nsrc.org-sd JobId 92925: Job > director.nsrc.org.2025-01-25_21.00.00_34 is waiting. Cannot find any > appendable volumes. > 26-Jan 02:09 store.nsrc.org-dir JobId 92925: Error: sql_create.c:430 Volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-26" already exists. > 26-Jan 02:14 store.nsrc.org-dir JobId 92925: Error: sql_create.c:430 Volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-26" already exists. > <<snip lots>> > 26-Jan 23:54 store.nsrc.org-dir JobId 92925: Error: sql_create.c:430 Volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-26" already exists. > 26-Jan 23:59 store.nsrc.org-dir JobId 92925: Error: sql_create.c:430 Volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-26" already exists. > 27-Jan 00:04 store.nsrc.org-dir JobId 92925: Created new > Volume="92925-director.nsrc.org-fd-Full-Full-2025-01-27", Pool="Full", > MediaType="File1" in catalog. > 27-Jan 00:04 store.nsrc.org-sd JobId 92925: Labeled new Volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-27" on File device "FileDev1" > (/backup/bacula). > 27-Jan 00:04 store.nsrc.org-sd JobId 92925: Wrote label to prelabeled Volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-27" on File device "FileDev1" > (/backup/bacula) > 27-Jan 00:04 store.nsrc.org-dir JobId 92925: Volume used once. Marking Volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-27" as Used. > 27-Jan 00:10 store.nsrc.org-sd JobId 92925: Elapsed time=00:06:00, Transfer > rate=4.460 M Bytes/second > 27-Jan 00:10 store.nsrc.org-sd JobId 92925: Sending spooled attrs to the > Director. Despooling 14,038,445 bytes ... > 27-Jan 00:10 store.nsrc.org-dir JobId 92925: Bacula store.nsrc.org-dir > 13.0.4 (12Feb24): > JobId: 92925 > Volume name(s): 92925-director.nsrc.org-fd-Full-Full-2025-01-27 > 27-Jan 00:10 store.nsrc.org-dir JobId 92925: Begin pruning Jobs older than 1 > year . > 27-Jan 00:10 store.nsrc.org-dir JobId 92925: No Jobs found to prune. > 27-Jan 00:10 store.nsrc.org-dir JobId 92925: Begin pruning Files. > 27-Jan 00:10 store.nsrc.org-dir JobId 92925: No Files found to prune. > 27-Jan 00:10 store.nsrc.org-dir JobId 92925: End auto prune. > > -------- > > What appears to be happening is: > > - Job 92926 creates the volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-26" - even though its job > ID is 92925, and the client is drupal.nsrc.org! - and successfully uses it. > > - Job 92925 starts, and tries to create volume > "92925-director.nsrc.org-fd-Full-Full-2025-01-26" - which is the correct > name. But it finds that the volume already exists. It backs off and > keeps retrying, hundreds of times
Actually, I think job 92925 runs first (according to the timestamps in the logs, which are not in order for some reason) and creates the volume using FileStorage0. Then, for some reason, the SD refuses to use FileStorage0 for job 92925, which makes it select FileStorage1 instead and get into the loop trying to create the volume again. When job 92926 runs, it selects FileStorage0 and uses the newly created volume (because it is a volume with no jobs at that point). > I don't know what the message > > Storage daemon "FileStorage0" didn't accept Device "FileDev0" because: > 3924 Device "FileDev0" not in SD Device resources or no matching Media > Type or is disabled. > > is telling me, and whether this is part of the problem - this message > didn't appear prior to the upgrade. I think this is evidence of the "refuses to use FileStorage0" that I mentioned above. __Martin _______________________________________________ Bacula-users mailing list Bacula-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/bacula-users
