I'm using edtFTPnet/PRO for a specialized file transfer application on Windows. I've used it for a while for both FTP and SFTP, and executing SSH commands. I'm currently trying to get timeouts working correctly. In most cases, they roughly do what they promise (though not exact; Timeout property set to 30000 or 60000 may actually time out after 24 seconds, but I'm fine with that).
However, I currently have a case that will not work. I open a connection, call UploadFile/UploadStream, with Timeout set to 60000. I'm transferring a file of about 200MB to a relatively small system, so this takes maybe 20 seconds. In the middle of this transfer, I unplug the Ethernet cable.
The UploadFile/UploadStream call never returns.
I tried KeepAlive/KeepAliveTransfer, setting RetryCount to 0 (suggested in the forums), and ultimately tried out BeginUploadFile/BeginUploadStream. This allows me to cancel manually after a given timeout, with CancelTask and or AbortAsynchronous returning immediately and the log shows that they are being called.
However, then in the next step, Close/Dispose hangs infinitely.
Note that if the cable is unplugged right before the file transfer starts, the timeout works fine.
There seems to be no way to get around this. We used 9.0.1.20 until now, but the behaviour with the latest 9.2.0.20 is identical. The debug log is as follows (replaced filenames with filename.ext):
Beginning file transfer with timeout 60000.
DEBUG [FTPTaskProcessor] 12 Nov 2018 12:01:15.301 : BeginTask: [ID=1] UploadStream(CrcCalculatorStream="Ionic.Crc.CrcCalculatorStream", String="filename.ext")
DEBUG [FTPTaskProcessor] 12 Nov 2018 12:01:15.305 : Invoking task on connection 3: [ID=1] UploadStream(CrcCalculatorStream="Ionic.Crc.CrcCalculatorStream", String="filename.ext")
DEBUG [FTPTaskProcessor] 12 Nov 2018 12:01:15.308 : FTPConnection.4 Running task on connection 3: [ID=1] UploadStream(CrcCalculatorStream="Ionic.Crc.CrcCalculatorStream", String="filename.ext")
DEBUG [SSHFTPClient] 12 Nov 2018 12:01:15.314 : FTPConnection.4 ResolveRemotePath('filename.ext'); [cwd='/tmp/fwupdate']
DEBUG [SSHFTPClient] 12 Nov 2018 12:01:15.316 : FTPConnection.4 Resolved to '/tmp/fwupdate/filename.ext'
DEBUG [SSHFTPClient] 12 Nov 2018 12:01:15.318 : FTPConnection.4 Remote path=/tmp/fwupdate/filename.ext
DEBUG [SSHFTPClient] 12 Nov 2018 12:01:15.319 : FTPConnection.4 ResolveRemotePath('/tmp/fwupdate/filename.ext'); [cwd='/tmp/fwupdate']
DEBUG [SSHFTPClient] 12 Nov 2018 12:01:15.321 : FTPConnection.4 Resolved to '/tmp/fwupdate/filename.ext'
DEBUG [SFTPSubsystem] 12 Nov 2018 12:01:15.323 : FTPConnection.4 GetAttributes(/tmp/fwupdate/filename.ext)
DEBUG [SFTPMessage] 12 Nov 2018 12:01:15.324 : FTPConnection.4 Send : Name=SSH_FXP_STAT,Type=17,RequestID=10
DEBUG [SSH2Channel] 12 Nov 2018 12:01:15.326 : FTPConnection.4 Transmit 49 bytes
DEBUG [ChannelDataWindow] 12 Nov 2018 12:01:15.328 : FTPConnection.4 Remote window size decreased to 24349
DEBUG [PlainSocket] 12 Nov 2018 12:01:15.332 : FTPConnection.4 RepeatCallback received 96 bytes
DEBUG [SSH2Connection] 12 Nov 2018 12:01:15.334 : FTPConnection.4 ProcessPacket pt=SSH_MSG_CHANNEL_DATA
DEBUG [SFTPMessageFactory] 12 Nov 2018 12:01:15.337 : FTPConnection.4 CreateMessage (bufferlength=50,offset=13,length=37,type=105)
DEBUG [SFTPMessageStore] 12 Nov 2018 12:01:15.338 : FTPConnection.4 AddMessage(10) - added to store
DEBUG [SFTPMessage] 12 Nov 2018 12:01:15.340 : FTPConnection.4 Reply : Name=SSH_FXP_ATTRS,Type=105,RequestID=10
DEBUG [SFTPMessage] 12 Nov 2018 12:01:15.342 : FTPConnection.4 Send : Name=SSH_FXP_OPEN,Type=3,RequestID=11
DEBUG [SSH2Channel] 12 Nov 2018 12:01:15.344 : FTPConnection.4 Transmit 61 bytes
DEBUG [ChannelDataWindow] 12 Nov 2018 12:01:15.345 : FTPConnection.4 Remote window size decreased to 24288
DEBUG [PlainSocket] 12 Nov 2018 12:01:15.350 : FTPConnection.4 RepeatCallback received 80 bytes
DEBUG [SSH2Connection] 12 Nov 2018 12:01:15.351 : FTPConnection.4 ProcessPacket pt=SSH_MSG_CHANNEL_DATA
DEBUG [SFTPMessageFactory] 12 Nov 2018 12:01:15.352 : FTPConnection.4 CreateMessage (bufferlength=26,offset=13,length=13,type=102)
DEBUG [SFTPMessageStore] 12 Nov 2018 12:01:15.355 : FTPConnection.4 AddMessage(11) - added to store
DEBUG [SFTPMessage] 12 Nov 2018 12:01:15.356 : FTPConnection.4 Reply : Name=SSH_FXP_HANDLE,Type=102,RequestID=11
DEBUG [SFTPFileStreamWriter] 12 Nov 2018 12:01:15.358 : FTPConnection.4 Parallel mode = True
DEBUG [SFTPMessage] 12 Nov 2018 12:01:15.362 : FTPConnection.4 Send : Name=SSH_FXP_WRITE,Type=6,RequestID=12
DEBUG [SSH2Channel] 12 Nov 2018 12:01:15.366 : FTPConnection.4 Transmit 24287 bytes
DEBUG [ChannelDataWindow] 12 Nov 2018 12:01:15.368 : FTPConnection.4 Remote window size decreased to 1
DEBUG [PlainSocket] 12 Nov 2018 12:01:15.384 : FTPConnection.4 RepeatCallback received 64 bytes
DEBUG [SSH2Connection] 12 Nov 2018 12:01:15.386 : FTPConnection.4 ProcessPacket pt=SSH_MSG_CHANNEL_WINDOW_ADJUST
DEBUG [ChannelDataWindow] 12 Nov 2018 12:01:15.387 : FTPConnection.4 Increased window space by 24575 to 24576
DEBUG [PlainSocket] 12 Nov 2018 12:01:15.388 : FTPConnection.4 RepeatCallback received 80 bytes
DEBUG [SSH2Connection] 12 Nov 2018 12:01:15.389 : FTPConnection.4 ProcessPacket pt=SSH_MSG_CHANNEL_DATA
DEBUG [SFTPMessageFactory] 12 Nov 2018 12:01:15.390 : FTPConnection.4 CreateMessage (bufferlength=37,offset=13,length=24,type=101)
DEBUG [SFTPMessage] 12 Nov 2018 12:01:15.391 : FTPConnection.4 ErrorCode|Status=0
DEBUG [SFTPMessageStore] 12 Nov 2018 12:01:15.392 : FTPConnection.4 AddMessage(12) - added to store
DEBUG [SFTPMessage] 12 Nov 2018 12:01:15.394 : FTPConnection.4 Send : Name=SSH_FXP_WRITE,Type=6,RequestID=13
DEBUG [SSH2Channel] 12 Nov 2018 12:01:15.396 : FTPConnection.4 Transmit 24575 bytes(snip, repeating for some time)
DEBUG [SSH2Channel] 12 Nov 2018 12:01:19.242 : FTPConnection.4 Transmit 16501 bytes
DEBUG [SFTPMessage] 12 Nov 2018 12:01:19.264 : FTPConnection.4 ErrorCode|Status=0
DEBUG [ChannelDataWindow] 12 Nov 2018 12:01:19.266 : FTPConnection.4 Remote window size decreased to 1
DEBUG [SFTPMessageStore] 12 Nov 2018 12:01:19.288 : FTPConnection.4 AddMessage(63) - added to store
DEBUG [SFTPMessage] 12 Nov 2018 12:01:19.312 : FTPConnection.4 Reply : Name=SSH_FXP_STATUS,Type=101,RequestID=62
DEBUG [SFTPMessage] 12 Nov 2018 12:01:19.314 : FTPConnection.4 Reply : Name=SSH_FXP_STATUS,Type=101,RequestID=63
Der Thread '<Kein Name>' (0x8010) hat mit Code 0 (0x0) geendet.
Der Thread '<Kein Name>' (0x3e58) hat mit Code 0 (0x0) geendet.
Der Thread '<Kein Name>' (0x875c) hat mit Code 0 (0x0) geendet.
Eine Ausnahme (erste Chance) des Typs "System.Net.Sockets.SocketException" ist in System.dll aufgetreten.
ERROR [SSHConnectionReceiver] 12 Nov 2018 12:01:38.232 : FTPConnection.4 Ein Verbindungsversuch ist fehlgeschlagen, da die Gegenstelle nach einer bestimmten Zeitspanne nicht richtig reagiert hat, oder die hergestellte Verbindung war fehlerhaft, da der verbundene Host nicht reagiert hat
ERROR [SSHConnectionReceiver] 12 Nov 2018 12:01:38.232 : FTPConnection.4 System.Net.Sockets.SocketException: Ein Verbindungsversuch ist fehlgeschlagen, da die Gegenstelle nach einer bestimmten Zeitspanne nicht richtig reagiert hat, oder die hergestellte Verbindung war fehlerhaft, da der verbundene Host nicht reagiert hat
ERROR [SSHConnectionReceiver] 12 Nov 2018 12:01:38.232 : FTPConnection.4 bei System.Net.Sockets.Socket.EndReceive(IAsyncResult asyncResult)
ERROR [SSHConnectionReceiver] 12 Nov 2018 12:01:38.232 : FTPConnection.4 bei YXKyprQS2JG75IiEfWI.k1aq8IQvWA5h930fNhp.kJW5lq8qSNa(IAsyncResult )
DEBUG [ChannelDataWindow] 12 Nov 2018 12:01:38.237 : FTPConnection.4 Stopped channel data window
Der Thread '<Kein Name>' (0x8b6c) hat mit Code 0 (0x0) geendet.
Der Thread '<Kein Name>' (0x8080) hat mit Code 0 (0x0) geendet.
DEBUG [FTPSynchronizer] 12 Nov 2018 12:02:45.313 : FTPConnection.4 Cancelling 0 tasks
DEBUG [FTPSynchronizer] 12 Nov 2018 12:02:45.314 : FTPConnection.4 All tasks cancelled
DEBUG [FTPConnectionPool] 12 Nov 2018 12:02:45.316 : FTPConnection.4 Cancelled task 1 on master
Der Thread '<Thread beendet>' (0x8684) hat mit Code 0 (0x0) geendet.
DEBUG [FTPSynchronizer] 12 Nov 2018 12:13:08.275 : FTPConnection.4 Cancelling 0 tasks
DEBUG [FTPSynchronizer] 12 Nov 2018 12:13:08.282 : FTPConnection.4 All tasks cancelled
DEBUG [FTPTaskProcessor] 12 Nov 2018 12:13:08.283 : FTPConnection.4 Purging task queue
DEBUG [FTPSynchronizer] 12 Nov 2018 12:13:08.285 : FTPConnection.4 Cancelling 0 tasks
DEBUG [FTPSynchronizer] 12 Nov 2018 12:13:08.286 : FTPConnection.4 All tasks cancelled
DEBUG [FTPTaskProcessor] 12 Nov 2018 12:13:08.289 : FTPConnection.4 Purging task queue
DEBUG [FTPConnection] 12 Nov 2018 12:13:08.291 : FTPConnection.4 Closing connection [instance=3,abrupt=True]
DEBUG [SSHFTPClient] 12 Nov 2018 12:13:08.293 : FTPConnection.4 QuitImmediately() called
DEBUG [SSH2Connection] 12 Nov 2018 12:13:08.294 : FTPConnection.4 Close() called
Der Thread '<Kein Name>' (0x8a7c) hat mit Code 0 (0x0) geendet.
As you can see, at some time there is a SocketException, which would be the point I would expect for the synchronous functions to return. However, it seems the single task 1 on master is being cancelled as it should be. A few seconds later (after continuing a break point), I'm calling CancelTask, and then, via using blocks, Close and Dispose are being called. But the last Close hangs infinitely.
I don't know what to do. The case of unplugging the connection has not been important for the customer until now, because now we're doing a Firmware Update over SSH and the connection may be over GSM, so it will be very slow and may break suddenly, so returning from a timeout is essential. The application cannot close currently.
Is there any solution to this?
