diff --git a/lib/sshkit/command.rb b/lib/sshkit/command.rb index b7f33041..70de4ce3 100644 --- a/lib/sshkit/command.rb +++ b/lib/sshkit/command.rb @@ -83,6 +83,14 @@ def failure? end alias :failed? :failure? + def clear_stdout_lines + split_and_clear_stream(@stdout) + 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 @@ -227,6 +235,10 @@ def sanitize_command! end end + def split_and_clear_stream(stream) + stream.lines.to_a.tap { stream.clear } # Convert lines enumerable to an array for ruby 1.9 + end + end end diff --git a/lib/sshkit/formatters/abstract.rb b/lib/sshkit/formatters/abstract.rb index 3e4f5665..99db14dd 100644 --- a/lib/sshkit/formatters/abstract.rb +++ b/lib/sshkit/formatters/abstract.rb @@ -19,6 +19,11 @@ def write(obj) end alias :<< :write + protected + + def format_std_stream_line(line) + ("\t" + line).chomp + end end end diff --git a/lib/sshkit/formatters/pretty.rb b/lib/sshkit/formatters/pretty.rb index 3e6958d7..c2de0291 100644 --- a/lib/sshkit/formatters/pretty.rb +++ b/lib/sshkit/formatters/pretty.rb @@ -19,40 +19,33 @@ def write(obj) def write_command(command) unless command.started? - original_output << "%6s %s\n" % [level(command.verbosity), - uuid(command) + "Running #{c.yellow(c.bold(String(command)))} #{command.host.user ? "as #{c.blue(command.host.user)}@" : "on "}#{c.blue(command.host.to_s)}"] + host_prefix = command.host.user ? "as #{c.blue(command.host.user)}@" : 'on ' + write_command_message("Running #{c.yellow(c.bold(String(command)))} #{host_prefix}#{c.blue(command.host.to_s)}", command) if SSHKit.config.output_verbosity == Logger::DEBUG - original_output << "%6s %s\n" % [level(Logger::DEBUG), - uuid(command) + "Command: #{c.blue(command.to_command)}"] + write_command_message("Command: #{c.blue(command.to_command)}", command, Logger::DEBUG) end end if SSHKit.config.output_verbosity == Logger::DEBUG - unless command.stdout.empty? - command.stdout.lines.each do |line| - original_output << "%6s %s" % [level(Logger::DEBUG), - uuid(command) + c.green("\t" + line)] - original_output << "\n" unless line[-1] == "\n" - end - command.stdout = '' + command.clear_stdout_lines.each do |line| + write_command_message(c.green(format_std_stream_line(line)), command, Logger::DEBUG) end - unless command.stderr.empty? - command.stderr.lines.each do |line| - original_output << "%6s %s" % [level(Logger::DEBUG), - uuid(command) + c.red("\t" + line)] - original_output << "\n" unless line[-1] == "\n" - end - command.stderr = '' + command.clear_stderr_lines.each do |line| + write_command_message(c.red(format_std_stream_line(line)), command, Logger::DEBUG) end end if command.finished? - original_output << "%6s %s\n" % [level(command.verbosity), - uuid(command) + "Finished in #{sprintf('%5.3f seconds', command.runtime)} with exit status #{command.exit_status} (#{c.bold { command.failure? ? c.red('failed') : c.green('successful') }})."] + successful_or_failed = c.bold { command.failure? ? c.red('failed') : c.green('successful') } + write_command_message("Finished in #{sprintf('%5.3f seconds', command.runtime)} with exit status #{command.exit_status} (#{successful_or_failed}).", command) end end + def write_command_message(message, command, verbosity_override=nil) + original_output << "%6s [%s] %s\n" % [level(verbosity_override || command.verbosity), c.green(command.uuid), message] + end + def write_log_message(log_message) original_output << "%6s %s\n" % [level(log_message.verbosity), log_message.to_s] end @@ -61,10 +54,6 @@ def c @c ||= Color end - def uuid(obj) - "[#{c.green(obj.uuid)}] " - end - def level(verbosity) c.send(level_formatting(verbosity), level_names(verbosity)) end diff --git a/lib/sshkit/formatters/simple_text.rb b/lib/sshkit/formatters/simple_text.rb index c954406a..5e7d6fd3 100644 --- a/lib/sshkit/formatters/simple_text.rb +++ b/lib/sshkit/formatters/simple_text.rb @@ -27,18 +27,8 @@ def write_command(command) end if SSHKit.config.output_verbosity == Logger::DEBUG - unless command.stdout.empty? - command.stdout.lines.each do |line| - original_output << "\t" + line - original_output << "\n" unless line[-1] == "\n" - end - end - - unless command.stderr.empty? - command.stderr.lines.each do |line| - original_output << "\t" + line - original_output << "\n" unless line[-1] == "\n" - end + (command.clear_stdout_lines + command.clear_stderr_lines).each do |line| + original_output << format_std_stream_line(line) << "\n" end end diff --git a/test/unit/formatters/test_pretty.rb b/test/unit/formatters/test_pretty.rb index e4baa693..c1224eb5 100644 --- a/test/unit/formatters/test_pretty.rb +++ b/test/unit/formatters/test_pretty.rb @@ -23,29 +23,54 @@ def teardown end def test_logging_fatal - pretty << SSHKit::LogMessage.new(Logger::FATAL, "Test") - assert_equal output.strip, "\e[0;31;49mFATAL\e[0m Test" + assert_log("\e[0;31;49mFATAL\e[0m Test\n", Logger::FATAL, "Test") end def test_logging_error - pretty << SSHKit::LogMessage.new(Logger::ERROR, "Test") - assert_equal output.strip, "\e[0;31;49mERROR\e[0m Test" + assert_log("\e[0;31;49mERROR\e[0m Test\n", Logger::ERROR, "Test") end def test_logging_warn - pretty << SSHKit::LogMessage.new(Logger::WARN, "Test") - assert_equal output.strip, "\e[0;33;49mWARN\e[0m Test".strip + assert_log("\e[0;33;49mWARN\e[0m Test\n", Logger::WARN, "Test") end def test_logging_info - pretty << SSHKit::LogMessage.new(Logger::INFO, "Test") - assert_equal output.strip, "\e[0;34;49mINFO\e[0m Test".strip + assert_log("\e[0;34;49mINFO\e[0m Test\n", Logger::INFO, "Test") end def test_logging_debug - pretty << SSHKit::LogMessage.new(Logger::DEBUG, "Test") - assert_equal output.strip, "\e[0;30;49mDEBUG\e[0m Test".strip + assert_log("\e[0;30;49mDEBUG\e[0m Test\n", Logger::DEBUG, "Test") end + def test_command_lifecycle_logging + command = SSHKit::Command.new(:a_cmd, 'some args', host: Host.new('localhost')) + command.stubs(:uuid).returns('aaaaaa') + pretty << command + command.started = true + pretty << command + command.stdout = 'stdout message' + pretty << command + command.stderr = 'stderr message' + pretty << command + command.exit_status = 0 + pretty << command + + expected_log_lines = [ + "\e[0;34;49mINFO\e[0m [\e[0;32;49maaaaaa\e[0m] Running \e[1;33;49m/usr/bin/env a_cmd some args\e[0m on \e[0;34;49mlocalhost\e[0m", + "\e[0;30;49mDEBUG\e[0m [\e[0;32;49maaaaaa\e[0m] Command: \e[0;34;49m/usr/bin/env a_cmd some args\e[0m", + "\e[0;30;49mDEBUG\e[0m [\e[0;32;49maaaaaa\e[0m] \e[0;32;49m\tstdout message\e[0m", + "\e[0;30;49mDEBUG\e[0m [\e[0;32;49maaaaaa\e[0m] \e[0;31;49m\tstderr message\e[0m", + "\e[0;34;49mINFO\e[0m [\e[0;32;49maaaaaa\e[0m] Finished in 0.000 seconds with exit status 0 (\e[1;32;49msuccessful\e[0m)." + ] + assert_equal expected_log_lines, output.split("\n") + end + + private + + def assert_log(expected_output, level, message) + pretty << SSHKit::LogMessage.new(level, message) + assert_equal expected_output, output + end + end end diff --git a/test/unit/formatters/test_simple_text.rb b/test/unit/formatters/test_simple_text.rb new file mode 100644 index 00000000..cb335345 --- /dev/null +++ b/test/unit/formatters/test_simple_text.rb @@ -0,0 +1,77 @@ +require 'helper' +require 'sshkit' + +module SSHKit + class TestSimpleText < UnitTest + + def setup + SSHKit.config.output_verbosity = Logger::DEBUG + end + + def output + @_output ||= String.new + end + + def pretty + @_simple ||= SSHKit::Formatter::SimpleText.new(output) + end + + def teardown + remove_instance_variable :@_simple + remove_instance_variable :@_output + SSHKit.reset_configuration! + end + + def test_logging_fatal + assert_log("Test\n", Logger::FATAL, 'Test') + end + + def test_logging_error + assert_log(output, Logger::ERROR, 'Test') + end + + def test_logging_warn + assert_log(output, Logger::WARN, 'Test') + end + + def test_logging_info + assert_log(output, Logger::INFO, 'Test') + end + + def test_logging_debug + assert_log(output, Logger::DEBUG, 'Test') + end + + def test_command_lifecycle_logging + command = SSHKit::Command.new(:a_cmd, 'some args', host: Host.new('localhost')) + command.stubs(:uuid).returns('aaaaaa') + + pretty << command + command.started = true + pretty << command + command.stdout = 'stdout message' + pretty << command + command.stderr = 'stderr message' + pretty << command + command.exit_status = 0 + pretty << command + + expected_log_lines = [ + 'Running /usr/bin/env a_cmd some args on localhost', + 'Command: /usr/bin/env a_cmd some args', + "\tstdout message", + "\tstderr message", + 'Finished in 0.000 seconds with exit status 0 (successful).' + ] + assert_equal expected_log_lines, output.split("\n") + end + + private + + def assert_log(expected_output, level, message) + pretty << SSHKit::LogMessage.new(level, message) + assert_equal expected_output, output + end + + end +end diff --git a/test/unit/test_command.rb b/test/unit/test_command.rb index 941b62c2..e755f6cf 100644 --- a/test/unit/test_command.rb +++ b/test/unit/test_command.rb @@ -199,5 +199,11 @@ def test_command_raises_command_failed_error_when_non_zero_exit assert_equal "whoami exit status: 1\nwhoami stdout: Nothing written\nwhoami stderr: Nothing written\n", error.message 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 + end + end end