caduceus
(Anthony)
April 30, 2019, 5:08pm
1
I connected a remote SFTP source, which I am able to ls
just fine. But when I try to sync or copy, I receive an error as rclone attempts to transfer each file. I'm running on OSX, and I believe the remote server is running on a Windows system win win_scp..
I am getting error like this:
rclone sync aiep:./ ~/home/Download/PEIA_CCP
2019/04/30 12:13:27 NOTICE: aaaaa_valley_hhhhhh_ccp/CCP_Valley_hhhhhh_190429.csv: Removing partially written file on error: sftp: "Folder not found: c:\ftpsites\aiep\valley_hhhhhh\CCP_Valley_hhhhhh_190429.csv" (SSH_FX_FAILURE)
2019/04/30 12:13:27 ERROR : rclone sync aiep:./ ~/home/Download/PEIA_CCP
2019/04/30 12:13:27 NOTICE: aaaaaaa_valley_hhhhhh_ccp/CCP_Valley_hhhhhh_190429.csv: Removing partially written file on error: sftp: "Folder not found: c:\ftpsites\aiep\valley_hhhhhh\CCP_Valley_hhhhhh_190429.csv" (SSH_FX_FAILURE)
2019/04/30 12:13:27 ERROR : aaaaaaa_valley_hhhhhh_ccp/CCP_Valley_hhhhhh_190429.csv: Failed to copy: sftp: "Folder not found: c:\ftpsites\aiep\valley_health\CCP_Valley_hhhhhh_190429.csv" (SSH_FX_FAILURE)
debug with -vv
rclone copy aiep:./ ~/home/Download/aiep_CCP -vv
2019/04/30 13:00:00 DEBUG : rclone: Version "v1.47.0" starting with parameters ["rclone" "copy" "aiep:./" "/Users/auser/home/Download/aiep_CCP" "-vv"]
2019/04/30 13:00:00 DEBUG : Using config file from "/Users/auser/.config/rclone/rclone.conf"
2019/04/30 13:00:03 DEBUG : aaaaaaa_iiiiicreek_ccp/CCP_iiiii_Creek_190429.csv: Sizes differ (src 1466472 vs dst 0)
2019/04/30 13:00:04 DEBUG : aaaaaaa_iiiiicreek_ccp/CCP_iiiii_Creek_190429.csv: Reopening on read failure after 0 bytes: retry 1/10: sftp: "Folder not found: c:\ftpsites\aiep\iiiiicreek\CCP_iiiii_Creek_190429.csv" (SSH_FX_FAILURE)
2019/04/30 13:00:05 DEBUG : aaaaaaa_iiiiicreek_ccp/CCP_iiiii_Creek_190429.csv: Reopening on read failure after 0 bytes: retry 2/10: sftp: "Folder not found: c:\ftpsites\aiep\iiiiicreek\CCP_iiiii_Creek_190429.csv" (SSH_FX_FAILURE)
2019/04/30 13:00:05 DEBUG : aaaaaaa_new_vvvvv_ccp/CCP_Newvvvvv_190429.csv: Modification times differ by 20h36m52.571731647s: 2019-04-29 15:36:37 -0400 EDT, 2019-04-30 12:13:29.571731647 -0400 EDT
2019/04/30 13:00:06 DEBUG : aaaaaaa_iiiiicreek_ccp/CCP_iiiii_Creek_190429.csv: Reopening on read failure after 0 bytes: retry 3/10: sftp: "Folder not found: c:\ftpsites\aiep\iiiiicreek\CCP_iiiii_Creek_190429.csv" (SSH_FX_FAILURE)
2019/04/30 13:00:06 DEBUG : aaaaaaa_mva_hhhhhh_ccp/CCP_MVA_190429.csv: Reopening on read failure after 0 bytes: retry 1/10: sftp: "Folder not found: c:\ftpsites\aiep\mva_hhhhhh_ccp\CCP_MVA_190429.csv" (SSH_FX_FAILURE)
2019/04/30 13:00:06 DEBUG : aaaaaaa_new_vvvvv_ccp/CCP_Newvvvvv_190429.csv: Reopening on read failure after 0 bytes: retry 1/10: sftp: "Folder not found: c:\ftpsites\aiep\new_vvvvv_ccp_program\CCP_Newvvvvv_190429.csv" (SSH_FX_FAILURE)
2019/04/30 13:00:06 DEBUG : aaaaaaa_iiiiicreek_ccp/CCP_iiiii_Creek_190429.csv: Reopening on read failure after 0 bytes: retry 4/10: sftp: "Folder not found: c:\ftpsites\aiep\iiiiicreek\CCP_iiiii_Creek_190429.csv" (SSH_FX_FAILURE)
2019/04/30 13:00:06 DEBUG : aaaaaaa_clay_bbbbbbbb_ccp/CCP_aaaaaaa_CLAYBATT_190429.CSV: Sizes differ (src 82474 vs dst 0)
2019/04/30 13:00:06 DEBUG : aaaaaaa_mva_hhhhhh_ccp/CCP_MVA_190429.csv: Reopening on read failure after 0 bytes: retry 2/10: sftp: "Folder not found: c:\ftpsites\aiep\mva_hhhhhh_ccp\CCP_MVA_190429.csv" (SSH_FX_FAILURE)
2019/04/30 13:00:06 INFO : Local file system at /Users/auser/home/Download/aiep_CCP: Waiting for checks to finish
2019/04/30 13:00:06 INFO : Local file system at /Users/auser/home/Download/aiep_CCP: Waiting for transfers to finish
rclone version shows what?
if you run the same command with -vv on it, can you share those results?
caduceus
(Anthony)
April 30, 2019, 5:18pm
3
rclone version
rclone v1.47.0
os/arch: darwin/amd64
go version: go1.12.4
I added the debug option info to the original post.
What does your rclone.conf look like for that? I just did a test on my Mac to a Linux host with SFTP and copied a few files over.
caduceus
(Anthony)
April 30, 2019, 6:16pm
5
Hi Animostiy022,
It looks like this:
[aiep]
type = sftp
host = ftp.thehost.com
user = User.name
port = 22
pass = {password}
use_insecure_cipher = true
disable_hashcheck = false
I had previously not had disable_hashcheck , but it did the same thing.
I have a pretty similar config:
[SFTP]
type = sftp
host = home.thehost.us
user = felix
port = 4022
pass = password
use_insecure_cipher = true
Can you do a ls on a single file that you know is there like:
rclone ls -vv aiep: aaaaaaa_iiiiicreek_ccp/CCP_iiiii_Creek_190429.csv
I think that is the path from reading the logs, but not quite sure.
And if you test via a scp command on the same host/path, can you share that too?
I just did a test file copy:
scp felix@home:hosts .
hosts
caduceus
(Anthony)
April 30, 2019, 7:10pm
7
I can access the sftp server just fine from the command line on my mac and in other sftp clients… here are the results of the -vv on ls:
rclone ls -vv aiep:aaaaaa_valley_hhhhh_ccp/CCP_Valley_hhhhh_190429.csv
2019/04/30 15:02:18 DEBUG : rclone: Version “v1.47.0” starting with parameters [“rclone” “ls” “-vv” “aiep:aaaaaaa_valley_hhhhh_ccp/CCP_Valley_hhhhh_190429.csv”]
2019/04/30 15:02:18 DEBUG : Using config file from “/Users/auser/.config/rclone/rclone.conf”
2368268 CCP_Valley_hhhhh_190429.csv
2019/04/30 15:02:19 DEBUG : 12 go routines active
2019/04/30 15:02:19 DEBUG : rclone: Version “v1.47.0” finishing with parameters [“rclone” “ls” “-vv” “aiep:aaaaaa_valley_hhhhh_ccp/CCP_Valley_hhhhh_190429.csv”]
caduceus
(Anthony)
April 30, 2019, 7:15pm
8
What was weird for me were these paths:
sftp: “Folder not found: c:\ftpsites\aiep\mva_hhhhhh_ccp\CCP_MVA_190429.csv”
I don’t know where the c:\ftpsites came from…
So when you run that you get those errors?
What does rclone ls aiep: -vv do?
ncw
(Nick Craig-Wood)
May 1, 2019, 9:23am
10
That is a strange error… It makes me wonder if rclone is mis-identifying files as directories…
That didn’t print the file did it? So it looks like rclone tried to list it as a directory.
Are these files (on the server) maybe symlinks (or junction points) on windows - that might explain what is going on.
Which server is it?
caduceus
(Anthony)
May 1, 2019, 1:43pm
11
Animosity022:
rclone ls aiep: -vv
rclone ls aiep: -vv
2019/05/01 09:38:58 DEBUG : rclone: Version “v1.47.0” starting with parameters [“rclone” “ls” “aiep:” “-vv”]
2019/05/01 09:38:58 DEBUG : Using config file from “/Users/anthonyvollmer/.config/rclone/rclone.conf”
2368268 aaaaaaa_valley_hhhhhh_ccp/CCP_Valley_hhhhhh_190429.csv
0 aaaaaaa_mva_hhhhhh_ccp/CCP_MVA_190429.csv
204078 aaaaaaa_rainelle_ccp/CCP_aaaaaaa_RAINELLE_190429.CSV
1466472 aaaaaaa_iiiiicreek_ccp/CCP_iiiii_Creek_190429.csv
0 aaaaaaa_new_rrrrr_ccp/CCP_Newrrrrr_190429.csv
82474 aaaaaaa_clay_battelle_ccp/CCP_aaaaaaa_CLAYBATT_190429.CSV
0 aaaaaaa_st_george_ccp/CCP_aaaaaaa_STGEORGE_190429.CSV
2019/05/01 09:39:01 DEBUG : 75 go routines active
2019/05/01 09:39:01 DEBUG : rclone: Version “v1.47.0” finishing with parameters [“rclone” “ls” “aiep:” “-vv”]
caduceus
(Anthony)
May 1, 2019, 1:44pm
12
No it did not print the file. I pasted the entire output.
I don’t know if the files are symlinks on Windows, looking at the error it was my first thought, having looked through other error reports and posts in forums, etc.
The server is an associate company where I get files waiting for me to process. I believe the server is Win_SCP as I had once tried to ssh to it instead of SFTP and it gave an error , WinSCP: this is end-of-file:0 when I pressed enter. I have no issues when connecting via SFTP.
ncw
(Nick Craig-Wood)
May 1, 2019, 7:55pm
13
caduceus:
rclone ls aiep: -vv
Could you repeat that with lsf -R
instead so rclone lsf -R aiep: -vv
and post the output? That will tell us whether rclone things they are files or directories.
caduceus:
I don’t know if the files are symlinks on Windows, looking at the error it was my first thought, having looked through other error reports and posts in forums, etc.
I don’t know if a different SFTP client might tell you.
Ah OK!
caduceus
(Anthony)
May 1, 2019, 11:15pm
14
rclone lsf -R aiep: -vv
2019/05/01 19:13:52 DEBUG : rclone: Version “v1.47.0” starting with parameters [“rclone” “lsf” “-R” “aiep:” “-vv”]
2019/05/01 19:13:52 DEBUG : Using config file from “/Users/auser/.config/rclone/rclone.conf”
aaaaaaa/
aaaaaaa_ccccccreek_ccp/
aaaaaaa_clay_battelle_ccp/
aaaaaaa_mva_hhhhhh_ccp/
aaaaaaa_new_rrrrr_ccp/
aaaaaaa_rainelle_ccp/
aaaaaaa_st_george_ccp/
aaaaaaa_valley_hhhhhh_ccp/
aaaaaaa_valley_hhhhhh_ccp/CCP_Valley_hhhhhh_190429.csv
aaaaaaa_mva_hhhhhh_ccp/CCP_MVA_190429.csv
aaaaaaa_st_george_ccp/CCP_aaaaaaa_STGEORGE_190429.CSV
aaaaaaa_rainelle_ccp/CCP_aaaaaaa_RAINELLE_190429.CSV
aaaaaaa_clay_battelle_ccp/CCP_aaaaaaa_CLAYBATT_190429.CSV
aaaaaaa_new_rrrrr_ccp/CCP_Newrrrrr_190429.csv
aaaaaaa_ccccccreek_ccp/CCP_ccccc_Creek_190429.csv
2019/05/01 19:13:57 DEBUG : 75 go routines active
2019/05/01 19:13:57 DEBUG : rclone: Version “v1.47.0” finishing with parameters [“rclone” “lsf” “-R” “aiep:” “-vv”]
caduceus
(Anthony)
May 1, 2019, 11:25pm
15
I did a debug on sftp from command line:
OpenSSH_7.9p1, LibreSSL 2.7.3
debug1: Local version string SSH-2.0-OpenSSH_7.9
debug1: Remote protocol version 2.0, remote software version WS_FTP-SSH_7.5.1
debug1: no match: WS_FTP-SSH_7.5.1
debug3: fd 5 is O_NONBLOCK
debug2: compression ctos: none,zlib@openssh.com ,zlib
debug2: compression stoc: none,zlib@openssh.com ,zlib
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug2: peer server KEXINIT proposal
debug2: KEX algorithms: diffie-hellman-group1-sha1,diffie-hellman-group14-sha1
debug2: host key algorithms: ssh-dss,ssh-rsa
debug2: ciphers ctos: 3des-cbc,blowfish-cbc,aes256-cbc,aes128-cbc,cast128-cbc
debug2: ciphers stoc: 3des-cbc,blowfish-cbc,aes256-cbc,aes128-cbc,cast128-cbc
debug2: MACs ctos: hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96
debug2: MACs stoc: hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96
debug2: compression ctos: none
debug2: compression stoc: none
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug1: kex: algorithm: diffie-hellman-group14-sha1
debug1: kex: host key algorithm: ssh-rsa
ncw
(Nick Craig-Wood)
May 2, 2019, 8:07am
16
caduceus:
rclone lsf -R aiep: -vv
That looks sensible…
After tracing through the code, I think what is happening is when the sftp library attempts to read from the file it gets the error sftp: “Folder not found: c:\ftpsites\aiep\iiiiicreek\CCP_iiiii_Creek_190429.csv” (SSH_FX_FAILURE)
From the listings, rclone thinks it is a file, but when the upstream library reads it things it is a folder, or the server thinks it is a folder.
Could you try doing this from a command line sftp client on the “aiep_CCP” directory? I used the one that comes with ubuntu
$ sftp sftptest@localhost
Connected to sftptest@localhost.
sftp> ls -l
lrwxrwxrwx 1 root root 13 Jan 28 17:08 dangling_link
-rw-r--r-- 1 sftptest sftptest 6 Dec 30 16:13 hello[brackends].txt
drwxrwxr-x 7 sftptest sftptest 4096 Nov 28 09:58 restic
drwxr-xr-x 2 sftptest sftptest 4096 Dec 30 16:13 subdir
drwxr-xr-x 3 sftptest sftptest 4096 Dec 30 16:51 test
That should show exactly what type of thing the sftp server thinks things are.
Is there any chance I could get access to the sftp server? I’m guessing not, but if it is OK then please DM me!
caduceus
(Anthony)
May 2, 2019, 11:38am
17
I didn’t see the aiep_CCP directory you were refering to, to I did an ls -l from the home/root where I login to and also inside the aaaaaaa_iiiiiicreek_ccp directory… I really appreciate all the help looking into this. Unfortunately, the server isn’t mine.
sftp> ls -l
drwx—r-x 2 ftpadmin ftpadmin 0 Apr 27 04:00 aaaaaaa
drwx—r-x 2 ftpadmin ftpadmin 0 Apr 29 11:14 aaaaaaa_iiiiicreek_ccp
drwx—r-x 2 ftpadmin ftpadmin 0 Apr 29 11:14 aaaaaaa_clay_battelle_ccp
drwx—r-x 2 ftpadmin ftpadmin 0 Apr 29 11:14 aaaaaaa_mva_hhhhhh_ccp
drwx—r-x 2 ftpadmin ftpadmin 0 Apr 29 11:14 aaaaaaa_new_rrrrr_ccp
drwx—r-x 2 ftpadmin ftpadmin 0 Apr 29 11:14 aaaaaaa_rainelle_ccp
drwx—r-x 2 ftpadmin ftpadmin 0 Apr 29 11:14 aaaaaaa_st_george_ccp
drwx—r-x 2 ftpadmin ftpadmin 0 Apr 29 11:14 aaaaaaa_valley_hhhhhh_ccp
sftp>
sftp> ls -l
-rwxr-xrwx 1 ftpadmin ftpadmin 1466472 Apr 29 11:14 CCP_iiiii_Creek_190429.csv
sftp>
ncw
(Nick Craig-Wood)
May 2, 2019, 3:19pm
18
Thanks for that, unfortunately those look normal!
I’ve compiled a version of the sftp library with debugging. This will print lots of hex numbers!
https://beta.rclone.org/branch/v1.47.0-032-g5c0574ea-fix-sftp-folder-beta/ (uploaded in 15-30 mins)
Can you find the minimum thing which prints the “Folder not found” error.
Something like this might do it
rclone copyto --low-level-retries 1 --retries 1 -vv aiep:aaaaaa_valley_hhhhh_ccp/CCP_Valley_hhhhh_190429.csv /tmp/z.csv
Then paste the debug stream!
Once we’ve got that I’ll probably ask for help upstream.
caduceus
(Anthony)
May 2, 2019, 5:02pm
19
./rclone copyto --low-level-retries 1 --retries 1 -vv aiep:aaaaaaa_valley_hhhhh_ccp/CCP_Valley_hhhhh_190429.csv ~/Downloads/z.csv
2019/05/02 13:00:24 DEBUG : rclone: Version “v1.47.0-032-g5c0574ea-fix-sftp-folder-beta” starting with parameters ["./rclone" “copyto” “–low-level-retries” “1” “–retries” “1” “-vv” “aiep:aaaaaaa_valley_hhhhh_ccp/CCP_Valley_hhhhh_190429.csv” “/Users/auser/Downloads/z.csv”]
2019/05/02 13:00:24 DEBUG : Using config file from “/Users/auser/.config/rclone/rclone.conf”
2019/05/02 13:00:24 send packet: SSH_FXP_INIT 5 bytes 00000003
2019/05/02 13:00:24 recv packet: SSH_FXP_VERSION 5 bytes 00000003
2019/05/02 13:00:24 send packet: SSH_FXP_STAT 63 bytes 0000000100000036616c65646164655f76616c6c65795f6865616c74685f6363702f4343505f56616c6c65795f4865616c74685f3139303432392e637376
2019/05/02 13:00:24 recv packet: SSH_FXP_ATTRS 29 bytes 000000010000003d000000000024230c000081ef5cc6dc835cc6dc83
2019/05/02 13:00:24 send packet: SSH_FXP_STAT 63 bytes 0000000200000036616c65646164655f76616c6c65795f6865616c74685f6363702f4343505f56616c6c65795f4865616c74685f3139303432392e637376
2019/05/02 13:00:24 recv packet: SSH_FXP_ATTRS 29 bytes 000000020000003d000000000024230c000081ef5cc6dc835cc6dc83
2019/05/02 13:00:24 DEBUG : CCP_Valley_hhhhh_190429.csv: Couldn’t find file - need to transfer
2019/05/02 13:00:25 send packet: SSH_FXP_OPEN 71 bytes 0000000300000036616c65646164655f76616c6c65795f6865616c74685f6363702f4343505f56616c6c65795f4865616c74685f3139303432392e6373760000000100000000
2019/05/02 13:00:25 recv packet: SSH_FXP_HANDLE 12 bytes 0000000300000003323535
2019/05/02 13:00:25 send packet: SSH_FXP_FSTAT 12 bytes 0000000400000003323535
2019/05/02 13:00:25 recv packet: SSH_FXP_STATUS 94 bytes 00000004000000040000004d466f6c646572206e6f7420666f756e643a20633a5c66747073697465735c706569615c76616c6c65795f6865616c74685c4343505f56616c6c65795f4865616c74685f3139303432392e63737600000000
2019/05/02 13:00:25 send packet: SSH_FXP_CLOSE 12 bytes 0000000500000003323535
2019/05/02 13:00:25 recv packet: SSH_FXP_STATUS 17 bytes 00000005000000000000000000000000
2019/05/02 13:00:25 DEBUG : CCP_Valley_hhhhh_190429.csv: Reopening on read failure after 0 bytes: retry 1/1: sftp: “Folder not found: c:\ftpsites\aiep\valley_hhhhh\CCP_Valley_hhhhh_190429.csv” (SSH_FX_FAILURE)
2019/05/02 13:00:25 DEBUG : CCP_Valley_hhhhh_190429.csv: Reopen failed after 0 bytes read: failed to reopen: too many retries
2019/05/02 13:00:25 NOTICE: z.csv: Removing partially written file on error: sftp: “Folder not found: c:\ftpsites\aiep\valley_hhhhh\CCP_Valley_hhhhh_190429.csv” (SSH_FX_FAILURE)
2019/05/02 13:00:25 ERROR : CCP_Valley_hhhhh_190429.csv: Failed to copy: sftp: “Folder not found: c:\ftpsites\aiep\valley_hhhhh\CCP_Valley_hhhhh_190429.csv” (SSH_FX_FAILURE)
2019/05/02 13:00:25 ERROR : Attempt 1/1 failed with 2 errors and: sftp: “Folder not found: c:\ftpsites\aiep\valley_hhhhh\CCP_Valley_hhhhh_190429.csv” (SSH_FX_FAILURE)
2019/05/02 13:00:25 Failed to copyto: sftp: “Folder not found: c:\ftpsites\aiep\valley_hhhhh\CCP_Valley_hhhhh_190429.csv” (SSH_FX_FAILURE)
ncw
(Nick Craig-Wood)
May 7, 2019, 9:58am
20
Thank you for that - that is very helpful.
I opened an upstream issue to ask the SFTP experts exactly what it means!
1 Like