Backup Error with virtual full

[Philippe]

Hi all,

I'm using bareos for a while now for making backups of a nextcloud
instance using 'always incremental'.

Since having upgraded to bareos 23.0.3 the virtual full shows me this
message:

> 12-Jun 12:30 director JobId 42456: Start Virtual Backup JobId 42456, Job=backup-myclient-nextcloud.2024-06-12_12.30.01_07
> 12-Jun 12:30 director JobId 42456: Bootstrap records written to /var/lib/bareos/director.restore.7.bsr
> 12-Jun 12:30 director JobId 42456: Consolidating JobIds 42340,41536,41594 containing 371868 files
> 12-Jun 12:30 director JobId 42456: Connected Storage daemon at storage:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
> 12-Jun 12:30 director JobId 42456: Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
> 12-Jun 12:30 director JobId 42456: Using Device "File-storage" to read.
> 12-Jun 12:30 director JobId 42456: Max configured use duration=82,800 sec. exceeded. Marking Volume "AI-Consolidated-0542" as Used.
> 12-Jun 12:30 director JobId 42456: Created new Volume "AI-Consolidated-0577" in catalog.
> 12-Jun 12:30 director JobId 42456: Using Device "File-Consolidated-storage" to write.
> 12-Jun 12:30 storage JobId 42456: Labeled new Volume "AI-Consolidated-0577" on device "File-Consolidated-storage" (/backup/bareos-consolidated-tape).
> 12-Jun 12:30 storage JobId 42456: Wrote label to prelabeled Volume "AI-Consolidated-0577" on device "File-Consolidated-storage" (/backup/bareos-consolidated-tape)
> 12-Jun 12:30 storage JobId 42456: Ready to read from volume "AI-Consolidated-0506" on device "File-storage" (/backup/bareos-tape).
> 12-Jun 12:30 storage JobId 42456: Forward spacing Volume "AI-Consolidated-0506" to file:block 0:257.
> 12-Jun 12:52 storage JobId 42456: End of Volume at file 15 on device "File-storage" (/backup/bareos-tape), Volume "AI-Consolidated-0506"
> 12-Jun 12:52 storage JobId 42456: Ready to read from volume "AI-Incremental-0525" on device "File-storage" (/backup/bareos-tape).
> 12-Jun 12:52 storage JobId 42456: Forward spacing Volume "AI-Incremental-0525" to file:block 0:256.
> 12-Jun 12:52 storage JobId 42456: Error: stored/block.cc:291 Volume data error at 0:256! Wanted ID: "BB02", got "B02". Buffer discarded.
> 12-Jun 12:52 storage JobId 42456: Fatal error: stored/mac.cc:696 Fatal append error on device "File-Consolidated-storage" (/backup/bareos-consolidated-tape): ERR=stored/dev.cc:597 Could not open: /backup/bareos-consolidated-tape/AI-Consolidated-0577, ERR=No such file or directory
>
> 12-Jun 12:52 storage JobId 42456: Elapsed time=00:21:56, Transfer rate=49.01 M Bytes/second
> 12-Jun 12:52 storage JobId 42456: Releasing device "File-Consolidated-storage" (/backup/bareos-consolidated-tape).
> 12-Jun 12:52 storage JobId 42456: Releasing device "File-storage" (/backup/bareos-tape).
> 12-Jun 12:52 director JobId 42456: Insert of attributes batch table with 371768 entries start
> 12-Jun 12:52 director JobId 42456: Insert of attributes batch table done
> 12-Jun 12:52 director JobId 42456: Replicating deleted files from jobids 42340,41536,41594 to jobid 42456
> 12-Jun 12:52 director JobId 42456: Error: lib/bsock_tcp.cc:418 Wrote -4 bytes to Storage daemon:storage:9103, but only 0 accepted.
> 12-Jun 12:52 director JobId 42456: Error: Bareos director 23.0.3 (04Jun24):
> Build OS: Red Hat Enterprise Linux release 9.4 (Plow)
> JobId: 42456
> Job: backup-myclient-nextcloud.2024-06-12_12.30.01_07
> Backup Level: Virtual Full
> Client: "myclient" 23.0.3 (04Jun24) Oracle Linux Server release 8.10,redhat
> FileSet: "nextcloud" 2022-04-29 00:20:01
> Pool: "AI-Consolidated" (From Job Pool's NextPool resource)
> Catalog: "MyCatalog" (From Client resource)
> Storage: "File-Consolidated-storage" (From Storage from Pool's NextPool resource)
> Scheduled time: 12-Jun-2024 12:30:01
> Start time: 30-May-2024 12:21:44
> End time: 30-May-2024 12:23:48
> Elapsed time: 2 mins 4 secs
> Priority: 20
> Allow Mixed Priority: no
> SD Files Written: 371,768
> SD Bytes Written: 64,508,320,142 (64.50 GB)
> Rate: 520228.4 KB/s
> Volume name(s): AI-Consolidated-0577
> Volume Session Id: 55
> Volume Session Time: 1718194593
> Last Volume Bytes: 64,532,512,888 (64.53 GB)
> SD Errors: 1
> SD termination status: Error
> Accurate: yes
> Bareos binary info: Self-compiled: Get professional support from https://www.bareos.com
> Job triggered by: User
> Termination: *** Backup Error ***

The "No such file or directory" error is probably misleading, as the
file exists and is something like 61 GiB of size.

I read about a bug in Bareos 22.0.0 that could have caused this issue
but 22.0.0 was a long time ago and my previous version was 23.0.2.

These are the corresponding lines from jobmedia:

> $ psql <<<'select * from jobmedia where jobid=42751'
> jobmediaid | jobid | mediaid | firstindex | lastindex | startfile | endfile | startblock | endblock | jobbytes | volindex
> ------------+-------+---------+------------+-----------+-----------+---------+------------+------------+----------+----------
> 128106 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1
> 128107 | 42751 | 585 | 1 | 14085 | 0 | 0 | 254 | 999293180 | 0 | 2
> 128108 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 3
> 128109 | 42751 | 585 | 14085 | 28894 | 0 | 0 | 999293181 | 1998586084 | 0 | 4
> 128110 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 5
> 128111 | 42751 | 585 | 28894 | 32067 | 0 | 0 | 1998586085 | 2997879012 | 0 | 6
> 128112 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 7
> 128113 | 42751 | 585 | 32067 | 34575 | 0 | 0 | 2997879013 | 3997171940 | 0 | 8
> 128114 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 9
> 128115 | 42751 | 585 | 34575 | 45716 | 0 | 1 | 3997171941 | 701497572 | 0 | 10
> 128116 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 11
> 128117 | 42751 | 585 | 45716 | 46431 | 1 | 1 | 701497573 | 1700790500 | 0 | 12
> 128118 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 13
> 128119 | 42751 | 585 | 46431 | 46785 | 1 | 1 | 1700790501 | 2700083428 | 0 | 14
> 128120 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 15
> 128121 | 42751 | 585 | 46785 | 46792 | 1 | 1 | 2700083429 | 3699376346 | 0 | 16
> 128122 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 17
> 128123 | 42751 | 585 | 46792 | 46800 | 1 | 2 | 3699376347 | 403701978 | 0 | 18
> 128124 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 19
> 128125 | 42751 | 585 | 46800 | 46820 | 2 | 2 | 403701979 | 1402994906 | 0 | 20
> 128126 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 21
> 128127 | 42751 | 585 | 46820 | 47101 | 2 | 2 | 1402994907 | 2402287834 | 0 | 22
> 128128 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 23
> 128129 | 42751 | 585 | 47101 | 47101 | 2 | 2 | 2402287835 | 3401580762 | 0 | 24
> 128130 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 25
> 128131 | 42751 | 585 | 47101 | 47447 | 2 | 3 | 3401580763 | 105906394 | 0 | 26
> 128132 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 27
> 128133 | 42751 | 585 | 47447 | 49108 | 3 | 3 | 105906395 | 1105199322 | 0 | 28
> 128134 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 29
> 128135 | 42751 | 585 | 49108 | 50054 | 3 | 3 | 1105199323 | 2104492250 | 0 | 30
> 128136 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 31
> 128137 | 42751 | 585 | 50054 | 50273 | 3 | 3 | 2104492251 | 3103785178 | 0 | 32
> 128138 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 33
> 128139 | 42751 | 585 | 50273 | 50302 | 3 | 3 | 3103785179 | 4103078106 | 0 | 34
> 128140 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 35
> 128141 | 42751 | 585 | 50302 | 50312 | 3 | 4 | 4103078107 | 807403738 | 0 | 36
> 128142 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 37
> 128143 | 42751 | 585 | 50312 | 50494 | 4 | 4 | 807403739 | 1806696666 | 0 | 38
> 128144 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 39
> 128145 | 42751 | 585 | 50494 | 50551 | 4 | 4 | 1806696667 | 2805989592 | 0 | 40
> 128146 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 41
> 128147 | 42751 | 585 | 50551 | 50573 | 4 | 4 | 2805989593 | 3805282520 | 0 | 42
> 128148 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 43
> 128149 | 42751 | 585 | 50573 | 50600 | 4 | 5 | 3805282521 | 509608151 | 0 | 44
> 128150 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 45
> 128151 | 42751 | 585 | 50600 | 50626 | 5 | 5 | 509608152 | 1508901079 | 0 | 46
> 128152 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 47
> 128153 | 42751 | 585 | 50626 | 50651 | 5 | 5 | 1508901080 | 2508194000 | 0 | 48
> 128154 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 49
> 128155 | 42751 | 585 | 50651 | 50683 | 5 | 5 | 2508194001 | 3507486923 | 0 | 50
> 128156 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 51
> 128157 | 42751 | 585 | 50683 | 50726 | 5 | 6 | 3507486924 | 211812555 | 0 | 52
> 128158 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 53
> 128159 | 42751 | 585 | 50726 | 50901 | 6 | 6 | 211812556 | 1211105483 | 0 | 54
> 128160 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 55
> 128161 | 42751 | 585 | 50901 | 52657 | 6 | 6 | 1211105484 | 2210398403 | 0 | 56
> 128162 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 57
> 128163 | 42751 | 585 | 52657 | 54395 | 6 | 6 | 2210398404 | 3209691331 | 0 | 58
> 128164 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 59
> 128165 | 42751 | 585 | 54395 | 56100 | 6 | 6 | 3209691332 | 4208984259 | 0 | 60
> 128166 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 61
> 128167 | 42751 | 585 | 56100 | 57485 | 6 | 7 | 4208984260 | 913309886 | 0 | 62
> 128168 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 63
> 128169 | 42751 | 585 | 57485 | 59173 | 7 | 7 | 913309887 | 1912602814 | 0 | 64
> 128170 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 65
> 128171 | 42751 | 585 | 59173 | 60681 | 7 | 7 | 1912602815 | 2911895742 | 0 | 66
> 128172 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 67
> 128173 | 42751 | 585 | 60681 | 61832 | 7 | 7 | 2911895743 | 3911188670 | 0 | 68
> 128174 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 69
> 128175 | 42751 | 585 | 61832 | 62430 | 7 | 8 | 3911188671 | 615514302 | 0 | 70
> 128176 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 71
> 128177 | 42751 | 585 | 62430 | 63425 | 8 | 8 | 615514303 | 1614807230 | 0 | 72
> 128178 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 73
> 128179 | 42751 | 585 | 63425 | 63676 | 8 | 8 | 1614807231 | 2614100158 | 0 | 74
> 128180 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 75
> 128181 | 42751 | 585 | 63676 | 64017 | 8 | 8 | 2614100159 | 3613393086 | 0 | 76
> 128182 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 77
> 128183 | 42751 | 585 | 64017 | 64090 | 8 | 9 | 3613393087 | 317718718 | 0 | 78
> 128184 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 79
> 128185 | 42751 | 585 | 64090 | 64279 | 9 | 9 | 317718719 | 1317011646 | 0 | 80
> 128186 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 81
> 128187 | 42751 | 585 | 64279 | 81118 | 9 | 9 | 1317011647 | 2316304574 | 0 | 82
> 128188 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 83
> 128189 | 42751 | 585 | 81118 | 81553 | 9 | 9 | 2316304575 | 3315597502 | 0 | 84
> 128190 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 85
> 128191 | 42751 | 585 | 81553 | 82580 | 9 | 10 | 3315597503 | 19923128 | 0 | 86
> 128192 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 87
> 128193 | 42751 | 585 | 82580 | 93528 | 10 | 10 | 19923129 | 1019216037 | 0 | 88
> 128194 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 89
> 128195 | 42751 | 585 | 93528 | 93895 | 10 | 10 | 1019216038 | 2018508965 | 0 | 90
> 128196 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 91
> 128197 | 42751 | 585 | 93895 | 94309 | 10 | 10 | 2018508966 | 3017801887 | 0 | 92
> 128198 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 93
> 128199 | 42751 | 585 | 94309 | 94693 | 10 | 10 | 3017801888 | 4017094815 | 0 | 94
> 128200 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 95
> 128201 | 42751 | 585 | 94693 | 94980 | 10 | 11 | 4017094816 | 721420447 | 0 | 96
> 128202 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 97
> 128203 | 42751 | 585 | 94980 | 95135 | 11 | 11 | 721420448 | 1720713375 | 0 | 98
> 128204 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 99
> 128205 | 42751 | 585 | 95135 | 95165 | 11 | 11 | 1720713376 | 2720006303 | 0 | 100
> 128206 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 101
> 128207 | 42751 | 585 | 95165 | 95514 | 11 | 11 | 2720006304 | 3719299231 | 0 | 102
> 128208 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 103
> 128209 | 42751 | 585 | 95514 | 96410 | 11 | 12 | 3719299232 | 423624863 | 0 | 104
> 128210 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 105
> 128211 | 42751 | 585 | 96410 | 97852 | 12 | 12 | 423624864 | 1422917791 | 0 | 106
> 128212 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 107
> 128213 | 42751 | 585 | 97852 | 134760 | 12 | 12 | 1422917792 | 2422210706 | 0 | 108
> 128214 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 109
> 128215 | 42751 | 585 | 134760 | 134980 | 12 | 12 | 2422210707 | 3421503633 | 0 | 110
> 128216 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 111
> 128217 | 42751 | 585 | 134980 | 136308 | 12 | 13 | 3421503634 | 125829265 | 0 | 112
> 128218 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 113
> 128219 | 42751 | 585 | 136308 | 136402 | 13 | 13 | 125829266 | 1125122193 | 0 | 114
> 128220 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 115
> 128221 | 42751 | 585 | 136402 | 136402 | 13 | 13 | 1125122194 | 2124415121 | 0 | 116
> 128222 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 117
> 128223 | 42751 | 585 | 136402 | 136605 | 13 | 13 | 2124415122 | 3123708049 | 0 | 118
> 128224 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 119
> 128225 | 42751 | 585 | 136605 | 139491 | 13 | 13 | 3123708050 | 4123000977 | 0 | 120
> 128226 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 121
> 128227 | 42751 | 585 | 139491 | 191423 | 13 | 14 | 4123000978 | 827326594 | 0 | 122
> 128228 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 123
> 128229 | 42751 | 585 | 191423 | 370188 | 14 | 14 | 827326595 | 1826619502 | 0 | 124
> 128230 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 125
> 128231 | 42751 | 585 | 370188 | 371136 | 14 | 14 | 1826619503 | 2825912430 | 0 | 126
> 128232 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 127
> 128233 | 42751 | 585 | 371136 | 371430 | 14 | 14 | 2825912431 | 3825205358 | 0 | 128
> 128234 | 42751 | 585 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 129
> 128235 | 42751 | 585 | 371430 | 371752 | 14 | 15 | 3825205359 | 108003438 | 0 | 130
> (130 rows)

Does anyone have an idea how to fix this?

Thanks!

[Andreas Rogge]

Hi Philippe,

I know there can be misleading errors in Bareos. But when Bareos logs a
"No such file or directory" from that location in the code, then the
file or directory doesn't exist.

Best Regards,
Andreas

--
Andreas Rogge andrea...@bareos.com
Bareos GmbH & Co. KG Phone: +49 221-630693-86
http://www.bareos.com

Sitz der Gesellschaft: Köln | Amtsgericht Köln: HRA 29646
Komplementär: Bareos Verwaltungs-GmbH
Geschäftsführer: Stephan Dühr, Jörg Steffens, Philipp Storz

[Philippe]

(re-sending to list)

Hi Andreas,


thanks for clarifying this. So, probably at least after Bareos throwing
the "does not exists" error the file shows up with a size of 61GiB.

Taking a closer look this report seem to have two errors, one
"non-fatal" error saying

> Volume data error at 0:256! Wanted ID: "BB02", got "B02". Buffer discarded.

and the "fatal" error related to the non-existing file at some point of
time.

I don't know what's broken here but since the errors are refering to
different files every day regarding the fatal error but not the
"non-fatal" error, I believe the AI-Incremental-0525 file (which exists
for a month now and is 530M of size) might be corrupted.

> 12-Jun 12:52 storage JobId 42456: Forward spacing Volume "AI-Incremental-0525" to file:block 0:256.
> 12-Jun 12:52 storage JobId 42456: Error: stored/block.cc:291 Volume data error at 0:256! Wanted ID: "BB02", got "B02". Buffer discarded.
> 12-Jun 12:52 storage JobId 42456: Fatal error: stored/mac.cc:696 Fatal append error on device "File-Consolidated-storage" (/backup/bareos-consolidated-tape): ERR=stored/dev.cc:597 Could not open: /backup/bareos-consolidated-tape/AI-Consolidated-0577, ERR=No such file or directory
>

> 13-Jun 12:54 storage JobId 42515: Forward spacing Volume "AI-Incremental-0525" to file:block 0:256.
> 13-Jun 12:54 storage JobId 42515: Error: stored/block.cc:291 Volume data error at 0:256! Wanted ID: "BB02", got "B02". Buffer discarded.
> 13-Jun 12:54 storage JobId 42515: Fatal error: stored/mac.cc:696 Fatal append error on device "File-Consolidated-storage" (/backup/bareos-consolidated-tape): ERR=stored/dev.cc:597 Could not open: /backup/bareos-consolidated-tape/AI-Consolidated-0578, ERR=No such file or directory
>
> 14-Jun 12:54 storage JobId 42574: Forward spacing Volume "AI-Incremental-0525" to file:block 0:256.
> 14-Jun 12:54 storage JobId 42574: Error: stored/block.cc:291 Volume data error at 0:256! Wanted ID: "BB02", got "B02". Buffer discarded.
> 14-Jun 12:54 storage JobId 42574: Fatal error: stored/mac.cc:696 Fatal append error on device "File-Consolidated-storage" (/backup/bareos-consolidated-tape): ERR=stored/dev.cc:597 Could not open: /backup/bareos-consolidated-tape/AI-Consolidated-0579, ERR=No such file or directory
>
> 15-Jun 13:03 storage JobId 42633: Forward spacing Volume "AI-Incremental-0525" to file:block 0:256.
> 15-Jun 13:03 storage JobId 42633: Error: stored/block.cc:291 Volume data error at 0:256! Wanted ID: "BB02", got "B02". Buffer discarded.
> 15-Jun 13:03 storage JobId 42633: Fatal error: stored/mac.cc:696 Fatal append error on device "File-Consolidated-storage" (/backup/bareos-consolidated-tape): ERR=stored/dev.cc:597 Could not open: /backup/bareos-consolidated-tape/AI-Consolidated-0581, ERR=No such file or directory
>
> 16-Jun 12:51 storage JobId 42692: Forward spacing Volume "AI-Incremental-0525" to file:block 0:256.
> 16-Jun 12:51 storage JobId 42692: Error: stored/block.cc:291 Volume data error at 0:256! Wanted ID: "BB02", got "B02". Buffer discarded.
> 16-Jun 12:51 storage JobId 42692: Fatal error: stored/mac.cc:696 Fatal append error on device "File-Consolidated-storage" (/backup/bareos-consolidated-tape): ERR=stored/dev.cc:597 Could not open: /backup/bareos-consolidated-tape/AI-Consolidated-0583, ERR=No such file or directory
>
> 17-Jun 12:53 storage JobId 42751: Forward spacing Volume "AI-Incremental-0525" to file:block 0:256.
> 17-Jun 12:53 storage JobId 42751: Error: stored/block.cc:291 Volume data error at 0:256! Wanted ID: "BB02", got "B02". Buffer discarded.
> 17-Jun 12:53 storage JobId 42751: Fatal error: stored/mac.cc:696 Fatal append error on device "File-Consolidated-storage" (/backup/bareos-consolidated-tape): ERR=stored/dev.cc:597 Could not open: /backup/bareos-consolidated-tape/AI-Consolidated-0585, ERR=No such file or directory

So, are some of my backups lost? What can I do here - remove the
nextcloud-jobs and all previous backups and start from scratch?

Kind regards,

Philippe

[Sebastian Sura]

Hi Philippe

It looks like the first block header of your volume somehow got corrupted.
Could you try to read the first 24 bytes of that volume and send them
here  ?
The block header is supposed to look like this:
https://docs.bareos.org/DeveloperGuide/mediaformat.html#block-header
While its probably not possible repair the block header ourselves, we
might be able to identify which byte was not written
and try to put it into a state where bareos will accept it.

Kind Regards
Sebastian Sura

Am 17.06.24 um 16:48 schrieb 'Philippe' via bareos-users:

--
Sebastian Sura sebasti...@bareos.com
Bareos GmbH & Co. KG Phone: +49 221 630693-0
https://www.bareos.com

[Philippe]

Hi Sebastian,

thanks for your answer!

Here's what I get from the disk:

> $ dd if=AI-Incremental-0525 bs=24 count=1 status=none | xxd
> 00000000: c75d 2e97 0000 00ff 0000 0000 4242 3032 .]..........BB02
> 00000010: 0000 0030 6640 9701 ...0f@..

comparing this with another file it doesn't look that bad for me:

> $ dd if=AI-Incremental-0526 bs=24 count=1 status=none | xxd
> 00000000: d5fa 7af2 0000 00ff 0000 0000 4242 3032 ..z.........BB02
> 00000010: 0000 0030 6659 a382 ...0fY..

fwiw: the data resides on a zfs (scrubbed, verified) and the sd machine
powers up before the backups start and shuts down when completed.


Kind regards,

Philippe

[Sebastian Sura]

Hi Philippe

Looks like i misread your joblog.  I missed that its forwarding the
volume to 0:256 (i.e. it skips the first 256 bytes [0, 255]).
That means that the first 256 bytes (the volume label) are read
correctly (as you verified).
Could you instead post the bytes [256, 280] (or to make off-by-ones more
unlikely, the first 300 bytes) ?
Sorry for the inconvenience!

Kind Regards
Sebastian Sura

Am 18.06.24 um 11:14 schrieb 'Philippe' via bareos-users:

[Philippe]

Hi Sebastian,

thanks for your reply.

Sure - here are the first 304 bytes:

> $ dd if=AI-Incremental-0525 bs=304 count=1 status=none | xxd

> 00000000: c75d 2e97 0000 00ff 0000 0000 4242 3032 .]..........BB02

> 00000010: 0000 0030 6640 9701 ffff fffe 0000 0000 ...0f@..........
> 00000020: 0000 00db 4261 7265 6f73 2032 2e30 2069 ....Bareos 2.0 i
> 00000030: 6d6d 6f72 7461 6c0a 0000 0000 1400 05f2 mmortal.........
> 00000040: 2d86 4318 e000 0618 3f24 27be 9700 0000 -.C.....?$'.....
> 00000050: 0000 0000 0000 0000 0000 0000 0041 492d .............AI-
> 00000060: 496e 6372 656d 656e 7461 6c2d 3035 3235 Incremental-0525
> 00000070: 0000 4149 2d49 6e63 7265 6d65 6e74 616c ..AI-Incremental
> 00000080: 0042 6163 6b75 7000 4669 6c65 0073 6372 .Backup.File.scr
> 00000090: 6174 6368 792e 696e 7472 616e 6574 2e75 atchy.intranet.u
> 000000a0: 6e69 7861 646d 2e6f 7267 0073 6372 6174 nixadm.org.scrat
> 000000b0: 6368 792e 696e 7472 616e 6574 2e75 6e69 chy.intranet.uni
> 000000c0: 7861 646d 2e6f 7267 0056 6572 2e20 3232 xadm.org.Ver. 22
> 000000d0: 2e30 2e31 2030 3220 4a61 6e75 6172 7920 .0.1 02 January
> 000000e0: 3230 3233 0042 7569 6c64 2032 3032 332d 2023.Build 2023-
> 000000f0: 3031 2d30 3220 3135 3a35 393a 3335 0040 01-02 15:59:35.@
> 00000100: 5ae0 9300 1000 0000 0000 0042 4230 3200 Z..........BB02.
> 00000110: 0000 3066 4097 01ff ffff fc00 009e 6400 ..0f@.........d.
> 00000120: 0000 f042 6172 656f 7320 322e 3020 696d ...Bareos 2.0 im

As I read a suspicious "Bareos 22.0.1" in there I reckon it might have
something to do with what I read earler at
https://groups.google.com/g/bareos-users/c/HNEG3fSuCtk/m/eE9pJRA1BgAJ

Kind regards,

Philippe

[Sebastian Sura]

Hi Philippe

from what i can tell your volume is fine.  I assume there is an issue in
your database however. You probably have a jobmedia id on that volume
with startblock 256 when it should be 255.

As you were consolidating the jobs 42340,41536,41594, it is safe to
assume that the problem is one of these jobs.  I assume that the mediaid
of the affected volume is 525 (but double check this), so try checking
all jobmedia entries from those jobs on this volume and see if this is
indeed the case.

One thing i find weird is that to me it looks like the first record on
the volume is a StartOfSession record for jobid 40548, so maybe there
was a mixup somehow ?

You can check the records on a volume with "bscan -r/--list-records". 
Maybe this can help you figure out what happened.

Kind Regards
Sebastian Sura

Am 18.06.24 um 19:57 schrieb 'Philippe' via bareos-users:

[Philippe]

Hi Sebastian,

that's a good approach :)

The only jobmedia entry for job 41536 is:

> $ psql <<<'select * from jobmedia where jobid=41536'

> jobmediaid | jobid | mediaid | firstindex | lastindex | startfile | endfile | startblock | endblock | jobbytes | volindex

> ------------+-------+---------+------------+-----------+-----------+---------+------------+----------+----------+----------
> 123840 | 41536 | 525 | 1 | 50 | 0 | 0 | 256 | 16770527 | 0 | 2

Is it safe to "just" update the startblock value to 255?

Job 40548 is somehow gone as I can't find it in the database. Probably
it was no longer needed, i.e. from a decommissioned client or the jobs
on that client changed.

How do I get bscan to work, what's the right way and what's needed to
invoke it?
I presume it needs both the database connection and the sd configs,
right? Asking because the director (which also hosts the database) has
no sd configs and on the other hand the sd has no database access.

Thank you & kind regards,

Philippe



On 6/19/24 08:29, Sebastian Sura wrote:
[snipped]

[Sebastian Sura]

Could you post the joblog of that job ? If you cannot find 40548 in the
database, then its probably because it got consolidated into a different
job (maybe even into 41536).

bscan currently needs access to both the storage configuration as well
as the database.  Alternatively you can also use bls instead which just
needs access to the sd configuration.

In regards to updating the database: I would suggest that if you do
that, that you make sure that you do not consolidate that job at first
and instead do a normal restore with the updated entry and check that
that 1) the restore works and 2) the files that were restored make sense
to you, i.e. compare them with the entries of the job table for that job.
Its hard to say why this happened so i cannot comment on how safe it is
to keep using that incremental for consolidations.  If possible try
creating a new full instead.

Kind Regards
Sebastian Sura

Am 19.06.24 um 09:54 schrieb 'Philippe' via bareos-users:

[Philippe]

Hi,

there's no joblog of 40548 anymore, or did I look at the wrong places
(no conmsg, no mails)?

'bls' shows no errors, it lists mostly nextcloud files and one file of a
different job.
I just restored some files from AI-Incremental-0525 and it looks fine so
far.

Now I'm creating a new full as you suggested using

> run job=my-nextcloud-job level=Full

Does Bareos ignore the previous backups after that or will it try to
consolidate them regardless of the existence of a new full?

Kind regards,

Philippe

[Sebastian Sura]

The joblog i was interested in was for job 41536, i.e. the job with the
'broken' volume.  Sorry for the confusion!

As far as I am aware, yes, the previous incrementals should not get
consolidated into the old full.  They should stay as they are.

Kind Regards
Sebastian Sura

Am 19.06.24 um 15:51 schrieb 'Philippe' via bareos-users:

[Philippe]

Ah, sorry. Sure, here's its joblog:

> 2024-05-29 12:21:43 director JobId 41536: Start Backup JobId 41536, Job=backup-client-nextcloud.2024-05-29_12.20.00_45
> 2024-05-29 12:21:43 director JobId 41536: Connected Storage daemon at storage:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
> 2024-05-29 12:21:43 director JobId 41536: Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
> 2024-05-29 12:21:43 director JobId 41536: Connected Client: client at 192.168.254.4:9102, encryption: TLS_AES_256_GCM_SHA384 TLSv1.3
> 2024-05-29 12:21:43 director JobId 41536: Handshake: Immediate TLS
> 2024-05-29 12:21:43 director JobId 41536: Encryption: TLS_AES_256_GCM_SHA384 TLSv1.3
> 2024-05-29 12:21:43 director JobId 41536: Sending Accurate information.
> 2024-05-29 12:22:05 director JobId 41536: Max configured use duration=82,800 sec. exceeded. Marking Volume "AI-Incremental-0540" as Used.
> 2024-05-29 12:22:05 director JobId 41536: There are no more Jobs associated with Volume "AI-Incremental-0525". Marking it purged.
> 2024-05-29 12:22:05 director JobId 41536: All records pruned from Volume "AI-Incremental-0525"; marking it "Purged"
> 2024-05-29 12:22:05 director JobId 41536: Recycled volume "AI-Incremental-0525"
> 2024-05-29 12:22:05 director JobId 41536: Using Device "File-storage" to write.
> 2024-05-29 12:22:07 client JobId 41536: Extended attribute support is enabled
> 2024-05-29 12:22:05 storage JobId 41536: Connected File Daemon at 192.168.254.4:9102, encryption: TLS_AES_256_GCM_SHA384 TLSv1.3
> 2024-05-29 12:22:07 client JobId 41536: ACL support is enabled
> 2024-05-29 12:22:07 storage JobId 41536: Labeled new Volume "AI-Incremental-0525" on device "File-storage" (/backup/bareos-tape).
> 2024-05-29 12:22:08 storage JobId 41536: Wrote label to prelabeled Volume "AI-Incremental-0525" on device "File-storage" (/backup/bareos-tape)
> 2024-05-29 12:22:32 client JobId 41536: Could not stat "/var/spool/backup/nextcloud.sql.gz": ERR=No such file or directory
> 2024-05-29 12:22:32 storage JobId 41536: Releasing device "File-storage" (/backup/bareos-tape).
> 2024-05-29 12:22:32 storage JobId 41536: Elapsed time=00:00:24, Transfer rate=698.5 K Bytes/second
> 2024-05-29 12:22:32 director JobId 41536: Insert of attributes batch table with 50 entries start
> 2024-05-29 12:22:32 director JobId 41536: Insert of attributes batch table done
> 2024-05-29 12:22:32 director JobId 41536: Bareos director 23.0.2 (28Feb24):
> Build OS: Red Hat Enterprise Linux release 9.3 (Plow)
> JobId: 41536
> Job: backup-client-nextcloud.2024-05-29_12.20.00_45
> Backup Level: Incremental, since=2024-05-28 12:22:04
> Client: "client" 23.0.2 (28Feb24) Oracle Linux Server release 8.9,redhat

> FileSet: "nextcloud" 2022-04-29 00:20:01

> Pool: "AI-Incremental" (From Job resource)

> Catalog: "MyCatalog" (From Client resource)

> Storage: "File-storage" (From Job resource)
> Scheduled time: 29-May-2024 12:20:00
> Start time: 29-May-2024 12:21:43
> End time: 29-May-2024 12:22:32
> Elapsed time: 49 secs
> Priority: 10
> Allow Mixed Priority: no
> FD Files Written: 50
> SD Files Written: 50
> FD Bytes Written: 16,757,674 (16.75 MB)
> SD Bytes Written: 16,765,064 (16.76 MB)
> Rate: 342.0 KB/s
> Software Compression: 67.5 % (lz4hc)
> VSS: no
> Encryption: no
> Accurate: yes
> Volume name(s): AI-Incremental-0525
> Volume Session Id: 48
> Volume Session Time: 1716977786
> Last Volume Bytes: 16,770,528 (16.77 MB)
> Non-fatal FD errors: 1
> SD Errors: 0
> FD termination status: OK
> SD termination status: OK

> Bareos binary info: Self-compiled: Get professional support from https://www.bareos.com

> Job triggered by: Scheduler
> Termination: Backup OK -- with warnings

Kind regards,

Philippe