Rclone can't create new folder on sftp mount

HiFiPhile · September 16, 2020, 8:06am

What is the problem you are having with rclone?

Rclone Windows can't create new folder in mounted sftp drive.
Seems like Dir.Mkdir not correctly executed.

With --vfs-cache-mode=off, directory can be created sometimes.

Maybe directory creation is conflicted with my short poll interval.

On failed cases Mkdir command is not logged on remote side SFTPGo

What is your rclone version (output from `rclone version`)

1.52 and 1.53, Winfsp 2020.1

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Windows 10 x64 2004

Which cloud storage system are you using? (eg Google Drive)

SFTPGo

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

Click 'new folder' in explorer, or md in cmd.

The rclone config contents with secrets removed.

[drive]
type = sftp
host = xxxx.com
user = ftp
port = xxxx
use_insecure_cipher = false
md5sum_command = md5sum
sha1sum_command = sha1sum
key_file = C:\Tool\xxxx.pem

rclone.exe mount drive: O: -vv --vfs-cache-mode minimal --file-perms 0777 --allow-other --poll-interval=10s --dir-cache-time=30s --config C:\Users\xxx\.config\rclone\rclone.conf

A log from the command with the `-vv` flag

2020/09/16 09:37:55 DEBUG : /data: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/09/16 09:37:55 DEBUG : /data: >Getattr: errc=0
2020/09/16 09:37:55 DEBUG : /data: Opendir:
2020/09/16 09:37:55 DEBUG : /data: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/09/16 09:37:55 DEBUG : /data: >OpenFile: fd=data/ (r), err=<nil>
2020/09/16 09:37:55 DEBUG : /data: >Opendir: errc=0, fh=0x5
2020/09/16 09:37:55 DEBUG : /data: Releasedir: fh=0x5
2020/09/16 09:37:55 DEBUG : /data: >Releasedir: errc=0
2020/09/16 09:37:55 DEBUG : /data/New folder: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/09/16 09:37:55 DEBUG : /data/New folder: >Getattr: errc=-2
2020/09/16 09:37:55 DEBUG : /data: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/09/16 09:37:55 DEBUG : /data: >Getattr: errc=0
2020/09/16 09:37:55 DEBUG : /data: Opendir:
2020/09/16 09:37:55 DEBUG : /data: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2020/09/16 09:37:55 DEBUG : /data: >OpenFile: fd=data/ (r), err=<nil>
2020/09/16 09:37:55 DEBUG : /data: >Opendir: errc=0, fh=0x5
2020/09/16 09:37:55 DEBUG : /data: Releasedir: fh=0x5
2020/09/16 09:37:55 DEBUG : /data: >Releasedir: errc=0
2020/09/16 09:37:55 DEBUG : /data: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/09/16 09:37:55 DEBUG : /data: >Getattr: errc=0
2020/09/16 09:37:55 DEBUG : /data/New folder: Mkdir: mode=0700
2020/09/16 09:37:55 ERROR : data/: Dir.Mkdir failed to create directory: mkdir dirExists failed: dirExists stat failed: sftp: "no such file or directory" (SSH_FX_FAILURE)
2020/09/16 09:37:55 ERROR : IO error: mkdir dirExists failed: dirExists stat failed: sftp: "no such file or directory" (SSH_FX_FAILURE)
2020/09/16 09:37:55 DEBUG : /data/New folder: >Mkdir: errc=-5

On remote side, Mkdir is not logged in failed cases:

{"level":"debug","time":"2020-09-16T09:43:17.325","sender":"SFTP","connection_id":"SFTP_15e8e11df40a22e6d2c5aaed693ebc53b4e9f667a00318f07d9fc0558852ad3f","message":"error running stat on path \"/data/New folder\": stat /data/New folder: no such file or directory"}

On successed cases:

{"level":"debug","time":"2020-09-16T09:43:17.332","sender":"SFTP","connection_id":"SFTP_15e8e11df40a22e6d2c5aaed693ebc53b4e9f667a00318f07d9fc0558852ad3f","message":"new cmd, method: Mkdir, sourcePath: \"/data/New folder\", targetPath: \"\""}
{"level":"info","time":"2020-09-16T09:43:17.353","sender":"Mkdir","username":"ftp","file_path":"/data/New folder","target_path":"","filemode":"","uid":-1,"gid":-1,"access_time":"","modification_time":"","size":-1,"ssh_command":"","connection_id":"SFTP_15e8e11df40a22e6d2c5aaed693ebc53b4e9f667a00318f07d9fc0558852ad3f","protocol":"SFTP"}

ncw · September 16, 2020, 1:56pm

Can you see if you can replicate this not using the mount? So using rclone mkdir?

HiFiPhile · September 16, 2020, 3:08pm

Hi,

With rclone mkdir I can't reproduce this issue. I've tested 20 times with different folder names.

c:\Tool>rclone\rclone.exe mkdir "nas:\data\c b a" -vv --config C:\Users\xxx\.config\rclone\rclone.conf
2020/09/16 17:03:02 DEBUG : rclone: Version "v1.53.1" starting with parameters ["rclone\\rclone.exe" "mkdir" "nas:\\data\\c b a" "-vv" "--config" "C:\\Users\\xxx\\.config\\rclone\\rclone.conf"]
2020/09/16 17:03:02 DEBUG : Creating backend with remote "nas:\\data\\c b a"
2020/09/16 17:03:02 DEBUG : Using config file from "C:\\Users\\xxx\\.config\\rclone\\rclone.conf"
2020/09/16 17:03:02 DEBUG : sftp://ftp@xxx.com:1234//data/c b a: New connection [ip]:51494->[ip]:1234 to "SSH-2.0-SFTPGo_1.0.0-dev"
2020/09/16 17:03:02 DEBUG : fs cache: renaming cache item "nas:\\data\\c b a" to be canonical "nas:/data/c b a"
2020/09/16 17:03:02 DEBUG : sftp://ftp@xxx.com:1234//data/c b a: Making directory
2020/09/16 17:03:02 DEBUG : 12 go routines active

ncw · September 16, 2020, 10:44pm

Could you try using "rclone serve sftp" as your sftp server and see if it has the same problem?

HiFiPhile · September 17, 2020, 9:42am

With rclone serve sftp I can't reproduce this issue. So it could be something wrong on SFTPGo side or compatibility issue between SFTPGo and Rclone.

I'll discuss with SFTPGo author and update this thread.

ncw · September 17, 2020, 9:53am

I had a little investigation in to what the error message is actually telling us...

The source of the error message is here

github.com

rclone/rclone/blob/61fe068c9067b361435b6e88bc69aae94d73dbc0/backend/sftp/sftp.go#L636-L643


	info, err := c.sftpClient.Stat(dir)
	f.putSftpConnection(&c, err)
	if err != nil {
		if os.IsNotExist(err) {
			return false, nil
		}
		return false, errors.Wrap(err, "dirExists stat failed")
	}

Now that error really looks like it os.IsNotExist(err) should have returned true. However the error code SSH_FX_FAILURE is wrong it should have been SSH_FX_NO_SUCH_FILE for the library to have returned the correct error.

See

github.com

pkg/sftp/blob/c05b4d1c301c80e38602a12a251eae8c2617c32b/client.go#L318-L339


func (c *Client) Stat(p string) (os.FileInfo, error) {
	id := c.nextID()
	typ, data, err := c.sendPacket(sshFxpStatPacket{
		ID:   id,
		Path: p,
	})
	if err != nil {
		return nil, err
	}
	switch typ {
	case sshFxpAttrs:
		sid, data := unmarshalUint32(data)
		if sid != id {
			return nil, &unexpectedIDErr{id, sid}
		}
		attr, _ := unmarshalAttrs(data)
		return fileInfoFromStat(attr, path.Base(p)), nil
	case sshFxpStatus:
		return nil, normaliseError(unmarshalStatus(id, data))
	default:

This file has been truncated. show original

Which calls this to normalize the error code

github.com

pkg/sftp/blob/c05b4d1c301c80e38602a12a251eae8c2617c32b/client.go#L1315-L1327


func normaliseError(err error) error {
	switch err := err.(type) {
	case *StatusError:
		switch err.Code {
		case sshFxEOF:
			return io.EOF
		case sshFxNoSuchFile:
			return os.ErrNotExist
		case sshFxOk:
			return nil
		default:
			return err
		}

So yes, I think this is a bug in SFTPGo and the bug is that it is returning the wrong error code on Stat.

HiFiPhile · September 18, 2020, 9:31am

This issue has been fixed in SFTPGo side in latest commit.

system · September 21, 2020, 9:31am

This topic was automatically closed 3 days after the last reply. New replies are no longer allowed.

Rclone can't create new folder on sftp mount

What is the problem you are having with rclone?

What is your rclone version (output from rclone version)

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Which cloud storage system are you using? (eg Google Drive)

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

The rclone config contents with secrets removed.

A log from the command with the -vv flag

What is your rclone version (output from `rclone version`)

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

A log from the command with the `-vv` flag