SFTP fails to sync to local "Failed to copy: file does not exist"

Help and Support
1

When I try to sync files from a remote SFTP onto my local file system, receive the following error: "Failed to copy: file does not exist"

I am running rclone version:

rclone v1.53.3
os/arch: linux/amd64
go version: go1.15.5

The config file I'm using is

type = sftp
host = {host}
user = {user}
port = {port}
pass = *** ENCRYPTED ***
use_insecure_cipher = false
md5sum_command = none
sha1sum_command = none

The command I am running is:

rclone sync --log-level DEBUG {sftp}: /home/lucas/test/

The log output for the previous command is:

2021/01/18 11:36:06 DEBUG : rclone: Version "v1.53.3" starting with parameters ["rclone" "sync" "--log-level" "DEBUG" "{sftp}:" "/home/lucas/test/"]
2021/01/18 11:36:06 DEBUG : Using config file from "/home/lucas/.config/rclone/rclone.conf"
2021/01/18 11:36:06 DEBUG : Creating backend with remote "{sftp}:"
2021/01/18 11:36:07 DEBUG : sftp://{username}@{host}:{remote_port}/: New connection {local_ip}:51526->{remote_ip}:{remote_port} to "SSH-2.0-Maverick_SSHD"
2021/01/18 11:36:08 DEBUG : sftp://{username}@{host}:{remote_port}/: Using absolute root directory "/{username}"
2021/01/18 11:36:08 DEBUG : Creating backend with remote "/home/lucas/test/"
2021/01/18 11:36:14 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 1/10: file does not exist
2021/01/18 11:36:14 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 2/10: file does not exist
2021/01/18 11:36:14 DEBUG : sftp://{username}@{host}:{remote_port}/: New connection {local_ip}:51528->{remote_ip}:{remote_port} to "SSH-2.0-Maverick_SSHD"
2021/01/18 11:36:14 DEBUG : sftp://{username}@{host}:{remote_port}/: New connection {local_ip}:51530->{remote_ip}:{remote_port} to "SSH-2.0-Maverick_SSHD"
2021/01/18 11:36:14 DEBUG : sftp://{username}@{host}:{remote_port}/: New connection {local_ip}:51532->{remote_ip}:{remote_port} to "SSH-2.0-Maverick_SSHD"
2021/01/18 11:36:14 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 3/10: file does not exist
2021/01/18 11:36:14 DEBUG : sftp://{username}@{host}:{remote_port}/: New connection {local_ip}:51534->{remote_ip}:{remote_port} to "SSH-2.0-Maverick_SSHD"
2021/01/18 11:36:14 DEBUG : sftp://{username}@{host}:{remote_port}/: New connection {local_ip}:51536->{remote_ip}:{remote_port} to "SSH-2.0-Maverick_SSHD"
2021/01/18 11:36:15 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 4/10: file does not exist
2021/01/18 11:36:15 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 5/10: file does not exist
2021/01/18 11:36:15 DEBUG : {file_name}.13474.20210111140917.dat.gz: Reopening on read failure after 0 bytes: retry 1/10: file does not exist
2021/01/18 11:36:15 DEBUG : {file_name}.13475.20210111150942.dat.gz: Reopening on read failure after 0 bytes: retry 1/10: file does not exist
2021/01/18 11:36:15 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 6/10: file does not exist
2021/01/18 11:36:15 DEBUG : {file_name}.13476.20210111160907.dat.gz: Reopening on read failure after 0 bytes: retry 1/10: file does not exist
2021/01/18 11:36:16 DEBUG : {file_name}.13474.20210111140917.dat.gz: Reopening on read failure after 0 bytes: retry 2/10: file does not exist
2021/01/18 11:36:16 DEBUG : {file_name}.13475.20210111150942.dat.gz: Reopening on read failure after 0 bytes: retry 2/10: file does not exist
2021/01/18 11:36:16 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 7/10: file does not exist
2021/01/18 11:36:16 DEBUG : Local file system at /home/lucas/test/: Waiting for checks to finish
2021/01/18 11:36:16 DEBUG : Local file system at /home/lucas/test/: Waiting for transfers to finish
2021/01/18 11:36:16 DEBUG : {file_name}.13476.20210111160907.dat.gz: Reopening on read failure after 0 bytes: retry 2/10: file does not exist
2021/01/18 11:36:16 DEBUG : {file_name}.13474.20210111140917.dat.gz: Reopening on read failure after 0 bytes: retry 3/10: file does not exist
2021/01/18 11:36:16 DEBUG : {file_name}.13475.20210111150942.dat.gz: Reopening on read failure after 0 bytes: retry 3/10: file does not exist
2021/01/18 11:36:16 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 8/10: file does not exist
2021/01/18 11:36:16 DEBUG : {file_name}.13476.20210111160907.dat.gz: Reopening on read failure after 0 bytes: retry 3/10: file does not exist
2021/01/18 11:36:16 DEBUG : {file_name}.13474.20210111140917.dat.gz: Reopening on read failure after 0 bytes: retry 4/10: file does not exist
2021/01/18 11:36:17 DEBUG : {file_name}.13475.20210111150942.dat.gz: Reopening on read failure after 0 bytes: retry 4/10: file does not exist
2021/01/18 11:36:17 DEBUG : {file_name}.13476.20210111160907.dat.gz: Reopening on read failure after 0 bytes: retry 4/10: file does not exist
2021/01/18 11:36:17 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 9/10: file does not exist
2021/01/18 11:36:17 DEBUG : {file_name}.13474.20210111140917.dat.gz: Reopening on read failure after 0 bytes: retry 5/10: file does not exist
2021/01/18 11:36:17 DEBUG : {file_name}.13475.20210111150942.dat.gz: Reopening on read failure after 0 bytes: retry 5/10: file does not exist
2021/01/18 11:36:17 DEBUG : {file_name}.13476.20210111160907.dat.gz: Reopening on read failure after 0 bytes: retry 5/10: file does not exist
2021/01/18 11:36:17 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 10/10: file does not exist
2021/01/18 11:36:17 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopen failed after 0 bytes read: failed to reopen: too many retries
2021/01/18 11:36:17 NOTICE: {file_name}.13473.20210111130757.dat.gz: Removing partially written file on error: file does not exist
2021/01/18 11:36:17 ERROR : {file_name}.13473.20210111130757.dat.gz: Failed to copy: file does not exist

This is a business partner's SFTP server so I'm not in control of it. I've tried using rclone with my personal SFTP server and it works great. I thought maybe they were using symlinks or something weird. So, I used sftp and ran ls -la and this is a sample result of that command:

-rwxrwxrwx 1 200      100         11475244 Jan 11 13:23 {file_name}.13473.20210111130757.dat.gz
-rwxrwxrwx 1 200      100         11823902 Jan 11 14:25 {file_name}.13474.20210111140917.dat.gz
-rwxrwxrwx 1 200      100          8540623 Jan 11 15:32 {file_name}.13475.20210111150942.dat.gz
-rwxrwxrwx 1 200      100         11629623 Jan 11 16:23 {file_name}.13476.20210111160907.dat.gz
-rwxrwxrwx 1 200      100          5162007 Jan 11 17:30 {file_name}.13477.20210111170939.dat.gz
-rwxrwxrwx 1 200      100          3036849 Jan 11 18:19 {file_name}.13478.20210111180643.dat.gz
-rwxrwxrwx 1 200      100          2683385 Jan 11 19:19 {file_name}.13479.20210111190653.dat.gz
-rwxrwxrwx 1 200      100          2612970 Jan 11 20:22 {file_name}.13480.20210111200843.dat.gz
-rwxrwxrwx 1 200      100         19310324 Jan 11 21:26 {file_name}.13481.20210111211146.dat.gz
-rwxrwxrwx 1 200      100         25187913 Jan 11 22:24 {file_name}.13482.20210111220902.dat.gz
-rwxrwxrwx 1 200      100          9904635 Jan 11 23:49 {file_name}.13483.20210111230848.dat.gz

It definitely seems like there's something about the remote SFTP server that doesn't play nice with rclone. I'm hoping, though, that there's some sort of options that can get me around it. Any help anyone can provide will be much appreciated!

3

It would be worth having a try with the latest beta to see if that fixes it - there have been quite a few sftp fixes since 1.53

4

I tried again with the latest linux build:

rclone v1.54.0-beta.5063.80e63af47
- os/arch: linux/amd64
- go version: go1.15.6

With the same command:

rclone sync --log-level DEBUG tmobile-sftp: /home/lucas/test

And it ran with similar output:

2021/01/19 09:05:29 DEBUG : rclone: Version "v1.54.0-beta.5063.80e63af47" starting with parameters ["rclone" "sync" "--log-level" "DEBUG" "{sftp}:" "/home/lucas/test"]
2021/01/19 09:05:29 DEBUG : Using config file from "/home/lucas/.config/rclone/rclone.conf"
2021/01/19 09:05:29 DEBUG : Creating backend with remote "{sftp}:"
2021/01/19 09:05:31 DEBUG : sftp://{user_name}@{host}:{remote_port}/: New connection {local_ip}:54850->2{remote_ip}:{remote_port} to "SSH-2.0-Maverick_SSHD"
2021/01/19 09:05:32 DEBUG : sftp://{user_name}@{host}:{remote_port}/: Using absolute root directory "/{user_name}"
2021/01/19 09:05:32 DEBUG : Creating backend with remote "/home/lucas/test"
2021/01/19 09:05:37 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 1/10: file does not exist
2021/01/19 09:05:37 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 2/10: file does not exist
2021/01/19 09:05:37 DEBUG : sftp://{user_name}@{host}:{remote_port}/: New connection {local_ip}:54854->2{remote_ip}:{remote_port} to "SSH-2.0-Maverick_SSHD"
2021/01/19 09:05:37 DEBUG : sftp://{user_name}@{host}:{remote_port}/: New connection {local_ip}:54852->2{remote_ip}:{remote_port} to "SSH-2.0-Maverick_SSHD"
2021/01/19 09:05:37 DEBUG : sftp://{user_name}@{host}:{remote_port}/: New connection {local_ip}:54856->2{remote_ip}:{remote_port} to "SSH-2.0-Maverick_SSHD"
2021/01/19 09:05:37 DEBUG : sftp://{user_name}@{host}:{remote_port}/: New connection {local_ip}:54858->2{remote_ip}:{remote_port} to "SSH-2.0-Maverick_SSHD"
2021/01/19 09:05:38 DEBUG : sftp://{user_name}@{host}:{remote_port}/: New connection {local_ip}:54860->2{remote_ip}:{remote_port} to "SSH-2.0-Maverick_SSHD"
2021/01/19 09:05:38 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 3/10: file does not exist
2021/01/19 09:05:38 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 4/10: file does not exist
2021/01/19 09:05:39 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 5/10: file does not exist
2021/01/19 09:05:39 DEBUG : Local file system at /home/lucas/test: Waiting for checks to finish
2021/01/19 09:05:39 DEBUG : Local file system at /home/lucas/test: Waiting for transfers to finish
2021/01/19 09:05:39 DEBUG : {file_name}.13475.20210111150942.dat.gz: Reopening on read failure after 0 bytes: retry 1/10: file does not exist
2021/01/19 09:05:39 DEBUG : {file_name}.13474.20210111140917.dat.gz: Reopening on read failure after 0 bytes: retry 1/10: file does not exist
2021/01/19 09:05:39 DEBUG : {file_name}.13476.20210111160907.dat.gz: Reopening on read failure after 0 bytes: retry 1/10: file does not exist
2021/01/19 09:05:39 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 6/10: file does not exist
2021/01/19 09:05:40 DEBUG : {file_name}.13476.20210111160907.dat.gz: Reopening on read failure after 0 bytes: retry 2/10: file does not exist
2021/01/19 09:05:40 DEBUG : {file_name}.13474.20210111140917.dat.gz: Reopening on read failure after 0 bytes: retry 2/10: file does not exist
2021/01/19 09:05:40 DEBUG : {file_name}.13475.20210111150942.dat.gz: Reopening on read failure after 0 bytes: retry 2/10: file does not exist
2021/01/19 09:05:40 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 7/10: file does not exist
2021/01/19 09:05:40 DEBUG : {file_name}.13476.20210111160907.dat.gz: Reopening on read failure after 0 bytes: retry 3/10: file does not exist
2021/01/19 09:05:40 DEBUG : {file_name}.13474.20210111140917.dat.gz: Reopening on read failure after 0 bytes: retry 3/10: file does not exist
2021/01/19 09:05:40 DEBUG : {file_name}.13475.20210111150942.dat.gz: Reopening on read failure after 0 bytes: retry 3/10: file does not exist
2021/01/19 09:05:40 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 8/10: file does not exist
2021/01/19 09:05:41 DEBUG : {file_name}.13476.20210111160907.dat.gz: Reopening on read failure after 0 bytes: retry 4/10: file does not exist
2021/01/19 09:05:41 DEBUG : {file_name}.13475.20210111150942.dat.gz: Reopening on read failure after 0 bytes: retry 4/10: file does not exist
2021/01/19 09:05:41 DEBUG : {file_name}.13474.20210111140917.dat.gz: Reopening on read failure after 0 bytes: retry 4/10: file does not exist
2021/01/19 09:05:41 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 9/10: file does not exist
2021/01/19 09:05:41 DEBUG : {file_name}.13476.20210111160907.dat.gz: Reopening on read failure after 0 bytes: retry 5/10: file does not exist
2021/01/19 09:05:41 DEBUG : {file_name}.13475.20210111150942.dat.gz: Reopening on read failure after 0 bytes: retry 5/10: file does not exist
2021/01/19 09:05:41 DEBUG : {file_name}.13474.20210111140917.dat.gz: Reopening on read failure after 0 bytes: retry 5/10: file does not exist
2021/01/19 09:05:42 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopening on read failure after 0 bytes: retry 10/10: file does not exist
2021/01/19 09:05:42 DEBUG : {file_name}.13473.20210111130757.dat.gz: Reopen failed after 0 bytes read: failed to reopen: too many retries
2021/01/19 09:05:42 NOTICE: {file_name}.13473.20210111130757.dat.gz: Removing partially written file on error: file does not exist
2021/01/19 09:05:42 ERROR : {file_name}.13473.20210111130757.dat.gz: Failed to copy: file does not exist

I noticed that my beta version is a couple versions behind but there are no linux builds for them yet. So, I may try build from them from source.

5

Is this the right directory on the server? If not, try using an absolute path so sftp:/path/to/dir

6

Yes, /{user_name} that should be the correct directory. When I log in with an SFTP client, all the files I need are under /{user_name}. But, I am concerned that that's the path and makes me wonder how directories are actually setup on the server. Is it possible that when rclone determines it needs to download specific file that the path to the file that rclone generates is somehow different than the actual path on the server?

7

That is what I was wondering. It shouldn't be like that though.

I did a bit of research on this and found these issues

Is this a read once SFTP server? As in once you read the file it gets deleted?

8

@ncw, thank you for looking into this issue. It appears your suspicion is correct. The SFTP is a read once server. So, after rclone reads the file to get it's attributes, the server deletes it, and rclone gets the above error when it tries to download it.

I appreciate your time. Feel free to close this ticket out.

9

Would you mind testing this?

If you could try the --sftp-use-fstat flag with that then that might be a fix according to the issues. It might not...

v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once on branch fix-sftp-read-once (uploaded in 15-30 mins)

Are you interested in working with me to find a fix if that doesn't work?

10

I would love to help out. However, I'm hesitant to try it out since the files get deleted on the server. We've already lost some data and I need to be careful so that we don't lose anymore.

11

Sure, I understand.

I wonder if you (or I) could get access to a test account?

12

I think i'm having the same problem and luckily I am experiencing it on a test account.

Similar setup - originally the remote config was set to 1 download and then delete (read once).

As a test, the counterparty graciously set it up with 6 downloads before deletion. I was able to do 5 and the on the 6th try recreated the issue above with the same error

I actually have a few versions or rclone I tried:
1.47.0 - "The message [filename] is not extractable!" (SSH_FX_FAILURE)
1.53.1 - "Reopening on read failure after 0 bytes: retry 10/10: file does not exist"

Note, to be careful, I'm using copyto so I only operate on 1 test file at a time.

I wasn't able to figure out how to install the beta release to test the suggested flag --sftp-use-fstat.
Currently running this on an ubuntu 16.04 box. Happy to try to install beta if you don't mind giving dummy proof instructions.

13

@ncw, that beta page is missing some executables, no linux versions...

hello and welcome to the forum,

if you already have rclone installed and a config file,
then download the beta to your computer and run it.
but i think that the linux versions files are missing for now.

you can get the beta here, just select your hardware specs.
https://beta.rclone.org/branch/fix-sftp-read-once/v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once/

14

@asdffdsa yeah i thought i was just blind or in the wrong spot...

15

So this should have allowed 6 downloads but you only managed 5. That seems pretty close to the original issue - we should be able to download it 6 times.

It looks like the CI had a bobble... I've restarted the build and hopefully in 15 - 30 mins there will be linux binaries here: https://beta.rclone.org/branch/fix-sftp-read-once/v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once/

If you download the linux-amd64 zip file, extract the zip file (unzip blah.zip) then you will see a directory with the rclone binary in. You can just run it from there - cd to the extracted directory then run the rclone binary with ./rclone .....

Something like this...

$ wget https://beta.rclone.org/branch/fix-sftp-read-once/v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once/rclone-v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once-linux-amd64.zip
[snip]
2021-01-25 11:01:48 (3.68 MB/s) - ‘rclone-v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once-linux-amd64.zip’ saved [12680756/12680756]
$ unzip rclone-v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once-linux-amd64.zip
Archive:  rclone-v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once-linux-amd64.zip
   creating: rclone-v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once-linux-amd64/
  inflating: rclone-v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once-linux-amd64/rclone.1  
  inflating: rclone-v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once-linux-amd64/README.html  
  inflating: rclone-v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once-linux-amd64/git-log.txt  
  inflating: rclone-v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once-linux-amd64/README.txt  
  inflating: rclone-v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once-linux-amd64/rclone  
$ cd rclone-v1.54.0-beta.5087.505a37bbe.fix-sftp-read-once-linux-amd64/
$ ./rclone version
16

copyto fails with --sftp-use-fstat
Reopening on read failure after 0 bytes: retry 1/10: sftp: "The message [] is not extractable!" (SSH_FX_FAILURE)

and eventually:
Failed to copy: sftp: "The message [] is not extractable!" (SSH_FX_FAILURE)

17

Did you get 5 downloads or 6 before the failure?

18

No, this is on the file that has 1 download left on it. I would need to ask them to reset. But they said that the 6 downloads isn't something they plan to allow in the other sftp. This was just for testing purposes.

19

Ah OK. So this didn't fix the problem :frowning:

I will merge that flag anyway because it was an option unexposed from the library/

We really need to fix these issues in the library

20

ok - any thoughts on other things to try on the read-once sftp sites?

21

I added some thoughts onto the issue - that is where it needs fixing.