SFTP server: long delay while connecting with full CPU load

0 votes
asked Nov 3, 2016 by Bernhard Schloss (210 points)

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!

Applies to: Rebex Time

1 Answer

0 votes
answered Nov 3, 2016 by Lukas Pokorny (86,990 points)
edited Dec 21, 2016 by Lukas Pokorny
 
Best answer

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).

commented Nov 3, 2016 by Bernhard Schloss (210 points)
Yes, this was the problem. After enabling Diffie-Hellman in the kernel, the delay decreased to 9 sec, which is acceptable. Thanks!
...