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.

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

extremely slow upload speed, using mod_sftp #1288

Open
bdimitrovITGix opened this issue Aug 6, 2021 · 33 comments
Open

extremely slow upload speed, using mod_sftp #1288

bdimitrovITGix opened this issue Aug 6, 2021 · 33 comments
Assignees

Comments

@bdimitrovITGix
Copy link

bdimitrovITGix commented Aug 6, 2021

What I Did

Hello,

We are have a strange issue regarding upload speeds. Our proFTPD server is installed on a CentOS7 machine and is configured to use LDAP authentication and mod_sftp. It is running on a custom port- 2222.
Downloading is as expected, around 10MB/s when testing with 1GB file.
Uploading is no where near that, running at 300-500kb/s when testing with the same 1GB file.

At the same time, trying the standart SFTP on port 22 doe not have this problem. Upload and Download there is fast, as expected. This should mean that the issue is not in our Network.
No transfer limits have been set and enforcing such did not improve the UPLOAD speed.

I have tried it using FileZilla and Linux CLI as client connections.

What I Expected/Wanted

I have been banging my head for days now. Any help towards troubleshooting this will be much appreciated.

ProFTPD Version and Configuration

VERSION:

Compile-time Settings:
  Version: 1.3.5e (maint)
  Platform: LINUX [Linux 3.10.0-862.14.4.el7.x86_64 x86_64]
  Built: Wed Jan 31 2018 16:32:29 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' '--enable-pcre' '--enable-shadow' '--enable-tests' '--with-libraries=/usr/lib64/mysql' '--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_wrap:mod_ctrls_admin:mod_facl:mod_load:mod_vroot:mod_radius:mod_ratio:mod_rewrite:mod_site_misc:mod_exec:mod_shaper:mod_geoip: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_ifsession' 'build_alias=x86_64-redhat-linux-gnu' 'host_alias=x86_64-redhat-linux-gnu' 'CFLAGS=-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1  -m64 -mtune=generic' 'LDFLAGS=-Wl,-z,relro -specs=/usr/lib/rpm/redhat/redhat-hardened-ld' 'CXXFLAGS=-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1  -m64 -mtune=generic'

  CFLAGS: -O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1  -m64 -mtune=generic -Wall
  LDFLAGS: -L$(top_srcdir)/lib -Wl,-z,relro -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -L/usr/lib64/mysql -L/usr/lib64/mysql -L/usr/lib64
  LIBS: -lacl  -lpcreposix -lpcre -lssl -lcrypto -lssl -lcrypto -lcap  -lmemcached -lmemcachedutil  -lssl -lcrypto  -lpam -lsupp -lcrypt -ldl 

  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

  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 (FIPS enabled)
    + PCRE support
    + POSIX ACL support
    + Shadow file support
    + Sendfile support
    + Trace support

  Tunable Options:
    PR_TUNABLE_BUFFER_SIZE = 1024
    PR_TUNABLE_DEFAULT_RCVBUFSZ = 8192
    PR_TUNABLE_DEFAULT_SNDBUFSZ = 8192
    PR_TUNABLE_GLOBBING_MAX_MATCHES = 100000
    PR_TUNABLE_GLOBBING_MAX_RECURSION = 8
    PR_TUNABLE_HASH_TABLE_SIZE = 40
    PR_TUNABLE_NEW_POOL_SIZE = 512
    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 = 30
    PR_TUNABLE_TIMEOUTLOGIN = 300
    PR_TUNABLE_TIMEOUTNOXFER = 300
    PR_TUNABLE_TIMEOUTSTALLED = 3600
    PR_TUNABLE_XFER_SCOREBOARD_UPDATES = 10

CONFOGURATION FILE:

LoadModule mod_ldap.c
LoadModule mod_sftp.c
LoadModule mod_vroot.c
LogFormat                       default "%h %l %u %t \"%r\" %s %b"
LogFormat                       auth    "%v [%P] %h %t \"%r\" %s"
UseIPv6                         off
UseReverseDNS                   off
ServerName                      "X-X-X"
ServerType                      standalone
ServerAdmin                     system_logs@X.X
PersistentPasswd                off
TLSRequired                     off
AuthPAM                         off
Port                            2222
Umask                           002
RequireValidShell               off
DefaultRoot                     ~
CreateHome                      on
AllowOverwrite                  on

<IfModule mod_ldap.c>
	AuthOrder                     mod_ldap.c
	LDAPUseTLS                    off
	LDAPServer                    "X-X-X-X.X.X.X"
	LDAPBindDN                    "cn=X,dc=X" "X"
	LDAPAuthBinds                 off
	LDAPUsers                     "ou=X,ou=X,ou=X,ou=X,dc=X" "(&(uid=%u)(objectClass=posixAccount))"
	LDAPGenerateHomedir           on
	LDAPGenerateHomedirPrefix     /var/ftp
	LDAPLog                       /var/log/proftpd/ldap.log
</IfModule>

<IfModule mod_sftp.c>
	SFTPEngine                    on
	SFTPHostKey                   /etc/proftpd/host_keys/proftpd_host_ecdsa_key
	SFTPHostKey                   /etc/proftpd/host_keys/proftpd_host_rsa_key
	SFTPLog                       /var/log/proftpd/sftp.log
	SFTPClientAlive               3 30
	SFTPAuthorizedUserKeys        file:/etc/proftpd/authorized_keys/%u
</IfModule>

<IfModule mod_vroot.c>
	VRootEngine                   on
</IfModule>

# Dynamic ban lists (http://www.proftpd.org/docs/contrib/mod_ban.html)
# Enable this with PROFTPD_OPTIONS=-DDYNAMIC_BAN_LISTS in /etc/sysconfig/proftpd
<IfDefine DYNAMIC_BAN_LISTS>
	LoadModule                    mod_ban.c
	BanEngine                     off
	BanLog                        /var/log/proftpd/ban.log
	BanTable                      /var/run/proftpd/ban.tab

	# If the same client reaches the MaxLoginAttempts limit 2 times
	# within 10 minutes, automatically add a ban for that client that
	# will expire after one hour.
	BanOnEvent                    MaxLoginAttempts 2/00:10:00 01:00:00

	# Inform the user that it's not worth persisting
	BanMessage                    "Host %a has been banned"

	# Allow the FTP admin to manually add/remove bans
	BanControlsACLs               all allow user ftpadm
</IfDefine>
@Castaglia
Copy link
Member

Can you provide the output from using the Linux CLI, e.g. what does sftp -vvv ... show, for one of these slow uploads? The extra -vvv information will produce verbose details about the SFTP protocol messages used; I'm hoping they can provide more clues.

@Castaglia Castaglia changed the title extremly slow upload speed, using mod_sftp extremely slow upload speed, using mod_sftp Aug 7, 2021
@bdimitrovITGix
Copy link
Author

sftp_log.txt

Hello,

I have attached a log from running sftp -vvv agains the proFTPD server. I have only inserted the log AFTER the connection has been established, on the actual upload. The speed gets up to 600kb/s today and then starts decreasing.

@bdimitrovITGix
Copy link
Author

Hello,
I have tested to upload both to the NFS share we use for FTP uploads an to a local directory in /home/XXX/.
Speed is still low.

@Castaglia
Copy link
Member

Unfortunately, the logs showing before the upload starts are also useful (including sftp/OpenSSH version); transfer speeds and server/client behavior are often determined by the various algorithms decided at connect time. And various OpenSSH client versions have been worse/better behavior over time, which is why knowing that version also helps answer your question.

@bdimitrovITGix
Copy link
Author

Hello,
Attaching those as-well.
after_connection.txt

@bdimitrovITGix
Copy link
Author

Hello,
Any ideas why this bandwidth "cap" might be happening? Could it be due to the sftp module somehow?

@bdimitrovITGix
Copy link
Author

Hello,
A quick update, as it appears my initial findings were not quite correct. It seems that the problem is only present when uploading to a NFS home directory.
I have since switched over to FTPS and there is no problem with the UP/DWN speeds.

Sadly, I am not in a position to try and upgrade proFTPD from 1.3.5e to a newer version but I have red that there might be some mod_sftp improvements in 1.3.6.

@Castaglia
Copy link
Member

There have been some other improvements for SFTP uploads in the 1.3.9 development cycle; in particular, we now avoid an expensive (and unnecessary) memory copy for each SFTP WRITE request:

I know you mentioned you may not be able to update ProFTPD yet, but I wanted you to know that I've not forgotten this issue.

@Castaglia Castaglia self-assigned this Oct 11, 2023
@cfiehe
Copy link

cfiehe commented Apr 20, 2024

Hi @Castaglia,
I think, I am facing the same issue that was reported by @bdimitrovITGix. The test setup consists of one client and one server machine in the same local network. The server is equipped with an OpenSSH_8.9p1 and a ProFTPD 1.3.9rc2-15-gebce2d375 (before the FSIO changes). The test case comprises the upload (PUT) of the Ubuntu Noble image followed by a download (GET). I have configured the same ciphers and digests, the servers use the same location for data access. The same CLI-based client was used. Both servers listen on different ports.

Upload command:

sftp -vvv -oBatchMode=no -b - myuser@filestore-srv1.mycompany.de << EOF
   put /root/noble-live-server-amd64.iso /srv/ftp/myuser
   bye
EOF

Download command:

sftp -vvv -oBatchMode=no -b - myuser@filestore-srv1.mycompany.de << EOF
   get /srv/ftp/myuser/noble-live-server-amd64.iso
   bye
EOF

Unfortunately, it seems that ProFTPD is approximately 4 to 5 times slower than OpenSSH.

ProFTPD upload: 102 s
ProFTPD download: 24 s
OpenSSH upload: 18 s
OpenSSH download: 6 s

It looks to me that different channel packet sizes (32768 vs. 261120) are used. But I am not sure, if I got that right.

@Castaglia Have you got an idea what is going wrong here?

I have attached the four output logs. I hope, that it helps to find the issue.

put-proftpd.log
get-proftpd.log
put-openssh.log
get-openssh.log

@a270443177
Copy link

ver:1.3.8 出现相同的问题

@cfiehe
Copy link

cfiehe commented Apr 23, 2024

I did some performance tests on a share mounted at /mnt/test via SSHFS from a system that runs ProFTPD v1.3.9rc2-22-g658233910 and OpenSSH_8.9p1. The mount command was the following:

sshfs -o ssh_command=ssh\\040-vvv,debug,sshfs_debug,loglevel=debug,allow_other,reconnect -p <22022|22> myuser@filestore-srv1.lx.mycompany.de:/srv/ftp/myuser /mnt/test

Write test:

dd if=/dev/zero of=/mnt/test/testfile bs=1G count=1 oflag=direct

Read test:

cp /mnt/test/testfile /var
ProFTPD (Write): 1073741824 bytes (1.1 GB, 1.0 GiB) copied, 38.1725 s, 28.1 MB/s
OpenSSH (Write): 1073741824 bytes (1.1 GB, 1.0 GiB) copied, 14.8472 s, 72.3 MB/s
ProFTPD (Read): 12 sec
OpenSSH (Read): 3 sec

These are the captured transfer logs:
sshfs-write-proftpd.log
sshfs-write-openssh.log
sshfs-read-proftpd.log
sshfs-read-openssh.log

@a270443177
Copy link

@cfiehe
"sftp -o Compression=no -o Ciphers=aes128-gcm@openssh.com -B 204800" adjust buffer size, speed fast

@Castaglia mod_sftp can auto adjust buffer size?
openssh sftp-server can auto adjust buffer size

openssh log===>

debug2: channel 0: rcvd adjust 98421
debug2: channel 0: rcvd adjust 98304
debug2: channel 0: rcvd adjust 81920
debug2: channel 0: rcvd adjust 49152
debug2: channel 0: rcvd adjust 16384
debug2: channel 0: rcvd adjust 16384
debug2: channel 0: rcvd adjust 32768
debug2: channel 0: rcvd adjust 32768
debug2: channel 0: rcvd adjust 16384
debug2: channel 0: rcvd adjust 16384
debug2: channel 0: rcvd adjust 32768
debug2: channel 0: rcvd adjust 32768
debug2: channel 0: rcvd adjust 32768
debug2: channel 0: rcvd adjust 114688

@cfiehe
Copy link

cfiehe commented Apr 24, 2024

@a270443177 Thanks for the hint.

I have modified the test case and used added the options -o Compression=no -o Ciphers=aes128-gcm@openssh.com -B 204800. It is getting better, but OpenSSH is still 2 times faster than ProFTPD:

ProFTPD upload: 29 s
ProFTPD download: 11 s
OpenSSH upload: 15 s
OpenSSH download: 7 s

So far, I have not found a way to increase buffer size in case of SSHFS.

@Castaglia
Copy link
Member

Castaglia commented Apr 25, 2024

@cfiehe FYI, I've now implemented the "limits@openssh.com" SFTP extension in mod_sftp, per Issue #1798. This should help the interactions with SSHFS.

With this, you should no longer need any client-side -B (or -R) command-line overrides. Those overrides specify the buffer lengths (and outstanding request count) that are negotiated via the limits@openssh.com extension -- and mod_sftp returns larger values than the -B value discussed here. Whether the OpenSSH SFTP client uses that full value, or something less, remains to be validated.

@a270443177
Copy link

a270443177 commented Apr 25, 2024

@Castaglia
OS: RHEL7.9

openssh-server-7.4p1-21.el7.x86_64
openssh-7.4p1-21.el7.x86_64
openssh-clients-7.4p1-21.el7.x86_64

sftp -vvvv

display this:
debug2: Unrecognised server extension "limits@openssh.com"
debug2: Unrecognised server extension "users-groups-by-id@openssh.com"

same speed

@cfiehe
Copy link

cfiehe commented Apr 25, 2024

That is awesome. Thank you very much @Castaglia. I did some testing. The handshake succeeds and I can login, but the upload fails with Outbound message too long 523301:

OpenSSH_8.9p1 Ubuntu-3ubuntu0.7, OpenSSL 3.0.2 15 Mar 2022
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: include /etc/ssh/ssh_config.d/*.conf matched no files
debug1: /etc/ssh/ssh_config line 21: Applying options for *
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts' -> '/root/.ssh/known_hosts'
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts2' -> '/root/.ssh/known_hosts2'
debug2: resolving "filestore.mycompany.de" port 22
debug3: resolve_host: lookup filestore.mycompany.de:22
debug3: ssh_connect_direct: entering
debug1: Connecting to filestore.mycompany.de [10.2.4.80] port 22.
debug3: set_sock_tos: set socket 3 IP_TOS 0x10
debug1: Connection established.
debug1: identity file /root/.ssh/id_rsa type -1
debug1: identity file /root/.ssh/id_rsa-cert type -1
debug1: identity file /root/.ssh/id_ecdsa type -1
debug1: identity file /root/.ssh/id_ecdsa-cert type -1
debug1: identity file /root/.ssh/id_ecdsa_sk type -1
debug1: identity file /root/.ssh/id_ecdsa_sk-cert type -1
debug1: identity file /root/.ssh/id_ed25519 type -1
debug1: identity file /root/.ssh/id_ed25519-cert type -1
debug1: identity file /root/.ssh/id_ed25519_sk type -1
debug1: identity file /root/.ssh/id_ed25519_sk-cert type -1
debug1: identity file /root/.ssh/id_xmss type -1
debug1: identity file /root/.ssh/id_xmss-cert type -1
debug1: identity file /root/.ssh/id_dsa type -1
debug1: identity file /root/.ssh/id_dsa-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_8.9p1 Ubuntu-3ubuntu0.7
debug1: Remote protocol version 2.0, remote software version mod_sftp
debug1: compat_banner: no match: mod_sftp
debug2: fd 3 setting O_NONBLOCK
debug1: Authenticating to filestore.mycompany.de:22 as 'myuser'
debug3: record_hostkey: found key type ED25519 in file /root/.ssh/known_hosts:18
debug3: record_hostkey: found key type ECDSA in file /root/.ssh/known_hosts:19
debug3: load_hostkeys_file: loaded 2 keys from filestore.mycompany.de
debug1: load_hostkeys: fopen /root/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
debug3: order_hostkeyalgs: have matching best-preference key type ssh-ed25519-cert-v01@openssh.com, using HostkeyAlgorithms verbatim
debug3: send packet: type 20
debug1: SSH2_MSG_KEXINIT sent
debug3: receive packet: type 20
debug1: SSH2_MSG_KEXINIT received
debug2: local client KEXINIT proposal
debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,sntrup761x25519-sha512@openssh.com,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,ext-info-c,kex-strict-c-v00@openssh.com
debug2: host key algorithms: ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,sk-ssh-ed25519-cert-v01@openssh.com,sk-ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ssh-ed25519@openssh.com,sk-ecdsa-sha2-nistp256@openssh.com,rsa-sha2-512,rsa-sha2-256
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: compression ctos: none,zlib@openssh.com,zlib
debug2: compression stoc: none,zlib@openssh.com,zlib
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug2: peer server KEXINIT proposal
debug2: KEX 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
debug2: host key algorithms: ssh-ed25519,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa
debug2: ciphers ctos: 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
debug2: ciphers stoc: 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
debug2: MACs ctos: 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
debug2: MACs stoc: 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
debug2: compression ctos: zlib@openssh.com,zlib,none
debug2: compression stoc: zlib@openssh.com,zlib,none
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug3: kex_choose_conf: will use strict KEX ordering
debug1: kex: algorithm: curve25519-sha256
debug1: kex: host key algorithm: ssh-ed25519
debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug3: send packet: type 30
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug3: receive packet: type 31
debug1: SSH2_MSG_KEX_ECDH_REPLY received
debug1: Server host key: ssh-ed25519 SHA256:ToODyXS66VHrDZBHR/UNjxv58kTRxiVW9NSv2iNVDCQ
debug3: record_hostkey: found key type ED25519 in file /root/.ssh/known_hosts:18
debug3: record_hostkey: found key type ECDSA in file /root/.ssh/known_hosts:19
debug3: load_hostkeys_file: loaded 2 keys from filestore.mycompany.de
debug1: load_hostkeys: fopen /root/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
debug1: Host 'filestore.mycompany.de' is known and matches the ED25519 host key.
debug1: Found key in /root/.ssh/known_hosts:18
debug3: send packet: type 21
debug1: ssh_packet_send2_wrapped: resetting send seqnr 3
debug2: ssh_set_newkeys: mode 1
debug1: rekey out after 134217728 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug3: receive packet: type 21
debug1: ssh_packet_read_poll2: resetting read seqnr 3
debug1: SSH2_MSG_NEWKEYS received
debug2: ssh_set_newkeys: mode 0
debug1: rekey in after 134217728 blocks
debug1: Will attempt key: /root/.ssh/id_rsa
debug1: Will attempt key: /root/.ssh/id_ecdsa
debug1: Will attempt key: /root/.ssh/id_ecdsa_sk
debug1: Will attempt key: /root/.ssh/id_ed25519
debug1: Will attempt key: /root/.ssh/id_ed25519_sk
debug1: Will attempt key: /root/.ssh/id_xmss
debug1: Will attempt key: /root/.ssh/id_dsa
debug2: pubkey_prepare: done
debug3: send packet: type 5
debug3: receive packet: type 7
debug1: SSH2_MSG_EXT_INFO received
debug1: kex_input_ext_info: server-sig-algs=<ssh-ed448,ssh-ed25519,rsa-sha2-256,rsa-sha2-512,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-rsa,ssh-dss>
debug3: receive packet: type 6
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug3: send packet: type 50
debug3: receive packet: type 51
debug1: Authentications that can continue: publickey,password
debug3: start over, passed a different list publickey,password
debug3: preferred gssapi-with-mic,publickey,keyboard-interactive,password
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Trying private key: /root/.ssh/id_rsa
debug3: no such identity: /root/.ssh/id_rsa: No such file or directory
debug1: Trying private key: /root/.ssh/id_ecdsa
debug3: no such identity: /root/.ssh/id_ecdsa: No such file or directory
debug1: Trying private key: /root/.ssh/id_ecdsa_sk
debug3: no such identity: /root/.ssh/id_ecdsa_sk: No such file or directory
debug1: Trying private key: /root/.ssh/id_ed25519
debug3: no such identity: /root/.ssh/id_ed25519: No such file or directory
debug1: Trying private key: /root/.ssh/id_ed25519_sk
debug3: no such identity: /root/.ssh/id_ed25519_sk: No such file or directory
debug1: Trying private key: /root/.ssh/id_xmss
debug3: no such identity: /root/.ssh/id_xmss: No such file or directory
debug1: Trying private key: /root/.ssh/id_dsa
debug3: no such identity: /root/.ssh/id_dsa: No such file or directory
debug2: we did not send a packet, disable method
debug3: authmethod_lookup password
debug3: remaining preferred: ,password
debug3: authmethod_is_enabled password
debug1: Next authentication method: password
myuser@filestore.mycompany.de's password:
debug3: send packet: type 50
debug2: we sent a password packet, wait for reply
debug3: receive packet: type 52
Authenticated to filestore.mycompany.de ([10.2.4.80]:22) using "password".
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug3: send packet: type 90
debug1: Entering interactive session.
debug1: pledge: filesystem
debug3: receive packet: type 80
debug1: client_input_global_request: rtype hostkeys-00@openssh.com want_reply 0
debug3: client_input_hostkeys: received RSA key SHA256:0S+ukF2Jlt6h9HyeD/IvgYsYC1OCFEailnli1aPNYwA
debug3: client_input_hostkeys: received ED25519 key SHA256:ToODyXS66VHrDZBHR/UNjxv58kTRxiVW9NSv2iNVDCQ
debug3: client_input_hostkeys: received ECDSA key SHA256:yedB41F+oOR/6fvDbvTSswLaTQwni5zKDdR/TIBvvh4
debug1: client_input_hostkeys: searching /root/.ssh/known_hosts for filestore.mycompany.de / (none)
debug3: hostkeys_foreach: reading file "/root/.ssh/known_hosts"
debug3: hostkeys_find: found ssh-ed25519 key at /root/.ssh/known_hosts:18
debug3: hostkeys_find: found ecdsa-sha2-nistp521 key at /root/.ssh/known_hosts:19
debug3: hostkeys_find: found ssh-rsa key under different name/addr at /root/.ssh/known_hosts:23
debug1: client_input_hostkeys: searching /root/.ssh/known_hosts2 for filestore.mycompany.de / (none)
debug1: client_input_hostkeys: hostkeys file /root/.ssh/known_hosts2 does not exist
debug3: client_input_hostkeys: 3 server keys: 1 new, 1 retained, 1 incomplete match. 0 to remove
debug1: client_input_hostkeys: host key found matching a different name/address, skipping UserKnownHostsFile update
debug3: receive packet: type 91
debug2: channel_input_open_confirmation: channel 0: callback start
debug2: fd 3 setting TCP_NODELAY
debug3: set_sock_tos: set socket 3 IP_TOS 0x08
debug2: client_session2_setup: id 0
debug1: Sending environment.
debug3: Ignored env SHELL
debug3: Ignored env no_proxy
debug3: Ignored env LANGUAGE
debug3: Ignored env PWD
debug3: Ignored env LOGNAME
debug3: Ignored env ftp_proxy
debug3: Ignored env HOME
debug1: channel 0: setting env LANG = "en_US.UTF-8"
debug2: channel 0: request env confirm 0
debug3: send packet: type 98
debug3: Ignored env LS_COLORS
debug3: Ignored env https_proxy
debug3: Ignored env LESSCLOSE
debug3: Ignored env TERM
debug3: Ignored env LESSOPEN
debug3: Ignored env USER
debug3: Ignored env NO_PROXY
debug3: Ignored env FTP_PROXY
debug3: Ignored env SHLVL
debug3: Ignored env HTTPS_PROXY
debug3: Ignored env HTTP_PROXY
debug3: Ignored env http_proxy
debug3: Ignored env XDG_DATA_DIRS
debug3: Ignored env PATH
debug3: Ignored env MAIL
debug3: Ignored env _
debug1: Sending subsystem: sftp
debug2: channel 0: request subsystem confirm 1
debug3: send packet: type 98
debug2: channel_input_open_confirmation: channel 0: callback done
debug2: channel 0: open confirm rwindow 4294967295 rmax 32768
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: subsystem request accepted on channel 0
debug2: Remote version: 3
debug2: Unrecognised server extension "versions"
debug2: Unrecognised server extension "check-file"
debug2: Unrecognised server extension "copy-file"
debug2: Unrecognised server extension "home-directory"
debug2: Unrecognised server extension "space-available"
debug2: Server supports extension "fsync@openssh.com" revision 1
debug2: Server supports extension "posix-rename@openssh.com" revision 1
debug2: Server supports extension "statvfs@openssh.com" revision 2
debug2: Server supports extension "fstatvfs@openssh.com" revision 2
debug2: Server supports extension "hardlink@openssh.com" revision 1
debug2: Server supports extension "limits@openssh.com" revision 1
debug2: Unrecognised server extension "users-groups-by-id@openssh.com"
debug3: Sent message limits@openssh.com I:1
debug3: Received limits reply T:201 I:1
debug1: Using server download size 523264
debug1: Using server upload size 523264
debug1: Server handle limit 1048568; using 64
Connected to filestore.mycompany.de.
debug2: Sending SSH2_FXP_REALPATH "."
debug3: Sent message fd 3 T:16 I:2
debug3: SSH2_FXP_REALPATH . -> /
sftp> put /root/noble-live-server-amd64.iso
debug3: Looking up /root/noble-live-server-amd64.iso
Uploading /root/noble-live-server-amd64.iso to /noble-live-server-amd64.iso
debug2: do_upload: upload local "/root/noble-live-server-amd64.iso" to remote "/noble-live-server-amd64.iso"
debug2: Sending SSH2_FXP_OPEN "/noble-live-server-amd64.iso"
debug3: Sent dest message SSH2_FXP_OPEN I:3 P:/noble-live-server-amd64.iso M:0x001a
noble-live-server-amd64.iso                                                                                                                                      0%    0     0.0KB/s   --:-- ETAOutbound message too long 523301
debug2: channel 0: read failed rfd 4 maxlen 32768: Broken pipe
debug2: channel 0: read failed
debug2: chan_shutdown_read: channel 0: (i0 o0 sock -1 wfd 4 efd 6 [write])
debug2: channel 0: input open -> drain
debug2: channel 0: ibuf empty
debug2: channel 0: send eof
debug3: send packet: type 96
debug2: channel 0: input drain -> closed
root@ansible-controller1:~# debug3: receive packet: type 98
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug3: receive packet: type 96
debug2: channel 0: rcvd eof
debug2: channel 0: output open -> drain
debug2: channel 0: obuf empty
debug2: chan_shutdown_write: channel 0: (i3 o1 sock -1 wfd 5 efd 6 [write])
debug2: channel 0: output drain -> closed
debug3: receive packet: type 97
debug2: channel 0: rcvd close
debug3: channel 0: will not send data after close
debug2: channel 0: almost dead
debug2: channel 0: gc: notify user
debug2: channel 0: gc: user detached
debug2: channel 0: send close
debug3: send packet: type 97
debug2: channel 0: is dead
debug2: channel 0: garbage collecting
debug1: channel 0: free: client-session, nchannels 1
debug3: channel 0: status: The following connections are open:
  #0 client-session (t4 r0 i3/0 o3/0 e[write]/0 fd -1/-1/6 sock -1 cc -1 io 0x00/0x00)

debug3: send packet: type 1
Transferred: sent 2212, received 3336 bytes, in 6.3 seconds
Bytes per second: sent 351.9, received 530.7
debug1: Exit status 0

@Castaglia
Copy link
Member

That is awesome. Thank you very much @Castaglia. I did some testing. The handshake succeeds and I can login, but the upload fails with Outbound message too long 523301:

Fascinating. Can you check the server-side logging, to see mod_sftp is complaining of that "Outbound message too long"? It's possible that that "message too long" might be coming from OpenSSH; mod_sftp uses larger packet/buffer sizes than OpenSSH.

@Castaglia
Copy link
Member

Castaglia commented Apr 25, 2024

That is awesome. Thank you very much @Castaglia. I did some testing. The handshake succeeds and I can login, but the upload fails with Outbound message too long 523301:

Fascinating. Can you check the server-side logging, to see mod_sftp is complaining of that "Outbound message too long"? It's possible that that "message too long" might be coming from OpenSSH; mod_sftp uses larger packet/buffer sizes than OpenSSH.

To answer my own question, it looks like this is coming from OpenSSH itself:

which, in turn, means this is essentially an OpenSSH bug. The mod_sftp module cannot "know" what buffer lengths are considered "too long" by the requesting client, and thus cannot (and should not) adjust the lengths returned in the limits@openssh.com reply based on the requesting client. The fact that OpenSSH uses those limits@openssh.com values, then exceeds its own maximum, is the bug, IMHO. Sadly.

I guess that means, in the mean time, I might be forced to make the limits@openssh.com reply take the remote client version into account (which is a bad/wrong design), otherwise that extension will cause other OpenSSH clients to trip over their own feet in this way. How depressing.

@Castaglia
Copy link
Member

Castaglia commented Apr 25, 2024

Ah-ha! Looks like this OpenSSH behavior (of not respecting its own limits) did get fixed, but in a later version than that you appear to be using @cfiehe see openssh/openssh-portable@48bf234

Looks like the above fix shipped in OpenSSH 9.2/9.2p1. Which means that the mod_sftp implementation of the limits@openssh.com extension will need automatically check the remote client version, and attempt to Do The Right Thing(tm) for OpenSSH versions prior to 9.2/9.2p1.

@cfiehe
Copy link

cfiehe commented Apr 25, 2024

Ah, ok. Those if conditions are not nice, but actually the only chance to work around the issue. Fortunately, it has been fixed on client side.

We use Ubuntu 22.04 that comes with an OpenSSH_8.9p1. Ubuntu 24.04 is equipped with OpenSSH_9.6p1.

Castaglia added a commit that referenced this issue Apr 25, 2024
…se the `limits@openssh.com` extension, yet cannot properly handle the longer mod_sftp lengths.
@Castaglia
Copy link
Member

@cfiehe #1800 should help address this interoperability for older OpenSSH clients.

Castaglia added a commit that referenced this issue Apr 25, 2024
…se the `limits@openssh.com` extension, yet cannot properly handle the longer mod_sftp lengths.
Castaglia added a commit that referenced this issue Apr 25, 2024
…se the `limits@openssh.com` extension, yet cannot properly handle the longer mod_sftp lengths.
@cfiehe
Copy link

cfiehe commented Apr 26, 2024

Hi @Castaglia. Pretty cool. I did a quick test with the sftp client and build ProFTPD based on your workaround sftp-limits-ext-compat-issue1288. It is working. Great job 👏! Thank you very much.

Now, we achieve the upload and download results from here #1288 (comment). I have tested it with again with the OpenSSH client 8.9p1-3ubuntu0.7 from Ubuntu 22.04 that supports only a package size of 255Kb.

Unfortunately, there remains a gap in speed in comparison with the OpenSSH server of factor 2.

OpenSSH client 8.9p1-3ubuntu0.7 -> ProFTPD sftp-limits-ext-compat-issue1288:
sftp> put /root/noble-live-server-amd64.iso
Uploading /root/noble-live-server-amd64.iso to /noble-live-server-amd64.iso
noble-live-server-amd64.iso   100% 2627MB  91.1MB/s   00:28
OpenSSH client 8.9p1-3ubuntu0.7 -> OpenSSH server 8.9p1-3ubuntu0.7:
sftp> put /root/noble-live-server-amd64.iso
Uploading /root/noble-live-server-amd64.iso to /noble-live-server-amd64.iso
noble-live-server-amd64.iso   100% 2627MB 185.0MB/s   00:14

@cfiehe
Copy link

cfiehe commented Apr 26, 2024

There seems to be some kind of adaption in the SFTP client when talking with the OpenSSH server. The magic seems to happen here https://github.com/openssh/openssh-portable/blob/00e63688920905e326d8667cb47f17a156b6dc8f/channels.c#L3660, but I am not sure.

I have created new logs:
put-proftpd-20240426.log
get-proftpd-20240426.log
put-openssh-20240426.log
get-openssh-20240426.log

@cfiehe
Copy link

cfiehe commented Apr 26, 2024

Maybe the trigger is rwindow 0. ProFTPD sets it to 4294967295.

ProFTPD:
debug2: channel 0: open confirm rwindow 4294967295 rmax 32768
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: subsystem request accepted on channel 0
debug2: Remote version: 3
OpenSSH
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel 0: rcvd adjust 2097152
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: subsystem request accepted on channel 0
debug2: Remote version: 3

Castaglia added a commit that referenced this issue Apr 26, 2024
…se the `limits@openssh.com` extension, yet cannot properly handle the longer mod_sftp lengths. (#1800)
@Castaglia
Copy link
Member

Hi @Castaglia. Pretty cool. I did a quick test with the sftp client and build ProFTPD based on your workaround sftp-limits-ext-compat-issue1288. It is working. Great job 👏! Thank you very much.

Excellent news. That PR has been merged to master.

Unfortunately, there remains a gap in speed in comparison with the OpenSSH server of factor 2.

We can continue to examine this (and in Issue #1751), but know that I am not aiming to have mod_sftp perform just like OpenSSH. In my mind, requests/questions about "performance" are incredibly subjective. Instead, I think in terms of "what latencies are required for your use case, and why?" Performance optimization covers the operating systems of clients and servers, the application implementations, every single networking component in the path, libraries, designs, etc. In short, one can spend years just on this topic -- and I don't always have the time/patience for performance optimizations.

I say this just as a reminder that at some point, I will consider the mod_sftp performance to be "good enough for now". OpenSSH has always performed better, and that hasn't stopped users like yourself from enjoying mod_sftp.

@cfiehe
Copy link

cfiehe commented Apr 26, 2024

You are right. Time is the most value thing we have. We have to spend it consciously. The implementation of the limits SFTP extension was a major improvement of the transfer speed. Thanks a lot for your efforts spent on this topic 👍. It was just curiosity to find out, what the OpenSSH guys make differently here and if there is a chance that mod_sftp could benefit from that. Nevertheless, it is a question of effort and benefit.

@Castaglia
Copy link
Member

Castaglia commented Apr 27, 2024

@cfiehe I took a look at the provided logs.

In comparing the SFTP uploads to ProFTPD vs OpenSSH, the client uses the same buffer lengths in the WRITE requests, and we see the exact same count of WRITE requests in both cases. Meaning the amount of data written/uploaded per request is the same, so that shouldn't be factor in the overall latency difference. (We see the same thing in the SFTP downloads: same size of buffer in READ requests, and same count of READ requests.) And in both cases, we see the same values used from the limits@openssh.com extension (which is good; that's the improvement/benefit we see from having that extension supported by mod_sftp):

# mod_sftp
debug3: Sent message limits@openssh.com I:1
debug3: Received limits reply T:201 I:1
debug1: Using server download size 261120
debug1: Using server upload size 261120
debug1: Server handle limit 1048568; using 64
# OpenSSH
debug3: Sent message limits@openssh.com I:1
debug3: Received limits reply T:201 I:1
debug1: Using server download size 261120
debug1: Using server upload size 261120
debug1: Server handle limit 1019; using 64

For the SSH window (used as a backpressure mechanism similar to TCP, since SSH allows for multiplexing multiple concurrent channels; see section "5.2. Data Transfer" of RFC 4254), we see:

# mod_sftp
debug2: channel 0: open confirm rwindow 4294967295 rmax 32768
# OpenSSH
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel 0: rcvd adjust 2097152

The initial window size set by mod_sftp is 4GB. I do this deliberately, so that the number of "window adjustment" messages, needed to "open" the window", is low. Fewer messages leads to lower latency, especially over long-lived channels and large data transfers. OpenSSH, on the other hand, starts with a zero window size, then immediately adjusts it, adding 2097152 bytes.

We can look at the number of these "adjustment" messages in the two uploads, to see if that contributes to the overall latency:

$ grep 'rcvd adjust' put-proftpd-20240426.log | wc -l
       0
$ grep 'rcvd adjust' put-openssh-20240426.log | wc -l
   95031

I think this rules out the SSH channel window as a contributing factor to the overall latency difference.

What are some other contributing factors? With long-lived channels and large data transfers, the overall algorithms negotiated can have an impact. Let's see what algorithms were negotiated:

# mod_sftp
debug1: kex: algorithm: curve25519-sha256
debug1: kex: host key algorithm: rsa-sha2-512
debug1: kex: server->client cipher: aes128-gcm@openssh.com MAC: <implicit> compression: none
debug1: kex: client->server cipher: aes128-gcm@openssh.com MAC: <implicit> compression: none
# OpenSSH
debug1: kex: algorithm: curve25519-sha256
debug1: kex: host key algorithm: ssh-ed25519
debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit
> compression: none
debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit
> compression: none

The difference in host key algorithm won't make difference for data transfer latency. The main factor for data transfer latency will be the cipher and MAC algorithms. Here, we see AES128-GCM used for the mod_sftp transfers, vs ChaChaPoly used for the OpenSSH transfers.

Other users have reported similar to negligible timing differences between AES128-GCM and ChaChaPoly algorithms (see #1751 (comment)), but here we get into the OpenSSL versions, and underlying CPUs, used. So you might add/configure ChaChaPoly support to your SFTPCiphers mod_sftp configuration (assuming your OpenSSL version supports that algorithm); looks like the Ubuntu 22.04 OpenSSL package should support it:

# cat /etc/os-release
PRETTY_NAME="Ubuntu 22.04 LTS"
NAME="Ubuntu"
VERSION_ID="22.04"
VERSION="22.04 LTS (Jammy Jellyfish)"
VERSION_CODENAME=jammy
ID=ubuntu
ID_LIKE=debian
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
UBUNTU_CODENAME=jammy

# openssl version
OpenSSL 3.0.2 15 Mar 2022 (Library: OpenSSL 3.0.2 15 Mar 2022)

# openssl ciphers -stdname | grep -i ChaCha
TLS_CHACHA20_POLY1305_SHA256                  - TLS_CHACHA20_POLY1305_SHA256   TLSv1.3 Kx=any      Au=any   Enc=CHACHA20/POLY1305(256) Mac=AEAD
TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256 - ECDHE-ECDSA-CHACHA20-POLY1305  TLSv1.2 Kx=ECDH     Au=ECDSA Enc=CHACHA20/POLY1305(256) Mac=AEAD
TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256   - ECDHE-RSA-CHACHA20-POLY1305    TLSv1.2 Kx=ECDH     Au=RSA   Enc=CHACHA20/POLY1305(256) Mac=AEAD
TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256     - DHE-RSA-CHACHA20-POLY1305      TLSv1.2 Kx=DH       Au=RSA   Enc=CHACHA20/POLY1305(256) Mac=AEAD
TLS_RSA_PSK_WITH_CHACHA20_POLY1305_SHA256     - RSA-PSK-CHACHA20-POLY1305      TLSv1.2 Kx=RSAPSK   Au=RSA   Enc=CHACHA20/POLY1305(256) Mac=AEAD
TLS_DHE_PSK_WITH_CHACHA20_POLY1305_SHA256     - DHE-PSK-CHACHA20-POLY1305      TLSv1.2 Kx=DHEPSK   Au=PSK   Enc=CHACHA20/POLY1305(256) Mac=AEAD
TLS_ECDHE_PSK_WITH_CHACHA20_POLY1305_SHA256   - ECDHE-PSK-CHACHA20-POLY1305    TLSv1.2 Kx=ECDHEPSK Au=PSK   Enc=CHACHA20/POLY1305(256) Mac=AEAD
TLS_PSK_WITH_CHACHA20_POLY1305_SHA256         - PSK-CHACHA20-POLY1305          TLSv1.2 Kx=PSK      Au=PSK   Enc=CHACHA20/POLY1305(256) Mac=AEAD

Everything else looked quite similar, which means that a much more in-depth (and reproducible) investigation would be needed to understand the latency differences.

@cfiehe
Copy link

cfiehe commented Apr 27, 2024

Thanks for your investigation.

I have set the cipher with SFTPCiphers chacha20-poly1305@openssh.com and removed the rsa as well as the ecdsa key. The outcome is still the same. The different cipher and key used above have no impact on the transfer speed in this use case:

ProFTPD upload: 29 s
ProFTPD download: 13 s

OpenSSH upload: 16 s
OpenSSH download: 7 s

put-proftpd-20240427.log
get-proftpd-20240427.log
put-openssh-20240427.log
get-openssh-20240427.log

I do not know if it helps, but that is the output of proftpd -V:

Compile-time Settings:
  Version: 1.3.9rc3 (git)
  Platform: LINUX [Linux 5.15.0-105-generic x86_64]
  OS/Release:
    PRETTY_NAME="Ubuntu 24.04 LTS"
    NAME="Ubuntu"
    VERSION_ID="24.04"
    VERSION="24.04 LTS (Noble Numbat)"
    VERSION_CODENAME=noble
    ID=ubuntu
    ID_LIKE=debian
    UBUNTU_CODENAME=noble
  Built: Fri Apr 26 2024 19:21:27 UTC
  Built With:
    configure  'CFLAGS=-DBAN_LIST_MAXSZ=8192' '--prefix=/usr' '--mandir=/usr/share/man' '--sysconfdir=/etc/proftpd' '--localstatedir=/run' '--libexecdir=/usr/lib/proftpd' '--with-includes=/usr/include/mysql:/usr/include/postgresql:/usr/include/sodium' '--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 -DBAN_LIST_MAXSZ=8192 -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 -lhiredis_ssl

  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.13 30 Jan 2024)
    - 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
ProFTPD Version: 1.3.9rc3 (git)
  Scoreboard Version: 01040003
  Built: Fri Apr 26 2024 19:21:27 UTC

Loaded modules:
  mod_ifsession/1.3.1
  mod_sftp_pam/0.3
  mod_sftp/1.2.0
  mod_load/1.0.1
  mod_rewrite/1.2
  mod_lang/1.1
  mod_ctrls/0.9.5
  mod_cap/1.1
  mod_auth_pam/1.2
  mod_dso/0.5
  mod_facts/0.7
  mod_delay/0.8
  mod_site.c
  mod_log/1.0
  mod_ls.c
  mod_auth.c
  mod_auth_file/1.0
  mod_auth_unix.c
  mod_rlimit/1.0
  mod_xfer.c
  mod_core.c

And my configuration:

Include /etc/proftpd/modules.conf

DefaultServer off
MaxInstances 500
Port 0
ServerType standalone
UseReverseDNS off

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

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

        SFTPHostKey /etc/proftpd/ssh_host_ed25519_key

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

        SFTPClientAlive 3 15
        SFTPCompression delayed

        SFTPOptions IgnoreSFTPSetTimes IgnoreSCPUploadPerms IgnoreSCPUploadTimes \
                    IgnoreSFTPSetExtendedAttributes IgnoreSFTPUploadExtendedAttributes \
                    PessimisticKexinit

        SFTPCiphers chacha20-poly1305@openssh.com

        MaxLoginAttempts 2
    </Global>
</IfModule>

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

    SFTPEngine on
    Port 22022

    DefaultRoot /

    AllowOverwrite on
    AllowStoreRestart on
</VirtualHost>

Castaglia added a commit that referenced this issue May 4, 2024
…memset(3)` calls in hot code paths in mod_sftp.
@Castaglia
Copy link
Member

Castaglia commented May 4, 2024

@cfiehe #1802 might be of some interest for your latency tests. I used flamegraphs to see where some of the CPU time was being spent, and removed some unnecessary memset(3) calls. I'm not sure how much of a latency improvement it provides, but it might be worth testing in your setup.

In addition, in the flamegraphs, I saw how much "overhead" occurs when trace logging is enabled (so disable that for less latency). I would also recommend that AllowOverride off be explicitly configured.

@cfiehe
Copy link

cfiehe commented May 5, 2024

@Castaglia Thanks a lot for your analysis. I built a new version of ProFTPD and set AllowOverride off. It is hard to say, it looks like a minor improvement of the upload speed:

ProFTPD upload: 26 s
ProFTPD download: 11 s
OpenSSH upload: 16 s
OpenSSH download: 6 s

@Castaglia
Copy link
Member

@Castaglia Thanks a lot for your analysis. I built a new version of ProFTPD and set AllowOverride off. It is hard to say, it looks like a minor improvement of the upload speed:

Excellent, thanks for the tests. I'll commit that PR, and continue looking at these flamegraphs to find other hot code paths, and see what kinds of optimizations I can easily find.

Castaglia added a commit that referenced this issue May 5, 2024
…memset(3)` calls in hot code paths in mod_sftp. (#1802)
Castaglia added a commit that referenced this issue May 10, 2024
…che the initial results of the `dir_check()` function at the start of the transfer.

According to flamegraphs, there is a fair amount of CPU time spent in `dir_check()` and related functions, almost all of which is redundant.  Those access checks apply to conditions which do not change over the course of the data transfer.
@Castaglia
Copy link
Member

@cfiehe Here's the next round of optimizations, informed by more flamegraph examinations, for you to try out: #1805

Castaglia added a commit that referenced this issue May 11, 2024
…che the initial results of the `dir_check()` function at the start of the transfer.

According to flamegraphs, there is a fair amount of CPU time spent in `dir_check()` and related functions, almost all of which is redundant.  Those access checks apply to conditions which do not change over the course of the data transfer.
@cfiehe
Copy link

cfiehe commented May 12, 2024

Great. Thanks a lot @Castaglia. I did some testing, but unfortunately, I could not measure any improvement of the transfer speed. I get:

ProFTPD upload: 27 s
ProFTPD download: 11 s
OpenSSH upload: 15 s
OpenSSH download: 6 s

Castaglia added a commit that referenced this issue May 14, 2024
…che the initial results of the `dir_check()` function at the start of the transfer. (#1805)

According to flamegraphs, there is a fair amount of CPU time spent in `dir_check()` and related functions, almost all of which is redundant.  Those access checks apply to conditions which do not change over the course of the data transfer.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants