Rclone / OneDrive integration is unstable with rclone v1.66. Consider updating.

[Daninet]

Hi devs! First of all, thank you for this awesome project!

I've ran into an issue with the latest Backrest v1.6.1 docker image. It has rclone v1.66.0 installed that has a randomly occurring bug in restic <-> rclone communication.

The error message looks like this:

command: /bin/restic-0.17.1 check -o sftp.args=-oBatchMode=yes
using temporary cache in /tmp/restic-check-cache-3523010399
create exclusive lock for repository
Load(<key/924efb6bc1>, 0, 0) failed: <key/924efb6bc1> does not exist
Load(<key/924efb6bc1>, 0, 0) failed: <key/924efb6bc1> does not exist
Fatal: <key/924efb6bc1> does not exist

The "924efb6bc1" file is there, just there is a communication error between restic and rclone.

It seems that the bug was fixed in rclone v1.67.0. Updating the rclone version in docker image fixes the issue on my computer.
Please consider updating the docker image.

Thank you!

[Daninet]

If anybody interested, here is the relevant part from restic debug log:

2024/11/17 20:45:46 rest/rest.go:398    rest.(*Backend).listv2  1       parsing API v2 response
2024/11/17 20:45:46 repository/key.go:145       repository.SearchKey.func1      1       trying key "924efb6bc1fb5cdce82fdb99ed549786c616addc3f608a070ce308a8495349ff"
2024/11/17 20:45:46 logger/log.go:45    logger.(*Backend).Load  1       Load(<key/924efb6bc1>, length 0, offset 0)
2024/11/17 20:45:46 sema/semaphore.go:27        sema.semaphore.GetToken 1       acquired token
2024/11/17 20:45:46 debug/round_tripper.go:93   debug.loggingRoundTripper.RoundTrip     1       ------------  HTTP REQUEST -----------
GET /keys/924efb6bc1fb5cdce82fdb99ed549786c616addc3f608a070ce308a8495349ff HTTP/1.1
Host: localhost
User-Agent: Go-http-client/1.1
Accept: application/vnd.x.restic.rest.v2
Range: bytes=0-


2024/11/17 20:45:47 debug/round_tripper.go:110  debug.loggingRoundTripper.RoundTrip     1       ------------  HTTP RESPONSE ----------
HTTP/2.0 404 Not Found
Content-Length: 454
Accept-Ranges: bytes
Content-Range: bytes 0-453/454
Content-Type: text/plain; charset=utf-8
Date: Sun, 17 Nov 2024 18:45:47 GMT
Last-Modified: Sun, 17 Nov 2024 12:44:43 GMT
Server: rclone/v1.66.0-DEV
X-Content-Type-Options: nosniff


2024/11/17 20:45:47 debug/round_tripper.go:46   debug.(*eofDetectReader).Close  1       body not drained, 0 bytes not read, error: unexpected EOF: Close()
github.com/restic/restic/internal/debug.(*eofDetectReader).Close
        /restic/internal/debug/round_tripper.go:46
github.com/restic/restic/internal/backend/rest.drainAndClose
        /restic/internal/backend/rest/rest.go:78
github.com/restic/restic/internal/backend/rest.(*Backend).openReader
        /restic/internal/backend/rest/rest.go:246
github.com/restic/restic/internal/backend/rest.(*Backend).Load
        /restic/internal/backend/rest/rest.go:199
github.com/restic/restic/internal/backend/sema.(*connectionLimitedBackend).Load
        /restic/internal/backend/sema/backend.go:95
github.com/restic/restic/internal/backend/logger.(*Backend).Load
        /restic/internal/backend/logger/log.go:46
github.com/restic/restic/internal/backend/retry.(*Backend).Load.func1
        /restic/internal/backend/retry/backend_retry.go:209
github.com/restic/restic/internal/backend/retry.(*Backend).retry.func1
        /restic/internal/backend/retry/backend_retry.go:132
github.com/restic/restic/internal/backend/retry.retryNotifyErrorWithSuccess.func1
        /restic/internal/backend/retry/backend_retry.go:53
github.com/cenkalti/backoff/v4.RetryNotifyWithTimer.Operation.withEmptyData.func1
        /home/build/go/pkg/mod/github.com/cenkalti/backoff/[email protected]/retry.go:18
github.com/cenkalti/backoff/v4.doRetryNotify[...]
        /home/build/go/pkg/mod/github.com/cenkalti/backoff/[email protected]/retry.go:88
github.com/cenkalti/backoff/v4.RetryNotifyWithTimer
        /home/build/go/pkg/mod/github.com/cenkalti/backoff/[email protected]/retry.go:61
github.com/cenkalti/backoff/v4.RetryNotify
        /home/build/go/pkg/mod/github.com/cenkalti/backoff/[email protected]/retry.go:49
github.com/restic/restic/internal/backend/retry.retryNotifyErrorWithSuccess
        /restic/internal/backend/retry/backend_retry.go:62
github.com/restic/restic/internal/backend/retry.(*Backend).retry
        /restic/internal/backend/retry/backend_retry.go:130
github.com/restic/restic/internal/backend/retry.(*Backend).Load
        /restic/internal/backend/retry/backend_retry.go:207
github.com/restic/restic/internal/repository.loadRaw
        /restic/internal/repository/raw.go:46
github.com/restic/restic/internal/repository.(*Repository).LoadRaw
        /restic/internal/repository/raw.go:19
github.com/restic/restic/internal/repository.LoadKey
        /restic/internal/repository/key.go:181
github.com/restic/restic/internal/repository.OpenKey
        /restic/internal/repository/key.go:66
github.com/restic/restic/internal/repository.SearchKey.func1
        /restic/internal/repository/key.go:146
github.com/restic/restic/internal/repository.SearchKey.(*Repository).List.func2
        /restic/internal/repository/repository.go:827
github.com/restic/restic/internal/backend/retry.(*Backend).List.func1.1
        /restic/internal/backend/retry/backend_retry.go:265
github.com/restic/restic/internal/backend/rest.(*Backend).listv2
        /restic/internal/backend/rest/rest.go:419
github.com/restic/restic/internal/backend/rest.(*Backend).List
        /restic/internal/backend/rest/rest.go:349
github.com/restic/restic/internal/backend/logger.(*Backend).List
        /restic/internal/backend/logger/log.go:60
github.com/restic/restic/internal/backend/retry.(*Backend).List.func1
        /restic/internal/backend/retry/backend_retry.go:259
github.com/restic/restic/internal/backend/retry.(*Backend).retry.func1
        /restic/internal/backend/retry/backend_retry.go:132
github.com/restic/restic/internal/backend/retry.retryNotifyErrorWithSuccess.func1
        /restic/internal/backend/retry/backend_retry.go:53
github.com/cenkalti/backoff/v4.RetryNotifyWithTimer.Operation.withEmptyData.func1
        /home/build/go/pkg/mod/github.com/cenkalti/backoff/[email protected]/retry.go:18
github.com/cenkalti/backoff/v4.doRetryNotify[...]
        /home/build/go/pkg/mod/github.com/cenkalti/backoff/[email protected]/retry.go:88
github.com/cenkalti/backoff/v4.RetryNotifyWithTimer
        /home/build/go/pkg/mod/github.com/cenkalti/backoff/[email protected]/retry.go:61
2024/11/17 20:45:47 logger/log.go:47    logger.(*Backend).Load  1         load err <key/924efb6bc1> does not exist
2024/11/17 20:45:47 restic/global.go:254        main.Warnf      1       Load(<key/924efb6bc1>, 0, 0) failed: <key/924efb6bc1> does not exist
2024/11/17 20:45:47 logger/log.go:45    logger.(*Backend).Load  1       Load(<key/924efb6bc1>, length 0, offset 0)
        

[garethgeorge]

Thanks for reporting this, I think we'll get a version bump to at least 1.68.2-r0
next time I publish a patch release https://pkgs.alpinelinux.org/package/edge/community/x86_64/rclone .

I'm expecting to run a patch release sometime either this week or early next, once I get a few more PRs in.