Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Using mod_facl and mod_vroot at same time causes unexpected permissions issues #1780

Closed
cfiehe opened this issue Feb 15, 2024 · 16 comments
Closed

Using mod_facl and mod_vroot at same time causes unexpected permissions issues #1780

cfiehe opened this issue Feb 15, 2024 · 16 comments
Assignees
@Castaglia
Labels
bug
Milestone
1.3.9

Comments

@cfiehe
Copy link

cfiehe commented Feb 15, 2024 •
edited
Loading

What I Did

I tried to activate the option HideNoAccess to make sure that the user gets only files and directory listings to which he has access to. I have used the following configuration snippet in my vHost:

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

Unfortunately, the directory listing is empty.

The issue is related to mod_vroot. The paths to the directories inside the user's home directory are regarded as absolute paths. Let us assume the following case: The user gets chrooted to his home directory under /srv/ftp/testuser. His home directory contains the following directories:

root@proftpd-srv1:/srv/ftp/testuser# ls
abc  incoming  prod  test
root@proftpd-srv1:/srv/ftp/testuser# ls -la
total 0
drwx------   6 testuser idm_service_customer_sftp_access 0 Feb 15 20:51 .
drwxr-xr-x 164 root              root                             0 Feb 14 17:56 ..
drw-------   2 root              root                             0 Feb 15 20:51 abc
drwxr-xr-x   3 testuser idm_service_customer_sftp_access 0 Feb 15 17:11 incoming
drwxr-xr-x   4 testuser idm_service_customer_sftp_access 0 Jun 20  2018 prod
drwxr-xr-x   5 testuser idm_service_customer_sftp_access 0 Feb 15 16:53 test

When the user testuser logs in, his home directory is empty:

$ sftp -P 22 testuser@proftpd.mycompany.de
testuser@proftpd.eurodata.de's password:
Connected to proftpd.eurodata.de.
sftp> ls
sftp>

The trace gives the answer, because the directory permissions are looked up e.g. for the directory /abc (does not exist) and not for /srv/ftp/testuser/abc. Please have a close look at the following trace excerpt. Both facl and sftp complain about not existing directories;

2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot readdir()
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot lstat() for path '/incoming'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot lstat() for path '/incoming'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/incoming'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/incoming'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/incoming/.ftpaccess'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/incoming/.ftpaccess'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,273 [16] <fsio:8>: using facl access() for path '/incoming'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/incoming'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/incoming'
2024-02-15 21:34:36,273 [16] <facl:5>: unable to retrieve ACL for '/incoming': [2] No such file or directory
2024-02-15 21:34:36,273 [16] <sftp:3>: unable to obtain directory listing for '/incoming': Permission denied
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot readdir()
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot lstat() for path '/prod'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot lstat() for path '/prod'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/prod'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/prod'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/prod/.ftpaccess'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/prod/.ftpaccess'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,273 [16] <fsio:8>: using facl access() for path '/prod'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/prod'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/prod'
2024-02-15 21:34:36,273 [16] <facl:5>: unable to retrieve ACL for '/prod': [2] No such file or directory
2024-02-15 21:34:36,273 [16] <sftp:3>: unable to obtain directory listing for '/prod': Permission denied
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot readdir()
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot lstat() for path '/test'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot lstat() for path '/test'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/test'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/test'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/test/.ftpaccess'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/test/.ftpaccess'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,273 [16] <fsio:8>: using facl access() for path '/test'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/test'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/test'
2024-02-15 21:34:36,273 [16] <facl:5>: unable to retrieve ACL for '/test': [2] No such file or directory
2024-02-15 21:34:36,273 [16] <sftp:3>: unable to obtain directory listing for '/test': Permission denied
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot readdir()
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot lstat() for path '/abc'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot lstat() for path '/abc'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/abc'
2024-02-15 21:34:36,273 [16] <fsio:8>: using vroot stat() for path '/abc'
2024-02-15 21:34:36,274 [16] <fsio:8>: using vroot stat() for path '/abc/.ftpaccess'
2024-02-15 21:34:36,274 [16] <fsio:8>: using vroot stat() for path '/abc/.ftpaccess'
2024-02-15 21:34:36,274 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,274 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,274 [16] <fsio:8>: using facl access() for path '/abc'
2024-02-15 21:34:36,274 [16] <fsio:8>: using vroot stat() for path '/abc'
2024-02-15 21:34:36,274 [16] <fsio:8>: using vroot stat() for path '/abc'
2024-02-15 21:34:36,274 [16] <facl:5>: unable to retrieve ACL for '/abc': [2] No such file or directory
2024-02-15 21:34:36,274 [16] <sftp:3>: unable to obtain directory listing for '/abc': Permission denied
2024-02-15 21:34:36,274 [16] <fsio:8>: using vroot readdir()
2024-02-15 21:34:36,274 [16] <fsio:8>: using vroot chdir() for path '/'
2024-02-15 21:34:36,274 [16] <fsio:8>: using vroot lstat() for path '/'
2024-02-15 21:34:36,274 [16] <sftp:8>: sending response: NAME (2 count)
2024-02-15 21:34:36,274 [16] <fsio:8>: using system llistxattr() for path '.'
2024-02-15 21:34:36,274 [16] <fsio:8>: using system lgetxattr() for path '.'
2024-02-15 21:34:36,274 [16] <fsio:8>: using system lgetxattr() for path '.'
2024-02-15 21:34:36,274 [16] <fsio:8>: using system llistxattr() for path '..'
2024-02-15 21:34:36,274 [16] <fsio:8>: using system lgetxattr() for path '..'
2024-02-15 21:34:36,274 [16] <fsio:8>: using system lgetxattr() for path '..'
2024-02-15 21:34:36,667 [16] <sftp:9>: reading SFTP data from SSH2 packet buffer (29 bytes)
2024-02-15 21:34:36,667 [16] <sftp:6>: received READDIR (12) SFTP request (request ID 256524, channel ID 0)
2024-02-15 21:34:36,667 [16] <sftp:7>: received request: READDIR e9f8f72bd76e6eb3
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot stat() for path '/'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot stat() for path '/'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot stat() for path '/'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot stat() for path '/'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot stat() for path '/'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot stat() for path '/'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot chdir() for path '/'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot lstat() for path '/'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot readdir()
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot chdir() for path '/'
2024-02-15 21:34:36,667 [16] <fsio:8>: using vroot lstat() for path '/'
2024-02-15 21:34:36,668 [16] <sftp:8>: sending response: STATUS 1 'End of file'
2024-02-15 21:34:36,668 [16] <sftp:9>: reading SFTP data from SSH2 packet buffer (29 bytes)
2024-02-15 21:34:36,668 [16] <sftp:6>: received CLOSE (4) SFTP request (request ID 256772, channel ID 0)
2024-02-15 21:34:36,668 [16] <sftp:7>: received request: CLOSE e9f8f72bd76e6eb3
2024-02-15 21:34:36,668 [16] <fsio:8>: using vroot closedir()
2024-02-15 21:34:36,668 [16] <sftp:8>: sending response: STATUS 0 'OK'

I have created the directory /abc:

root@244ae82ac9d7:/# mkdir /abc
root@244ae82ac9d7:/# chown testuser /abc

and now the directory abc is listed in the user's home directory:

sftp> ls
abc

What I Expected/Wanted

All directories to which the user has access to are listed and the other one get filtered out.

ProFTPD Version and Configuration

Compile-time Settings:
  Version: 1.3.9rc3 (git)
  Platform: LINUX [Linux 5.15.0-94-generic x86_64]
  OS/Release:
    PRETTY_NAME="Ubuntu 22.04.3 LTS"
    NAME="Ubuntu"
    VERSION_ID="22.04"
    VERSION="22.04.3 LTS (Jammy Jellyfish)"
    VERSION_CODENAME=jammy
    ID=ubuntu
    ID_LIKE=debian
    UBUNTU_CODENAME=jammy
  Built: Sun Feb 11 2024 21:07:53 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

Is it possible to fix the issue?

Thank you very much.
@Castaglia Castaglia self-assigned this Feb 15, 2024
@Castaglia Castaglia added the bug label Feb 15, 2024
@Castaglia Castaglia added this to the 1.3.9 milestone Feb 15, 2024
@Castaglia
Copy link
Member

I think this issue is similar to #1764 -- both mod_facl and mod_vroot are using the same internal API for custom filesystem operations:

Fortunately, I think a similar solution can be used here, since mod_facl only wants to override/provide custom handlers for two specific filesystem operations -- and mod_vroot does not override those particular operations.

Castaglia added a commit that referenced this issue Feb 16, 2024
@Castaglia
Issue #1780: Make sure that mod_facl honors any other FS handlers' ca…
6362728 
…llbacks as needed.
@Castaglia
Copy link
Member

Can you try out #1781, see if it addresses your issue?

@cfiehe
Copy link
Author

cfiehe commented Feb 16, 2024 •
edited
Loading

Hi @Castaglia,
thanks a lot for your quick response. I have switched to the branch facl-vroot-issue1780

#12 0.265 Cloning into 'proftpd'...
#12 7.674 Switched to a new branch 'facl-vroot-issue1780'
#12 7.674 Branch 'facl-vroot-issue1780' set up to track remote branch 'facl-vroot-issue1780' from 'origin'.
[...]

Unfortunately, the result is still the same. All directories get filtered out and the trace gives again:

2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot readdir()
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot lstat() for path '/incoming'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot lstat() for path '/incoming'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/incoming'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/incoming'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/incoming/.ftpaccess'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/incoming/.ftpaccess'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-16 09:46:31,330 [16] <fsio:8>: using facl+system access() for path '/incoming'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/incoming'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/incoming'
2024-02-16 09:46:31,330 [16] <facl:5>: unable to retrieve ACL for '/incoming': [2] No such file or directory
2024-02-16 09:46:31,330 [16] <sftp:3>: unable to obtain directory listing for '/incoming': Permission denied
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot readdir()
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot lstat() for path '/prod'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot lstat() for path '/prod'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/prod'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/prod'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/prod/.ftpaccess'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/prod/.ftpaccess'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/.ftpaccess'
2024-02-16 09:46:31,331 [16] <fsio:8>: using facl+system access() for path '/prod'
2024-02-16 09:46:31,331 [16] <fsio:8>: using vroot stat() for path '/prod'
2024-02-16 09:46:31,331 [16] <fsio:8>: using vroot stat() for path '/prod'
2024-02-16 09:46:31,331 [16] <facl:5>: unable to retrieve ACL for '/prod': [2] No such file or directory
2024-02-16 09:46:31,331 [16] <sftp:3>: unable to obtain directory listing for '/prod': Permission denied
[...]

@Castaglia
Copy link
Member

These are interesting:

2024-02-16 09:46:31,330 [16] <fsio:8>: using facl+system access() for path '/incoming'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/incoming'
2024-02-16 09:46:31,330 [16] <fsio:8>: using vroot stat() for path '/incoming'
2024-02-16 09:46:31,330 [16] <facl:5>: unable to retrieve ACL for '/incoming': [2] No such file or directory
2024-02-16 09:46:31,330 [16] <sftp:3>: unable to obtain directory listing for '/incoming': Permission denied

I guess it is showing that mod_facl does, somehow, need to use mod_vroot path-unmangling logic in order to retrieve the POSIX ACL for the correct path.

@cfiehe
Copy link
Author

cfiehe commented Feb 16, 2024

Thanks for your efforts. So you suspect mod_vroot as the root source?

@Castaglia
Copy link
Member

Thanks for your efforts. So you suspect mod_vroot as the root source?

I'm not sure if it's only mod_vroot, or if there are interactions involved as well. I do know, however, that an update to mod_vroot, similar to what we're doing here for mod_facl, might be needed; see Castaglia/proftpd-mod_vroot#45

@cfiehe
Copy link
Author

cfiehe commented Feb 17, 2024

I built a new version that contains both of your modifications. The directories are still filtered out. The log looks a little bit different:

2024-02-17 18:17:05,628 [6825] <fsio:8>: using vroot+clamav readdir()
2024-02-17 18:17:05,628 [6825] <fsio:8>: using vroot+clamav lstat() for path '/incoming'
2024-02-17 18:17:05,628 [6825] <fsio:8>: using vroot+clamav lstat() for path '/incoming'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/incoming'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/incoming'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/incoming/.ftpaccess'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/incoming/.ftpaccess'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/.ftpaccess'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/.ftpaccess'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using facl+system access() for path '/incoming'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/incoming'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/incoming'
2024-02-17 18:17:05,629 [6825] <facl:5>: unable to retrieve ACL for '/incoming': [2] No such file or directory
2024-02-17 18:17:05,629 [6825] <sftp:3>: unable to obtain directory listing for '/incoming': Permission denied
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav readdir()
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav lstat() for path '/prod'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav lstat() for path '/prod'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/prod'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/prod'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/prod/.ftpaccess'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/prod/.ftpaccess'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/.ftpaccess'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/.ftpaccess'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using facl+system access() for path '/prod'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/prod'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/prod'
2024-02-17 18:17:05,629 [6825] <facl:5>: unable to retrieve ACL for '/prod': [2] No such file or directory
2024-02-17 18:17:05,629 [6825] <sftp:3>: unable to obtain directory listing for '/prod': Permission denied
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav readdir()
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav lstat() for path '/test'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav lstat() for path '/test'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/test'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/test'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/test/.ftpaccess'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/test/.ftpaccess'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/.ftpaccess'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/.ftpaccess'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using facl+system access() for path '/test'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/test'
2024-02-17 18:17:05,629 [6825] <fsio:8>: using vroot+clamav stat() for path '/test'
2024-02-17 18:17:05,629 [6825] <facl:5>: unable to retrieve ACL for '/test': [2] No such file or directory
2024-02-17 18:17:05,629 [6825] <sftp:3>: unable to obtain directory listing for '/test': Permission denied
[...]

@cfiehe
Copy link
Author

cfiehe commented Feb 17, 2024

When I deactivate and remove mod_clamav from the list of loaded modules, the directories are still not visible. If I got it right, I think that mod_clamav also overwrites the preexisting filesystem handlers. With a deactivated mod_clamav, the trace log gives the following:

2024-02-17 18:22:29,959 [12] <fsio:8>: using vroot+facl+system readdir()
2024-02-17 18:22:29,959 [12] <fsio:8>: using vroot+facl+system lstat() for path '/incoming'
2024-02-17 18:22:29,959 [12] <fsio:8>: using vroot+facl+system lstat() for path '/incoming'
2024-02-17 18:22:29,960 [12] <fsio:8>: using vroot+facl+system stat() for path '/incoming'
2024-02-17 18:22:29,960 [12] <fsio:8>: using vroot+facl+system stat() for path '/incoming'
2024-02-17 18:22:29,960 [12] <fsio:8>: using vroot+facl+system stat() for path '/incoming/.ftpaccess'
2024-02-17 18:22:29,960 [12] <fsio:8>: using vroot+facl+system stat() for path '/incoming/.ftpaccess'
2024-02-17 18:22:29,960 [12] <fsio:8>: using vroot+facl+system stat() for path '/.ftpaccess'
2024-02-17 18:22:29,960 [12] <fsio:8>: using vroot+facl+system stat() for path '/.ftpaccess'
2024-02-17 18:22:29,960 [12] <fsio:8>: using vroot+facl+system access() for path '/incoming'
2024-02-17 18:22:29,960 [12] <fsio:8>: using vroot+facl+system stat() for path '/incoming'
2024-02-17 18:22:29,960 [12] <fsio:8>: using vroot+facl+system stat() for path '/incoming'
2024-02-17 18:22:29,960 [12] <facl:5>: unable to retrieve ACL for '/incoming': [2] No such file or directory
2024-02-17 18:22:29,960 [12] <sftp:3>: unable to obtain directory listing for '/incoming': Permission denied
[...]

@Castaglia
Copy link
Member

The mod_clamav module does indeed provide some of its own filesystem handlers as well. Hmm.

I'm now contemplating trying a different approach, i.e. redoing the API that all of these modules use, such that their handlers are automatically merged/stacked, like I have been doing to mod_quotatab, mod_facl, mod_vroot. The benefit of this approach is that it would automatically apply to modules like mod_clamav, without modifications to that module, as well.

Would this solve this current issue, with mod_facl? Not by itself, no; I think mod_facl would still require a few other tweaks.

Castaglia added a commit that referenced this issue Mar 30, 2024
@Castaglia
Issue #1780: Refactor the FSIO API for registering custom FS handlers…
45b2044 
…, such that inheriting existing handlers is the default behavior.
Castaglia added a commit that referenced this issue Mar 30, 2024
@Castaglia
Issue #1780: Refactor the FSIO API for registering custom FS handlers…
824afde 
…, such that inheriting existing handlers is the default behavior.
Castaglia added a commit that referenced this issue Mar 30, 2024
@Castaglia
Issue #1780: Refactor the FSIO API for registering custom FS handlers…
07a7c85 
…, such that inheriting existing handlers is the default behavior.
Castaglia added a commit that referenced this issue Mar 30, 2024
@Castaglia
Issue #1780: Refactor the FSIO API for registering custom FS handlers…
471d3f3 
…, such that inheriting existing handlers is the default behavior.
Castaglia added a commit that referenced this issue Mar 30, 2024
@Castaglia
Issue #1780: Refactor the FSIO API for registering custom FS handlers…
dc50e7b 
…, such that inheriting existing handlers is the default behavior.
Castaglia added a commit that referenced this issue Mar 30, 2024
@Castaglia
Issue #1780: Refactor the FSIO API for registering custom FS handlers…
1db5835 
…, such that inheriting existing handlers is the default behavior.
@Castaglia
Copy link
Member

#1789 implements the refactoring of the FSIO API, so that modules like mod_quotatab, mod_facl, mod_vroot, mod_clamav need no additional tweaks to inherit/stack the previously registered FSIO callbacks. This will be the first part of addressing this particular issue.

I'll now start on the second part, which is getting mod_facl to somehow make use of mod_vroot internal path lookup/resolution machinery, so that the mod_facl FSIO callbacks work on the proper filesystem paths.

Castaglia added a commit that referenced this issue Mar 30, 2024
@Castaglia
Issue #1780: Refactor the FSIO API for registering custom FS handlers…
4aad05f 
…, such that inheriting existing handlers is the default behavior. (#1789)
Castaglia added a commit that referenced this issue Mar 30, 2024
@Castaglia
Issue #1780: Implement a new FSIO handler akin to the realpath(3) f…
c017ee2 
…unction, for resolving paths.

Most of the time, this will be a pass-through.  However, modules like mod_vroot
play games with filesystem paths, and other modules need a way to play by those
same rules.
@Castaglia
Copy link
Member

#1790 adds a new FSIO API, for resolving paths. Right now, only mod_facl will make use of it, in the FACL-specific callbacks, for verifying that it works as expected/desired.

The last part will be updating the mod_vroot module so that it provides a custom implementation for this new path resolver function.

Castaglia added a commit that referenced this issue Mar 30, 2024
@Castaglia
Issue #1780: Implement a new FSIO handler akin to the realpath(3) f…
184f7a7 
…unction, for resolving paths.

Most of the time, this will be a pass-through.  However, modules like mod_vroot
play games with filesystem paths, and other modules need a way to play by those
same rules.
Castaglia added a commit that referenced this issue Mar 30, 2024
@Castaglia
Issue #1780: Implement a new FSIO handler akin to the realpath(3) f…
61fce5b 
…unction, for resolving paths. (#1790)

Most of the time, this will be a pass-through.  However, modules like mod_vroot
play games with filesystem paths, and other modules need a way to play by those
same rules.
@Castaglia Castaglia mentioned this issue Mar 30, 2024
Merged
@Castaglia
Copy link
Member

Here's the last PR, for mod_vroot, to try: Castaglia/proftpd-mod_vroot#46

Using that, and then running your mod_facl test, do things work better?

@cfiehe
Copy link
Author

cfiehe commented Mar 31, 2024

Hi @Castaglia,
I built a new container image based on PROFTPD_VERSION="v1.3.9rc2-17-g61fce5bbf" and PROFTPD_MOD_VROOT_VERSION="fsio-realpath-impl-issue1780". I used the following in my virtual host:

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

Unfortunately, all files get still filtered out, even those to which the user has access to. The log looks promising, but there still seems to be something that does not consider the new way of looking up files:

2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42/abc/proftpd-1.3.8.zip'
[...]
2024-03-31 08:05:09,079 [64] <facl:5>: unable to retrieve ACL for '/srv/ftp/edsb.mycompany.de/c.fiehe/': [95] Operation not supported
2024-03-31 08:05:09,079 [64] <facl:3>: ACL retrieval operation not supported for '�', falling back to normal access check
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,079 [64] <facl:6>: normal access check for '�' failed: No such file or directory
2024-03-31 08:05:09,079 [64] <sftp:3>: unable to obtain directory listing for '..': Permission denied

@cfiehe
Copy link
Author

cfiehe commented Mar 31, 2024 

2024-03-31 08:05:08,171 [64] <ssh2:8>: using PAM service name 'sshd'
2024-03-31 08:05:08,171 [64] <ssh2:9>: loading host key from file '/etc/proftpd/ssh_host_rsa_key'
2024-03-31 08:05:08,173 [64] <ssh2:4>: using '/etc/proftpd/ssh_host_rsa_key' as RSA hostkey (2048 bits)
2024-03-31 08:05:08,173 [64] <ssh2:7>: client alive checks requested after 15 secs, up to 3 times
2024-03-31 08:05:08,173 [64] <redis:7>: sending command: SENTINEL
2024-03-31 08:05:08,174 [64] <redis:7>: SENTINEL reply: 2 elements
2024-03-31 08:05:08,174 [64] <redis:7>: sending command: QUIT
2024-03-31 08:05:08,174 [64] <redis:3>: error connecting to 10.2.59.156#26379: [io] Connection refused
2024-03-31 08:05:08,174 [64] <redis:3>: error connecting to 10.2.59.157#26379: [io] Connection refused
2024-03-31 08:05:08,174 [64] <redis:7>: sending command: PING
2024-03-31 08:05:08,175 [64] <redis:7>: PING reply: PONG
2024-03-31 08:05:08,175 [64] <redis:7>: sending command: INFO
2024-03-31 08:05:08,175 [64] <redis:7>: INFO reply: (text, 656 bytes)
2024-03-31 08:05:08,175 [64] <redis:9>: parsed Redis version 7 (major), 2 (minor), 3 (patch) out of INFO
2024-03-31 08:05:08,175 [64] <redis:7>: sending command: AUTH
2024-03-31 08:05:08,175 [64] <redis:7>: AUTH reply: OK
2024-03-31 08:05:08,175 [64] <redis:7>: sending command: SELECT
2024-03-31 08:05:08,175 [64] <redis:7>: SELECT reply: OK
2024-03-31 08:05:08,175 [64] <redis:7>: sending command: GET
2024-03-31 08:05:08,175 [64] <redis:7>: GET reply: nil
2024-03-31 08:05:08,175 [64] <ban:8>: no matching Redis entry found for name 10.2.4.14, type 2
2024-03-31 08:05:08,251 [64] <ssh2:5>: handling connection from SSH2 client 'WinSCP_release_6.3.1'
2024-03-31 08:05:08,251 [64] <ssh2:3>: unable to use 'blowfish-cbc' cipher: Must be explicitly requested via SFTPCiphers
2024-03-31 08:05:08,251 [64] <ssh2:3>: unable to use 'arcfour256' cipher: Must be explicitly requested via SFTPCiphers
2024-03-31 08:05:08,251 [64] <ssh2:3>: unable to use 'arcfour128' cipher: Must be explicitly requested via SFTPCiphers
2024-03-31 08:05:08,251 [64] <ssh2:3>: unable to use 'none' cipher: Must be explicitly requested via SFTPCiphers
2024-03-31 08:05:08,251 [64] <ssh2:3>: unable to use 'hmac-md5' digest: Must be explicitly requested via SFTPDigests
2024-03-31 08:05:08,251 [64] <ssh2:3>: unable to use 'hmac-md5-etm@openssh.com' digest: Must be explicitly requested via SFTPDigests
2024-03-31 08:05:08,251 [64] <ssh2:3>: unable to use 'hmac-md5-96' digest: Must be explicitly requested via SFTPDigests
2024-03-31 08:05:08,251 [64] <ssh2:3>: unable to use 'hmac-md5-96-etm@openssh.com' digest: Must be explicitly requested via SFTPDigests
2024-03-31 08:05:08,251 [64] <ssh2:3>: unable to use 'hmac-ripemd160' digest: Must be explicitly requested via SFTPDigests
2024-03-31 08:05:08,251 [64] <ssh2:3>: unable to use 'none' digest: Must be explicitly requested via SFTPDigests
2024-03-31 08:05:08,251 [64] <ssh2:9>: sending KEXINIT message to client
2024-03-31 08:05:08,252 [64] <ssh2:3>: sent SSH_MSG_KEXINIT (20) packet (1352 bytes)
2024-03-31 08:05:08,275 [64] <ssh2:3>: received SSH_MSG_KEXINIT (20) packet
2024-03-31 08:05:08,275 [64] <ssh2:9>: reading KEXINIT message from client
2024-03-31 08:05:08,275 [64] <ssh2:3>: first kex packet follows = false
2024-03-31 08:05:08,275 [64] <ssh2:9>: determining shared algorithms for SSH session
2024-03-31 08:05:08,275 [64] <ssh2:8>: client-sent key exchange algorithms: sntrup761x25519-sha512@openssh.com,curve448-sha512,curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group18-sha512,diffie-hellman-group17-sha512,diffie-hellman-group16-sha512,diffie-hellman-group15-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,rsa2048-sha256,rsa1024-sha1,diffie-hellman-group1-sha1,ext-info-c,kex-strict-c-v00@openssh.com
2024-03-31 08:05:08,275 [64] <ssh2:8>: server-sent key exchange algorithms: curve448-sha512,curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group18-sha512,diffie-hellman-group16-sha512,diffie-hellman-group14-sha256,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,rsa1024-sha1,ext-info-s,kex-strict-s-v00@openssh.com
2024-03-31 08:05:08,275 [64] <ssh2:8>: client-sent host key algorithms: ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-ed448,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-dss
2024-03-31 08:05:08,275 [64] <ssh2:8>: server-sent host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa
2024-03-31 08:05:08,275 [64] <ssh2:8>: client-sent client encryption algorithms: aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,chacha20-poly1305@openssh.com,aes128-gcm@openssh.com,aes256-gcm@openssh.com,3des-ctr,3des-cbc,blowfish-ctr,blowfish-cbc,arcfour256,arcfour128
2024-03-31 08:05:08,275 [64] <ssh2:8>: server-sent client encryption algorithms: chacha20-poly1305@openssh.com,aes256-ctr,aes192-ctr,aes128-ctr,aes256-gcm@openssh.com,aes128-gcm@openssh.com,aes256-cbc,aes192-cbc,aes128-cbc,cast128-cbc,3des-cbc
2024-03-31 08:05:08,275 [64] <ssh2:8>: client-sent server encryption algorithms: aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,chacha20-poly1305@openssh.com,aes128-gcm@openssh.com,aes256-gcm@openssh.com,3des-ctr,3des-cbc,blowfish-ctr,blowfish-cbc,arcfour256,arcfour128
2024-03-31 08:05:08,275 [64] <ssh2:8>: server-sent server encryption algorithms: chacha20-poly1305@openssh.com,aes256-ctr,aes192-ctr,aes128-ctr,aes256-gcm@openssh.com,aes128-gcm@openssh.com,aes256-cbc,aes192-cbc,aes128-cbc,cast128-cbc,3des-cbc
2024-03-31 08:05:08,275 [64] <ssh2:8>: client-sent client MAC algorithms: hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-etm@openssh.com
2024-03-31 08:05:08,275 [64] <ssh2:8>: server-sent client MAC algorithms: hmac-sha2-256,hmac-sha2-256-etm@openssh.com,hmac-sha2-512,hmac-sha2-512-etm@openssh.com,hmac-sha1,hmac-sha1-etm@openssh.com,hmac-sha1-96,hmac-sha1-96-etm@openssh.com,umac-64@openssh.com,umac-64-etm@openssh.com,umac-128@openssh.com,umac-128-etm@openssh.com
2024-03-31 08:05:08,275 [64] <ssh2:8>: client-sent server MAC algorithms: hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-etm@openssh.com
2024-03-31 08:05:08,275 [64] <ssh2:8>: server-sent server MAC algorithms: hmac-sha2-256,hmac-sha2-256-etm@openssh.com,hmac-sha2-512,hmac-sha2-512-etm@openssh.com,hmac-sha1,hmac-sha1-etm@openssh.com,hmac-sha1-96,hmac-sha1-96-etm@openssh.com,umac-64@openssh.com,umac-64-etm@openssh.com,umac-128@openssh.com,umac-128-etm@openssh.com
2024-03-31 08:05:08,275 [64] <ssh2:8>: client-sent client compression algorithms: none,zlib,zlib@openssh.com
2024-03-31 08:05:08,275 [64] <ssh2:8>: server-sent client compression algorithms: zlib@openssh.com,zlib,none
2024-03-31 08:05:08,275 [64] <ssh2:8>: client-sent server compression algorithms: none,zlib,zlib@openssh.com
2024-03-31 08:05:08,275 [64] <ssh2:8>: server-sent server compression algorithms: zlib@openssh.com,zlib,none
2024-03-31 08:05:08,275 [64] <ssh2:8>: client-sent client languages: 
2024-03-31 08:05:08,275 [64] <ssh2:8>: server-sent client languages: 
2024-03-31 08:05:08,275 [64] <ssh2:8>: client-sent server languages: 
2024-03-31 08:05:08,275 [64] <ssh2:8>: server-sent server languages: 
2024-03-31 08:05:08,275 [64] <ssh2:9>: waiting for a message of 3 types from client
2024-03-31 08:05:08,311 [64] <ssh2:9>: reading ECDH_INIT message from client
2024-03-31 08:05:08,313 [64] <ssh2:9>: writing ECDH_INIT message to client
2024-03-31 08:05:08,313 [64] <ssh2:3>: sent SSH_MSG_KEX_DH_REPLY (31) packet (640 bytes)
2024-03-31 08:05:08,313 [64] <ssh2:9>: sending NEWKEYS message to client
2024-03-31 08:05:08,313 [64] <ssh2:3>: sent SSH_MSG_NEWKEYS (21) packet (16 bytes)
2024-03-31 08:05:08,313 [64] <ssh2:9>: waiting for a message of 1 type from client
2024-03-31 08:05:08,399 [64] <ssh2:9>: setting session keys
2024-03-31 08:05:08,399 [64] <ssh2:9>: sending EXT_INFO message to client
2024-03-31 08:05:08,399 [64] <ssh2:3>: sent SSH_MSG_EXT_INFO (7) packet (192 bytes)
2024-03-31 08:05:08,399 [64] <ssh2:3>: received SSH_MSG_SERVICE_REQUEST (5) packet
2024-03-31 08:05:08,399 [64] <ssh2:10>: 'ssh-userauth' service requested
2024-03-31 08:05:08,399 [64] <ssh2:3>: sent SSH_MSG_SERVICE_ACCEPT (6) packet (64 bytes)
2024-03-31 08:05:08,567 [64] <ssh2:3>: received SSH_MSG_USER_AUTH_REQUEST (50) packet
2024-03-31 08:05:08,567 [64] <ssh2:10>: auth requested for user 'c.fiehe@edsb.mycompany.de', service 'ssh-connection', using method 'none'
2024-03-31 08:05:08,567 [64] <ssh2:9>: offering authentication methods: publickey,password
2024-03-31 08:05:08,567 [64] <ssh2:3>: sent SSH_MSG_USER_AUTH_FAILURE (51) packet (80 bytes)
2024-03-31 08:05:08,587 [64] <ssh2:3>: received SSH_MSG_USER_AUTH_REQUEST (50) packet
2024-03-31 08:05:08,587 [64] <ssh2:10>: auth requested for user 'c.fiehe@edsb.mycompany.de', service 'ssh-connection', using method 'publickey'
2024-03-31 08:05:08,587 [64] <redis:7>: sending command: GET
2024-03-31 08:05:08,588 [64] <redis:7>: GET reply: nil
2024-03-31 08:05:08,588 [64] <ban:8>: no matching Redis entry found for name c.fiehe@edsb.mycompany.de, type 3
2024-03-31 08:05:08,588 [64] <redis:7>: sending command: GET
2024-03-31 08:05:08,588 [64] <redis:7>: GET reply: nil
2024-03-31 08:05:08,588 [64] <ban:8>: no matching Redis entry found for name c.fiehe@edsb.mycompany.de@10.2.4.14, type 4
2024-03-31 08:05:08,588 [64] <ssh2:9>: client sent 'rsa-sha2-512' public key without signature
2024-03-31 08:05:08,589 [64] <ssh2:3>: sent SSH_MSG_USER_AUTH_PASSWD (60) packet (608 bytes)
2024-03-31 08:05:08,715 [64] <ssh2:3>: received SSH_MSG_USER_AUTH_REQUEST (50) packet
2024-03-31 08:05:08,715 [64] <ssh2:10>: auth requested for user 'c.fiehe@edsb.mycompany.de', service 'ssh-connection', using method 'publickey'
2024-03-31 08:05:08,715 [64] <redis:7>: sending command: GET
2024-03-31 08:05:08,716 [64] <redis:7>: GET reply: nil
2024-03-31 08:05:08,716 [64] <ban:8>: no matching Redis entry found for name c.fiehe@edsb.mycompany.de, type 3
2024-03-31 08:05:08,716 [64] <redis:7>: sending command: GET
2024-03-31 08:05:08,716 [64] <redis:7>: GET reply: nil
2024-03-31 08:05:08,716 [64] <ban:8>: no matching Redis entry found for name c.fiehe@edsb.mycompany.de@10.2.4.14, type 4
2024-03-31 08:05:08,716 [64] <ssh2:9>: client sent 'rsa-sha2-512' public key with signature
2024-03-31 08:05:08,716 [64] <ssh2:5>: checking key MD5 fingerprint against SFTPKeyBlacklist '/etc/proftpd/blacklist.dat'
2024-03-31 08:05:08,716 [64] <ssh2:2>: using SFTPAuthorizedUserKeys 'file:~/.ssh/authorized_keys' for public key authentication for user 'c.fiehe@edsb.mycompany.de'
2024-03-31 08:05:08,716 [64] <fsio:8>: using facl+system open() for path '/srv/ftp/edsb.mycompany.de/c.fiehe/.ssh/authorized_keys'
2024-03-31 08:05:08,718 [64] <fsio:8>: using facl+system fstat() for path '/srv/ftp/edsb.mycompany.de/c.fiehe/.ssh/authorized_keys'
2024-03-31 08:05:08,718 [64] <fsio:8>: using facl+system read() for path '/srv/ftp/edsb.mycompany.de/c.fiehe/.ssh/authorized_keys' (524288 bytes)
2024-03-31 08:05:08,718 [64] <ssh2:10>: failed to match key #1 from file '/srv/ftp/edsb.mycompany.de/c.fiehe/.ssh/authorized_keys'
2024-03-31 08:05:08,718 [64] <ssh2:10>: found matching public key for user 'c.fiehe@edsb.mycompany.de' in '/srv/ftp/edsb.mycompany.de/c.fiehe/.ssh/authorized_keys'
2024-03-31 08:05:08,718 [64] <fsio:8>: using facl+system lseek() for path '/srv/ftp/edsb.mycompany.de/c.fiehe/.ssh/authorized_keys'
2024-03-31 08:05:08,718 [64] <fsio:8>: using facl+system close() for path '/srv/ftp/edsb.mycompany.de/c.fiehe/.ssh/authorized_keys'
2024-03-31 08:05:08,719 [64] <ssh2:8>: verified public key for user 'c.fiehe@edsb.mycompany.de'
2024-03-31 08:05:08,723 [64] <fsio:8>: using facl+system lstat() for path '/'
2024-03-31 08:05:08,724 [64] <fsio:8>: using facl+system lstat() for path '/srv'
2024-03-31 08:05:08,724 [64] <fsio:8>: using facl+system lstat() for path '/srv/ftp'
2024-03-31 08:05:08,724 [64] <fsio:8>: using facl+system lstat() for path '/srv/ftp/edsb.mycompany.de'
2024-03-31 08:05:08,724 [64] <fsio:8>: using facl+system lstat() for path '/srv/ftp/edsb.mycompany.de/c.fiehe'
2024-03-31 08:05:08,724 [64] <fsio:8>: using facl+system stat() for path '/srv/ftp/edsb.mycompany.de/c.fiehe'
2024-03-31 08:05:08,724 [64] <fsio:8>: using facl+system stat() for path '/srv/ftp/edsb.mycompany.de/c.fiehe'
2024-03-31 08:05:08,724 [64] <fsio:8>: using facl+system lstat() for path '/'
2024-03-31 08:05:08,724 [64] <fsio:8>: using facl+system lstat() for path '/srv'
2024-03-31 08:05:08,724 [64] <fsio:8>: using facl+system lstat() for path '/srv/ftp'
2024-03-31 08:05:08,724 [64] <fsio:8>: using facl+system lstat() for path '/srv/ftp/edsb.mycompany.de'
2024-03-31 08:05:08,724 [64] <fsio:8>: using facl+system lstat() for path '/srv/ftp/edsb.mycompany.de/c.fiehe'
2024-03-31 08:05:08,724 [64] <fsio:8>: using vroot+facl+system chroot() for path '/srv/ftp/edsb.mycompany.de/c.fiehe'
2024-03-31 08:05:08,724 [64] <fsio:8>: using vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,724 [64] <fsio:8>: using vroot+facl+system chdir() for path '/'
2024-03-31 08:05:08,724 [64] <fsio:8>: using vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,724 [64] <fsio:8>: using vroot+facl+system stat() for path '/'
2024-03-31 08:05:08,724 [64] <fsio:8>: using vroot+facl+system stat() for path '/'
2024-03-31 08:05:08,724 [64] <fsio:8>: using vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:08,724 [64] <fsio:8>: using vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:08,724 [64] <fsio:8>: using vroot+facl+system stat() for path '/'
2024-03-31 08:05:08,724 [64] <fsio:8>: using vroot+facl+system stat() for path '/'
2024-03-31 08:05:08,724 [64] <fsio:8>: using vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:08,724 [64] <fsio:8>: using vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:08,724 [64] <fsio:8>: using vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,725 [64] <ssh2:3>: sent SSH_MSG_USER_AUTH_SUCCESS (52) packet (48 bytes)
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system opendir() for path '/'
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42'
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42'
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42'
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42'
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42'
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system opendir() for path '/test42'
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42/abc'
2024-03-31 08:05:08,759 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42/abc'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42/abc'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42/abc'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42/abc'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system opendir() for path '/test42/abc'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42/abc/proftpd-1.3.8.zip'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42/abc/proftpd-1.3.8.zip'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system closedir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system closedir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/.ssh'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/.ssh'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/.ssh'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/.ssh'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/.ssh'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system opendir() for path '/.ssh'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/.ssh/authorized_keys'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/.ssh/authorized_keys'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system closedir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/Dockerfile'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/Dockerfile'
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system readdir()
2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system closedir()
2024-03-31 08:05:08,762 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:08,762 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:08,762 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:08,762 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:08,763 [64] <ssh2:3>: sent SSH_MSG_GLOBAL_REQUEST (80) packet (368 bytes)
2024-03-31 08:05:08,763 [64] <ssh2:3>: received SSH_MSG_CHANNEL_OPEN (90) packet
2024-03-31 08:05:08,763 [64] <ssh2:8>: open of 'session' channel using remote ID 256 requested: initial client window len = 2147483647 bytes, client max packet size = 16384 bytes
2024-03-31 08:05:08,763 [64] <ssh2:8>: confirm open channel remote ID 256, local ID 0: initial server window len = 4294967295 bytes, server max packet size = 32768 bytes
2024-03-31 08:05:08,763 [64] <ssh2:3>: sent SSH_MSG_CHANNEL_OPEN_CONFIRMATION (91) packet (64 bytes)
2024-03-31 08:05:08,847 [64] <ssh2:3>: received SSH_MSG_CHANNEL_REQUEST (98) packet
2024-03-31 08:05:08,847 [64] <ssh2:7>: received 'simple@putty.projects.tartarus.org' request for channel ID 0, want reply = false
2024-03-31 08:05:08,847 [64] <ssh2:3>: received SSH_MSG_CHANNEL_REQUEST (98) packet
2024-03-31 08:05:08,847 [64] <ssh2:7>: received 'subsystem' request for channel ID 0, want reply = true
2024-03-31 08:05:08,847 [64] <ssh2:3>: sent SSH_MSG_CHANNEL_SUCCESS (99) packet (48 bytes)
2024-03-31 08:05:08,943 [64] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2024-03-31 08:05:08,943 [64] <sftp:9>: reading SFTP data from SSH2 packet buffer (9 bytes)
2024-03-31 08:05:08,943 [64] <sftp:6>: received INIT (1) SFTP request (channel ID 0)
2024-03-31 08:05:08,943 [64] <sftp:7>: received request: INIT 6
2024-03-31 08:05:08,943 [64] <sftp:8>: sending response: VERSION 3
2024-03-31 08:05:08,943 [64] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 256, 296 data bytes)
2024-03-31 08:05:08,943 [64] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (352 bytes)
2024-03-31 08:05:08,959 [64] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2024-03-31 08:05:08,959 [64] <sftp:9>: reading SFTP data from SSH2 packet buffer (14 bytes)
2024-03-31 08:05:08,959 [64] <sftp:6>: received REALPATH (16) SFTP request (request ID 129552, channel ID 0)
2024-03-31 08:05:08,959 [64] <sftp:7>: received request: REALPATH /
2024-03-31 08:05:08,959 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,959 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:08,959 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:08,959 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:08,959 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:08,959 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,959 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,959 [64] <sftp:8>: sending response: NAME 1 / type=dir;size=50;UNIX.owner=1758007907;UNIX.group=1758007907;UNIX.mode=0700;access=20240331055515;modify=20240331055515;
2024-03-31 08:05:08,959 [64] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 256, 115 data bytes)
2024-03-31 08:05:08,959 [64] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (176 bytes)
2024-03-31 08:05:08,979 [64] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2024-03-31 08:05:08,979 [64] <sftp:9>: reading SFTP data from SSH2 packet buffer (14 bytes)
2024-03-31 08:05:08,979 [64] <sftp:6>: received LSTAT (7) SFTP request (request ID 129799, channel ID 0)
2024-03-31 08:05:08,979 [64] <sftp:7>: received request: LSTAT /
2024-03-31 08:05:08,979 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,979 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:08,979 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:08,979 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:08,979 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:08,979 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,979 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/'
2024-03-31 08:05:08,979 [64] <sftp:8>: sending response: ATTRS type=dir;size=50;UNIX.owner=1758007907;UNIX.group=1758007907;UNIX.mode=0700;access=20240331055515;modify=20240331055515;
2024-03-31 08:05:08,979 [64] <fsio:8>: using system llistxattr() for path '/'
2024-03-31 08:05:08,979 [64] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 256, 45 data bytes)
2024-03-31 08:05:08,979 [64] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (96 bytes)
2024-03-31 08:05:09,059 [64] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2024-03-31 08:05:09,059 [64] <sftp:9>: reading SFTP data from SSH2 packet buffer (14 bytes)
2024-03-31 08:05:09,059 [64] <sftp:6>: received OPENDIR (11) SFTP request (request ID 130059, channel ID 0)
2024-03-31 08:05:09,059 [64] <sftp:7>: received request: OPENDIR /
2024-03-31 08:05:09,059 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/'
2024-03-31 08:05:09,059 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/'
2024-03-31 08:05:09,059 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/'
2024-03-31 08:05:09,059 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:09,059 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:09,059 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:09,059 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:09,059 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/'
2024-03-31 08:05:09,059 [64] <fsio:8>: using quotatab+vroot+facl+system opendir() for path '/'
2024-03-31 08:05:09,060 [64] <sftp:8>: sending response: HANDLE cb8eafc228717990
2024-03-31 08:05:09,060 [64] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 256, 29 data bytes)
2024-03-31 08:05:09,060 [64] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (80 bytes)
2024-03-31 08:05:09,079 [64] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2024-03-31 08:05:09,079 [64] <sftp:9>: reading SFTP data from SSH2 packet buffer (29 bytes)
2024-03-31 08:05:09,079 [64] <sftp:6>: received READDIR (12) SFTP request (request ID 130316, channel ID 0)
2024-03-31 08:05:09,079 [64] <sftp:7>: received request: READDIR cb8eafc228717990
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system chdir() for path '/'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system readdir()
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '.'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '.'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '.'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '.'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path './.ftpaccess'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path './.ftpaccess'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system access() for path '.'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '.'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '.'
2024-03-31 08:05:09,079 [64] <fsio:8>: using vroot+facl+system realpath() for path '.'
2024-03-31 08:05:09,079 [64] <facl:5>: unable to retrieve ACL for '/srv/ftp/edsb.mycompany.de/c.fiehe/': [95] Operation not supported
2024-03-31 08:05:09,079 [64] <facl:3>: ACL retrieval operation not supported for '�', falling back to normal access check
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,079 [64] <facl:6>: normal access check for '�' failed: No such file or directory
2024-03-31 08:05:09,079 [64] <sftp:3>: unable to obtain directory listing for '.': Permission denied
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system readdir()
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '..'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '..'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '..'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '..'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '../.ftpaccess'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '../.ftpaccess'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system access() for path '..'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '..'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '..'
2024-03-31 08:05:09,079 [64] <fsio:8>: using vroot+facl+system realpath() for path '..'
2024-03-31 08:05:09,079 [64] <facl:5>: unable to retrieve ACL for '/srv/ftp/edsb.mycompany.de/c.fiehe/': [95] Operation not supported
2024-03-31 08:05:09,079 [64] <facl:3>: ACL retrieval operation not supported for '�', falling back to normal access check
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,079 [64] <facl:6>: normal access check for '�' failed: No such file or directory
2024-03-31 08:05:09,079 [64] <sftp:3>: unable to obtain directory listing for '..': Permission denied
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system readdir()
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/test42'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/test42'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/test42'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/test42'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/test42/.ftpaccess'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/test42/.ftpaccess'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system access() for path '/test42'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/test42'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/test42'
2024-03-31 08:05:09,080 [64] <fsio:8>: using vroot+facl+system realpath() for path '/test42'
2024-03-31 08:05:09,080 [64] <facl:5>: unable to retrieve ACL for '/srv/ftp/edsb.mycompany.de/c.fiehe/test42': [95] Operation not supported
2024-03-31 08:05:09,080 [64] <facl:3>: ACL retrieval operation not supported for '�', falling back to normal access check
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,080 [64] <facl:6>: normal access check for '�' failed: No such file or directory
2024-03-31 08:05:09,080 [64] <sftp:3>: unable to obtain directory listing for '/test42': Permission denied
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system readdir()
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/.ssh'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/.ssh'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ssh'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ssh'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ssh/.ftpaccess'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ssh/.ftpaccess'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ftpaccess'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system access() for path '/.ssh'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ssh'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/.ssh'
2024-03-31 08:05:09,080 [64] <fsio:8>: using vroot+facl+system realpath() for path '/.ssh'
2024-03-31 08:05:09,080 [64] <facl:5>: unable to retrieve ACL for '/srv/ftp/edsb.mycompany.de/c.fiehe/.ssh': [95] Operation not supported
2024-03-31 08:05:09,080 [64] <facl:3>: ACL retrieval operation not supported for '�', falling back to normal access check
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,080 [64] <facl:6>: normal access check for '�' failed: No such file or directory
2024-03-31 08:05:09,080 [64] <sftp:3>: unable to obtain directory listing for '/.ssh': Permission denied
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system readdir()
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/Dockerfile'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/Dockerfile'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/Dockerfile'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/Dockerfile'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '.ftpaccess'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '.ftpaccess'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system access() for path '/Dockerfile'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/Dockerfile'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/Dockerfile'
2024-03-31 08:05:09,080 [64] <fsio:8>: using vroot+facl+system realpath() for path '/Dockerfile'
2024-03-31 08:05:09,080 [64] <facl:5>: unable to retrieve ACL for '/srv/ftp/edsb.mycompany.de/c.fiehe/Dockerfile': [95] Operation not supported
2024-03-31 08:05:09,080 [64] <facl:3>: ACL retrieval operation not supported for '�', falling back to normal access check
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,080 [64] <facl:6>: normal access check for '�' failed: No such file or directory
2024-03-31 08:05:09,080 [64] <sftp:3>: unable to obtain directory listing for '/Dockerfile': Permission denied
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system readdir()
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system chdir() for path '/'
2024-03-31 08:05:09,080 [64] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/'
2024-03-31 08:05:09,080 [64] <sftp:8>: sending response: STATUS 1 'End of file'
2024-03-31 08:05:09,080 [64] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 256, 37 data bytes)
2024-03-31 08:05:09,080 [64] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (96 bytes)
2024-03-31 08:05:09,803 [64] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2024-03-31 08:05:09,803 [64] <sftp:9>: reading SFTP data from SSH2 packet buffer (29 bytes)
2024-03-31 08:05:09,803 [64] <sftp:6>: received CLOSE (4) SFTP request (request ID 130564, channel ID 0)
2024-03-31 08:05:09,803 [64] <sftp:7>: received request: CLOSE cb8eafc228717990
2024-03-31 08:05:09,803 [64] <fsio:8>: using quotatab+vroot+facl+system closedir()
2024-03-31 08:05:09,804 [64] <sftp:8>: sending response: STATUS 0 'OK'
2024-03-31 08:05:09,804 [64] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 256, 28 data bytes)
2024-03-31 08:05:09,804 [64] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (80 bytes)
2024-03-31 08:05:25,105 [64] <ssh2:9>: sending CHANNEL_REQUEST (remote channel ID 256, keepalive@proftpd.org)
2024-03-31 08:05:25,105 [64] <ssh2:3>: sent SSH_MSG_CHANNEL_REQUEST (98) packet (80 bytes)
2024-03-31 08:05:29,387 [64] <ssh2:3>: received SSH_MSG_CHANNEL_FAILURE (100) packet

Castaglia added a commit that referenced this issue Mar 31, 2024
@Castaglia
Issue #1780: Don't free the memory used for resolving the path when c…
fbafe5f 
…hecking POSIX ACLs until after all uses.
Castaglia added a commit that referenced this issue Mar 31, 2024
@Castaglia
Issue #1780: Don't free the memory used for resolving the path when c…
fcaf732 
…hecking POSIX ACLs until after all uses. (#1791)
@Castaglia
Copy link
Member

Castaglia commented Mar 31, 2024 •
edited
Loading

Hi @Castaglia, I built a new container image based on PROFTPD_VERSION="v1.3.9rc2-17-g61fce5bbf" and PROFTPD_MOD_VROOT_VERSION="fsio-realpath-impl-issue1780". I used the following in my virtual host:

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

Unfortunately, all files get still filtered out, even those to which the user has access to. The log looks promising, but there still seems to be something that does not consider the new way of looking up files:

2024-03-31 08:05:08,760 [64] <fsio:8>: using vroot+facl+system lstat() for path '/test42/abc/proftpd-1.3.8.zip'
[...]
2024-03-31 08:05:09,079 [64] <facl:5>: unable to retrieve ACL for '/srv/ftp/edsb.mycompany.de/c.fiehe/': [95] Operation not supported
2024-03-31 08:05:09,079 [64] <facl:3>: ACL retrieval operation not supported for '�', falling back to normal access check
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system stat() for path '�'
2024-03-31 08:05:09,079 [64] <facl:6>: normal access check for '�' failed: No such file or directory
2024-03-31 08:05:09,079 [64] <sftp:3>: unable to obtain directory listing for '..': Permission denied

Thanks! There's some garbled characters in these log messages, which should now be fixed via #1791.

If you try this again, and see it happen again like the above, you should also see something like:

2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system access() for path '/srv/ftp/edsb.mycompany.de/c.fiehe/'

or:

2024-03-31 08:05:09,079 [64] <fsio:8>: using quotatab+vroot+facl+system faccess() for path '/srv/ftp/edsb.mycompany.de/c.fiehe/'

The difference being whether this is mod_facl's "access()" callback, or "faccess()" callback. Knowing which callback is seeing this issue would be useful information for me. Thanks!

Update: Ah, for the later provided logs, it looks to be the "access()" callback. Perfect.

Castaglia added a commit that referenced this issue Mar 31, 2024
@Castaglia
Issue #1780: Stylistic changes to make clearer the handling of "can't…
27f265a 
… do this operation" in mod_facl.
@cfiehe
Copy link
Author

cfiehe commented Apr 1, 2024 •
edited
Loading

It is working 😃. Now, the files to which the user has no access are filtered out and the other remain visible. This is the trace log of fsio:

2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system readdir()
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/Dockerfile'
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/Dockerfile'
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/Dockerfile'
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/Dockerfile'
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system stat() for path '.ftpaccess'
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system stat() for path '.ftpaccess'
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system access() for path '/Dockerfile'
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/Dockerfile'
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/Dockerfile'
2024-04-01 07:55:19,296 [11407] <fsio:8>: using vroot+facl+system realpath() for path '/Dockerfile'
2024-04-01 07:55:19,296 [11407] <facl:5>: unable to retrieve ACL for '/srv/ftp/myuser/Dockerfile': [95] Operation not supported
2024-04-01 07:55:19,296 [11407] <facl:3>: ACL retrieval operation not supported for '/srv/ftp/myuser/Dockerfile', falling back to normal access check
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/srv/ftp/myuser/Dockerfile'
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system stat() for path '/srv/ftp/myuser/Dockerfile'
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system readdir()
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system chdir() for path '/'
2024-04-01 07:55:19,296 [11407] <fsio:8>: using quotatab+vroot+facl+system lstat() for path '/'
2024-04-01 07:55:19,296 [11407] <sftp:8>: sending response: NAME (1 count)

In the home directory of myuser exists a Dockerfile that is owned by root with access mode 0644 (rw-r--r--):

$ sftp -P 22 myuser@secdata-t.mycompany.de
myuser@secdata-t.mycompany.de's password:
Connected to secdata-t.mycompany.de.
sftp> ls -la
-rw-r--r--    1 root     root         2393 Nov 23 09:53 Dockerfile

When I remove the read permission for everyone and change it e.g. to 0640 (rw-r-----), the file gets filtered out 👍:

sftp> ls
sftp>

Thank you very much for your efforts!

@Castaglia Castaglia changed the title FACL broken in combination with mod_vroot Using mod_facl and mod_vroot at same time causes unexpected permissions issues Apr 3, 2024
Castaglia added a commit that referenced this issue Apr 3, 2024
@Castaglia
Updating NEWS for fix for Issue #1780.
c22345a
@cfiehe cfiehe mentioned this issue Apr 18, 2024
Closed
Castaglia added a commit that referenced this issue Apr 20, 2024
@Castaglia
Issue #1792: Use the new pr_fsio_realpath() function implemented in…
4fac72e 
… Issue #1780 in the `statvfs(2)` system calls in mod_sftp.
@Castaglia Castaglia mentioned this issue Apr 20, 2024
Merged
Castaglia added a commit that referenced this issue Apr 20, 2024
@Castaglia
Issue #1792: Use the new pr_fsio_realpath() function implemented in…
4f131c6 
… Issue #1780 in the `statvfs(2)` system calls in mod_sftp. (#1795)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Castaglia Castaglia

Labels
bug
Projects
None yet
Milestone
1.3.9
Development

No branches or pull requests
2 participants
@Castaglia @cfiehe