Re: net-ssh - execution expired

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:in
`io_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:in
`block 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:in
`loop'
        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:in
`exec!'

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,

-- 
Posted via http://www.ruby-forum.com/.