Client timeout after sending client version string after upgrading from 1.3.7e to 1.3.8b, but not reproducible for me

[maltris]

Recently I cam e across a problem where some of the users of my proftpd based sftp server started to have problems when I bumped from

1.3.7e

to

1.3.8b

Among ~360 clients, there have been 2-3 which started to have a problem where within the start of the SSH conversation, a timeout happens and the client is stuck forever.
One client told me that they use the latest Debian 12 openssh-client package (OpenSSH_9.2p1 Debian-2+deb12u2, OpenSSL 3.0.11 19 Sep 2023).
I tried to replicate the test setup 1 by 1 in a docker container, but havent been able to reproduce the problem.
Unfortunately I have no direct access to the affected client.

The clients logs may look like this:

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 *
debug1: Connecting to 127.0.0.1 [127.0.0.1] port 22.
debug1: fd 3 clearing O_NONBLOCK
debug1: Connection established.
debug1: identity file /home/user/.ssh/id_rsa type 0
debug1: identity file /home/user/.ssh/id_rsa-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_9.2p1 Debian-2+deb12u2

After that "Local version string" message nothing more appears.

The servers logs may look like this (1.3.8b with mod_sftp/1.1.1):

2024-01-09 14:00:01,492 mod_sftp/1.1.1[10640]: using '/etc/ssh/ssh_host_ecdsa_key' as 256-bit ECDSA hostkey (256 bits)
2024-01-09 14:00:01,493 mod_sftp/1.1.1[10640]: client (127.0.0.1:50512) connected to server (127.0.0.2:22)
2024-01-09 14:00:01,493 mod_sftp/1.1.1[10640]: sent server version 'SSH-2.0-mod_sftp'
2024-01-09 14:00:01,493 mod_sftp/1.1.1[10640]: received client version 'SSH-2.0-OpenSSH_9.2p1 Debian-2+deb12u2'
2024-01-09 14:00:01,493 mod_sftp/1.1.1[10640]: handling connection from SSH2 client 'OpenSSH_9.2p1'

After that, there is just nothing. An example of a working connection (1.3.7e with mod_sftp/1.0.1):

2024-01-09 11:45:01,399 mod_sftp/1.0.1[2428676]: using '/etc/ssh/ssh_host_ecdsa_key' as 256-bit ECDSA hostkey
2024-01-09 11:45:01,401 mod_sftp/1.0.1[2428676]: sent server version 'SSH-2.0-mod_sftp'
2024-01-09 11:45:01,401 mod_sftp/1.0.1[2428676]: received client version 'SSH-2.0-OpenSSH_9.2p1 Debian-2+deb12u2'
2024-01-09 11:45:01,401 mod_sftp/1.0.1[2428676]: handling connection from SSH2 client 'OpenSSH_9.2p1'
2024-01-09 11:45:01,420 mod_sftp/1.0.1[2428676]: + Session key exchange: ecdh-sha2-nistp256
2024-01-09 11:45:01,420 mod_sftp/1.0.1[2428676]: + Session server hostkey: ecdsa-sha2-nistp256
2024-01-09 11:45:01,420 mod_sftp/1.0.1[2428676]: + Session client-to-server encryption: aes128-ctr
2024-01-09 11:45:01,420 mod_sftp/1.0.1[2428676]: + Session server-to-client encryption: aes128-ctr
2024-01-09 11:45:01,420 mod_sftp/1.0.1[2428676]: + Session client-to-server MAC: umac-64@openssh.com
2024-01-09 11:45:01,420 mod_sftp/1.0.1[2428676]: + Session server-to-client MAC: umac-64@openssh.com
2024-01-09 11:45:01,420 mod_sftp/1.0.1[2428676]: + Session client-to-server compression: none
2024-01-09 11:45:01,420 mod_sftp/1.0.1[2428676]: + Session server-to-client compression: none
2024-01-09 11:45:01,504 mod_sftp/1.0.1[2428676]: sending acceptable userauth methods: publickey,hostbased,password
2024-01-09 11:45:01,547 mod_sftp/1.0.1[2428676]: public key SHA256 fingerprint: <fp>
2024-01-09 11:45:01,547 mod_sftp/1.0.1[2428676]: sending publickey OK
2024-01-09 11:45:01,574 mod_sftp/1.0.1[2428676]: public key SHA256 fingerprint: <fp>
2024-01-09 11:45:01,576 mod_sftp_sql/0.4[2428676]: SQLNamedQuery 'get-user-authorized-keys' returned 1 row
2024-01-09 11:45:01,579 mod_sftp/1.0.1[2428676]: no supplemental groups found for user 'user'
2024-01-09 11:45:01,580 mod_sftp/1.0.1[2428676]: sending userauth success
2024-01-09 11:45:01,580 mod_sftp/1.0.1[2428676]: user 'user' authenticated via 'publickey' method
2024-01-09 11:45:01,614 mod_sftp/1.0.1[2428676]: 'env' channel request: 'LANG' = 'en_US.UTF-8'
2024-01-09 11:45:01,614 mod_sftp/1.0.1[2428676]: 'subsystem' channel request for 'sftp' subsystem
2024-01-09 11:45:01,614 mod_sftp/1.0.1[2428676]: using SFTP protocol version 3 for this session (channel ID 0)
2024-01-09 11:45:01,703 mod_sftp/1.0.1[2428676]: creating directory '/some/path' with mode 0777
2024-01-09 11:45:01,703 mod_sftp/1.0.1[2428676]: MKDIR of '/some/path' failed: File exists
2024-01-09 11:45:01,842 mod_sftp/1.0.1[2428676]: client at 127.0.0.1 sent SSH_DISCONNECT message: disconnected by user (Application disconnected)

At first I thought it had something to do with the Terrapin mitigation/strict kex mode, so with 1.3.8b I enabled NoStrictKex, which yielded no other results.
I feel a little out of luck, because with my test client, which is exactly the same openssh-client version, all works.

The issue seems a little similar to #1694, but the logs are different, in my case it just seems to time out at some point.

Sorry for skipping the issue template this time, here is the needed informations:

Compile-time Settings:
  Version: 1.3.8b (maint)
  Platform: LINUX [Linux 5.4.0-96-generic x86_64]
  OS/Release:
    NAME="Alpine Linux"
    ID=alpine
    VERSION_ID=3.19.0
    PRETTY_NAME="Alpine Linux v3.19"
  Built: Mon Jan 8 2024 16:08:53 UTC
  Built With:
    configure  '--enable-ctrls' '--enable-openssl' '--enable-quotatab' '--with-modules=mod_tls:mod_quotatab:mod_sql:mod_sql_passwd:mod_quotatab_sql:mod_quotatab_file:mod_ctrls_admin:mod_auth_otp:mod_sql_sqlite:mod_sql_mysql:mod_ban:mod_readme:mod_sftp:mod_sftp_sql:mod_proxy_protocol:mod_ident:mod_ifsession' '--enable-nls'

  CFLAGS: -g2 -O2 -Wall -fno-omit-frame-pointer -fno-strict-aliasing
  LDFLAGS: -Wl,-L$(top_srcdir)/lib,-L$(top_builddir)/lib  -rdynamic  -L/usr/lib/
  LIBS:  -lssl -lcrypto -lm -lmysqlclient -lz  -lsqlite3  -lssl  -lcrypto 

  Files:
    Configuration File:
      /usr/local/etc/proftpd.conf
    Pid File:
      /usr/local/var/proftpd.pid
    Scoreboard File:
      /usr/local/var/proftpd.scoreboard

  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
    - ncurses support
    + NLS support
    + OpenSSL support (OpenSSL 3.1.4 24 Oct 2023)
    - 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 = 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

Config (changed to remove identifying information):

<global>
RootLogin off
RequireValidShell off
AllowOverwrite on
WtmpLog off
TransferLog /var/log/xfer.log
DefaultRoot ~

IdentLookups                    off
DeferWelcome                    off
MultilineRFC2228                on
ShowSymlinks                    on

TimeoutNoTransfer               6000
TimeoutStalled                  6000
TimeoutIdle                     12000

SQLBackend              mysql
SQLAuthTypes            Crypt
SQLAuthenticate         users groups

SQLConnectInfo  credentials

SQLGroupInfo    ftpgroup groupname gid members
SQLMinID        500
CreateHome on

SQLNamedQuery get-user-authorized-keys SELECT "user_key FROM sftpuserkeys WHERE user='%U'"
SQLNamedQuery get-host-authorized-keys SELECT "host_key FROM sftphostkeys WHERE host='%{0}'"

    <Directory /proc>
        <Limit ALL>
            DenyAll
        </Limit>
    </Directory>

</global>

<IfModule mod_sftp.c>
    <VirtualHost 0.0.0.0>
        Port 22
        SFTPOptions     IgnoreSFTPUploadPerms
        SFTPEngine      on
        SFTPCompression delayed

        SFTPHostKey /etc/ssh/ssh_host_rsa_key
        SFTPHostKey /etc/ssh/ssh_host_ecdsa_key

        SQLUserInfo     sftp userid passwd uid gid homedir shell

        SFTPClientMatch ".*XFB.*" channelWindowSize 1GB
        SFTPClientMatch ".*XFB.*" sftpUTF8ProtocolVersion 3

        <IfModule mod_sftp_sql.c>
             SFTPAuthorizedUserKeys sql:/get-user-authorized-keys
             SFTPAuthorizedHostKeys sql:/get-host-authorized-keys
        </IfModule>

	SFTPLog /var/log/sftp.log
    </VirtualHost>
</IfModule>

<IfModule mod_sql_passwd.c>
    <VirtualHost 0.0.0.0>

        Port 21
        DefaultServer on

        PassivePorts 10000 10250
        MasqueradeAddress 10.0.0.1

        SQLPasswordEngine on

        SQLUserInfo     ftpuser userid passwd uid gid homedir shell
    </VirtualHost>
</IfModule>

Port 0

UseIPv6                         off
UseReverseDNS                   off

ServerName                      "SFTP"
ServerType                      standalone

SystemLog /var/log/proftpd.log
SyslogLevel info

I fully read the changelog/news file but found nothing that would look like it affects my use case, except maybe the host key rotation feature, which if I understand correctly, is just not used if the client doesnt support it.

I would be very grateful for info pointing me in the right direction and to get this solved.

Best regards

[Castaglia]

Hmm. I've not heard of any reports along these lines before. Let's see if we can get some more details.

Would it be possible to add the following to your ProFTP configuration?

TraceLog /var/log/proftpd-trace.log
Trace ssh2:30 sftp:30

Note that this will generate quite a lot of logging data, for the working connections. I am most interested in the additional trace logging seen for the non-working sessions.

In the mean time, I am attempting to reproduce this issue locally, using debian:12 and alpine:3.19.0 Docker containers; so far, all of the connection attempts are working as expected for me as well.

[cfiehe]

Hi @maltris,
we faced the same issue and were confronted with hanging clients (2 or 3 out ouf 150) at the same point during SSH handshake. We found out that the server-side worked properly and sent a correct response, but the client did not receive it (using tcpdump). The problem was, that this happened on the customer's side and we had only limited debugging capabilities. The client's host was based on Ubuntu 20.04. We never understood the issue completely and have not find a way to reproduce it, but adding

SFTPOptions PessimisticKexinit

helped to workaround the issue of hanging clients. Maybe, you can give it a try, too.

On the client’s side there was a firewall appliance in place and we had it in suspicion of dropping the server's response. Unfortunately, we could not get the firewall logs to underline that theory. For test purposes, we used a pretty old ProFTPD server that was based on 1.3.5e and used the setting for optimistic key exchange. That was working without any issues and the SSH handshake completed normally. Maybe the issue was introduced, starting with ProFTPD 1.3.8.