SSH 文件傳輸在 ~700KB 後掛起
概述
我在現場的 Windows 7 機器上編寫 SFTP 文件傳輸腳本。當我傳輸大於 1 兆字節左右的 zip 文件時,傳輸(和 SSH)在大約 700KB 後意外停止。SSH 程序似乎掛起,但它並沒有開始大量消耗 CPU 或記憶體,而且 Windows 也沒有說它停止響應。伺服器最終放棄並超時,但客戶端永遠不會返回(儘管設置了 ServerAliveCountMax 和 ServerAliveInterval)。伺服器日誌顯示傳輸開始,然後是超時並在很長一段時間後斷開連接。
細節
背靠背重新執行腳本,每次掛起前傳輸的字節數相同。走開又回來,然後再次執行腳本,字節數會相差幾十千字節。
命令行 sftp.exe 客戶端使用預設選項正常工作;那些較大的 zip 文件傳輸成功。我無法測試 scp.exe,因為 SSH 使用者帳戶沒有 shell 訪問權限。我相信這個問題在從 XP 到 7 的作業系統擦除和重新映像中仍然存在,所以我懷疑是網路問題,但我無法理解什麼樣的問題會導致這種行為。
我正在使用 Perl 和 Net::SFTP::Foreign 模組編寫腳本。以下是從我的測試案例腳本中提取的相關程式碼(SSH 輸出日誌附在下面):
my %connectOpts = ( user => $username ,timeout => $timeout ,warn => sub {} ,more => [ "-o PreferredAuthentications=publickey", "-o ServerAliveCountMax=6", "-o ServerAliveInterval=" . int($timeout/6), "-vvvv" ] ); my $sftp = Net::SFTP::Foreign::Compat->new( $host, %connectOpts ); foreach my $local_file ( @local_files ) { $sftp->do_stat( 'upload.tmp' ) && print( "Overwriting upload.tmp\n" ); $sftp->put( $local_file, 'upload.tmp' ); $sftp->do_rename( 'upload.tmp', basename( $local_file )); }
為了相同的目的,我在數十台其他現場 PC 上使用此程式碼和非常相似的配置。這是我第一次看到這個問題。我正在尋找根本原因或診斷建議,而不是這個生態系統之外的解決方法。有無數種編寫腳本的方法,但我需要 Net::SFTP::Foreign 模組的粒度、回饋和模組化來進行日誌記錄和錯誤報告。Perl 是唯一可用的腳本語言。
謝謝。這令人難以置信的沮喪。
配置:
- Windows 7的
- ActivePerl 5.8.9
- Net::SFTP::國外 v1.69
- OpenSSH 5.3p1(來自 CopSSH 發行版的 Windows 客戶端)
- OpenVPN 2.2-rc(Windows 連接回企業網路)
- Tectia Server 6.2.1.168(Linux SSH 伺服器)
客戶端輸出 (-vvvv) 直到我在 ssh.exe 橫盤後手動終止它:
OpenSSH_5.3p1, OpenSSL 0.9.8k 25 Mar 2009 debug1: Reading configuration data /etc/ssh_config debug2: ssh_connect: needpriv 0 debug1: Connecting to sftp.server.com [xx.xx.xx.xx] port 22. debug1: Connection established. debug1: identity file /cygdrive/c/program files/copssh/.ssh/identity type -1 debug3: Not a RSA1 key file /cygdrive/c/program files/copssh/.ssh/id_rsa. debug2: key_type_from_name: unknown key type '-----BEGIN' debug3: key_read: missing keytype debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug3: key_read: missing whitespace debug2: key_type_from_name: unknown key type '-----END' debug3: key_read: missing keytype debug1: identity file /cygdrive/c/program files/copssh/.ssh/id_rsa type 1 debug1: identity file /cygdrive/c/program files/copssh/.ssh/id_dsa type -1 debug1: Remote protocol version 2.0, remote software version 6.2.1.168 SSH Tectia Server debug1: no match: 6.2.1.168 SSH Tectia Server debug1: Enabling compatibility mode for protocol 2.0 debug1: Local version string SSH-2.0-OpenSSH_5.3 debug2: fd 3 setting O_NONBLOCK debug1: SSH2_MSG_KEXINIT sent debug3: Wrote 792 bytes for a total of 813 debug1: SSH2_MSG_KEXINIT received debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie-hellman-g roup-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 debug2: kex_parse_kexinit: ssh-rsa,ssh-dss debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour12 8,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rij ndael-cbc@lysator.liu.se debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour12 8,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rij ndael-cbc@lysator.liu.se debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160 ,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96 debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160 ,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96 debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib debug2: kex_parse_kexinit: debug2: kex_parse_kexinit: debug2: kex_parse_kexinit: first_kex_follows 0 debug2: kex_parse_kexinit: reserved 0 debug2: kex_parse_kexinit: diffie-hellman-group1-sha1,diffie-hellman-group14-sha 1,diffie-hellman-group14-sha256@ssh.com,diffie-hellman-group-exchange-sha1,diffi e-hellman-group-exchange-sha256 debug2: kex_parse_kexinit: ssh-rsa,ssh-rsa-sha256@ssh.com debug2: kex_parse_kexinit: aes256-cbc,aes192-cbc,aes128-cbc,3des-cbc debug2: kex_parse_kexinit: aes256-cbc,aes192-cbc,aes128-cbc,3des-cbc debug2: kex_parse_kexinit: hmac-sha1 debug2: kex_parse_kexinit: hmac-sha1 debug2: kex_parse_kexinit: none,zlib debug2: kex_parse_kexinit: none,zlib debug2: kex_parse_kexinit: debug2: kex_parse_kexinit: debug2: kex_parse_kexinit: first_kex_follows 0 debug2: kex_parse_kexinit: reserved 0 debug2: mac_setup: found hmac-sha1 debug1: kex: server->client aes128-cbc hmac-sha1 none debug2: mac_setup: found hmac-sha1 debug1: kex: client->server aes128-cbc hmac-sha1 none debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<2048<8192) sent debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP debug3: Wrote 24 bytes for a total of 837 debug2: dh_gen_key: priv key bits set: 160/320 debug2: bits set: 1016/2048 debug1: SSH2_MSG_KEX_DH_GEX_INIT sent debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY debug3: Wrote 272 bytes for a total of 1109 debug3: check_host_in_hostfile: filename /cygdrive/c/program files/copssh/.ssh/known_hosts debug3: check_host_in_hostfile: match line 2 debug3: check_host_in_hostfile: filename /cygdrive/c/program files/copssh/.ssh/known_hosts debug3: check_host_in_hostfile: match line 1 debug1: Host 'sftp.server.com' is known and matches the RSA host key. debug1: Found key in /cygdrive/c/program files/copssh/.ssh/known_hosts:2 debug2: bits set: 995/2048 debug1: ssh_rsa_verify: signature correct debug2: kex_derive_keys debug2: set_newkeys: mode 1 debug1: SSH2_MSG_NEWKEYS sent debug1: expecting SSH2_MSG_NEWKEYS debug3: Wrote 16 bytes for a total of 1125 debug2: set_newkeys: mode 0 debug1: SSH2_MSG_NEWKEYS received debug1: SSH2_MSG_SERVICE_REQUEST sent debug3: Wrote 52 bytes for a total of 1177 debug3: Received SSH2_MSG_IGNORE debug3: Received SSH2_MSG_IGNORE debug2: service_accept: ssh-userauth debug1: SSH2_MSG_SERVICE_ACCEPT received debug2: key: /cygdrive/c/program files/copssh/.ssh/identity (0x0) debug2: key: /cygdrive/c/program files/copssh/.ssh/id_rsa (0xd4b720) debug2: key: /cygdrive/c/program files/copssh/.ssh/id_dsa (0x0) debug3: Wrote 84 bytes for a total of 1261 debug3: Received SSH2_MSG_IGNORE debug1: Authentications that can continue: publickey,keyboard-interactive debug3: start over, passed a different list publickey,keyboard-interactive debug3: preferred publickey debug3: authmethod_lookup publickey debug3: remaining preferred: debug3: authmethod_is_enabled publickey debug1: Next authentication method: publickey debug1: Trying private key: /cygdrive/c/program files/copssh/.ssh/identity debug3: no such identity: /cygdrive/c/program files/copssh/.ssh/identity debug1: Offering public key: /cygdrive/c/program files/copssh/.ssh/id_rsa debug3: send_pubkey_test debug2: we sent a publickey packet, wait for reply debug3: Wrote 372 bytes for a total of 1633 debug3: Received SSH2_MSG_IGNORE debug1: Server accepts key: pkalg ssh-rsa blen 277 debug2: input_userauth_pk_ok: fp (...) debug3: sign_and_send_pubkey debug1: read PEM private key done: type RSA debug3: Wrote 644 bytes for a total of 2277 debug3: Received SSH2_MSG_IGNORE debug1: Authentication succeeded (publickey). debug2: fd 4 setting O_NONBLOCK debug2: fd 5 setting O_NONBLOCK debug1: channel 0: new [client-session] debug3: ssh_session2_open: channel_new: 0 debug2: channel 0: send open debug1: Entering interactive session. debug3: Wrote 68 bytes for a total of 2345 debug3: Received SSH2_MSG_IGNORE debug2: callback start debug2: client_session2_setup: id 0 debug1: Sending subsystem: sftp debug2: channel 0: request subsystem confirm 1 debug2: fd 3 setting TCP_NODELAY debug2: callback done debug2: channel 0: open confirm rwindow 65536 rmax 32768 debug3: Wrote 68 bytes for a total of 2413 debug3: Wrote 52 bytes for a total of 2465 debug3: Received SSH2_MSG_IGNORE debug2: channel_input_status_confirm: type 99 id 0 debug2: subsystem request accepted on channel 0 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 68 bytes for a total of 2533 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 84 bytes for a total of 2617 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 68 bytes for a total of 2685 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 16436 bytes for a total of 19121 debug3: Wrote 4148 bytes for a total of 23269 debug3: Wrote 12372 bytes for a total of 35641 debug3: Wrote 16436 bytes for a total of 52077 debug3: Wrote 4148 bytes for a total of 56225 debug3: Wrote 12196 bytes for a total of 68421 debug3: Received SSH2_MSG_IGNORE debug2: channel 0: rcvd adjust 32899 debug3: Wrote 212 bytes for a total of 68633 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 16436 bytes for a total of 85069 debug3: Wrote 4148 bytes for a total of 89217 debug3: Received SSH2_MSG_IGNORE debug2: channel 0: rcvd adjust 98337 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 12372 bytes for a total of 101589 debug3: Wrote 16436 bytes for a total of 118025 debug3: Wrote 4148 bytes for a total of 122173 debug3: Wrote 12372 bytes for a total of 134545 debug3: Wrote 16436 bytes for a total of 150981 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 4148 bytes for a total of 155129 debug3: Wrote 12372 bytes for a total of 167501 debug3: Received SSH2_MSG_IGNORE debug2: channel 0: rcvd adjust 196674 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 16436 bytes for a total of 183937 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 4148 bytes for a total of 188085 debug3: Wrote 12372 bytes for a total of 200457 debug3: Wrote 16436 bytes for a total of 216893 debug3: Wrote 4148 bytes for a total of 221041 debug3: Wrote 12372 bytes for a total of 233413 debug3: Wrote 16436 bytes for a total of 249849 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 4148 bytes for a total of 253997 debug3: Wrote 12372 bytes for a total of 266369 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 16436 bytes for a total of 282805 debug3: Wrote 4148 bytes for a total of 286953 debug3: Wrote 12372 bytes for a total of 299325 debug3: Received SSH2_MSG_IGNORE debug2: channel 0: rcvd adjust 131204 debug3: Wrote 16436 bytes for a total of 315761 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 4148 bytes for a total of 319909 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 12372 bytes for a total of 332281 debug3: Wrote 16436 bytes for a total of 348717 debug3: Wrote 4148 bytes for a total of 352865 debug3: Wrote 12372 bytes for a total of 365237 debug3: Wrote 16436 bytes for a total of 381673 debug3: Wrote 4148 bytes for a total of 385821 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 12372 bytes for a total of 398193 debug3: Wrote 16436 bytes for a total of 414629 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 4148 bytes for a total of 418777 debug3: Wrote 12372 bytes for a total of 431149 debug3: Wrote 16436 bytes for a total of 447585 debug3: Received SSH2_MSG_IGNORE debug2: channel 0: rcvd adjust 393348 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 4148 bytes for a total of 451733 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 12372 bytes for a total of 464105 debug3: Wrote 16436 bytes for a total of 480541 debug3: Wrote 4148 bytes for a total of 484689 debug3: Wrote 12372 bytes for a total of 497061 debug3: Wrote 16436 bytes for a total of 513497 debug3: Wrote 4148 bytes for a total of 517645 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 12372 bytes for a total of 530017 debug3: Wrote 16436 bytes for a total of 546453 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 4148 bytes for a total of 550601 debug3: Wrote 12372 bytes for a total of 562973 debug3: Wrote 16436 bytes for a total of 579409 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 4148 bytes for a total of 583557 debug3: Wrote 12372 bytes for a total of 595929 debug3: Wrote 16436 bytes for a total of 612365 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 4148 bytes for a total of 616513 debug3: Wrote 12372 bytes for a total of 628885 debug3: Wrote 16436 bytes for a total of 645321 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 4148 bytes for a total of 649469 debug3: Wrote 12372 bytes for a total of 661841 debug3: Wrote 16436 bytes for a total of 678277 debug3: Wrote 4148 bytes for a total of 682425 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 12372 bytes for a total of 694797 debug3: Wrote 16436 bytes for a total of 711233 debug3: Received SSH2_MSG_IGNORE debug2: channel 0: rcvd adjust 738120 debug3: Received SSH2_MSG_IGNORE debug3: Wrote 4148 bytes for a total of 715381 debug3: Received SSH2_MSG_IGNORE
更新 1
根據@Daniel Lawson 的建議,我嘗試使用 netsh 將 VPN 介面的 MTU 限制為 1280,以避免在伺服器路徑上的 MTU 不匹配的情況下填充客戶端的 TCP 緩衝區。轉移仍然在大約同一點停滯不前。我還嘗試斷開 VPN 並將物理介面的 MTU 限制為 1280,但結果相同。
這對我來說就像一個 MTU 問題。當路徑 MTU 不匹配時,我已經看到與 scping 文件類似的問題。主機上的 TCP 緩衝區可能會填滿,這就是為什麼您發送多個數據包的原因,但是一旦它們填滿您的客戶端就會停止 - 在 MTU 問題本身實際產生影響之後很久。
要驗證這一點,您可以查看像scamper這樣的工具。或者您可以嘗試手動將您的 MTU 限製到某個較低的點(例如 1280 字節)並查看是否可以解決問題。很有可能只有輕微的不匹配,例如因為路徑中的 PPPoE 鏈路將 MTU 降低到 1492。
也許你可以玩這個
block_size
參數?我經歷了一些與通過 SSH/SSL 上傳文件相關的怪事,並且以某種方式調整塊/塊大小有所幫助。我相信預設值是32 * 1024
,所以也許將其降低到 16、8、4 並嘗試可能會有所不同。可能值得一試。