SFTP server: long delay while connecting with full CPU load

Question

Hi,

while evaluating Rebex File Server (SFTP), I see a long delay of about 70 seconds when a client connects. During this time, the SFTP server seems to take 100% of the CPU. After that, the connection succeeds and the CPU load goes back to normal.
The device is a PDA with ARM processor, Windows CE 6.0, .NET Compact Framework 3.5.

Here is the Log. The delay is between 16:13:47 and 16:15:01:

2016-11-02 16:12:44 INFO FileServer(1)[77332506] Server: Starting server.
2016-11-02 16:12:44 INFO FileServer(1)[77332506] Server: Listening for connections at 0.0.0.0:22.
2016-11-02 16:12:44 INFO FileServer(1)[77332506] Server: Server started.
2016-11-02 16:13:47 DEBUG FileServer(1)[95813678] Server: Accepted connection from 172.23.6.38:54792.
2016-11-02 16:13:47 INFO FileServer(1)[95813678] Server: Session 1: Started on connection from 172.23.6.38:54792.
2016-11-02 16:13:47 DEBUG FileServer(1)[95813678] SSH: Session 1: Local SSH version: SSH-2.0-RebexSSH_1.0.6083.0
2016-11-02 16:13:47 DEBUG FileServer(1)[93782146] SSH: Session 1: Remote SSH version: SSH-2.0-OpenSSH_7.3
2016-11-02 16:13:47 DEBUG FileServer(1)[93782146] SSH: Session 1: Performing algorithm negotiation and key exchange.
2016-11-02 16:13:47 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_KEXINIT (776 bytes).
2016-11-02 16:13:47 VERBOSE FileServer(1)[95813678] SSH: Session 1: Received packet SSH_MSG_KEXINIT (1432 bytes).
2016-11-02 16:13:47 DEBUG FileServer(1)[95813678] SSH: Session 1: Performing key exchange using diffie-hellman-group-exchange-sha256 with ssh-rsa.
2016-11-02 16:13:47 VERBOSE FileServer(1)[93782146] SSH: Session 1: Received packet SSH_MSG_PACKET34 (24 bytes).
2016-11-02 16:13:47 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_KEXDH_REPLY (536 bytes).
2016-11-02 16:13:47 VERBOSE FileServer(1)[95813678] SSH: Session 1: Received packet SSH_MSG_PACKET32 (272 bytes).
2016-11-02 16:15:01 VERBOSE FileServer(1)[95813678] SSH: Session 1: Sent packet SSH_MSG_PACKET33 (832 bytes).
2016-11-02 16:15:01 VERBOSE FileServer(1)[95813678] SSH: Session 1: Sent packet SSH_MSG_NEWKEYS (16 bytes).
2016-11-02 16:15:01 DEBUG FileServer(1)[95813678] SSH: Session 1: Current encryptor is aes128-ctr/hmac-sha2-256.
2016-11-02 16:15:01 VERBOSE FileServer(1)[93782146] SSH: Session 1: Received packet SSH_MSG_NEWKEYS (16 bytes).
2016-11-02 16:15:01 DEBUG FileServer(1)[93782146] SSH: Session 1: Current decryptor is aes128-ctr/hmac-sha2-256.
2016-11-02 16:15:01 DEBUG FileServer(1)[93782146] SSH: Session 1: Key exchange finished.
2016-11-02 16:15:02 VERBOSE FileServer(1)[95813678] SSH: Session 1: Received packet SSH_MSG_SERVICE_REQUEST (64 bytes).
2016-11-02 16:15:02 DEBUG FileServer(1)[95813678] SSH: Session 1: Performing authentication.
2016-11-02 16:15:02 VERBOSE FileServer(1)[95813678] SSH: Session 1: Sent packet SSH_MSG_SERVICE_ACCEPT (64 bytes).
2016-11-02 16:15:02 VERBOSE FileServer(1)[93782146] SSH: Session 1: Received packet SSH_MSG_USERAUTH_REQUEST (80 bytes).
2016-11-02 16:15:02 DEBUG FileServer(1)[93782146] SSH: Session 1: Starting authentication as 'admin' for 'ssh-connection'.
2016-11-02 16:15:02 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_USERAUTH_FAILURE (80 bytes).
2016-11-02 16:15:02 VERBOSE FileServer(1)[95813678] SSH: Session 1: Received packet SSH_MSG_USERAUTH_REQUEST (112 bytes).
2016-11-02 16:15:02 VERBOSE FileServer(1)[95813678] SSH: Session 1: Sent packet SSH_MSG_PACKET60 (80 bytes).
2016-11-02 16:15:09 VERBOSE FileServer(1)[93782146] SSH: Session 1: Received packet SSH_MSG_USERAUTH_INFO_RESPONSE (96 bytes).
2016-11-02 16:15:09 INFO FileServer(1)[93782146] Server: Session 1: Authentication for 'admin' succeeded.
2016-11-02 16:15:09 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_USERAUTH_SUCCESS (48 bytes).
2016-11-02 16:15:09 DEBUG FileServer(1)[93782146] SSH: Session 1: Authenticated as 'admin' for 'ssh-connection'.
2016-11-02 16:15:09 VERBOSE FileServer(1)[95813678] SSH: Session 1: Received packet SSH_MSG_CHANNEL_OPEN (80 bytes).
2016-11-02 16:15:09 VERBOSE FileServer(1)[95813678] SSH: Session 1: Sent packet SSH_MSG_CHANNEL_OPEN_CONFIRMATION (64 bytes).
2016-11-02 16:15:09 VERBOSE FileServer(1)[93782146] SSH: Session 1: Received packet SSH_MSG_CHANNEL_REQUEST (80 bytes).
2016-11-02 16:15:09 DEBUG FileServer(1)[93782146] Server: Session 1: Starting SftpModule(1) subsystem.
2016-11-02 16:15:09 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_CHANNEL_WINDOW_ADJUST (64 bytes).
2016-11-02 16:15:09 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_CHANNEL_SUCCESS (48 bytes).
2016-11-02 16:15:09 VERBOSE FileServer(1)[95813678] SSH: Session 1: Received packet SSH_MSG_CHANNEL_DATA (64 bytes).
2016-11-02 16:15:09 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_IGNORE (48 bytes).
2016-11-02 16:15:09 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_CHANNEL_DATA (112 bytes).
2016-11-02 16:15:09 VERBOSE FileServer(1)[96534662] SSH: Session 1: Received packet SSH_MSG_CHANNEL_DATA (64 bytes).
2016-11-02 16:15:09 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_IGNORE (48 bytes).
2016-11-02 16:15:09 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_CHANNEL_DATA (80 bytes).
2016-11-02 16:15:30 VERBOSE FileServer(1)[95813678] SSH: Session 1: Received packet SSH_MSG_CHANNEL_DATA (64 bytes).
2016-11-02 16:15:30 DEBUG SftpModule(1)[93782146] SFTP: Opening directory '/': success.
2016-11-02 16:15:30 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_IGNORE (48 bytes).
2016-11-02 16:15:30 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_CHANNEL_DATA (80 bytes).
2016-11-02 16:15:30 VERBOSE FileServer(1)[96534662] SSH: Session 1: Received packet SSH_MSG_CHANNEL_DATA (80 bytes).
2016-11-02 16:15:30 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_IGNORE (48 bytes).
2016-11-02 16:15:30 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_CHANNEL_DATA (1328 bytes).
2016-11-02 16:15:30 VERBOSE FileServer(1)[95813678] SSH: Session 1: Received packet SSH_MSG_CHANNEL_DATA (80 bytes).
2016-11-02 16:15:30 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_IGNORE (48 bytes).
2016-11-02 16:15:30 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_CHANNEL_DATA (96 bytes).
2016-11-02 16:15:30 VERBOSE FileServer(1)[96534662] SSH: Session 1: Received packet SSH_MSG_CHANNEL_DATA (80 bytes).
2016-11-02 16:15:30 DEBUG SftpModule(1)[93782146] SFTP: Closing file '/': success.
2016-11-02 16:15:30 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_IGNORE (48 bytes).
2016-11-02 16:15:30 VERBOSE FileServer(1)[93782146] SSH: Session 1: Sent packet SSH_MSG_CHANNEL_DATA (80 bytes).
2016-11-02 16:15:34 VERBOSE FileServer(1)[95813678] SSH: Session 1: Received packet SSH_MSG_CHANNEL_EOF (48 bytes).
2016-11-02 16:15:34 VERBOSE FileServer(1)[95813678] SSH: Session 1: Sent packet SSH_MSG_CHANNEL_CLOSE (48 bytes).
2016-11-02 16:15:34 VERBOSE FileServer(1)[93782146] SSH: Session 1: Received packet SSH_MSG_CHANNEL_CLOSE (48 bytes).
2016-11-02 16:15:34 VERBOSE FileServer(1)[95813678] SSH: Session 1: Received packet SSH_MSG_DISCONNECT (80 bytes).
2016-11-02 16:15:34 VERBOSE FileServer(1)[95813678] SSH: Session 1: Sent packet SSH_MSG_DISCONNECT (96 bytes).
2016-11-02 16:15:34 INFO FileServer(1)[95813678] SSH: Session 1: Connection close requested.

What's going on during this delay and what can be done to avoid it?

Thanks!

Answer 1

This delay is almost certainly caused by Diffie-Hellman key exchange - a shared secret key is being calculated during those 70 seconds.

This should not normally take so long - we use "Enhanced DSS and Diffie-Hellman Cryptographic Provider" (part of Windows CryptoAPI) whenever available, and it's reasonably fast even on old Windows CE devices. However, some device vendors forgot to include the Diffie-Hellman CSP in their OS image (the relevant checkbox in Platform Builder used to be disabled by default), making this impossible.

As a workaround, we use a custom managed implementation of Diffie-Hellman algorithm written in C#, which is very slow. For large key sizes, the calculation can take as long as two minutes on older devices.
Please see my reply to a related support request for additional details.

The best solution would be to use an OS image with "Enhanced DSS and Diffie-Hellman Cryptographic Provider" enabled.

Alternatively, disabling Diffie-Hellman key exchange ciphers that use Diffie-Hellman with long key size would solve the issue as well, but this is strongly discouraged because short Diffie-Hellman keys are weak.

However, since Rebex File Server 2016 R3, it has been possible to use key exchange ciphers based on Elliptic Curve Diffie-Hellman (Curve 25519 and NIST P-256/P-384/P-521), which are much faster. The drawback is that they require plugins based on third-party open source libraries (see the KB article on elliptic curve support for details).

Comments

Yes, this was the problem. After enabling Diffie-Hellman in the kernel, the delay decreased to 9 sec, which is acceptable. Thanks!

---

Hi, I'm having the same problem in a similar device that use Windows CE 6.0, .NET Compact Framework 3.5. I was wondering how do you enable  Diffie-Hellman in the kernel.

thanks

---

Hi, you have to enable the SYSGEN_CRYPTO_DSSDH option (see https://docs.microsoft.com/en-us/previous-versions/windows/embedded/ms922656(v=msdn.10)) when building the OS image in Windows CE 6.0 Platform builder. There is a corresponding option in Platform Builder's GUI as well.