Fix handling of output streams, including in cases of error.

[leehambley]

In SSHKit we do some weird stuff with stream handling depending on the packets (sic) we receive back from Net::SSH.

I'd like to write a test case script that produces buffered, and unbuffered output, line- and character-wise, on standard error, and standard out to test the correct usage.

With a pathologically badly behaved script, we could find a way to make this work reliably, I am sure.

[tisba]

For reference https://github.com/capistrano/capistrano/issues/895

[madsheep]

@leehambley Not sure if this helps and if it does not - please ignore me. I can see everybody pointing this issue out to you and my guess is you are probably sick of it right now.

As for the weird stuff there - I've seen you remove stderr value to fix the 'double output bug' https://github.com/capistrano/sshkit/issues/20 https://github.com/capistrano/sshkit/commit/ef80a33e3cc59be25ec82f23c88ef913365094cf

Reverting this commit causes sshkit to suddenly show outputs of failed commands:

before:

on %w{madsheep@a_server_far_far_away} do
  execute "lsaslasdasd"
end
 INFO [5aec5608] Running /usr/bin/env lsaslasdasd on a_server_far_far_away
SSHKit::Command::Failed: lsaslasdasd stdout: Nothing written
lsaslasdasd stderr: Nothing written

after reverting the commit

on %w{madsheep@a_server_far_far_away} do
  execute "lsaslasdasd"
end
 INFO [0c55883b] Running /usr/bin/env lsaslasdasd on a_server_far_far_away
SSHKit::Command::Failed: lsaslasdasd stdout: Nothing written
lsaslasdasd stderr: : No such file or directory

Again - not sure if that helps with anything - but I'm keeping my local version of sshkit patched to help me build my capistrano 3 recipes.

[leehambley]

Thanks for the feedback @tisba, actually it's a bit more complex than that, which is to say if we don't clear the output when it finished, you get the last "chunk" twice. (although risking showing it twice might be better than not showing it at all)

[madsheep]

I was not able to use capistrano 3 before that change - as none of the failed commands were giving output for me, which is crucial for debugging. I think it's worth making a dirty hack for checking if the line you want to append is already there. This will make it useable (and the hack can be removed once you figure this whole part properly)

[tisba]

I'd too rather prefer to have duplicate output. No output on errors is a big problem IMO.

[leehambley]

I just wrote this, which I've been meaning to do for a while:

• https://gist.github.com/leehambley/2ea90b2d7bec46153520

I believe if we can set this up somewhere, and poke the 5 different ways it can be operated until we find a solution that doesn't lose output, we should be in a good place.

[leehambley]

( I will get around to it sometime, but if someone can help, that would be greatly appreciated. )

[denmat]

Yeah, this had/has me stumped too. I can't see any output from failed commands unless I comment out:

              chan.on_request("exit-status") do |ch, data|
#                cmd.stdout = ''
#                cmd.stderr = ''
                cmd.exit_status = data.read_long
                output << cmd
              end

Would this be fixed with the #86 pull request to use capture instead? Am about to find out :)

[denmat]

this gets me what I want after using the #86 code base.

    begin 
      on(@AGENTS, in: :parallel) do |agent|
        capture "sudo puppet agent --test --environment fixing_test_env ", raise_on_non_zero_exit: true
      end
    rescue SSHKit::Command::Failed => e
      if e.message.scan(/exit\s+status:\s+(0|2)/)
        exit(0)
      else
        puts e.message.match(/stderr:\s+(Error:.*)/m)
        @exit_status
      end
    end

[maxim]

So aside from the issue with stderr not being reported on failed commands, my issue is with very messy output in my successful deploy. I'm not sure if this is related/helpful, but here's what actually happens:

I have a deploy.sh script on all machines. It has echo "fetching", echo "checking assets" and stuff (each message is output once). I have it on 5 machines. Capistrano is programmed to run it on one machine first, then on 4 others next. Keep in mind, 5 machines total.

This is what I actually see when I run this with logging set to debug and it runs successfully: https://gist.github.com/maxim/102892c03a7f4a34c61e

All of the standard output from the script is colored red (including git fetching stuff) while capistrano messages are green, so it looks even messier with color. If I set logging to info - then no output from remote machines is shown at all.

Notice all the repeated strings coming from the same machines, and some inconsistent spacing (see info message on the very bottom).

[mattbrictson]

@maxim My solution to all this was to write a custom subclass of SSHKit::Formatter::Abstract to get the concise kind of output I was looking for.

In my formatter, I write the full debug output to a log file and use stdout just for printing which command is being executed. The console now lets me monitor what is happening at a high level; if a command fails or I need to troubleshoot something, I can dig into the log file (which is super verbose and has the problems you mentioned, but it is a last resort).

[maxim]

@mbrictson This is nice, most likely will follow your example. Would be helpful to see your implementation, if you don't mind gist'ing it.

[mattbrictson]

@maxim The implementation turned out to be pretty complicated (I had to monkey patch to get access to the currently executing rake task), but the resulting output is pretty:

Most of the code lives here: https://github.com/mattbrictson/airbrussh/blob/master/lib/airbrussh/formatter.rb

[mattbrictson]

@maxim @leehambley Let me know if you think my formatter would be useful packaged as its own gem, or if you have any other suggestions on how I could improve it.

Edit: I've packaged up the formatter as a gem called airbrussh.

[maxim]

@mbrictson Wow, this plumbing must've taken quite a bit of effort, could be immensely useful and time-saving if you can make it a drop-in solution. Unfortunate thing is that if sshkit itself is fixed this might get obsolete pretty quick. Perhaps this could be worked into sshkit directly? /cc @leehambley

[leehambley]

@mattbrictson that output looks great. Nice work!

[Aeon]

So since #86 was closed, what's the currently accepted solution? Seems like there's no way to get stdout/stderr at all right now when a task fails with non-zero exit status?

[ghost]

would also like to know, as redirecting remote command's stdout and stderr to (remote) files and then (remote) cat'ing them seems far from ideal

[robd]

@daniel-gomes-sociomantic I may have misunderstood the problem here, but there is an option which can be applied to commands to stop non zero commands from raising an exception: raise_on_non_zero_exit: false. The command output is collected in the full_stderr and full_stdout attrs of the command object.

On SSHKit master, you could patch something like this on to the abstract back end (based on a mixture of the test and capture methods:

module SSHKit
  module Backend
    class Abstract
      def capture_error(*args)
        options = args.extract_options!.merge(raise_on_non_zero_exit: false, verbosity: Logger::DEBUG)
        executed_command = create_command_and_execute(args, options)
        # Do something with executed_command.full_stdout or executed_command.full_stderr
      end
    end
  end
end

Does this help?

[ghost]

@robd I'm aware of raise_on_non_zero_exit: false (so I might be the one misunderstanding the issue after all), all I wanted was to be able to capture either the stdout or the stderr of a remote command regardless of whether it succeeded or not (without having to do the redirection myself, that is).

Looking at your proposed patch, it might be just the thing I need!! Unfortunately I am not so ruby-savvy as to being able to make my Capistrano use sshkit's master branch instead of the latest release (v1.7.1)... I tried calling command directly from my task but then of course there's no defined execute_command function

[robd]

@daniel-gomes-sociomantic Are you using a Gemfile with Bundler? If so you can add the following line to your Gemfile:

gem 'sshkit', :github => 'capistrano/sshkit', :branch => 'master'

and run bundle install

[ghost]

@daniel-gomes-sociomantic Are you using a Gemfile with Bundler?

I'm not, my application is not written in ruby so I never got into the whole Gemfile setup (which is what I meant by not being very Ruby-savvy).

In the meantime, following your idea I managed to get what I wanted by combining the test and capture methods (from the v1.7.1 codebase) into one:

module SSHKit
    module Backend
        class Abstract
            def capture_error(*args)
                options = args.extract_options!.merge(
                    raise_on_non_zero_exit: false,
                    verbosity: Logger::DEBUG
                )

                executed_command = _execute(*[*args, options])

                info "stdout: #{executed_command.full_stdout}"
                info "stderr: #{executed_command.full_stderr}"
            end
        end
    end
end

and it seems to work fine, cheers @robd!

[robd]

@daniel-gomes-sociomantic Ah great - glad you got something working

[leehambley]

@mattbrictson we can close this now that Airbrusssh is the default, right ?

[mattbrictson]

Yes, this will be fixed at least in Capistrano with the merge of https://github.com/capistrano/capistrano/pull/1541. (I'm waiting until a new version of SSHKit is released to rubygems to move ahead on that PR.)