Net-ssh - execution expired

Ruby
1

hi *,

i’m having a problem with net-ssh. i’m trying to run a command on
another server that might take about 10h. after about 4 to 5 hours i ran
into the error below.
is there a way to modify the timeout that might cause the problem?

i know this is the ruby mailing list and i’m working on a rails app but
this problem is more related to pure ruby than rails.

it would be great if somebody could give me some pointers.

thx for your help,
simon

#Class:0x000000043ba6b0: execution expired
/usr/local/lib/ruby/gems/1.9.1/gems/net-ssh-2.0.23/lib/net/ssh/ruby_compat.rb:22:in
select' /usr/local/lib/ruby/gems/1.9.1/gems/net-ssh-2.0.23/lib/net/ssh/ruby_compat.rb:22:inio_select’
/usr/local/lib/ruby/gems/1.9.1/gems/net-ssh-2.0.23/lib/net/ssh/connection/session.rb:201:in
process' /usr/local/lib/ruby/gems/1.9.1/gems/net-ssh-2.0.23/lib/net/ssh/connection/session.rb:161:inblock in loop’
/usr/local/lib/ruby/gems/1.9.1/gems/net-ssh-2.0.23/lib/net/ssh/connection/session.rb:161:in
loop' /usr/local/lib/ruby/gems/1.9.1/gems/net-ssh-2.0.23/lib/net/ssh/connection/session.rb:161:inloop’
/usr/local/lib/ruby/gems/1.9.1/gems/net-ssh-2.0.23/lib/net/ssh/connection/channel.rb:269:in
wait' /var/rails/releases/20110314075616/lib/ssh_commander.rb:119:inblock (2
levels) in runCmd’
/var/rails/releases/20110314075616/lib/ssh_commander.rb:96:in each' /var/rails/releases/20110314075616/lib/ssh_commander.rb:96:inblock in
runCmd’
/usr/local/lib/ruby/gems/1.9.1/gems/net-ssh-2.0.23/lib/net/ssh.rb:186:in
start' /var/rails/releases/20110314075616/lib/ssh_commander.rb:88:inrunCmd’
/var/rails/releases/20110314075616/app/models/task.rb:292:in
command_run' /var/rails/releases/20110314075616/app/models/task_mysql_slave.rb:65:inblock (2 levels) in class:TaskMysqlSlave’
/var/rails/releases/20110314075616/app/models/task.rb:341:in call' /var/rails/releases/20110314075616/app/models/task.rb:341:incommand_log_block’
/var/rails/releases/20110314075616/app/models/task_mysql_slave.rb:59:in
block in <class:TaskMysqlSlave>' /var/rails/releases/20110314075616/app/models/task.rb:154:ininstance_exec’
/var/rails/releases/20110314075616/app/models/task.rb:154:in exec' /usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/performable_method.rb:20:inperform’
/usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/backend/base.rb:83:in
invoke_job' /usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/worker.rb:119:inblock (2 levels) in run’
/usr/local/lib/ruby/1.9.1/timeout.rb:57:in timeout' /usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/worker.rb:119:inblock in run’
/usr/local/lib/ruby/1.9.1/benchmark.rb:309:in realtime' /usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/worker.rb:118:inrun’
/usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/worker.rb:176:in
reserve_and_run_one_job' /usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/worker.rb:103:inblock in work_off’
/usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/worker.rb:102:in
times' /usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/worker.rb:102:inwork_off’
/usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/worker.rb:77:in
block (2 levels) in start' /usr/local/lib/ruby/1.9.1/benchmark.rb:309:inrealtime’
/usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/worker.rb:76:in
block in start' /usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/worker.rb:73:inloop’
/usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/worker.rb:73:in
start' /usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/command.rb:100:inrun’
/usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/command.rb:79:in
block in run_process' /usr/local/lib/ruby/gems/1.9.1/gems/daemons-1.0.10/lib/daemons/application.rb:215:incall’
/usr/local/lib/ruby/gems/1.9.1/gems/daemons-1.0.10/lib/daemons/application.rb:215:in
block in start_proc' /usr/local/lib/ruby/gems/1.9.1/gems/daemons-1.0.10/lib/daemons/daemonize.rb:192:incall’
/usr/local/lib/ruby/gems/1.9.1/gems/daemons-1.0.10/lib/daemons/daemonize.rb:192:in
call_as_daemon' /usr/local/lib/ruby/gems/1.9.1/gems/daemons-1.0.10/lib/daemons/application.rb:219:instart_proc’
/usr/local/lib/ruby/gems/1.9.1/gems/daemons-1.0.10/lib/daemons/application.rb:255:in
start' /usr/local/lib/ruby/gems/1.9.1/gems/daemons-1.0.10/lib/daemons/controller.rb:69:inrun’
/usr/local/lib/ruby/gems/1.9.1/gems/daemons-1.0.10/lib/daemons.rb:188:in
block in run_proc' /usr/local/lib/ruby/gems/1.9.1/gems/daemons-1.0.10/lib/daemons/cmdline.rb:105:incall’
/usr/local/lib/ruby/gems/1.9.1/gems/daemons-1.0.10/lib/daemons/cmdline.rb:105:in
catch_exceptions' /usr/local/lib/ruby/gems/1.9.1/gems/daemons-1.0.10/lib/daemons.rb:187:inrun_proc’
/usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/command.rb:78:in
run_process' /usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/command.rb:72:inblock in daemonize’
/usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/command.rb:70:in
times' /usr/local/lib/ruby/gems/1.9.1/gems/delayed_job-2.1.2/lib/delayed/command.rb:70:indaemonize’
/var/rails/current/script//delayed_job:5:in `’

2

Hey,

it seems I am getting the same kind of issue right now that seems to
happen randomly where one of my ssh.exec! call get stuck.

I ran with debug verbose and collected the following logs:

I, [2011-07-21T21:08:41.387471 #17018] INFO –
net.ssh.connection.session[54acbcc]: channel_open_confirmation: 5 1 0
32768
I, [2011-07-21T21:08:41.387596 #17018] INFO –
net.ssh.connection.channel[53efa28]: sending channel request “exec”
D, [2011-07-21T21:08:41.387805 #17018] DEBUG – tcpsocket[5505212]:
queueing packet nr 22 type 98 len 44
D, [2011-07-21T21:08:41.387947 #17018] DEBUG – tcpsocket[5505212]: sent
68 bytes
D, [2011-07-21T21:08:41.391034 #17018] DEBUG – tcpsocket[5505212]: read
88 bytes
D, [2011-07-21T21:08:41.391278 #17018] DEBUG – tcpsocket[5505212]:
received packet nr 39 type 93 len 28
I, [2011-07-21T21:08:41.391397 #17018] INFO –
net.ssh.connection.session[54acbcc]: channel_window_adjust: 5 +2097152
D, [2011-07-21T21:08:41.391558 #17018] DEBUG – tcpsocket[5505212]:
received packet nr 40 type 99 len 12
I, [2011-07-21T21:08:41.391650 #17018] INFO –
net.ssh.connection.session[54acbcc]: channel_success: 5
D, [2011-07-21T21:08:41.418998 #17018] DEBUG – tcpsocket[5505212]: read
36 bytes
D, [2011-07-21T21:08:41.419205 #17018] DEBUG – tcpsocket[5505212]:
received packet nr 41 type 96 len 12
I, [2011-07-21T21:08:41.419302 #17018] INFO –
net.ssh.connection.session[54acbcc]: channel_eof: 4
D, [2011-07-21T21:08:41.419501 #17018] DEBUG – tcpsocket[5505212]: read
104 bytes
D, [2011-07-21T21:08:41.419699 #17018] DEBUG – tcpsocket[5505212]:
received packet nr 42 type 98 len 44
I, [2011-07-21T21:08:41.419825 #17018] INFO –
net.ssh.connection.session[54acbcc]: channel_request: 4 exit-signal
false
D, [2011-07-21T21:08:41.420041 #17018] DEBUG – tcpsocket[5505212]:
received packet nr 43 type 97 len 12
I, [2011-07-21T21:08:41.420133 #17018] INFO –
net.ssh.connection.session[54acbcc]: channel_close: 4
D, [2011-07-21T21:08:41.420344 #17018] DEBUG – tcpsocket[5505212]:
queueing packet nr 23 type 97 len 28
D, [2011-07-21T21:08:41.420464 #17018] DEBUG – tcpsocket[5505212]: read
140 bytes
D, [2011-07-21T21:08:41.420620 #17018] DEBUG – tcpsocket[5505212]:
received packet nr 44 type 96 len 12
I, [2011-07-21T21:08:41.420711 #17018] INFO –
net.ssh.connection.session[54acbcc]: channel_eof: 5
D, [2011-07-21T21:08:41.420886 #17018] DEBUG – tcpsocket[5505212]:
received packet nr 45 type 98 len 44
I, [2011-07-21T21:08:41.421000 #17018] INFO –
net.ssh.connection.session[54acbcc]: channel_request: 5 exit-status
false
D, [2011-07-21T21:08:41.421197 #17018] DEBUG – tcpsocket[5505212]:
received packet nr 46 type 97 len 12
I, [2011-07-21T21:08:41.421289 #17018] INFO –
net.ssh.connection.session[54acbcc]: channel_close: 5
D, [2011-07-21T21:08:41.421444 #17018] DEBUG – tcpsocket[5505212]:
queueing packet nr 24 type 97 len 28

I don’t see anything obviously wrong. The backtrace when I kill the app
is the following:

~/.gem/ruby/1.9.1/gems/net-ssh-2.1.4/lib/net/ssh/ruby_compat.rb:22:in
select': Interrupt from ~/.gem/ruby/1.9.1/gems/net-ssh-2.1.4/lib/net/ssh/ruby_compat.rb:22:inio_select’
from
~/.gem/ruby/1.9.1/gems/net-ssh-2.1.4/lib/net/ssh/connection/session.rb:201:in
process' from ~/.gem/ruby/1.9.1/gems/net-ssh-2.1.4/lib/net/ssh/connection/session.rb:161:inblock in loop’
from
~/.gem/ruby/1.9.1/gems/net-ssh-2.1.4/lib/net/ssh/connection/session.rb:161:in
loop' from ~/.gem/ruby/1.9.1/gems/net-ssh-2.1.4/lib/net/ssh/connection/session.rb:161:inloop’
from
~/.gem/ruby/1.9.1/gems/net-ssh-2.1.4/lib/net/ssh/connection/channel.rb:269:in
wait' from ~/.gem/ruby/1.9.1/gems/net-ssh-2.1.4/lib/net/ssh/connection/session.rb:355:inexec!’

The code is the following:

mcast.each do |gaddr|
STDERR.print " [+] testing filtering for multicast address
(#{gaddr})"

thleafiperf = Thread.new do
  ch = @sshleafvm.open_channel do |ch|
    ch.exec("iperf -s -u -B #{gaddr}") do |ch, success|
      raise "failed to launch iperf on multicast leaf vm" unless

success
end
end
ch.wait
end

thleaftcpdump = Thread.new do
  ch = @sshleafvm.open_channel do |ch|
    ch[:result]

    ch.exec("tcpdump -i eth0 src host #{@vmrouterip} and dst host

#{gaddr} -c 1 -n -N") do |ch, success|
raise “failed to launch tcpdump on multicast leaf vm” unless
success
end

    ch.on_data do |ch, data|
      ch[:result] << data
    end
  end
  ch.wait
  ch[:result]
end

throuter = Thread.new do
  ch = @sshroutervm.open_channel do |ch|
    ch.exec("iperf -c #{gaddr} -u -T 32 -t 20 -i 1") do |ch,

success|
raise “failed to launch iperf on multicast router vm” unless
success
end
end
ch.wait
end

(1..60).each do
  sleep 1
  STDERR.print "."
end
puts ""

puts "   [+] multicast leaf vm captured: #{thleaftcpdump.value}"

unless thleaftcpdump.alive?
puts " [+] multicast leaf vm did not capture anything" unless
!thleaftcpdump.alive?
passed = (acl == “white-list”) ? !thleaftcpdump.alive? :
thleaftcpdump.alive?

if passed
  puts "   [+] multicast address (#{gaddr}) properly filtered"
else
  puts "   [-] multicast address (#{gaddr}) filtering failed"
end

@sshleafvm.exec!("killall -9 iperf")
@sshleafvm.exec!("killall -9 tcpdump")
@sshroutervm.exec!("killall -9 iperf")

end

It seems to get stuck around the killall commands after couple of
iterations. I did not let it run long enough but I am sure on the long
run I would get the execution expired issue mentioned above.

Thanks for the help,