Opened on Feb 27, 2015 at 10:22:44 AM
Closed on Apr 17, 2015 at 9:25:40 PM
Last modified on Apr 18, 2015 at 4:57:12 AM
#8618 closed defect (fixed)
I/O dropping to zero for file transfers
Reported by: | shorshe | Owned by: | dkocher |
---|---|---|---|
Priority: | high | Milestone: | 4.7 |
Component: | sftp | Version: | 4.6.5 |
Severity: | normal | Keywords: | |
Cc: | Architecture: | Intel | |
Platform: | Mac OS X 10.10 |
Description
I have a strange issue:
Upload to a SFTP-Server stops transferring after 60 seconds. Without any error message. Just IO dropping to zero. Testing with FileZilla with the same server same login credentials same OS same files has no issues.
Attachments (1)
Change History (20)
comment:1 Changed on Feb 27, 2015 at 12:03:27 PM by shorshe
comment:2 Changed on Feb 27, 2015 at 1:47:38 PM by dkocher
- Summary changed from Connection to SFTP-Server terminates after 60 Seconds to Connection terminates after 60 Seconds
comment:3 Changed on Mar 3, 2015 at 5:34:54 PM by jihadjo
Same issue also with ftp, I can connect to every FTP server just fine, however being inactive for X amount of minutes causes me to be unable to save an open document on the server because the connection has been lost. I tried to change my code editor, backets sublime text, coda, nothing changes. Trying with Filezilla, the problem does not appear. The workaround is to go back to my bookmarks page and navigate the filesystem and reopen the document for editing. This is very constraining
I'm using Cyberduck 4.6.5 (17000)
comment:4 Changed on Mar 31, 2015 at 8:37:21 AM by dkocher
- Milestone set to 4.7
#8699 closed as duplicate.
comment:5 Changed on Mar 31, 2015 at 8:38:03 AM by dkocher
- Status changed from new to assigned
- Summary changed from Connection terminates after 60 Seconds to I/O dropping to zero for file transfers
comment:6 Changed on Mar 31, 2015 at 2:46:38 PM by dkocher
- Priority changed from normal to high
#8710 closed as duplicate.
comment:7 Changed on Apr 17, 2015 at 2:04:31 PM by dkocher
Please update to the latest snapshot build available and report if the issue persists.
comment:8 Changed on Apr 17, 2015 at 2:23:21 PM by dkocher
- Resolution set to worksforme
- Status changed from assigned to closed
comment:9 follow-up: ↓ 11 Changed on Apr 17, 2015 at 2:40:45 PM by shorshe
tested with Version 4.7 (17316) still persists for me.
comment:10 Changed on Apr 17, 2015 at 2:44:47 PM by dkocher
- Resolution worksforme deleted
- Status changed from closed to reopened
comment:11 in reply to: ↑ 9 Changed on Apr 17, 2015 at 2:45:28 PM by dkocher
Replying to shorshe:
tested with Version 4.7 (17316) still persists for me.
Is it possible to get a test account on this server?
comment:12 follow-up: ↓ 13 Changed on Apr 17, 2015 at 2:52:25 PM by shorshe
I'll ask the admin on monday.
Is there any info/log I could give you in the meantime?
comment:13 in reply to: ↑ 12 Changed on Apr 17, 2015 at 6:52:59 PM by dkocher
Replying to shorshe:
I'll ask the admin on monday.
Is there any info/log I could give you in the meantime? Would a remote session to my machine help?
It would help if you can run Cyberduck CLI with logging enabled and attach the output.
env "logging=debug" duck --upload …
comment:14 Changed on Apr 17, 2015 at 7:51:50 PM by shorshe
ok here you go (just the interesting part at the end):
2015-04-17 21:48:14,939 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 184 down to 98258 2015-04-17 21:48:14,940 [background-1] INFO ch.cyberduck.core.Session - 228 WRITE 2015-04-17 21:48:14,940 [background-1] DEBUG ch.cyberduck.core.sftp.SFTPSession$4 - Sending Request{228;WRITE} 2015-04-17 21:48:14,942 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 32814 down to 65444 2015-04-17 21:48:14,942 [background-1] INFO ch.cyberduck.core.Session - 229 WRITE 2015-04-17 21:48:14,942 [background-1] DEBUG ch.cyberduck.core.sftp.SFTPSession$4 - Sending Request{229;WRITE} 2015-04-17 21:48:14,944 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 32814 down to 32630 2015-04-17 21:48:14,945 [background-1] INFO ch.cyberduck.core.Session - 230 WRITE 2015-04-17 21:48:14,945 [background-1] DEBUG ch.cyberduck.core.sftp.SFTPSession$4 - Sending Request{230;WRITE} 2015-04-17 21:48:14,946 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 32630 down to 0 2015-04-17 21:48:14,946 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Waiting, need size to grow from 0 bytes 2015-04-17 21:48:15,141 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 53 down to 2085173 2015-04-17 21:48:15,141 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received STATUS packet 2015-04-17 21:48:15,141 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 227>> to `Buffer [rpos=5, wpos=49, size=49]` 2015-04-17 21:48:15,732 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 53 down to 2085120 2015-04-17 21:48:15,732 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received STATUS packet 2015-04-17 21:48:15,732 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 228>> to `Buffer [rpos=5, wpos=49, size=49]` 2015-04-17 21:48:15,784 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 53 down to 2085067 2015-04-17 21:48:15,785 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received STATUS packet 2015-04-17 21:48:15,785 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 229>> to `Buffer [rpos=5, wpos=49, size=49]` 2015-04-17 21:48:15,785 [reader] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Received window adjustment for 98442 bytes 2015-04-17 21:48:15,785 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Increasing by 98442 up to 98442 2015-04-17 21:48:15,785 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 184 down to 98258 2015-04-17 21:48:15,785 [background-1] INFO ch.cyberduck.core.Session - 231 WRITE 2015-04-17 21:48:15,785 [background-1] DEBUG ch.cyberduck.core.sftp.SFTPSession$4 - Sending Request{231;WRITE} 2015-04-17 21:48:15,787 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 32814 down to 65444 2015-04-17 21:48:15,788 [background-1] INFO ch.cyberduck.core.Session - 232 WRITE 2015-04-17 21:48:15,788 [background-1] DEBUG ch.cyberduck.core.sftp.SFTPSession$4 - Sending Request{232;WRITE} 2015-04-17 21:48:15,789 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 32814 down to 32630 2015-04-17 21:48:15,790 [background-1] INFO ch.cyberduck.core.Session - 233 WRITE 2015-04-17 21:48:15,790 [background-1] DEBUG ch.cyberduck.core.sftp.SFTPSession$4 - Sending Request{233;WRITE} 2015-04-17 21:48:15,792 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 32630 down to 0 2015-04-17 21:48:15,792 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Waiting, need size to grow from 0 bytes 2015-04-17 21:48:15,899 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 53 down to 2085014 2015-04-17 21:48:15,900 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received STATUS packet 2015-04-17 21:48:15,900 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 230>> to `Buffer [rpos=5, wpos=49, size=49]` 2015-04-17 21:48:16,167 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 53 down to 2084961 2015-04-17 21:48:16,167 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received STATUS packet 2015-04-17 21:48:16,167 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 231>> to `Buffer [rpos=5, wpos=49, size=49]` 2015-04-17 21:48:16,502 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 53 down to 2084908 2015-04-17 21:48:16,502 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received STATUS packet 2015-04-17 21:48:16,502 [reader] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Received window adjustment for 98442 bytes 2015-04-17 21:48:16,502 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Increasing by 98442 up to 98442 2015-04-17 21:48:16,502 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 232>> to `Buffer [rpos=5, wpos=49, size=49]` 2015-04-17 21:48:16,503 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 184 down to 98258 2015-04-17 21:48:16,503 [background-1] INFO ch.cyberduck.core.Session - 234 WRITE 2015-04-17 21:48:16,503 [background-1] DEBUG ch.cyberduck.core.sftp.SFTPSession$4 - Sending Request{234;WRITE} 2015-04-17 21:48:16,505 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 32814 down to 65444 2015-04-17 21:48:16,505 [background-1] INFO ch.cyberduck.core.Session - 235 WRITE 2015-04-17 21:48:16,505 [background-1] DEBUG ch.cyberduck.core.sftp.SFTPSession$4 - Sending Request{235;WRITE} 2015-04-17 21:48:16,507 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 32814 down to 32630 2015-04-17 21:48:16,507 [background-1] INFO ch.cyberduck.core.Session - 236 WRITE 2015-04-17 21:48:16,507 [background-1] DEBUG ch.cyberduck.core.sftp.SFTPSession$4 - Sending Request{236;WRITE} 2015-04-17 21:48:16,509 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 32630 down to 0 2015-04-17 21:48:16,509 [background-1] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Waiting, need size to grow from 0 bytes 2015-04-17 21:48:16,660 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 53 down to 2084855 2015-04-17 21:48:16,660 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received STATUS packet 2015-04-17 21:48:16,660 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 233>> to `Buffer [rpos=5, wpos=49, size=49]` 2015-04-17 21:48:17,015 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 53 down to 2084802 2015-04-17 21:48:17,015 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received STATUS packet 2015-04-17 21:48:17,015 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 234>> to `Buffer [rpos=5, wpos=49, size=49]` 2015-04-17 21:48:17,134 [keep-alive] DEBUG net.schmizz.keepalive.KeepAliveRunner - Sending keep-alive since 10 seconds elapsed 2015-04-17 21:48:17,134 [keep-alive] ERROR net.schmizz.sshj.transport.TransportImpl - Dying because - {} net.schmizz.sshj.connection.ConnectionException: [CONNECTION_LOST] Did not receive any keep-alive response for 50 seconds at net.schmizz.keepalive.KeepAliveRunner.checkMaxReached(KeepAliveRunner.java:63) at net.schmizz.keepalive.KeepAliveRunner.doKeepAlive(KeepAliveRunner.java:56) at net.schmizz.keepalive.KeepAlive.run(KeepAlive.java:64) 2015-04-17 21:48:17,135 [keep-alive] WARN ch.cyberduck.core.sftp.SFTPSession - Disconnected CONNECTION_LOST 2015-04-17 21:48:17,136 [keep-alive] DEBUG net.schmizz.sshj.transport.KeyExchanger - Got notified of net.schmizz.sshj.connection.ConnectionException: [CONNECTION_LOST] Did not receive any keep-alive response for 50 seconds 2015-04-17 21:48:17,136 [keep-alive] DEBUG net.schmizz.sshj.connection.ConnectionImpl - Notified of net.schmizz.sshj.connection.ConnectionException: [CONNECTION_LOST] Did not receive any keep-alive response for 50 seconds
Changed on Apr 17, 2015 at 8:09:40 PM by shorshe
Full Log of duck.sh output while connecting to an sftp-server
comment:15 Changed on Apr 17, 2015 at 8:40:23 PM by dkocher
Thanks for posting the transcript. I suspect there might be an interoperability issue with the SSH serverwith the heartbeat packets sent. Can you try with
env "ssh.heartbeat.seconds=0" duck …
comment:16 follow-up: ↓ 17 Changed on Apr 17, 2015 at 8:49:07 PM by shorshe
Seems to work fine. I'm well beyond the 50 sec mark and still going.
I think you found the reason! Upload still alive after 10 minutes bandwidth fluctuation in normal range.
FYI: older Versions of Cyberduck could work with this server.
comment:17 in reply to: ↑ 16 Changed on Apr 17, 2015 at 9:13:19 PM by dkocher
comment:18 Changed on Apr 17, 2015 at 9:25:40 PM by dkocher
- Resolution set to fixed
- Status changed from reopened to closed
In r17336.
comment:19 Changed on Apr 18, 2015 at 4:57:12 AM by shorshe
That's great news!! Thanks a lot!
Cyberduck CLI shows the same behaviour. Successful connection successful start of transfer with subsequent stall until local timeout.