ncw
June 27, 2020, 12:02pm
10
Thanks! Those are useful logs.
This shows that rclone can find the current directory and the two directories within it IN and OUT.
andyklier:
2020/06/26 08:28:21 DEBUG : Dir Stat result for "." is &sftp.fileInfo{name:".", size:0, mode:0x800001e8, mtime:time.Time{wall:0x0, ext:63728709547, loc:(*time.Location)(0x2a053a0)}, sys:(*sftp.FileStat)(0xc00003a280)}, <nil>
-1 2020-06-08 23:47:31 -1 IN
-1 2020-06-08 23:47:39 -1 OUT
However this shows that the server can't return a stat result for the IN directory and the OUT directory.
andyklier:
2020/06/26 08:31:47 DEBUG : Dir Stat result for "." is &sftp.fileInfo{name:".", size:0, mode:0x800001e8, mtime:time.Time{wall:0x0, ext:63728709547, loc:(*time.Location)(0x2a053a0)}, sys:(*sftp.FileStat)(0xc00003b4c0)}, <nil>
2020/06/26 08:31:47 DEBUG : Dir Stat result for "OUT" is <nil>, &sftp.StatusError{Code:0x4, msg:"Folder not found: OUT", lang:""}
2020/06/26 08:31:47 ERROR : OUT: error listing: List failed: dirExists stat failed: sftp: "Folder not found: OUT" (SSH_FX_FAILURE)
2020/06/26 08:31:48 DEBUG : sftp://user@example.com:22/: New connection 1.2.3.4:36224->4.5.6.7:22 to "SSH-2.0-WS_FTP-SSH_7.6.2"
2020/06/26 08:31:48 DEBUG : Dir Stat result for "IN" is <nil>, &errors.errorString{s:"file does not exist"}
2020/06/26 08:31:48 ERROR : IN: error listing: directory not found
Which is very strange!
A bit of searching lead me to this very similar problem
opened 09:57AM - 07 May 19 UTC
closed 02:58AM - 23 May 19 UTC
[An rclone user has reported](https://forum.rclone.org/t/failed-to-copy-sftp-fol… der-not-found-c-ftpsites-ssh-fx-failure/9778) that rclone with a certain sftp server reports the error `"Folder not found: c:\xxx\yyy.csv" (SSH_FX_FAILURE)`. As far as I can work out this is being generated by the `Read()` call on an open file, though looking at the trace below it seems to come from `Fstat` on the open file - not sure what is calling that.
The user reports that other sftp clients work just fine.
I turned on debugging and sent the user a binary to try.
Here is rclone logs interleaved with sftp debugs
```
./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
```
Rclone has identified the file as needing to transfer
```
2019/05/02 13:00:24 DEBUG : CCP_Valley_hhhhh_190429.csv: Couldn’t find file - need to transfer
```
Now we open it
```
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
```
However the SSH_FXP_FSTAT returned an error. I don't know why! Rclone doesn't directly call `Stat()` on the handle returned - I'm not sure where that gets called.
```
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)
```
I attempted to decode the sftp debug using the RFC but it wasn't making sense, so I'm asking for help here.
Thanks in advance!
So apparently I diagnosed and fixed this very similar problem in the upstream library already!
I checked and rclone is using the patched library. However the problem is very similar...
OK here is a trial fix which probably won't work, but you never know! I tried prefixing the direcotyr paths with ./.
https://beta.rclone.org/branch/v1.52.2-137-g43c4109a-fix-sftp-wsftp-beta/ (uploaded in 15-30 mins)
Is there any way I could get access to the server? I'm guessing not, but if it would it would speed up this process! Email nick@craig-wood.com or PM me if you want to discuss further.