SetAsyncRequestReply called to wrong time

[DynamicBits]

I am attempting to transfer tens of thousands of files, totaling over 50GB to a SFTP server. They all show up in the queue and everything starts out OK.

After transferring approximately 1GB of data, the transfer stalls. It happens both with lots of small files, or one giant file. I have tried with a maximum of one upload and also with two simultaneous uploads and the result is always the same.

The problem seems to revolve around the negotiation of a new key.

The server is running ubuntu 10.04.
The client is running Windows XP Pro SP3 (with FileZilla 3.3.2.1).

Below is the log from initial connection until the timeout. (Only the last dozen lines seem relevant to this problem.)

Status: Connecting to 192.168.254.200:2222...
Trace: Going to execute "C:\Program Files\FileZilla FTP Client\fzsftp.exe"
Status: Connecting to 192.168.254.200:2222...
Trace: Going to execute "C:\Program Files\FileZilla FTP Client\fzsftp.exe"
Response: fzSftp started
Trace: CSftpControlSocket::ConnectParseResponse(fzSftp started)
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::ConnectSend()
Command: open "user001@192.168.254.200" 2222
Response: fzSftp started
Trace: CSftpControlSocket::ConnectParseResponse(fzSftp started)
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::ConnectSend()
Command: open "user001@192.168.254.200" 2222
Trace: Looking up host "192.168.254.200"
Trace: Connecting to 192.168.254.200 port 2222
Trace: Looking up host "192.168.254.200"
Trace: Connecting to 192.168.254.200 port 2222
Trace: Server version: SSH-2.0-OpenSSH_5.3p1 Debian-3ubuntu3
Trace: Using SSH protocol version 2
Trace: We claim version: SSH-2.0-PuTTY_Local:_Mar_21_2010_19:19:21
Trace: Doing Diffie-Hellman group exchange
Trace: Server version: SSH-2.0-OpenSSH_5.3p1 Debian-3ubuntu3
Trace: Using SSH protocol version 2
Trace: We claim version: SSH-2.0-PuTTY_Local:_Mar_21_2010_19:19:21
Trace: Doing Diffie-Hellman key exchange with hash SHA-256
Trace: Doing Diffie-Hellman group exchange
Trace: Doing Diffie-Hellman key exchange with hash SHA-256
Command: Trust new Hostkey: Once
Command: Trust new Hostkey: Once
Trace: Host key fingerprint is:
Trace: ssh-rsa 2048 c0:32:e1:9c:0a:e7:fe:4f:03:70:e7:83:90:33:b5:d1
Trace: Host key fingerprint is:
Trace: ssh-rsa 2048 c0:32:e1:9c:0a:e7:fe:4f:03:70:e7:83:90:33:b5:d1
Trace: Initialised AES-256 SDCTR client->server encryption
Trace: Initialised HMAC-SHA1 client->server MAC algorithm
Trace: Initialised AES-256 SDCTR server->client encryption
Trace: Initialised HMAC-SHA1 server->client MAC algorithm
Trace: Pageant is running. Requesting keys.
Trace: Pageant has 0 SSH-2 keys
Trace: Initialised AES-256 SDCTR client->server encryption
Trace: Initialised HMAC-SHA1 client->server MAC algorithm
Trace: Initialised AES-256 SDCTR server->client encryption
Trace: Initialised HMAC-SHA1 server->client MAC algorithm
Trace: Pageant is running. Requesting keys.
Trace: Pageant has 0 SSH-2 keys
Command: Pass: ********
Command: Pass: ********
Trace: Sent password
Trace: Sent password
Trace: Access granted
Trace: Access granted
Trace: Opened channel for session
Trace: Started a shell/command
Status: Connected to 192.168.254.200
Trace: CSftpControlSocket::ConnectParseResponse()
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CSftpControlSocket::FileTransfer(...)
Status: Starting upload of S:\old drive\user001\vmware\XP Pro SP1a PartnerPak\Win XP Pro SP1a-cl1-000004-s007.vmdk
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::ChangeDirSend()
Command: cd "/media/truecrypt1/from hp/old old drive/user001/vmware/XP Pro SP1a PartnerPak"
Trace: Opened channel for session
Trace: Started a shell/command
Status: Connected to 192.168.254.200
Response: New directory is: "/media/truecrypt1/from hp/old old drive/user001/vmware/XP Pro SP1a PartnerPak"
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::FileTransferSubcommandResult()
Status: Retrieving directory listing...
Trace: sftpcontrolsocket.cpp(959): List called from other command caller=0p5eb1b40
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::ListSubcommandResult()
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::ListSend()
Command: ls
Trace: CSftpControlSocket::ConnectParseResponse()
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CSftpControlSocket::FileTransfer(...)
Status: Starting upload of S:\old drive\user001\vmware\XP Pro SP1a PartnerPak\Win XP Pro SP1a-cl1-000003-s002.vmdk
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::ChangeDirSend()
Command: cd "/media/truecrypt1/from hp/old old drive/user001/vmware/XP Pro SP1a PartnerPak"
Status: Listing directory /media/truecrypt1/from hp/old old drive/user001/vmware/XP Pro SP1a PartnerPak
Trace: CSftpControlSocket::ListParseResponse()
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::ListSend()
Status: Calculating timezone offset of server...
Command: mtime "Win XP Pro SP1a-cl1-000001-s001.vmdk"
Response: New directory is: "/media/truecrypt1/from hp/old old drive/user001/vmware/XP Pro SP1a PartnerPak"
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::FileTransferSubcommandResult()
Status: Retrieving directory listing...
Trace: sftpcontrolsocket.cpp(959): List called from other command caller=0p5eb1890
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::ListSubcommandResult()
Response: 1275163077
Trace: CSftpControlSocket::ListParseResponse(1275163077)
Status: Timezone offsets: Server: -18000 seconds. Local: -18000 seconds. Difference: 0 seconds.
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::FileTransferSubcommandResult()
Trace: CSftpControlSocket::SendNextCommand()
Trace: CSftpControlSocket::ListSend()
Trace: Unknown opStatein CSftpControlSocket::ListSend
Trace: CSftpControlSocket::ResetOperation(130)
Trace: CControlSocket::ResetOperation(130)
Trace: CSftpControlSocket::ResetOperation(130)
Trace: CControlSocket::ResetOperation(130)
Error: File transfer failed
Trace: CSftpControlSocket::FileTransfer(...)
Status: Starting upload of S:\old drive\user001\vmware\XP Pro SP1a PartnerPak\Win XP Pro SP1a-cl1-000003-s002.vmdk
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::FileTransferSubcommandResult()
Trace: CSftpControlSocket::SendNextCommand()
Trace: FileTransferSend()
Command: put "S:\old drive\user001\vmware\XP Pro SP1a PartnerPak\Win XP Pro SP1a-cl1-000003-s002.vmdk" "Win XP Pro SP1a-cl1-000003-s002.vmdk"
Status: local:S:\old drive\user001\vmware\XP Pro SP1a PartnerPak\Win XP Pro SP1a-cl1-000003-s002.vmdk => remote:/media/truecrypt1/from hp/old old drive/user001/vmware/XP Pro SP1a PartnerPak/Win XP Pro SP1a-cl1-000003-s002.vmdk
Trace: CSftpControlSocket::SendNextCommand()
Trace: FileTransferSend()
Command: put "S:\old drive\user001\vmware\XP Pro SP1a PartnerPak\Win XP Pro SP1a-cl1-000004-s007.vmdk" "Win XP Pro SP1a-cl1-000004-s007.vmdk"
Status: local:S:\old drive\user001\vmware\XP Pro SP1a PartnerPak\Win XP Pro SP1a-cl1-000004-s007.vmdk => remote:/media/truecrypt1/from hp/old old drive/user001/vmware/XP Pro SP1a PartnerPak/Win XP Pro SP1a-cl1-000004-s007.vmdk
Trace: FileTransferParseResponse()
Trace: CSftpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Status: File transfer successful, transferred 860,401,664 bytes in 493 seconds
Trace: CSftpControlSocket::FileTransfer(...)
Status: Starting upload of S:\old drive\user001\vmware\XP Pro SP1a PartnerPak\Win XP Pro SP1a-cl1-s001.vmdk
Trace: CSftpControlSocket::ParseSubcommandResult(0)
Trace: CSftpControlSocket::FileTransferSubcommandResult()
Trace: CSftpControlSocket::SendNextCommand()
Trace: FileTransferSend()
Command: put "S:\old drive\user001\vmware\XP Pro SP1a PartnerPak\Win XP Pro SP1a-cl1-s001.vmdk" "Win XP Pro SP1a-cl1-s001.vmdk"
Status: local:S:\old drive\user001\vmware\XP Pro SP1a PartnerPak\Win XP Pro SP1a-cl1-s001.vmdk => remote:/media/truecrypt1/from hp/old old drive/user001/vmware/XP Pro SP1a PartnerPak/Win XP Pro SP1a-cl1-s001.vmdk
Trace: Initiating key re-exchange (too much data sent)
Trace: Doing Diffie-Hellman group exchange
Trace: Doing Diffie-Hellman key exchange with hash SHA-256
Trace: SetAsyncRequestReply called to wrong time
Trace: Initiating key re-exchange (too much data sent)
Trace: Doing Diffie-Hellman group exchange
Trace: Doing Diffie-Hellman key exchange with hash SHA-256
Trace: SetAsyncRequestReply called to wrong time
Error: Connection timed out
Trace: CSftpControlSocket::ResetOperation(2114)
Trace: CControlSocket::ResetOperation(2114)
Error: File transfer failed after transferring 992,083,968 bytes in 608 seconds

[DynamicBits]

I have a little more to add. I have the "Timeout in seconds" value in FileZilla set to 20. Often times, the timeout is not ever detected after the SetAsyncRequestReply message. If I right-click in the queue and (un)select the "Process Queue" option, *then* the "CSftpControlSocket::ResetOperation(74)" (and the next two lines) appear.

I set LogLevel to DEBUG3 on the ssh server and captured the log output for both FileZilla and the server when another transfer failed. Here is the relevant portion from FileZilla (this time FileZilla did not detect the timeout and I had to eventually cancel the queue):

Trace: Initiating key re-exchange (too much data sent)
Trace: Doing Diffie-Hellman group exchange
Trace: Doing Diffie-Hellman key exchange with hash SHA-256
Trace: SetAsyncRequestReply called to wrong time
Trace: CSftpControlSocket::ResetOperation(74)
Trace: CControlSocket::ResetOperation(74)
Error: File transfer aborted by user after transferring 5,468,160 bytes in 400 seconds

Here is the relevant portion from the ssh server:

May 30 03:15:18 toronto sshd[6496]: debug3: Wrote 68 bytes for a total of 16694139
May 30 03:15:18 toronto sshd[6496]: debug3: Wrote 68 bytes for a total of 16694207
May 30 03:15:18 toronto sshd[6496]: debug2: channel 0: window 1998664 sent adjust 98488
May 30 03:15:18 toronto sshd[6496]: debug3: Wrote 52 bytes for a total of 16694259
May 30 03:15:18 toronto sshd[6496]: debug3: Wrote 68 bytes for a total of 16694327
May 30 03:15:18 toronto sshd[6496]: debug3: Wrote 68 bytes for a total of 16694395
May 30 03:15:18 toronto sshd[6496]: debug3: Wrote 68 bytes for a total of 16694463
May 30 03:15:18 toronto sshd[6496]: debug3: Wrote 68 bytes for a total of 16694531
May 30 03:15:18 toronto sshd[6496]: debug3: Wrote 68 bytes for a total of 16694599
May 30 03:15:18 toronto sshd[6496]: debug3: Wrote 68 bytes for a total of 16694667
May 30 03:15:18 toronto sshd[6496]: debug3: Wrote 68 bytes for a total of 16694735
May 30 03:15:19 toronto sshd[6496]: debug3: Wrote 68 bytes for a total of 16694803
May 30 03:15:19 toronto sshd[6496]: debug1: SSH2_MSG_KEXINIT received
May 30 03:15:19 toronto sshd[6496]: debug1: SSH2_MSG_KEXINIT sent
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@…
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@…
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@…,hmac-ripemd160,hmac-ripemd160@…,hmac-sha1-96,hmac-md5-96
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@…,hmac-ripemd160,hmac-ripemd160@…,hmac-sha1-96,hmac-md5-96
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: none,zlib@…
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: none,zlib@…
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit:
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit:
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: first_kex_follows 0
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: reserved 0
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,rsa2048-sha256,rsa1024-sha1
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: aes256-ctr,aes256-cbc,rijndael-cbc@…,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,arcfour128
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: aes256-ctr,aes256-cbc,rijndael-cbc@…,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,arcfour128
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: hmac-sha1,hmac-sha1-96,hmac-md5
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: hmac-sha1,hmac-sha1-96,hmac-md5
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: none,zlib
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: none,zlib
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit:
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit:
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: first_kex_follows 0
May 30 03:15:19 toronto sshd[6496]: debug2: kex_parse_kexinit: reserved 0
May 30 03:15:19 toronto sshd[6496]: debug2: mac_setup: found hmac-sha1
May 30 03:15:19 toronto sshd[6496]: debug1: kex: client->server aes256-ctr hmac-sha1 none
May 30 03:15:19 toronto sshd[6496]: debug2: mac_setup: found hmac-sha1
May 30 03:15:19 toronto sshd[6496]: debug1: kex: server->client aes256-ctr hmac-sha1 none
May 30 03:15:19 toronto sshd[6496]: debug3: Wrote 804 bytes for a total of 16695607
May 30 03:15:19 toronto sshd[6496]: debug1: SSH2_MSG_KEX_DH_GEX_REQUEST_OLD received
May 30 03:15:19 toronto sshd[6496]: debug3: mm_request_send entering: type 0
May 30 03:15:19 toronto sshd[6496]: debug3: mm_choose_dh: waiting for MONITOR_ANS_MODULI
May 30 03:15:19 toronto sshd[6496]: debug3: mm_request_receive_expect entering: type 1
May 30 03:15:19 toronto sshd[6432]: debug3: monitor_read: checking request 0
May 30 03:15:19 toronto sshd[6496]: debug3: mm_request_receive entering
May 30 03:15:19 toronto sshd[6432]: debug3: mm_answer_moduli: got parameters: 1024 4096 8192
May 30 03:15:19 toronto sshd[6432]: debug3: mm_request_send entering: type 1
May 30 03:15:19 toronto sshd[6432]: debug3: mm_request_receive entering
May 30 03:15:19 toronto sshd[6496]: debug3: mm_choose_dh: remaining 0
May 30 03:15:19 toronto sshd[6496]: debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
May 30 03:15:19 toronto sshd[6496]: debug3: Wrote 564 bytes for a total of 16696171
May 30 03:15:19 toronto sshd[6496]: debug2: dh_gen_key: priv key bits set: 255/512
May 30 03:15:19 toronto sshd[6496]: debug2: bits set: 2051/4096
May 30 03:15:19 toronto sshd[6496]: debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT
May 30 03:15:19 toronto sshd[6496]: debug2: bits set: 2000/4096
May 30 03:15:19 toronto sshd[6496]: debug3: mm_key_sign entering
May 30 03:15:19 toronto sshd[6496]: debug3: mm_request_send entering: type 5
May 30 03:15:19 toronto sshd[6432]: debug3: monitor_read: checking request 5
May 30 03:15:19 toronto sshd[6432]: debug3: mm_answer_sign
May 30 03:15:19 toronto sshd[6496]: debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN
May 30 03:15:19 toronto sshd[6496]: debug3: mm_request_receive_expect entering: type 6
May 30 03:15:19 toronto sshd[6496]: debug3: mm_request_receive entering
May 30 03:15:19 toronto sshd[6432]: debug3: mm_answer_sign: signature 0x7f891d777d70(271)
May 30 03:15:19 toronto sshd[6432]: debug3: mm_request_send entering: type 6
May 30 03:15:19 toronto sshd[6432]: debug3: mm_request_receive entering
May 30 03:15:19 toronto sshd[6496]: debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent
May 30 03:15:19 toronto sshd[6496]: debug2: kex_derive_keys
May 30 03:15:19 toronto sshd[6496]: debug2: set_newkeys: mode 1
May 30 03:15:19 toronto sshd[6496]: debug1: set_newkeys: rekeying
May 30 03:15:19 toronto sshd[6496]: debug2: cipher_init: set keylen (16 -> 32)
May 30 03:15:19 toronto sshd[6496]: debug1: SSH2_MSG_NEWKEYS sent
May 30 03:15:19 toronto sshd[6496]: debug1: expecting SSH2_MSG_NEWKEYS
May 30 03:15:19 toronto sshd[6496]: debug3: Wrote 1144 bytes for a total of 16697315
May 30 03:21:57 toronto sshd[6496]: fatal: Read from socket failed: Connection reset by peer
May 30 03:21:57 toronto sshd[6496]: debug1: do_cleanup
May 30 03:21:57 toronto sshd[6496]: debug3: PAM: sshpam_thread_cleanup entering
May 30 03:21:57 toronto sshd[6432]: debug1: do_cleanup
May 30 03:21:57 toronto sshd[6432]: debug1: PAM: cleanup
May 30 03:21:57 toronto sshd[6432]: debug1: PAM: closing session
May 30 03:21:57 toronto sshd[6432]: pam_unix(sshd:session): session closed for user user001
May 30 03:21:57 toronto sshd[6432]: debug1: PAM: deleting credentials
May 30 03:21:57 toronto sshd[6432]: debug3: PAM: sshpam_thread_cleanup entering

During this, there were no firewall rules on either the client or server.

[codesquid]

Confirmed.

Workaround: Permanently trust the hostkey instead of just once.

[codesquid]

I have committed a fix into the repository. Will be included in the next version of FileZilla.