improved logging all around.

10 files changed, 364 insertions, 130 deletions

diff --git a/lib/leap_cli.rb b/lib/leap_cli.rb
index 5eecf62..9068b4e 100644
--- a/lib/leap_cli.rb
+++ b/lib/leap_cli.rb
@@ -6,6 +6,7 @@ require 'core_ext/hash'
 require 'core_ext/boolean'
 require 'core_ext/nil'
 
+require 'leap_cli/log'
 require 'leap_cli/init'
 require 'leap_cli/path'
 require 'leap_cli/util'
@@ -13,14 +14,25 @@ require 'leap_cli/util/secret'
 require 'leap_cli/util/remote_command'
 require 'leap_cli/util/x509'
 
-require 'leap_cli/log'
+require 'leap_cli/remote/log_streamer'
+require 'leap_cli/logger'
+
 require 'leap_cli/ssh_key'
 require 'leap_cli/config/object'
 require 'leap_cli/config/object_list'
 require 'leap_cli/config/manager'
 
+module LeapCli::Commands; end
+
+module LeapCli
+  Util.send(:extend, LeapCli::Log)
+  Commands.send(:extend, LeapCli::Log)
+  Config::Manager.send(:include, LeapCli::Log)
+  extend LeapCli::Log
+end
+
 #
-# make 1.8 act like ruby 1.9
+# make ruby 1.9 act more like ruby 1.8
 #
 unless String.method_defined?(:to_a)
   class String
diff --git a/lib/leap_cli/commands/deploy.rb b/lib/leap_cli/commands/deploy.rb
index 84c7846..63e6c73 100644
--- a/lib/leap_cli/commands/deploy.rb
+++ b/lib/leap_cli/commands/deploy.rb
@@ -24,9 +24,11 @@ module LeapCli
           ssh.leap.chown_root("/srv/leap")
 
           # sync hiera conf
-          ssh.leap.rsync_update do |server|
-            node = manager.node(server.host)
-            {:source => Path.named_path([:hiera, node.name]), :dest => "/etc/leap/hiera.yaml"}
+          ssh.leap.log :updating, "hiera.yaml" do
+            ssh.leap.rsync_update do |server|
+              node = manager.node(server.host)
+              {:source => Path.named_path([:hiera, node.name]), :dest => "/etc/leap/hiera.yaml"}
+            end
           end
 
           # sync puppet
diff --git a/lib/leap_cli/log.rb b/lib/leap_cli/log.rb
index 0821177..42a886e 100644
--- a/lib/leap_cli/log.rb
+++ b/lib/leap_cli/log.rb
@@ -1,13 +1,20 @@
 require 'paint'
 
+##
+## LOGGING
+##
+
 module LeapCli
   extend self
+
+  # logging options
   def log_level
     @log_level ||= 1
   end
   def log_level=(value)
     @log_level = value
   end
+
   def indent_level
     @indent_level ||= 0
   end
@@ -16,67 +23,71 @@ module LeapCli
   end
 end
 
-##
-## LOGGING
-##
 
-#
-# these are log titles typically associated with files
-#
-FILE_TITLES = [:updated, :created, :removed, :missing, :nochange, :loading]
+module LeapCli
+  module Log
+    #
+    # these are log titles typically associated with files
+    #
+    FILE_TITLES = [:updated, :created, :removed, :missing, :nochange, :loading]
 
-#
-# master logging function.
-#
-# arguments can be a String, Integer, Symbol, or Hash, in any order.
-#
-# * String: treated as the message to log.
-# * Integer: the log level (0, 1, 2)
-# * Symbol: the prefix title to colorize. may be one of
-#   [:error, :warning, :info, :updated, :created, :removed, :no_change, :missing]
-# * Hash: a hash of options. so far, only :indent is supported.
-#
-def log(*args)
-  level   = args.grep(Integer).first || 1
-  title   = args.grep(Symbol).first
-  message = args.grep(String).first
-  options = args.grep(Hash).first || {}
-  options[:indent] ||= LeapCli.indent_level
-  if message && LeapCli.log_level >= level
-    print "  " * (options[:indent]+1)
-    if options[:indent] > 0
-      print '- '
-    else
-      print '= '
-    end
-    if title
-      prefix = case title
-        when :error     then Paint['error', :red, :bold]
-        when :warning   then Paint['warning', :yellow, :bold]
-        when :info      then Paint['info', :cyan, :bold]
-        when :updated   then Paint['updated', :cyan, :bold]
-        when :updating  then Paint['updating', :cyan, :bold]
-        when :created   then Paint['created', :green, :bold]
-        when :removed   then Paint['removed', :red, :bold]
-        when :nochange  then Paint['no change', :magenta]
-        when :loading   then Paint['loading', :magenta]
-        when :missing   then Paint['missing', :yellow, :bold]
-        when :run       then Paint['run', :magenta]
-        when :failed    then Paint['FAILED', :red, :bold]
-        when :ran       then Paint['ran', :green, :bold]
-        when :bail      then Paint['bailing out', :red, :bold]
-        else Paint[title.to_s, :cyan, :bold]
-      end
-      print "#{prefix} "
-      if FILE_TITLES.include?(title) && message =~ /^\//
-        message = LeapCli::Path.relative_path(message)
+
+    #
+    # master logging function.
+    #
+    # arguments can be a String, Integer, Symbol, or Hash, in any order.
+    #
+    # * String: treated as the message to log.
+    # * Integer: the log level (0, 1, 2)
+    # * Symbol: the prefix title to colorize. may be one of
+    #   [:error, :warning, :info, :updated, :created, :removed, :no_change, :missing]
+    # * Hash: a hash of options. so far, only :indent is supported.
+    #
+
+    def log(*args)
+      level   = args.grep(Integer).first || 1
+      title   = args.grep(Symbol).first
+      message = args.grep(String).first
+      options = args.grep(Hash).first || {}
+      options[:indent] ||= LeapCli.indent_level
+      if message && LeapCli.log_level >= level
+        print "  " * (options[:indent]+1)
+        if options[:indent] > 0
+          print '- '
+        else
+          print '= '
+        end
+        if title
+          prefix = case title
+            when :error     then Paint['error', :red, :bold]
+            when :warning   then Paint['warning', :yellow, :bold]
+            when :info      then Paint['info', :cyan, :bold]
+            when :updated   then Paint['updated', :cyan, :bold]
+            when :updating  then Paint['updating', :cyan, :bold]
+            when :created   then Paint['created', :green, :bold]
+            when :removed   then Paint['removed', :red, :bold]
+            when :nochange  then Paint['no change', :magenta]
+            when :loading   then Paint['loading', :magenta]
+            when :missing   then Paint['missing', :yellow, :bold]
+            when :run       then Paint['run', :magenta]
+            when :failed    then Paint['FAILED', :red, :bold]
+            when :completed then Paint['completed', :green, :bold]
+            when :ran       then Paint['ran', :green, :bold]
+            when :bail      then Paint['bailing out', :red, :bold]
+            else Paint[title.to_s, :cyan, :bold]
+          end
+          print "#{prefix} "
+          if FILE_TITLES.include?(title) && message =~ /^\//
+            message = LeapCli::Path.relative_path(message)
+          end
+        end
+        puts "#{message}"
+        if block_given?
+          LeapCli.indent_level += 1
+          yield
+          LeapCli.indent_level -= 1
+        end
       end
     end
-    puts "#{message}"
-    if block_given?
-      LeapCli.indent_level += 1
-      yield
-      LeapCli.indent_level -= 1
-    end
   end
-end
+end
\ No newline at end of file
diff --git a/lib/leap_cli/logger.rb b/lib/leap_cli/logger.rb
new file mode 100644
index 0000000..989a548
--- /dev/null
+++ b/lib/leap_cli/logger.rb
@@ -0,0 +1,157 @@
+#
+# A drop in replacement for Capistrano::Logger that integrates better with LEAP CLI.
+#
+
+require 'capistrano/logger'
+
+#
+# from Capistrano::Logger
+# =========================
+#
+# IMPORTANT = 0
+# INFO      = 1
+# DEBUG     = 2
+# TRACE     = 3
+# MAX_LEVEL = 3
+# COLORS = {
+#   :none     => "0",
+#   :black    => "30",
+#   :red      => "31",
+#   :green    => "32",
+#   :yellow   => "33",
+#   :blue     => "34",
+#   :magenta  => "35",
+#   :cyan     => "36",
+#   :white    => "37"
+# }
+# STYLES = {
+#   :bright     => 1,
+#   :dim        => 2,
+#   :underscore => 4,
+#   :blink      => 5,
+#   :reverse    => 7,
+#   :hidden     => 8
+# }
+#
+
+module LeapCli
+  class Logger < Capistrano::Logger
+
+    def initialize(options={})
+      @options = options
+      @level = options[:level] || 0
+    end
+
+    def log(level, message, line_prefix=nil, options={})
+      # formatting modifies message & line_prefix, so create dups
+      message = message.dup
+      options = options.dup
+      if !line_prefix.nil?
+        if !line_prefix.is_a?(String)
+          line_prefix = line_prefix.to_s.dup
+        else
+          line_prefix = line_prefix.dup
+        end
+      end
+      options[:level] ||= level
+
+      # apply formatting
+      apply_formatting(message, line_prefix, options)
+
+      # print message
+      if options[:level] <= self.level
+        message.lines.each do |line|
+          line = line.strip
+          line_prefix = line_prefix.strip if line_prefix
+          if line.chars.any?
+            if line_prefix
+              LeapCli::log "[#{line_prefix}] #{line}"
+            else
+              LeapCli::log line
+            end
+          end
+        end
+      end
+    end
+
+    private
+
+    ##
+    ## FORMATTING
+    ##
+
+    @formatters = [
+      # TRACE
+      { :match => /command finished/,          :color => :white,   :style => :dim, :match_level => 3, :priority => -10 },
+      { :match => /executing locally/,         :color => :yellow,  :match_level => 3, :priority => -20 },
+
+      # DEBUG
+      #{ :match => /executing .*/,             :color => :green,   :match_level => 2, :priority => -10, :timestamp => true },
+      #{ :match => /.*/,                        :color => :yellow,  :match_level => 2, :priority => -30 },
+      { :match => /^transaction:/,             :level => 3 },
+
+      # INFO
+      { :match => /.*out\] (fatal:|ERROR:).*/, :color => :red,     :match_level => 1, :priority => -10 },
+      { :match => /Permission denied/,         :color => :red,     :match_level => 1, :priority => -20 },
+      { :match => /sh: .+: command not found/, :color => :magenta, :match_level => 1, :priority => -30 },
+
+      # IMPORTANT
+      { :match => /^err ::/,                   :color => :red,     :match_level => 0, :priority => -10 },
+      { :match => /.*/,                        :color => :blue,    :match_level => 0, :priority => -20 },
+
+      # PREFIX CLEANUP
+      { :match => /(err|out) :: /,             :replace => '', :priority => 0},
+
+      # DEBIAN PACKAGES
+      { :match => /^(Hit|Ign) /,                :color => :green,   :priority => -20},
+      { :match => /^Err /,                      :color => :red,     :priority => -20},
+      { :match => /^W: /,                       :color => :yellow,  :priority => -20},
+      { :match => /already the newest version/, :color => :green,   :priority => -20},
+
+      # PUPPPET
+      { :match => /^warning: .*is deprecated.*$/,  :level => 2, :color => :yellow, :priority => -10},
+      { :match => /^notice:/,                      :level => 1, :color => :cyan,   :priority => -20},
+      { :match => /^err:/,                         :level => 0, :color => :red,    :priority => -20},
+      { :match => /^warning:/,                     :level => 0, :color => :yellow, :priority => -20},
+      { :match => /Finished catalog run/,          :level => 0, :color => :green,  :priority => -10},
+    ]
+
+    def apply_formatting(message, line_prefix = nil, options={})
+      color = options[:color] || :none
+      style = options[:style]
+      continue = true
+      self.class.sorted_formatters.each do |formatter|
+        break unless continue
+        if (formatter[:match_level] == level || formatter[:match_level].nil?)
+          [message, line_prefix].compact.each do |str|
+            if str =~ formatter[:match]
+              options[:level] = formatter[:level] if formatter[:level]
+              color = formatter[:color] if formatter[:color]
+              style = formatter[:style] || formatter[:attribute] # (support original cap colors)
+
+              str.gsub!(formatter[:match], formatter[:replace]) if formatter[:replace]
+              str.replace(formatter[:prepend] + str) unless formatter[:prepend].nil?
+              str.replace(str + formatter[:append])  unless formatter[:append].nil?
+              str.replace(Time.now.strftime('%Y-%m-%d %T') + ' ' + str) if formatter[:timestamp]
+
+              # stop formatting, unless formatter was just for string replacement
+              continue = false unless formatter[:replace]
+            end
+          end
+        end
+      end
+
+      return if color == :hide
+      return if color == :none && style.nil?
+
+      term_color = COLORS[color]
+      term_style = STYLES[style]
+      if line_prefix.nil?
+        message.replace format(message, term_color, term_style)
+      else
+        line_prefix.replace format(line_prefix, term_color, term_style)
+      end
+    end
+
+  end
+end
diff --git a/lib/leap_cli/remote/plugin.rb b/lib/leap_cli/remote/plugin.rb
index 6b59727..a69cca4 100644
--- a/lib/leap_cli/remote/plugin.rb
+++ b/lib/leap_cli/remote/plugin.rb
@@ -4,6 +4,10 @@
 
 module LeapCli; module Remote; module Plugin
 
+  def log(*args, &block)
+    LeapCli::Util::log(*args, &block)
+  end
+
   def mkdir(dir)
     run "mkdir -p #{dir}"
   end
@@ -20,8 +24,8 @@ module LeapCli; module Remote; module Plugin
     servers = SupplyDrop::Util.optionally_async(find_servers, puppet_parallel_rsync)
 
     # rsync to each server
-    failed_servers = servers.map do |server|
-
+    failed_servers = []
+    servers.each do |server|
       # build rsync command
       paths       = yield server
       remote_user = server.user || fetch(:user, ENV['USER'])
@@ -33,11 +37,32 @@ module LeapCli; module Remote; module Plugin
 
       # run command
       logger.debug rsync_cmd
-      server.host unless system rsync_cmd
-
-    end.compact
+      ok = system(rsync_cmd)
+      if ok
+        logger.log 1, "rsync #{paths[:source]} #{paths[:dest]}", server.host, :color => :green
+      else
+        failed_servers << server.host
+      end
+    end
 
     raise "rsync failed on #{failed_servers.join(',')}" if failed_servers.any?
   end
 
+  #def logrun(cmd)
+  #  @streamer ||= LeapCli::Remote::LogStreamer.new
+  #  run cmd do |channel, stream, data|
+  #    @streamer.collect_output(channel[:host], data)
+  #  end
+  #end
+
+#    return_code = nil
+#    run "something; echo return code: $?" do |channel, stream, data|
+#      if data =~ /return code: (\d+)/
+#        return_code = $1.to_i
+#      else
+#        Capistrano::Configuration.default_io_proc.call(channel, stream, data)
+#      end
+#    end
+#    puts "finished with return code: #{return_code}"
+
 end; end; end
\ No newline at end of file
diff --git a/lib/leap_cli/remote/tasks.rb b/lib/leap_cli/remote/tasks.rb
index 6bfffb2..4a29517 100644
--- a/lib/leap_cli/remote/tasks.rb
+++ b/lib/leap_cli/remote/tasks.rb
@@ -8,15 +8,21 @@ require 'supply_drop'
 MAX_HOSTS = 10
 
 task :install_authorized_keys, :max_hosts => MAX_HOSTS do
-  run 'mkdir -p /root/.ssh && chmod 700 /root/.ssh'
-  upload LeapCli::Path.named_path(:authorized_keys), '/root/.ssh/authorized_keys', :mode => '600'
+  leap.log :updating, "authorized_keys" do
+    run 'mkdir -p /root/.ssh && chmod 700 /root/.ssh'
+    upload LeapCli::Path.named_path(:authorized_keys), '/root/.ssh/authorized_keys', :mode => '600'
+  end
 end
 
 task :install_prerequisites, :max_hosts => MAX_HOSTS do
   packages = "puppet ruby-hiera-puppet rsync lsb-release"
   run "mkdir -p #{puppet_destination}"
-  run "apt-get update"
-  run "DEBIAN_FRONTEND=noninteractive apt-get -q -y -o DPkg::Options::=--force-confold install #{packages}"
+  leap.log :updating, "package list" do
+    run "apt-get update"
+  end
+  leap.log :installing, "required packages" do
+    run "DEBIAN_FRONTEND=noninteractive apt-get -q -y -o DPkg::Options::=--force-confold install #{packages}"
+  end
 end
 
 #task :update_platform, :max_hosts => MAX_HOSTS do
@@ -29,5 +35,7 @@ end
 
 task :apply_puppet, :max_hosts => MAX_HOSTS do
   raise "now such directory #{puppet_source}" unless File.directory?(puppet_source)
-  puppet.apply
+  leap.log :applying, "puppet" do
+    puppet.apply
+  end
 end
diff --git a/lib/leap_cli/util.rb b/lib/leap_cli/util.rb
index c3adbdc..967acca 100644
--- a/lib/leap_cli/util.rb
+++ b/lib/leap_cli/util.rb
@@ -4,7 +4,6 @@ require 'fileutils'
 require 'erb'
 
 module LeapCli
-
   module Util
     extend self
 
@@ -54,9 +53,13 @@ module LeapCli
     #
     # assert that the command is available
     #
-    def assert_bin!(cmd_name)
+    def assert_bin!(cmd_name, msg=nil)
       assert! `which #{cmd_name}`.strip.any? do
-        log :missing, "command '%s'" % cmd_name
+        log :missing, "command '%s'" % cmd_name do
+          if msg
+            log msg
+          end
+        end
       end
     end
 
diff --git a/lib/leap_cli/util/remote_command.rb b/lib/leap_cli/util/remote_command.rb
index 118a65e..aee4eff 100644
--- a/lib/leap_cli/util/remote_command.rb
+++ b/lib/leap_cli/util/remote_command.rb
@@ -12,7 +12,7 @@ module LeapCli; module Util; module RemoteCommand
     node_list = parse_node_list(nodes)
 
     cap = new_capistrano
-    cap.logger.level = LeapCli.log_level
+    cap.logger = LeapCli::Logger.new(:level => LeapCli.log_level)
     user = options[:user] || 'root'
     cap.set :user, user
     cap.set :ssh_options, ssh_options # ssh options common to all nodes
diff --git a/vendor/supply_drop/lib/supply_drop/writer/colorful_streaming.rb b/vendor/supply_drop/lib/supply_drop/writer/colorful_streaming.rb
new file mode 100644
index 0000000..6abe90d
--- /dev/null
+++ b/vendor/supply_drop/lib/supply_drop/writer/colorful_streaming.rb
@@ -0,0 +1,67 @@
+begin
+  require 'paint'
+rescue
+end
+
+module SupplyDrop
+  module Writer
+    class Streaming
+      def initialize(logger)
+        @mode = Capistrano::Logger::DEBUG
+        @logger = logger
+      end
+
+      def collect_output(host, data)
+        if data =~ /^(notice|err|warning):/
+          @mode = $1
+
+          # make deprecation warnings like notices
+          if data =~ /^warning: .*is deprecated.*$/
+            @mode = 'notice'
+          end
+
+          # force the printing of 'finished catalog run' if there have not been any errors
+          if @mode == 'notice' && !@error_encountered && data =~ /Finished catalog run/
+            @mode = 'forced_notice'
+          elsif @mode == 'err'
+            @error_encountered = true
+          end
+        end
+
+        # log each line, colorizing the hostname
+        data.lines.each do |line|
+          if line =~ /\w/
+            @logger.log log_level, line.sub(/\n$/,''), colorize(host)
+          end
+        end
+      end
+
+      def log_level
+        case @mode
+          when 'err'     then Capistrano::Logger::IMPORTANT
+          when 'warning' then Capistrano::Logger::INFO
+          when 'notice'  then Capistrano::Logger::DEBUG
+          else Capistrano::Logger::IMPORTANT
+        end
+      end
+
+      def colorize(str)
+        if defined? Paint
+          color = case @mode
+            when 'err'     then :red
+            when 'warning' then :yellow
+            when 'notice'  then :cyan
+            when 'forced_notice' then :cyan
+            else :clear
+          end
+          Paint[str, color, :bold]
+        else
+          str
+        end
+      end
+
+      def all_output_collected
+      end
+    end
+  end
+end
diff --git a/vendor/supply_drop/lib/supply_drop/writer/streaming.rb b/vendor/supply_drop/lib/supply_drop/writer/streaming.rb
index 6abe90d..e180ec8 100644
--- a/vendor/supply_drop/lib/supply_drop/writer/streaming.rb
+++ b/vendor/supply_drop/lib/supply_drop/writer/streaming.rb
@@ -1,63 +1,12 @@
-begin
-  require 'paint'
-rescue
-end
-
 module SupplyDrop
   module Writer
     class Streaming
       def initialize(logger)
-        @mode = Capistrano::Logger::DEBUG
         @logger = logger
       end
 
       def collect_output(host, data)
-        if data =~ /^(notice|err|warning):/
-          @mode = $1
-
-          # make deprecation warnings like notices
-          if data =~ /^warning: .*is deprecated.*$/
-            @mode = 'notice'
-          end
-
-          # force the printing of 'finished catalog run' if there have not been any errors
-          if @mode == 'notice' && !@error_encountered && data =~ /Finished catalog run/
-            @mode = 'forced_notice'
-          elsif @mode == 'err'
-            @error_encountered = true
-          end
-        end
-
-        # log each line, colorizing the hostname
-        data.lines.each do |line|
-          if line =~ /\w/
-            @logger.log log_level, line.sub(/\n$/,''), colorize(host)
-          end
-        end
-      end
-
-      def log_level
-        case @mode
-          when 'err'     then Capistrano::Logger::IMPORTANT
-          when 'warning' then Capistrano::Logger::INFO
-          when 'notice'  then Capistrano::Logger::DEBUG
-          else Capistrano::Logger::IMPORTANT
-        end
-      end
-
-      def colorize(str)
-        if defined? Paint
-          color = case @mode
-            when 'err'     then :red
-            when 'warning' then :yellow
-            when 'notice'  then :cyan
-            when 'forced_notice' then :cyan
-            else :clear
-          end
-          Paint[str, color, :bold]
-        else
-          str
-        end
+        @logger.debug data, host
       end
 
       def all_output_collected