diff --git a/BREAKING_API_WISHLIST.md b/BREAKING_API_WISHLIST.md index 9d5ba571..b9fcd03e 100644 --- a/BREAKING_API_WISHLIST.md +++ b/BREAKING_API_WISHLIST.md @@ -5,6 +5,10 @@ which could be considered at the next major release. * Consider no longer stripping by default on `capture` [#249](https://github.com/capistrano/sshkit/pull/249) -## Deprecated methods which could be deleted in a future major release +## Deprecated code which could be deleted in a future major release -* [Abstract.background](lib/sshkit/backends/abstract.rb#L43) \ No newline at end of file +* [Abstract.background method](lib/sshkit/backends/abstract.rb#L43) +* [`@stderr`, `@stdout` attrs on `Command`](lib/sshkit/command.rb#L28) + +## Cleanup when Ruby 1.9 support is dropped +* `to_a` can probably be removed from `"str".lines.to_a`, since `"str".lines` returns an `Array` under Ruby 2 \ No newline at end of file diff --git a/CHANGELOG.md b/CHANGELOG.md index e5f3e2e6..630c5dea 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,9 +7,14 @@ appear at the top. * Add your entries below here, remember to credit yourself however you want to be credited! + * Introduce `log_command_start`, `log_command_data`, `log_command_exit` methods on `Formatter` + [PR #257](https://github.com/capistrano/sshkit/pull/257) + @robd + * Deprecate `@stdout` and `@stderr` accessors on `Command` * Add support for deprecation logging options. [README](README.md#deprecation-warnings), [PR #258](https://github.com/capistrano/sshkit/pull/258) + @robd * Quote environment variable values. [PR #250](https://github.com/capistrano/sshkit/pull/250) @Sinjo - Chris Sinjakli diff --git a/lib/sshkit/backends/local.rb b/lib/sshkit/backends/local.rb index 37397d02..83588dae 100644 --- a/lib/sshkit/backends/local.rb +++ b/lib/sshkit/backends/local.rb @@ -34,7 +34,7 @@ def download!(remote, local=nil, options = {}) private def execute_command(cmd) - output << cmd + output.log_command_start(cmd) cmd.started = Time.now @@ -42,14 +42,14 @@ def execute_command(cmd) stdout_thread = Thread.new do while line = stdout.gets do cmd.on_stdout(stdin, line) - output << cmd + output.log_command_data(cmd, :stdout, line) end end stderr_thread = Thread.new do while line = stderr.gets do cmd.on_stderr(stdin, line) - output << cmd + output.log_command_data(cmd, :stderr, line) end end @@ -57,10 +57,8 @@ def execute_command(cmd) stderr_thread.join cmd.exit_status = wait_thr.value.to_i - cmd.clear_stdout_lines - cmd.clear_stderr_lines - output << cmd + output.log_command_exit(cmd) end end diff --git a/lib/sshkit/backends/netssh.rb b/lib/sshkit/backends/netssh.rb index 33d5ef12..fb1709f5 100644 --- a/lib/sshkit/backends/netssh.rb +++ b/lib/sshkit/backends/netssh.rb @@ -81,7 +81,7 @@ def transfer_summarizer(action) end def execute_command(cmd) - output << cmd + output.log_command_start(cmd) cmd.started = true exit_status = nil with_ssh do |ssh| @@ -90,11 +90,11 @@ def execute_command(cmd) chan.exec cmd.to_command do |ch, success| chan.on_data do |ch, data| cmd.on_stdout(ch, data) - output << cmd + output.log_command_data(cmd, :stdout, data) end chan.on_extended_data do |ch, type, data| cmd.on_stderr(ch, data) - output << cmd + output.log_command_data(cmd, :stderr, data) end chan.on_request("exit-status") do |ch, data| exit_status = data.read_long @@ -104,7 +104,7 @@ def execute_command(cmd) # # might also be a worthwhile thing to report # exit_signal = data.read_string.to_i # warn ">>> " + exit_signal.inspect - # output << cmd + # output.log_command_killed(cmd, exit_signal) #end chan.on_open_failed do |ch| # TODO: What do do here? @@ -125,7 +125,7 @@ def execute_command(cmd) # Set exit_status and log the result upon completion if exit_status cmd.exit_status = exit_status - output << cmd + output.log_command_exit(cmd) end end diff --git a/lib/sshkit/backends/printer.rb b/lib/sshkit/backends/printer.rb index e59fecb0..d9c5277d 100644 --- a/lib/sshkit/backends/printer.rb +++ b/lib/sshkit/backends/printer.rb @@ -5,7 +5,7 @@ module Backend class Printer < Abstract def execute_command(cmd) - output << cmd + output.log_command_start(cmd) end alias :upload! :execute diff --git a/lib/sshkit/command.rb b/lib/sshkit/command.rb index 7feb73f8..ca4d484c 100644 --- a/lib/sshkit/command.rb +++ b/lib/sshkit/command.rb @@ -56,26 +56,38 @@ def failure? end alias :failed? :failure? + def stdout + log_reader_deprecation('stdout') + @stdout + end + + def stdout=(new_value) + log_writer_deprecation('stdout') + @stdout = new_value + end + + def stderr + log_reader_deprecation('stderr') + @stderr + end + + def stderr=(new_value) + log_writer_deprecation('stderr') + @stderr = new_value + end + def on_stdout(channel, data) @stdout = data @full_stdout += data call_interaction_handler(channel, data, :on_stdout) end - def clear_stdout_lines - split_and_clear_stream(:@stdout) - end - def on_stderr(channel, data) @stderr = data @full_stderr += data call_interaction_handler(channel, data, :on_stderr) end - def clear_stderr_lines - split_and_clear_stream(:@stderr) - end - def exit_status=(new_exit_status) @finished_at = Time.now @exit_status = new_exit_status @@ -218,16 +230,24 @@ def sanitize_command! end end - def split_and_clear_stream(stream_name) - # Convert lines enumerable to an array for ruby 1.9 - instance_variable_get(stream_name).lines.to_a.tap { instance_variable_set(stream_name, '') } - end - def call_interaction_handler(channel, data, callback_name) interaction_handler = options[:interaction_handler] interaction_handler = MappingInteractionHandler.new(interaction_handler) if interaction_handler.kind_of?(Hash) interaction_handler.send(callback_name, channel, data, self) if interaction_handler.respond_to?(callback_name) end + + def log_reader_deprecation(stream) + SSHKit.config.deprecation_logger.log( + "The #{stream} method on Command is deprecated. " \ + "The @#{stream} attribute will be removed in a future release. Use full_#{stream}() instead." + ) + end + + def log_writer_deprecation(stream) + SSHKit.config.deprecation_logger.log( + "The #{stream}= method on Command is deprecated. The @#{stream} attribute will be removed in a future release." + ) + end end end diff --git a/lib/sshkit/formatters/abstract.rb b/lib/sshkit/formatters/abstract.rb index 2ae43ceb..38c4d895 100644 --- a/lib/sshkit/formatters/abstract.rb +++ b/lib/sshkit/formatters/abstract.rb @@ -23,10 +23,25 @@ def initialize(output) end alias :log :info + def log_command_start(command) + write(command) + end + + def log_command_data(command, stream_type, stream_data) + write(command) + end + + def log_command_exit(command) + write(command) + end + + def <<(obj) + write(obj) + end + def write(obj) raise "Abstract formatter should not be used directly, maybe you want SSHKit::Formatter::BlackHole" end - alias :<< :write end diff --git a/lib/sshkit/formatters/black_hole.rb b/lib/sshkit/formatters/black_hole.rb index a4babd47..29ca1179 100644 --- a/lib/sshkit/formatters/black_hole.rb +++ b/lib/sshkit/formatters/black_hole.rb @@ -7,7 +7,6 @@ class BlackHole < Abstract def write(obj) # Nothing, nothing to do end - alias :<< :write end diff --git a/lib/sshkit/formatters/dot.rb b/lib/sshkit/formatters/dot.rb index 540bba5e..23c62982 100644 --- a/lib/sshkit/formatters/dot.rb +++ b/lib/sshkit/formatters/dot.rb @@ -4,13 +4,12 @@ module Formatter class Dot < Abstract + def log_command_exit(command) + original_output << colorize('.', command.failure? ? :red : :green) + end + def write(obj) - return unless obj.is_a? SSHKit::Command - if obj.finished? - original_output << colorize('.', obj.failure? ? :red : :green) - end end - alias :<< :write end diff --git a/lib/sshkit/formatters/pretty.rb b/lib/sshkit/formatters/pretty.rb index 77db195c..e8014852 100644 --- a/lib/sshkit/formatters/pretty.rb +++ b/lib/sshkit/formatters/pretty.rb @@ -8,16 +8,35 @@ class Pretty < Abstract LEVEL_COLORS = [:black, :blue, :yellow, :red, :red].freeze def write(obj) - return if obj.respond_to?(:verbosity) && obj.verbosity < SSHKit.config.output_verbosity - case obj - when SSHKit::Command then write_command(obj) - when SSHKit::LogMessage then write_message(obj.verbosity, obj.to_s) + if obj.kind_of?(SSHKit::LogMessage) + write_message(obj.verbosity, obj.to_s) else - raise "Output formatter only supports formatting SSHKit::Command and SSHKit::LogMessage, " \ - "called with #{obj.class}: #{obj.inspect}" + raise "write only supports formatting SSHKit::LogMessage, called with #{obj.class}: #{obj.inspect}" end end - alias :<< :write + + def log_command_start(command) + host_prefix = command.host.user ? "as #{colorize(command.host.user, :blue)}@" : 'on ' + message = "Running #{colorize(command, :yellow, :bold)} #{host_prefix}#{colorize(command.host, :blue)}" + write_message(command.verbosity, message, command.uuid) + write_message(Logger::DEBUG, "Command: #{colorize(command.to_command, :blue)}", command.uuid) + end + + def log_command_data(command, stream_type, stream_data) + color = case stream_type + when :stdout then :green + when :stderr then :red + else raise "Unrecognised stream_type #{stream_type}, expected :stdout or :stderr" + end + write_message(Logger::DEBUG, colorize("\t#{stream_data}".chomp, color), command.uuid) + end + + def log_command_exit(command) + runtime = sprintf('%5.3f seconds', command.runtime) + successful_or_failed = command.failure? ? colorize('failed', :red, :bold) : colorize('successful', :green, :bold) + message = "Finished in #{runtime} with exit status #{command.exit_status} (#{successful_or_failed})." + write_message(command.verbosity, message, command.uuid) + end protected @@ -29,39 +48,8 @@ def format_message(verbosity, message, uuid=nil) private - def write_command(command) - uuid = command.uuid - - unless command.started? - host_prefix = command.host.user ? "as #{colorize(command.host.user, :blue)}@" : 'on ' - message = "Running #{colorize(command, :yellow, :bold)} #{host_prefix}#{colorize(command.host, :blue)}" - write_message(command.verbosity, message, uuid) - write_debug("Command: #{colorize(command.to_command, :blue)}", uuid) - end - - write_std_stream_debug(command.clear_stdout_lines, :green, uuid) - write_std_stream_debug(command.clear_stderr_lines, :red, uuid) - - if command.finished? - runtime = sprintf('%5.3f seconds', command.runtime) - successful_or_failed = command.failure? ? colorize('failed', :red, :bold) : colorize('successful', :green, :bold) - message = "Finished in #{runtime} with exit status #{command.exit_status} (#{successful_or_failed})." - write_message(command.verbosity, message, uuid) - end - end - - def write_std_stream_debug(lines, color, uuid) - lines.each do |line| - write_debug(colorize("\t#{line}".chomp, color), uuid) - end - end - - def write_debug(message, uuid) - write_message(Logger::DEBUG, message, uuid) if SSHKit.config.output_verbosity == Logger::DEBUG - end - def write_message(verbosity, message, uuid=nil) - original_output << "#{format_message(verbosity, message, uuid)}\n" + original_output << "#{format_message(verbosity, message, uuid)}\n" if verbosity >= SSHKit.config.output_verbosity end end diff --git a/test/unit/formatters/test_custom.rb b/test/unit/formatters/test_custom.rb new file mode 100644 index 00000000..e4afac3e --- /dev/null +++ b/test/unit/formatters/test_custom.rb @@ -0,0 +1,65 @@ +require 'helper' + +module SSHKit + # Try to maintain backwards compatibility with Custom formatters defined by other people + class TestCustom < UnitTest + + def setup + super + SSHKit.config.output_verbosity = Logger::DEBUG + end + + def output + @output ||= String.new + end + + def custom + @custom ||= CustomFormatter.new(output) + end + + { + log: 'LM 1 Test', + fatal: 'LM 4 Test', + error: 'LM 3 Test', + warn: 'LM 2 Test', + info: 'LM 1 Test', + debug: 'LM 0 Test' + }.each do |level, expected_output| + define_method("test_#{level}_logging") do + custom.send(level, 'Test') + assert_log_output expected_output + end + end + + def test_write_logs_commands + custom.write(Command.new(:ls)) + + assert_log_output 'C 1 /usr/bin/env ls' + end + + def test_double_chevron_logs_commands + custom << Command.new(:ls) + + assert_log_output 'C 1 /usr/bin/env ls' + end + + private + + def assert_log_output(expected_output) + assert_equal expected_output, output + end + + end + + class CustomFormatter < SSHKit::Formatter::Abstract + def write(obj) + original_output << case obj + when SSHKit::Command then "C #{obj.verbosity} #{obj}" + when SSHKit::LogMessage then "LM #{obj.verbosity} #{obj}" + end + end + alias :<< :write + + end + +end diff --git a/test/unit/formatters/test_dot.rb b/test/unit/formatters/test_dot.rb index 3c803a6f..343fef9e 100644 --- a/test/unit/formatters/test_dot.rb +++ b/test/unit/formatters/test_dot.rb @@ -23,9 +23,13 @@ def dot end end - def test_unfinished_command - command = SSHKit::Command.new(:ls) - dot << command + def test_log_command_start + dot.log_command_start(SSHKit::Command.new(:ls)) + assert_log_output('') + end + + def test_log_command_data + dot.log_command_data(SSHKit::Command.new(:ls), :stdout, 'Some output') assert_log_output('') end @@ -33,7 +37,7 @@ def test_command_success output.stubs(:tty?).returns(true) command = SSHKit::Command.new(:ls) command.exit_status = 0 - dot << command + dot.log_command_exit(command) assert_log_output("\e[0;32;49m.\e[0m") end @@ -41,15 +45,10 @@ def test_command_failure output.stubs(:tty?).returns(true) command = SSHKit::Command.new(:ls, {raise_on_non_zero_exit: false}) command.exit_status = 1 - dot << command + dot.log_command_exit(command) assert_log_output("\e[0;31;49m.\e[0m") end - def test_unsupported_class - dot << Pathname.new('/tmp') - assert_log_output('') - end - private def assert_log_output(expected_output) diff --git a/test/unit/formatters/test_pretty.rb b/test/unit/formatters/test_pretty.rb index 59d41afb..007881ef 100644 --- a/test/unit/formatters/test_pretty.rb +++ b/test/unit/formatters/test_pretty.rb @@ -6,6 +6,7 @@ class TestPretty < UnitTest def setup super SSHKit.config.output_verbosity = Logger::DEBUG + Command.any_instance.stubs(:uuid).returns('aaaaaa') end def output @@ -87,21 +88,31 @@ def test_unsupported_class raised_error = assert_raises RuntimeError do pretty << Pathname.new('/tmp') end - assert_equal('Output formatter only supports formatting SSHKit::Command and SSHKit::LogMessage, called with Pathname: #', raised_error.message) + assert_equal('write only supports formatting SSHKit::LogMessage, called with Pathname: #', raised_error.message) end - def test_does_not_log_when_verbosity_is_too_low - output.stubs(:tty?).returns(true) - + def test_does_not_log_message_when_verbosity_is_too_low SSHKit.config.output_verbosity = Logger::WARN pretty.info('Some info') assert_log_output('') SSHKit.config.output_verbosity = Logger::INFO pretty.info('Some other info') - assert_log_output("\e[0;34;49mINFO\e[0m Some other info\n") + assert_log_output(" INFO Some other info\n") end + def test_does_not_log_command_when_verbosity_is_too_low + SSHKit.config.output_verbosity = Logger::WARN + command = Command.new(:ls, host: Host.new('user@localhost'), verbosity: Logger::INFO) + pretty.log_command_start(command) + assert_log_output('') + + SSHKit.config.output_verbosity = Logger::INFO + pretty.log_command_start(command) + assert_log_output(" INFO [aaaaaa] Running /usr/bin/env ls as user@localhost\n") + end + + def test_can_write_to_output_which_just_supports_append # Note output doesn't have to be an IO, it only needs to support << output = stub(:<<) @@ -113,17 +124,15 @@ def test_can_write_to_output_which_just_supports_append def simulate_command_lifecycle(pretty) command = SSHKit::Command.new(:a_cmd, 'some args', host: Host.new('user@localhost')) - command.stubs(:uuid).returns('aaaaaa') command.stubs(:runtime).returns(1) - pretty << command + pretty.log_command_start(command) command.started = true - pretty << command command.on_stdout(nil, 'stdout message') - pretty << command + pretty.log_command_data(command, :stdout, 'stdout message') command.on_stderr(nil, 'stderr message') - pretty << command + pretty.log_command_data(command, :stderr, 'stderr message') command.exit_status = 0 - pretty << command + pretty.log_command_exit(command) end def assert_log_output(expected_output) diff --git a/test/unit/formatters/test_simple_text.rb b/test/unit/formatters/test_simple_text.rb index ab5b81a8..4a6d1fd0 100644 --- a/test/unit/formatters/test_simple_text.rb +++ b/test/unit/formatters/test_simple_text.rb @@ -38,15 +38,14 @@ def test_command_lifecycle_logging command.stubs(:uuid).returns('aaaaaa') command.stubs(:runtime).returns(1) - simple << command + simple.log_command_start(command) command.started = true - simple << command command.on_stdout(nil, 'stdout message') - simple << command + simple.log_command_data(command, :stdout, 'stdout message') command.on_stderr(nil, 'stderr message') - simple << command + simple.log_command_data(command, :stderr, 'stderr message') command.exit_status = 0 - simple << command + simple.log_command_exit(command) expected_log_lines = [ 'Running /usr/bin/env a_cmd some args as user@localhost', @@ -62,7 +61,7 @@ def test_unsupported_class raised_error = assert_raises RuntimeError do simple << Pathname.new('/tmp') end - assert_equal('Output formatter only supports formatting SSHKit::Command and SSHKit::LogMessage, called with Pathname: #', raised_error.message) + assert_equal('write only supports formatting SSHKit::LogMessage, called with Pathname: #', raised_error.message) end def test_does_not_log_when_verbosity_is_too_low diff --git a/test/unit/test_command.rb b/test/unit/test_command.rb index 9cca5d2b..69598158 100644 --- a/test/unit/test_command.rb +++ b/test/unit/test_command.rb @@ -168,19 +168,46 @@ def test_failure? def test_on_stdout c = Command.new(:whoami) c.on_stdout(nil, "test\n") - assert_equal ["test\n"], c.clear_stdout_lines + c.on_stdout(nil, 'test2') + c.on_stdout(nil, 'test3') + assert_equal "test\ntest2test3", c.full_stdout end def test_on_stderr c = Command.new(:whoami) - c.on_stderr(nil, "test\n") - assert_equal ["test\n"], c.clear_stderr_lines + c.on_stderr(nil, 'test') + assert_equal 'test', c.full_stderr end - def test_clear_lines_methods_return_empty_array_when_blank - command = Command.new(:some_command) - assert_equal [], command.clear_stdout_lines - assert_equal [], command.clear_stderr_lines + def test_deprecated_stdtream_accessors + deprecation_out = '' + SSHKit.config.deprecation_output = deprecation_out + + c = Command.new(:whoami) + c.stdout='a test' + assert_equal('a test', c.stdout) + c.stderr='another test' + assert_equal('another test', c.stderr) + deprecation_lines = deprecation_out.lines.to_a + + assert_equal 8, deprecation_lines.size + assert_equal( + '[Deprecated] The stdout= method on Command is deprecated. ' + + "The @stdout attribute will be removed in a future release.\n", + deprecation_lines[0]) + assert_equal( + '[Deprecated] The stdout method on Command is deprecated. ' + + "The @stdout attribute will be removed in a future release. Use full_stdout() instead.\n", + deprecation_lines[2]) + + assert_equal( + '[Deprecated] The stderr= method on Command is deprecated. ' + + "The @stderr attribute will be removed in a future release.\n", + deprecation_lines[4]) + assert_equal( + '[Deprecated] The stderr method on Command is deprecated. ' + + "The @stderr attribute will be removed in a future release. Use full_stderr() instead.\n", + deprecation_lines[6]) end def test_setting_exit_status