SSH timeouts and reset connections

[matt]

Is there anyway to increase the ssh timeout in capistrano, or even
better to have some form of keep-alive like the ServerAliveInterval/
ServerAliveCountMax settings in the openssh client config?

I'm deploying to EC2, and I've noticed that capistrano will die half
way through a deploy pretty reliably with a ECONNRESET. This mostly
happens during ec2 peak hours, so I think something in their routers
must be removing idle connections. The problem is, my connection
isn't really idle - during my deployment I serially execute the
restart of my servers so that we don't have any downtime. As a
result, by the time it gets to the last server, its been sitting idle
for a while, and I think the connection is dead, though cap doesn't
seem to know it till it tries to write to it. This happens when I do
other long lived tasks that don't have any output. Here is the stack
trace I see when my deploy dies:

usr/local/lib/ruby/gems/1.8/gems/net-ssh-2.0.2/lib/net/ssh/
buffered_io.rb:64:in `recv': Connection reset by peer - recvfrom(2)
(Errno::ECONNRESET)
from /usr/local/lib/ruby/gems/1.8/gems/net-ssh-2.0.2/lib/net/ssh/
buffered_io.rb:64:in `fill'
from /usr/local/lib/ruby/gems/1.8/gems/net-ssh-2.0.2/lib/net/ssh/
connection/session.rb:200:in `postprocess'
from /usr/local/lib/ruby/gems/1.8/gems/net-ssh-2.0.2/lib/net/ssh/
connection/session.rb:196:in `each'
from /usr/local/lib/ruby/gems/1.8/gems/net-ssh-2.0.2/lib/net/ssh/
connection/session.rb:196:in `postprocess'
from /usr/local/lib/ruby/gems/1.8/gems/capistrano-2.4.0/lib/
capistrano/processable.rb:31:in `process_iteration'
from /usr/local/lib/ruby/gems/1.8/gems/capistrano-2.4.0/lib/
capistrano/processable.rb:43:in `ensure_each_session'
from /usr/local/lib/ruby/gems/1.8/gems/capistrano-2.4.0/lib/
capistrano/processable.rb:41:in `each'
from /usr/local/lib/ruby/gems/1.8/gems/capistrano-2.4.0/lib/
capistrano/processable.rb:41:in `ensure_each_session'
... 67 levels...
from /usr/local/lib/ruby/gems/1.8/gems/capistrano-2.4.0/lib/
capistrano/cli/execute.rb:14:in `execute'
from /usr/local/lib/ruby/gems/1.8/gems/capistrano-2.4.0/bin/cap:4
from /usr/local/bin/cap:19:in `load'
from /usr/local/bin/cap:19

Any help appreciated, thanks,

Matt

[matt]

I'm able to easily duplicate this (on EC2 mid-afternoon anyway) with:

COMMAND="sleep 3000" cap invoke

I'll see the sleep disappear from the server, but cap will sit there
indefinitely.

So I guess 2 problems here, one I can't keep the connection alive, and
two, the connection doesn't know its no longer alive.

Matt

[Jamis Buck]

Is your EC2 instance configured to send keep-alive pings? Net::SSH
plays nice with those, so long running commands should work fine.

- Jamis

[matt]

I have TCPKeepAlive turned on, but not ClientAliveInterval, I'll try
that. Thanks,

Matt

[matt]

Ok, I added "ClientAliveInterval 60", and now I'm getting a couple of
different errors, at the exact same point in the deploy process that I
was getting the ECONNRESET, pretty repeatable, and probably too
strange to be coincidence:

/Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/buffered_io.rb:
98:in `send': closed stream (IOError)
from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
buffered_io.rb:98:in `send_pending'
from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
session.rb:208:in `postprocess'
from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
session.rb:207:in `each'
from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
session.rb:207:in `postprocess'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
processable.rb:31:in `process_iteration'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
processable.rb:43:in `ensure_each_session'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
processable.rb:41:in `each'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
processable.rb:41:in `ensure_each_session'
... 75 levels...
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/cli/
execute.rb:14:in `execute'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/bin/cap:4
from /usr/bin/cap:19:in `load'
from /usr/bin/cap:19

/Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
session.rb:523:in `channel_request': undefined method `do_request' for
nil:NilClass (NoMethodError)
from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
session.rb:428:in `send'
from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
session.rb:428:in `dispatch_incoming_packets'
from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
session.rb:185:in `preprocess'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
processable.rb:17:in `process_iteration'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
processable.rb:43:in `ensure_each_session'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
processable.rb:41:in `each'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
processable.rb:41:in `ensure_each_session'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
processable.rb:17:in `process_iteration'
... 74 levels...
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/cli/
execute.rb:14:in `execute'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/bin/cap:4
from /usr/bin/cap:19:in `load'
from /usr/bin/cap:19

[Jamis Buck]

Try reducing the interval to 15 or 20 and see if that makes any
difference. If it doesn't, try setting ClientAliveCountMax to 6 or
higher.

- Jamis

[matt]

Nope,

ClientAliveInterval 15
ClientAliveCountMax 15

gives the following stack trace every time in the same place (when it
tries to restart the 3rd of 3 app server instances)

/Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/buffered_io.rb:
98:in `send': closed stream (IOError)
from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
buffered_io.rb:98:in `send_pending'
from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
session.rb:208:in `postprocess'
from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
session.rb:207:in `each'
from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
session.rb:207:in `postprocess'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
processable.rb:31:in `process_iteration'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
processable.rb:43:in `ensure_each_session'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
processable.rb:41:in `each'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
processable.rb:41:in `ensure_each_session'
... 75 levels...
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/cli/
execute.rb:14:in `execute'
from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/bin/cap:4
from /usr/bin/cap:19:in `load'
from /usr/bin/cap:19

or sometimes this trace earlier in the process:

[Jamis Buck]

Any chance you could email me your recipe files and let me know what
task you are invoking on the command-line? I wonder if there's a bit
of ruby code or shell commands that are running for a while on your
local machine before that place where the error happens.

- Jamis

On Jul 14, 2008, at 8:53 PM, matt wrote:

>
> Nope,
>
> ClientAliveInterval 15
> ClientAliveCountMax 15
>
> gives the following stack trace every time in the same place (when it
> tries to restart the 3rd of 3 app server instances)
>
> /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/buffered_io.rb:
> 98:in `send': closed stream (IOError)
> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
> buffered_io.rb:98:in `send_pending'

> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
> connection/
> session.rb:208:in `postprocess'
> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
> connection/
> session.rb:207:in `each'
> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
> connection/
> session.rb:207:in `postprocess'
> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
> processable.rb:31:in `process_iteration'
> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
> processable.rb:43:in `ensure_each_session'
> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
> processable.rb:41:in `each'
> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/
> processable.rb:41:in `ensure_each_session'
> ... 75 levels...
> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/capistrano/cli/
> execute.rb:14:in `execute'
> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/bin/cap:4
> from /usr/bin/cap:19:in `load'
> from /usr/bin/cap:19
>
>

> or sometimes this trace earlier in the process:
>
> /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
> session.rb:523:in `channel_request': undefined method `do_request' for
> nil:NilClass (NoMethodError)

[matt]

And when I comment out these settings, things start working again (at
least now during non-peak hours), so it seems these settings break cap
(or net:ssh). In the man page for sshd_config, it states that these
settings are for ssh protocol v2 only - is net::ssh v2? If it is,
then maybe the async nature of the server polling back to the client
is exposing a bug somewhere?

Also, the net:ssh docs mention have this intriguing example for
Net::SSH::Connection:Session::send_global_request
ssh.send_global_request("keep-...@openssh.com")
If I can't get server side keep alives working, any tips on using this
as a keep-alive mechanism on the client side?

Matt

[Jamis Buck]

On Jul 14, 2008, at 10:13 PM, matt wrote:

> And when I comment out these settings, things start working again (at
> least now during non-peak hours), so it seems these settings break cap
> (or net:ssh). In the man page for sshd_config, it states that these
> settings are for ssh protocol v2 only - is net::ssh v2? If it is,
> then maybe the async nature of the server polling back to the client
> is exposing a bug somewhere?

Net::SSH is v2, yeah. I suspect the absence of those settings just
means that the connection remains open until the underlying connection
times out, which is longer than the 60 seconds that you had originally
set.

> Also, the net:ssh docs mention have this intriguing example for
> Net::SSH::Connection:Session::send_global_request
> ssh.send_global_request("keep-...@openssh.com")
> If I can't get server side keep alives working, any tips on using this
> as a keep-alive mechanism on the client side?

I'd need to see your full deploy.rb to answer that one. Basically, at
certain points during your local processing, you'd need to do
something like:

sessions.values.each do |session|
session.send_global_request("keep-...@openssh.com")
end

That may not be possible, though, if your local processing involves
something like waiting for a text editor to finish (which is where
I've run into this in the past).

- Jamis

>
>
> Matt
>
>
> On Jul 14, 10:53 pm, matt <m...@mobicious.com> wrote:
>> Nope,
>>
>> ClientAliveInterval 15
>> ClientAliveCountMax 15
>>
>> gives the following stack trace every time in the same place (when it
>> tries to restart the 3rd of 3 app server instances)
>>
>> /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/buffered_io.rb:
>> 98:in `send': closed stream (IOError)
>> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
>> buffered_io.rb:98:in `send_pending'

>> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
>> connection/
>> session.rb:208:in `postprocess'
>> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
>> connection/
>> session.rb:207:in `each'
>> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
>> connection/
>> session.rb:207:in `postprocess'
>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>> capistrano/

>> processable.rb:31:in `process_iteration'
>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>> capistrano/
>> processable.rb:43:in `ensure_each_session'
>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>> capistrano/
>> processable.rb:41:in `each'
>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>> capistrano/
>> processable.rb:41:in `ensure_each_session'
>> ... 75 levels...
>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>> capistrano/cli/
>> execute.rb:14:in `execute'
>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/bin/cap:4
>> from /usr/bin/cap:19:in `load'
>> from /usr/bin/cap:19
>>
>> or sometimes this trace earlier in the process:
>>
>> /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
>> session.rb:523:in `channel_request': undefined method `do_request'
>> for
>> nil:NilClass (NoMethodError)

>> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
>> connection/
>> session.rb:428:in `send'
>> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
>> connection/
>> session.rb:428:in `dispatch_incoming_packets'
>> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
>> connection/
>> session.rb:185:in `preprocess'
>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>> capistrano/

>> processable.rb:17:in `process_iteration'
>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>> capistrano/

>> processable.rb:43:in `ensure_each_session'
>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>> capistrano/
>> processable.rb:41:in `each'
>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>> capistrano/

>>>> processable.rb:31:in `process_iteration'
>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>> capistrano/
>>>> processable.rb:43:in `ensure_each_session'
>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>> capistrano/
>>>> processable.rb:41:in `each'
>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>> capistrano/
>>>> processable.rb:41:in `ensure_each_session'
>>>> ... 75 levels...
>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>> capistrano/cli/

>>>> execute.rb:14:in `execute'
>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/bin/cap:4
>>>> from /usr/bin/cap:19:in `load'
>>>> from /usr/bin/cap:19
>>
>>>> /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
>>>> session.rb:523:in `channel_request': undefined method
>>>> `do_request' for
>>>> nil:NilClass (NoMethodError)
>>>> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
>>>> connection/
>>>> session.rb:428:in `send'
>>>> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
>>>> connection/
>>>> session.rb:428:in `dispatch_incoming_packets'
>>>> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
>>>> connection/
>>>> session.rb:185:in `preprocess'
>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>> capistrano/

>>>> processable.rb:17:in `process_iteration'
>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>> capistrano/

>>>> processable.rb:43:in `ensure_each_session'
>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>> capistrano/
>>>> processable.rb:41:in `each'
>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>> capistrano/

>>>> processable.rb:41:in `ensure_each_session'
>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>> capistrano/
>>>> processable.rb:17:in `process_iteration'
>>>> ... 74 levels...
>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>> capistrano/cli/

[matt]

My deploy scripts are a little complicated :) They are actually part
of the rubber framework for deploying rails apps to ec2. Here is the
relevant portion of the deploy script. If you want to run this
yourself, I can easily setup a set of ec2 instances that mimic my
setup and give you access (it would just be the rubber quickstart plus
a couple of extra app servers).

http://github.com/wr0ngway/rubber/tree/master/generators/vulcanize/templates/mongrel/config/rubber/deploy-mongrel.rb

The part where I am running into trouble is when I serially restart
mongrels on each app server in turn, waiting for the app server to
come up before moving on to the next. Server 1 and 2 usually complete
ok, but I get the ECONNRESET when it starts to try to talk to server
3, I think because the ssh connection gets timeout while it is sitting
idle for too long waiting for server 1 and 2. I'm not running
anything locally, just running a while loop remotely waiting for all
the mongrel pid files to show up, thereby indicating they have all
started, and its safe to move on to the next server to restart the
mongrels there.

Matt

[Jamis Buck]

Ah-ha. Yeah, the serial restart is probably the culprit. What I
suspect is happening is that while the first servers are restarting,
the connections for the others are being starved, since cap is only
running the commands against a subset of servers (and isn't processing
events from the other servers at all). Eventually, the starved
connections will die, and then when you go to connect to them, *crash*.

We had to deal with this in one of our recipes, where we throw up a
text editor and ask the deployer to describe the changes being
deployed. While the text editor was open, the connections were all
being starved, so if the deployer took too long composing their novel,
things would blow up. :(

The work around is this. Close all sessions before you start serially
restarting servers. After each one finishes restarting, close the
connection again. The worst that happens here is that cap just needs
to reconnect to those servers multiple times, which takes a few seconds.

It should work to just put the following at the top of serial_restart:

teardown_connections_to(sessions.keys)

Let me know if that makes any difference,

Jamis

>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>> capistrano/cli/
>>> execute.rb:14:in `execute'
>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/bin/cap:4
>>> from /usr/bin/cap:19:in `load'
>>> from /usr/bin/cap:19
>>

>>>>> processable.rb:31:in `process_iteration'
>>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>>> capistrano/
>>>>> processable.rb:43:in `ensure_each_session'
>>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>>> capistrano/
>>>>> processable.rb:41:in `each'
>>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>>> capistrano/

>>>>> processable.rb:41:in `ensure_each_session'
>>>>> ... 75 levels...
>>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>>> capistrano/cli/
>>>>> execute.rb:14:in `execute'
>>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/bin/cap:4
>>>>> from /usr/bin/cap:19:in `load'
>>>>> from /usr/bin/cap:19
>>
>>>>> /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/connection/
>>>>> session.rb:523:in `channel_request': undefined method `do_request'
>>>>> for
>>>>> nil:NilClass (NoMethodError)
>>>>> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
>>>>> connection/
>>>>> session.rb:428:in `send'
>>>>> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
>>>>> connection/
>>>>> session.rb:428:in `dispatch_incoming_packets'
>>>>> from /Library/Ruby/Gems/1.8/gems/net-ssh-2.0.3/lib/net/ssh/
>>>>> connection/
>>>>> session.rb:185:in `preprocess'
>>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>>> capistrano/

>>>>> processable.rb:17:in `process_iteration'
>>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>>> capistrano/

>>>>> processable.rb:43:in `ensure_each_session'
>>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>>> capistrano/
>>>>> processable.rb:41:in `each'
>>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>>> capistrano/

>>>>> processable.rb:41:in `ensure_each_session'
>>>>> from /Library/Ruby/Gems/1.8/gems/capistrano-2.4.3/lib/
>>>>> capistrano/

[matt]

Cool, thanks Jamis, that worked perfectly.
I wonder if this is something that should be worked around in core
capistrano since I'd imagine long running migrations would also cause
this problem (for those with short tcp tmeouts anyway)

Matt