Wrong idle time?

Hi,

I am wondering about the idle time FlashFXP shows to me at the end:

[00:07:13] [R] Connecting to BACKUP-HOST -> IP=XXX.XXX.XXX.XXX PORT=22
[00:07:13] [R] Connected to BACKUP-HOST
[00:07:13] [R] Host key algorithm ssh-RSA, size 2048 bits.
[00:07:13] [R] Fingerprint (MD5): XX:XX:XX:XX:XX:XX:XX:XX:XX:XX:XX:XX:XX:XX:XX:XX
[00:07:13] [R] Key exchange: diffie-hellman-group14-sha1. Session encryption: aes256-ctr, MAC: hmac-sha1, compression: none.
[00:07:16] [R] Auth Type: Public Key
[00:07:16] [R] Authentication succeeded
[00:07:16] [R] SSH Connection open
[00:07:16] [R] Connection established with OpenSSH_5.9p1-hpn13v11 (SFTP v3)
[00:07:16] [R] SFTP Connection Ready
[00:07:16] [R] Retrieving file list...
[00:07:16] [R] List Complete: 1 KB in 0,13 second (1,6 KB/s)
[00:07:30] [R] Changed Directory to: /backups/
[00:07:30] [R] Retrieving file list...
[00:07:31] [R] List Complete: 28 KB in 0,22 second (28,2 KB/s)
[00:07:32] 209 object(s) Filtered.
[00:07:37] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[00:50:13] Transferred: host_XXX-full_YYYYYYYY.tar.gz 2,79 GB in 42 minutes 35 seconds (1,12 MB/s)
[00:50:13] Transfer queue completed
[00:50:13] Transferred 1 File (2,79 GB) in 42 minutes 35 seconds (1,12 MB/s)
[00:50:27] [R] Retrieving file list...
[00:50:27] [R] List Complete: 30 KB in 0,20 second (30,3 KB/s)
[00:50:30] 212 object(s) Filtered.
[00:51:20] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[01:12:53] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,55 GB in 21 minutes 33 seconds (1,22 MB/s)
[01:12:53] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[01:33:29] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,48 GB in 20 minutes 36 seconds (1,22 MB/s)
[01:33:29] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[02:01:22] Transferred: host_XXX-full_YYYYYYYY.tar.gz 2,01 GB in 27 minutes 53 seconds (1,23 MB/s)
[02:01:22] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[02:36:36] Transferred: host_XXX-full_YYYYYYYY.tar.gz 2,53 GB in 35 minutes 13 seconds (1,23 MB/s)
[02:36:36] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[03:18:39] Transferred: host_XXX-full_YYYYYYYY.tar.gz 3,02 GB in 42 minutes 3 seconds (1,23 MB/s)
[03:18:39] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[04:05:14] Transferred: host_XXX-full_YYYYYYYY.tar.gz 3,34 GB in 46 minutes 36 seconds (1,22 MB/s)
[04:05:14] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[04:39:31] Transferred: host_XXX-full_YYYYYYYY.tar.gz 2,45 GB in 34 minutes 17 seconds (1,22 MB/s)
[04:39:32] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[05:33:16] Transferred: host_XXX-full_YYYYYYYY.tar.gz 3,85 GB in 53 minutes 44 seconds (1,22 MB/s)
[05:33:16] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[06:18:03] Transferred: host_XXX-full_YYYYYYYY.tar.gz 3,17 GB in 44 minutes 48 seconds (1,21 MB/s)
[06:18:03] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[06:31:25] [R] SFTP Connection closed
[06:31:25] [R] Download Error: Connection closed by lower level protocol
[06:31:25] [R] SSH Connection closed
[06:31:25] [R] Transfer Failed!
[06:31:25] [R] Connection lost: BACKUP-HOST (Duration: 6 hours 24 minutes 12 seconds / Idle: 5 hours 40 minutes 39 seconds)
[06:31:25] Transferred 9 Files (23,40 GB) in 5 hours 40 minutes 6 seconds (1,17 MB/s)

Seems like you forgot to substract the transfer time from the idle time or something else...

Thank you for your bug report.

My first thought was Doh! How could something so obvious be missed/overlooked?

.. And then I started investigating the issue..

After quite a few tests I determined that the issue only occurs when using the SFTP protocol, further testing then revealed that when working on a SFTP server my transport component class (which acts as a middle-man between the UI and the underlying server protocol) doesn't fire any events when a command is sent or a reply is received.

These events are used to update and display certain messages, as well as reset the idle time.

It appears that the command/reply triggers are written in such a way that they only fire for FTP/FTPS connections and not SFTP. I'm not sure if this was an oversight on my part or intentional.

I will need to review additional areas of the source as well as test a few different things before implementing a fix.

This issue should now be resolved in 4.2 build 1734.

The update is available via live update as a beta update.

I have to re-open the ticket - I still have this bug:

FlashFXP 4.2.0 (build 1739)
Support Forums http://forum.flashfxp.com
[01:03:27] Winsock 2.2 -- OpenSSL 1.0.1 14 Mar 2012
[01:08:25] [R] Connecting to BACKUP-HOST -> IP=XXX.XXX.XXX.XXX PORT=22
[01:08:26] [R] Connected to BACKUP-HOST
[01:08:26] [R] Host key algorithm ssh-RSA, size 2048 bits.
[01:08:26] [R] Fingerprint (MD5): XX:XX:XX:XX:XX:XX:XX:XX:XX:XX:XX:XX:XX:XX:XX:XX
[01:08:26] [R] Key exchange: diffie-hellman-group14-sha1. Session encryption: aes256-ctr, MAC: hmac-sha1, compression: none.
[01:08:29] [R] Authentication failed [Keyboard-interactive]
[01:08:29] [R] Auth Type: Public Key
[01:08:29] [R] Authentication succeeded
[01:08:29] [R] SSH Connection open
[01:08:29] [R] Connection established with OpenSSH_5.9p1-hpn13v11 (SFTP v3)
[01:08:29] [R] SFTP Connection Ready
[01:08:29] [R] Retrieving file list...
[01:08:29] [R] List Complete: 1 KB in 0,32 second (1,6 KB/s)
[01:08:39] [R] Changed Directory to: /backups/
[01:08:39] [R] Retrieving file list...
[01:08:39] [R] List Complete: 3 KB in 0,25 second (3,9 KB/s)
[01:08:41] 18 object(s) Filtered.
[01:09:02] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[01:48:17] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,87 GB in 39 minutes 15 seconds (833,7 KB/s)
[01:48:17] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[02:05:34] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,25 GB in 17 minutes 17 seconds (1,23 MB/s)
[02:05:34] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[02:26:55] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,54 GB in 21 minutes 21 seconds (1,23 MB/s)
[02:26:55] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[02:54:15] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,97 GB in 27 minutes 20 seconds (1,23 MB/s)
[02:54:15] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[03:21:03] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,93 GB in 26 minutes 47 seconds (1,23 MB/s)
[03:21:03] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[03:45:10] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,74 GB in 24 minutes 7 seconds (1,23 MB/s)
[03:45:10] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[04:07:40] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,62 GB in 22 minutes 30 seconds (1,23 MB/s)
[04:07:40] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[04:35:09] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,98 GB in 27 minutes 29 seconds (1,23 MB/s)
[04:35:09] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[04:54:57] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,43 GB in 19 minutes 49 seconds (1,23 MB/s)
[04:54:57] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[05:15:03] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,45 GB in 20 minutes 5 seconds (1,23 MB/s)
[05:15:03] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[05:32:56] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,29 GB in 17 minutes 53 seconds (1,23 MB/s)
[05:32:56] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[05:59:18] Transferred: host_XXX-full_YYYYYYYY.tar.gz 1,90 GB in 26 minutes 22 seconds (1,23 MB/s)
[05:59:18] [R] Downloading: /backups/host_XXX-full_YYYYYYYY.tar.gz
[06:19:46] [R] SFTP Connection closed
[06:19:46] [R] Download Error: Connection closed by lower level protocol
[06:19:46] [R] SSH Connection closed
[06:19:46] [R] Transfer Failed!
[06:19:46] [R] Connection lost: BACKUP-HOST (Duration: 5 hours 11 minutes 21 seconds / Idle: 5 hours 10 minutes 44 seconds)
[06:19:46] Transferred 12 Files (20,00 GB) in 5 hours 10 minutes 44 seconds (1,10 MB/s)
[06:19:46] Transfer queue completed
[06:19:46] Transferred 12 Files (20,00 GB) in 5 hours 10 minutes 44 seconds (1,10 MB/s)
[06:19:46] 1 File Failed

Thank you for the status update, I will continue to investigate this issue.

This should now be fixed in build 1744, which is now available via the update check.