We follow -current on amd64, upgrading about once a month. Occasional WinSCP (5.7.1, 5.7.2) clients, which previously worked fine, appear to be unable to connect following recent upgrades to -current. We don't know exactly which snapshot this stopped working. FileZilla on Linux clients still work fine. /etc/ssh/sshd_config is stock.
On 5.7 GENERIC.MP#971 amd64 (May 2), this happens: $ sudo /usr/sbin/sshd -ddd debug2: load_server_config: filename /etc/ssh/sshd_config debug2: load_server_config: done config len = 245 debug2: parse_server_config: config /etc/ssh/sshd_config len 245 debug3: /etc/ssh/sshd_config:37 setting LogLevel DEBUG1 debug3: /etc/ssh/sshd_config:52 setting AuthorizedKeysFile .ssh/authorized_keys debug3: /etc/ssh/sshd_config:87 setting UsePrivilegeSeparation sandbox debug3: /etc/ssh/sshd_config:92 setting UseDNS no debug3: /etc/ssh/sshd_config:103 setting Subsystem sftp /usr/libexec/sftp-server debug1: sshd version OpenSSH_6.8, LibreSSL 2.1 debug1: private host key #0: ssh-rsa SHA256: debug1: private host key #1: ssh-dss SHA256: debug1: private host key #2: ecdsa-sha2-nistp256 SHA256: debug1: private host key #3: ssh-ed25519 SHA256: debug1: rexec_argv[0]='/usr/sbin/sshd' debug1: rexec_argv[1]='-ddd' debug2: fd 3 setting O_NONBLOCK debug1: Bind to port 22 on 0.0.0.0. Server listening on 0.0.0.0 port 22. debug2: fd 4 setting O_NONBLOCK debug1: Bind to port 22 on ::. Server listening on :: port 22. (WinSCP attempts connect here) debug1: fd 5 clearing O_NONBLOCK debug1: Server will not fork when running in debugging mode. debug3: send_rexec_state: entering fd = 8 config len 245 debug3: ssh_msg_send: type 0 debug3: send_rexec_state: done debug1: rexec start in 5 out 5 newsock 5 pipe -1 sock 8 debug1: inetd sockets after dupping: 3, 3 Connection from 192.168.0.7 port 49179 on 192.168.0.11 port 22 debug1: Client protocol version 2.0; client software version WinSCP_release_5.7.2 debug1: no match: WinSCP_release_5.7.2 debug1: Enabling compatibility mode for protocol 2.0 debug1: Local version string SSH-2.0-OpenSSH_6.8 debug2: fd 3 setting O_NONBLOCK debug3: ssh_sandbox_init: preparing systrace sandbox debug2: Network child is on pid 9854 debug3: ssh_sandbox_parent: wait for child 9854 debug3: ssh_sandbox_parent: child 9854 stopped debug3: ssh_sandbox_parent: systrace attach, fd=9 debug3: ssh_sandbox_parent: policy: enable syscall 1 debug3: ssh_sandbox_parent: policy: enable syscall 3 debug3: ssh_sandbox_parent: policy: enable syscall 4 debug3: ssh_sandbox_parent: policy: enable syscall 5 debug3: ssh_sandbox_parent: policy: enable syscall 6 debug3: ssh_sandbox_parent: policy: enable syscall 7 debug3: ssh_sandbox_parent: policy: enable syscall 20 debug3: ssh_sandbox_parent: policy: enable syscall 48 debug3: ssh_sandbox_parent: policy: enable syscall 67 debug3: ssh_sandbox_parent: policy: enable syscall 71 debug3: ssh_sandbox_parent: policy: enable syscall 73 debug3: ssh_sandbox_parent: policy: enable syscall 74 debug3: ssh_sandbox_parent: policy: enable syscall 75 debug3: ssh_sandbox_parent: policy: enable syscall 83 debug3: ssh_sandbox_parent: policy: enable syscall 87 debug3: ssh_sandbox_parent: policy: enable syscall 134 debug3: ssh_sandbox_parent: policy: enable syscall 197 debug3: ssh_sandbox_parent: policy: enable syscall 252 debug3: ssh_sandbox_parent: policy: enable syscall 286 debug3: ssh_sandbox_parent: start child 9854 debug3: preauth child monitor started debug3: privsep user:group 27:27 [preauth] debug1: permanently_set_uid: 27/27 [preauth] debug3: ssh_sandbox_child: ready [preauth] debug3: ssh_sandbox_child: started [preauth] debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth] debug1: SSH2_MSG_KEXINIT sent [preauth] debug1: SSH2_MSG_KEXINIT received [preauth] debug2: kex_parse_kexinit: curve25519-sha...@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1 [preauth] debug2: kex_parse_kexinit: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ssh-ed25519 [preauth] debug2: kex_parse_kexinit: chacha20-poly1...@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-...@openssh.com,aes256-...@openssh.com [preauth] debug2: kex_parse_kexinit: chacha20-poly1...@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-...@openssh.com,aes256-...@openssh.com [preauth] debug2: kex_parse_kexinit: umac-64-...@openssh.com,umac-128-...@openssh.com,hmac-sha2-256-...@openssh.com,hmac-sha2-512-...@openssh.com,hmac-sha1-...@openssh.com,umac...@openssh.com,umac-...@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] debug2: kex_parse_kexinit: umac-64-...@openssh.com,umac-128-...@openssh.com,hmac-sha2-256-...@openssh.com,hmac-sha2-512-...@openssh.com,hmac-sha1-...@openssh.com,umac...@openssh.com,umac-...@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] debug2: kex_parse_kexinit: none,z...@openssh.com [preauth] debug2: kex_parse_kexinit: none,z...@openssh.com [preauth] debug2: kex_parse_kexinit: [preauth] debug2: kex_parse_kexinit: [preauth] debug2: kex_parse_kexinit: first_kex_follows 0 [preauth] debug2: kex_parse_kexinit: reserved 0 [preauth] debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,rsa2048-sha256,rsa1024-sha1 [preauth] debug2: kex_parse_kexinit: ssh-rsa,ssh-dss [preauth] debug2: kex_parse_kexinit: aes256-ctr,aes256-cbc,rijndael-...@lysator.liu.se,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,arcfour128 [preauth] debug2: kex_parse_kexinit: aes256-ctr,aes256-cbc,rijndael-...@lysator.liu.se,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,blowfish-ctr,blowfish-cbc,3des-ctr,3des-cbc,arcfour256,arcfour128 [preauth] debug2: kex_parse_kexinit: hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5 [preauth] debug2: kex_parse_kexinit: hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5 [preauth] debug2: kex_parse_kexinit: zlib,none [preauth] debug2: kex_parse_kexinit: zlib,none [preauth] debug2: kex_parse_kexinit: [preauth] debug2: kex_parse_kexinit: [preauth] debug2: kex_parse_kexinit: first_kex_follows 0 [preauth] debug2: kex_parse_kexinit: reserved 0 [preauth] debug1: kex: client->server aes256-ctr hmac-sha2-256 none [preauth] debug1: kex: server->client aes256-ctr hmac-sha2-256 none [preauth] debug1: expecting SSH2_MSG_KEX_DH_GEX_REQUEST [preauth] Hm, kex protocol error: type 30 seq 1 [preauth] (delay here) Connection closed by 192.168.0.7 [preauth] debug1: do_cleanup [preauth] debug1: monitor_read_log: child log fd closed debug3: mm_request_receive entering debug1: do_cleanup debug1: Killing privsep child 9854 $ WinSCP logs this: . 2015-05-04 04:35:59.738 -------------------------------------------------------------------------- . 2015-05-04 04:35:59.738 WinSCP Version 5.7.2 (Build 5316) (OS 6.1.7601 Service Pack 1 - Windows 7 Home Premium) . 2015-05-04 04:35:59.738 Configuration: HKCU\Software\Martin Prikryl\WinSCP 2\ . 2015-05-04 04:35:59.738 Log level: Debug 2, Logging passwords . 2015-05-04 04:35:59.738 Local account: user-PC\user . 2015-05-04 04:35:59.738 Working directory: C:\Program Files (x86)\WinSCP . 2015-05-04 04:35:59.738 Process ID: 2964 . 2015-05-04 04:35:59.738 Command-line: "C:\Program Files (x86)\WinSCP\WinSCP.exe" . 2015-05-04 04:35:59.738 Time zone: Current: GMT-7, Standard: GMT-8 (Pacific Standard Time), DST: GMT-7 (Pacific Daylight Time), DST Start: 3/8/2015, DST End: 11/1/2015 . 2015-05-04 04:35:59.738 Login time: Monday, May 04, 2015 4:35:59 AM . 2015-05-04 04:35:59.738 -------------------------------------------------------------------------- . 2015-05-04 04:35:59.738 Session name: user@192.168.0.11 (Site) . 2015-05-04 04:35:59.738 Host name: 192.168.0.11 (Port: 22) . 2015-05-04 04:35:59.738 User name: user (Password: No, Key file: No) . 2015-05-04 04:35:59.738 Tunnel: No . 2015-05-04 04:35:59.738 Transfer Protocol: SFTP (SCP) . 2015-05-04 04:35:59.738 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec . 2015-05-04 04:35:59.738 Disable Nagle: No . 2015-05-04 04:35:59.738 Proxy: none . 2015-05-04 04:35:59.738 Send buffer: 0 . 2015-05-04 04:35:59.738 SSH protocol version: 2; Compression: Yes . 2015-05-04 04:35:59.738 Bypass authentication: No . 2015-05-04 04:35:59.738 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No . 2015-05-04 04:35:59.738 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No . 2015-05-04 04:35:59.738 KEX: dh-gex-sha1,dh-group14-sha1,dh-group1-sha1,rsa,WARN . 2015-05-04 04:35:59.738 SSH Bugs: A,A,A,A,A,A,A,A,A,A,A . 2015-05-04 04:35:59.738 Simple channel: No . 2015-05-04 04:35:59.738 Return code variable: Autodetect; Lookup user groups: A . 2015-05-04 04:35:59.738 Shell: default . 2015-05-04 04:35:59.738 EOL: 0, UTF: 2 . 2015-05-04 04:35:59.738 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes . 2015-05-04 04:35:59.738 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No . 2015-05-04 04:35:59.738 SFTP Bugs: A,A . 2015-05-04 04:35:59.738 SFTP Server: default . 2015-05-04 04:35:59.738 Local directory: C:\, Remote directory: /, Update: Yes, Cache: Yes . 2015-05-04 04:35:59.738 Cache directory changes: Yes, Permanent: Yes . 2015-05-04 04:35:59.738 DST mode: 1 . 2015-05-04 04:35:59.738 -------------------------------------------------------------------------- . 2015-05-04 04:35:59.816 Looking up host "192.168.0.11" . 2015-05-04 04:35:59.816 Connecting to 192.168.0.11 port 22 . 2015-05-04 04:35:59.816 Selecting events 63 for socket 1700 . 2015-05-04 04:35:59.878 Waiting for the server to continue with the initialization . 2015-05-04 04:35:59.878 Looking for incoming data . 2015-05-04 04:35:59.878 Looking for network events . 2015-05-04 04:35:59.878 Detected network event . 2015-05-04 04:35:59.878 Enumerating network events for socket 1700 . 2015-05-04 04:35:59.878 Enumerated 19 network events making 19 cumulative events for socket 1700 . 2015-05-04 04:35:59.878 Handling network read event on socket 1700 with error 0 . 2015-05-04 04:35:59.878 Server version: SSH-2.0-OpenSSH_6.8 . 2015-05-04 04:35:59.878 Using SSH protocol version 2 . 2015-05-04 04:35:59.878 We claim version: SSH-2.0-WinSCP_release_5.7.2 . 2015-05-04 04:35:59.878 Handling network write event on socket 1700 with error 0 . 2015-05-04 04:35:59.878 Handling network connect event on socket 1700 with error 0 . 2015-05-04 04:35:59.878 Waiting for the server to continue with the initialization . 2015-05-04 04:35:59.878 Looking for incoming data . 2015-05-04 04:35:59.878 Looking for network events . 2015-05-04 04:35:59.878 Detected network event . 2015-05-04 04:35:59.878 Enumerating network events for socket 1700 . 2015-05-04 04:35:59.878 Enumerated 1 network events making 1 cumulative events for socket 1700 . 2015-05-04 04:35:59.878 Handling network read event on socket 1700 with error 0 . 2015-05-04 04:35:59.878 Server supports delayed compression; will try this later . 2015-05-04 04:35:59.878 Doing Diffie-Hellman group exchange . 2015-05-04 04:35:59.878 Waiting for the server to continue with the initialization . 2015-05-04 04:35:59.878 Looking for incoming data . 2015-05-04 04:35:59.878 Looking for network events (delay here) . 2015-05-04 04:36:15.088 Timeout waiting for network events . 2015-05-04 04:36:15.088 Waiting for data timed out, asking user what to do. . 2015-05-04 04:36:15.088 Asking user: . 2015-05-04 04:36:15.088 **Host is not communicating for 15 seconds. . 2015-05-04 04:36:15.088 . 2015-05-04 04:36:15.088 Wait for another 15 seconds?** () . 2015-05-04 04:36:15.618 Pooling for data in case they finally arrives . 2015-05-04 04:36:15.618 Looking for network events . 2015-05-04 04:36:15.618 Timeout waiting for network events . 2015-05-04 04:36:16.133 Pooling for data in case they finally arrives . 2015-05-04 04:36:16.133 Looking for network events . 2015-05-04 04:36:16.133 Timeout waiting for network events . 2015-05-04 04:36:16.648 Pooling for data in case they finally arrives . 2015-05-04 04:36:16.648 Looking for network events . 2015-05-04 04:36:16.648 Timeout waiting for network events . 2015-05-04 04:36:16.664 Attempt to close connection due to fatal exception: * 2015-05-04 04:36:16.664 **Terminated by user.** . 2015-05-04 04:36:16.664 Closing connection. . 2015-05-04 04:36:16.664 Sending special code: 12 . 2015-05-04 04:36:16.664 Selecting events 0 for socket 1700 * 2015-05-04 04:36:16.726 (EFatal) **Terminated by user.** What did we break and how can we fix it?
