Rclone stalls on ACD upload: "done, 0 Bytes/s, ETA: 0s" and must be restarted

I posted about my problem in someone else’s thread a week ago, but there was no reply, so I am making my own thread. Rclone sync: Stuck?

I am testing either copy or sync from unencrypted ACD to a different encrypted ACD.

standard command i am using: rclone copy amazon:/ crypt:amazon1/

The transfer will start, and all four threads will be busy. Then they will slowly die out until this all show: “0 Bytes/s, ETA: 0s”

running in verbose there are no errors, it just cycles through the same four stalled transfers forever. I have been trying to make this transfer for weeks and it requires me to shutdown the process and restart it every hour.

i am using rclone v1.35-DEV

Transferred: 15.223 GBytes (6.031 MBytes/s)
Errors: 0
Checks: 522
Transferred: 347
Elapsed time: 43m4.7s
Transferring:

  • … #####: 30% done, 0 Bytes/s, ETA: 0s
  • … #####: 11% done, 0 Bytes/s, ETA: 0s
  • … #####: 7% done, 0 Bytes/s, ETA: 1776724h23m22.311929344s
  • … #####: 1% done, 1.746 MBytes/s, ETA: 26m17s

If a copy or a sync never finishes, how can I be sure that it got all the data?

How big are the files you are transferring?

Are you sure things have stalled - does the (6.031 MBytes/s) figure steadily decrease, or does it remain constant?

Post a log made with -v for more help debugging (redact as necessary).

It does slowly go down. For example:

2017/01/14 17:02:35
Transferred: 108.045 GBytes (1.806 MBytes/s) Errors: 36 Checks: 32325 Transferred: 3637 Elapsed time: 17h1m14.1s

followed by:

2017/01/14 17:04:35 Transferred: 108.045 GBytes (1.802 MBytes/s) Errors: 36 Checks: 32325 Transferred: 3637 Elapsed time: 17h3m14.2s

and steadily decreasing in “speed”.

I am running with -v now. I have done this before and it shows some errors in the beginning, because a few filenames are too long, but by the time it gets to this point of stalling there are no errors. Will upload in a few hours when it stalls.

Files are mostly 5-40MB in size.

Redacted LOG showing common errors related to filename length. no other errors present:

2017/01/14 17:11:50 rclone: Version "v1.35-DEV" starting with parameters ["rclone" "copy" "-v" "--log-file=/home/user/logs/rclone.log" "amazon:/" "crypt:amazon1/"]
2017/01/14 17:11:51 amazon: Saved new token in config file
2017/01/14 17:11:53 Encrypted amazon drive root 'bucket/l9#4': Modify window not supported
2017/01/14 17:11:53 amazon drive root 'bucket/l9f#4': Reading ""
2017/01/14 17:11:53 amazon drive root 'bucket/l9f#4': Finished reading ""

-------

2017/01/14 17:12:53 
Transferred:      0 Bytes (0 Bytes/s)
Errors:                 0
Checks:                 0
Transferred:            0
Elapsed time:     1m20.2s

----

2017/01/14 17:14:26 bucket/#jpg: Sizes identical
2017/01/14 17:14:26 bucket/#: Unchanged skipping
2017/01/14 17:14:27 bucket/#.jpg: Upload error detected but didn't finish upload: HTTP code 400: "400 Bad Request": response body: "{\"logref\":\"c####7\",\"message\":\"1 validation error detected: Value \\u00####a9k8\\u0027 at \\u0027name\\u0027 failed to satisfy constraint: Member must have length less than or equal to 280\",\"code\":\"\"}" ("400 Bad Request")
2017/01/14 17:14:27 pacer: Rate limited, sleeping for 839.692041ms (1 consecutive low level retries)

------

2017/01/14 19:19:53 
Transferred:   11.352 GBytes (1.510 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:   2h8m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 345.899 kBytes/s, ETA: 1m36s

2017/01/14 19:20:53 
Transferred:   11.352 GBytes (1.498 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:   2h9m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 6.325 kBytes/s, ETA: 1h28m7s

2017/01/14 19:21:53 
Transferred:   11.352 GBytes (1.486 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h10m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 118 Bytes/s, ETA: 80h18m18s

2017/01/14 19:22:53 
Transferred:   11.352 GBytes (1.475 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h11m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 2 Bytes/s, ETA: 4391h0m44s

2017/01/14 19:23:53 
Transferred:   11.352 GBytes (1.464 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h12m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 240096h49m36s

2017/01/14 19:24:53 
Transferred:   11.352 GBytes (1.453 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h13m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s

2017/01/14 19:25:53 
Transferred:   11.352 GBytes (1.442 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h14m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 470384h36m55.66277376s

2017/01/14 19:26:53 
Transferred:   11.352 GBytes (1.432 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h15m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 514929h24m49.83462144s

2017/01/14 19:27:53 
Transferred:   11.352 GBytes (1.421 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h16m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s

2017/01/14 19:28:53 
Transferred:   11.352 GBytes (1.411 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h17m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s

2017/01/14 19:29:53 
Transferred:   11.352 GBytes (1.400 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h18m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s

2017/01/14 19:30:53 
Transferred:   11.352 GBytes (1.390 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h19m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s

2017/01/14 19:31:53 
Transferred:   11.352 GBytes (1.381 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h20m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s

2017/01/14 19:32:53 
Transferred:   11.352 GBytes (1.371 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h21m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s

2017/01/14 19:33:53 
Transferred:   11.352 GBytes (1.361 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h22m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s

2017/01/14 19:34:53 
Transferred:   11.352 GBytes (1.352 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h23m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s

2017/01/14 19:35:53 
Transferred:   11.352 GBytes (1.342 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h24m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s

2017/01/14 19:36:53 
Transferred:   11.352 GBytes (1.333 MBytes/s)
Errors:                27
Checks:             28722
Transferred:          483
Elapsed time:  2h25m20.3s
Transferring:
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 18% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s
 * ...##########################################: 13% done, 0 Bytes/s, ETA: 0s

Thanks for making those logs - that does look odd…

Just trying to figure out if it is using two acds that is the problem…

Are you setting client_id or client_secret in either of those acd remotes? I just noticed a bit of code which would likely cause trouble if you were.

Can you see if you can copy one of those files to your local disk with rclone, and then upload it to the crypt with rclone in two steps?

The two amazon remotes - are they different accounts?

Thanks for getting back to me.

They are two different amazon accounts. I have not specified any client_id or client_secret.

some more logs from a check and a copy from the unencypted acd and then to the encrypted acd. this is based on a directory that had a ‘stuck’ file in the log i posted above.

what you can see is that rclone has already copied all those files, apparently on a subsequent run.

rclone check --log-file=/logs/rclone_check.log amazon:'bucket/Downloads/##long_directory_name###/' 'crypt:amazon1/bucket/Downloads/##long_directory_name###/'
2017/01/16 07:03:13 amazon drive root 'bucket/Downloads/###long_directory_name###': Building file list
2017/01/16 07:03:13 Encrypted amazon drive root 'bucket/###hash1###/###hash2###/###hash3###/###hash4###/###hash5(long)###': Building file list
2017/01/16 07:03:14 Encrypted amazon drive root 'bucket/###hash1###/###hash2###/###hash3###/###hash4###/###hash5(long)###': 0 files not in amazon drive root 'bucket/Downloads/###long_directory_name###'
2017/01/16 07:03:14 amazon drive root 'bucket/Downloads/###long_directory_name###': 0 files not in Encrypted amazon drive root 'bucket/###hash1###/###hash2###/###hash3###/###hash4###/###hash5(long)###'
2017/01/16 07:03:14 Encrypted amazon drive root 'bucket/###hash1###/###hash2###/###hash3###/###hash4###/###hash5(long)###': Waiting for checks to finish
2017/01/16 07:03:14 Encrypted amazon drive root 'bucket/###hash1###/###hash2###/###hash3###/###hash4###/###hash5(long)###': 0 differences found
2017/01/16 07:03:14 Encrypted amazon drive root 'bucket/###hash1###/###hash2###/###hash3###/###hash4###/###hash5(long)###': 15 hashes could not be checked

2017/01/16 06:54:47 rclone: Version "v1.35-DEV" starting with parameters ["rclone" "copy" "-v" "--log-file=/rclone_copy1.log" "amazon:bucket/Downloads/###long_directory_name###/" "./###long_directory_name###/"]
2017/01/16 06:54:49 amazon drive root 'bucket/Downloads/###long_directory_name###': Modify window not supported
2017/01/16 06:54:49 amazon drive root 'bucket/Downloads/###long_directory_name###': Reading ""
2017/01/16 06:54:49 amazon drive root 'bucket/Downloads/###long_directory_name###': Finished reading ""
2017/01/16 06:54:56 015 filename.jpg: Copied (new)
2017/01/16 06:55:02 007 filename.jpg: Copied (new)
2017/01/16 06:55:04 013 filename.jpg: Copied (new)
2017/01/16 06:55:05 005 filename.jpg: Copied (new)
2017/01/16 06:55:11 001 Welcome.jpg: Copied (new)
2017/01/16 06:55:49 
Transferred:   101.699 MBytes (1.463 MBytes/s)
Errors:                 0
Checks:                 0
Transferred:            5
Elapsed time:      1m9.5s
Transferring:
 *        006 filename.jpg: 22% done, 91.202 kBytes/s, ETA: 3m14s
 *      009 filename.jpg: 22% done, 105.846 kBytes/s, ETA: 2m45s
 *   004 filename.jpg: 23% done, 182.382 kBytes/s, ETA: 1m30s
 * ...filename.jpg: 22% done, 34.681 kBytes/s, ETA: 8m17s

2017/01/16 06:55:51 004 filename.jpg: Copied (new)
2017/01/16 06:55:54 012 filename.jpg: Removing partially written file on error: unexpected EOF
2017/01/16 06:55:54 012 filename.jpg: Received error: unexpected EOF - low level retry 1/10
2017/01/16 06:56:05 009 filename.jpg: Copied (new)
2017/01/16 06:56:05 Local file system at /home/seedbox/###long_directory_name###: Waiting for checks to finish
2017/01/16 06:56:05 Local file system at /home/seedbox/###long_directory_name###: Waiting for transfers to finish
2017/01/16 06:56:13 012 filename.jpg: Copied (new)
2017/01/16 06:56:15 006 filename.jpg: Removing partially written file on error: unexpected EOF
2017/01/16 06:56:15 006 filename.jpg: Received error: unexpected EOF - low level retry 1/10
2017/01/16 06:56:17 014 filename.jpg: Copied (new)
2017/01/16 06:56:24 006 filename.jpg: Copied (new)
2017/01/16 06:56:24 011 filename.jpg: Copied (new)
2017/01/16 06:56:25 002 filename.jpg: Copied (new)
2017/01/16 06:56:37 003 filename.jpg: Copied (new)
2017/01/16 06:56:39 010 filename.jpg: Copied (new)
2017/01/16 06:56:49 
Transferred:   284.163 MBytes (2.194 MBytes/s)
Errors:                 0
Checks:                 0
Transferred:           14
Elapsed time:      2m9.5s
Transferring:
 *  008 filename.jpg: 22% done, 74.389 kBytes/s, ETA: 3m55s

2017/01/16 06:56:53 008 filename.jpg: Copied (new)
2017/01/16 06:56:53 
Transferred:   301.285 MBytes (2.254 MBytes/s)
Errors:                 0
Checks:                 0
Transferred:           15
Elapsed time:     2m13.6s
2017/01/16 06:56:53 Go routines at exit 14

rclone copy --log-file=/logs/rclone_copy2.log ./###long_directory_name###/' 'crypt:amazon1/bucket/Downloads/###long_directory_name###/'

2017/01/16 07:04:28 Encrypted amazon drive root 'bucket/###hash1###/###hash2###/###hash3###/###hash4###/###hash5###': Waiting for checks to finish
2017/01/16 07:04:28 Encrypted amazon drive root 'bucket/###hash1###/###hash2###/###hash3###/###hash4###/###hash5###': Waiting for transfers to finish
2017/01/16 07:04:28 
Transferred:      0 Bytes (0 Bytes/s)
Errors:                 0
Checks:                15
Transferred:            0
Elapsed time:        8.5s

I am having the same issue 1.35. I am using copy on a ded server from acd to crypt file in same acd account. Starts off fine but then a file will stall then the 2nd and so on until nothing is being moved in any thread 0b/s.

Update: It appears I have 1 active thread that continues to move through files but the other 3 threads have been dead for a few hours now.

i can confirm the same issue doing exactly the same as smfnut all threads have frozen i don’t even have the one lonely thread still chugging along

if i alt+c the command and run it again it will scan the files and add ones it missed but with a large amount of files it can be tough to know if its still moving

yeah, i have a script that kills the process and restarts after three hours.

would you be able to share how you did this im kinda new and still learning linux

#!/bin/bash
export RCLONE_CONFIG_PASS=yourconfigpasswordifyouseone
while true; do
    timeout -k 4h 3h rclone copy amazon:/ crypt:amazon1/
done

thank you so much green this is an answer to a very annoying issue

OK so in summary it seems to be a problem copying from acd to acd - it doesn’t matter whether it is the same account or a different account and the symptom is all the upload goroutines stall.

THere is an issue about this which I think is the same problem: https://github.com/ncw/rclone/issues/902

I’ll see if I can replicate - if not I’ll need your help!

Actually to be more precise all the reports have been from acd to crypted acd.

I think I’ve worked out what is happening here. I managed to reproduce it once, and it gave me enough of a clue.

Can you try this beta please and let me know how you get on:

http://beta.rclone.org/v1.35-41-g2abfae2/ (uploaded in 15-30 mins)

Thanks

Nick

been running for 2 hours and it is still going strong. thanks for sorting this out!

1 Like

Thanks for testing. I was about 95% certain the beta would fix it - it is really good to have confirmation.

Testing this now as well. Cross fingers

1 Like

Can confirm it works as expected. Now, for those pesky long filenames… https://github.com/ncw/rclone/issues/637

1 Like

Outstanding. Works like a charm!