"SSHException: Error reading SSH protocol banner" when using ProxyCommand

[depado]

Hello,

It's been a few days and I'm still struggling with this, I think it's quite a known issue but wasn't able to find a workaround.

Paramiko 1.16.0
Python 3.5.1
Operating System : Archlinux

Below is a simplified version of my actual code that throws the same error :

import os
import paramiko

# Loading ssh configuration to get the IP and user of the desired host (here 'bastion')
cfg = paramiko.SSHConfig()
with open(os.path.expanduser("~/.ssh/config")) as f:
    cfg.parse(f)
host_cfg = cfg.lookup('bastion')
sock = paramiko.ProxyCommand("ssh -W %h:%p {}@{}".format(host_cfg.get('user', 'root'), host_cfg.get('hostname')))

# Client Setup
client = paramiko.SSHClient()
client.load_system_host_keys()
client.set_missing_host_key_policy(paramiko.AutoAddPolicy())

# Connect and execute command
client.connect("my.ip.ad.dr", username='root', sock=sock)
(stdin, stdout, stderr) = client.exec_command("echo 'Hello World !'")
for line in stdout.readlines():
    print(line)
client.close()

Note that the whole parsing the ssh config thing is simplified because I know this entry is in the ssh config. (And yes I'm sure the error doesn't come from that because the generated ProxyCommand is correct)

Of course it raises the error when executing the client.connect line. The ProxyCommand is correct, tested multiple times and works just fine in my ~/.ssh/config. When using it with the command line, it creates an entry in the logs of my bastion. When using it within paramiko it doesn't generate an entry in the logs.

I also tested using the netcat approach like this :

sock = paramiko.ProxyCommand("ssh {}@{} nc %h %p".format(host_cfg.get('user', 'root'), host_cfg.get('hostname')))

This time it generates an entry in the logs of my bastion (even though it still raises this error) but closes the connection immediatly.

Anyone having the same issue and could help me with that ?

[ktbyers]

@depado I am having a similar issue connecting to Cisco devices through a proxy. In other words using ProxyCommand and I am receiving "SSHException: Error reading SSH protocol banner".

Does it fix your problem if you do the following (to see if we are having the same issue):

In transport.py line 486 add a short delay (this is using paramiko 1.16.0)

        # delay starting thread for SSH proxies
        event.wait(0.2)                     # Added this delay
        self.start()

This fixes my issue.

[depado]

@ktbyers, I gave your solution a try but that doesn't seem to solve my problem. Thanks to pkapp on IRC I was able to debug a bit further what's going on.

I started by activating the debug logs but paramiko isn't very chatty about what it does under the hood unfortunately.

import logging
logging.basicConfig(level=logging.DEBUG)

These are the only things paramiko sends me back before throwing the traceback at me.

DEBUG:paramiko.transport:starting thread (client mode): 0xb4c74668
DEBUG:paramiko.transport:Local version/idstring: SSH-2.0-paramiko_1.16.0
ERROR:paramiko.transport:Exception: Error reading SSH protocol banner

I also learned that the %h %p won't be automatically used by paramiko when passing them as a string to a ProxyCommand. (Even though it does seem to be working on my system, that may be the problem) Also, the nc approach looks like it works better than the OpenSSH -W flag. So my actual ProxyCommand then looked like this :

cmd = "ssh {}@{} nc {} 22".format(host_cfg.get('user'), host_cfg.get('hostname'), destination_ip)
# cmd is now "ssh root@jump_ip nc dest_ip 22" where jump_ip and dest_ip are valid IPs
sock = ProxyCommand(cmd)

Still getting the same error though, so it didn't come from there. I added a time.sleep right after the call to ProxyCommand, checked my proxy's logs and the returned stdout and stderr from the subprocess like this :

sock = ProxyCommand(cmd)
print(sock.process.poll())
print(sock.process.stdout.read())
print(sock.process.stderr.read())

This code yells the following output :

None
b'SSH-2.0-OpenSSH_6.7p1 Debian-5+deb8u1\r\n'
b''

While the time.sleep or the reading of stdout/stderr is active, the connection on my proxy is kept open. (Of course I removed these before going any further because I'm not supposed to read directly from the process) What I don't understand is why that _check_banner function fails although the stdout of the socket is clearly beginning with SSH-...
On the other hand, as soon as the client.connect(...) is called, the connection is immediatly destroyed on my proxy. I now need a way to investigate why the connection fails this way.

For those who wants more information, here is the line in paramiko that causes that error : transport.py:1858

(Thanks again pkapp for all the help on IRC o/)

[radssh]

Able to reproduce under Python3 with a program that works find under Python2. Hacking around a bit with proxy.py to find out what the underlying issue really is. Will post findings if/when I can get some better details.

[ktbyers]

@radssh @depado I saw similar behavior. I could get @depado code to work under Python2.7 (with minor modifications to the proxy command), but saw 'Error reading SSH protocol banner' message when testing with Python3.4.

[depado]

Well we're getting to the bottom of this. Hope you can sort this out ! Thanks for all the help on IRC @radssh !

[radssh]

PR #681 submitted.

With Python3 switch to io.BufferedReader, the select call here doesn't indicate that buffered data is ready to be read - only if new data has arrived. Changing to unbuffered pipes wound up breaking under Python2, since the method's own buffering code was a bit wonky to begin with.

[depado]

Very nice ! Thanks a lot @radssh !

[kryptek]

I'm having an issue with the SSH banner as well. I'm using port forwarding in my ProxyCommand and paramiko doesn't seem to like it. Kills the connection with the same exception. The connection opens just fine and if I set the banner_timeout to a large value, I can connect to localhost:PORT and do whatever I need to do until the SSHException is raised.

Is there any hope for me?

[depado]

Hi @kryptek maybe you can try the fix provided by @radssh ? I didn't have the time to test it yet, but it looks like it fixed the problem I had which was caused by Python3.

[bitprophet]

We have a whole passle of other issues relating to this (common and often covering unrelated problems, YAY PROGRAMMING!) error, FTR. I don't have time right now to go dig them all up but if others want to do so & link them here, that'd be super appreciated. Would love to either merge some dusty PRs or otherwise have someone sleuth up a better way to surface these.

[depado]

@bitprophet, @radssh opened #681
Looks like it is related to a Python 3.x problem.

[akulakhan]

@radssh patch (manually inserted) fixed issue with ncclient wherein I am using proxycommand and was receiving paramiko.ssh_exception.SSHException: Error reading SSH protocol banner with logging debug level enabled & ncclient.transport.errors.SSHError: Negotiation failed