Dropbox remote-to-remote move: Error message, but actually worked

Suspected Bug
1

What is the problem you are having with rclone?

When attempting to move a large directory (i.e., containing thousands of files each in half a dozen subdirs) from remote to remote using the Dropbox backend, rclone attempts to use remote directory move, reports that it failed ("error"), and then goes through all the low-level and high-level retries, all of which result in follow-up errors (too_many_write_operations, from_lookup/not_found/..). In fact, however, the move operation actually succeeds: The directory gets moved as specified, but the result only becomes visible in the Dropbox web gui with delays of up to tens of minutes.

From the dump of responses (pasted below), it seems that the response to the initial "POST /2/files/move_v2" request is "504 Gateway Timeout", and rclone considers that an error and proceeds to retry the request, which leads to follow-up errors. In fact, however, it seems that executing the original move request merely takes very long (> 5 minutes), but eventually succeeds.

Is there a way to handle this issue, e.g. by waiting longer or re-checking the result of the initial move request asynchronously rather than re-sending the move request? Should a gateway timeout actually be considered an error?

What is your rclone version (output from rclone version)

v1.50.2

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)

Dropbox

The command you were trying to run (eg rclone copy /tmp remote:tmp)

rclone moveto my_dbx:dir1/mydir my_dbx:dir2/mydir -vvv --dump responses --progress --contimeout=15m --low-level-retries 30

The rclone config contents with secrets removed.

[my_dbx]
type = dropbox
token = {"access_token":"REDACTED","token_type":"bearer","expiry":"0001-01-01T00:00:00Z"}

A log from the command with the -vv flag

See https://pastebin.com/00pWaG6q (sorry for the progress printouts...)

2

hello and welcome to the forum,

  • you are using an old version of rclone, so can you update to v1.52.2 and test again.

  • have you done this?
    https://rclone.org/dropbox/#get-your-own-dropbox-app-id

  • 504 Gateway Timeout implies there is a problem with a server, not with rclone
    "HTTP status codes beginning with the digit “ 5 ” are server-side errors. They pop up whenever it’s impossible to complete a request due to a miscommunication between several servers."

  • there are two kind of errors

    1. minor errors such as intermittent internet connectivity or with upstream servers, which rclone will retry
    2. major errors that cause rclone to exit with a exit code.

  • if the all the files got moved, then where is the bug?

3

Hello,

  • I used the rclone web gui to create a dropbox config (it asked me to log in), so I would assume that I got the necessary app id. From the command line, I can list remote directories just fine. Doesn't this imply that I have the credentials that I need?

  • The bug is that rclone reports a ton of errors and falsely claims that the operation failed!

  • 5xx status code may be server-side issues, but what I'm trying to say is that rclone doesn't handle this one in a suitable way.

4

Following up: It seems the rclone web gui did not create an app id; I'll try that

5

can you please post a snippet from the log file. thanks

however, you wrote that:
"In fact, however, the move operation actually succeeds"
i can understand that perhaps the phraseology of the log might be confusing.
so you seem to be making a feature request, not reporting a bug.

6

For the full log file, please see here (a bit too verbose, I aoplogize, but all error messages are in there, including two dozen messages from rclone that say that the move operation failed (those messages also get printed without the -v flag):

As to whether this is a feature request or a bug: I'd say that an inaccurate error message is a bug, not a missing feature, but I'm open to negotiations :slight_smile: -- in the end, the user needs to know if an operation succeeded or not; further processing in a script might depend on this information, etc. I was only able to verify what actually happened by using the Dropbox web interface.

7

you are using an old version of rclone,did you update rclone and test again?

rclone, as with most/all apps, will produce an exit code.
https://rclone.org/docs/#exit-code

8

I'm well aware of that. Don't you think that the output I pasted looks entirely like the operation went wrong?

9

i think we are going around in circles with lots of fuzzy words.

  • bugs
  • errors
  • wrong

with rclone, lots of operations go wrong or generate recoverable errors, the smartness of rclone is reporting such a recoverable error and working around it.

i am not much of a log hunter.
what operation went wrong?

10

Here's a less verbose output from an equivalent attempt (the exact followup errors are sometimes different, see original post). Note the exit code, 3. The directory mydir actually got moved from dir1/ to dir2/ on Dropbox. So what actually happened and what rclone reports is clearly at odds.

For this attempt I was using a freshly generated app key.

$ rclone moveto my_dbx:dir1/mydir my_dbx:dir2/mydir -vv
2020/07/11 17:02:31 DEBUG : rclone: Version "v1.50.2" starting with parameters ["rclone" "moveto" "my_dbx:dir1/mydir" "my_dbx:dir2/mydir" "-vv"]
2020/07/11 17:02:31 DEBUG : Using config file from "/home/myuser/.config/rclone/rclone.conf"
2020/07/11 17:02:32 DEBUG : Dropbox root 'dir2/mydir': Using server side directory move
2020/07/11 17:03:32 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Errors:                 0
Checks:                 0 / 0, -
Transferred:            0 / 0, -
Elapsed time:          0s

2020/07/11 17:04:02 DEBUG : pacer: low level retry 1/10 (error )
2020/07/11 17:04:02 DEBUG : pacer: Rate limited, increasing sleep to 20ms
2020/07/11 17:04:02 DEBUG : pacer: Reducing sleep to 15ms
2020/07/11 17:04:02 ERROR : Dropbox root 'dir2/mydir': Server side directory move failed: MoveDir failed: from_lookup/not_found/...
2020/07/11 17:04:02 ERROR : Attempt 1/3 failed with 2 errors and: MoveDir failed: from_lookup/not_found/...
2020/07/11 17:04:02 DEBUG : Dropbox root 'dir2/mydir': Using server side directory move
2020/07/11 17:04:02 DEBUG : pacer: Reducing sleep to 11.25ms
2020/07/11 17:04:02 INFO  : Dropbox root 'dir2/mydir': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2020/07/11 17:04:03 DEBUG : pacer: Reducing sleep to 10ms
2020/07/11 17:04:03 ERROR : : error reading source directory: directory not found
2020/07/11 17:04:03 INFO  : Dropbox root 'dir2/mydir': Waiting for checks to finish
2020/07/11 17:04:03 INFO  : Dropbox root 'dir2/mydir': Waiting for transfers to finish
2020/07/11 17:04:03 ERROR : Attempt 2/3 failed with 2 errors and: directory not found
2020/07/11 17:04:03 DEBUG : Dropbox root 'dir2/mydir': Using server side directory move
2020/07/11 17:04:03 INFO  : Dropbox root 'dir2/mydir': Server side directory move failed - fallback to file moves: can't copy directory - destination already exists
2020/07/11 17:04:06 ERROR : : error reading source directory: directory not found
2020/07/11 17:04:06 INFO  : Dropbox root 'dir2/mydir': Waiting for checks to finish
2020/07/11 17:04:06 INFO  : Dropbox root 'dir2/mydir': Waiting for transfers to finish
2020/07/11 17:04:06 ERROR : Attempt 3/3 failed with 2 errors and: directory not found
2020/07/11 17:04:06 Failed to moveto with 2 errors: last error was: directory not found
$ echo $?
3
11

since you are not renaming a folder but moving it, perhaps try rclone move

there is a difference in behavior between `rclone moveto' and ''rclone move'
notice "can't copy directory - destination already exists"

12

I tried with rclone move, it is the exact same issue. As I wrote before, "destination already exists" is clearly a follow-up error from the fact that the initial move command actually succeeded.

13

sorry, destination already exists, that really is nothing but a notice in the log.
so please just ignore that.

if the source dir does not exist, rclone cannot move it thus error
"ERROR : : error reading source directory: directory not found"

14

Again, "error reading source directory" is a follow-up error: The initial move actually was carried out on the first attempt, so upon retry, the source dir is gone and exists already at the desination.

I apologize, I can't spend more time on this right now. I think I have documented this issue quite extensively. Please take a look at the more detailed pastebin log file I linked to in the original post, it shows the sequence of HTTP API requests and respective responses: The initial move api call receives a "gateway timeout" response, and that is interpreted as a failed operation. In fact, this seems to be Dropbox's way of saying that the command took long. I suspect the success of the move command would have to be checked asynchronously.

15

no worries, since you are calling this a bug with rclone, all the rclone experts will go thru that log.

16

Looks like a timeout waiting for Dropbox to respond to something as taking that long for a server side move seems odd.

Can you:

Update to the latest version.
Try adjusting the timeout to something bigger.

     --contimeout duration                  Connect timeout (default 1m0s)

The logs look like it timed out after a minute and failed, which is why you get an error.

17

I tried that, see command line in my original post: connection timeout was set to 15 minutes there. This did not affect the time it took from the initial move request and the “gateway timeout” response.

Should I file a bug report on the rclone github page?

18

Can you update version, please post a fresh debug log with the full log and as the first post, I can't tell what's been updated or not as it doesn't seem to be.

19

OK, I updated to the latest version and re-ran with increased connection timeout. Exact same result: Initial move request receives gateway timeout response, then all the retries fail with consecutive errors. Return value was 1 this time. Folder actually gets moved on Dropbox, with several minutes of delay.
Log: https://pastebin.com/WMJpWBgB

20

You need to increase the retries as that's why it gets the error as it doesn't timeout, but 10 errors:

2020/07/12 17:21:33 DEBUG : pacer: low level retry 10/10 (error too_many_write_operations/..)

So then the error pops up.