View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0001395bareos-coreGeneralpublic2021-10-22 17:502021-11-16 15:13
Reporterdedysobr Assigned Tobruno-at-bareos  
PriorityhighSeveritycrashReproducibilityrandom
Status closedResolutionfixed 
PlatformLinuxOSDebianOS Version10
Product Version20.0.2 
Summary0001395: Broken backup
DescriptionFrom time to time in early tasks I see broken backups

Sometimes I receive letters from Bareos stating that the backup is not successful. The problem I see is the following
1) This job number is not displayed in WebGui
2) In the log I see the error "Warning: Error updating job record. Cats / sql_update.cc: 192 Update failed: affected_rows = 0 for UPDATE Job SET JobStatus = 'T', Level = 'F'"
3) There is no way to restore the backup via WebGui since all backups are not visible there.
4) in the postgres database select * from job where jobid = 18099; shows empty.

I have attached a file with an error. The problem is solved only if I add additional volumes. but I think this is a bad decision.
Steps To ReproduceThere is no way to reproduce.
TagsNo tags attached.

Activities

dedysobr

dedysobr

2021-10-22 17:50

reporter  

error.txt (12,592 bytes)    
22-Oct 04:00 bareos-dir JobId 18098: Start Backup JobId 18098, Job=Parus-MTDB.2021-10-22_04.00.00_33
22-Oct 04:00 bareos-dir JobId 18098: Connected Storage daemon at CEUA-BareosDIR:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3 22-Oct 04:00 bareos-dir JobId 18098: Using Device "FileStorage" to write.
22-Oct 04:00 bareos-dir JobId 18098: Probing client protocol... (result will be saved until config reload) 22-Oct 04:00 bareos-dir JobId 18098: Connected Client: Parus-MTDB at 10.26.27.92:9102, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
22-Oct 04:00 bareos-dir JobId 18098:    Handshake: Immediate TLS 22-Oct 04:00 bareos-dir JobId 18098:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
22-Oct 04:00 bareos-sd JobId 18098: Volume "Parus-MTDB-0210" previously written, moving to end of data.
22-Oct 04:00 bareos-sd JobId 18098: Ready to append to end of Volume "Parus-MTDB-0210" size=533650278 22-Oct 04:00 CEUA-TMMTDB JobId 18098: Created 20 wildcard excludes from FilesNotToBackup Registry key 22-Oct 04:00 CEUA-TMMTDB JobId 18098: Connected Storage daemon at CEUA-BareosDIR:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3 22-Oct 04:00 CEUA-TMMTDB JobId 18098: Generate VSS snapshots. Driver="Win64 VSS", Drive(s)="E"
22-Oct 04:00 CEUA-TMMTDB JobId 18098: VolumeMountpoints are not processed as onefs = yes.
22-Oct 04:02 bareos-sd JobId 18098: User defined maximum volume capacity 1,073,741,824 exceeded on device "FileStorage" (/mnt/data-hdd/backups).
22-Oct 04:02 bareos-sd JobId 18098: End of medium on Volume "Parus-MTDB-0210" Bytes=1,073,680,155 Blocks=16,644 at 22-Oct-2021 04:02.
22-Oct 04:02 bareos-dir JobId 18098: Purging oldest volume "Parus-MTDB-1247"
22-Oct 04:02 bareos-dir JobId 18098: 1 File on Volume "Parus-MTDB-1247" purged from catalog.
22-Oct 04:02 bareos-dir JobId 18098: There are no more Jobs associated with Volume "Parus-MTDB-1247". Marking it purged.
22-Oct 04:02 bareos-dir JobId 18098: All records pruned from Volume "Parus-MTDB-1247"; marking it "Purged"
22-Oct 04:02 bareos-sd JobId 18098: Recycled volume "Parus-MTDB-1247" on device "FileStorage" (/mnt/data-hdd/backups), all previous data lost.
22-Oct 04:02 bareos-sd JobId 18098: New volume "Parus-MTDB-1247" mounted on device "FileStorage" (/mnt/data-hdd/backups) at 22-Oct-2021 04:02.
22-Oct 04:08 bareos-sd JobId 18098: User defined maximum volume capacity 1,073,741,824 exceeded on device "FileStorage" (/mnt/data-hdd/backups).
22-Oct 04:08 bareos-sd JobId 18098: End of medium on Volume "Parus-MTDB-1247" Bytes=1,073,737,842 Blocks=16,644 at 22-Oct-2021 04:08.
22-Oct 04:08 bareos-dir JobId 18098: There are no more Jobs associated with Volume "Parus-MTDB-0211". Marking it purged.
22-Oct 04:08 bareos-dir JobId 18098: All records pruned from Volume "Parus-MTDB-0211"; marking it "Purged"
22-Oct 04:08 bareos-dir JobId 18098: Recycled volume "Parus-MTDB-0211"
22-Oct 04:08 bareos-sd JobId 18098: Recycled volume "Parus-MTDB-0211" on device "FileStorage" (/mnt/data-hdd/backups), all previous data lost.
22-Oct 04:08 bareos-sd JobId 18098: New volume "Parus-MTDB-0211" mounted on device "FileStorage" (/mnt/data-hdd/backups) at 22-Oct-2021 04:08.
22-Oct 04:12 bareos-sd JobId 18098: User defined maximum volume capacity 1,073,741,824 exceeded on device "FileStorage" (/mnt/data-hdd/backups).
22-Oct 04:12 bareos-sd JobId 18098: End of medium on Volume "Parus-MTDB-0211" Bytes=1,073,737,853 Blocks=16,644 at 22-Oct-2021 04:12.
22-Oct 04:12 bareos-dir JobId 18098: There are no more Jobs associated with Volume "Parus-MTDB-1992". Marking it purged.
22-Oct 04:12 bareos-dir JobId 18098: All records pruned from Volume "Parus-MTDB-1992"; marking it "Purged"
22-Oct 04:12 bareos-dir JobId 18098: Recycled volume "Parus-MTDB-1992"
22-Oct 04:12 bareos-sd JobId 18098: Recycled volume "Parus-MTDB-1992" on device "FileStorage" (/mnt/data-hdd/backups), all previous data lost.
22-Oct 04:12 bareos-sd JobId 18098: New volume "Parus-MTDB-1992" mounted on device "FileStorage" (/mnt/data-hdd/backups) at 22-Oct-2021 04:12.
22-Oct 04:15 bareos-sd JobId 18098: User defined maximum volume capacity 1,073,741,824 exceeded on device "FileStorage" (/mnt/data-hdd/backups).
22-Oct 04:15 bareos-sd JobId 18098: End of medium on Volume "Parus-MTDB-1992" Bytes=1,073,737,840 Blocks=16,644 at 22-Oct-2021 04:15.
22-Oct 04:15 bareos-dir JobId 18098: There are no more Jobs associated with Volume "Parus-MTDB-1993". Marking it purged.
22-Oct 04:15 bareos-dir JobId 18098: All records pruned from Volume "Parus-MTDB-1993"; marking it "Purged"
22-Oct 04:15 bareos-dir JobId 18098: Recycled volume "Parus-MTDB-1993"
22-Oct 04:15 bareos-sd JobId 18098: Recycled volume "Parus-MTDB-1993" on device "FileStorage" (/mnt/data-hdd/backups), all previous data lost.
22-Oct 04:15 bareos-sd JobId 18098: New volume "Parus-MTDB-1993" mounted on device "FileStorage" (/mnt/data-hdd/backups) at 22-Oct-2021 04:15.
22-Oct 04:19 bareos-sd JobId 18098: User defined maximum volume capacity 1,073,741,824 exceeded on device "FileStorage" (/mnt/data-hdd/backups).
22-Oct 04:19 bareos-sd JobId 18098: End of medium on Volume "Parus-MTDB-1993" Bytes=1,073,737,866 Blocks=16,644 at 22-Oct-2021 04:19.
22-Oct 04:19 bareos-dir JobId 18098: There are no more Jobs associated with Volume "Parus-MTDB-0537". Marking it purged.
22-Oct 04:19 bareos-dir JobId 18098: All records pruned from Volume "Parus-MTDB-0537"; marking it "Purged"
22-Oct 04:19 bareos-dir JobId 18098: Recycled volume "Parus-MTDB-0537"
22-Oct 04:19 bareos-sd JobId 18098: Recycled volume "Parus-MTDB-0537" on device "FileStorage" (/mnt/data-hdd/backups), all previous data lost.
22-Oct 04:19 bareos-sd JobId 18098: New volume "Parus-MTDB-0537" mounted on device "FileStorage" (/mnt/data-hdd/backups) at 22-Oct-2021 04:19.
22-Oct 04:22 bareos-sd JobId 18098: User defined maximum volume capacity 1,073,741,824 exceeded on device "FileStorage" (/mnt/data-hdd/backups).
22-Oct 04:22 bareos-sd JobId 18098: End of medium on Volume "Parus-MTDB-0537" Bytes=1,073,737,896 Blocks=16,644 at 22-Oct-2021 04:22.
22-Oct 04:22 bareos-dir JobId 18098: There are no more Jobs associated with Volume "Parus-MTDB-0538". Marking it purged.
22-Oct 04:22 bareos-dir JobId 18098: All records pruned from Volume "Parus-MTDB-0538"; marking it "Purged"
22-Oct 04:22 bareos-dir JobId 18098: Recycled volume "Parus-MTDB-0538"
22-Oct 04:22 bareos-sd JobId 18098: Recycled volume "Parus-MTDB-0538" on device "FileStorage" (/mnt/data-hdd/backups), all previous data lost.
22-Oct 04:22 bareos-sd JobId 18098: New volume "Parus-MTDB-0538" mounted on device "FileStorage" (/mnt/data-hdd/backups) at 22-Oct-2021 04:22.
22-Oct 04:25 bareos-sd JobId 18098: User defined maximum volume capacity 1,073,741,824 exceeded on device "FileStorage" (/mnt/data-hdd/backups).
22-Oct 04:25 bareos-sd JobId 18098: End of medium on Volume "Parus-MTDB-0538" Bytes=1,073,737,876 Blocks=16,644 at 22-Oct-2021 04:25.
22-Oct 04:25 bareos-dir JobId 18098: There are no more Jobs associated with Volume "Parus-MTDB-1041". Marking it purged.
22-Oct 04:25 bareos-dir JobId 18098: All records pruned from Volume "Parus-MTDB-1041"; marking it "Purged"
22-Oct 04:25 bareos-dir JobId 18098: Recycled volume "Parus-MTDB-1041"
22-Oct 04:25 bareos-sd JobId 18098: Recycled volume "Parus-MTDB-1041" on device "FileStorage" (/mnt/data-hdd/backups), all previous data lost.
22-Oct 04:25 bareos-sd JobId 18098: New volume "Parus-MTDB-1041" mounted on device "FileStorage" (/mnt/data-hdd/backups) at 22-Oct-2021 04:25.
22-Oct 04:28 bareos-sd JobId 18098: User defined maximum volume capacity 1,073,741,824 exceeded on device "FileStorage" (/mnt/data-hdd/backups).
22-Oct 04:28 bareos-sd JobId 18098: End of medium on Volume "Parus-MTDB-1041" Bytes=1,073,737,881 Blocks=16,644 at 22-Oct-2021 04:28.
22-Oct 04:28 bareos-dir JobId 18098: Purging oldest volume "Parus-MTDB-0210"
22-Oct 04:28 bareos-dir JobId 18098: 1 File on Volume "Parus-MTDB-0210" purged from catalog.
22-Oct 04:28 bareos-dir JobId 18098: There are no more Jobs associated with Volume "Parus-MTDB-0210". Marking it purged.
22-Oct 04:28 bareos-dir JobId 18098: All records pruned from Volume "Parus-MTDB-0210"; marking it "Purged"
22-Oct 04:28 bareos-sd JobId 18098: Recycled volume "Parus-MTDB-0210" on device "FileStorage" (/mnt/data-hdd/backups), all previous data lost.
22-Oct 04:28 bareos-sd JobId 18098: New volume "Parus-MTDB-0210" mounted on device "FileStorage" (/mnt/data-hdd/backups) at 22-Oct-2021 04:28.
22-Oct 04:31 CEUA-TMMTDB JobId 18098: VSS Writer (BackupComplete): "Task Scheduler Writer", State: 0x1 (VSS_WS_STABLE) 22-Oct 04:31 CEUA-TMMTDB JobId 18098: VSS Writer (BackupComplete): "VSS Metadata Store Writer", State: 0x1 (VSS_WS_STABLE) 22-Oct 04:31 CEUA-TMMTDB JobId 18098: VSS Writer (BackupComplete): "Performance Counters Writer", State: 0x1 (VSS_WS_STABLE) 22-Oct 04:31 CEUA-TMMTDB JobId 18098: VSS Writer (BackupComplete): "System Writer", State: 0x1 (VSS_WS_STABLE) 22-Oct 04:31 CEUA-TMMTDB JobId 18098: VSS Writer (BackupComplete): "ASR Writer", State: 0x1 (VSS_WS_STABLE) 22-Oct 04:31 CEUA-TMMTDB JobId 18098: VSS Writer (BackupComplete): "SqlServerWriter", State: 0x1 (VSS_WS_STABLE) 22-Oct 04:31 CEUA-TMMTDB JobId 18098: VSS Writer (BackupComplete): "Shadow Copy Optimization Writer", State: 0x1 (VSS_WS_STABLE) 22-Oct 04:31 CEUA-TMMTDB JobId 18098: VSS Writer (BackupComplete): "COM+ REGDB Writer", State: 0x1 (VSS_WS_STABLE) 22-Oct 04:31 CEUA-TMMTDB JobId 18098: VSS Writer (BackupComplete): "WMI Writer", State: 0x1 (VSS_WS_STABLE) 22-Oct 04:31 CEUA-TMMTDB JobId 18098: VSS Writer (BackupComplete): "Registry Writer", State: 0x1 (VSS_WS_STABLE) 22-Oct 04:31 bareos-sd JobId 18098: Releasing device "FileStorage" (/mnt/data-hdd/backups).
22-Oct 04:31 bareos-sd JobId 18098: Elapsed time=00:31:38, Transfer rate=4.796 M Bytes/second 22-Oct 04:31 bareos-dir JobId 18098: Insert of attributes batch table with 2 entries start 22-Oct 04:31 bareos-dir JobId 18098: Insert of attributes batch table done 22-Oct 04:31 bareos-dir JobId 18098: Warning: Error updating job record. cats/sql_update.cc:192 Update failed: affected_rows=0 for UPDATE Job SET JobStatus='T',Level='F',EndTime='2021-10-22 04:31:44',ClientId=65,JobBytes=9103248382,ReadBytes=45373524056,JobFiles=3,JobErrors=0,VolSessionId=2100,VolSessionTime=1626181830,PoolId=86,FileSetId=71,JobTDate=1634866304,RealEndTime='2021-10-22 04:31:44',PriorJobId=0,HasBase=0,PurgedFiles=0 WHERE JobId=18098 22-Oct 04:31 bareos-dir JobId 18098: Warning: Error getting Job record for Job report: ERR=cats/sql_get.cc:273 No Job found for JobId 18098 22-Oct 04:31 bareos-dir JobId 18098: Error: Bareos bareos-dir 20.0.1 (02Mar21):
  Build OS:               Debian GNU/Linux 10 (buster)
  JobId:                  18098
  Job:                    Parus-MTDB.2021-10-22_04.00.00_33
  Backup Level:           Full
  Client:                 "Parus-MTDB" 20.0.1 (02Mar21) Microsoft Windows Server 2012 Standard Edition (build 9200), 64-bit,Cross-compile
  FileSet:                "Parus-MTDB" 2021-03-17 16:36:11
  Pool:                   "Parus-MTDB" (From Job resource)
  Catalog:                "MyCatalog" (From Client resource)
  Storage:                "File" (From Pool resource)
  Scheduled time:         22-Oct-2021 04:00:00
  Start time:             22-Oct-2021 04:00:01
  End time:               22-Oct-2021 04:31:44
  Elapsed time:           31 mins 43 secs
  Priority:               10
  FD Files Written:       3
  SD Files Written:       3
  FD Bytes Written:       9,103,248,382 (9.103 GB)
  SD Bytes Written:       9,103,249,124 (9.103 GB)
  Rate:                   4783.6 KB/s
  Software Compression:   79.9 % (gzip)
  VSS:                    yes
  Encryption:             no
  Accurate:               no
  Volume name(s):         Parus-MTDB-0210
  Volume Session Id:      2100
  Volume Session Time:    1626181830
  Last Volume Bytes:      1,060,450,613 (1.060 GB)
  Non-fatal FD errors:    0
  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
  Job triggered by:       Scheduler
  Termination:            *** Backup Error ***

22-Oct 04:31 bareos-dir JobId 18098: Begin pruning Jobs older than 1 month .
22-Oct 04:31 bareos-dir JobId 18098: No Jobs found to prune.
22-Oct 04:31 bareos-dir JobId 18098: Begin pruning Files.
22-Oct 04:31 bareos-dir JobId 18098: No Files found to prune.
22-Oct 04:31 bareos-dir JobId 18098: End auto prune.
error.txt (12,592 bytes)   
bruno-at-bareos

bruno-at-bareos

2021-11-16 15:12

manager   ~0004338

Hello, did you pay attention to the following in your error log

```
22-Oct 04:00 bareos-sd JobId 18098: Volume "Parus-MTDB-0210" previously written, moving to end of data.
22-Oct 04:00 bareos-sd JobId 18098: Ready to append to end of Volume "Parus-MTDB-0210" size=533650278 22-Oct 04:00 CEUA-TMMTDB JobId 18098: Created 20 wildcard excludes from FilesNotToBackup Registry key
22-Oct 04:00 CEUA-TMMTDB JobId 18098: Connected Storage daemon at CEUA-BareosDIR:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
22-Oct 04:00 CEUA-TMMTDB JobId 18098: Generate VSS snapshots. Driver="Win64 VSS", Drive(s)="E"
22-Oct 04:00 CEUA-TMMTDB JobId 18098: VolumeMountpoints are not processed as onefs = yes.
22-Oct 04:02 bareos-sd JobId 18098: User defined maximum volume capacity 1,073,741,824 exceeded on device "FileStorage" (/mnt/data-hdd/backups).
22-Oct 04:02 bareos-sd JobId 18098: End of medium on Volume "Parus-MTDB-0210" Bytes=1,073,680,155 Blocks=16,644 at 22-Oct-2021 04:02.

```

and at the end of the block

```
22-Oct 04:28 bareos-dir JobId 18098: Purging oldest volume "Parus-MTDB-0210"
22-Oct 04:28 bareos-dir JobId 18098: 1 File on Volume "Parus-MTDB-0210" purged from catalog.
22-Oct 04:28 bareos-dir JobId 18098: There are no more Jobs associated with Volume "Parus-MTDB-0210". Marking it purged.
22-Oct 04:28 bareos-dir JobId 18098: All records pruned from Volume "Parus-MTDB-0210"; marking it "Purged"
22-Oct 04:28 bareos-sd JobId 18098: Recycled volume "Parus-MTDB-0210" on device "FileStorage" (/mnt/data-hdd/backups), all previous data lost.
22-Oct 04:28 bareos-sd JobId 18098: New volume "Parus-MTDB-0210" mounted on device "FileStorage" (/mnt/data-hdd/backups) at 22-Oct-2021 04:28.

```

So the job is initialized with Parus-MTDB-0210, every 1GB a media is purge (mean all containing job get deleted from the database), and a new media is used.
As you didn't provide any other information on your configuration, it look like your pool didn't provide enough volumes for the job, and/or as a spurious recycle configuration,
then at the end of the job the first volume used get again purged and as such, the jobid was deleted from the catalog, which lead to the warning/error update of the job which didn't exist anymore.

You will have to review carefully the way you have defined your pool and volume recycling mechanism.
I will close this report as non bug.
Regards
bruno-at-bareos

bruno-at-bareos

2021-11-16 15:13

manager   ~0004339

not a bug as such. Configuration not valid

Issue History

Date Modified Username Field Change
2021-10-22 17:50 dedysobr New Issue
2021-10-22 17:50 dedysobr File Added: error.txt
2021-11-16 15:12 bruno-at-bareos Note Added: 0004338
2021-11-16 15:12 bruno-at-bareos Assigned To => bruno-at-bareos
2021-11-16 15:12 bruno-at-bareos Status new => assigned
2021-11-16 15:13 bruno-at-bareos Status assigned => closed
2021-11-16 15:13 bruno-at-bareos Resolution open => fixed
2021-11-16 15:13 bruno-at-bareos Note Added: 0004339