Merge pull request #235 from robd/formatter-stdout-stderr-clearing

Remove duplication in clearing command stdout / stderr

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

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

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

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
 

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

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

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