100+ percents of copying on last release

You can post a link here or email it to me nick@craig-wood.com with a link to this forum post in.

Ok, thanks, I’ll do

1 Like

Here's a result. Uploaded 15 files (16 at all but 1 of them was uploaded before so only checked). Manually stopped on 127%. All the files was successfully uploaded but Rclone knew nothing about it and continued uploading. Then I checked all the files successfully as well. The log of upload and check here: https://www.dropbox.com/s/y64rj2ogtw2421q/RcloneLog.zip?dl=0

It would be great to have it fixed.


I think these are the problem

2019-11-06 12:55:32 DEBUG : pacer: low level retry 2/10 (error This file is already being processed. Please wait until previous upload operation will be finished. (Error 423)) 
2019-11-06 12:55:32 DEBUG : pacer: Rate limited, increasing sleep to 20ms 
2019-11-06 12:55:44 DEBUG : pacer: Reducing sleep to 10ms 

This means that opendrive rejected the chunk and rclone had to send it again. I had a look in the opendrive API docs and I couldn't see that referenced: https://www.opendrive.com/wp-content/uploads/guides/OpenDrive_API_guide.pdf

In fact looking more closely at the log I see lots of different errors

Received error: failed to create file: File update error. Temp file doesn't exist. Please restart task. (Error 400) - low level retry 1/10 
Received error: failed to create file: Invalid temp file location (Error 400) - low level retry 1/10 
low level retry 1/10 (error Post https://dev.opendrive.com/api/v1/upload/close_file_upload.json: net/http: timeout awaiting response headers) 
low level retry 1/10 (error Unknown 502 Bad Gateway (Error 502)) 
Received error: failed to create file: File update error. Temp file doesn't exist. Please restart task. (Error 400) - low level retry 1/10 
Received error: failed to create file: This file is already being processed. Please wait until previous upload operation will be finished. (Error 423) - low level retry 1/10 
Received error: failed to create file: File update error. Temp file doesn't exist. Please restart task. (Error 400) - low level retry 1/10 
Received error: failed to create file: This file is already being processed. Please wait until previous upload operation will be finished. (Error 423) - low level retry 1/10 
Received error: failed to create file: File update error. Temp file doesn't exist. Please restart task. (Error 400) - low level retry 1/10 
Received error: failed to create file: File update error. Temp file doesn't exist. Please restart task. (Error 400) - low level retry 1/10 
Received error: failed to create file: File update error. Temp file doesn't exist. Please restart task. (Error 400) - low level retry 1/10 
Received error: failed to create file: File update error. Temp file doesn't exist. Please restart task. (Error 400) - low level retry 1/10 
Received error: failed to create file: File update error. Temp file doesn't exist. Please restart task. (Error 400) - low level retry 1/10 
Received error: failed to create file: This file is already being processed. Please wait until previous upload operation will be finished. (Error 423) - low level retry 1/10 
Received error: failed to create file: File update error. Temp file doesn't exist. Please restart task. (Error 400) - low level retry 1/10 
Received error: failed to create file: File update error. Temp file doesn't exist. Please restart task. (Error 400) - low level retry 1/10 
Received error: failed to create file: File update error. Temp file doesn't exist. Please restart task. (Error 400) - low level retry 1/10 

That is why you are seeing uploads > 100%.- rclone is having to retry files.

I think maybe the reason this didn't show for older rclone versions is that it didn't count the retries in the upload traffic.

So you mean the files were not uploaded correctly when I stopped Rclone manually?
But:

  1. when Rclone uploaded 100% opendrive decided they are ok and added them to it's log (as you can see) despite they are still was uploading over 100%;
  2. the same Rclone checks them successfully;
  3. being downloaded they was unzipped with no issues.
    What does it mean? Despite of Rclone messages they was uploaded correctly. So these messages are incorrect (or have no sense). Rclone should stop overuploading and add a next file to a queue.
    Am I correct?

Maybe after 100% uploading but before retrying over and over Rclone should do a check, and if it is ok do not keep on retrying?

That is what the error messages say

I guess what is happening is that opendrive says there is an error but the file is actually OK.

Can you try your transfer with --transfers 1 - maybe opendrive doesn't like multiple uploads at once for some reason.

So the problem is in Opendrive API, isn't it?

I tried, the speed was dramatically low.

I just tried to download some files uploaded yesterday (from a browser just clicking on a link). They was downloaded but couldn't unzip. There was a CRC error.
Could you tell me is Rclone check a guaranty the files are absolutely ok? As I think it calculates some hashes (MD5, CRC?) on source and target, compares them and if they are equal tells ok. Is it correct?
Should I try to download all the files (with Rclone) to check them additionally or it's for nothing?

Updated. Downloaded these files using Rclone and they unzipped ok. So the problem was in simple browser download.
Now I'm downloading another 34G file to test. 10h and 253G at the moment. On target it is 29G now (was 31G 8h ago). Nobody knows when (if) it will be downloaded :frowning:

One question. Why these mad percents? Imagine we're trying to upload (download) a chunk. It's failed with an error. Why you mark it as succeeded and add to total percents? Why just not to ignore it and try to upload next time. In this case there will be no percents more than 100%.

A good question :slight_smile: The accounting in rclone is rather complicated but maybe we could fix it somehow!

Only one issue. Now uploading on 1.50.1 I wait until 100% and despite a file is still uploading over 100% stop it and it's ok. If you fixed these crazy percents how could I realize it's time to stop? Only using a target log.

Rclone should stop when it thinks the file is correctly uploaded.

I realized. But this time might never become but actually the file has been correctly uploaded. In other words Rclone don't know what's going on actually. I's a main issue :frowning:

I tried to download with Rclone the file uploaded 3 days ago 2 times. With no success. 34G file was downloaded on ~10 Mb/s speed about a day each time with many times overdownloading and finally crashed. The file was on target but corrupted. I was tired and thought to stop this monkey business: I uploaded files (with big troubles but did) but couldn't download it.
Finally I installed native OpenDrive app to my Mac and tried to download this file. Downloaded in 1.5 hours on 12 Mb/s speed. And file is ok: md5 is equal to original and uploaded, 7zip found no issues. So the problem is solved. I can download my files. Without Rclone but...
So now I'm tending not to use Rclone anymore with Opendrive. More troubles than help.

This is due to the opendrive API I think - I'm not sure what rclone can do to fix it.

I'm glad your files are OK and sorry for the problems you've been having.

This really needs someone to dig into the Opendrive API a bit more - have you got the time and skills to do that?

I'm having same issue but with Jottacloud.
See the log here https://pastebin.com/JMMsqkF4

I also noticed that the overall transfer size increases as the transfers progress.
I checked the files on Jottacloud and there were 40GB worth of files (log file shows 80GB).
So is rclone really transferring the files twice?

That shows these errors

   2044:2016/04/12 15:48:57 0af2a1536886f6509ce6f5ef680128eb.gpg: Failed to copy: Post https://www.googleapis.com/upload/drive/v2/files?alt=json&uploadType=resumable: http: ContentLength=243 with Body length 0
   2046:2016/04/12 15:49:01 0af2a1536886f6509ce6f5ef680128eb.gpg: Failed to remove failed copy: googleapi: got HTTP response code 404 with body: Not Found
   2753:2016/04/12 16:36:15 b4935791494176f6eddec923b78fcb1b.gpg: Failed to copy: Post https://www.googleapis.com/upload/drive/v2/files?alt=json&uploadType=resumable&upload_id=AEnB2UpptDiY36wBmYSuNqKOGcg16g43WtZtQnBgtA-EVeLYfiasow8E64nJCMxzYddYDH93GioqfVGKLZp85iLTF8AnPpt8AQ: EOF
   2755:2016/04/12 16:36:16 b4935791494176f6eddec923b78fcb1b.gpg: Failed to remove failed copy: googleapi: got HTTP response code 404 with body: Not Found
   3123:2016/04/12 16:58:55 8f56c769288b16b2bab3da9e880bb252.gpg: Failed to copy: Post https://www.googleapis.com/upload/drive/v2/files?alt=json&uploadType=resumable&upload_id=AEnB2UqOCA40gJC0clQxOpH9WRyUvJQkD7jp5YhoZxIsuxzPac7w-I9pemnGJpvXqQiZrDgkpiPrmmGrRzYhWQIDj3Gdxi8Mlw: EOF
   3125:2016/04/12 16:58:56 8f56c769288b16b2bab3da9e880bb252.gpg: Failed to remove failed copy: googleapi: got HTTP response code 404 with body: Not Found

Those looks maybe like interrupted transfers caused by networking propblems. Also they are to google drive - where does jottacloud fit it - is it the source?

Hmm are you viewing the right paste? :slight_smile: Those dates are from 2016. :slight_smile:
And Jottacloud is the destination.

Obviously not :blush:

Looking at the real log I can see quite a few of these errors

2019/12/01 00:16:01 DEBUG : XXX: Received error: Post https://067-up.jotta.cloud/files/v1/upload/XXX: write tcp 192.168.1.12:47120->185.179.128.29:443: use of closed network connection - low level retry 1/10

What happens here is that rclone will retry the file. Looking at the jotta code, assuming the retry is working properly, it will read the file to where it got to and not upload it then it will resume the upload. This will unfortunately count as % transferred

Thanks for checking the log. I was wondering what those were.

Any idea why would it do that - because of my connection or because of Jottacloud?

It could be your local firewall, router, ISP, or jottacloud itself.

It is most likely to be jottacloud I think, but I'm not certain.

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