Tons of data corruption after rclone copy to Mega, can rclone correct it?

chi · June 9, 2020, 11:36am

What is the problem you are having with rclone?

I uploaded about 17GB of data to Mega using "rclone copy". It completed successfully, but "rclone check" says the data is corrupted. I had to use the "--download" flag as Mega doesn't support checksums.

I can't find any documented way to actually correct the data.

I'm going to rerun the check with "-vv", however since Mega doesn't support checksums, this probably won't be finished until tomorrow.

What is your rclone version (output from `rclone version`)

$ rclone version
rclone v1.52.0

os/arch: linux/amd64
go version: go1.14.3

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Ubuntu 20.04, 64 bit

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

Mega

The initial copy (in two parts, the first attempt was interrupted with CTRL+C)

$ rclone --transfers 1 --bwlimit=0.5M -v -P copy XXXXX remotename:XXXXX

2020/06/07 15:46:13 INFO  : Starting bandwidth limiter at 512kBytes/s
2020-06-07 15:46:14 INFO  : XXXXX: Copied (new)
2020-06-07 15:47:03 INFO  : XXXXX: Copied (new)
2020-06-07 15:47:04 INFO  : XXXXX: Copied (new)
2020-06-07 15:47:05 INFO  : XXXXX: Copied (new)
2020-06-07 15:47:07 INFO  : XXXXX: Copied (new)
2020-06-07 15:47:08 INFO  : XXXXX: Copied (new)
2020-06-07 15:47:08 INFO  : XXXXX: Copied (new)
2020-06-07 15:47:09 INFO  : XXXXX: Copied (new)
2020-06-07 15:47:10 INFO  : XXXXX: Copied (new)
2020-06-07 15:47:10 INFO  : XXXXX: Copied (new)
2020-06-07 15:47:18 INFO  : XXXXX: Copied (new)
2020-06-07 15:47:18 INFO  : XXXXX: Copied (new)
2020-06-07 15:48:06 INFO  : XXXXX: Copied (new)
Transferred:      129.979M / 16.967 GBytes, 1%, 494.796 kBytes/s, ETA 9h54m47s
Transferred:           13 / 81, 16%
Elapsed time:      4m28.9s
Transferring:
 * XXXXX: 14% /512.079M, 412.064k/s, 18m9s^C

$ rclone --transfers 1 --bwlimit=0.5M -v -P copy XXXXX remotename:XXXXX

2020/06/07 15:54:00 INFO  : Starting bandwidth limiter at 512kBytes/s
2020-06-07 16:24:05 INFO  : *go-mega*: pollEvents: Error fetching status: Post "https://g.api.mega.co.nz/sc?sn=XXXXX": dial tcp XXXXX:443: i/o timeout
2020-06-07 16:36:19 INFO  : XXXXX: Copied (new)
2020-06-07 16:36:19 INFO  : XXXXX: Copied (new)
2020-06-07 16:58:11 INFO  : XXXXX: Copied (new)
2020-06-07 16:58:12 INFO  : XXXXX: Copied (new)
2020-06-07 17:15:50 INFO  : XXXXX: Copied (new)
2020-06-07 17:15:51 INFO  : XXXXX: Copied (new)
2020-06-07 17:37:57 INFO  : XXXXX: Copied (new)
2020-06-07 17:37:58 INFO  : XXXXX: Copied (new)
2020-06-07 17:42:58 INFO  : *go-mega*: pollEvents: Error from server: 500 Server Too Busy
2020-06-07 17:42:58 INFO  : *go-mega*: pollEvents: Error from server: 500 Server Too Busy
2020-06-07 17:54:56 INFO  : XXXXX: Copied (new)
2020-06-07 17:54:58 INFO  : XXXXX: Copied (new)
2020-06-07 18:12:01 INFO  : XXXXX: Copied (new)
2020-06-07 18:12:04 INFO  : XXXXX: Copied (new)
2020-06-07 18:30:33 INFO  : XXXXX: Copied (new)
2020-06-07 18:30:34 INFO  : XXXXX: Copied (new)
2020-06-07 18:37:27 INFO  : *go-mega*: pollEvents: Error from server: 500 Server Too Busy
2020-06-07 18:47:31 INFO  : XXXXX: Copied (new)
2020-06-07 18:47:33 INFO  : XXXXX: Copied (new)
// .... (lots of repeats of "Copied (new)") ....
2020-06-08 02:47:01 INFO  : XXXXX: Copied (new)
2020-06-08 02:47:01 INFO  : XXXXX: Copied (new)
Transferred:       16.912G / 16.912 GBytes, 100%, 452.610 kBytes/s, ETA 0s
Checks:                13 / 13, 100%
Transferred:           68 / 68, 100%
Elapsed time:   10h53m0.5s
2020/06/08 02:47:01 INFO  : 
Transferred:       16.912G / 16.912 GBytes, 100%, 452.610 kBytes/s, ETA 0s
Checks:                13 / 13, 100%
Transferred:           68 / 68, 100%
Elapsed time:   10h53m0.5s

Check

$ rclone --transfers 1 --bwlimit=0.5M -v -P check --download XXXXX remotename:XXXXX

2020/06/08 10:06:27 INFO  : Starting bandwidth limiter at 512kBytes/s
2020-06-08 10:41:36 INFO  : *go-mega*: pollEvents: Error from server: 500 Server Too Busy
2020-06-08 17:18:08 INFO  : *go-mega*: pollEvents: Error fetching status: Post "https://g.api.mega.co.nz/sc?XXXXX": dial tcp: lookup g.api.mega.co.nz on 127.0.0.53:53: read udp 127.0.0.1:51618->127.0.0.53:53: i/o timeout
2020-06-08 17:18:28 INFO  : *go-mega*: pollEvents: Error fetching status: Post "https://g.api.mega.co.nz/sc?XXXXX": dial tcp: lookup g.api.mega.co.nz on 127.0.0.53:53: read udp 127.0.0.1:40067->127.0.0.53:53: i/o timeout
2020-06-08 18:33:46 INFO  : *go-mega*: pollEvents: Error fetching status: Post "https://g.api.mega.co.nz/sc?XXXXX": dial tcp XXXXX: connect: network is unreachable
2020-06-08 18:33:52 INFO  : *go-mega*: pollEvents: Error from server: 500 Server Too Busy
2020-06-08 20:24:20 ERROR : XXXXX: Failed to download: read tcp XXXXX: i/o timeout
2020-06-08 21:28:29 ERROR : XXXXX: Failed to download: read tcp XXXXX: read: connection reset by peer
2020-06-08 22:38:44 ERROR : XXXXX: Failed to download: read tcp XXXXX: read: connection reset by peer
2020-06-08 23:51:40 INFO  : *go-mega*: pollEvents: Error fetching status: Post "https://g.api.mega.co.nz/sc?XXXXX": net/http: TLS handshake timeout
2020-06-09 01:12:19 INFO  : *go-mega*: pollEvents: Error fetching status: Post "https://g.api.mega.co.nz/sc?XXXXX": read tcp XXXXX: read: connection reset by peer
2020-06-09 04:35:12 ERROR : XXXXX: Failed to download: read tcp XXXXX: read: connection reset by peer
2020-06-09 04:49:38 INFO  : *go-mega*: pollEvents: Error from server: 500 Server Too Busy
2020-06-09 05:02:44 NOTICE: mega root 'XXXXX': 12 differences found
2020-06-09 05:02:44 NOTICE: mega root 'XXXXX': 77 matching files
Transferred:       31.975G / 31.975 GBytes, 100%, 491.783 kBytes/s, ETA 0s
Errors:                13 (retrying may help)
Checks:                81 / 81, 100%
Transferred:          154 / 154, 100%
Elapsed time:  18h56m16.3s
2020/06/09 05:02:44 Failed to check with 13 errors: last error was: 4 differences found

Animosity022 · June 9, 2020, 11:47am

chi:

2020-06-08 17:18:08 INFO  : *go-mega*: pollEvents: Error fetching status: Post "https://g.api.mega.co.nz/sc?XXXXX": dial tcp: lookup g.api.mega.co.nz on 127.0.0.53:53: read udp 127.0.0.1:51618->127.0.0.53:53: i/o timeout
2020-06-08 17:18:28 INFO  : *go-mega*: pollEvents: Error fetching status: Post "https://g.api.mega.co.nz/sc?XXXXX": dial tcp: lookup g.api.mega.co.nz on 127.0.0.53:53: read udp 127.0.0.1:40067->127.0.0.53:53: i/o timeout
2020-06-08 18:33:46 INFO  : *go-mega*: pollEvents: Error fetching status: Post "https://g.api.mega.co.nz/sc?XXXXX": dial tcp XXXXX: connect: network is unreachable

Those are network errors on your end so you'd want to clear them up and re-run the command.

chi · June 9, 2020, 12:09pm

Thanks, but shouldn't rclone retry the check if there's a network error? My connection is unreliable and I can't really avoid a few network errors in over 12 hours of constant downloading.

It's running with -vv now, and rclone doesn't seem to retry the download for a particular file if it fails:

Failed to download: read tcp XXXXX: read: connection reset by peer

(and then it just moves on to the next file without retrying)

Animosity022 · June 9, 2020, 12:14pm

By default it retries 3 times:

      --retries int                          Retry operations this many times if they fail (default 3)

and low level, it does 10 times:

--low-level-retries int                Number of low level retries to do. (default 10)

You can try to increase them as well or you can just re-run the command again if your network is not stable as those errors are pretty bad in terms of your connection.

calisro · June 9, 2020, 12:14pm

you can also control the wait time between retries:


      --retries-sleep duration               Interval between retrying operations if they fail, e.g 500ms, 60s, 5m. (0 to disable)

ncw · June 9, 2020, 6:49pm

That is bad.

It looks like from your log that you had a bit of networking problems while uploading.

Rclone should be accounting for this so there is a problem which needs fixing.

Can you see how the files are corrupted? Are they too short? Or corrupted in some other way?

Do you have an example of a normal file and a corrupted file that you could share with me?

chi · June 10, 2020, 8:13pm

Thank you all for your responses.

I've now run the check with -vv. It looks like the data was uploaded without corruption, but the check failed.

As far as I can tell, "rclone check" made no attempt to retry the one failed transfer, despite the default apparently being 3 attempts. The file that says "Failed to download" in the log below never appeared in the log again.
A failed transfer is reported as a "difference" at the end of the check

The log says "3 differences found", but then on the last line it also says "1 differences found", which is a bit confusing.

Full log included below.

2020/06/09 12:24:40 DEBUG : rclone: Version "v1.52.0" starting with parameters ["rclone" "--transfers" "1" "--bwlimit=0.5M" "-vv" "-P" "check" "--download" "XXXXX" "XXXXX"]
2020/06/09 12:24:40 DEBUG : Using config file from "/home/user/.config/rclone/rclone.conf"
2020/06/09 12:24:40 INFO  : Starting bandwidth limiter at 512kBytes/s
2020-06-09 12:24:41 DEBUG : mega root 'XXXXX': Waiting for checks to finish
2020-06-09 12:24:42 DEBUG : XXXXX: OK
2020-06-09 12:24:42 DEBUG : XXXXX: OK
2020-06-09 12:24:42 DEBUG : XXXXX: OK
2020-06-09 12:24:42 DEBUG : XXXXX: OK
2020-06-09 12:24:55 DEBUG : XXXXX: OK
2020-06-09 12:24:57 DEBUG : XXXXX: OK
2020-06-09 12:25:12 DEBUG : XXXXX: OK
2020-06-09 12:25:13 DEBUG : XXXXX: OK
2020-06-09 12:25:14 DEBUG : XXXXX: OK
2020-06-09 12:25:15 DEBUG : XXXXX: OK
2020-06-09 12:28:14 DEBUG : XXXXX: OK
2020-06-09 12:28:16 DEBUG : XXXXX: OK
2020-06-09 12:28:26 DEBUG : XXXXX: OK
2020-06-09 12:34:16 ERROR : XXXXX: Failed to download: read tcp XXXXX: read: connection reset by peer
2020-06-09 12:34:17 DEBUG : XXXXX: OK
2020-06-09 13:08:25 DEBUG : XXXXX: OK
2020-06-09 13:08:27 DEBUG : XXXXX: OK
2020-06-09 13:42:34 DEBUG : XXXXX: OK
2020-06-09 13:42:35 DEBUG : XXXXX: OK
2020-06-09 14:16:43 DEBUG : XXXXX: OK
2020-06-09 14:16:44 DEBUG : XXXXX: OK
2020-06-09 14:50:53 DEBUG : XXXXX: OK
2020-06-09 14:50:55 DEBUG : XXXXX: OK
2020-06-09 15:25:03 DEBUG : XXXXX: OK
2020-06-09 15:25:04 DEBUG : XXXXX: OK
2020-06-09 15:59:12 DEBUG : XXXXX: OK
2020-06-09 15:59:14 DEBUG : XXXXX: OK
2020-06-09 16:30:00 INFO  : *go-mega*: pollEvents: Error from server: 500 Server Too Busy
2020-06-09 16:33:21 DEBUG : XXXXX: OK
2020-06-09 16:33:24 DEBUG : XXXXX: OK
2020-06-09 17:07:32 DEBUG : XXXXX: OK
2020-06-09 17:07:34 DEBUG : XXXXX: OK
2020-06-09 17:41:41 DEBUG : XXXXX: OK
2020-06-09 17:41:43 DEBUG : XXXXX: OK
2020-06-09 18:15:50 DEBUG : XXXXX: OK
2020-06-09 18:15:53 DEBUG : XXXXX: OK
2020-06-09 18:40:16 INFO  : *go-mega*: pollEvents: Error from server: 500 Server Too Busy
2020-06-09 18:50:00 DEBUG : XXXXX: OK
2020-06-09 18:50:01 DEBUG : XXXXX: OK
2020-06-09 19:24:09 DEBUG : XXXXX: OK
2020-06-09 19:24:10 DEBUG : XXXXX: OK
2020-06-09 19:35:20 INFO  : *go-mega*: pollEvents: Error from server: 500 Server Too Busy
2020-06-09 19:58:18 DEBUG : XXXXX: OK
2020-06-09 19:58:19 DEBUG : XXXXX: OK
2020-06-09 20:32:27 DEBUG : XXXXX: OK
2020-06-09 20:32:29 DEBUG : XXXXX: OK
2020-06-09 21:06:36 DEBUG : XXXXX: OK
2020-06-09 21:06:39 DEBUG : XXXXX: OK
2020-06-09 21:40:45 DEBUG : XXXXX: OK
2020-06-09 21:40:46 DEBUG : XXXXX: OK
2020-06-09 22:14:54 DEBUG : XXXXX: OK
2020-06-09 22:14:57 DEBUG : XXXXX: OK
2020-06-09 22:49:04 DEBUG : XXXXX: OK
2020-06-09 22:49:07 DEBUG : XXXXX: OK
2020-06-09 23:23:14 DEBUG : XXXXX: OK
2020-06-09 23:23:17 DEBUG : XXXXX: OK
2020-06-09 23:25:38 INFO  : *go-mega*: pollEvents: Error from server: 500 Server Too Busy
2020-06-09 23:25:39 INFO  : *go-mega*: pollEvents: Error from server: 500 Server Too Busy
2020-06-09 23:57:24 DEBUG : XXXXX: OK
2020-06-09 23:57:26 DEBUG : XXXXX: OK
2020-06-10 00:31:33 DEBUG : XXXXX: OK
2020-06-10 00:31:35 DEBUG : XXXXX: OK
2020-06-10 01:05:41 DEBUG : XXXXX: OK
2020-06-10 01:05:44 DEBUG : XXXXX: OK
2020-06-10 01:39:51 DEBUG : XXXXX: OK
2020-06-10 01:39:53 DEBUG : XXXXX: OK
2020-06-10 02:14:00 DEBUG : XXXXX: OK
2020-06-10 02:14:03 DEBUG : XXXXX: OK
2020-06-10 02:48:09 DEBUG : XXXXX: OK
2020-06-10 02:48:10 DEBUG : XXXXX: OK
2020-06-10 03:22:18 DEBUG : XXXXX: OK
2020-06-10 03:22:21 DEBUG : XXXXX: OK
2020-06-10 03:56:27 DEBUG : XXXXX: OK
2020-06-10 03:56:30 DEBUG : XXXXX: OK
2020-06-10 04:21:03 INFO  : *go-mega*: pollEvents: Error from server: 500 Server Too Busy
2020-06-10 04:30:37 DEBUG : XXXXX: OK
2020-06-10 04:30:39 DEBUG : XXXXX: OK
2020-06-10 05:04:46 DEBUG : XXXXX: OK
2020-06-10 05:04:47 DEBUG : XXXXX: OK
2020-06-10 05:38:56 DEBUG : XXXXX: OK
2020-06-10 05:38:58 DEBUG : XXXXX: OK
2020-06-10 06:13:04 DEBUG : XXXXX: OK
2020-06-10 06:13:07 DEBUG : XXXXX: OK
2020-06-10 06:47:14 DEBUG : XXXXX: OK
2020-06-10 06:47:16 DEBUG : XXXXX: OK
2020-06-10 07:14:38 DEBUG : XXXXX: OK
2020-06-10 07:14:41 DEBUG : XXXXX: OK
2020-06-10 07:14:41 NOTICE: mega root 'XXXXX': 3 differences found
2020-06-10 07:14:41 NOTICE: mega root 'XXXXX': 80 matching files
Transferred:       33.105G / 33.105 GBytes, 100%, 511.993 kBytes/s, ETA 0s
Errors:                 4 (retrying may help)
Checks:                81 / 81, 100%
Transferred:          160 / 160, 100%
Elapsed time:  18h49m59.9s
2020/06/10 07:14:41 DEBUG : 13 go routines active
2020/06/10 07:14:41 Failed to check with 4 errors: last error was: 1 differences found

ncw · June 12, 2020, 4:03pm

Hmm, that is an error from the mega polling loop and I don't think they are too important - they just get polled later.

That is an actual error that rclone would have counted as a difference. This isn't ideal I agree - the errors aren't being bubbled up properly, nor being retried.

Yes I am confused too

I think that is a bug - it is just printing the wrong thing.

I made a fix for the printing problem and to make check retry if a download failed. Can you have a go with this? Thanks!

https://beta.rclone.org/branch/v1.52.1-063-g800ad3c4-fix-check-beta/ (uploaded in 15-30 mins)

chi · June 18, 2020, 1:26pm

Thanks @ncw, I'm trying that now!

One thing I have noticed is that this new build seems to ignore the --transfers flag: I've set it to --transfers 1, but it's currently doing 8 downloads in parallel. IIRC this wasn't a problem with the original v1.52 release.

ncw · June 18, 2020, 3:20pm

The new build is running --checkers worth of checks in parallel. If you are using the --download flag then these become downloads, so you'll want to set --checkers 1 instead or maybe as well.

I've merged this fix to master now which means it will be in the latest beta in 15-30 mins and released in v1.53

chi · June 19, 2020, 10:10am

Thanks. It's just finished -- it's better than it was before, and did successfully retry 4 files.

2020-06-19 10:21:41 NOTICE: mega root 'XXXXX': 0 differences found
2020-06-19 10:21:41 NOTICE: mega root 'XXXXX': 4 errors while checking
2020-06-19 10:21:41 NOTICE: mega root 'XXXXX': 81 matching files
Transferred:       35.173G / 35.173 GBytes, 100%, 512.007 kBytes/s, ETA 0s
Errors:                 4 (retrying may help)
Checks:                81 / 81, 100%
Transferred:          162 / 162, 100%
Elapsed time:   20h0m32.3s
2020/06/19 10:21:41 DEBUG : 9 go routines active
2020/06/19 10:21:41 Failed to check with 4 errors: last error was: read tcp XXXXX: read: connection reset by peer

I can see it was successful due to the "81 matching files" line (which is only a notice, so I guess it doesn't show up without -vv?)

Still surprised to see "Failed to check" at the end though, given that all the retries were successful and all the files matched.

ncw · June 20, 2020, 1:53pm

NOTICE messages show up without any logging flags.

Hmm, that looks like a bug...

I've fixed that in the latest beta which you'll find in 15-30 mins.

https://beta.rclone.org/v1.52.1-102-g62a1a561-beta/ (uploaded in 15-30 mins)

Thanks for testing

system · August 20, 2020, 9:53am

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.