Thanks for the log.
I see what is happening now!
What is happening is this…
Rclone notices that the file has the incorrect modification time
2018/03/12 19:04:37 DEBUG : file.jpg: Modification times differ by -91373h52m55.7006214s: 2018-01-25 00:40:19.7006214 -0200 -02, 2007-08-23 20:47:24 +0000 UTC
Rclone figures out it will have to re-upload the file
2018/03/12 19:04:37 DEBUG : file.jpg: src and dst identical but can't set mod time without deleting and re-uploading
So it deletes it in preparation for the re-upload.
However since you have --backup-dir
set, rclone thinks there is an existing file.jpg
which it needs to move into the backup dir.
However trying that move gives this error (since rclone already deleted the file in preparation for the re-upload).
2018/03/12 19:04:42 ERROR : file.jpg: Couldn't move: move failed: from_lookup/not_found/
Rclone then abandons the upload of the file.
How to fix…
I think in an ideal world we’d like rclone to put the incorrectly dated file.jpg
into the --backup-dir
, but at minimum we want rclone to transfer the file straight away and not wait for the retry.
Here is my attempt to replicate the problem. Note I see from this that rclone does transfer the file correctly on the retry so you should be seeing that too.
$ echo "hello" > file.txt
$ rclone -v copy file.txt dropbox:test/test1
2018/03/13 09:37:30 INFO : Dropbox root 'test/test1': Modify window is 1s
2018/03/13 09:37:30 INFO : Dropbox root 'test/test1': Waiting for checks to finish
2018/03/13 09:37:30 INFO : Dropbox root 'test/test1': Waiting for transfers to finish
2018/03/13 09:37:31 INFO : file.txt: Copied (new)
2018/03/13 09:37:31 INFO :
Transferred: 6 Bytes (3 Bytes/s)
Errors: 0
Checks: 0
Transferred: 1
Elapsed time: 1.9s
$ touch file.txt
$ rclone -vv copy file.txt --backup-dir dropbox:test/test2 dropbox:test/test1
2018/03/13 09:38:05 DEBUG : Using config file from "/home/ncw/.rclone.conf"
2018/03/13 09:38:05 DEBUG : rclone: Version "v1.39-233-g383feca6" starting with parameters ["rclone" "-vv" "copy" "file.txt" "--backup-dir" "dropbox:test/test2" "dropbox:test/test1"]
2018/03/13 09:38:06 INFO : Dropbox root 'test/test1': Modify window is 1s
2018/03/13 09:38:07 INFO : Dropbox root 'test/test1': Waiting for checks to finish
2018/03/13 09:38:07 DEBUG : file.txt: Modification times differ by -45.652019585s: 2018-03-13 09:37:38.652019585 +0000 GMT, 2018-03-13 09:36:53 +0000 UTC
2018/03/13 09:38:07 DEBUG : file.txt: src and dst identical but can't set mod time without deleting and re-uploading
2018/03/13 09:38:08 ERROR : file.txt: Couldn't move: move failed: from_lookup/not_found/...
2018/03/13 09:38:08 INFO : Dropbox root 'test/test1': Waiting for transfers to finish
2018/03/13 09:38:08 ERROR : Attempt 1/3 failed with 1 errors and: move failed: from_lookup/not_found/...
2018/03/13 09:38:10 INFO : Dropbox root 'test/test1': Waiting for checks to finish
2018/03/13 09:38:10 INFO : Dropbox root 'test/test1': Waiting for transfers to finish
2018/03/13 09:38:10 INFO : file.txt: Copied (new)
2018/03/13 09:38:10 ERROR : Attempt 2/3 succeeded
2018/03/13 09:38:10 INFO :
Transferred: 6 Bytes (1 Bytes/s)
Errors: 0
Checks: 1
Transferred: 1
Elapsed time: 5s
2018/03/13 09:38:10 DEBUG : 7 go routines active
2018/03/13 09:38:10 DEBUG : rclone: Version "v1.39-233-g383feca6" finishing with parameters ["rclone" "-vv" "copy" "file.txt" "--backup-dir" "dropbox:test/test2" "dropbox:test/test1"]
$ rclone lsl dropbox:test/test1 # file is correct here
6 2018-03-13 09:37:39.000000000 file.txt
$ rclone lsl dropbox:test/test2 # nothing in the backup
2018/03/13 09:38:58 ERROR : : error listing: directory not found
2018/03/13 09:38:58 Failed to lsl: directory not found
$ ls -l --full-time file.txt
-rw-rw-r-- 1 ncw ncw 6 2018-03-13 09:37:38.652019585 +0000 file.txt
I created a new issue #2134 about this - can you subscribe to that issue and I’ll post fixes there.