Backup to B2 has tons of rclone rcat and rclone put errors and it never finishes

[RobTheBuilder2]

Creating a discussion because I'm not quite sure this is a bug in rustic, but need some direction on how to narrow this down. I'm running a backup of several ZFS datasets to Backblaze B2. I have backed up a smaller ~17G dataset without any issues. I am now trying to back up a 1.08T dataset and running into some issues.

Setup:

• Ubuntu 22.04
• rustic v0.5.3
• rclone v1.62.2

I have created separate buckets in b2 for each of my ZFS datasets. Figured this would allow for easier management and more flexible restore options in the future. I have a script that runs each backup synchronously, so there is only one backup happening with rustic at a time. I wanted to prevent issues with the files changing mid backup so I decided to use the ZFS snapshot as the source for my backup. My script queries ZFS to get the read-only mountpoint for the latest daily ZFS snapshot. I then call rustic with the --ignore-devid and I set the --as-path to reflect the actual dataset path, not the snapshot path. This allows rustic to properly recognize the parent of subsequent backups even though the snapshot path is different every time a backup runs.

For my smaller ~17G dataset, the backup is successful and subsequent backups correctly identify changed files, etc. However, when running a backup of my ~1.08T dataset, it runs smooth for a few days and then starts spitting out a ton of rclone errors. Now, my backup has been running for 14 days and my current B2 bucket size is actually larger than the source dataset being backed up (the bucket was empty at the beginning of this backup run). My bucket size is now ~1.15T while the data to be backed up from the source is only ~1.08T as mentioned before. Even though it seems there is a more data in the bucket than in the source at this point, the backup is still running and the errors are still being thrown.

The following are the configuration and run time details for my backup run (x's replacing sensitive information):
Command Line:
rustic backup --use-profile XXX --ignore-devid --as-path /naspool/XX /naspool/XX/.zfs/snapshot/autosnap_2023-06-01_00:00:04_daily

Rustic Profile toml:

[global]
log-level = "info"
no-progress = true

[repository]
repository = "rclone:Backblaze:XXXXX"  <-XXXXX = BUCKET NAME
password-file = "XXXXXXX"
no-cache = true

[forget]
keep-daily = 8
keep-weekly = 5
keep-monthly = 13
keep-yearly = 10

[backup]
exclude-if-present = [".nobackup", "CACHEDIR.TAG"]

rclone configuration:

[Backblaze]
type = b2
account = XXXXXXXXXXXXXXXXXXXXX
key = XXXXXXXXXXXXXXXXXXXXX
hard_delete = true

Errors found in logs. This is just a few lines. I can provide more if necessary:

[INFO] rclone output: <3>ERROR : data/fd/fd0564df471ff3802e4e3e42b2df4bc7b928ceb9cc927caff1194e331d2f25c3: Post request put error: Post "https://pod-050-1001-01.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501001_t0045": context canceled



[INFO] rclone output: <3>ERROR : data/fd/fd0564df471ff3802e4e3e42b2df4bc7b928ceb9cc927caff1194e331d2f25c3: Post request rcat error: Post "https://pod-050-1001-01.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501001_t0045": context canceled



[WARN] Error error sending request for url (http://127.0.0.1:44079/data/fd0564df471ff3802e4e3e42b2df4bc7b928ceb9cc927caff1194e331d2f25c3): operation timed out at 3.305898633s, retrying

[INFO] rclone output: <3>ERROR : data/fd/fd0564df471ff3802e4e3e42b2df4bc7b928ceb9cc927caff1194e331d2f25c3: Post request put error: Post "https://pod-050-1005-01.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501005_t0027": context canceled



[INFO] rclone output: <3>ERROR : data/fd/fd0564df471ff3802e4e3e42b2df4bc7b928ceb9cc927caff1194e331d2f25c3: Post request rcat error: Post "https://pod-050-1005-01.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501005_t0027": context canceled



[WARN] Error error sending request for url (http://127.0.0.1:44079/data/1d9c19c83688d4446ae7678d95086da765a6fd7e2a0c3c643aa2e391f542b74b): operation timed out at 654.849972ms, retrying

[INFO] rclone output: <3>ERROR : data/1d/1d9c19c83688d4446ae7678d95086da765a6fd7e2a0c3c643aa2e391f542b74b: Post request put error: Post "https://pod-050-1005-01.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501005_t0027": context canceled



[INFO] rclone output: <3>ERROR : data/1d/1d9c19c83688d4446ae7678d95086da765a6fd7e2a0c3c643aa2e391f542b74b: Post request rcat error: Post "https://pod-050-1005-01.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501005_t0027": context canceled



[WARN] Error error sending request for url (http://127.0.0.1:44079/data/1d9c19c83688d4446ae7678d95086da765a6fd7e2a0c3c643aa2e391f542b74b): operation timed out at 518.998993ms, retrying

[INFO] rclone output: <3>ERROR : data/1d/1d9c19c83688d4446ae7678d95086da765a6fd7e2a0c3c643aa2e391f542b74b: Post request put error: Post "https://pod-050-1001-01.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501001_t0045": context canceled



[INFO] rclone output: <3>ERROR : data/1d/1d9c19c83688d4446ae7678d95086da765a6fd7e2a0c3c643aa2e391f542b74b: Post request rcat error: Post "https://pod-050-1001-01.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501001_t0045": context canceled



[WARN] Error error sending request for url (http://127.0.0.1:44079/data/e31271d79d989248835f8511d033a096b27a6fbd70a1692b985a7a1322c39552): operation timed out at 470.218131ms, retrying

[INFO] rclone output: <3>ERROR : data/e3/e31271d79d989248835f8511d033a096b27a6fbd70a1692b985a7a1322c39552: Post request put error: Post "https://pod-050-1001-01.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501001_t0045": context canceled



[INFO] rclone output: <3>ERROR : data/e3/e31271d79d989248835f8511d033a096b27a6fbd70a1692b985a7a1322c39552: Post request rcat error: Post "https://pod-050-1001-01.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501001_t0045": context canceled



[WARN] Error error sending request for url (http://127.0.0.1:44079/data/e31271d79d989248835f8511d033a096b27a6fbd70a1692b985a7a1322c39552): operation timed out at 1.078056185s, retrying

[INFO] rclone output: <3>ERROR : data/e3/e31271d79d989248835f8511d033a096b27a6fbd70a1692b985a7a1322c39552: Post request put error: Post "https://pod-050-1005-01.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501005_t0027": context canceled



[INFO] rclone output: <3>ERROR : data/e3/e31271d79d989248835f8511d033a096b27a6fbd70a1692b985a7a1322c39552: Post request rcat error: Post "https://pod-050-1005-01.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501005_t0027": context canceled



[WARN] Error error sending request for url (http://127.0.0.1:44079/data/e31271d79d989248835f8511d033a096b27a6fbd70a1692b985a7a1322c39552): operation timed out at 901.616388ms, retrying

Thanks in advance for any guidance you can provide! Been googling and cannot find any concrete answers.

[aawsome]

Thanks for opening this discussion!
At a first glance, it looks like you are getting errors from rclone - maybe you can ask the rclone forum for what they mean.

Besides that, here are some thoughts:

• The fact that this just started to happen for your large repository AND after some time without problems MAY indicate that the problem starts to arise with a given pack size (Note: The pack size is increased DURING the backup run depending on how much data is already saved in the repo)
• You get "operation timed out" errors. These could be caused by the fact that your (larger) packfiles cannot be sent during the timeout specified by the http client which connect to rclone. By default it seems to be 30s which - depending on your internet connection - could be too less to upload large files. I think I should increase the default timeout to something like 10 minutes. You can also manually set it by using timeout = "10min" in the [repository.options] of your config file.

[RobTheBuilder2]

Yea, I have restarted the backup, but as I mentioned, then I get a weird issue where the rustic snapshot shows a size 5x more than what's actually on disk. This does not give me confidence that if I need to restore, my data will be restored in tact. Also, it seems odd that rustic/rclone can recover from disconnects several times, but then all of a sudden it is unrecoverable and the backup is marked as failed. So two issues:

1. Why is this connection issue not recoverable when all the other instances of the same exception logged recover just fine?
2. Why when I resume, the final backup has inconsistent size reported between rustic repoinfo and the actual size on disk.

[aawsome]

1. The errors shown did indicate some network error ("dial tcp 149.137.136.116:443: i/o timeout"; "use of closed network connection"). In this case rustic re-tries to upload the files. But after a couple of retries it will give up - it could be a permanent error, so retrying forever doesn't help. From the errors I assume that you had a longer network failure. It can also be that you had only a shorter failure, but for some reason rclone or B2 did cut the connection off - which for rustic has the same effect. But as said, this is not that bad as you can simply restart the backup and rustic won't restart from scratch.
2. As long as you are talking about ZFS and what ZFS is reporting as actual disc size used, you cannot compare that to the "total snaphot size" by rustic. Rustic simply reports the sum of the length of all files. This can differ very much to what needs to be stored on disc - especially if you have sparse files or more sophisticated file systems which also use deduplication internally. Even on "old-school" FS, this will differ as usually filesystems will use whole blocks (e.g. 4kiB) even if a file doesn't need the full block. Please finish your backup first - and than you can go look for why the numbers are as they are. Note that even if rustic would save extra unneeded data, the prune command would be able to detect and remove that data.

[DianaNites]

Also had this issue and resolved it with an increased time out to 10 minutes

personally i would expect it to either by default or optionally retry forever, with an increasing timeout each retry up to a max timeout of X. The idea being it is highly unlikely that goes down forever and far more likely to be an intermittent network issue that a user would prefer be automatically resumed from when connectivity returns. 1 request/hour to check if its still down is unlikely to be an issue, and allows long-running backup jobs to safely run in the background for as long as they need.

[simonsan]

@RobTheBuilder2

It would make me feel more comfortable that the data being backed up is accurate and I can count on it if I need to restore.
This does not give me confidence that if I need to restore, my data will be restored in tact.

Side note: You don't know if it works until you have tried it. restoring and tests if restore works should definitely be part of your backup strategy.

[simonsan]

Also had this issue and resolved it with an increased time out to 10 minutes

personally i would expect it to either by default or optionally retry forever, with an increasing timeout each retry up to a max timeout of X. The idea being it is highly unlikely that goes down forever and far more likely to be an intermittent network issue that a user would prefer be automatically resumed from when connectivity returns. 1 request/hour to check if its still down is unlikely to be an issue, and allows long-running backup jobs to safely run in the background for as long as they need.

My personal opinion is that rustic shouldn't just retry forever. I think that this behaviour should be implemented elsewhere. E.g. check rustic output for errors and retry itself after a while in a script or implement a daemon on top of rustic that takes care of handling such cases.

[aawsome]

I did dig a bit into the retry/timeout topic. Actually there are three things:

1. The retries/timeout rclone is performing => this cannot be influenced by rustic, but some setups may require rclone config to work. I think this is not the case for a rustic repo as files can be maximum 4GiB size - and especially not for your usecase of a ~1TiB repo which should have file sizes around 64 MiB.
2. The timeout set for the http client used in rustic to access rclone. This can be set by the timeout repository option and defaults now to 10min (latest beta - the latest release has still only 2min, IIRC).
3. In cases of failures/timeouts, rustic retries the operation. But here, currently only a total elapsed time starting from the first try is set - and it is set to just 2 min. So the current effect could be that rustic tries to transfer a large file which takes more than 2min and then fails. In this case rustic won't even retry a single time, but just aborts. So I think we should change this to a fixed maximum number of retries - and make this number also customizable. I'll prepare a PR for this.

[RobTheBuilder2]

I have the latest from that PR. When i run rustic --version, I get:
rustic v0.5.4-88-ga57d02b

Here's the full output:
2023-07-11T00:50:37-05:00 Summary Info Captured:
2023-07-11T00:50:37-05:00 error: backoff failed: Transient(reqwest::Error { kind: Status(500), url: Url { scheme: "http", cannot_be_a_base: false, username: "", password: None, host: Some(Ipv4(127.0.0.1)), port: Some(35129), path: "/data/7e84274b0f53016ad7bd995a0701b295be376cb22eeffbac3a62470324a37488", query: None, fragment: None } })
2023-07-11T00:50:37-05:00
2023-07-11T00:50:37-05:00 [INFO] rclone output: <3>ERROR : data/95/95bfd8cb77a9189de242dcfd7bf9f1b51c4d4bd7ac3384829a6b96a586180582: Post request rcat error: Unknown 401 (401 expired_auth_token)
2023-07-11T00:50:37-05:00
2023-07-11T00:50:37-05:00 [INFO] rclone output: <3>ERROR : data/95/95bfd8cb77a9189de242dcfd7bf9f1b51c4d4bd7ac3384829a6b96a586180582: Post request put error: Unknown 401 (401 expired_auth_token)
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/80/80223f3419b951128862b6c33cc111c87d692a9fdb43be872eb67cf7d0f77777: Post request rcat error: Post "https://pod-050-1002-18.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501002_t0057": use of closed network connection
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/80/80223f3419b951128862b6c33cc111c87d692a9fdb43be872eb67cf7d0f77777: Post request put error: Post "https://pod-050-1002-18.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501002_t0057": use of closed network connection
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/d6/d60d63218057c7c1a78e65b7c5b899ccb1c5f3f41476b6f40aba621903b2e3ad: Post request rcat error: Unknown 401 (401 expired_auth_token)
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/d6/d60d63218057c7c1a78e65b7c5b899ccb1c5f3f41476b6f40aba621903b2e3ad: Post request put error: Unknown 401 (401 expired_auth_token)
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/5d/5db3992b8e440b450a5b6b58f6d422f7b75f813bae752c4e6109ceca66f8704a: Post request rcat error: Unknown 401 (401 expired_auth_token)
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/5d/5db3992b8e440b450a5b6b58f6d422f7b75f813bae752c4e6109ceca66f8704a: Post request put error: Unknown 401 (401 expired_auth_token)
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/f4/f4488ffbbceb7b53d47d4702adb3bbec4de71ad941ff50a1e5772c526f3c8762: Post request rcat error: Unknown 401 (401 expired_auth_token)
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/f4/f4488ffbbceb7b53d47d4702adb3bbec4de71ad941ff50a1e5772c526f3c8762: Post request put error: Unknown 401 (401 expired_auth_token)
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/83/830910d6eacda017efc172849fed576f48e5d361ae394ddf736cc4bd23b337a0: Post request rcat error: Unknown 401 (401 expired_auth_token)
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/83/830910d6eacda017efc172849fed576f48e5d361ae394ddf736cc4bd23b337a0: Post request put error: Unknown 401 (401 expired_auth_token)
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/a2/a2e66c6e1634d8664755b6742fc9a6e659aff8a5a261d601b50ee6e00b9dea79: Post request rcat error: Post "https://pod-050-1000-16.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501000_t0038": write tcp 192.168.2.2:45584->149.137.136.67:443: write: connection reset by peer
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/a2/a2e66c6e1634d8664755b6742fc9a6e659aff8a5a261d601b50ee6e00b9dea79: Post request put error: Post "https://pod-050-1000-16.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501000_t0038": write tcp 192.168.2.2:45584->149.137.136.67:443: write: connection reset by peer
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/97/97986a28c9b1b3a206148c3f0bb2f9b60779f3f7028633241535e8e3915593c0: Post request rcat error: Post "https://pod-050-1003-19.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501003_t0058": write tcp 192.168.2.2:57482->149.137.136.130:443: write: connection reset by peer
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/97/97986a28c9b1b3a206148c3f0bb2f9b60779f3f7028633241535e8e3915593c0: Post request put error: Post "https://pod-050-1003-19.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501003_t0058": write tcp 192.168.2.2:57482->149.137.136.130:443: write: connection reset by peer
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/35/359beb75a525400d0bf3fea892196f25dbd351e66f38fa885de1e0df4d9d28ba: Post request rcat error: Post "https://pod-050-1002-08.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501002_t0022": net/http: TLS handshake timeout
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/35/359beb75a525400d0bf3fea892196f25dbd351e66f38fa885de1e0df4d9d28ba: Post request put error: Post "https://pod-050-1002-08.backblaze.com/b2api/v1/b2_upload_file/583356dd947c7f8f80820613/c005_v0501002_t0022": net/http: TLS handshake timeout
2023-07-10T18:01:13-05:00
2023-07-10T18:01:13-05:00 [INFO] rclone output: <3>ERROR : data/61/618a5c42108da46ac9fe572ec96f6abd467973260e8b61c3d5a57ba801b4c1e7: Post request rcat error: Unknown 401 (401 expired_auth_token)

I'm going to try restarting now.

[aawsome]

I have the latest from that PR. When i run rustic --version, I get: rustic v0.5.4-88-ga57d02b

Actually this is the version without retries. You should get -g5bd4fa5. This version uses 5 retries by default.

[RobTheBuilder2]

OK. That was my mistake. I now have confirmed the version reports as rustic v0.5.4-129-g5bd4fa5. Will re-run to see if it recovers, but that won't tell us if the retry logic is working. After completing this data set I will try my other large dataset that I have not tried yet to see if the retry works.

[aawsome]

No sorry, that was my mistake or at least the confusion I was responsible for. I created #720 but by accident made the default number of retries 0. This I only encountered after #720 got reviewed, so I changed this yesterday (in v0.5.4-129-g5bd4fa5). TL;DR: you didn't have a change to test it in the first time... Sorry for that.
Anyway, would be good to see an example where it is working and I'm pretty confident it will :-)

[RobTheBuilder2]

OK. It worked with my other large dataset. I got the full first backup complete in the first pass. I am seeing the same snapshot size issue on this dataset as well. It is showing the snapshot size as 5.4TiB. I pulled this data from a 1TB drive when I backed it up on my NAS, so there is no way it is that size. Any idea why rustic keeps reporting these odd snapshot sizes? That's really the only remaining open question.

[aawsome]

OK. It worked with my other large dataset.

Great! Did you see some retries in your log?

Any idea why rustic keeps reporting these odd snapshot sizes?

Can you give the output of rustic repoinfo?

[RobTheBuilder2]

Great! Did you see some retries in your log?

Yes.

Can you give the output of rustic repoinfo?

repository files

File type	Count	Total Size
Key	1	363 B
Snapshot	1	602 B
Index	958	26.9 MiB
Pack	14270	682.7 GiB
Total	15230	682.8 GiB

Blob type	Count	Total Size	Total Size in Packs
Tree	1910	664.9 MiB	32.6 MiB
Data	542237	700.4 GiB	682.7 GiB
Total	544147	701.0 GiB	682.7 GiB

Blob type	Pack Count	Minimum Size	Maximum Size
Tree packs	179	131 B	3.6 MiB
Data packs	14091	1.2 MiB	64.6 MiB

And if I run rustic snapshots I get:

snapshots for (host [Kraken], label [], paths [/naspool/Elnaz])

ID	Time	Host	Label	Tags	Paths	Files	Dirs	Size
4c337e08	2023-07-12 15:13:00	Kraken			//**	104568	1974	5.4 TiB
1 snapshot(s)

[aawsome]

Ok, I see what you mean. First, The repository size seems to be perfectly reasonable. You backuped from a 1 TB drive; rustic stored 701 GiB of "raw" data and the total repository size is 682.8 GiB (this is what also Backblaze should report).

So, your only concern is the snaphot size, which is reported as 5.4 TiB, right?
In fact this again is perfectly plausible if rustic was able to deduplicate a lot of data. This could be sparse files or duplicate files (or just file parts which are duplicate :-) ).

Also, if your filesystem is able to take advantage of these things (with sparse files it definitively is, for duplicate files, I think ZFS is also), then it is also perfectly plausible that this "content" fits onto your 1TB drive - even though the "apparent size" of all files is larger than 1TB. Can you run du -b on the backup'ed dir? It should show the apparent size of it. (But it also counts the directories which are not included in rustic's "Size" information).

[RobTheBuilder2]

The output is 5953159859638 when I ran du -b. That does come out to around 5+ TB. However, this is very odd and I'll need to track down. This is a brand new NAS and I copied this particular dataset from a 1TB external drive. So it was impossible that this data was 5+TB because it would not have fit on that drive.

However, it seems though at this point, rustic is working as expected and there is something else on my system I need to dig into.

[RobTheBuilder2]

Did some quick research. This is an issue with ZFS and how it reports block usage to the kernel. Since it is a copy on write file system, it doesn't follow all the behaviors linux expects in the file system. It seems this is not an issue at all and likely everything is backed up appropriately. The only problem is this particular file system is reporting odd values for blocks used because it is a CoW FS under the hood.

[aawsome]

As #720 has been just merged and there seems to be no open questions, I'll mark this discussion as answered.
Thanks again @RobTheBuilder2 for the intensive testing!
If you could create a PR putting your configuration in the config dir, I would very much appreciate that!