Introduce explicit command logging methods and deprecate stdout / stderr Command attrs

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)
+* [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

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

lib/sshkit/backends/local.rb

@@ -34,33 +34,31 @@ def download!(remote, local=nil, options = {})
       private
 
       def execute_command(cmd)
-        output << cmd
+        output.log_command_start(cmd)
 
         cmd.started = Time.now
 
         Open3.popen3(cmd.to_command) do |stdin, stdout, stderr, wait_thr|
           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
 
           stdout_thread.join
           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
 

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
 

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

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

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
 

lib/sshkit/formatters/black_hole.rb

@@ -7,7 +7,6 @@ class BlackHole < Abstract
       def write(obj)
         # Nothing, nothing to do
       end
-      alias :<< :write
 
     end
 

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
 

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

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