Spurious 500/503 errors on `rclone serve restic b2:bucket`

pkel · August 30, 2025, 8:46am

What is the problem you are having with rclone?

When I run rclone serve restic backblaze-b2:bucket I regularly encounter “no tomes available (503 service_unavailable)” or similar errors on the host (running rclone). These errors surface as “500 Internal Server Error (500)” on the client (running restic).

To give you a feeling what “regularly” means, here are the last night's logs:

Logs on the host (running rclone)

2025-08-30T00:57:56+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client0/snapshots/2ba83f28d20ed32ba5b12ecd8d28596cb547264a5c94ae18c7b3f8d3ff4c86bc: Post request put error: no tomes available (503 service_unavailable)
2025-08-30T00:57:56+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client0/snapshots/2ba83f28d20ed32ba5b12ecd8d28596cb547264a5c94ae18c7b3f8d3ff4c86bc: Post request rcat error: no tomes available (503 service_unavailable)
2025-08-30T02:15:03+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client1/data/42/421d0233542e158409497a0bab9da7e0498a410b986b9493b264f46b6e05d86a: Post request put error: no tomes available (503 service_unavailable)
2025-08-30T02:15:03+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client1/data/42/421d0233542e158409497a0bab9da7e0498a410b986b9493b264f46b6e05d86a: Post request rcat error: no tomes available (503 service_unavailable)
2025-08-30T02:28:56+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client2/data/d4/d4d3f43c9149adbe79dbb8f0d7602be4a31a1a32ff43ecb2c5d2fea870226ed3: Post request put error: no tomes available (503 service_unavailable)
2025-08-30T02:28:56+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client2/data/d4/d4d3f43c9149adbe79dbb8f0d7602be4a31a1a32ff43ecb2c5d2fea870226ed3: Post request rcat error: no tomes available (503 service_unavailable)
2025-08-30T02:32:36+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client3/data/bb/bb3d9da2a3234ee852e0e6aff7cce63e3c3abb17e24a3f5f8ad43a91e8a38443: Post request put error: CPU too busy (503 service_unavailable)
2025-08-30T02:32:36+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client3/data/bb/bb3d9da2a3234ee852e0e6aff7cce63e3c3abb17e24a3f5f8ad43a91e8a38443: Post request rcat error: CPU too busy (503 service_unavailable)
2025-08-30T03:01:05+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/f3/f362b46770a9011a256c6594217008d36225075b1215715c75a7e155a06a478c: Post request put error: no tomes available (503 service_unavailable)
2025-08-30T03:01:05+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/f3/f362b46770a9011a256c6594217008d36225075b1215715c75a7e155a06a478c: Post request rcat error: no tomes available (503 service_unavailable)
2025-08-30T03:01:27+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/26/2623e853536ce98559a2bf9e8f80d0ed54548db6e0ecc638da222fbbef2c2a88: Post request put error: incident id 56861bac9343-8e0997d219e66776 (500 internal_error)
2025-08-30T03:01:27+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/26/2623e853536ce98559a2bf9e8f80d0ed54548db6e0ecc638da222fbbef2c2a88: Post request rcat error: incident id 56861bac9343-8e0997d219e66776 (500 internal_error)
2025-08-30T03:01:44+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/2f/2f99846394ec582a8b42c3c341cc2db3f2d389ba5b5fb4bd2d0c8fb39e81a43c: Post request put error: no tomes available (503 service_unavailable)
2025-08-30T03:01:44+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/2f/2f99846394ec582a8b42c3c341cc2db3f2d389ba5b5fb4bd2d0c8fb39e81a43c: Post request rcat error: no tomes available (503 service_unavailable)
2025-08-30T03:02:14+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/34/34cd821f4c62c4d98cc2c2172c24b482b3c8fe3b59932d70c8fda485cd3033f5: Post request put error: no tomes available (503 service_unavailable)
2025-08-30T03:02:14+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/34/34cd821f4c62c4d98cc2c2172c24b482b3c8fe3b59932d70c8fda485cd3033f5: Post request rcat error: no tomes available (503 service_unavailable)
2025-08-30T03:04:15+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/25/253fd032652645ca9066968d838b04d7acb07512c0c1f74d044b0dd705b12e33: Post request put error: no tomes available (503 service_unavailable)
2025-08-30T03:04:15+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/25/253fd032652645ca9066968d838b04d7acb07512c0c1f74d044b0dd705b12e33: Post request rcat error: no tomes available (503 service_unavailable)
2025-08-30T03:04:18+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/ca/cae43f748aa52d36c8313e8d992f0f6c0e48d329973752ba3dd7fa4c074d9b90: Post request put error: CPU too busy (503 service_unavailable)
2025-08-30T03:04:18+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/ca/cae43f748aa52d36c8313e8d992f0f6c0e48d329973752ba3dd7fa4c074d9b90: Post request rcat error: CPU too busy (503 service_unavailable)
2025-08-30T03:05:15+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/7c/7c9520385ac80ac0ee577e763babe4a4f7395d57269cd0fa014043ae3cb6b8f6: Post request put error: no tomes available (503 service_unavailable)
2025-08-30T03:05:15+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/7c/7c9520385ac80ac0ee577e763babe4a4f7395d57269cd0fa014043ae3cb6b8f6: Post request rcat error: no tomes available (503 service_unavailable)
2025-08-30T03:05:17+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/7c/7c9520385ac80ac0ee577e763babe4a4f7395d57269cd0fa014043ae3cb6b8f6: Post request put error: no tomes available (503 service_unavailable)
2025-08-30T03:05:17+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/7c/7c9520385ac80ac0ee577e763babe4a4f7395d57269cd0fa014043ae3cb6b8f6: Post request rcat error: no tomes available (503 service_unavailable)
2025-08-30T03:05:19+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/17/1731859bc124cab04bf27e90a5a5e035867f4bdec89d7e1daf537ebf5c1a1026: Post request put error: no tomes available (503 service_unavailable)
2025-08-30T03:05:19+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/17/1731859bc124cab04bf27e90a5a5e035867f4bdec89d7e1daf537ebf5c1a1026: Post request rcat error: no tomes available (503 service_unavailable)
2025-08-30T03:05:22+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/7c/7c9520385ac80ac0ee577e763babe4a4f7395d57269cd0fa014043ae3cb6b8f6: Post request put error: no tomes available (503 service_unavailable)
2025-08-30T03:05:22+02:00 rclone-host daemon.err rclone[6777]: ERROR : restic-client4/data/7c/7c9520385ac80ac0ee577e763babe4a4f7395d57269cd0fa014043ae3cb6b8f6: Post request rcat error: no tomes available (503 service_unavailable)

STDERR on client0 (running restic)

Save(<snapshot/2ba83f28d2>) returned error, retrying after 325.933913ms: server response unexpected: 500 Internal Server Error (500)
Save(<snapshot/2ba83f28d2>) operation successful after 1 retries

Backblaze describes at length that this is expected behavior on their side and that the client (rclone) should recover by repeating the request: Backblaze FAQ on 503 Errors

So these 'errors’ are not really errors and should not be reported as such. When I run rclone sync to the same bucket, I do not see such errors. My expectation would be that rclone serve restic recovers silently as well. Pushing this as HTTP 500 Internal Server error to the client seems wrong.

Run the command 'rclone version' and share the full output of the command.

rclone v1.69.1

os/version: nixos 25.05 (64 bit)
os/kernel: 6.12.43 (x86_64)
os/type: linux
os/arch: amd64
go/version: go1.24.5
go/linking: dynamic
go/tags: cmount

I’ve checked the Changelog; the last mention of restic is in 1.66.0. So this should be the ‘latest’ version of restic serve. I’m happy to try with 1.71.0 if you think otherwise.

Which cloud storage system are you using? (eg Google Drive)

Backblaze B2

The command you were trying to run (eg `rclone copy /tmp remote:tmp`)

rclone serve restic \
        --private-repos \
        --htpasswd /secrets/restic-htpasswd \
        --append-only \
        b2:backup-9arLoGfq/

The rclone config contents with secrets removed.

[b2]
type = b2
account = ***
key = ***

A log from the command with the `-vv` flag

Aug 30 09:49:46 rclone-host rclone[13821]: 2025/08/30 09:49:46 DEBUG : Setting --config "/secrets/rclone.conf" from environment variable RCLONE_CONFIG="/secrets/rclone.conf"
Aug 30 09:49:46 rclone-host rclone[13821]: DEBUG : rclone: Version "v1.69.1" starting with parameters ["/nix/store/vnfy6y0dfq3rmjx4syn6yp788j5rbwgp-rclone-1.69.1/bin/rclone" "serve" "restic" "--private-repos" "--htpasswd" "/secrets/restic-htpasswd" "--append-only" "-vv" "b2:backup-9arLoGfq/"]
Aug 30 09:49:46 rclone-host rclone[13821]: DEBUG : rclone: systemd logging support activated
Aug 30 09:49:46 rclone-host rclone[13821]: DEBUG : Creating backend with remote "b2:backup-9arLoGfq/"
Aug 30 09:49:46 rclone-host rclone[13821]: DEBUG : Using config file from "/secrets/rclone.conf"
Aug 30 09:49:46 rclone-host rclone[13821]: DEBUG : fs cache: renaming cache item "b2:backup-9arLoGfq/" to be canonical "b2:backup-9arLoGfq"
Aug 30 09:49:46 rclone-host rclone[13821]: INFO  : Using "/secrets/restic-htpasswd" as htpasswd storage
Aug 30 09:49:46 rclone-host rclone[13821]: NOTICE: B2 bucket backup-9arLoGfq: Serving restic REST API on [sd-listen:rclone-restic.socket-0/]
Aug 30 09:50:46 rclone-host rclone[13821]: INFO  :
Aug 30 09:50:46 rclone-host rclone[13821]: Transferred:                     0 B / 0 B, -, 0 B/s, ETA -
Aug 30 09:50:46 rclone-host rclone[13821]: Elapsed time:         0.0s

… the INFO repeats every minute. I’m waiting for B2 to trigger a 503 … there it is:

Aug 30 10:24:17 rclone-host rclone[13821]: DEBUG : restic-client4/keys: list request
Aug 30 10:24:19 rclone-host rclone[13821]: DEBUG : restic-client4/locks: list request
Aug 30 10:24:21 rclone-host rclone[13821]: DEBUG : restic-client4/locks: list request
Aug 30 10:24:21 rclone-host rclone[13821]: DEBUG : restic-client4/keys: list request
Aug 30 10:24:23 rclone-host rclone[13821]: DEBUG : restic-client4/locks: list request
Aug 30 10:24:24 rclone-host rclone[13821]: DEBUG : restic-client4/locks: list request
Aug 30 10:24:24 rclone-host rclone[13821]: DEBUG : restic-client4/snapshots: list request
Aug 30 10:24:24 rclone-host rclone[13821]: DEBUG : restic-client4/index: list request
Aug 30 10:24:44 rclone-host rclone[13821]: DEBUG : restic-client4/index/c79f1b689656ebf7496d131e6639d371f7feac2d31dcdd41acbd5d3d8b78d018: Clearing upload URL because of error: no tomes available (503 service_unavailable)
Aug 30 10:24:44 rclone-host rclone[13821]: DEBUG : pacer: low level retry 1/1 (error no tomes available (503 service_unavailable))
Aug 30 10:24:44 rclone-host rclone[13821]: DEBUG : pacer: Rate limited, increasing sleep to 1s
Aug 30 10:24:44 rclone-host rclone[13821]: ERROR : restic-client4/index/c79f1b689656ebf7496d131e6639d371f7feac2d31dcdd41acbd5d3d8b78d018: Post request put error: no tomes available (503 service_unavailable)
Aug 30 10:24:44 rclone-host rclone[13821]: ERROR : restic-client4/index/c79f1b689656ebf7496d131e6639d371f7feac2d31dcdd41acbd5d3d8b78d018: Post request rcat error: no tomes available (503 service_unavailable)
Aug 30 10:24:46 rclone-host rclone[13821]: DEBUG : pacer: Reducing sleep to 500ms
Aug 30 10:24:46 rclone-host rclone[13821]: INFO  :
Aug 30 10:24:46 rclone-host rclone[13821]: Transferred:              41.821 MiB / 41.825 MiB, 100%, 116 B/s, ETA 37s
Aug 30 10:24:46 rclone-host rclone[13821]: Errors:                 2 (retrying may help)
Aug 30 10:24:46 rclone-host rclone[13821]: Transferred:           27 / 28, 96%
Aug 30 10:24:46 rclone-host rclone[13821]: Elapsed time:     33m59.9s
Aug 30 10:24:46 rclone-host rclone[13821]: Transferring:
Aug 30 10:24:46 rclone-host rclone[13821]:  * restic-client4/index/c79f1b6896…dcdd41acbd5d3d8b78d018:  0% /4.332Ki, 0/s, -
Aug 30 10:24:49 rclone-host rclone[13821]: DEBUG : pacer: Reducing sleep to 250ms
Aug 30 10:24:49 rclone-host rclone[13821]: DEBUG : pacer: Reducing sleep to 125ms
Aug 30 10:24:50 rclone-host rclone[13821]: DEBUG : pacer: Reducing sleep to 62.5ms
Aug 30 10:24:50 rclone-host rclone[13821]: DEBUG : pacer: Reducing sleep to 31.25ms

Thanks for looking into this. Let me know if you need more info.

ncw · August 30, 2025, 12:03pm

The reason rclone sync works is that these errors get picked up in the outer --retries loop, but rclone serve restic doesn't have that retry loop.

There is a good reason for that - we stream the requests straight from the http server to b2 and don't store them in memory. To do a retry we would have to read the request into memory.

My understanding of restic (I use it for my backups, also to b2) is that it is quite happy to retry the 500 error and so the backup should complete properly.

Is that what you are seeing?

pkel · August 30, 2025, 3:50pm

This makes a lot of sense.

Restic is happy. It seems to back off with a random component and recovers silently. Consider the restic-client side logs for the above rclone serve side logs. This is all stdout, stderr is empty. (I got this wrong in my first message, in the label of the second collapsible section)

Summary

Aug 30 10:24:24 restic-client4 restic[2779]: using parent snapshot e903eae5
Aug 30 10:24:44 restic-client4 restic[2779]: Save(<index/c79f1b6896>) returned error, retrying after 1.403795614s: unexpected HTTP res>
Aug 30 10:24:49 restic-client4 restic[2779]: Save(<index/c79f1b6896>) operation successful after 1 retries
Aug 30 10:24:50 restic-client4 restic[2779]: Files:          52 new,    14 changed, 150031 unmodified
Aug 30 10:24:50 restic-client4 restic[2779]: Dirs:            0 new,    27 changed, 13262 unmodified
Aug 30 10:24:50 restic-client4 restic[2779]: Added to the repository: 50.470 MiB (41.784 MiB stored)
Aug 30 10:24:50 restic-client4 restic[2779]: processed 150097 files, 515.015 GiB in 0:27
Aug 30 10:24:50 restic-client4 restic[2779]: snapshot 4eb1c416 saved

The setup works as intended, but I worry about the error messages on the rclone side. Stderr should IMO remain empty as long as things work as expected.

ncw · August 31, 2025, 11:32am

I wonder if rclone returned a 503 error if restic would be happier. That's them nearest http has to try again. 429 would be another alternative.

If we could find a code restic retries but doesn't log an error that would be sufficient.

pkel · September 3, 2025, 7:58am

To clarify: my problem is that the rclone serve restic daemon spams my error logs while all the restic backup jobs succeed.

ncw · September 3, 2025, 11:09am

Ah, so it is the rclone logs that are bothering you.

Unfortunately not being able to upload the file is an ERROR which isn't easy to mask as the upper levels of rclone can't tell that sort of failure from any other sort of failure.

There is a unique identifier in the logs though so you could grep them out looking for "ERROR.*no tomes available". Not very elegant I know!

grep -v "ERROR.*no tomes available" < rclone.log > cleaned-rclone.log

pkel · September 3, 2025, 11:58am

Yeah, I'm already doing this. But as you said, it is not exactly elegant.

I get these errors during normal operation:

Unknown 401 (401 expired_auth_token)
CPU too busy (503 service_unavailable)
no tomes available (503 service_unavailable)

Based on this design decision, wouldn't it make sense to just pass through the error to the restic client, without logging the error on the rclone side? Or at least downgrade to the message to INFO level on the rclone side?

My mental model is:

ERROR level messages trigger my attention and action to resolve
INFO level messages are under my radar during normal operations, they assist setup and debugging

Is this unreasonable for rclone? In that case I will just downgrade all rclone ERROR level messages to INFO.

If this is reasonable for rclone, I think downgrading these errors to info on the rclone side would be fine: The restic clients will do their retries and recover from the temporary failure. Only if recovery fails, restic returns and logs an error. At that point, one can correlate the restic error with the rclone INFO level messages for debugging.

ncw · September 3, 2025, 1:32pm

I think that is a reasonable suggestion. If we are reporting errors to the client then we don't need to log them as anything other than debug really.

This is the culprit log line

github.com/rclone/rclone

cmd/serve/restic/restic.go

99e8a63df


      
          			fs.Errorf(remote, "Post request: file already exists, refusing to overwrite in append-only mode")
          			http.Error(w, http.StatusText(http.StatusForbidden), http.StatusForbidden)
          
          			return
          		}
          	}
          
          	o, err := operations.RcatSize(r.Context(), s.f, remote, r.Body, r.ContentLength, time.Now(), nil)
          	if err != nil {
          		err = accounting.Stats(r.Context()).Error(err)
          		fs.Errorf(remote, "Post request rcat error: %v", err)
          		http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError)
          
          		return
          	}
          
          	// if successfully uploaded add to cache
          	s.cache.add(remote, o)
          }
          
          // delete the remote

I guess whether we error them or debug them could be an option.