The Issue
I'm facing an issue that my ProFTPD server is canceling an FTP user's request when the user tries to, for example, delete a 1000 files from the server and disconnects them from the server.
Filezilla shows in the message log something like this:
Deleting file 1 - Successful
Deleting file 2 - Successful
...
Connection closed by server
Connecting to server again
...
Deleting file 1 again - file not found
Deleteing file 2 again - file not found
...
After about 500 failed delete actions, the connection is closed by the server.
I've tested this inside our firm with filezilla connected to the local server IP, so no firewall is between the server and client.
Is there a setting for ProFTPD that limits delete actions for all FTP users?
The only time this doesn't happen is when I do this as the root user.
Server configuration
Ubuntu Linux 16.04.1
ProFTPd v 1.35
Virtualmin GPL latest
I've checked the ProFTPD config file for any relevant settings, but couldn't find any.
Any ideas what could cause this?
UPDATE
The xferlog file doesn't show anything but transfers (doesn't show errors) so nothing really useful there.
Typical message is something like this:
Wed Aug 08 11:53:31 2018 0 192.168.144.166 164276 /home/virtual_server_name/public_html/wp-content/uploads/2018/test/image_330746-1024x768.jpg b _ d r virtual_server_name ftps 0 * c
The proftpd.log shows only connections:
2018-08-08 11:53:31,286 domain.com proftpd[12636] localhost (192.168.144.166[192.168.144.166]): FTP session opened.
2018-08-08 11:53:31,345 domain.com proftpd[12636] localhost (192.168.144.166[192.168.144.166]): USER virtual_server_user: Login successful.
2018-08-08 11:53:32,824 domain.com proftpd[12636] localhost (192.168.144.166[192.168.144.166]): FTP session closed.
UPDATE 2 Upon further inspection, it seems that this is somehow connected to TLS since the same users, when connected via plain FTP, don't experience the same issue. That is, they don't get suddenly disconnected when deleting many files.
UPDATE 3 When debugging is enabled, the detailed log shows this:
dispatching PRE_CMD command 'DELE image_344312_9-1024x576.jpg' to mod_exec
dispatching PRE_CMD command 'DELE image_344312_9-1024x576.jpg' to mod_rewrite
dispatching PRE_CMD command 'DELE image_344312_9-1024x576.jpg' to mod_tls
dispatching PRE_CMD command 'DELE image_344312_9-1024x576.jpg' to mod_core
dispatching PRE_CMD command 'DELE image_344312_9-1024x576.jpg' to mod_core
dispatching PRE_CMD command 'DELE image_344312_9-1024x576.jpg' to mod_quotatab
dispatching PRE_CMD command 'DELE image_344312_9-1024x576.jpg' to mod_log
dispatching CMD command 'DELE image_344312_9-1024x576.jpg' to mod_core
in dir_check_full(): path = '/public_html/wp-content/uploads/2018/bla/image_344312_9-1024x576.jpg', fullpath = '/home/domain.com/public_html/wp-content/uploads/2018/bla/image_344312_9-1024x576.jpg'.
in dir_check_full(): setting umask to 0022 (was 0022)
dispatching POST_CMD command 'DELE image_344312_9-1024x576.jpg' to mod_exec
dispatching POST_CMD command 'DELE image_344312_9-1024x576.jpg' to mod_quotatab
dispatching LOG_CMD command 'DELE image_344312_9-1024x576.jpg' to mod_log
Basically I get 500-1000 of such log sections (1 for each file that was deleted)
Then comes the interesting part:
ROOT PRIVS at mod_auth_pam.c:201
RELINQUISH PRIVS at mod_auth_pam.c:228
mod_tls/2.6: scrubbing 1 passphrase from memory
FTP session closed.
ROOT PRIVS at main.c:1227
RELINQUISH PRIVS at main.c:1231
no matching vhost found for ::ffff:192.168.144.12#21, using 'Debian' listening on wildcard address
ROOT PRIVS at main.c:1034
SETUP PRIVS at main.c:1039
session requested from client in unknown class
performing module session initializations
mod_unique_id/0.2: generating unique session ID
mod_unique_id/0.2: unique session ID is 'W2vyzn8AAAHAqJCmAAB+Gt0I'
ROOT PRIVS at mod_tls.c:2199
RELINQUISH PRIVS at mod_tls.c:2225
mod_tls/2.6: supporting TLSv1, TLSv1.1, TLSv1.2 protocols
ROOT PRIVS at mod_tls.c:2865
RELINQUISH PRIVS at mod_tls.c:2874
ROOT PRIVS at mod_tls.c:2930
RELINQUISH PRIVS at mod_tls.c:2932
ROOT PRIVS at mod_tls.c:3015
RELINQUISH PRIVS at mod_tls.c:3537
mod_cap/1.1: adding CAP_AUDIT_WRITE capability
mod_ident/1.0: ident lookup disabled
ROOT PRIVS at mod_delay.c:1756
RELINQUISH PRIVS at mod_delay.c:1759
ROOT PRIVS at mod_log.c:2105
RELINQUISH PRIVS at mod_log.c:2108
ROOT PRIVS at mod_auth.c:142
opening scoreboard '/run/proftpd.scoreboard'
RELINQUISH PRIVS at mod_auth.c:144
connected - local : ::ffff:192.168.144.12:21
connected - remote : 192.168.144.166:61300
FTP session opened.
dispatching PRE_CMD command 'AUTH TLS' to mod_exec
dispatching PRE_CMD command 'AUTH TLS' to mod_rewrite
dispatching PRE_CMD command 'AUTH TLS' to mod_tls
dispatching PRE_CMD command 'AUTH TLS' to mod_core
dispatching PRE_CMD command 'AUTH TLS' to mod_core
dispatching CMD command 'AUTH TLS' to mod_tls
dispatching POST_CMD command 'AUTH TLS' to mod_exec
dispatching LOG_CMD command 'AUTH TLS' to mod_log
dispatching PRE_CMD command 'USER domain.com' to mod_exec
dispatching PRE_CMD command 'USER domain.com' to mod_rewrite
dispatching PRE_CMD command 'USER domain.com' to mod_tls
dispatching PRE_CMD command 'USER domain.com' to mod_core
dispatching PRE_CMD command 'USER domain.com' to mod_core
dispatching PRE_CMD command 'USER domain.com' to mod_delay
dispatching PRE_CMD command 'USER domain.com' to mod_auth
dispatching CMD command 'USER domain.com' to mod_ratio
dispatching CMD command 'USER domain.com' to mod_auth
dispatching POST_CMD command 'USER domain.com' to mod_exec
dispatching POST_CMD command 'USER domain.com' to mod_delay
dispatching LOG_CMD command 'USER domain.com' to mod_log
dispatching PRE_CMD command 'PASS (hidden)' to mod_exec
dispatching PRE_CMD command 'PASS (hidden)' to mod_rewrite
dispatching PRE_CMD command 'PASS (hidden)' to mod_tls
dispatching PRE_CMD command 'PASS (hidden)' to mod_core
dispatching PRE_CMD command 'PASS (hidden)' to mod_core
dispatching PRE_CMD command 'PASS (hidden)' to mod_ifsession
retrieved UID 1058 for user 'domain.com'
retrieved group 'domain.com' for GID 1015
retrieved group ID: 1015
retrieved group name: domain.com
dispatching PRE_CMD command 'PASS (hidden)' to mod_shaper
ROOT PRIVS at mod_shaper.c:2026
RELINQUISH PRIVS at mod_shaper.c:2028
dispatching PRE_CMD command 'PASS (hidden)' to mod_wrap2
dispatching PRE_CMD command 'PASS (hidden)' to mod_ban
dispatching PRE_CMD command 'PASS (hidden)' to mod_wrap
dispatching PRE_CMD command 'PASS (hidden)' to mod_radius
dispatching PRE_CMD command 'PASS (hidden)' to mod_delay
dispatching PRE_CMD command 'PASS (hidden)' to mod_auth
dispatching CMD command 'PASS (hidden)' to mod_auth
retrieved UID 1058 for user 'domain.com'
retrieved group ID: 1015
retrieved group name: domain.com
ROOT PRIVS at mod_auth_pam.c:344
RELINQUISH PRIVS at mod_auth_pam.c:514
user 'domain.com' authenticated by mod_auth_pam.c
ROOT PRIVS at auth.c:1310
RELINQUISH PRIVS at auth.c:1312
USER PRIVS 1058 at mod_auth.c:1363
RELINQUISH PRIVS at mod_auth.c:1365
Config for Debian:
IdentLookups
DeferWelcome
MultilineRFC2228
DefaultServer
ShowSymlinks
DisplayLogin
DisplayChdir
ListOptions
DenyFilter
PassivePorts
UserID
UserName
GroupID
GroupName
Umask
DirUmask
AllowOverwrite
TransferLog
SystemLog
QuotaEngine
Ratios
DelayEngine
TLSRSACertificateFile
TLSRSACertificateKeyFile
TLSEngine
TLSCACertificateFile
DefaultRoot
RootLogin
IdentLookups
ServerIdent
UseFtpUsers
RequireValidShell
AllowOverwrite
ROOT PRIVS at mod_auth.c:1453
opening TransferLog '/var/log/proftpd/xferlog'
setting group ID: 1015
RELINQUISH PRIVS at mod_auth.c:1493
USER PRIVS 1058 at mod_auth.c:796
retrieved UID 1058 for user 'domain.com'
RELINQUISH PRIVS at mod_auth.c:799
set TZ environment variable to 'CET'
Preparing to chroot to directory '/home/domain.com'
ROOT PRIVS at auth.c:1424
RELINQUISH PRIVS at auth.c:1427
Environment successfully chroot()ed
ROOT PRIVS at mod_auth.c:1542
SETUP PRIVS at mod_auth.c:1564
in dir_check_full(): path = '/', fullpath = '/home/domain.com/'.
dispatching POST_CMD command 'PASS (hidden)' to mod_exec
dispatching POST_CMD command 'PASS (hidden)' to mod_ifsession
dispatching POST_CMD command 'PASS (hidden)' to mod_ratio
dispatching POST_CMD command 'PASS (hidden)' to mod_shaper
dispatching POST_CMD command 'PASS (hidden)' to mod_wrap2
dispatching POST_CMD command 'PASS (hidden)' to mod_ban
dispatching POST_CMD command 'PASS (hidden)' to mod_quotatab
dispatching POST_CMD command 'PASS (hidden)' to mod_radius
dispatching POST_CMD command 'PASS (hidden)' to mod_tls
dispatching POST_CMD command 'PASS (hidden)' to mod_cap
mod_cap/1.1: uid = 1058, euid = 1058, gid = 1015, egid = 1015
mod_cap/1.1: capabilities '= cap_chown,cap_setgid,cap_setuid,cap_net_bind_service,cap_audit_write+ep'
dispatching POST_CMD command 'PASS (hidden)' to mod_delay
dispatching POST_CMD command 'PASS (hidden)' to mod_log
dispatching POST_CMD command 'PASS (hidden)' to mod_ls
dispatching POST_CMD command 'PASS (hidden)' to mod_auth
unable to display DisplayLogin file 'welcome.msg': No such file or directory
dispatching POST_CMD command 'PASS (hidden)' to mod_rlimit
dispatching POST_CMD command 'PASS (hidden)' to mod_xfer
dispatching POST_CMD command 'PASS (hidden)' to mod_core
dispatching LOG_CMD command 'PASS (hidden)' to mod_log
dispatching LOG_CMD command 'PASS (hidden)' to mod_ratio
dispatching LOG_CMD command 'PASS (hidden)' to mod_readme
dispatching LOG_CMD command 'PASS (hidden)' to mod_auth
USER domain.com: Login successful.
dispatching PRE_CMD command 'OPTS UTF8 ON' to mod_exec
dispatching PRE_CMD command 'OPTS UTF8 ON' to mod_rewrite
dispatching PRE_CMD command 'OPTS UTF8 ON' to mod_tls
dispatching PRE_CMD command 'OPTS UTF8 ON' to mod_core
dispatching PRE_CMD command 'OPTS UTF8 ON' to mod_core
dispatching CMD command 'OPTS UTF8 ON' to mod_core
in dir_check_full(): path = '/', fullpath = '/home/domain.com/'.
dispatching PRE_CMD command 'OPTS_UTF8 ON' to mod_exec
dispatching PRE_CMD command 'OPTS_UTF8 ON' to mod_rewrite
dispatching PRE_CMD command 'OPTS_UTF8 ON' to mod_tls
dispatching PRE_CMD command 'OPTS_UTF8 ON' to mod_core
dispatching PRE_CMD command 'OPTS_UTF8 ON' to mod_core
dispatching CMD command 'OPTS_UTF8 ON' to mod_lang
mod_lang/1.0: Handling OPTS UTF8 ON (current encoding is 'UTF-8')
dispatching POST_CMD command 'OPTS_UTF8 ON' to mod_exec
dispatching LOG_CMD command 'OPTS_UTF8 ON' to mod_log
dispatching POST_CMD command 'OPTS UTF8 ON' to mod_exec
dispatching LOG_CMD command 'OPTS UTF8 ON' to mod_log
dispatching PRE_CMD command 'PBSZ 0' to mod_exec
dispatching PRE_CMD command 'PBSZ 0' to mod_rewrite
dispatching PRE_CMD command 'PBSZ 0' to mod_tls
dispatching PRE_CMD command 'PBSZ 0' to mod_core
dispatching PRE_CMD command 'PBSZ 0' to mod_core
dispatching CMD command 'PBSZ 0' to mod_tls
dispatching POST_CMD command 'PBSZ 0' to mod_exec
dispatching LOG_CMD command 'PBSZ 0' to mod_log
dispatching PRE_CMD command 'PROT P' to mod_exec
dispatching PRE_CMD command 'PROT P' to mod_rewrite
dispatching PRE_CMD command 'PROT P' to mod_tls
dispatching PRE_CMD command 'PROT P' to mod_core
dispatching PRE_CMD command 'PROT P' to mod_core
dispatching CMD command 'PROT P' to mod_tls
in dir_check_full(): path = '/', fullpath = '/home/domain.com/'.
dispatching POST_CMD command 'PROT P' to mod_exec
dispatching POST_CMD command 'PROT P' to mod_xfer
dispatching LOG_CMD command 'PROT P' to mod_log
And after it goes on the same as the 1st part of the log (deleting files) just with the additional message of unable to lstat /path/to/file No such file or directory
