SSH agent forwarding error

[jravetch]

I enabled ssh agent forwarding with fab 1.4 with env.forward_agent = 'True' and all seems fine, except I receive an odd error during code shipment:

out: Authentication response too long: 3577407571
out: fatal: The remote end hung up unexpectedly

Fab does properly forward the agent when pulling code from github, so not sure what's going on.

Before fab 1.4, I used this function to get around the key forwarding issue:

def sshagent_run(cmd):
local('ssh -A %s@%s "%s"' % (env.user, env.host, cmd))

Any idea what's going on?

[bitprophet]

Not sure what you mean by "code shipment" exactly. Can you please provide links to a Gist of your fabfile & the full output of when you run it and get this error? Might help. Haven't seen this error before myself but the feature is brand new and has only been tested in a few situations.

[jravetch]

Thanks for looking into this. When I say "code shipment", I mean pulling a repo, archiving the previous release, and creating a new directory with new code. Please refer to my fabfile and shipper library here: https://gist.github.com/1849832.

The full output from one of the servers is as follows (I put xxx for the server name and module for privacy sake):

[xxx] out: Loading staging settings ...
[xxx] out: Switching assets hash for xxx (release: milestone_latest-20120217.01) to 2ae3e41
[xxx] out: done!
[xxx] out: Shipped. Deploy when ready.
[xxx] out: Loading staging settings ...
[xxx] out: Shipping env: staging, module: xxx, branch: milestone_latest
[xxx] out: Switching from branch master to milestone_latest
[xxx] out: Switched to branch 'milestone_latest'
[xxx] out: Authentication response too long: 3577407571
[xxx] out: fatal: The remote end hung up unexpectedly

[bitprophet]

Sorry, I meant literally all the output from the fab task, not just the lines displaying the remote server's stdout :) If you're explicitly hiding the rest with eg hide(), I'd recommend removing those temporarily, and in fact using show('debug') or fab --show=debug.

I can say that the error there appears to be not from Fabric itself but from whatever is being invoked remotely, but without more info (see above) I can't tell which run/sudo call actually generated that :)

[osi]

I've seen this as well. I have a git checkout on a remote server, and if I do 'git submodule update' and there are multiple sub-modules to update, the 2nd one always fails.

[gosusnp]

I have a similar issues using mercurial:

• when I clone a repository which has multiple subrepos, the first one passes the second hangs,
• when I use a buildout which has multiple mercurial, same story.

[bitprophet]

Thanks a lot for the feedback, guys. That's really interesting, especially how it affects hg too -- @gosusnp, is hg also using the SSH protocol in this instance (from your target to the repository host)? I assume 'yes' but want to make sure.

So, sounds like there may be some problem with initiating multiple agent-using requests on the remote box -- I'll see if even the base case for this (two simple ssh calls, using interactivity) triggers it.

EDIT: Well, that didn't replicate the problem -- two subsequent run("ssh xxx") calls to two different hosts (from the same single remote target) worked fine. Don't have time to set up any kind of realistic multi-submodule Git repo right now; if @osi is using a public set of repos I could try using that one sometime.

[gosusnp]

@bitprophet, your assumption is correct.

If it helps, my current workaround is to execute the whole command using local("ssh -A %(host)s .... buildout") instead of run("buildout").

[jravetch]

Just as I initially reported ;)

[stevenmcdonald]

I have a similar problem to gosusnp, though in my case with svn (ssh+svn protocol). I'm not clear that it's exactly the same issue as the original report, though. I'm running python 2.7.1

This hangs after the output from updating 'foo'. A plain "svn up" fails the same way. One line of output then it hangs.

def doesnotwork():
  with cd('$PATH'):
    run('svn update foo bar')

This works as expected:

def works():
  with cd('$PATH'):
    run('svn update foo')

as another commenter mentioned, this workaround seems to work:

def workaround():
  local('ssh %(host)s cd $PATH && svn up foo bar' % env)

running with --show=debug doesn't seem to provide any help.

[stevenmcdonald]

Did a little more digging, and I think the issue I'm seeing is the same as #613 rather than this one. It does seem to be related to agent forwarding.

FWIW the minimal test case to show the problem I've found is:

def test():
  run('ssh server ls && ssh server ls')

Running the 2 ssh operations in separate run() calls doesn't have any problems.

[bitprophet]

Yes, this and #613 are almost definitely the same root cause, namely some sort of deficiency in the agent forwarding feature. (The perils of pull requests -- I don't know how it actually works, only that it passed tests & worked in a few basic real world test situations.)

I had tried triggering this issue with two run calls but didn't think to try doing them both within the same remote session -- that's a good catch. I'll try to recreate that version myself which might help me debug. Thanks!

[stevenmcdonald]

I don't know a lot about how ssh works its magic, and my python is pretty rusty, but I thought I'd take a stab at debugging the issue.

One thing I noticed is that in ssh.transport._parse_channel_open(), the two lines that test kind == 'auth-agent@openssh.com' (2011 and 2090) are indented with tabs while the rest of the file is indented with spaces. Correcting this has no effect on the bug though :)

Looking at the logging, I see that when auth is requested, it makes a connection to the AgentClientProxy. Then when the second ssh call makes an auth request, it fires up another AgentClientProxy to handle that, though the first AgentClientProxy is never closed.

Again, I don't know a lot about how this is supposed to work, but it seems like the ideal case would be to reuse the first AgentClientProxy, or if it does need to be shut down, maybe the fact that it's not being closed before another instance tries to connect that's causing the problem.

[bitprophet]

Actually, in my explorations, AgentClientProxy is only instantiated once, are you referring to the Secsh channel 3 (auth-agent@openssh.com) opened style lines (of which there are two)?

Anyway, have done some digging but not done yet. Mostly focusing on "what might be different in the 2nd agent request that's causing it to upset the remote sshd". Found two spots already where state is created in a non-idempotent manner:

• AgentClientProxy._forward_agent_handler sets (and starts) self.thread.
  • Making this idempotent (so only one thread is created) does impact the forwarding, in the sense that the forwarding simply does not occur the 2nd time -- I am prompted for my passphrase (but it works fine otherwise, if I enter it correctly.) Not very useful.
• AgentClientProxy.connect sets and returns self._conn, a socket object hooked up to the local SSH_AUTH_SOCK.
  • Making this idempotent (returning self._conn immediately if it's not None) has no measurable effect.
  • This was kind of expected -- the local socket isn't changing any so any socket connection to it would theoretically behave identically to any other, even if they're different Python objects.

Still digging around; also thinking based on the above that the agent handler thread might be a place to dig deeper if no other spots in the code seem likely.