Restic Prune issue?

killmasta93 · September 27, 2020, 12:37am

Hi,
Currently getting an issue to prune

I ran the check to see and this is what i get ( had to cut alot of pack 35f11a2f: not referenced in any index)

1387 additional files were found in the repo, which likely contain duplicate data.
You can run `restic prune` to correct this.
check snapshots, trees and blobs
no errors were found

This is the error when prunning

counting files in repo
building new index for repo
[12:03] 100.00%  41107 / 41107 packs

repository contains 41107 packs (518611 blobs) with 192.556 GiB
processed 518611 blobs: 23264 duplicate blobs, 6.349 GiB duplicate
load all snapshots
find data that is still in use for 90 snapshots
[7:50] 100.00%  90 / 90 snapshots

found 474050 of 518611 data blobs still in use, removing 44561 blobs
will remove 0 invalid files
will delete 842 packs and rewrite 3429 packs, this frees 13.495 GiB
hash does not match id: want 28802ae5cf4bea45a0acdda16d399eb6a429299b51835a203c151d63fb910734, got bb42da9ed12c3e2e3b54ae73de5322401209f8adceda5255d59d3f620ac25226
github.com/restic/restic/internal/repository.Repack
        /restic/internal/repository/repack.go:34
main.pruneRepository
        /restic/cmd/restic/cmd_prune.go:278
main.runPrune
        /restic/cmd/restic/cmd_prune.go:85
main.glob..func18
        /restic/cmd/restic/cmd_prune.go:25
github.com/spf13/cobra.(*Command).execute
        /restic/vendor/github.com/spf13/cobra/command.go:762
github.com/spf13/cobra.(*Command).ExecuteC
        /restic/vendor/github.com/spf13/cobra/command.go:852
github.com/spf13/cobra.(*Command).Execute
        /restic/vendor/github.com/spf13/cobra/command.go:800
main.main
        /restic/cmd/restic/main.go:86
runtime.main
        /usr/local/go/src/runtime/proc.go:200
runtime.goexit
        /usr/local/go/src/runtime/asm_amd64.s:1337

WARNING!
[prune] failed; exit code 1

Then checked it with the sha256sum

root@mail:~# sha256sum /media/backupnas/data/28/28802ae5cf4bea45a0acdda16d399eb6a429299b51835a203c151d63fb910734
bb42da9ed12c3e2e3b54ae73de5322401209f8adceda5255d59d3f620ac25226  /media/backupnas/data/28/28802ae5cf4bea45a0acdda16d399eb6a429299b51835a203c151d63fb910734

So my question is how could i fix this?
Thank you

gurkan · September 27, 2020, 5:25pm

Ouch, looks like corruption on the data file.

Anyway you can check which snapshots are using this broken file by:

restic find --pack 28802ae5cf4bea45a0acdda16d399eb6a429299b51835a203c151d63fb910734

And forget all relevant snapshots (if this is acceptable), and then prune.

You might want to run a memtest or FS health check also, considering this looks very fishy.

Or someone else can recommend something better, maybe recover command somehow skips checking hashes etc…

killmasta93 · September 29, 2020, 1:45am

Thanks for the reply,
so i retried to prune again and got this error

root@mail:/media# restic -r /media/backupnas/ prune --cleanup-cache
enter password for repository:
repository 06411559 opened successfully, password is correct
counting files in repo
building new index for repo
[13:55] 100.00%  42506 / 42506 packs
incomplete pack file (will be removed): a2255c10b326151d8707afbd04edc173675b05077731fddcae9676bcf02d5209
repository contains 42505 packs (541255 blobs) with 198.973 GiB
processed 541255 blobs: 45908 duplicate blobs, 12.765 GiB duplicate
load all snapshots
find data that is still in use for 30 snapshots
[2:31] 100.00%  30 / 30 snapshots
found 262135 of 541255 data blobs still in use, removing 279120 blobs
will remove 1 invalid files
will delete 12404 packs and rewrite 8880 packs, this frees 91.062 GiB
Save(<data/4318bdb8df>) returned error, retrying after 552.330144ms: Sync: sync /media/backupnas/data/43/4318bdb8df4fce606d767c41f4f3e19560916e939aff19b776fc10beb1b8603f: input/output error
Save(<data/4318bdb8df>) returned error, retrying after 1.080381816s: OpenFile: open /media/backupnas/data/43/4318bdb8df4fce606d767c41f4f3e19560916e939aff19b776fc10beb1b8603f: file exists
Save(<data/4318bdb8df>) returned error, retrying after 1.31013006s: OpenFile: open /media/backupnas/data/43/4318bdb8df4fce606d767c41f4f3e19560916e939aff19b776fc10beb1b8603f: file exists
Save(<data/4318bdb8df>) returned error, retrying after 1.582392691s: OpenFile: open /media/backupnas/data/43/4318bdb8df4fce606d767c41f4f3e19560916e939aff19b776fc10beb1b8603f: file exists
Save(<data/4318bdb8df>) returned error, retrying after 2.340488664s: OpenFile: open /media/backupnas/data/43/4318bdb8df4fce606d767c41f4f3e19560916e939aff19b776fc10beb1b8603f: file exists
Save(<data/4318bdb8df>) returned error, retrying after 4.506218855s: OpenFile: open /media/backupnas/data/43/4318bdb8df4fce606d767c41f4f3e19560916e939aff19b776fc10beb1b8603f: file exists
Save(<data/4318bdb8df>) returned error, retrying after 3.221479586s: OpenFile: open /media/backupnas/data/43/4318bdb8df4fce606d767c41f4f3e19560916e939aff19b776fc10beb1b8603f: file exists
Save(<data/4318bdb8df>) returned error, retrying after 5.608623477s: OpenFile: open /media/backupnas/data/43/4318bdb8df4fce606d767c41f4f3e19560916e939aff19b776fc10beb1b8603f: file exists
Save(<data/4318bdb8df>) returned error, retrying after 7.649837917s: OpenFile: open /media/backupnas/data/43/4318bdb8df4fce606d767c41f4f3e19560916e939aff19b776fc10beb1b8603f: file exists
Save(<data/4318bdb8df>) returned error, retrying after 15.394871241s: OpenFile: open /media/backupnas/data/43/4318bdb8df4fce606d767c41f4f3e19560916e939aff19b776fc10beb1b8603f: file exists
[3:46] 3.89%  345 / 8880 packs rewritten
open /media/backupnas/data/43/4318bdb8df4fce606d767c41f4f3e19560916e939aff19b776fc10beb1b8603f: file exists
OpenFile
github.com/restic/restic/internal/backend/local.(*Local).Save
        /restic/internal/backend/local/local.go:108
github.com/restic/restic/internal/limiter.rateLimitedBackend.Save
        /restic/internal/limiter/limiter_backend.go:30
github.com/restic/restic/internal/backend.(*RetryBackend).Save.func1
        /restic/internal/backend/backend_retry.go:56
github.com/cenkalti/backoff.RetryNotify
        /home/build/go/pkg/mod/github.com/cenkalti/backoff@v2.2.1+incompatible/retry.go:37
github.com/restic/restic/internal/backend.(*RetryBackend).retry
        /restic/internal/backend/backend_retry.go:36
github.com/restic/restic/internal/backend.(*RetryBackend).Save
        /restic/internal/backend/backend_retry.go:50
github.com/restic/restic/internal/cache.(*Backend).Save
        /restic/internal/cache/backend.go:54
github.com/restic/restic/internal/repository.(*Repository).savePacker
        /restic/internal/repository/packer_manager.go:107
github.com/restic/restic/internal/repository.(*Repository).SaveAndEncrypt
        /restic/internal/repository/repository.go:281
github.com/restic/restic/internal/repository.(*Repository).SaveBlob
        /restic/internal/repository/repository.go:720
github.com/restic/restic/internal/repository.Repack
        /restic/internal/repository/repack.go:90
main.pruneRepository
        /restic/cmd/restic/cmd_prune.go:242
main.runPrune
        /restic/cmd/restic/cmd_prune.go:62
main.glob..func19
        /restic/cmd/restic/cmd_prune.go:27
github.com/spf13/cobra.(*Command).execute
        /home/build/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:842
github.com/spf13/cobra.(*Command).ExecuteC
        /home/build/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:950
github.com/spf13/cobra.(*Command).Execute
        /home/build/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:887
main.main
        /restic/cmd/restic/main.go:86
runtime.main
        /usr/local/go/src/runtime/proc.go:204
runtime.goexit
        /usr/local/go/src/runtime/asm_amd64.s:1374

gurkan · September 29, 2020, 7:26am

IO error, needless to say, could you move this file out manually?

4318bdb8df4fce606d767c41f4f3e19560916e939aff19b776fc10beb1b8603f

Any just for curiosity, does the hash match for this one?

MichaelEischer · September 30, 2020, 8:44am

The Save operation tries to delete the old file if the operation failed. As later retries complain that the file already exists, it seems like deleting the failed also failed for some reason.

killmasta93 · October 1, 2020, 2:13pm

Thanks for the reply, it seems it might be a NAS issue as i have 2 failing disks going to swap them out to see if thats the issue thank you

killmasta93 · October 2, 2020, 12:52am

so i thought it might be the NAS i tried another NAS storage got this error started a new repo

Hostname: mail
Repository Location: /media/backupnas/bakemail
Restic Version: 0.10.0
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
[Taking a Snapshot...]
open repository
created new cache in /root/.cache/restic
lock repository
load index files
start scan on [/home]
start backup on [/home]
scan finished in 129.932s: 128815 files, 109.009 GiB
Save(<data/a0a71d235c>) returned error, retrying after 552.330144ms: Sync: sync /media/backupnas/bakemail/data/a0/a0a71d235c75c7b10e6b938474d8ee816a70706eae2279dd7de9f69e6ffd7c1c: input/output error
Save(<data/a0a71d235c>) returned error, retrying after 1.080381816s: OpenFile: open /media/backupnas/bakemail/data/a0/a0a71d235c75c7b10e6b938474d8ee816a70706eae2279dd7de9f69e6ffd7c1c: file exists
Save(<data/a0a71d235c>) returned error, retrying after 1.31013006s: OpenFile: open /media/backupnas/bakemail/data/a0/a0a71d235c75c7b10e6b938474d8ee816a70706eae2279dd7de9f69e6ffd7c1c: file exists
Save(<data/a0a71d235c>) returned error, retrying after 1.582392691s: OpenFile: open /media/backupnas/bakemail/data/a0/a0a71d235c75c7b10e6b938474d8ee816a70706eae2279dd7de9f69e6ffd7c1c: file exists
Save(<data/a0a71d235c>) returned error, retrying after 2.340488664s: OpenFile: open /media/backupnas/bakemail/data/a0/a0a71d235c75c7b10e6b938474d8ee816a70706eae2279dd7de9f69e6ffd7c1c: file exists
Save(<data/a0a71d235c>) returned error, retrying after 4.506218855s: OpenFile: open /media/backupnas/bakemail/data/a0/a0a71d235c75c7b10e6b938474d8ee816a70706eae2279dd7de9f69e6ffd7c1c: file exists
Save(<data/a0a71d235c>) returned error, retrying after 3.221479586s: OpenFile: open /media/backupnas/bakemail/data/a0/a0a71d235c75c7b10e6b938474d8ee816a70706eae2279dd7de9f69e6ffd7c1c: file exists
Save(<data/a0a71d235c>) returned error, retrying after 5.608623477s: OpenFile: open /media/backupnas/bakemail/data/a0/a0a71d235c75c7b10e6b938474d8ee816a70706eae2279dd7de9f69e6ffd7c1c: file exists
Save(<data/a0a71d235c>) returned error, retrying after 7.649837917s: OpenFile: open /media/backupnas/bakemail/data/a0/a0a71d235c75c7b10e6b938474d8ee816a70706eae2279dd7de9f69e6ffd7c1c: file exists
Save(<data/a0a71d235c>) returned error, retrying after 15.394871241s: OpenFile: open /media/backupnas/bakemail/data/a0/a0a71d235c75c7b10e6b938474d8ee816a70706eae2279dd7de9f69e6ffd7c1c: file exists
Fatal: unable to save snapshot: OpenFile: open /media/backupnas/bakemail/data/a0/a0a71d235c75c7b10e6b938474d8ee816a70706eae2279dd7de9f69e6ffd7c1c: file exists

WARNING!
[backup] failed; exit code 1
[rescript] can't send emails; install [mailutils] package to do so.
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
End: Thu Oct 01 2020 07:05:10 PM
Duration: 18 minutes and 12 seconds

MichaelEischer · October 3, 2020, 12:59pm

Can you access the problematic file? Is it possible to delete it? The input/output error seems to indicate some problem on the target filesystem, as saving data file apparently works fine for the first few minutes.

killmasta93 · October 3, 2020, 5:54pm

Thanks for the reply, what i did so far is create another repo and downgraded to 0.9.5 not sure if its because im running ubuntu 14 which is old (i know i need to update which has postfix but moving to zimbra next month to ubuntu 18)

root@mail:~# rescript mail
=============================================================================================================================================================================================================================================
                                                                                                               STARTING SCRIPT
=============================================================================================================================================================================================================================================
Date and Time: Thu Oct 01 2020 08:03:23 PM
System: Ubuntu 14.04.4 LTS
Hostname: mail
Repository Location: /media/backupnas/bakhermes
Restic Version: 0.9.5
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
[Taking a Snapshot...]
open repository
lock repository
load index files
start scan on [/home]
start backup on [/home]
scan finished in 20.702s: 128905 files, 109.053 GiB
uploaded intermediate index 751a9d5c
uploaded intermediate index f052ff7e
uploaded intermediate index 102ebcfc
uploaded intermediate index 859cb0b1
uploaded intermediate index 6d75b9e5
uploaded intermediate index 954272b3
uploaded intermediate index f495d22e
uploaded intermediate index eaf6a2c9
uploaded intermediate index f9288fec
uploaded intermediate index 62c269cb
uploaded intermediate index b6fa87db
uploaded intermediate index 410042ab
uploaded intermediate index 6fa1a99d
uploaded intermediate index c409d0d5
uploaded intermediate index 2e71cd7c
uploaded intermediate index ff429c94
uploaded intermediate index 784e66f9
uploaded intermediate index 593a8812
uploaded intermediate index 38310ade
uploaded intermediate index ab94eb48
uploaded intermediate index 9c734610
uploaded intermediate index 5e659052
uploaded intermediate index 6a9a6f46
uploaded intermediate index f44315dd
uploaded intermediate index 7eea0e0c
uploaded intermediate index 105d8555
uploaded intermediate index d07743a7
uploaded intermediate index 91acb986
uploaded intermediate index 8a8d3fab
uploaded intermediate index e27df00e
uploaded intermediate index ed33c60e
uploaded intermediate index 3d6cdc77
uploaded intermediate index cb3f698b
uploaded intermediate index fdf27b9c
uploaded intermediate index 673ec1a1
uploaded intermediate index 84279057
uploaded intermediate index baa13574
uploaded intermediate index 5c3a6424
uploaded intermediate index 3d655b0e
uploaded intermediate index 29fbc71c
uploaded intermediate index b223bb52
uploaded intermediate index d37bbab0
uploaded intermediate index b7eb595e
uploaded intermediate index add5e5ca
uploaded intermediate index bab81b5c
uploaded intermediate index 73904494
uploaded intermediate index c4b16bf0
uploaded intermediate index 3cdbf902
uploaded intermediate index 34e6ad89
uploaded intermediate index 5e68ac0a
uploaded intermediate index 47417dc1
uploaded intermediate index 1e38af52
uploaded intermediate index 947d3075
uploaded intermediate index 86f88a60
uploaded intermediate index 195e5f8e
uploaded intermediate index d95aae68
uploaded intermediate index 494c285a
uploaded intermediate index f0c33c2f
uploaded intermediate index 0a6eec08
uploaded intermediate index 6c6f7231
uploaded intermediate index e7447bdd
uploaded intermediate index 744bbed8
uploaded intermediate index 263055df
uploaded intermediate index 72b4cf18
uploaded intermediate index 9aa46603
uploaded intermediate index 46f29c00
uploaded intermediate index a8216b5a
uploaded intermediate index 348f42b5
uploaded intermediate index 287fb6e3
uploaded intermediate index 9303d27e

Files:       128979 new,     0 changed,     0 unmodified
Dirs:            0 new,     0 changed,     0 unmodified
Data Blobs:  170242 new
Tree Blobs:      1 new
Added to the repo: 86.618 GiB

processed 128979 files, 109.062 GiB in 4:12:10
snapshot 53e4fc77 saved

MichaelEischer · October 3, 2020, 8:19pm

Could you try to set the environment variable GODEBUG to asyncpreemptoff=1? You’re using CIFS to mount `/media/backupnas’?

killmasta93 · October 6, 2020, 4:05am

Thanks for the reply, correct its using CIFS as for the GODEBUG to asyncpreemptoff=1
not sure what you mean?
the GOROOT path for me

export GOROOT=/usr/local/go
     export PATH=$GOPATH/bin:$GOROOT/bin:$PATH

Thank you

MichaelEischer · October 6, 2020, 1:04pm

I had setting export GODEBUG="asyncpreemptoff=1" in mind.

killmasta93 · October 15, 2020, 2:25pm

sorry for the late reply, seems that it was a server issue, i updated to ubuntu 18 and all seems to be working again