Difficulty using rustic copy with large snapshots on S3 cloud service

[kalleyne]

This problem may be related to this other problem posted to the restic forum:
https://forum.restic.net/t/errors-restoring-with-restic-on-windows-server-s3/6943/11?u=kalleyne

Seeing that I was having difficulty using restic to copy large snapshots between a S3 cloud service and a local repo I then switched my attention to rustic (rustic 0.7.0) to see if it would solve my problem.

I created the prerequisite file: /home/user1/.config/rustic/rustic.toml

Trying to copy a different snapshot as compared to the restic test:
rustic copy --init 4246b963

Client::send, service: s3, path: data/2c/2ce42718cd8168266901d2add31e1118209f02c8ef0afe0290f8ca6f996d9a2b, range: 946843-3017373 } => send http request, source: error sending request for url (https://s3.somecloudservice.com/bucket/data/2c/2ce42718cd8168266901d2add31e1118209f02c8ef0afe0290f8ca6f996d9a2b): connection error: unexpected end of file
[1d 00:06:51] copying blobs...               ████████████████████████████████████████   6.97 TiB            85.48 MiB/s                                                 [WARN] operation=Reader::read path=data/37/37a837b0a47d2960613733c7e33880d7b6d3c70aeb6191a4eff797c708fd039d -> retry after 1.318771243s: error=Unexpected (temporary) at read, context: { url: https://s3.somecloudservice.com/bucket/data/37/37a837b0a47d2960613733c7e33880d7b6d3c70aeb6191a4eff797c708fd039d, called: http_util::Client::send, service: s3, path: data/37/37a837b0a47d2960613733c7e33880d7b6d3c70aeb6191a4eff797c708fd039d, range: 1408493-3775655 } => send http request, source: error sending request for url (https://s3.somecloudservice.com/bucket/data/37/37a837b0a47d2960613733c7e33880d7b6d3c70aeb6191a4eff797c708fd039d): connection error: unexpected end of file
[1d 00:07:07] copying blobs...               ████████████████████████████████████████   6.97 TiB            90.78 MiB/s                                                 [WARN] operation=Reader::read path=data/37/37a837b0a47d2960613733c7e33880d7b6d3c70aeb6191a4eff797c708fd039d -> retry after 2.110703707s: error=Unexpected (temporary) at read, context: { url: https://s3.somecloudservice.com/bucket/data/37/37a837b0a47d2960613733c7e33880d7b6d3c70aeb6191a4eff797c708fd039d, called: http_util::Client::send, service: s3, path: data/37/37a837b0a47d2960613733c7e33880d7b6d3c70aeb6191a4eff797c708fd039d, range: 1408493-3775655 } => send http request, source: error sending request for url (https://s3.somecloudservice.com/bucket/data/37/37a837b0a47d2960613733c7e33880d7b6d3c70aeb6191a4eff797c708fd039d): connection error: unexpected end of file
[1d 01:56:59] copying blobs...               ████████████████████████████████████████   7.50 TiB            81.25 MiB/s                                                 [WARN] operation=Reader::read path=data/7e/7e44316e24597795ffc2cc8b950806dee272a78338dab84eadd317a94577d432 -> retry after 1.9007521870000001s: error=Unexpected (temporary) at read, context: { url: https://s3.somecloudservice.com/bucket/data/7e/7e44316e24597795ffc2cc8b950806dee272a78338dab84eadd317a94577d432, called: http_util::Client::send, service: s3, path: data/7e/7e44316e24597795ffc2cc8b950806dee272a78338dab84eadd317a94577d432, range: 0-1912884 } => send http request, source: error sending request for url (https://s3.somecloudservice.com/bucket/data/7e/7e44316e24597795ffc2cc8b950806dee272a78338dab84eadd317a94577d432): connection error: unexpected end of file
[1d 07:31:26] copying blobs...               ████████████████████████████████████████   9.05 TiB            69.63 MiB/s                                                 [WARN] operation=Reader::read path=data/2d/2df4cbd0c6dec4012b11600d37870cb4064a2bfb520e3e2094c53806c0523a4c -> retry after 1.932788968s: error=Unexpected (temporary) at read, context: { url: https://s3.somecloudservice.com/bucket/data/2d/2df4cbd0c6dec4012b11600d37870cb4064a2bfb520e3e2094c53806c0523a4c, called: http_util::Client::send, service: s3, path: data/2d/2df4cbd0c6dec4012b11600d37870cb4064a2bfb520e3e2094c53806c0523a4c, range: 2920010-4143412 } => send http request, source: error sending request for url (https://s3.somecloudservice.com/bucket/data/2d/2df4cbd0c6dec4012b11600d37870cb4064a2bfb520e3e2094c53806c0523a4c): connection closed before message completed
[1d 10:28:26] copying blobs...               ████████████████████████████████████████   9.87 TiB            80.90 MiB/s                                                 [WARN] operation=Reader::read path=data/14/14cedaa3f2832d8ccd359593b52c51d86a20bf787e7563d68272eaf79440ead9 -> retry after 1.10575521s: error=Unexpected (temporary) at read, context: { url: https://s3.somecloudservice.com/bucket/data/14/14cedaa3f2832d8ccd359593b52c51d86a20bf787e7563d68272eaf79440ead9, called: http_util::Client::send, service: s3, path: data/14/14cedaa3f2832d8ccd359593b52c51d86a20bf787e7563d68272eaf79440ead9, range: 0-2289818 } => send http request, source: error sending request for url (https://s3.somecloudservice.com/bucket/data/14/14cedaa3f2832d8ccd359593b52c51d86a20bf787e7563d68272eaf79440ead9): connection error: unexpected end of file
[1d 13:39:23] copying blobs...               ████████████████████████████████████████  10.80 TiB            86.64 MiB/s                                                 [WARN] operation=Reader::read path=data/9d/9d6d2e37702f5990de9e70883e183213af4a1cac58b177438b4c75d62e9b92f1 -> retry after 1.41057992s: error=Unexpected (temporary) at read, context: { url: https://s3.somecloudservice.com/bucket/data/9d/9d6d2e37702f5990de9e70883e183213af4a1cac58b177438b4c75d62e9b92f1, called: http_util::Client::send, service: s3, path: data/9d/9d6d2e37702f5990de9e70883e183213af4a1cac58b177438b4c75d62e9b92f1, range: 2570590-3379765 } => send http request, source: error sending request for url (https://s3.somecloudservice.com/bucket/data/9d/9d6d2e37702f5990de9e70883e183213af4a1cac58b177438b4c75d62e9b92f1): connection closed before message completed
[1d 17:17:32] copying blobs...               ████████████████████████████████████████  11.85 TiB            80.22 MiB/s                            `

The transfer started working for more than a day but then stopped transferring data and so I had to ctrl+c.

Tried the copy operation again this time without "-- init"

rustic copy 4246b963

[00:47:12] copying blobs...               ████████████████████████████████████████ 215.87 GiB            78.29 MiB/s                                                    [ERROR] service=s3 operation=Reader::read path=data/81/815238a856c9dc4f25a08179f4bc7092b99a6f6f5696d31c841ad5fa8c1ae2c6 read=0 -> read failed: Unexpected (temporary) at read, context: { url: https://s3.somecloudservice.com/bucket/data/81/815238a856c9dc4f25a08179f4bc7092b99a6f6f5696d31c841ad5fa8c1ae2c6, called: http_util::Client::send, service: s3, path: data/81/815238a856c9dc4f25a08179f4bc7092b99a6f6f5696d31c841ad5fa8c1ae2c6, range: 2748878-4859002 } => send http request, source: error sending request for url (https://s3.somecloudservice.com/bucket/data/81/815238a856c9dc4f25a08179f4bc7092b99a6f6f5696d31c841ad5fa8c1ae2c6): connection closed before message completed
[00:47:14] copying blobs...               ████████████████████████████████████████ 216.09 GiB            78.45 MiB/s                                                    [WARN] operation=Reader::read path=data/4e/4ec7008bbba0b0246cab82fe468592e562a7088a6822d42294a09801441ab764 -> retry after 4.812975168s: error=Unexpected (temporary) at read, context: { url: https://s3.somecloudservice.com/bucket/data/4e/4ec7008bbba0b0246cab82fe468592e562a7088a6822d42294a09801441ab764, called: http_util::Client::send, service: s3, path: data/4e/4ec7008bbba0b0246cab82fe468592e562a7088a6822d42294a09801441ab764, range: 1540147-3014903 } => send http request, source: error sending request for url (https://s3.somecloudservice.com/bucket/data/4e/4ec7008bbba0b0246cab82fe468592e562a7088a6822d42294a09801441ab764): connection error: unexpected end of file
[00:47:21] copying blobs...               ████████████████████████████████████████ 216.54 GiB            76.19 MiB/s                                                    [WARN] operation=Reader::read path=data/4e/4ec7008bbba0b0246cab82fe468592e562a7088a6822d42294a09801441ab764 -> retry after 8.348090649s: error=Unexpected (temporary) at Reader::read, context: { url: https://s3.somecloudservice.com/bucket/data/4e/4ec7008bbba0b0246cab82fe468592e562a7088a6822d42294a09801441ab764, service: s3, path: data/4e/4ec7008bbba0b0246cab82fe468592e562a7088a6822d42294a09801441ab764, read_buf: 1474757 } => read data from http stream, source: request or response body error: error reading a body from connection: end of file before message length reached
[00:47:30] copying blobs...               ████████████████████████████████████████ 217.32 GiB            81.50 MiB/s                                                    [WARN] operation=Reader::read path=data/4e/4ec7008bbba0b0246cab82fe468592e562a7088a6822d42294a09801441ab764 -> retry after 16.068087101s: error=Unexpected (temporary) at Reader::read, context: { url: https://s3.somecloudservice.com/bucket/data/4e/4ec7008bbba0b0246cab82fe468592e562a7088a6822d42294a09801441ab764, service: s3, path: data/4e/4ec7008bbba0b0246cab82fe468592e562a7088a6822d42294a09801441ab764, read_buf: 1474757 } => read data from http stream, source: request or response body error: error reading a body from connection: end of file before message length reached
[01:28:34] copying blobs...               ████████████████████████████████████████ 383.45 GiB            68.28 MiB/s                                                    [WARN] operation=Reader::read path=data/63/63005e109decac2219c770a18b541217f020c4bc1f1a61b4e4a57d3bc7af46b5 -> retry after 1.8064556120000002s: error=Unexpected (temporary) at read, context: { url: https://s3.somecloudservice.com/bucket/data/63/63005e109decac2219c770a18b541217f020c4bc1f1a61b4e4a57d3bc7af46b5, called: http_util::Client::send, service: s3, path: data/63/63005e109decac2219c770a18b541217f020c4bc1f1a61b4e4a57d3bc7af46b5, range: 0-981761 } => send http request, source: error sending request for url (https://s3.somecloudservice.com/bucket/data/63/63005e109decac2219c770a18b541217f020c4bc1f1a61b4e4a57d3bc7af46b5): connection error: unexpected end of file
[04:12:56] copying blobs...               ████████████████████████████████████████   1.11 TiB            89.06 MiB/s                                                    The application panicked (crashed).
Message:  called `Result::unwrap()` on an `Err` value: "SendError(..)"
Location: /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rustic_core-0.2.0/src/blob/tree.rs:500

Backtrace omitted. Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.
The application panicked (crashed).
Message:  called `Result::unwrap()` on an `Err` value: "SendError(..)"
Location: /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rustic_core-0.2.0/src/blob/tree.rs:500

Backtrace omitted. Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.
Aborted (core dumped)

Any good suggestions?

Thanks.

[aawsome]

@kalleyne It seems to me that your backend connection is not stable.
In the first example it seems it just got stale and you probably canceled rustic before the connection timed out.

You can try to increase the retries an/or minimize the timeout by setting retry and timeout under [repository.options], see https://github.com/rustic-rs/rustic/blob/main/config/full.toml

Besides this there is an error handling issue which makes rustic panic here, but this is IMO another topic and probably not the root cause of your problem.

[simonsan]

Besides this there is an error handling issue which makes rustic panic here, but this is IMO another topic and probably not the root cause of your problem.

"If a Rust program panics, then it signals a bug in the program. That is, correct Rust programs don’t panic." (https://blog.burntsushi.net/unwrap/)

I extracted that bug to it's own issue, so we don't forget about it: rustic-rs/rustic_core#209

[aawsome]

And, of course, what Michael Eischer wrote in the restic forum also applies to rustic: If copy aborts, you can always manually restart it and it will (more or less) continue from the point it got aborted.