View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0001022bareos-coredirectorpublic2018-10-18 14:542023-10-24 09:17
Reporterder_andrew Assigned Toarogge  
PrioritynormalSeverityminorReproducibilityrandom
Status closedResolutionunable to reproduce 
Platformx86_64OSCentOSOS Version7 (Core)
Product Version17.2.4 
Summary0001022: Error message upon create volume
DescriptionI have this pattern for volume name:
Label Format = "$Storage-$Level-$JobId-$Day-$WeekDay-$Minute-$Second"

The job is successfully complited, but randomly message occure:
JobId 112049: Error: sql_create.c:444 Volume "ke047-bkp2-sd-Incremental-112049-17-3-0-14" already exists.

It's not possible IMHO :) because of "JobId 112049" and $JobId.

About a couple of month ago it was upgrade from 16.2.4 to 17.2.4.
Additional Information17-Oct 18:00 ms001-brbkp01-dir JobId 112049: Start Backup JobId 112049, Job=ke047-mx1-job.2018-10-17_18.00.07_49
17-Oct 18:00 ms001-brbkp01-dir JobId 112049: Max configured use duration=86,400 sec. exceeded. Marking Volume "ke047-bkp2-sd-Incremental-111627-16-2-0-17" as Used.
17-Oct 18:00 ms001-brbkp01-dir JobId 112049: Created new Volume "ke047-bkp2-sd-Incremental-112049-17-3-0-14" in catalog.
17-Oct 18:00 ms001-brbkp01-dir JobId 112049: Error: sql_create.c:444 Volume "ke047-bkp2-sd-Incremental-112049-17-3-0-14" already exists.
17-Oct 18:00 ms001-brbkp01-dir JobId 112049: Using Device "FileStorage01" to write.
17-Oct 18:00 bareos-sd JobId 112049: Elapsed time=00:00:04, Transfer rate=6.427 M Bytes/second
17-Oct 18:00 ms001-brbkp01-dir JobId 112049: sql_create.c:872 Insert of attributes batch table done
17-Oct 18:00 ms001-brbkp01-dir JobId 112049: Bareos ms001-brbkp01-dir 17.2.4 (21Sep17):
  Build OS: x86_64-redhat-linux-gnu redhat CentOS Linux release 7.4.1708 (Core)
  JobId: 112049
  Job: ke047-mx1-job.2018-10-17_18.00.07_49
  Backup Level: Incremental, since=2018-10-16 18:00:15
  Client: "ke047-mx1-fd" 17.2.4 (21Sep17) x86_64-redhat-linux-gnu,redhat,CentOS Linux release 7.4.1708 (Core) ,CentOS_7,x86_64
  FileSet: "CentOS7-common" 2018-09-17 18:00:00
  Pool: "CentOS7-common-ke047-Inc" (From Job IncPool override)
  Catalog: "ms001-brbkp01" (From Client resource)
  Storage: "ke047-bkp2-sd" (From Pool resource)
  Scheduled time: 17-Oct-2018 18:00:07
  Start time: 17-Oct-2018 18:00:16
  End time: 17-Oct-2018 18:00:24
  Elapsed time: 8 secs
  Priority: 10
  FD Files Written: 37
  SD Files Written: 37
  FD Bytes Written: 25,703,427 (25.70 MB)
  SD Bytes Written: 25,708,405 (25.70 MB)
  Rate: 3212.9 KB/s
  Software Compression: 86.6 % (gzip,gzip)
  VSS: no
  Encryption: no
  Accurate: no
  Volume name(s): ke047-bkp2-sd-Incremental-112049-17-3-0-14
  Volume Session Id: 277
  Volume Session Time: 1537967550
  Last Volume Bytes: 40,415,797 (40.41 MB)
  Non-fatal FD errors: 1
  SD Errors: 0
  FD termination status: OK
  SD termination status: OK
  Termination: Backup OK -- with warnings
TagsNo tags attached.

Activities

der_andrew

der_andrew

2019-02-14 06:50

reporter   ~0003260

Upgrade to 18.2.5. The same issue...
arogge

arogge

2019-03-13 18:51

manager   ~0003286

The code does a "SELECT MediaId FROM Media WHERE VolumeName='%s'" (replacing %s with the volume-name) and then checks whether the database returns a row.
You can check this by executing the above query when the issue occurs and see wether the volume already exists in the catalog.
arogge

arogge

2019-04-10 17:45

manager   ~0003320

Can you provide any further insight on this? I'll have to close the issue otherwise.
der_andrew

der_andrew

2019-04-10 18:17

reporter   ~0003321

Sorry. I'll miss you message) Give me a couple of days.
der_andrew

der_andrew

2019-04-11 07:35

reporter   ~0003325

It's hard to me to exlain in English. So I'll try with my native language)
Итак. Шаблон для volume имеет вид: Label Format = "$Storage-$Level-$JobId-$Day-$WeekDay-$Minute-$Second"
Тут присутствует $JobId. $JobId всегда уникален. Это факт.
Если Job создаёт volume, то имя у volume уникально. Согласен? :) (Если А=В и В=С следовательно А=С)
Поэтому в нормальной ситуации ошибки быть не должно.
IMHO внутри алгоритма работы job происходит двойная проверка имени volume: до создания volume и после создания volume.
Так же повторюсь, что в версии 16.2.4 таких ошибок не было. Началось после перехода на версию 17.2.4.
arogge

arogge

2019-04-11 08:28

manager   ~0003326

[google translate of previous comment]
So. The template for volume looks like: Label Format = "$ Storage- $ Level- $ JobId- $ Day- $ WeekDay- $ Minute- $ Second"
There is $ JobId. $ JobId is always unique. It is a fact.
If Job creates volume, then the name of volume is unique. I agree? :) (If A = B and B = C therefore A = C)
Therefore, in a normal situation, there should be no error.
IMHO inside the job job algorithm, double checking of the volume name occurs: before volume is created and after volume is created.
I repeat that in version 16.2.4 there were no such errors. It began after the transition to version 17.2.4.
arogge

arogge

2019-04-11 08:43

manager   ~0003327

I'll try to write as simple as possible.

I understand what you are doing and I understand that it fails sometimes.
The error happens when a volume is labeled and the new label is already in the database.
This should not happen, so it is probably a bug.

I will need more details.
Please issue "setdebug level=500 trace=1 timestamp=1 director" in bconsole to enable tracing.
This will write trace information to /var/lib/bareos/bareos-dir.*
When the problem happens again upload the trace and I will try to find out why this happened.
der_andrew

der_andrew

2019-04-11 10:12

reporter   ~0003330

OK I got it.
der_andrew

der_andrew

2019-04-12 07:40

reporter   ~0003334

Hi!
Check out attache
dir.tar.gz (160,987 bytes)
arogge

arogge

2019-04-30 11:15

manager   ~0003344

There is no trace information for the problem in your trace.
You need to enable tracing and wait for the problem to occur.
der_andrew

der_andrew

2019-04-30 12:16

reporter   ~0003345

I did as requestd... Hmmm...
Should I restart bareos-dir after `setdebug level=500 trace=1 timestamp=1 director`?
arogge

arogge

2019-04-30 12:31

manager   ~0003346

You need to "setdebug level=500 trace=1 timestamp=1 director" and then make the error happen again.
There should be lots of text in the trace-file, yours had exactly one line.
der_andrew

der_andrew

2019-04-30 12:45

reporter   ~0003347

Again. I did as you say)
Form archive after error. I don't know why its empty \_0o_/
I'll try one more time. Should I restart bareos-dir after `setdebug level=500 trace=1 timestamp=1 director`?
arogge

arogge

2019-04-30 12:48

manager   ~0003348

No don't restart bareos-dir. Restarting bareos-dir will unset the debugging options.
der_andrew

der_andrew

2019-05-06 08:38

reporter   ~0003362

Hello!
It was wrong permissions on ms001-brbkp01-dir.trace. #$%^!!! Sorry)
Fix it and waiting forward for error...
der_andrew

der_andrew

2019-05-16 08:04

reporter  

ms001-brbkp01-dir.trace-20190516.txt (5,065 bytes)    
15-May 22:00 ms001-brbkp01-dir JobId 207257: Start Backup JobId 207257, Job=vr009-zm1-job.2019-05-15_22.00.04_26
15-May 22:00 ms001-brbkp01-dir JobId 207257: Connected Storage daemon at vr009-bkp2.nes.lan:9103, encryption: PSK-AES256-CBC-SHA
15-May 22:00 ms001-brbkp01-dir JobId 207257: Max configured use duration=86,400 sec. exceeded. Marking Volume "vr009-bkp2-sd-Incremental-103286-27-4-0-5" as Used.
15-May 22:00 ms001-brbkp01-dir JobId 207257: There are no more Jobs associated with Volume "vr009-bkp2-sd-Incremental-165407-12-2-0-7". Marking it purged.
15-May 22:00 ms001-brbkp01-dir JobId 207257: All records pruned from Volume "vr009-bkp2-sd-Incremental-165407-12-2-0-7"; marking it "Purged"
15-May 22:00 ms001-brbkp01-dir JobId 207257: Recycled volume "vr009-bkp2-sd-Incremental-165407-12-2-0-7"
15-May 22:00 ms001-brbkp01-dir JobId 207257: There are no more Jobs associated with Volume "vr009-bkp2-sd-Incremental-165849-13-3-0-7". Marking it purged.
15-May 22:00 ms001-brbkp01-dir JobId 207257: All records pruned from Volume "vr009-bkp2-sd-Incremental-165849-13-3-0-7"; marking it "Purged"
15-May 22:00 ms001-brbkp01-dir JobId 207257: Recycled volume "vr009-bkp2-sd-Incremental-165849-13-3-0-7"
15-May 22:00 ms001-brbkp01-dir JobId 207257: There are no more Jobs associated with Volume "vr009-bkp2-sd-Incremental-166734-15-5-0-10". Marking it purged.
15-May 22:00 ms001-brbkp01-dir JobId 207257: All records pruned from Volume "vr009-bkp2-sd-Incremental-166734-15-5-0-10"; marking it "Purged"
15-May 22:00 ms001-brbkp01-dir JobId 207257: Recycled volume "vr009-bkp2-sd-Incremental-166734-15-5-0-10"
15-May 22:00 ms001-brbkp01-dir JobId 207257: There are no more Jobs associated with Volume "vr009-bkp2-sd-Incremental-166734-15-5-0-11". Marking it purged.
15-May 22:00 ms001-brbkp01-dir JobId 207257: All records pruned from Volume "vr009-bkp2-sd-Incremental-166734-15-5-0-11"; marking it "Purged"
15-May 22:00 ms001-brbkp01-dir JobId 207257: Recycled volume "vr009-bkp2-sd-Incremental-166734-15-5-0-11"
15-May 22:00 ms001-brbkp01-dir JobId 207257: Created new Volume "vr009-bkp2-sd-Incremental-207257-15-3-0-12" in catalog.
15-May 22:00 ms001-brbkp01-dir JobId 207257: Error: cats/sql_create.cc:445 Volume "vr009-bkp2-sd-Incremental-207257-15-3-0-12" already exists.
15-May 22:00 ms001-brbkp01-dir JobId 207257: Using Device "FileStorage01" to write.
15-May 22:00 ms001-brbkp01-dir JobId 207257: Connected Client: vr009-zm1-fd at vr009-zm1.nes.lan:9102, encryption: PSK-AES256-CBC-SHA
15-May 22:00 ms001-brbkp01-dir JobId 207257:  Handshake: Immediate TLS 15-May 22:00 ms001-brbkp01-dir JobId 207257:  Encryption: PSK-AES256-CBC-SHA
15-May 22:00 bareos-fd JobId 207257: Connected Storage daemon at vr009-bkp2.nes.lan:9103, encryption: PSK-AES256-CBC-SHA
15-May 22:00 bareos-fd JobId 207257: Extended attribute support is enabled
15-May 22:00 bareos-fd JobId 207257: ACL support is enabled
15-May 22:00 bareos-sd JobId 207257: Releasing device "FileStorage01" (/storage/backup).
15-May 22:00 bareos-sd JobId 207257: Elapsed time=00:00:02, Transfer rate=128.1 K Bytes/second
15-May 22:00 ms001-brbkp01-dir JobId 207257: Insert of attributes batch table with 27 entries start
15-May 22:00 ms001-brbkp01-dir JobId 207257: Insert of attributes batch table done
15-May 22:00 ms001-brbkp01-dir JobId 207257: Bareos ms001-brbkp01-dir 18.2.5 (30Jan19):
  Build OS:               Linux-4.4.92-6.18-default redhat CentOS Linux release 7.6.1810 (Core) 
  JobId:                  207257
  Job:                    vr009-zm1-job.2019-05-15_22.00.04_26
  Backup Level:           Incremental, since=2019-05-14 22:00:09
  Client:                 "vr009-zm1-fd" 18.2.5 (30Jan19) Linux-4.4.92-6.18-default,redhat,CentOS Linux release 7.6.1810 (Core) ,CentOS_7,x86_64
  FileSet:                "CentOS7-common" 2018-09-17 18:00:00
  Pool:                   "CentOS7-common-vr009-Inc" (From Job IncPool override)
  Catalog:                "ms001-brbkp01" (From Client resource)
  Storage:                "vr009-bkp2-sd" (From Pool resource)
  Scheduled time:         15-May-2019 22:00:04
  Start time:             15-May-2019 22:00:14
  End time:               15-May-2019 22:00:29
  Elapsed time:           15 secs
  Priority:               10
  FD Files Written:       315
  SD Files Written:       315
  FD Bytes Written:       217,348 (217.3 KB)
  SD Bytes Written:       256,211 (256.2 KB)
  Rate:                   14.5 KB/s
  Software Compression:   89.8 % (gzip,gzip)
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         vr009-bkp2-sd-Incremental-171763-26-2-0-8
  Volume Session Id:      591
  Volume Session Time:    1553697198
  Last Volume Bytes:      18,058,125 (18.05 MB)
  Non-fatal FD errors:    1
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Bareos binary info:     bareos.org build: Get official binaries and vendor support on bareos.com
  Termination:            Backup OK -- with warnings
ms001-brbkp01-dir.trace-20190516.txt (5,065 bytes)   
der_andrew

der_andrew

2019-05-16 08:06

reporter  

ms001-brbkp01-dir.trace-20190516-2.txt (5,065 bytes)    
15-May 22:00 ms001-brbkp01-dir JobId 207257: Start Backup JobId 207257, Job=vr009-zm1-job.2019-05-15_22.00.04_26
15-May 22:00 ms001-brbkp01-dir JobId 207257: Connected Storage daemon at vr009-bkp2.nes.lan:9103, encryption: PSK-AES256-CBC-SHA
15-May 22:00 ms001-brbkp01-dir JobId 207257: Max configured use duration=86,400 sec. exceeded. Marking Volume "vr009-bkp2-sd-Incremental-103286-27-4-0-5" as Used.
15-May 22:00 ms001-brbkp01-dir JobId 207257: There are no more Jobs associated with Volume "vr009-bkp2-sd-Incremental-165407-12-2-0-7". Marking it purged.
15-May 22:00 ms001-brbkp01-dir JobId 207257: All records pruned from Volume "vr009-bkp2-sd-Incremental-165407-12-2-0-7"; marking it "Purged"
15-May 22:00 ms001-brbkp01-dir JobId 207257: Recycled volume "vr009-bkp2-sd-Incremental-165407-12-2-0-7"
15-May 22:00 ms001-brbkp01-dir JobId 207257: There are no more Jobs associated with Volume "vr009-bkp2-sd-Incremental-165849-13-3-0-7". Marking it purged.
15-May 22:00 ms001-brbkp01-dir JobId 207257: All records pruned from Volume "vr009-bkp2-sd-Incremental-165849-13-3-0-7"; marking it "Purged"
15-May 22:00 ms001-brbkp01-dir JobId 207257: Recycled volume "vr009-bkp2-sd-Incremental-165849-13-3-0-7"
15-May 22:00 ms001-brbkp01-dir JobId 207257: There are no more Jobs associated with Volume "vr009-bkp2-sd-Incremental-166734-15-5-0-10". Marking it purged.
15-May 22:00 ms001-brbkp01-dir JobId 207257: All records pruned from Volume "vr009-bkp2-sd-Incremental-166734-15-5-0-10"; marking it "Purged"
15-May 22:00 ms001-brbkp01-dir JobId 207257: Recycled volume "vr009-bkp2-sd-Incremental-166734-15-5-0-10"
15-May 22:00 ms001-brbkp01-dir JobId 207257: There are no more Jobs associated with Volume "vr009-bkp2-sd-Incremental-166734-15-5-0-11". Marking it purged.
15-May 22:00 ms001-brbkp01-dir JobId 207257: All records pruned from Volume "vr009-bkp2-sd-Incremental-166734-15-5-0-11"; marking it "Purged"
15-May 22:00 ms001-brbkp01-dir JobId 207257: Recycled volume "vr009-bkp2-sd-Incremental-166734-15-5-0-11"
15-May 22:00 ms001-brbkp01-dir JobId 207257: Created new Volume "vr009-bkp2-sd-Incremental-207257-15-3-0-12" in catalog.
15-May 22:00 ms001-brbkp01-dir JobId 207257: Error: cats/sql_create.cc:445 Volume "vr009-bkp2-sd-Incremental-207257-15-3-0-12" already exists.
15-May 22:00 ms001-brbkp01-dir JobId 207257: Using Device "FileStorage01" to write.
15-May 22:00 ms001-brbkp01-dir JobId 207257: Connected Client: vr009-zm1-fd at vr009-zm1.nes.lan:9102, encryption: PSK-AES256-CBC-SHA
15-May 22:00 ms001-brbkp01-dir JobId 207257:  Handshake: Immediate TLS 15-May 22:00 ms001-brbkp01-dir JobId 207257:  Encryption: PSK-AES256-CBC-SHA
15-May 22:00 bareos-fd JobId 207257: Connected Storage daemon at vr009-bkp2.nes.lan:9103, encryption: PSK-AES256-CBC-SHA
15-May 22:00 bareos-fd JobId 207257: Extended attribute support is enabled
15-May 22:00 bareos-fd JobId 207257: ACL support is enabled
15-May 22:00 bareos-sd JobId 207257: Releasing device "FileStorage01" (/storage/backup).
15-May 22:00 bareos-sd JobId 207257: Elapsed time=00:00:02, Transfer rate=128.1 K Bytes/second
15-May 22:00 ms001-brbkp01-dir JobId 207257: Insert of attributes batch table with 27 entries start
15-May 22:00 ms001-brbkp01-dir JobId 207257: Insert of attributes batch table done
15-May 22:00 ms001-brbkp01-dir JobId 207257: Bareos ms001-brbkp01-dir 18.2.5 (30Jan19):
  Build OS:               Linux-4.4.92-6.18-default redhat CentOS Linux release 7.6.1810 (Core) 
  JobId:                  207257
  Job:                    vr009-zm1-job.2019-05-15_22.00.04_26
  Backup Level:           Incremental, since=2019-05-14 22:00:09
  Client:                 "vr009-zm1-fd" 18.2.5 (30Jan19) Linux-4.4.92-6.18-default,redhat,CentOS Linux release 7.6.1810 (Core) ,CentOS_7,x86_64
  FileSet:                "CentOS7-common" 2018-09-17 18:00:00
  Pool:                   "CentOS7-common-vr009-Inc" (From Job IncPool override)
  Catalog:                "ms001-brbkp01" (From Client resource)
  Storage:                "vr009-bkp2-sd" (From Pool resource)
  Scheduled time:         15-May-2019 22:00:04
  Start time:             15-May-2019 22:00:14
  End time:               15-May-2019 22:00:29
  Elapsed time:           15 secs
  Priority:               10
  FD Files Written:       315
  SD Files Written:       315
  FD Bytes Written:       217,348 (217.3 KB)
  SD Bytes Written:       256,211 (256.2 KB)
  Rate:                   14.5 KB/s
  Software Compression:   89.8 % (gzip,gzip)
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         vr009-bkp2-sd-Incremental-171763-26-2-0-8
  Volume Session Id:      591
  Volume Session Time:    1553697198
  Last Volume Bytes:      18,058,125 (18.05 MB)
  Non-fatal FD errors:    1
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Bareos binary info:     bareos.org build: Get official binaries and vendor support on bareos.com
  Termination:            Backup OK -- with warnings
ms001-brbkp01-dir.trace-20190516-2.txt (5,065 bytes)   
der_andrew

der_andrew

2019-05-16 08:09

reporter   ~0003371

Hi!
Good news! Finaly its catched. Tracelog and message are in attachement.
der_andrew

der_andrew

2019-05-16 08:10

reporter   ~0003372

Tracelog some later. 2MB size can't attache (((
der_andrew

der_andrew

2019-05-16 08:13

reporter   ~0003373

Here you are
https://drive.google.com/file/d/1ROXpyWakUNbD1snAWLdDWV-LrLMcmhCl/view?usp=sharing
der_andrew

der_andrew

2019-05-17 09:44

reporter   ~0003376

one more fish
https://drive.google.com/file/d/1ROXpyWakUNbD1snAWLdDWV-LrLMcmhCl/view?usp=sharing
ms001-brbkp01-dir.trace-20190517.txt (9,537 bytes)    

16-May 20:00 ms001-brbkp01-dir JobId 207665: Start Backup JobId 207665, Job=om024-man1-job.2019-05-16_20.00.10_18
16-May 20:00 ms001-brbkp01-dir JobId 207665: Connected Storage daemon at om024-bkp2.nes.lan:9103, encryption: PSK-AES256-CBC-SHA
16-May 20:00 ms001-brbkp01-dir JobId 207665: Created new Volume "om024-bkp2-sd-Incremental-207665-16-4-0-36" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Created new Volume "om024-bkp2-sd-Incremental-207665-16-4-0-37" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Created new Volume "om024-bkp2-sd-Incremental-207665-16-4-0-38" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Created new Volume "om024-bkp2-sd-Incremental-207665-16-4-0-39" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Created new Volume "om024-bkp2-sd-Incremental-207665-16-4-0-40" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Created new Volume "om024-bkp2-sd-Incremental-207665-16-4-0-41" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Error: cats/sql_create.cc:445 Volume "om024-bkp2-sd-Incremental-207665-16-4-0-41" already exists.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Using Device "FileStorage01" to write.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Connected Client: om024-man1-fd at om024-man1.nes.lan:9102, encryption: PSK-AES256-CBC-SHA
16-May 20:00 ms001-brbkp01-dir JobId 207665:  Handshake: Immediate TLS 16-May 20:00 ms001-brbkp01-dir JobId 207665:  Encryption: PSK-AES256-CBC-SHA
16-May 20:00 bareos-fd JobId 207665: Connected Storage daemon at om024-bkp2.nes.lan:9103, encryption: PSK-AES256-CBC-SHA
16-May 20:00 bareos-fd JobId 207665: Extended attribute support is enabled
16-May 20:00 bareos-fd JobId 207665: ACL support is enabled
16-May 20:00 bareos-sd JobId 207665: Volume "om024-bkp2-sd-Incremental-207664-16-4-0-31" previously written, moving to end of data.
16-May 20:00 bareos-sd JobId 207665: Ready to append to end of Volume "om024-bkp2-sd-Incremental-207664-16-4-0-31" size=722
16-May 20:00 bareos-sd JobId 207665: Releasing device "FileStorage01" (/storage/backup).
16-May 20:00 bareos-sd JobId 207665: Elapsed time=00:00:01, Transfer rate=0  Bytes/second
16-May 20:00 ms001-brbkp01-dir JobId 207665: Bareos ms001-brbkp01-dir 18.2.5 (30Jan19):
  Build OS:               Linux-4.4.92-6.18-default redhat CentOS Linux release 7.6.1810 (Core) 
  JobId:                  207665
  Job:                    om024-man1-job.2019-05-16_20.00.10_18
  Backup Level:           Incremental, since=2019-05-15 20:00:14
  Client:                 "om024-man1-fd" 18.2.5 (30Jan19) Linux-4.4.92-6.18-default,redhat,CentOS Linux release 7.6.1810 (Core) ,CentOS_7,x86_64
  FileSet:                "man1-common" 2018-05-30 18:00:00
  Pool:                   "CentOS7-common-om024-Inc" (From Job IncPool override)
  Catalog:                "ms001-brbkp01" (From Client resource)
  Storage:                "om024-bkp2-sd" (From Pool resource)
  Scheduled time:         16-May-2019 20:00:10
  Start time:             16-May-2019 20:00:44
  End time:               16-May-2019 20:00:45
  Elapsed time:           1 sec
  Priority:               10
  FD Files Written:       0
  SD Files Written:       0
  FD Bytes Written:       0 (0 B)
  SD Bytes Written:       0 (0 B)
  Rate:                   0.0 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         
  Volume Session Id:      311
  Volume Session Time:    1553756258
  Last Volume Bytes:      0 (0 B)
  Non-fatal FD errors:    1
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Bareos binary info:     bareos.org build: Get official binaries and vendor support on bareos.com
  Termination:            Backup OK -- with warnings




  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  


16-May 20:00 ms001-brbkp01-dir JobId 207664: Start Backup JobId 207664, Job=om024-gw1-job.2019-05-16_20.00.08_17
16-May 20:00 ms001-brbkp01-dir JobId 207664: Connected Storage daemon at om024-bkp2.nes.lan:9103, encryption: PSK-AES256-CBC-SHA
16-May 20:00 ms001-brbkp01-dir JobId 207664: Max configured use duration=86,400 sec. exceeded. Marking Volume "om024-bkp2-sd-Incremental-139717-18-2-0-22" as Used.
16-May 20:00 ms001-brbkp01-dir JobId 207664: There are no more Jobs associated with Volume "om024-bkp2-sd-Incremental-139713-18-2-0-18". Marking it purged.
16-May 20:00 ms001-brbkp01-dir JobId 207664: All records pruned from Volume "om024-bkp2-sd-Incremental-139713-18-2-0-18"; marking it "Purged"
16-May 20:00 ms001-brbkp01-dir JobId 207664: Recycled volume "om024-bkp2-sd-Incremental-139713-18-2-0-18"
16-May 20:00 ms001-brbkp01-dir JobId 207664: There are no more Jobs associated with Volume "om024-bkp2-sd-Incremental-139713-18-2-0-19". Marking it purged.
16-May 20:00 ms001-brbkp01-dir JobId 207664: All records pruned from Volume "om024-bkp2-sd-Incremental-139713-18-2-0-19"; marking it "Purged"
16-May 20:00 ms001-brbkp01-dir JobId 207664: Recycled volume "om024-bkp2-sd-Incremental-139713-18-2-0-19"
16-May 20:00 ms001-brbkp01-dir JobId 207664: There are no more Jobs associated with Volume "om024-bkp2-sd-Incremental-139715-18-2-0-20". Marking it purged.
16-May 20:00 ms001-brbkp01-dir JobId 207664: All records pruned from Volume "om024-bkp2-sd-Incremental-139715-18-2-0-20"; marking it "Purged"
16-May 20:00 ms001-brbkp01-dir JobId 207664: Recycled volume "om024-bkp2-sd-Incremental-139715-18-2-0-20"
16-May 20:00 ms001-brbkp01-dir JobId 207664: There are no more Jobs associated with Volume "om024-bkp2-sd-Incremental-204082-8-3-0-17". Marking it purged.
16-May 20:00 ms001-brbkp01-dir JobId 207664: All records pruned from Volume "om024-bkp2-sd-Incremental-204082-8-3-0-17"; marking it "Purged"
16-May 20:00 ms001-brbkp01-dir JobId 207664: Recycled volume "om024-bkp2-sd-Incremental-204082-8-3-0-17"
16-May 20:00 ms001-brbkp01-dir JobId 207664: There are no more Jobs associated with Volume "om024-bkp2-sd-Incremental-204082-8-3-0-18". Marking it purged.
16-May 20:00 ms001-brbkp01-dir JobId 207664: All records pruned from Volume "om024-bkp2-sd-Incremental-204082-8-3-0-18"; marking it "Purged"
16-May 20:00 ms001-brbkp01-dir JobId 207664: Recycled volume "om024-bkp2-sd-Incremental-204082-8-3-0-18"
16-May 20:00 ms001-brbkp01-dir JobId 207664: Created new Volume "om024-bkp2-sd-Incremental-207664-16-4-0-31" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207664: Created new Volume "om024-bkp2-sd-Incremental-207664-16-4-0-32" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207664: Error: cats/sql_create.cc:445 Volume "om024-bkp2-sd-Incremental-207664-16-4-0-32" already exists.
16-May 20:00 ms001-brbkp01-dir JobId 207664: Using Device "FileStorage01" to write.
16-May 20:00 ms001-brbkp01-dir JobId 207664: Connected Client: om024-gw1-fd at om024-gw1.nes.lan:9102, encryption: PSK-AES256-CBC-SHA
16-May 20:00 ms001-brbkp01-dir JobId 207664:  Handshake: Immediate TLS 16-May 20:00 ms001-brbkp01-dir JobId 207664:  Encryption: PSK-AES256-CBC-SHA
16-May 20:00 bareos-fd JobId 207664: Connected Storage daemon at om024-bkp2.nes.lan:9103, encryption: PSK-AES256-CBC-SHA
16-May 20:00 bareos-fd JobId 207664: Extended attribute support is enabled
16-May 20:00 bareos-fd JobId 207664: ACL support is enabled
16-May 20:00 bareos-sd JobId 207664: Volume "om024-bkp2-sd-Incremental-207664-16-4-0-31" previously written, moving to end of data.
16-May 20:00 bareos-sd JobId 207664: Ready to append to end of Volume "om024-bkp2-sd-Incremental-207664-16-4-0-31" size=27796411
16-May 20:00 bareos-sd JobId 207664: Releasing device "FileStorage01" (/storage/backup).
16-May 20:00 bareos-sd JobId 207664: Elapsed time=00:00:01, Transfer rate=0  Bytes/second
16-May 20:00 ms001-brbkp01-dir JobId 207664: Bareos ms001-brbkp01-dir 18.2.5 (30Jan19):
  Build OS:               Linux-4.4.92-6.18-default redhat CentOS Linux release 7.6.1810 (Core) 
  JobId:                  207664
  Job:                    om024-gw1-job.2019-05-16_20.00.08_17
  Backup Level:           Incremental, since=2019-05-15 20:00:27
  Client:                 "om024-gw1-fd" 18.2.5 (30Jan19) Linux-4.4.92-6.18-default,redhat,CentOS Linux release 7.6.1810 (Core) ,CentOS_7,x86_64
  FileSet:                "CentOS7-common" 2018-09-17 18:00:00
  Pool:                   "CentOS7-common-om024-Inc" (From Job IncPool override)
  Catalog:                "ms001-brbkp01" (From Client resource)
  Storage:                "om024-bkp2-sd" (From Pool resource)
  Scheduled time:         16-May-2019 20:00:08
  Start time:             16-May-2019 20:00:51
  End time:               16-May-2019 20:00:52
  Elapsed time:           1 sec
  Priority:               10
  FD Files Written:       0
  SD Files Written:       0
  FD Bytes Written:       0 (0 B)
  SD Bytes Written:       0 (0 B)
  Rate:                   0.0 KB/s
  Software Compression:   None
  VSS:                    no
  Encryption:             no
  Accurate:               no
  Volume name(s):         
  Volume Session Id:      310
  Volume Session Time:    1553756258
  Last Volume Bytes:      0 (0 B)
  Non-fatal FD errors:    1
  SD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Bareos binary info:     bareos.org build: Get official binaries and vendor support on bareos.com
  Termination:            Backup OK -- with warnings
ms001-brbkp01-dir.trace-20190517.txt (9,537 bytes)   
der_andrew

der_andrew

2019-05-31 08:21

reporter   ~0003385

Hi my friend!
Is it enough info? Can I turn off debug level? Its realy HUGE:-)
arogge

arogge

2019-07-09 08:11

manager   ~0003419

When I look at the second attachment from #c3376 I see the following:
16-May 20:00 ms001-brbkp01-dir JobId 207665: Created new Volume "om024-bkp2-sd-Incremental-207665-16-4-0-36" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Created new Volume "om024-bkp2-sd-Incremental-207665-16-4-0-37" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Created new Volume "om024-bkp2-sd-Incremental-207665-16-4-0-38" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Created new Volume "om024-bkp2-sd-Incremental-207665-16-4-0-39" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Created new Volume "om024-bkp2-sd-Incremental-207665-16-4-0-40" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Created new Volume "om024-bkp2-sd-Incremental-207665-16-4-0-41" in catalog.
16-May 20:00 ms001-brbkp01-dir JobId 207665: Error: cats/sql_create.cc:445 Volume "om024-bkp2-sd-Incremental-207665-16-4-0-41" already exists.

This looks like two volumes should be labeled for the same job within one second. This will of course lead to a collision with your configuration.
arogge

arogge

2019-07-09 09:01

manager   ~0003420

Sorry. I'm afraid I have no idea what is wrong here.
It looks like Bareos tries to create two new volumes and the creation of the second one with identical name fails.
I just don't understand why that happens. And cannot find anything helpful in the traces.

If you have any idea how I can reproduce that problem so I can test here, I'm happy to help. But without a way to reproduce it, I'm afraid I cannot do anything else.
der_andrew

der_andrew

2019-07-09 13:38

reporter   ~0003427

Oh! Reproduce is realy challange! I was waiting about a week... Of course I could share my configs, but there are about 100+ servers in my infrastructure)
The only idea is to make smaller time period f.e. Label Format = "$Storage-$Level-$JobId-$Day-$WeekDay-$Hour" and to make smaller f.e. Maximum Volume Bytes = 1M. And than to generate a lot of Jobs per minute/second.

Issue History

Date Modified Username Field Change
2018-10-18 14:54 der_andrew New Issue
2019-02-14 06:50 der_andrew Note Added: 0003260
2019-03-13 18:51 arogge Assigned To => arogge
2019-03-13 18:51 arogge Status new => feedback
2019-03-13 18:51 arogge Note Added: 0003286
2019-04-10 17:45 arogge Note Added: 0003320
2019-04-10 18:17 der_andrew Note Added: 0003321
2019-04-10 18:17 der_andrew Status feedback => assigned
2019-04-11 07:35 der_andrew Note Added: 0003325
2019-04-11 08:28 arogge Note Added: 0003326
2019-04-11 08:43 arogge Note Added: 0003327
2019-04-11 10:12 der_andrew Note Added: 0003330
2019-04-12 07:40 der_andrew File Added: dir.tar.gz
2019-04-12 07:40 der_andrew Note Added: 0003334
2019-04-30 11:15 arogge Note Added: 0003344
2019-04-30 11:15 arogge Status assigned => feedback
2019-04-30 12:16 der_andrew Note Added: 0003345
2019-04-30 12:16 der_andrew Status feedback => assigned
2019-04-30 12:31 arogge Note Added: 0003346
2019-04-30 12:31 arogge Status assigned => feedback
2019-04-30 12:45 der_andrew Note Added: 0003347
2019-04-30 12:45 der_andrew Status feedback => assigned
2019-04-30 12:48 arogge Note Added: 0003348
2019-05-06 08:38 der_andrew Note Added: 0003362
2019-05-16 08:04 der_andrew File Added: ms001-brbkp01-dir.trace-20190516.txt
2019-05-16 08:06 der_andrew File Added: ms001-brbkp01-dir.trace-20190516-2.txt
2019-05-16 08:09 der_andrew Note Added: 0003371
2019-05-16 08:10 der_andrew Note Added: 0003372
2019-05-16 08:13 der_andrew Note Added: 0003373
2019-05-17 09:44 der_andrew File Added: ms001-brbkp01-dir.trace-20190517.txt
2019-05-17 09:44 der_andrew Note Added: 0003376
2019-05-31 08:21 der_andrew Note Added: 0003385
2019-07-09 08:11 arogge Note Added: 0003419
2019-07-09 09:01 arogge Status assigned => feedback
2019-07-09 09:01 arogge Note Added: 0003420
2019-07-09 13:38 der_andrew Note Added: 0003427
2019-07-09 13:38 der_andrew Status feedback => assigned
2023-10-24 09:17 arogge Status assigned => resolved
2023-10-24 09:17 arogge Resolution open => unable to reproduce
2023-10-24 09:17 arogge Status resolved => closed