"No such file or directory" when initially creating new file

[teemupulliainen]

Background: Trying to a) mount resources from two remote SFTP servers and b) provide them for Windows hosts via Samba. The Samba part is likely irrelevant and the following examples are not done via Samba. On one of the SFTP servers everything works OK. On the other I have strange issues when trying to create a new file on an sshfs mount. The remote users seem to be chrooted and I don't have any shell access.

Sshfs versions on Centos 7:
SSHFS version 2.5 FUSE library version: 2.9.2 fusermount version: 2.9.2 using FUSE kernel interface version 7.19
also tried with Fedora 25:
SSHFS version 2.8 FUSE library version: 2.9.7 fusermount version: 2.9.7 using FUSE kernel interface version 7.19

Symptoms:

touch remote/foo
touch: cannot touch 'remote/foo’: No such file or directory

However, 'foo' is created. Now when I try to touch the same file again, no issues. Similarily:

echo bar > remote/foo2
-bash: remote/foo2: No such file or directory

Again, foo2 is created, but is empty. Now if I issue the same command the second time, there's no error and foo2 contains 'bar'. Cp seems to behave in a similar fashion and vim claims that 'swap file already exists' for every new file.

A few things I've tried so far:

• readdir=ino
• cache=no
• workaround=rename (and ...all)

An example mount command is:

echo password | sshfs -o reconnect,ServerAliveInterval=30,ServerAliveCountMax=6,allow_other,uid=1000,gid=1000,umask=0077,sshfs_debug,debug,loglevel=debug,password_stdin [email protected]: basware_invoice/

(SSH keys not supported, thus the password from stdin)

Below is a partial debug output when trying to touch basware_invoice/IN/4900/test/foo2 twice. Full output: https://paste.fedoraproject.org/526294/48423812/

...
unique: 5, opcode: LOOKUP (1), nodeid: 4, insize: 45, pid: 29076
LOOKUP /IN/4900/test/foo2
getattr /IN/4900/test/foo2
[00004] LSTAT
[00004] STATUS 36bytes (53ms)
unique: 5, error: -2 (No such file or directory), outsize: 16
unique: 6, opcode: CREATE (35), nodeid: 4, insize: 61, pid: 29076
create flags: 0x8841 /IN/4900/test/foo2 0100664 umask=0002
[00005] OPEN
[00006] LSTAT
[00005] HANDLE 17bytes (53ms)
[00006] STATUS 36bytes (53ms)
[00007] CLOSE
unique: 6, error: -2 (No such file or directory), outsize: 16
unique: 7, opcode: LOOKUP (1), nodeid: 4, insize: 45, pid: 29076
LOOKUP /IN/4900/test/foo2
getattr /IN/4900/test/foo2
[00008] LSTAT
[00008] ATTRS 33bytes (54ms)
NODEID: 5
unique: 7, success, outsize: 144
[00007] STATUS 23bytes (56ms)
unique: 8, opcode: SETATTR (4), nodeid: 5, insize: 128, pid: 29076
utime /IN/4900/test/foo2 1484235677 1484235677
[00009] SETSTAT
[00009] STATUS 23bytes (53ms)
getattr /IN/4900/test/foo2
[00010] LSTAT
[00010] ATTRS 33bytes (53ms)
unique: 8, success, outsize: 120
unique: 9, opcode: REMOVEXATTR (24), nodeid: 5, insize: 53, pid: 29076
unique: 9, error: -38 (Function not implemented), outsize: 16
unique: 10, opcode: LOOKUP (1), nodeid: 1, insize: 43, pid: 29080
LOOKUP /IN
getattr /IN
NODEID: 2
unique: 10, success, outsize: 144
unique: 11, opcode: LOOKUP (1), nodeid: 2, insize: 45, pid: 29080
LOOKUP /IN/4900
getattr /IN/4900
NODEID: 3
unique: 11, success, outsize: 144
unique: 12, opcode: LOOKUP (1), nodeid: 3, insize: 45, pid: 29080
LOOKUP /IN/4900/test
getattr /IN/4900/test
NODEID: 4
unique: 12, success, outsize: 144
unique: 13, opcode: LOOKUP (1), nodeid: 4, insize: 45, pid: 29080
LOOKUP /IN/4900/test/foo2
getattr /IN/4900/test/foo2
NODEID: 5
unique: 13, success, outsize: 144
unique: 14, opcode: OPEN (14), nodeid: 5, insize: 48, pid: 29080
open flags: 0x8801 /IN/4900/test/foo2
[00011] OPEN
[00012] LSTAT
[00011] HANDLE 17bytes (53ms)
[00012] ATTRS 33bytes (53ms)
open[140467643618192] flags: 0x8801 /IN/4900/test/foo2
unique: 14, success, outsize: 32
unique: 15, opcode: FLUSH (25), nodeid: 5, insize: 64, pid: 29080
flush[140467643618192]
unique: 15, success, outsize: 16
unique: 16, opcode: SETATTR (4), nodeid: 5, insize: 128, pid: 29080
utime /IN/4900/test/foo2 1484235690 1484235690
[00013] SETSTAT
[00013] STATUS 23bytes (52ms)
getattr /IN/4900/test/foo2
[00014] LSTAT
[00014] ATTRS 33bytes (53ms)
unique: 16, success, outsize: 120
unique: 17, opcode: FLUSH (25), nodeid: 5, insize: 64, pid: 29080
flush[140467643618192]
unique: 17, success, outsize: 16
unique: 18, opcode: RELEASE (18), nodeid: 5, insize: 64, pid: 0
release[140467643618192] flags: 0x8801
[00015] CLOSE
unique: 18, success, outsize: 16
[00015] STATUS 23bytes (52ms)

strace touch (initial, failing):

[sftpuser@sftpproxy ~]$ strace touch basware_invoice/IN/4900/test/foo2
execve("/bin/touch", ["touch", "basware_invoice/IN/4900/test/foo"...], [/* 18 vars */]) = 0
brk(0) = 0xf91000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f69df72a000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=23927, ...}) = 0
mmap(NULL, 23927, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f69df724000
close(3) = 0
open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@\34\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=2118128, ...}) = 0
mmap(NULL, 3932672, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f69df14b000
mprotect(0x7f69df301000, 2097152, PROT_NONE) = 0
mmap(0x7f69df501000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b6000) = 0x7f69df501000
mmap(0x7f69df507000, 16896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f69df507000
close(3) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f69df723000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f69df721000
arch_prctl(ARCH_SET_FS, 0x7f69df721740) = 0
mprotect(0x7f69df501000, 16384, PROT_READ) = 0
mprotect(0x60d000, 4096, PROT_READ) = 0
mprotect(0x7f69df72b000, 4096, PROT_READ) = 0
munmap(0x7f69df724000, 23927) = 0
brk(0) = 0xf91000
brk(0xfb2000) = 0xfb2000
brk(0) = 0xfb2000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=106070960, ...}) = 0
mmap(NULL, 106070960, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f69d8c22000
close(3) = 0
open("basware_invoice/IN/4900/test/foo2", O_WRONLY|O_CREAT|O_NOCTTY|O_NONBLOCK, 0666) = -1 ENOENT (No such file or directory)
utimensat(AT_FDCWD, "basware_invoice/IN/4900/test/foo2", NULL, 0) = 0
close(1) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++

strace touch (second time, succeeds):

[sftpuser@sftpproxy ~]$ strace touch basware_invoice/IN/4900/test/foo2
execve("/bin/touch", ["touch", "basware_invoice/IN/4900/test/foo"...], [/* 18 vars */]) = 0
brk(0) = 0x6e8000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f84ac77b000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=23927, ...}) = 0
mmap(NULL, 23927, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f84ac775000
close(3) = 0
open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@\34\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=2118128, ...}) = 0
mmap(NULL, 3932672, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f84ac19c000
mprotect(0x7f84ac352000, 2097152, PROT_NONE) = 0
mmap(0x7f84ac552000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b6000) = 0x7f84ac552000
mmap(0x7f84ac558000, 16896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f84ac558000
close(3) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f84ac774000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f84ac772000
arch_prctl(ARCH_SET_FS, 0x7f84ac772740) = 0
mprotect(0x7f84ac552000, 16384, PROT_READ) = 0
mprotect(0x60d000, 4096, PROT_READ) = 0
mprotect(0x7f84ac77c000, 4096, PROT_READ) = 0
munmap(0x7f84ac775000, 23927) = 0
brk(0) = 0x6e8000
brk(0x709000) = 0x709000
brk(0) = 0x709000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=106070960, ...}) = 0
mmap(NULL, 106070960, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f84a5c73000
close(3) = 0
open("basware_invoice/IN/4900/test/foo2", O_WRONLY|O_CREAT|O_NOCTTY|O_NONBLOCK, 0666) = 3
dup2(3, 0) = 0
close(3) = 0
utimensat(0, NULL, NULL, 0) = 0
close(0) = 0
close(1) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++

[MrAbaddon]

I'm also having the same issue with CentOS 7.

[Nikratio]

Thanks for the report! Could you please clarify if the versions that you gave are for the client or the server (and provide what's not yet specified)? Thanks!

[teemupulliainen]

Thanks for taking a look. The versions are all for the client side (two different clients, Centos 7 and Fedora 25). I don't have access to the problematic server, nor do I know which SFTP implementation the server is using.

[Nikratio]

As far as I can tell, the SFTP server returns an ENOENT error message when SSHFS issues a CLOSE request. SSHFS simply forwards that to the user. Short of silently ignoring errors on close (which wouldn't be a good idea), there is thus nothing that SFTP could do differently here.

I'm afraid this is a bug in the SFTP server that SSHFS can't work around.