id summary reporter owner description type status priority component resolution keywords cc component_version os os_version 5375 SetAsyncRequestReply called to wrong time Andy Tim Kosse "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" Other closed low FileZilla Client fixed Windows XP SP3