From 61e03af2be631444f24ce2aa847d36245d9473af Mon Sep 17 00:00:00 2001 From: Rob Dupuis Date: Tue, 21 Apr 2015 22:45:04 +0100 Subject: [PATCH 01/10] Add explicit tests for newline behaviour on Pretty formatter --- test/unit/formatters/test_pretty.rb | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/test/unit/formatters/test_pretty.rb b/test/unit/formatters/test_pretty.rb index e4baa693..3f190ace 100644 --- a/test/unit/formatters/test_pretty.rb +++ b/test/unit/formatters/test_pretty.rb @@ -24,27 +24,27 @@ def teardown def test_logging_fatal pretty << SSHKit::LogMessage.new(Logger::FATAL, "Test") - assert_equal output.strip, "\e[0;31;49mFATAL\e[0m Test" + assert_equal output, "\e[0;31;49mFATAL\e[0m Test\n" end def test_logging_error pretty << SSHKit::LogMessage.new(Logger::ERROR, "Test") - assert_equal output.strip, "\e[0;31;49mERROR\e[0m Test" + assert_equal output, "\e[0;31;49mERROR\e[0m Test\n" 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_equal output, "\e[0;33;49mWARN\e[0m Test\n" 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_equal output, "\e[0;34;49mINFO\e[0m Test\n" 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_equal output, "\e[0;30;49mDEBUG\e[0m Test\n" end end From 60df2d9580b6bdfb728f5e62701d0f33839c3d15 Mon Sep 17 00:00:00 2001 From: Rob Dupuis Date: Tue, 21 Apr 2015 22:59:52 +0100 Subject: [PATCH 02/10] Fixed expected / actual ordering --- test/unit/formatters/test_pretty.rb | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/test/unit/formatters/test_pretty.rb b/test/unit/formatters/test_pretty.rb index 3f190ace..331cf4fe 100644 --- a/test/unit/formatters/test_pretty.rb +++ b/test/unit/formatters/test_pretty.rb @@ -24,27 +24,27 @@ def teardown def test_logging_fatal pretty << SSHKit::LogMessage.new(Logger::FATAL, "Test") - assert_equal output, "\e[0;31;49mFATAL\e[0m Test\n" + assert_equal "\e[0;31;49mFATAL\e[0m Test\n", output end def test_logging_error pretty << SSHKit::LogMessage.new(Logger::ERROR, "Test") - assert_equal output, "\e[0;31;49mERROR\e[0m Test\n" + assert_equal "\e[0;31;49mERROR\e[0m Test\n", output end def test_logging_warn pretty << SSHKit::LogMessage.new(Logger::WARN, "Test") - assert_equal output, "\e[0;33;49mWARN\e[0m Test\n" + assert_equal "\e[0;33;49mWARN\e[0m Test\n", output end def test_logging_info pretty << SSHKit::LogMessage.new(Logger::INFO, "Test") - assert_equal output, "\e[0;34;49mINFO\e[0m Test\n" + assert_equal "\e[0;34;49mINFO\e[0m Test\n", output end def test_logging_debug pretty << SSHKit::LogMessage.new(Logger::DEBUG, "Test") - assert_equal output, "\e[0;30;49mDEBUG\e[0m Test\n" + assert_equal "\e[0;30;49mDEBUG\e[0m Test\n", output end end From 9a3c3888985c206bb4380d2c24a628f8b631dda2 Mon Sep 17 00:00:00 2001 From: Rob Dupuis Date: Tue, 21 Apr 2015 23:46:49 +0100 Subject: [PATCH 03/10] Added command lifecycle logging test for pretty formatter Try to protect against duplicate log lines caused by the interaction between the backend, command and formatter --- test/unit/formatters/test_pretty.rb | 29 +++++++++++++++++++++++++++++ 1 file changed, 29 insertions(+) diff --git a/test/unit/formatters/test_pretty.rb b/test/unit/formatters/test_pretty.rb index 331cf4fe..f217f179 100644 --- a/test/unit/formatters/test_pretty.rb +++ b/test/unit/formatters/test_pretty.rb @@ -47,5 +47,34 @@ def test_logging_debug assert_equal "\e[0;30;49mDEBUG\e[0m Test\n", output end + def test_command_lifecycle_logging + command = fixed_uid_command('aaaaaa', :a_cmd, 'some args', 'localhost') + 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 fixed_uid_command(constant_uuid, *args, host) + command = SSHKit::Command.new(*args, host: Host.new(host)) + command.stubs(:uuid).returns(constant_uuid) + command + end end end From c13b10b76a03893872f11ddda483d07583b21665 Mon Sep 17 00:00:00 2001 From: Rob Dupuis Date: Wed, 22 Apr 2015 00:08:50 +0100 Subject: [PATCH 04/10] Added failing test for the SimpleText formatter MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit I believe issue #224 also affects the SimpleText formatter. I’ve added a failing test (test_command_lifecycle_logging) to expose the problem. --- test/unit/formatters/test_simple_text.rb | 77 ++++++++++++++++++++++++ 1 file changed, 77 insertions(+) create mode 100644 test/unit/formatters/test_simple_text.rb 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 From cb06ab2744daa4d249c40586903cd736d1ab0ca5 Mon Sep 17 00:00:00 2001 From: Rob Dupuis Date: Wed, 22 Apr 2015 00:35:12 +0100 Subject: [PATCH 05/10] Fix for duplicate messages from the SimpleText formatter (#224) --- lib/sshkit/formatters/simple_text.rb | 2 ++ 1 file changed, 2 insertions(+) diff --git a/lib/sshkit/formatters/simple_text.rb b/lib/sshkit/formatters/simple_text.rb index c954406a..f7e95641 100644 --- a/lib/sshkit/formatters/simple_text.rb +++ b/lib/sshkit/formatters/simple_text.rb @@ -32,6 +32,7 @@ def write_command(command) original_output << "\t" + line original_output << "\n" unless line[-1] == "\n" end + command.stdout = '' end unless command.stderr.empty? @@ -39,6 +40,7 @@ def write_command(command) original_output << "\t" + line original_output << "\n" unless line[-1] == "\n" end + command.stderr = '' end end From e4f6ca2eeaf179a39ee0f5c29d6f03b9baece0cf Mon Sep 17 00:00:00 2001 From: Rob Dupuis Date: Wed, 22 Apr 2015 00:37:27 +0100 Subject: [PATCH 06/10] Made TestPretty formatter test asserts consistent with TestSimpleText --- test/unit/formatters/test_pretty.rb | 26 +++++++++++--------------- 1 file changed, 11 insertions(+), 15 deletions(-) diff --git a/test/unit/formatters/test_pretty.rb b/test/unit/formatters/test_pretty.rb index f217f179..c1224eb5 100644 --- a/test/unit/formatters/test_pretty.rb +++ b/test/unit/formatters/test_pretty.rb @@ -23,32 +23,28 @@ def teardown end def test_logging_fatal - pretty << SSHKit::LogMessage.new(Logger::FATAL, "Test") - assert_equal "\e[0;31;49mFATAL\e[0m Test\n", output + 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 "\e[0;31;49mERROR\e[0m Test\n", output + 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 "\e[0;33;49mWARN\e[0m Test\n", output + 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 "\e[0;34;49mINFO\e[0m Test\n", output + 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 "\e[0;30;49mDEBUG\e[0m Test\n", output + assert_log("\e[0;30;49mDEBUG\e[0m Test\n", Logger::DEBUG, "Test") end def test_command_lifecycle_logging - command = fixed_uid_command('aaaaaa', :a_cmd, 'some args', 'localhost') + command = SSHKit::Command.new(:a_cmd, 'some args', host: Host.new('localhost')) + command.stubs(:uuid).returns('aaaaaa') pretty << command command.started = true pretty << command @@ -71,10 +67,10 @@ def test_command_lifecycle_logging private - def fixed_uid_command(constant_uuid, *args, host) - command = SSHKit::Command.new(*args, host: Host.new(host)) - command.stubs(:uuid).returns(constant_uuid) - command + def assert_log(expected_output, level, message) + pretty << SSHKit::LogMessage.new(level, message) + assert_equal expected_output, output end + end end From cd3cdad1a14f20d265c7d58acfb4238643d63440 Mon Sep 17 00:00:00 2001 From: Rob Dupuis Date: Wed, 22 Apr 2015 01:08:41 +0100 Subject: [PATCH 07/10] Introduced clear_stdout_lines and clear_stderr_lines on Command This commit removes duplication in the SimpleText and Pretty formatters by better encapsulating the logic to split and clear stdout/stderr buffers on the Command object. --- lib/sshkit/command.rb | 8 ++++++++ lib/sshkit/formatters/pretty.rb | 22 ++++++++-------------- lib/sshkit/formatters/simple_text.rb | 18 ++++++------------ test/unit/test_command.rb | 6 ++++++ 4 files changed, 28 insertions(+), 26 deletions(-) diff --git a/lib/sshkit/command.rb b/lib/sshkit/command.rb index b7f33041..410ec48d 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 + @stdout.lines.tap { @stdout.clear } + end + + def clear_stderr_lines + @stderr.lines.tap { @stderr.clear } + end + def exit_status=(new_exit_status) @finished_at = Time.now @exit_status = new_exit_status diff --git a/lib/sshkit/formatters/pretty.rb b/lib/sshkit/formatters/pretty.rb index 3e6958d7..842f41cc 100644 --- a/lib/sshkit/formatters/pretty.rb +++ b/lib/sshkit/formatters/pretty.rb @@ -28,22 +28,16 @@ def write_command(command) 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| + original_output << "%6s %s" % [level(Logger::DEBUG), + uuid(command) + c.green("\t" + line)] + original_output << "\n" unless line[-1] == "\n" 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| + original_output << "%6s %s" % [level(Logger::DEBUG), + uuid(command) + c.red("\t" + line)] + original_output << "\n" unless line[-1] == "\n" end end diff --git a/lib/sshkit/formatters/simple_text.rb b/lib/sshkit/formatters/simple_text.rb index f7e95641..95346bea 100644 --- a/lib/sshkit/formatters/simple_text.rb +++ b/lib/sshkit/formatters/simple_text.rb @@ -27,20 +27,14 @@ 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 - command.stdout = '' + command.clear_stdout_lines.each do |line| + original_output << "\t" + line + original_output << "\n" unless line[-1] == "\n" end - unless command.stderr.empty? - command.stderr.lines.each do |line| - original_output << "\t" + line - original_output << "\n" unless line[-1] == "\n" - end - command.stderr = '' + command.clear_stderr_lines.each do |line| + original_output << "\t" + line + original_output << "\n" unless line[-1] == "\n" 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 From 6bdc94566e08aac210b0ac356f500e2b07b2256b Mon Sep 17 00:00:00 2001 From: Rob Dupuis Date: Wed, 22 Apr 2015 02:04:41 +0100 Subject: [PATCH 08/10] Introduced format_std_stream_line() on Abstract formatter Factored out duplicated logic from SimpleText and Pretty formatters for formatting a log line from one of the standard streams (ie stdout/stderr). --- lib/sshkit/formatters/abstract.rb | 5 +++++ lib/sshkit/formatters/pretty.rb | 8 ++------ lib/sshkit/formatters/simple_text.rb | 10 ++-------- 3 files changed, 9 insertions(+), 14 deletions(-) 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 842f41cc..9653f269 100644 --- a/lib/sshkit/formatters/pretty.rb +++ b/lib/sshkit/formatters/pretty.rb @@ -29,15 +29,11 @@ def write_command(command) if SSHKit.config.output_verbosity == Logger::DEBUG command.clear_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" + original_output << "%6s %s\n" % [level(Logger::DEBUG), uuid(command) + c.green(format_std_stream_line(line))] end command.clear_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" + original_output << "%6s %s\n" % [level(Logger::DEBUG), uuid(command) + c.red(format_std_stream_line(line))] end end diff --git a/lib/sshkit/formatters/simple_text.rb b/lib/sshkit/formatters/simple_text.rb index 95346bea..5e7d6fd3 100644 --- a/lib/sshkit/formatters/simple_text.rb +++ b/lib/sshkit/formatters/simple_text.rb @@ -27,14 +27,8 @@ def write_command(command) end if SSHKit.config.output_verbosity == Logger::DEBUG - command.clear_stdout_lines.each do |line| - original_output << "\t" + line - original_output << "\n" unless line[-1] == "\n" - end - - command.clear_stderr_lines.each do |line| - original_output << "\t" + line - original_output << "\n" unless line[-1] == "\n" + (command.clear_stdout_lines + command.clear_stderr_lines).each do |line| + original_output << format_std_stream_line(line) << "\n" end end From c9de10d38f5ddb81e8bdbacf58ac4e5094277d03 Mon Sep 17 00:00:00 2001 From: Rob Dupuis Date: Wed, 22 Apr 2015 02:30:17 +0100 Subject: [PATCH 09/10] Introduced write_command_message method on PrettyFormatter --- lib/sshkit/formatters/pretty.rb | 23 +++++++++++------------ 1 file changed, 11 insertions(+), 12 deletions(-) diff --git a/lib/sshkit/formatters/pretty.rb b/lib/sshkit/formatters/pretty.rb index 9653f269..c2de0291 100644 --- a/lib/sshkit/formatters/pretty.rb +++ b/lib/sshkit/formatters/pretty.rb @@ -19,30 +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 command.clear_stdout_lines.each do |line| - original_output << "%6s %s\n" % [level(Logger::DEBUG), uuid(command) + c.green(format_std_stream_line(line))] + write_command_message(c.green(format_std_stream_line(line)), command, Logger::DEBUG) end command.clear_stderr_lines.each do |line| - original_output << "%6s %s\n" % [level(Logger::DEBUG), uuid(command) + c.red(format_std_stream_line(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 @@ -51,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 From af6390432dc7da44afc166f8701ccd048323dec5 Mon Sep 17 00:00:00 2001 From: Rob Dupuis Date: Wed, 22 Apr 2015 11:46:19 +0100 Subject: [PATCH 10/10] Fixed ruby 1.9 compatibility string.lines returns array in ruby 2, but enumerable in 1.9. Convert the enumarable to array - can remove this when we stop supporting ruby 1.9. --- lib/sshkit/command.rb | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/lib/sshkit/command.rb b/lib/sshkit/command.rb index 410ec48d..70de4ce3 100644 --- a/lib/sshkit/command.rb +++ b/lib/sshkit/command.rb @@ -84,11 +84,11 @@ def failure? alias :failed? :failure? def clear_stdout_lines - @stdout.lines.tap { @stdout.clear } + split_and_clear_stream(@stdout) end def clear_stderr_lines - @stderr.lines.tap { @stderr.clear } + split_and_clear_stream(@stderr) end def exit_status=(new_exit_status) @@ -235,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