Stabilizing ACD uploads on metered connections

Help and Support
1

I have a VM on Azure that is used primarily to accept files from a few different processes and upload them to ACD using rclone. It’s working great overall but I’ve seen a couple of issues that are making my bandwidth costs go through the roof.

  1. Uploading files multiple times. The original file is 349 MB but it transferred just over 1 GB.

    2017/03/10 01:24:20 Encrypted amazon drive root ‘r0se4srg8pfi541es0umll0ieo/udg644vig6rvbtrfnfsfkm2qb8/d7pkbual9tdmrf0258uu373g3i41asqrluv4q58g1l4j3i68hmdg/6dr9jboan506ts2uir76nmfis0’: Waiting for checks to finish
    2017/03/10 01:24:20 Encrypted amazon drive root ‘r0se4srg8pfi541es0umll0ieo/udg644vig6rvbtrfnfsfkm2qb8/d7pkbual9tdmrf0258uu373g3i41asqrluv4q58g1l4j3i68hmdg/6dr9jboan506ts2uir76nmfis0’: Waiting for transfers to finish
    2017/03/10 01:25:21
    Transferred: 349.009 MBytes (5.536 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 1m3s
    Transferring:

    • XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX: 100% done, 1.722 MBytes/s, ETA: 0s

    2017/03/10 01:26:22
    Transferred: 349.009 MBytes (2.816 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 2m3.9s
    Transferring:

    • XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX: 100% done, 32.249 kBytes/s, ETA: 0s

    2017/03/10 01:27:23
    Transferred: 538.322 MBytes (2.913 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 3m4.8s
    Transferring:

    • XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX: 53% done, 10.769 MBytes/s, ETA: 14s

    2017/03/10 01:28:24
    Transferred: 699.331 MBytes (2.846 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 4m5.7s
    Transferring:

    • XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX: 100% done, 564.192 kBytes/s, ETA: 0s

    2017/03/10 01:29:25
    Transferred: 699.331 MBytes (2.281 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 5m6.6s
    Transferring:

    • XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX: 100% done, 10.317 kBytes/s, ETA: 0s

    2017/03/10 01:30:25
    Transferred: 1007.956 MBytes (2.742 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 6m7.5s
    Transferring:

    • XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX: 88% done, 6.989 MBytes/s, ETA: 5s

    2017/03/10 01:30:44
    Transferred: 1.024 GBytes (2.716 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 1
    Elapsed time: 6m25.9s

  2. Uploading that goes WAY over 100%. The original file is ~522 MB but transferred over 28 GB (!?!)

    2017/03/08 08:30:11 Encrypted amazon drive root ‘r0se4srg8pfi541es0umll0ieo/pp8mqogu6kbh4ri8l1me82spv8/0dboqkesotd6f235gi1918sank6jfenddbb7l41rhp9gq6dv4bg0’: Waiting for $
    2017/03/08 08:30:11 Encrypted amazon drive root ‘r0se4srg8pfi541es0umll0ieo/pp8mqogu6kbh4ri8l1me82spv8/0dboqkesotd6f235gi1918sank6jfenddbb7l41rhp9gq6dv4bg0’: Waiting for $
    2017/03/08 08:31:11
    Transferred: 449.500 MBytes (7.396 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 1m0.7s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 90% done, 7.147 MBytes/s, ETA: 6s

    2017/03/08 08:32:11
    Transferred: 903.125 MBytes (7.493 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 2m0.5s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 181% done, 8.070 MBytes/s, ETA: 0s

    2017/03/08 08:33:10
    Transferred: 1.320 GBytes (7.496 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 3m0.2s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 271% done, 7.975 MBytes/s, ETA: 0s

    2017/03/08 08:34:10
    Transferred: 1.626 GBytes (6.934 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 4m0s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 333% done, 1.949 MBytes/s, ETA: 0s

    2017/03/08 08:35:10
    Transferred: 1.626 GBytes (5.552 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 4m59.8s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 333% done, 36.492 kBytes/s, ETA: 0s

    2017/03/08 08:36:10
    Transferred: 1.626 GBytes (4.629 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 5m59.5s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 333% done, 683 Bytes/s, ETA: 0s

    2017/03/08 08:37:09
    Transferred: 1.993 GBytes (4.867 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 6m59.3s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 75% done, 7.181 MBytes/s, ETA: 17s

    2017/03/08 08:38:09
    Transferred: 2.406 GBytes (5.143 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 7m59s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 160% done, 6.835 MBytes/s, ETA: 0s

    2017/03/08 08:39:09
    Transferred: 2.840 GBytes (5.397 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 8m58.8s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 249% done, 7.869 MBytes/s, ETA: 0s

    2017/03/08 08:40:09
    Transferred: 3.232 GBytes (5.529 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 9m58.5s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 329% done, 6.999 MBytes/s, ETA: 0s

    2017/03/08 08:41:08
    Transferred: 3.684 GBytes (5.731 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 10m58.3s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 422% done, 8.014 MBytes/s, ETA: 0s

    2017/03/08 08:42:08
    Transferred: 4.103 GBytes (5.851 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 11m58s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 508% done, 7.022 MBytes/s, ETA: 0s

    2017/03/08 08:43:08
    Transferred: 4.535 GBytes (5.970 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 12m57.8s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 597% done, 7.471 MBytes/s, ETA: 0s

    2017/03/08 08:44:08
    Transferred: 4.970 GBytes (6.076 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 13m57.5s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 686% done, 7.064 MBytes/s, ETA: 0s

    2017/03/08 08:45:07
    Transferred: 5.384 GBytes (6.144 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 14m57.3s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 771% done, 6.867 MBytes/s, ETA: 0s

    2017/03/08 08:46:07
    Transferred: 5.819 GBytes (6.226 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 15m57.1s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 861% done, 6.668 MBytes/s, ETA: 0s

    2017/03/08 08:47:07
    Transferred: 6.298 GBytes (6.342 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 16m56.8s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 959% done, 9.670 MBytes/s, ETA: 0s

    2017/03/08 08:48:07
    Transferred: 6.691 GBytes (6.364 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 17m56.6s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 1040% done, 6.229 MBytes/s, ETA: 0s

    2017/03/08 08:49:06
    Transferred: 7.091 GBytes (6.390 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 18m56.4s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 1122% done, 4.627 MBytes/s, ETA: 0s

    2017/03/08 08:50:06
    Transferred: 7.091 GBytes (6.070 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 19m56.2s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 1122% done, 86.647 kBytes/s, ETA: 0s

    2017/03/08 08:51:06
    Transferred: 7.091 GBytes (5.781 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 20m55.9s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 1122% done, 1.584 kBytes/s, ETA: 0s

    . etc…
    .
    2017/03/08 09:41:56
    Transferred: 28.644 GBytes (6.812 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 1h11m45.5s
    Transferring:

    •               XXXXXXXXXXXXXXXXXXXXXXXXXXX: 1059% done, 8.889 MBytes/s, ETA: 0s

    2017/03/08 09:42:55 XXXXXXXXXXXXXXXXXXXXXXXXXXX: corrupted on transfer: sizes differ 522813440 vs 5868571429
    2017/03/08 09:42:55 Attempt 1/3 failed with 1 errors and: corrupted on transfer: sizes differ 522813440 vs 5868571429
    2017/03/08 09:42:55
    Transferred: 28.953 GBytes (6.792 MBytes/s)
    Errors: 0
    Checks: 0
    Transferred: 0
    Elapsed time: 1h12m45.3s

I understand there’s logic in place that retries large files if they don’t appear in ACD within a certain period of time or possibly even if they are corrupt, so I don’t necessarily think this is a bug.

Instead, I’m curious if there’s any recommendations on how to stabilize the transfers or possibly even enforce a sanity check; anything that can stop it from going crazy and eating through my monthly budget in a week.

A few implementation details:
OS - Ubuntu 16.04
Rclone version: Logs from rclone v1.34-71-g4482e75β but similar behavior noticed in the official v1.35 build.

Let me know if any other details would help.

Thanks!

2

Same story here. I don’t know the file size because I’m not logging to file. I’ll start doing that, but it’s 1-8 gb:

2017/03/10 07:11:21 INFO  :
Transferred:   241.161 GBytes (7.930 MBytes/s)
Errors:                 0
Checks:                 0
Transferred:            0
Elapsed time:   8h39m0.9s
Transferring:
 * ...7IBsuMVt24SsvOfgg3QDLUTfN178hUb9KjDbCqtDP7: 100% done, 0 Bytes/s, ETA: 0s

2017/03/10 07:12:21 INFO  :
Transferred:   241.161 GBytes (7.915 MBytes/s)
Errors:                 0
Checks:                 0
Transferred:            0
Elapsed time:   8h40m0.9s
Transferring:
 * ...7IBsuMVt24SsvOfgg3QDLUTfN178hUb9KjDbCqtDP7: 100% done, 0 Bytes/s, ETA: 0s

2017/03/10 07:13:21 INFO  :
Transferred:   241.161 GBytes (7.900 MBytes/s)
Errors:                 0
Checks:                 0
Transferred:            0
Elapsed time:   8h41m0.9s
Transferring:
 * ...7IBsuMVt24SsvOfgg3QDLUTfN178hUb9KjDbCqtDP7: 100% done, 0 Bytes/s, ETA: 0s

2017/03/10 07:14:21 INFO  :
Transferred:   241.161 GBytes (7.884 MBytes/s)
Errors:                 0
Checks:                 0
Transferred:            0
Elapsed time:   8h42m0.9s
Transferring:
 * ...7IBsuMVt24SsvOfgg3QDLUTfN178hUb9KjDbCqtDP7: 100% done, 0 Bytes/s, ETA: 0s

2017/03/10 07:15:21 INFO  :
Transferred:   241.161 GBytes (7.869 MBytes/s)
Errors:                 0
Checks:                 0
Transferred:            0
Elapsed time:   8h43m0.9s
Transferring:
 * ...7IBsuMVt24SsvOfgg3QDLUTfN178hUb9KjDbCqtDP7: 100% done, 0 Bytes/s, ETA: 0s

rclone version:
$ rclone -V
rclone v1.35-163-gc45c604β

3

I guess it could work to try to increase acd-upload-wait-per-gb from the 3 minute default to say 5?

4

I tried using rclone copy with acd-upload-wait-per-gb set to 10m0s and I get some odd restarts of the transfer after having uploaded 20-26% of the file: http://pastebin.com/raw/RenZKdfK

5

Thanks. It looks like your issue is like my first case and increasing the acd-upload-wait-per-gb might help with that. I’ll have to give it a try.

The second case is far more alarming to me. Rclone acts as though it doesn’t know where the end of the file is and copies over 10x the data multiple times.

I’ve upgraded to the latest beta to see if that helps.

6

Looks like the file was only 522M when rclone scanned the directory, but it was 5868M when it came to upload it. Is that possible?

Yes me too! If you are copying over the network from a crypted file system then this is a bug which should be fixed in the latest beta.

7

Thanks for responding.

I’m not above admitting that my code isn’t bug free; I’m sure it’s not. If you think that’s what happened then I’ll investigate the possibility that it’s prematurely handing an uncompleted upload to Rclone to be transferred to ACD. The actual file was only ~522M though so I’m not sure where the extra data would have come from.

I’ve updated to the latest beta so hopefully it’ll address the overrun issue and, if not, hopefully I’ll find that my code is doing something it shouldn’t.

Beyond fixing the potential bugs, are there any settings or possibly external tools that can be used to enforce a sanity check? The first case is lesser and even an expected hazard of working with ACD - I get that - but is there anything that I can do to make the first upload pass more reliable?

8

Some days I think I write more bugs that code :wink:

Tests with the new beta should rule one way or the other

Let me know how it goes.

Not as far as I know.

You can check things have gone OK with rclone check or rclone cryptcheck