View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000500bareos-core[All Projects] directorpublic2015-08-06 10:062015-12-03 17:39
ReporterurushaAssigned To 
PrioritylowSeverityminorReproducibilityalways
Status acknowledgedResolutionopen 
PlatformLinuxOSUbuntuOS Version14.04
Product Version14.2.2 
Fixed in Version 
Summary0000500: Bareos labels multiple new volumes at once
DescriptionIf determined "label format" is used, Bareos labels multiple new volumes at once with errors like:
Error: sql_create.c:453 Volume "some-volume-name" already exists.

These created volumes may be used by another jobs later, so if ${JobId} / ${Job} / ${Hour} variables are used, volume labels become confusing.
Steps To Reproduce1. Create pool like this:
Pool {
  Name = Incr-1w
  Label Format = "${Pool}-${Job}-${JobId}-${Year}${Month:p/2/0/r}${Day:p/2/0/r}-${Hour:p/2/0/r}${Minute:p/2/0/r}${Second:p/2/0/r}"
  Volume Retention = 2 weeks
  Pool Type = Backup
  Recycle = no
  AutoPrune = yes
  Action On Purge = Truncate
  Volume Use Duration = 23 hours
  Maximum Volume Jobs = 1
}

2. Run job that uses this pool
Additional Information# The first job run, see that Incr-1w-sd2-somejob-10900-20150730-190749 is finally used:

2015-07-30 19:06:44 bak-dir JobId 10900: Start Backup JobId 10900, Job=somejob.2015-07-30_19.05.00_04
2015-07-30 19:07:49 bak-dir JobId 10900: Created new Volume "Incr-1w-sd2-somejob-10900-20150730-190749" in catalog.
2015-07-30 19:07:49 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-190749" already exists.
2015-07-30 19:07:49 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-190749" already exists.
2015-07-30 19:07:49 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-190749" already exists.
2015-07-30 19:08:50 bak-dir JobId 10900: Created new Volume "Incr-1w-sd2-somejob-10900-20150730-190850" in catalog.
2015-07-30 19:08:50 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-190850" already exists.
2015-07-30 19:08:50 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-190850" already exists.
2015-07-30 19:08:50 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-190850" already exists.
2015-07-30 19:09:20 bak-dir JobId 10900: Created new Volume "Incr-1w-sd2-somejob-10900-20150730-190920" in catalog.
2015-07-30 19:09:20 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-190920" already exists.
2015-07-30 19:09:20 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-190920" already exists.
2015-07-30 19:09:20 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-190920" already exists.
2015-07-30 19:09:50 bak-dir JobId 10900: Created new Volume "Incr-1w-sd2-somejob-10900-20150730-190950" in catalog.
2015-07-30 19:09:50 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-190950" already exists.
2015-07-30 19:09:50 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-190950" already exists.
2015-07-30 19:09:50 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-190950" already exists.
2015-07-30 19:10:21 bak-dir JobId 10900: Created new Volume "Incr-1w-sd2-somejob-10900-20150730-191021" in catalog.
2015-07-30 19:10:21 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191021" already exists.
2015-07-30 19:10:21 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191021" already exists.
2015-07-30 19:10:21 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191021" already exists.
2015-07-30 19:10:51 bak-dir JobId 10900: Created new Volume "Incr-1w-sd2-somejob-10900-20150730-191051" in catalog.
2015-07-30 19:10:51 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191051" already exists.
2015-07-30 19:10:51 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191051" already exists.
2015-07-30 19:10:51 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191051" already exists.
2015-07-30 19:11:21 bak-dir JobId 10900: Created new Volume "Incr-1w-sd2-somejob-10900-20150730-191121" in catalog.
2015-07-30 19:11:21 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191121" already exists.
2015-07-30 19:11:21 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191121" already exists.
2015-07-30 19:11:21 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191121" already exists.
2015-07-30 19:11:52 bak-dir JobId 10900: Created new Volume "Incr-1w-sd2-somejob-10900-20150730-191152" in catalog.
2015-07-30 19:11:52 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191152" already exists.
2015-07-30 19:11:52 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191152" already exists.
2015-07-30 19:11:52 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191152" already exists.
2015-07-30 19:12:22 bak-dir JobId 10900: Created new Volume "Incr-1w-sd2-somejob-10900-20150730-191222" in catalog.
2015-07-30 19:12:22 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191222" already exists.
2015-07-30 19:12:22 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191222" already exists.
2015-07-30 19:12:22 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191222" already exists.
2015-07-30 19:12:52 bak-dir JobId 10900: Created new Volume "Incr-1w-sd2-somejob-10900-20150730-191252" in catalog.
2015-07-30 19:12:52 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191252" already exists.
2015-07-30 19:12:52 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191252" already exists.
2015-07-30 19:12:52 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191252" already exists.
2015-07-30 19:13:23 bak-dir JobId 10900: Created new Volume "Incr-1w-sd2-somejob-10900-20150730-191323" in catalog.
2015-07-30 19:13:23 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191323" already exists.
2015-07-30 19:13:23 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191323" already exists.
2015-07-30 19:13:23 bak-dir JobId 10900: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10900-20150730-191323" already exists.
2015-07-30 19:13:53 bak-dir JobId 10900: Using Device "FileStorage" to write.
2015-07-30 19:13:53 bak-dir JobId 10900: Sending Accurate information.
2015-07-30 19:07:03 bak-sd2 JobId 10900: Labeled new Volume "Incr-1w-sd2-somejob-10900-20150730-190749" on device "FileStorage" (/u/1/bareos).
2015-07-30 19:07:03 bak-sd2 JobId 10900: Wrote label to prelabeled Volume "Incr-1w-sd2-somejob-10900-20150730-190749" on device "FileStorage" (/u/1/bareos)
2015-07-30 19:15:17 bak-dir JobId 10900: Max Volume jobs=1 exceeded. Marking Volume "Incr-1w-sd2-somejob-10900-20150730-190749" as Used.
2015-07-30 19:10:50 bak-sd2 JobId 10900: Elapsed time=00:03:47, Transfer rate=10.72 M Bytes/second
2015-07-30 19:19:05 bak-dir JobId 10900: Bareos bak-dir 14.2.2 (12Dec14):
...

### Is it some kind of race condition?
### The next job run, see that the old volume Incr-1w-sd2-somejob-10900-20150730-191222 is actually used:

2015-08-03 19:06:56 bak-dir JobId 10965: Start Backup JobId 10965, Job=somejob.2015-08-03_19.05.00_31
2015-08-03 19:07:57 bak-dir JobId 10965: Created new Volume "Incr-1w-sd2-somejob-10965-20150803-190757" in catalog.
2015-08-03 19:07:57 bak-dir JobId 10965: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10965-20150803-190757" already exists.
2015-08-03 19:07:57 bak-dir JobId 10965: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10965-20150803-190757" already exists.
2015-08-03 19:07:57 bak-dir JobId 10965: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10965-20150803-190757" already exists.
2015-08-03 19:08:57 bak-dir JobId 10965: Created new Volume "Incr-1w-sd2-somejob-10965-20150803-190857" in catalog.
2015-08-03 19:08:57 bak-dir JobId 10965: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10965-20150803-190857" already exists.
2015-08-03 19:08:57 bak-dir JobId 10965: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10965-20150803-190857" already exists.
2015-08-03 19:08:58 bak-dir JobId 10965: Created new Volume "Incr-1w-sd2-somejob-10965-20150803-190858" in catalog.
2015-08-03 19:08:58 bak-dir JobId 10965: Error: sql_create.c:453 Volume "Incr-1w-sd2-somejob-10965-20150803-190858" already exists.
2015-08-03 19:09:28 bak-dir JobId 10965: Using Device "FileStorage" to write.
2015-08-03 19:09:28 bak-dir JobId 10965: Sending Accurate information.
2015-08-03 19:02:19 bak-sd2 JobId 10965: Labeled new Volume "Incr-1w-sd2-somejob-10900-20150730-191222" on device "FileStorage" (/u/1/bareos).
2015-08-03 19:02:19 bak-sd2 JobId 10965: Wrote label to prelabeled Volume "Incr-1w-sd2-somejob-10900-20150730-191222" on device "FileStorage" (/u/1/bareos)
2015-08-03 19:10:52 bak-dir JobId 10965: Max Volume jobs=1 exceeded. Marking Volume "Incr-1w-sd2-somejob-10900-20150730-191222" as Used.
2015-08-03 19:04:09 bak-sd2 JobId 10965: Elapsed time=00:01:50, Transfer rate=6.934 M Bytes/second
2015-08-03 19:12:44 bak-dir JobId 10965: Bareos bak-dir 14.2.2 (12Dec14):
...

### Here are volumes from catalog:

Incr-1w-sd2-somejob-10870-20150728-190753 Used 4.8 GB 0 1 14 File 2015-07-28 19:08:36 2015-07-28 19:11:06 0 -
Incr-1w-sd2-somejob-10885-20150729-190751 Used 1 GB 0 1 14 File 2015-07-29 19:09:51 2015-07-29 19:05:26 0 -
Incr-1w-sd2-somejob-10885-20150729-190851 Used 35.5 GB 0 1 14 File 2015-07-30 03:05:03 2015-07-30 03:07:15 0 -
Incr-1w-sd2-somejob-10885-20150729-190921 Used 15.9 GB 0 1 14 File 2015-07-30 19:05:00 2015-07-30 19:05:16 0 -
Incr-1w-sd2-somejob-10900-20150730-190749 Used 2.3 GB 0 1 14 File 2015-07-30 19:13:53 2015-07-30 19:10:50 0 -
Incr-1w-sd2-somejob-10900-20150730-190850 Used 35.7 GB 0 1 14 File 2015-07-31 03:05:02 2015-07-31 03:07:02 0 -
Incr-1w-sd2-somejob-10900-20150730-190920 Used 43.4 GB 0 1 14 File 2015-07-31 19:05:00 2015-07-31 19:07:58 0 -
Incr-1w-sd2-somejob-10900-20150730-190950 Used 733 MB 0 1 14 File 2015-07-31 19:16:17 2015-07-31 19:10:58 0 -
Incr-1w-sd2-somejob-10900-20150730-191021 Used 35.9 GB 0 1 14 File 2015-08-01 03:05:02 2015-08-01 03:06:48 0 -
Incr-1w-sd2-somejob-10900-20150730-191051 Used 3.8 MB 0 1 14 File 2015-08-03 02:05:46 2015-08-03 02:00:18 0 -
Incr-1w-sd2-somejob-10900-20150730-191121 Used 15.9 GB 0 1 14 File 2015-08-03 03:05:02 2015-08-03 02:59:16 0 -
Incr-1w-sd2-somejob-10900-20150730-191152 Used 5.5 GB 0 1 14 File 2015-08-03 19:05:00 2015-08-03 19:00:30 0 -
Incr-1w-sd2-somejob-10900-20150730-191222 Used 728.1 MB 0 1 14 File 2015-08-03 19:09:28 2015-08-03 19:04:09 0 -
Incr-1w-sd2-somejob-10900-20150730-191252 Used 36.6 GB 0 1 14 File 2015-08-04 03:05:02 2015-08-04 03:06:32 0 -
Incr-1w-sd2-somejob-10900-20150730-191323 Used 922.5 MB 0 1 14 File 2015-08-04 19:05:01 2015-08-04 18:59:11 0 -
Incr-1w-sd2-somejob-10918-20150731-190740 Used 2.1 GB 0 1 14 File 2015-08-04 19:07:50 2015-08-04 19:04:22 0 -
Incr-1w-sd2-somejob-10918-20150731-190840 Used 36.9 GB 0 1 14 File 2015-08-05 03:05:02 2015-08-05 03:06:50 0 -
Incr-1w-sd2-somejob-10918-20150731-190911 Used 11 GB 0 1 14 File 2015-08-05 19:05:00 2015-08-05 19:04:13 0 -
Incr-1w-sd2-somejob-10918-20150731-190941 Used 1.2 GB 0 1 14 File 2015-08-05 19:13:08 2015-08-05 19:08:21 0 -
Incr-1w-sd2-somejob-10918-20150731-191012 Used 37.1 GB 0 1 14 File 2015-08-06 03:05:02 2015-08-06 03:06:38 0 -
Incr-1w-sd2-somejob-10918-20150731-191042 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10918-20150731-191113 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10918-20150731-191143 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10918-20150731-191214 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10918-20150731-191244 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10918-20150731-191315 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10965-20150803-190757 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10965-20150803-190857 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10965-20150803-190858 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10982-20150804-190740 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10997-20150805-190832 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10997-20150805-190933 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10997-20150805-191004 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10997-20150805-191035 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10997-20150805-191106 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10997-20150805-191137 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -
Incr-1w-sd2-somejob-10997-20150805-191208 Append 0 0 0 14 File 0000-00-00 00:00:00 0000-00-00 00:00:00 0 -

### Not all volumes from catalog are actually created as files, only the ones that was used:

# ls -l Incr-1w-sd2-somejob-*
-rw-r----- 1 bareos bareos 5176939123 Jul 28 19:11 Incr-1w-sd2-somejob-10870-20150728-190753
-rw-r----- 1 bareos bareos 1108107165 Jul 29 19:05 Incr-1w-sd2-somejob-10885-20150729-190751
-rw-r----- 1 bareos bareos 38072378649 Jul 30 03:07 Incr-1w-sd2-somejob-10885-20150729-190851
-rw-r----- 1 bareos bareos 17051411525 Jul 30 19:05 Incr-1w-sd2-somejob-10885-20150729-190921
-rw-r----- 1 bareos bareos 2436885228 Jul 30 19:10 Incr-1w-sd2-somejob-10900-20150730-190749
-rw-r----- 1 bareos bareos 38325069557 Jul 31 03:07 Incr-1w-sd2-somejob-10900-20150730-190850
-rw-r----- 1 bareos bareos 46636649284 Jul 31 19:07 Incr-1w-sd2-somejob-10900-20150730-190920
-rw-r----- 1 bareos bareos 768607258 Jul 31 19:10 Incr-1w-sd2-somejob-10900-20150730-190950
-rw-r----- 1 bareos bareos 38581511656 Aug 1 03:06 Incr-1w-sd2-somejob-10900-20150730-191021
-rw-r----- 1 bareos bareos 4035052 Aug 3 02:00 Incr-1w-sd2-somejob-10900-20150730-191051
-rw-r----- 1 bareos bareos 17023640905 Aug 3 02:59 Incr-1w-sd2-somejob-10900-20150730-191121
-rw-r----- 1 bareos bareos 5944993151 Aug 3 19:00 Incr-1w-sd2-somejob-10900-20150730-191152
-rw-r----- 1 bareos bareos 763424403 Aug 3 19:04 Incr-1w-sd2-somejob-10900-20150730-191222
-rw-r----- 1 bareos bareos 39257721621 Aug 4 03:06 Incr-1w-sd2-somejob-10900-20150730-191252
-rw-r----- 1 bareos bareos 967340280 Aug 4 18:59 Incr-1w-sd2-somejob-10900-20150730-191323
-rw-r----- 1 bareos bareos 2218583780 Aug 4 19:04 Incr-1w-sd2-somejob-10918-20150731-190740
-rw-r----- 1 bareos bareos 39591520401 Aug 5 03:06 Incr-1w-sd2-somejob-10918-20150731-190840
-rw-r----- 1 bareos bareos 11860023781 Aug 5 19:04 Incr-1w-sd2-somejob-10918-20150731-190911
-rw-r----- 1 bareos bareos 1335834273 Aug 5 19:08 Incr-1w-sd2-somejob-10918-20150731-190941
-rw-r----- 1 bareos bareos 39867717744 Aug 6 03:06 Incr-1w-sd2-somejob-10918-20150731-191012
TagsNo tags attached.
bareos-master: impact
bareos-master: action
bareos-19.2: impact
bareos-19.2: action
bareos-18.2: impact
bareos-18.2: action
bareos-17.2: impact
bareos-17.2: action
bareos-16.2: impact
bareos-16.2: action
bareos-15.2: impact
bareos-15.2: action
bareos-14.2: impact
bareos-14.2: action
bareos-13.2: impact
bareos-13.2: action
bareos-12.4: impact
bareos-12.4: action

Activities

maik

maik

2015-11-06 17:42

administrator   ~0001941

This problem seems to occur rather intermittently and not very often. May fix this in the long run.
kantv

kantv

2015-12-03 17:36

reporter   ~0002026

I have the same issue on CentOS7 with bareos 14.2 and 15.2 also.
My Label format is "$Job-$JobId".

Issue History

Date Modified Username Field Change
2015-08-06 10:06 urusha New Issue
2015-11-06 17:42 maik Note Added: 0001941
2015-11-06 17:42 maik Priority normal => low
2015-11-06 17:42 maik Status new => acknowledged
2015-12-03 17:36 kantv Note Added: 0002026