SFTP statvfs extension fails when mod_vroot is in use #1792

cfiehe · 2024-04-18T15:04:32Z

What I Did

I have mounted a share via SSHFS from our ProFTPD server, but the application is not able to write into the files even with the correct permissions set. The files are accessible and can be modified manually without any issues. The share is mounted via systemd:

elastic-logging@filestore.mycompany.de:/elastic-hot-srv5    /mnt/elastic/log    fuse.sshfs    noauto,x-systemd.automount,nofail,allow_other,reconnect,ServerAliveInterval=15,_netdev,IdentityFile=/root/.ssh/id_ed25519    0    0

When I do a tail –f on an existing file within the share, we get:

$ systemctl start mnt-elastic-log.mount
$ ls -la log
total 20
drwxr-xr-x 1 elastic-logging idm_service_customer_sftp_access 4096 Apr 18 16:23 .
drwxr-xr-x 4 root            root                               29 Apr 18 16:21 ..
-rw-r--r-- 1 elastic-logging idm_service_customer_sftp_access    5 Apr 18 16:43 test42
$ cat log/test42
TEST
$ tail -f log/test42
TEST
tail: cannot determine location of 'log/test42'. reverting to polling: No such file or directory

I enabled the trace log and we see the following error in the log:

2024-04-18 16:52:57,590 [650] <sftp:6>: received EXTENDED (200) SFTP request (request ID 38, channel ID 0)
2024-04-18 16:52:57,590 [650] <sftp:7>: received request: EXTENDED statvfs@openssh.com
2024-04-18 16:52:57,590 [650] <sftp:3>: statvfs() error using '/elastic-hot-srv5/test42': No such file or directory
2024-04-18 16:52:57,590 [650] <sftp:8>: sending response: STATUS 2 'No such file' ('No such file or directory' [2])

This is the full trace of the tail operation:

2024-04-18 16:52:57,587 [650] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2024-04-18 16:52:57,587 [650] <sftp:9>: reading SFTP data from SSH2 packet buffer (37 bytes)
2024-04-18 16:52:57,587 [650] <sftp:6>: received LSTAT (7) SFTP request (request ID 34, channel ID 0)
2024-04-18 16:52:57,587 [650] <sftp:7>: received request: LSTAT /elastic-hot-srv5/test42
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system lstat() for path '/elastic-hot-srv5'
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system lstat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system stat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system stat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system stat() for path '/elastic-hot-srv5/.ftpaccess'
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system stat() for path '/elastic-hot-srv5/.ftpaccess'
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system stat() for path '/.ftpaccess'
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system stat() for path '/.ftpaccess'
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system access() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system stat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system stat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system lstat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,587 [650] <fsio:8>: using vroot+system lstat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,587 [650] <sftp:8>: sending response: ATTRS type=file;size=5;UNIX.owner=1844400761;UNIX.group=1844400043;UNIX.mode=0644;access=20240418144757;modify=20240418144306;
2024-04-18 16:52:57,587 [650] <fsio:8>: using system llistxattr() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,587 [650] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 0, 45 data bytes)
2024-04-18 16:52:57,587 [650] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (84 bytes)
2024-04-18 16:52:57,588 [650] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2024-04-18 16:52:57,588 [650] <sftp:9>: reading SFTP data from SSH2 packet buffer (86 bytes)
2024-04-18 16:52:57,588 [650] <sftp:6>: received OPEN (3) SFTP request (request ID 35, channel ID 0)
2024-04-18 16:52:57,588 [650] <sftp:7>: received request: OPEN /elastic-hot-srv5/test42 type=unknown;UNIX.mode=0000; (O_RDONLY)
2024-04-18 16:52:57,588 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,588 [650] <fsio:8>: using vroot+system lstat() for path '/elastic-hot-srv5'
2024-04-18 16:52:57,588 [650] <fsio:8>: using vroot+system lstat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,588 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,588 [650] <fsio:8>: using vroot+system lstat() for path '/srv'
2024-04-18 16:52:57,588 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system access() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system open() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system fstat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system fstat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <sftp:8>: sending response: HANDLE 87b8d24793248897
2024-04-18 16:52:57,589 [650] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 0, 29 data bytes)
2024-04-18 16:52:57,589 [650] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (68 bytes)
2024-04-18 16:52:57,589 [650] <sftp:6>: received LSTAT (7) SFTP request (request ID 36, channel ID 0)
2024-04-18 16:52:57,589 [650] <sftp:7>: received request: LSTAT /elastic-hot-srv5/test42
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/elastic-hot-srv5'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/elastic-hot-srv5/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/elastic-hot-srv5/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/.ftpaccess'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system access() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system lstat() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <sftp:8>: sending response: ATTRS type=file;size=5;UNIX.owner=1844400761;UNIX.group=1844400043;UNIX.mode=0644;access=20240418144757;modify=20240418144306;
2024-04-18 16:52:57,589 [650] <fsio:8>: using system llistxattr() for path '/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 0, 45 data bytes)
2024-04-18 16:52:57,589 [650] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (84 bytes)
2024-04-18 16:52:57,589 [650] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2024-04-18 16:52:57,589 [650] <sftp:9>: reading SFTP data from SSH2 packet buffer (41 bytes)
2024-04-18 16:52:57,589 [650] <sftp:6>: received READ (5) SFTP request (request ID 37, channel ID 0)
2024-04-18 16:52:57,589 [650] <sftp:7>: received request: READ 87b8d24793248897 0 4096
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,589 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/.ftpaccess'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/.ftpaccess'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/.ftpaccess'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/.ftpaccess'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/.ftpaccess'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/.ftpaccess'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system stat() for path '/srv/.ftpaccess'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system stat() for path '/srv/.ftpaccess'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system stat() for path '/.ftpaccess'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system stat() for path '/.ftpaccess'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system access() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system stat() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42'
2024-04-18 16:52:57,590 [650] <fsio:8>: using vroot+system pread() for path '/srv/ftp/elastic-logging/elastic-hot-srv5/test42' (4096 bytes, 0 offset)
2024-04-18 16:52:57,590 [650] <sftp:8>: sending response: DATA (5 bytes)
2024-04-18 16:52:57,590 [650] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 0, 18 data bytes)
2024-04-18 16:52:57,590 [650] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (52 bytes)
2024-04-18 16:52:57,590 [650] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2024-04-18 16:52:57,590 [650] <sftp:9>: reading SFTP data from SSH2 packet buffer (60 bytes)
2024-04-18 16:52:57,590 [650] <sftp:6>: received EXTENDED (200) SFTP request (request ID 38, channel ID 0)
2024-04-18 16:52:57,590 [650] <sftp:7>: received request: EXTENDED statvfs@openssh.com
2024-04-18 16:52:57,590 [650] <sftp:3>: statvfs() error using '/elastic-hot-srv5/test42': No such file or directory
2024-04-18 16:52:57,590 [650] <sftp:8>: sending response: STATUS 2 'No such file' ('No such file or directory' [2])
2024-04-18 16:52:57,590 [650] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 0, 38 data bytes)
2024-04-18 16:52:57,590 [650] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (76 bytes)

I am not sure, if the issue is related to the combination of using mod_sftp together with mod_vroot or is related to #1780

ProFTPD Version and Configuration

I am on the latest code base within this and the mod_vroot repository.

Compile-time Settings:
  Version: 1.3.9rc3 (git)
  Platform: LINUX [Linux 5.15.0-102-generic x86_64]
  OS/Release:
    PRETTY_NAME="Ubuntu 22.04.4 LTS"
    NAME="Ubuntu"
    VERSION_ID="22.04"
    VERSION="22.04.4 LTS (Jammy Jellyfish)"
    VERSION_CODENAME=jammy
    ID=ubuntu
    ID_LIKE=debian
    UBUNTU_CODENAME=jammy
  Built: Mon Apr 1 2024 06:35:19 UTC
  Built With:
    configure  '--prefix=/usr' '--mandir=/usr/share/man' '--sysconfdir=/etc/proftpd' '--localstatedir=/run' '--libexecdir=/usr/lib/proftpd' '--with-includes=/usr/include/mysql:/usr/include/postgresql' '--with-shared=mod_auth_otp:mod_ban:mod_clamav:mod_copy:mod_ctrls_admin:mod_deflate:mod_digest:mod_dnsbl:mod_dynmasq:mod_exec:mod_facl:mod_geoip:mod_ident:mod_ifsession:mod_ifversion:mod_ldap:mod_load:mod_log_forensic:mod_proxy_protocol:mod_qos:mod_quotatab:mod_quotatab_file:mod_quotatab_ldap:mod_quotatab_radius:mod_quotatab_sql:mod_radius:mod_ratio:mod_readme:mod_redis:mod_rewrite:mod_sftp:mod_sftp_pam:mod_sftp_sql:mod_shaper:mod_site_misc:mod_snmp:mod_sql:mod_sql_mysql:mod_sql_odbc:mod_sql_passwd:mod_sql_postgres:mod_statcache:mod_tls:mod_tls_fscache:mod_tls_redis:mod_tls_shmcache:mod_unique_id:mod_vroot:mod_wrap:mod_wrap2:mod_wrap2_file:mod_wrap2_redis:mod_wrap2_sql' '--enable-autoshadow' '--enable-ctrls' '--enable-dso' '--enable-facl' '--enable-ipv6' '--enable-openssl' '--enable-pcre2' '--enable-nls' '--enable-redis' '--enable-sendfile' '--with-lastlog=/var/log/lastlog' '--disable-strip' '--disable-ident'

  CFLAGS: -g2 -O2 -Wall -fno-omit-frame-pointer -fno-strict-aliasing -Werror=implicit-function-declaration
  LDFLAGS: -Wl,-L$(top_srcdir)/lib,-L$(top_builddir)/lib  -rdynamic  -L/usr/lib/x86_64-linux-gnu -L/usr/lib/x86_64-linux-gnu
  LIBS: -lacl  -lpcre2-posix -lpcre2-8 -lssl -lcrypto -lsodium -lcap  -lpam -lattr -lidn2 -lcrypt -lhiredis  -pthread

  Files:
    Configuration File:
      /etc/proftpd/proftpd.conf
    Pid File:
      /run/proftpd.pid
    Scoreboard File:
      /run/proftpd.scoreboard
    Header Directory:
      /usr/include/proftpd
    Shared Module Directory:
      /usr/lib/proftpd

  Info:
    + Max supported UID: 4294967295
    + Max supported GID: 4294967295

  Features:
    + Autoshadow support
    + Controls support
    + curses support
    - Developer support
    + DSO support
    + IPv6 support
    + Largefile support
    + Lastlog support
    - Memcache support
    + ncursesw support
    + NLS support
    + OpenSSL support (OpenSSL 3.0.2 15 Mar 2022)
    - PCRE support
    + PCRE2 support
    + POSIX ACL support
    + Redis support
    + Sendfile support
    + Shadow file support
    + Sodium support
    + Trace support
    + xattr support

  Tunable Options:
    PR_TUNABLE_BUFFER_SIZE = 1024
    PR_TUNABLE_DEFAULT_RCVBUFSZ = 65536
    PR_TUNABLE_DEFAULT_SNDBUFSZ = 65536
    PR_TUNABLE_ENV_MAX = 2048
    PR_TUNABLE_GLOBBING_MAX_MATCHES = 100000
    PR_TUNABLE_GLOBBING_MAX_RECURSION = 8
    PR_TUNABLE_HASH_TABLE_SIZE = 40
    PR_TUNABLE_LOGIN_MAX = 256
    PR_TUNABLE_NEW_POOL_SIZE = 512
    PR_TUNABLE_PATH_MAX = 4096
    PR_TUNABLE_SCOREBOARD_BUFFER_SIZE = 80
    PR_TUNABLE_SCOREBOARD_SCRUB_TIMER = 30
    PR_TUNABLE_SELECT_TIMEOUT = 30
    PR_TUNABLE_TIMEOUTIDENT = 10
    PR_TUNABLE_TIMEOUTIDLE = 600
    PR_TUNABLE_TIMEOUTLINGER = 10
    PR_TUNABLE_TIMEOUTLOGIN = 300
    PR_TUNABLE_TIMEOUTNOXFER = 300
    PR_TUNABLE_TIMEOUTSTALLED = 3600
    PR_TUNABLE_XFER_SCOREBOARD_UPDATES = 10

Any help is greatly appreciated.

The text was updated successfully, but these errors were encountered:

Castaglia · 2024-04-18T16:14:14Z

Hmm. Interesting that a failed EXTENDED statvfs@openssh.com request would prevent writes. Perhaps mod_sftp will need to use the FSIO "realpath" functionality added in #1780 for this code path, to "resolve" path (see here) according to the mod_vroot rules?

In the mean time, as a workaround, you might disable that extension, and see if that makes SSHFS happier:

SFTPExtensions -statvfs

cfiehe · 2024-04-18T18:37:59Z

Good hint. I already tried that without success, but I think I forgot to remount the share in order to start a new round of negotiation. I added the new setting and remounted the share now. The first impression is promising. Hopefully, tomorrow I have more information.

I agree, it feels like #1780 and an improper path resolution when mod_vroot gets used.

Thanks a lot for your quick response 😃.

cfiehe · 2024-04-19T07:28:18Z

Hi @Castaglia,
we tried to redo our test case, but we are running into several No such file or directory exceptions coming from mod_sftp. The files are present in the directory. There must still be some more path resolutions, that point to the wrong location when using mod_vroot.

sftp.log gives us:

2024-04-19 08:16:25,488 mod_sftp/1.2.0[991]: error checking '/elastic-hot-srv5/prod-cluster_server.json' for LSTAT: No such file or directory
2024-04-19 08:16:25,489 mod_sftp/1.2.0[991]: error checking '/elastic-hot-srv5/prod-cluster_server.json' for LSTAT: No such file or directory
2024-04-19 08:16:25,500 mod_sftp/1.2.0[991]: OPEN command for '/elastic-hot-srv5/prod-cluster_server.json' blocked by 'APPE' handler: Operation not permitted
2024-04-19 08:16:25,551 mod_sftp/1.2.0[991]: error checking '/elastic-hot-srv5/prod-cluster_audit.json' for LSTAT: No such file or directory
2024-04-19 08:16:25,553 mod_sftp/1.2.0[991]: error checking '/elastic-hot-srv5/prod-cluster_audit.json' for LSTAT: No such file or directory
2024-04-19 08:16:25,562 mod_sftp/1.2.0[991]: OPEN command for '/elastic-hot-srv5/prod-cluster_audit.json' blocked by 'APPE' handler: Operation not permitted
2024-04-19 08:16:25,571 mod_sftp/1.2.0[991]: error checking '/elastic-hot-srv5/prod-cluster.log' for LSTAT: No such file or directory
2024-04-19 08:16:25,573 mod_sftp/1.2.0[991]: error checking '/elastic-hot-srv5/prod-cluster.log' for LSTAT: No such file or directory
2024-04-19 08:16:25,582 mod_sftp/1.2.0[991]: OPEN command for '/elastic-hot-srv5/prod-cluster.log' blocked by 'APPE' handler: Operation not permitted
2024-04-19 08:16:25,590 mod_sftp/1.2.0[991]: error checking '/elastic-hot-srv5/prod-cluster_deprecation.json' for LSTAT: No such file or directory
2024-04-19 08:16:25,591 mod_sftp/1.2.0[991]: error checking '/elastic-hot-srv5/prod-cluster_deprecation.json' for LSTAT: No such file or directory
2024-04-19 08:16:25,600 mod_sftp/1.2.0[991]: OPEN command for '/elastic-hot-srv5/prod-cluster_deprecation.json' blocked by 'APPE' handler: Operation not permitted
2024-04-19 08:16:25,605 mod_sftp/1.2.0[991]: error checking '/elastic-hot-srv5/prod-cluster_index_search_slowlog.json' for LSTAT: No such file or directory
2024-04-19 08:16:25,607 mod_sftp/1.2.0[991]: error checking '/elastic-hot-srv5/prod-cluster_index_search_slowlog.json' for LSTAT: No such file or directory
2024-04-19 08:16:25,616 mod_sftp/1.2.0[991]: OPEN command for '/elastic-hot-srv5/prod-cluster_index_search_slowlog.json' blocked by 'APPE' handler: Operation not permitted
2024-04-19 08:16:25,625 mod_sftp/1.2.0[991]: error checking '/elastic-hot-srv5/prod-cluster_index_indexing_slowlog.json' for LSTAT: No such file or directory
2024-04-19 08:16:25,626 mod_sftp/1.2.0[991]: error checking '/elastic-hot-srv5/prod-cluster_index_indexing_slowlog.json' for LSTAT: No such file or directory
2024-04-19 08:16:25,636 mod_sftp/1.2.0[991]: OPEN command for '/elastic-hot-srv5/prod-cluster_index_indexing_slowlog.json' blocked by 'APPE' handler: Operation not permitted
2024-04-19 08:16:43,649 mod_sftp/1.2.0[991]: client sent GLOBAL_REQUEST for 'keepalive@openssh.com', denying
2024-04-19 08:16:58,665 mod_sftp/1.2.0[991]: client sent GLOBAL_REQUEST for 'keepalive@openssh.com', denying
2024-04-19 08:17:13,676 mod_sftp/1.2.0[991]: client sent GLOBAL_REQUEST for 'keepalive@openssh.com', denying

I have attached the corresponding parts of the trace log.
trace.log

Castaglia · 2024-04-20T14:55:45Z

The interesting question for me is whether you were seeing similar path resolution issues, when using mod_vroot and SFTP, prior to those recent FSIO changes? For as I recall, mod_vroot and mod_sftp did not see such issues before.

… Issue #1780 in the `statvfs(2)` system calls in mod_sftp.

… Issue #1780 in the `statvfs(2)` system calls in mod_sftp. (#1795)

Castaglia · 2024-04-20T16:03:51Z

Hopefully #1795 will at least make the statvfs SFTP extension work once more in your use case.

cfiehe · 2024-04-21T18:05:03Z

Hi @Castaglia
thank you very much. Your change #1795 fixed the issue with the statvfs SFTP extension.

cfiehe · 2024-04-21T18:29:17Z

I built a version before the FSIO changes based on ProFTPD v1.3.9rc2-15-gebce2d375 and mod_vroot v0.9.11-6-geac69e8. But also in that version the append operation on a file with the correct permissions and ownership echo "test" >> /mnt/elastic/log/test42 fails with -bash: /mnt/elastic/log/test42: Permission denied.

The trace log gives:

2024-04-21 20:15:28,595 [8] <sftp:8>: sending response: STATUS 3 'Permission denied' ('No such file or directory' [1])

The sftp log gives:

2024-04-21 20:15:28,595 mod_sftp/1.2.0[8]: OPEN command for '/test42' blocked by 'APPE' handler: Operation not permitted

The problem does not seem to introduced by the FSIO changes. I have also deactivated mod_vroot and mod_facl, but the append operation keeps failing.

Castaglia · 2024-04-21T19:23:36Z

Could you provide the ProFTPD configuration you're using? I'm wondering if there's something else that might be blocking that OPEN SFTP request. It's possible that standard ProFTPD debug logging might also provide more hints/clues for this APPE handler blockage.

And thanks for mentioning/confirming that this behavior occurs even with mod_vroot and mod_facl disabled; it's always good to rule out possible sources of unexpected behavior.

cfiehe · 2024-04-21T20:22:29Z

I set the DebugLevel to 10, but the logs contain only the two lines from above.

This is my current configuration:

#
# This file is used to manage DSO modules and features.
#

ModulePath /usr/lib/proftpd

ModuleControlsACLs insmod,rmmod allow user root
ModuleControlsACLs lsmod allow user *

LoadModule mod_ctrls_admin.c
LoadModule mod_sql.c
LoadModule mod_sql_postgres.c
LoadModule mod_quotatab.c
LoadModule mod_quotatab_sql.c
LoadModule mod_rewrite.c
LoadModule mod_load.c
LoadModule mod_ban.c
LoadModule mod_wrap2.c
LoadModule mod_wrap2_file.c
LoadModule mod_wrap2_sql.c
LoadModule mod_shaper.c
LoadModule mod_site_misc.c
LoadModule mod_sftp.c
LoadModule mod_sftp_pam.c
LoadModule mod_facl.c
LoadModule mod_unique_id.c
LoadModule mod_copy.c
LoadModule mod_deflate.c
LoadModule mod_ifversion.c
LoadModule mod_redis.c
LoadModule mod_wrap2_redis.c
LoadModule mod_vroot.c
LoadModule mod_ifsession.c
LoadModule mod_proxy_protocol.c

#
# /etc/proftpd/proftpd.conf -- The main ProFTPD configuration file.
#

# Includes DSO modules
Include /etc/proftpd/modules.conf

DefaultServer off
MaxInstances 500
Port 0
ServerType standalone
UseReverseDNS off

Include /etc/proftpd/conf.d/*.conf

<IfModule mod_auth.c>
    <Global>
        AllowEmptyPasswords no

        # Limits the number of connections on a per-server/vhost basis
        MaxClients 300

        # Limits the number of clients that may be connecting from the same host
        MaxClientsPerHost 25

        # Limits the number of clients that may be logged in at one time using
        # the same username
        MaxClientsPerUser 50

        # Limits the number of unauthenticated clients allowed to connect from a host.
        MaxConnectionsPerHost 25

        # Limits the number of hosts from which clients may be logged in at one time
        # using the same username
        MaxHostsPerUser 50

        # Limits the number of times a client may attempt to authenticate to the server
        # on the same TCP connection.
        # MaxLoginAttempts 1

        RequireValidShell off
        RootLogin off
        RootRevoke on
        TimeoutLogin 60
        TimeoutSession 86400
        WtmpLog off
    </Global>
</IfModule>

<IfModule mod_auth_pam.c>
    <Global>
        AuthPAM on
        AuthPAMConfig proftpd
    </Global>
</IfModule>

#<Global>
#    <Class whitelist>
#        From 10.0.0.0/8
#        From 172.16.0.0/12
#        From 192.168.0.0/16
#    </Class>
#
#    <IfClass whitelist>
#        BanEngine off
#    </IfClass>
#
#    <IfClass !whitelist>
#        BanEngine on
#    </IfClass>
#</Global>

<IfModule mod_ban.c>
    BanEngine on
    BanLog /var/log/proftpd/ban.log
    BanCacheOptions UseJSON
    BanControlsACLs all allow user root
    BanOnEvent ClientConnectRate 60/00:01:00 00:05:00
    BanOnEvent LoginRate 60/00:01:00 00:05:00
    BanOnEvent MaxLoginAttempts 3/00:01:00 00:10:00
    BanOnEvent RootLogin 2/00:01:00 12:00:00
    BanTable /run/proftpd-mod-ban.tab
</IfModule>

<IfModule mod_ctrls.c>
    ControlsEngine on
    ControlsMaxClients 10
    # ControlsLog /var/log/proftpd/controls.log
    ControlsInterval 5
    ControlsSocket /run/proftpd.sock
    ControlsACLs all allow user root

    <IfModule mod_ctrls_admin.c>
        AdminControlsEngine on
        AdminControlsACLs all allow user root
    </IfModule>
</IfModule>

<IfModule mod_core.c>
    SystemLog /var/log/proftpd/proftpd.log
    TimeoutIdle 300
    TimesGMT off
    Umask 022 022

    # Debugging
    DebugLevel 10
    TraceLog /var/log/proftpd/trace.log
    # Trace ban:10
    # Trace clamav:10
    # Trace facl:10
    Trace fsio:10
    # Trace ftp:10
    # Trace ifsession:10
    # Trace proxy_protocol:10
    # Trace quotatab:10
    # Trace quotatab_file:10
    # Trace quotatab_sql:10
    # Trace redis:10
    # Trace scp:10
    # Trace vroot:10
    Trace sftp:10
    Trace ssh2:10
</IfModule>

<IfModule mod_delay.c>
    DelayEngine off
</IfModule>

<VirtualHost 0.0.0.0 ::>
    ServerName filestore.mycompany.de
    ServerAdmin loc@mycompany.de

    ProxyProtocolEngine on

    SFTPEngine on
    Port 22

    RedisEngine on
    BanCache redis

    VRootEngine on
    DefaultRoot ~
    CreateHome on 0700 dirmode 0755

    AllowOverwrite on

    RewriteEngine on
    RewriteHome on
    RewriteCondition %m REWRITE_HOME
    RewriteRule ^(?:\/home|\/var\/data\/sftp)\/(.*)$ /srv/ftp/$1

    RewriteCondition %m USER
    RewriteRule ^(.+)@(edsb|edsbrv|lx)$ $1@$2.mycompany.de

    RewriteCondition %m USER
    RewriteRule ^(.+)@lx\.mycompany\.de$ $1

    QuotaEngine on
    # Unit is in byte (10 GB)
    QuotaDefault user false hard 10737418240 0 0 0 0 0

#    <Directory /*>
#        HideNoAccess on
#        HideFiles ^\.keep$
#        <Limit ALL>
#            IgnoreHidden on
#        </Limit>
#    </Directory>
</VirtualHost>

<IfModule mod_proxy_protocol.c>
    <Global>
        ProxyProtocolVersion haproxyV2
        ProxyProtocolTimeout 3sec
    </Global>
</IfModule>

<IfModule mod_quotatab.c>
    <Global>
        QuotaDisplayUnits Mb
        QuotaLog /var/log/proftpd/quota.log
        QuotaOptions ScanOnLogin
    </Global>

    <IfModule mod_quotatab_sql.c>
        <Global>
            SQLNamedQuery get-quota-limit SELECT "name, quota_type, per_session, limit_type, bytes_in_avail, bytes_out_avail, bytes_xfer_avail, files_in_avail, files_out_avail, files_xfer_avail FROM quotalimits WHERE name = '%{0}' AND quota_type = '%{1}'"
            SQLNamedQuery get-quota-tally SELECT "name, quota_type, bytes_in_used, bytes_out_used, bytes_xfer_used, files_in_used, files_out_used, files_xfer_used FROM quotatallies WHERE name = '%{0}' AND quota_type = '%{1}'"
            SQLNamedQuery update-quota-tally UPDATE "bytes_in_used = bytes_in_used + %{0}, bytes_out_used = bytes_out_used + %{1}, bytes_xfer_used = bytes_xfer_used + %{2}, files_in_used = files_in_used + %{3}, files_out_used = files_out_used + %{4}, files_xfer_used = files_xfer_used + %{5} WHERE name = '%{6}' AND quota_type = '%{7}'" quotatallies
            SQLNamedQuery insert-quota-tally INSERT "%{0}, %{1}, %{2}, %{3}, %{4}, %{5}, %{6}, %{7}" quotatallies

            QuotaLock /var/lock/proftpd-quota-tallytab.lock
            QuotaLimitTable sql:/get-quota-limit
            QuotaTallyTable sql:/get-quota-tally/update-quota-tally/insert-quota-tally
        </Global>
    </IfModule>
</IfModule>

<IfModule mod_redis.c>
    <Global>
        RedisLog /var/log/proftpd/redis.log
        RedisSentinel filestore-redis1.mycompany.de:26379 filestore-redis2.mycompany.de:26379 filestore-redis3.mycompany.de:26379 master redis-primary
        RedisServer localhost:6379 proftpd <SECRET>
    </Global>
</IfModule>

<IfModule mod_rewrite.c>
    <Global>
        # RewriteLog /var/log/proftpd/rewrite.log
    </Global>
</IfModule>

<IfModule mod_sftp.c>
    <Global>
        SFTPLog /var/log/proftpd/sftp.log

        SFTPHostKey /etc/proftpd/ssh_host_ecdsa_key
        SFTPHostKey /etc/proftpd/ssh_host_ed25519_key
        SFTPHostKey /etc/proftpd/ssh_host_rsa_key

        SFTPAuthMethods publickey password
        SFTPAuthorizedUserKeys file:~/.ssh/authorized_keys

        SFTPClientAlive 3 15
        SFTPCompression delayed

        # Set 'PessimisticKexinit' to avoid hanging SSH handshakes
        # under currently not understood circumstances.
        SFTPOptions IgnoreSFTPSetTimes IgnoreSCPUploadPerms IgnoreSCPUploadTimes PessimisticKexinit

        # Refer to:
        # https://github.com/proftpd/proftpd/issues/1792
        # SFTPExtensions -statvfs

        SFTPClientMatch "JSCH.*" channelWindowSize 1GB
        SFTPClientMatch ".*SecureBlackbox.*" sftpProtocolVersion 1-3
        SFTPClientMatch ".*WS_FTP.*" channelWindowSize 1GB
        SFTPClientMatch ".*WinSCP.*" sftpProtocolVersion 1-3
        SFTPClientMatch ".*XFB.*" channelWindowSize 1GB sftpUTF8ProtocolVersion 3

        # It is recommended to explicitly configure MaxLoginAttempts for a SSH2/SFTP instance to be higher than
        # the normal MaxLoginAttempts value for FTP, as there are more ways to authenticate using SSH2.
        MaxLoginAttempts 2

        <Directory />
            HideFiles (\.sftp|\.ssh)$
        </Directory>
    </Global>
</IfModule>

<IfModule mod_sql.c>
    <Global>
        SQLEngine on
        SQLAuthenticate off
        SQLBackend postgres
        SQLAuthTypes OpenSSL
        SQLConnectInfo filestore@db-pg3-rw-prod.mycompany.de filestore <SECRET>
        # SQLLogFile /var/log/proftpd/sql.log
    </Global>
</IfModule>

<IfModule mod_vroot.c>
    <Global>
        VRootLog /var/log/proftpd/vroot.log
    </Global>
</IfModule>

<IfModule mod_xfer.c>
    <Global>
        AllowRetrieveRestart on
        DeleteAbortedStores on
        TimeoutNoTransfer 300
        TimeoutStalled 180
    </Global>
</IfModule>

cfiehe · 2024-04-21T20:39:40Z

I also switched every folder and the corresponding file to mode 0777, but that did not make any difference.

cfiehe · 2024-04-22T11:21:50Z

@Castaglia You were right. The setting AllowStoreRestart on was missing. Now the append operation is working. Thank you very much.

Castaglia · 2024-04-22T16:39:39Z

@Castaglia You were right. The setting AllowStoreRestart on was missing. Now the append operation is working. Thank you very much.

Ah, good. I'll add some debug logging in mod_xfer for this code path, to make diagnosing such issues easier in the future.

With that addition of AllowStoreRestart on, is your installation now working as expected, SSHFS-wise? I.e. are there any other lingering problems around this SFTP statvfs ticket/issue?

cfiehe · 2024-04-22T18:54:34Z

First of all: Sorry for causing all the trouble. Our use case utilizes a lot of feature of the ProFTPD and the service is under heavy load. Even under those circumstances, your implementation does a really good job. Thank you very much for all your efforts spent over the years.

I must do some more testing with SSHFS. Currently we are resorting to NFS. Unfortunately, SSHFS in combination with ProFTPD is really slow. We tested it against an OpenSSH server. I will give you the measurements in the next days. I think the main problem is that the ProFTPD does not implement the SFTP extension limits@openssh.com. Therefore, the server can tell the client which maximum packet size is supported. I am not sure, but that maybe the reason why the clients cuts the data in smaller packets when talking with ProFTPD. The behavior causes a lot of overhead when big files are being transferred. Please have a look here: #1288 (comment)

Maybe you have an idea.

Castaglia · 2024-04-24T00:11:05Z

First of all: Sorry for causing all the trouble. Our use case utilizes a lot of feature of the ProFTPD and the service is under heavy load. Even under those circumstances, your implementation does a really good job. Thank you very much for all your efforts spent over the years.

Glad to hear it! No worries about any trouble caused. I strive to keep ProFTPD very flexible, configuration-wise. Unfortunately that means a lot of edge cases and combinations which I don't always test well, and have to rely on reports like these to fix those edge cases.

Mostly I wanted to confirm that the specific scope for this ticket, that of having a working statvfs SFTP extension when mod_vroot is in use, has been addressed? I'm happy to use other tickets for other concerns; I try to not conflate/mix concerns in a single ticket, so as to keep symptoms and observations focused on one issue at a time.

I must do some more testing with SSHFS. Currently we are resorting to NFS. Unfortunately, SSHFS in combination with ProFTPD is really slow. We tested it against an OpenSSH server. I will give you the measurements in the next days. I think the main problem is that the ProFTPD does not implement the SFTP extension limits@openssh.com. Therefore, the server can tell the client which maximum packet size is supported. I am not sure, but that maybe the reason why the clients cuts the data in smaller packets when talking with ProFTPD. The behavior causes a lot of overhead when big files are being transferred. Please have a look here: #1288 (comment)

Maybe you have an idea.

I will take a look into this, and at the OpenSSH source code, to see if implementing the limits@openssh.com extension would help or not -- but probably as part of Issue #1288 or Issue #1751.

…nt issue related to the `AllowStoreRestart` directive when used with SFTP. Add some debug logging in the checking of this configuration in mod_xfer, to make future diagnosis easier.

…nt issue related to the `AllowStoreRestart` directive when used with SFTP. (#1797) Add some debug logging in the checking of this configuration in mod_xfer, to make future diagnosis easier.

cfiehe · 2024-04-25T14:15:42Z

Thanks a lot @Castaglia. We did a new test run and the issue did not occur. It can be closed 👍.

Castaglia self-assigned this Apr 18, 2024

Castaglia added a commit that referenced this issue Apr 20, 2024

Issue #1792: Use the new pr_fsio_realpath() function implemented in…

4fac72e

… Issue #1780 in the `statvfs(2)` system calls in mod_sftp.

Castaglia added a commit that referenced this issue Apr 20, 2024

Issue #1792: Use the new pr_fsio_realpath() function implemented in…

4f131c6

… Issue #1780 in the `statvfs(2)` system calls in mod_sftp. (#1795)

Castaglia changed the title ~~statvfs() error: No such file or directory~~ SFTP statvfs extension fails when mod_vroot is in use Apr 25, 2024

Castaglia added a commit that referenced this issue Apr 25, 2024

Update NEWS for fix for Issue #1792.

8b7fa6e

Castaglia closed this as completed Apr 25, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

SFTP statvfs extension fails when mod_vroot is in use #1792

SFTP statvfs extension fails when mod_vroot is in use #1792

cfiehe commented Apr 18, 2024 •

edited

Castaglia commented Apr 18, 2024 •

edited

cfiehe commented Apr 18, 2024 •

edited

cfiehe commented Apr 19, 2024

Castaglia commented Apr 20, 2024

Castaglia commented Apr 20, 2024

cfiehe commented Apr 21, 2024

cfiehe commented Apr 21, 2024 •

edited

Castaglia commented Apr 21, 2024 •

edited

cfiehe commented Apr 21, 2024

cfiehe commented Apr 21, 2024

cfiehe commented Apr 22, 2024

Castaglia commented Apr 22, 2024 •

edited

cfiehe commented Apr 22, 2024

Castaglia commented Apr 24, 2024

cfiehe commented Apr 25, 2024

SFTP statvfs extension fails when mod_vroot is in use #1792

SFTP statvfs extension fails when mod_vroot is in use #1792

Comments

cfiehe commented Apr 18, 2024 • edited

What I Did

ProFTPD Version and Configuration

Castaglia commented Apr 18, 2024 • edited

cfiehe commented Apr 18, 2024 • edited

cfiehe commented Apr 19, 2024

Castaglia commented Apr 20, 2024

Castaglia commented Apr 20, 2024

cfiehe commented Apr 21, 2024

cfiehe commented Apr 21, 2024 • edited

Castaglia commented Apr 21, 2024 • edited

cfiehe commented Apr 21, 2024

cfiehe commented Apr 21, 2024

cfiehe commented Apr 22, 2024

Castaglia commented Apr 22, 2024 • edited

cfiehe commented Apr 22, 2024

Castaglia commented Apr 24, 2024

cfiehe commented Apr 25, 2024

cfiehe commented Apr 18, 2024 •

edited

Castaglia commented Apr 18, 2024 •

edited

cfiehe commented Apr 18, 2024 •

edited

cfiehe commented Apr 21, 2024 •

edited

Castaglia commented Apr 21, 2024 •

edited

Castaglia commented Apr 22, 2024 •

edited