Page MenuHomePhabricator
Create Task
Maniphest T130

BUG?: sftp via socks5 with PROXYCOMMAND bails with read_packet(): Packet len too high (1818845806 6c69626e)
Closed, ResolvedPublic
Actions

Description

Hi, i'm having PROXYCOMMAND issues.

I'm trying to connect from our rhel7 servers to external sftp servers via our socks5 server.

-the rhel7 sftp cli +ncat works ( sftp -vvv -o ProxyCommand='ncat -vvv --proxy <proxy server:port> --proxy-type socks5 %h %p' -o'User <user>' -P 22 <external site> )
but the libssh connection don't.

Attatching failing communication capture:

traffic.pcap17 KBDownload

Libssh bails with "read_packet(): Packet len too high (1818845006 6c69626e)" after ss_send_kex: SSH_MSG_KEXINIT sent

(6c69626e is "libn" in ascii)

I've tested last stable libssh and the latest master (27/1), forcing KEX algo and C_S S_C chipers etc. to no avail. Still the same packet response from 2 diffrent external sftp servers. I'm on statically linked OpenSSL_1_1_0-stable (latest commit) and have further tested with openssl 1.1.1 & boringssl with the same result

Our socks5 proxy don't do any ssh interception

libssh "indirect" connections via a external socks5 bridge / virtual NIC & statically linked borinssl works from my windows7 workstation though.

I guess this is an issue with the openssl implementation since it works for the workstation / boringssl implementation or Is there any issue with the PROXYCOMMAND implementation ?

Thanks

/Niclas

Details

Commits
rLIBSSHc6c7856b5163: socket: Do not process stderr of proxy commands (Fixes T130)
rLIBSSH6c49c41c1915: socket: Do not process stderr of proxy commands (Fixes T130)

Related Objects

Event Timeline

Niclas created this task.Jan 24 2019, 11:39 AM
Niclas updated the task description. (Show Details)Jan 24 2019, 11:58 AM
Niclas updated the task description. (Show Details)
Niclas updated the task description. (Show Details)
Niclas updated the task description. (Show Details)Jan 24 2019, 12:01 PM
Niclas updated the task description. (Show Details)Jan 24 2019, 12:12 PM
Niclas renamed this task from BUG?: sftp via socks5 with PROXYCOMMAND bails with read_packet(): Packet len too high (1818845006 6c69626e) to BUG?: sftp via socks5 with PROXYCOMMAND bails with read_packet(): Packet len too high (1818845806 6c69626e).Jan 24 2019, 12:37 PM
Niclas updated the task description. (Show Details)Jan 24 2019, 12:39 PM
Niclas updated the task description. (Show Details)Jan 24 2019, 3:49 PM
Niclas updated the task description. (Show Details)Jan 24 2019, 4:45 PM
Niclas updated the task description. (Show Details)Jan 28 2019, 2:12 PM
asn added a project: Restricted Project.Feb 7 2019, 2:52 PM
asn added a subscriber: asn.

Can you enable full logging and provide a log?

Niclas added a comment.Feb 21 2019, 4:13 PM
This comment was removed by Niclas.
Niclas added a comment.Feb 21 2019, 4:13 PM
This comment was removed by Niclas.
Niclas added a comment.EditedFeb 21 2019, 4:17 PM

[2019/02/21 16:35:31.184417, 2] ssh_connect: libssh 0.8.90 (c) 2003-2019 Aris Adamantiadis, Andreas Schneider and libssh contributors. Distributed under the LGPL, please refer to COPYING file for information about your rights, using threading threads_pthread
[2019/02/21 16:35:31.184544, 2] ssh_socket_connect_proxycommand: Executing proxycommand 'ncat -vvv -C --proxy <proxy server address>:<proxy server port> --proxy-type socks5 <server address> 22'
[2019/02/21 16:35:31.184773, 2] ssh_socket_connect_proxycommand: ProxyCommand connection pipe: [4,7]
[2019/02/21 16:35:31.184898, 1] socket_callback_connected: Socket connection callback: 1 (0)
[2019/02/21 16:35:31.184996, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[2019/02/21 16:35:31.185080, 2] ssh_connect: Socket connecting, now waiting for the callbacks to work
[2019/02/21 16:35:31.185159, 3] ssh_connect: Actual timeout : 10000
[2019/02/21 16:35:31.185256, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLOUT ), out buffer 0
[2019/02/21 16:35:31.187685, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.187831, 3] callback_receive_banner: ssh_protocol_version_exchange: Ncat: Version 7.70 ( https://nmap.org/ncat )
[2019/02/21 16:35:31.204436, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.204598, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.204748, 3] callback_receive_banner: ssh_protocol_version_exchange: NCAT DEBUG: Using system default trusted CA certificates and those in /usr/share/ncat/ca-bundle.crt.
[2019/02/21 16:35:31.212543, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.212627, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.212665, 3] callback_receive_banner: ssh_protocol_version_exchange: Ncat: Connected to proxy 10.158.167.118:1080
[2019/02/21 16:35:31.213973, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.214044, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.214061, 3] callback_receive_banner: ssh_protocol_version_exchange: Ncat: No authentication needed.
[2019/02/21 16:35:31.328489, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.328627, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.328646, 3] callback_receive_banner: ssh_protocol_version_exchange: Ncat: connection succeeded.
[2019/02/21 16:35:31.328765, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.328784, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_iod_new2(): nsock_iod_new (IOD #1)
[2019/02/21 16:35:31.328851, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.328867, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_iod_new2(): nsock_iod_new (IOD #2)
[2019/02/21 16:35:31.328923, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.328939, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_read(): Read request from IOD #1 [peer unspecified] (timeout: -1ms) EID 10
[2019/02/21 16:35:31.328994, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.329009, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_readbytes(): Read request for 0 bytes from IOD #2 [peer unspecified] EID 18
[2019/02/21 16:35:31.329083, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.329099, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_trace_handler_callback(): Callback: READ SUCCESS for EID 18 [peer unspecified] (23 bytes): SSH-2.0-libssh_0.8.90..
[2019/02/21 16:35:31.329152, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.329167, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_write(): Write request for 23 bytes to IOD #1 EID 27 [peer unspecified]
[2019/02/21 16:35:31.329238, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.329255, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_trace_handler_callback(): Callback: WRITE SUCCESS for EID 27 [peer unspecified]
[2019/02/21 16:35:31.329309, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.329323, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_readbytes(): Read request for 0 bytes from IOD #2 [peer unspecified] EID 34
[2019/02/21 16:35:31.380097, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.380150, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_trace_handler_callback(): Callback: READ SUCCESS for EID 10 [peer unspecified] (36 bytes): SSH-2.0-1.82_sshlib <server name>..
[2019/02/21 16:35:31.380259, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:35:31.380278, 3] callback_receive_banner: Received banner: SSH-2.0-1.82_sshlib <server name>
[2019/02/21 16:35:31.380287, 1] ssh_client_connection_callback: SSH server banner: SSH-2.0-1.82_sshlib <server name>
[2019/02/21 16:35:31.380296, 1] ssh_analyze_banner: Analyzing banner: SSH-2.0-1.82_sshlib <server name>
[2019/02/21 16:35:31.385699, 1] ssh_known_hosts_read_entries: Failed to open the known_hosts file '/etc/ssh/ssh_known_hosts': No such file or directory
session cookie: 56:ff:ca:c3:2b:30:b7:bb:fb:18:88:cb:6d:0f:8c:eb
[2019/02/21 16:35:31.385750, 4] ssh_list_kex: kex algos: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group18-sha512,diffie-hellman-group16-sha512,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,ext-info-c
[2019/02/21 16:35:31.385762, 4] ssh_list_kex: server host key algo: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-rsa,rsa-sha2-512,rsa-sha2-256,ssh-dss
[2019/02/21 16:35:31.385771, 4] ssh_list_kex: encryption client->server: aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-cbc
[2019/02/21 16:35:31.385780, 4] ssh_list_kex: encryption server->client: aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-cbc
[2019/02/21 16:35:31.385789, 4] ssh_list_kex: mac algo client->server: hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2019/02/21 16:35:31.385798, 4] ssh_list_kex: mac algo server->client: hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2019/02/21 16:35:31.385807, 4] ssh_list_kex: compression algo client->server: none
[2019/02/21 16:35:31.385815, 4] ssh_list_kex: compression algo server->client: none
[2019/02/21 16:35:31.385824, 4] ssh_list_kex: languages client->server:
[2019/02/21 16:35:31.385833, 4] ssh_list_kex: languages server->client:
[2019/02/21 16:35:31.385859, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[2019/02/21 16:35:31.385873, 3] packet_send2: packet: wrote [type=20, len=644, padding_size=9, comp=634, payload=634]
[2019/02/21 16:35:31.385883, 3] ssh_send_kex: SSH_MSG_KEXINIT sent
[2019/02/21 16:35:31.385892, 3] ssh_packet_socket_callback: rcv packet cb (len=0, state=INIT)
[2019/02/21 16:35:31.385901, 3] ssh_packet_socket_callback: Waiting for more data (0 < 8)
[2019/02/21 16:35:31.385913, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN POLLOUT ), out buffer 0
[2019/02/21 16:35:31.385928, 3] ssh_packet_socket_callback: rcv packet cb (len=912, state=INIT)
[2019/02/21 16:35:31.385939, 1] ssh_packet_socket_callback: read_packet(): Packet len too high(1818845806 6c69626e)
[2019/02/21 16:35:31.385948, 3] ssh_packet_socket_callback: Packet: processed 8 bytes
[2019/02/21 16:35:31.385957, 3] ssh_packet_socket_callback: Packet: processed 0 bytes
[2019/02/21 16:35:31.385966, 4] ssh_socket_pollcallback: sending control flow event
[2019/02/21 16:35:31.385976, 4] ssh_packet_socket_controlflow_callback: sending channel_write_wontblock callback
[2019/02/21 16:35:31.385988, 3] ssh_connect: current state : 9
Encountered unhandled exeption: An error occured connecting to <server name> reason: read_packet(): Packet len too high(1818845806 6c69626e)

Niclas added a comment.Feb 21 2019, 4:43 PM

with another endpoint;

[2019/02/21 16:40:54.875040, 2] ssh_connect: libssh 0.8.90 (c) 2003-2019 Aris Adamantiadis, Andreas Schneider and libssh contributors. Distributed under the LGPL, please refer to COPYING file for information about your rights, using threading threads_pthread
[2019/02/21 16:40:54.875161, 2] ssh_socket_connect_proxycommand: Executing proxycommand 'ncat -vvv -C --proxy <proxy server address>:<proxy port> --proxy-type socks5 <server address> 22'
[2019/02/21 16:40:54.875368, 2] ssh_socket_connect_proxycommand: ProxyCommand connection pipe: [4,7]
[2019/02/21 16:40:54.875487, 1] socket_callback_connected: Socket connection callback: 1 (0)
[2019/02/21 16:40:54.875598, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[2019/02/21 16:40:54.875699, 2] ssh_connect: Socket connecting, now waiting for the callbacks to work
[2019/02/21 16:40:54.875780, 3] ssh_connect: Actual timeout : 10000
[2019/02/21 16:40:54.875871, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLOUT ), out buffer 0
[2019/02/21 16:40:54.877619, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:40:54.877730, 3] callback_receive_banner: ssh_protocol_version_exchange: Ncat: Version 7.70 ( https://nmap.org/ncat )
[2019/02/21 16:40:54.894451, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:40:54.894593, 3] callback_receive_banner: ssh_protocol_version_exchange: NCAT DEBUG: Using system default trusted CA certificates and those in /usr/share/ncat/ca-bundle.crt.
[2019/02/21 16:40:54.902290, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:40:54.902491, 3] callback_receive_banner: ssh_protocol_version_exchange: Ncat: Connected to proxy <proxy address>:<proxy port>
[2019/02/21 16:40:54.903670, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:40:54.903703, 3] callback_receive_banner: ssh_protocol_version_exchange: Ncat: No authentication needed.
[2019/02/21 16:40:54.920129, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:40:54.920205, 3] callback_receive_banner: ssh_protocol_version_exchange: Ncat: connection succeeded.
[2019/02/21 16:40:54.920251, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_iod_new2(): nsock_iod_new (IOD #1)
[2019/02/21 16:40:54.920290, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_iod_new2(): nsock_iod_new (IOD #2)
[2019/02/21 16:40:54.920496, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:40:54.920527, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_read(): Read request from IOD #1 [peer unspecified] (timeout: -1ms) EID 10
[2019/02/21 16:40:54.920546, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_readbytes(): Read request for 0 bytes from IOD #2 [peer unspecified] EID 18
[2019/02/21 16:40:54.920625, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:40:54.920663, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_trace_handler_callback(): Callback: READ SUCCESS for EID 18 [peer unspecified] (23 bytes): SSH-2.0-libssh_0.8.90..
[2019/02/21 16:40:54.920684, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_write(): Write request for 23 bytes to IOD #1 EID 27 [peer unspecified]
[2019/02/21 16:40:54.920757, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:40:54.920786, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_trace_handler_callback(): Callback: WRITE SUCCESS for EID 27 [peer unspecified]
[2019/02/21 16:40:54.920801, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_readbytes(): Read request for 0 bytes from IOD #2 [peer unspecified] EID 34
[2019/02/21 16:40:54.932541, 4] ssh_socket_pollcallback: Poll callback on socket 7 (POLLIN ), out buffer 0
[2019/02/21 16:40:54.932576, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_trace_handler_callback(): Callback: READ SUCCESS for EID 10 [peer unspecified] (33 bytes): SSH-2.0-1.36_sshlib GlobalSCAPE..
[2019/02/21 16:40:54.932593, 3] callback_receive_banner: Received banner: SSH-2.0-1.36_sshlib GlobalSCAPE
[2019/02/21 16:40:54.932607, 1] ssh_client_connection_callback: SSH server banner: SSH-2.0-1.36_sshlib GlobalSCAPE
[2019/02/21 16:40:54.932620, 1] ssh_analyze_banner: Analyzing banner: SSH-2.0-1.36_sshlib GlobalSCAPE
Importing a 8 bits, 1 bytes object ...
Importing a 2056 bits, 257 bytes object ...
e: 11
n: 00:ad:3e:84:dc:a1:3e:51:84:17:da:7a:9f:f9:01:6b:4f:7c:38:b2:17:fc:89:61:3b:cd:d6:55:70:71:19:5c:52:06:5f:02:1a:64:02:09:d6:cd:dc:88:2e:80:3d:c4:4e:83:51:cb:b4:91:89:7c:dd:8c:1a:15:c9:ff:04:54:88:fe:ed:6f:16:5c:6d:83:eb:8b:5a:e4:ca:21:a9:85:2b:7c:54:3b:18:48:00:ec:b8:21:c9:ad:83:f4:2e:8a:d1:29:1e:a9:06:02:56:c9:ea:b2:3f:b6:d6:8d:8c:a2:97:97:5e:e5:5b:11:58:7c:b4:9a:c3:47:41:32:f6:b6:cf:b5:75:40:bb:d6:b1:c0:49:8d:51:60:3f:4d:8a:6c:03:07:f0:e2:d4:3d:bf:91:9c:22:1a:a6:ab:aa:16:11:a4:99:06:f7:f3:50:a9:c1:15:b1:84:fc:5d:25:dd:bd:da:6a:e6:60:28:de:48:ff:f4:96:10:42:bf:61:4b:25:d9:1a:44:db:b3:9f:3d:10:bc:98:af:0a:8e:1e:c6:07:b2:01:86:c5:16:8b:1c:e2:69:b7:99:6b:fa:57:e3:43:e6:30:8d:6f:29:f7:4c:f4:65:36:af:d0:4f:4a:8f:71:92:9f:39:e3:3d:47:05:ab:95:80:e8:28:07:54:83:f7:41
[2019/02/21 16:40:54.932997, 1] ssh_known_hosts_read_entries: Failed to open the known_hosts file '/etc/ssh/ssh_known_hosts': No such file or directory
[2019/02/21 16:40:54.933058, 3] ssh_client_select_hostkeys: Changing host key method to "rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,ssh-dss"
session cookie: 4d:fe:5a:55:b3:9b:8e:5a:c0:f9:86:87:66:ce:d1:c5
[2019/02/21 16:40:54.933158, 4] ssh_list_kex: kex algos: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group18-sha512,diffie-hellman-group16-sha512,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,ext-info-c
[2019/02/21 16:40:54.933178, 4] ssh_list_kex: server host key algo: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-ed25519,ecdsa-sha2-nistp521,ecdsa-sha2-nistp384,ecdsa-sha2-nistp256,ssh-dss
[2019/02/21 16:40:54.933194, 4] ssh_list_kex: encryption client->server: aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-cbc
[2019/02/21 16:40:54.933209, 4] ssh_list_kex: encryption server->client: aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-cbc
[2019/02/21 16:40:54.933223, 4] ssh_list_kex: mac algo client->server: hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2019/02/21 16:40:54.933237, 4] ssh_list_kex: mac algo server->client: hmac-sha2-256,hmac-sha2-512,hmac-sha1
[2019/02/21 16:40:54.933253, 4] ssh_list_kex: compression algo client->server: none
[2019/02/21 16:40:54.933267, 4] ssh_list_kex: compression algo server->client: none
[2019/02/21 16:40:54.933280, 4] ssh_list_kex: languages client->server:
[2019/02/21 16:40:54.933294, 4] ssh_list_kex: languages server->client:
[2019/02/21 16:40:54.933325, 3] ssh_socket_unbuffered_write: Enabling POLLOUT for socket
[2019/02/21 16:40:54.933411, 3] packet_send2: packet: wrote [type=20, len=644, padding_size=9, comp=634, payload=634]
[2019/02/21 16:40:54.933430, 3] ssh_send_kex: SSH_MSG_KEXINIT sent
[2019/02/21 16:40:54.933445, 3] ssh_packet_socket_callback: rcv packet cb (len=91, state=INIT)
[2019/02/21 16:40:54.933461, 1] ssh_packet_socket_callback: read_packet(): Packet len too high(1818845806 6c69626e)
[2019/02/21 16:40:54.933476, 3] ssh_packet_socket_callback: Packet: processed 8 bytes
[2019/02/21 16:40:54.933498, 3] ssh_packet_socket_callback: Packet: processed 0 bytes
[2019/02/21 16:40:54.933521, 3] ssh_connect: current state : 9
Encountered unhandled exeption: An error occured connecting to <server address> reason: read_packet(): Packet len too high(1818845806 6c69626e)

Niclas added a comment.Apr 4 2019, 3:26 PM

still the same issue & trace using 33ad6bc54e9246e57b1bdd32e7f7a869d07b7ace & openssl 1.1.1

Jakuje added a subscriber: Jakuje.Jun 19 2019, 2:00 PM

Do you have a minimal reproducer that demonstrates this issue? The following parts do not look correct:

[2019/02/21 16:35:31.187831, 3] callback_receive_banner: ssh_protocol_version_exchange: Ncat: Version 7.70 ( https://nmap.org/ncat )

a bit later is what should be coming -- the SSH identification banner:

[2019/02/21 16:40:54.932576, 3] callback_receive_banner: ssh_protocol_version_exchange: libnsock nsock_trace_handler_callback(): Callback: READ SUCCESS for EID 10 [peer unspecified] (33 bytes): SSH-2.0-1.36_sshlib GlobalSCAPE..`

I am afraid that the ncat dumps some additional data to stderr, which is unintentionally picked up by the libssh. This is caused by the code in the src/socket.c:815, where both stdout and stderr is redirected to libssh

dup2(out,1);
dup2(out,2);

You ca try to drop the second line above, which should let the stderr to be mixed up with the libssh stderr or dropped (not sure from top of my head), but it should let you move on.

I will try to experiment with that a bit more.

Jakuje added a comment.Jun 19 2019, 2:31 PM

Please, check the following commits in the master-fix branch:

https://gitlab.com/jjelen/libssh-mirror/commits/master-fix

According to my testing, this should resolve your issue. Can you rebuild libssh with these patches and verify that it solves your problem?

Jakuje added a comment.Jun 19 2019, 3:23 PM

FYI, as a workaround, you can use ProxyCommand='ncat -vvv --proxy <proxy server:port> --proxy-type socks5 %h %p' -o'User <user> 2>/dev/null', which drops the stderr. But indeed, this is something to fix in libssh.

Niclas added a comment.Jun 25 2019, 5:40 PM

Thank you! I confirm that 6c49c41c19157cbafb8f4b90276b83550da98da9 solves the issue.