Proftpd sftp setup disconnecting

[robbevaes2]

What I Did

We have proftpd server running with mod_sftp to be able to do sftp. We have a number of clients running jobs to send data to this proftpd server. However, we have noticed that we are getting a lot of random disconnects from the proftpd server. The client uses phpseclib and returns messages like:
Connection closed by server
No data received from server
Error reading from socket

This happens randomly and we are not able to steadily reproduce this. We have already tested everything on the network, which is all fine. Below are also log file output from the proftpd server. We are not able to see any more logs than the ones below:

2023-06-20 11:42:57,730 [435265] <ssh2:8>: verified public key for user xxxx
2023-06-20 11:42:57,734 [435265] <ssh2:19>: waiting for max of 600 secs while polling socket 1 for writing using select(2)
2023-06-20 11:42:57,734 [435265] <ssh2:3>: sent SSH_MSG_USER_AUTH_SUCCESS (52) packet (48 bytes)
2023-06-20 11:42:57,735 [435265] <ssh2:19>: waiting for max of 600 secs while polling socket 0 for reading using select(2)
2023-06-20 11:42:57,740 [435265] <ssh2:20>: SSH2 packet len = 28 bytes
2023-06-20 11:42:57,740 [435265] <ssh2:20>: SSH2 packet padding len = 8 bytes
2023-06-20 11:42:57,740 [435265] <ssh2:20>: SSH2 packet payload len = 19 bytes
2023-06-20 11:42:57,740 [435265] <ssh2:19>: waiting for max of 600 secs while polling socket 0 for reading using select(2)
2023-06-20 11:42:57,740 [435265] <ssh2:20>: SSH2 packet MAC len = 32 bytes
2023-06-20 11:42:57,740 [435265] <ssh2:19>: waiting for max of 600 secs while polling socket 0 for reading using select(2)
2023-06-20 11:42:57,740 [435265] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2023-06-20 11:42:57,740 [435265] <ssh2:8>: unable to handle data for channel ID 1: Permission denied
2023-06-20 11:42:57,740 [435265] <ssh2:9>: disconnecting (Application error) [at packet.c:1633]
2023-06-20 11:42:57,740 [435265] <ssh2:19>: waiting for max of 5 secs while polling socket 1 for writing using select(2)
2023-06-20 11:42:57,740 [435265] <ssh2:3>: sent SSH_MSG_DISCONNECT (1) packet (80 bytes)

What I Expected/Wanted

We want our jobs to not fail because of disconnects and more information on what unable to handle data for channel ID 1: Permission denied and disconnecting (Application error) [at packet.c:1633] mean or ways on how to troubleshoot this further.

ProFTPD Version and Configuration

Please help us reproduce the problem/issue you are encountering. To do this,
we need to know which version of ProFTPD you are using, how it was built,
etc. The following command is an easy way to get all of this information:

Compile-time Settings:
  Version: 1.3.6e (maint)
  Platform: LINUX [Linux 4.18.0-425.19.2.el8_7.x86_64 x86_64]
  Built: Mon Aug 1 2022 13:09:36 UTC
  Built With:
    configure  '--build=x86_64-redhat-linux-gnu' '--host=x86_64-redhat-linux-gnu' '--program-prefix=' '--disable-dependency-tracking' '--prefix=/usr' '--exec-prefix=/usr' '--bindir=/usr/bin' '--sbindir=/usr/sbin' '--sysconfdir=/etc' '--datadir=/usr/share' '--includedir=/usr/include' '--libdir=/usr/lib64' '--libexecdir=/usr/libexec' '--localstatedir=/var' '--sharedstatedir=/var/lib' '--mandir=/usr/share/man' '--infodir=/usr/share/info' '--libexecdir=/usr/libexec/proftpd' '--localstatedir=/run/proftpd' '--disable-strip' '--enable-ctrls' '--enable-dso' '--enable-facl' '--enable-ipv6' '--enable-memcache' '--enable-nls' '--enable-openssl' '--disable-pcre' '--disable-redis' '--enable-shadow' '--enable-tests=nonetwork' '--with-libraries=/usr/lib64/mariadb' '--with-includes=/usr/include/mysql' '--with-modules=mod_readme:mod_auth_pam:mod_tls' '--with-shared=mod_sql:mod_sql_passwd:mod_sql_mysql:mod_sql_postgres:mod_sql_sqlite:mod_quotatab:mod_quotatab_file:mod_quotatab_ldap:mod_quotatab_radius:mod_quotatab_sql:mod_ldap:mod_ban:mod_ctrls_admin:mod_facl:mod_load:mod_vroot:mod_radius:mod_ratio:mod_rewrite:mod_site_misc:mod_exec:mod_shaper:mod_wrap2:mod_wrap2_file:mod_wrap2_sql:mod_copy:mod_deflate:mod_ifversion:mod_qos:mod_sftp:mod_sftp_pam:mod_sftp_sql:mod_tls_shmcache:mod_tls_memcache:mod_unique_id:mod_ifsession' 'build_alias=x86_64-redhat-linux-gnu' 'host_alias=x86_64-redhat-linux-gnu' 'CFLAGS=-O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection' 'LDFLAGS=-Wl,-z,relro  -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld' 'CXXFLAGS=-O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection'

  CFLAGS: -g2 -O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -Wall -fno-omit-frame-pointer -Werror=implicit-function-declaration
  LDFLAGS: -L$(top_srcdir)/lib -Wl,-z,relro  -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -rdynamic -L/usr/lib64/mariadb -L/usr/lib64/ -L/usr/lib64
  LIBS: -lacl  -lssl -lcrypto -lcap  -lssl -lcrypto  -lpam -lsupp -lattr -lresolv -lresolv -lcrypt -ldl -lmemcachedutil -lmemcached

  Files:
    Configuration File:
      /etc/proftpd.conf
    Pid File:
      /run/proftpd/proftpd.pid
    Scoreboard File:
      /run/proftpd/proftpd.scoreboard
    Header Directory:
      /usr/include/proftpd
    Shared Module Directory:
      /usr/libexec/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
    - Redis support
    - Sodium support
    + OpenSSL support (FIPS enabled)
    - PCRE support
    + POSIX ACL support
    + Shadow file support
    + Sendfile support
    + Trace support
    + xattr support

  Tunable Options:
    PR_TUNABLE_BUFFER_SIZE = 1024
    PR_TUNABLE_DEFAULT_RCVBUFSZ = 8192
    PR_TUNABLE_DEFAULT_SNDBUFSZ = 8192
    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

In addition, we need to see all of the ProFTPD configuration files you are
using (minus any sensitive information like passwords, of course). Armed
with the version and configuration data, then, we can set up ProFTPD locally
using the same configuration, and see what happens.

This is the config of our sftp:

<VirtualHost HOST IP>

Include /etc/proftpd/users.d/HOSTIP_22.conf

ServerName                      "Name"
ServerIdent                     on "FTP server ready"
ServerAdmin                     Name
Port                            22

DisplayLogin                    welcome.msg
PathDenyFilter                  \.ftp[a-z]+$

<IfModule mod_sftp.c>
SFTPEngine                      on
SFTPLog                         /data/logs/proftpd/sftp/sftp.log

SFTPHostKey                     /etc/proftpd/ssl/ssh_host_rsa_key
SFTPHostKey                     /etc/proftpd/ssl/ssh_host_ecdsa_key
#  Note that this option first appeared in proftpd-1.3.6rc1.
#InsecureHostKeyPerms            false
SFTPClientMatch                 WinSCP|ClientSftp sftpProtocolVersion 1-3
SFTPCompression                 delayed

SFTPClientMatch                 ".*XFB.*" sftpProtocolVersion 1-3 channelWindowSize 256MB
SFTPClientMatch                 ".*SecureBlackbox.*" sftpProtocolVersion 1-3
</IfModule>

Umask                           0006 0007

DeleteAbortedStores             on
MaxClientsPerHost               45
MaxLoginAttempts                6
DefaultRoot                     ~
AllowOverwrite                  on


TimesGMT                        off

TransferLog                     /data/logs/proftpd/sftp/HOSTIP_22_xferlog
ExtendedLog                     /data/logs/proftpd/sftp/HOSTIP_22_commands.log all
WtmpLog                         off

<Limit WRITE>
  DenyUser Name
  DenyGroup readonly
</Limit>
</VirtualHost>

[Castaglia]

Very interesting, and perplexing.

There's only one place in the mod_sftp code where the "unable to handle data for channel" trace log message occurs:

• https://github.com/proftpd/proftpd/blob/master/contrib/mod_sftp/channel.c#L545

In this code path, we have received a CHANNEL_DATA SSH message from the client. Each channel is identified by a number, which is provided to the client, by the server (mod_sftp) in response to a CHANNEL_OPEN request from the client. A CHANNEL_DATA SSH message, then, provides the channel ID, and the payload of data for that channel.

Under what conditions would we log "unable to handle data for channel N: Permission denied", though? The only way that happens is if this condition is reached:

• https://github.com/proftpd/proftpd/blob/master/contrib/mod_sftp/channel.c#L168

Here, we are looking up the channel context/info for the channel ID that the client provided. If we don't have any currently open channels, though, we return the EACCES error ("Permission denied"). This indicates that, for some reason, the client is sending us a CHANNEL_DATA message for a channel that we've never seen/opened. And that is very confusing.

Do you perhaps have a load balancer in front of your ProFTPD, such that there are several different servers/processes, and a given client might connect to a different server over its lifetime? Or maybe the client opens multiple concurrent SFTP connections via threads, and the thread state is getting mixed up?

[kevinreniers]

Thanks for your investigation so far. I'm working together with @robbevaes2 to troubleshoot this issue on our stack.

Do you perhaps have a load balancer in front of your ProFTPD, such that there are several different servers/processes, and a given client might connect to a different server over its lifetime?

No, we're using a standalone ProFTPD server.

Or maybe the client opens multiple concurrent SFTP connections via threads, and the thread state is getting mixed up?

Client does open multiple concurrent connections, but from different processes. We have about 50-60 clients simultaneously doing this from multiple (10) processes each.

Additionally, it seems that phpseclib always uses the same channel ID after initializing the connection.