Merge pull request #458 from Shopify/master

Debug statements

8 files changed, 23 insertions, 5 deletions

diff --git a/lib/oxidized/core.rb b/lib/oxidized/core.rb
index d57c5cb..e007c9d 100644
--- a/lib/oxidized/core.rb
+++ b/lib/oxidized/core.rb
@@ -31,6 +31,7 @@ module Oxidized
     private
 
     def run
+      Oxidized.logger.debug "lib/oxidized/core.rb: Starting the worker..."
       while true
         @worker.work
         sleep Config::Sleep
diff --git a/lib/oxidized/input/cli.rb b/lib/oxidized/input/cli.rb
index 731b459..fc7f426 100644
--- a/lib/oxidized/input/cli.rb
+++ b/lib/oxidized/input/cli.rb
@@ -17,10 +17,15 @@ module Oxidized
       end
 
       def connect_cli
-        @post_login.each { |command, block| block ? block.call : (cmd command) }
+        Oxidized.logger.debug "lib/oxidized/input/cli.rb: Running post_login commands at #{node.name}"
+        @post_login.each do |command, block|
+          Oxidized.logger.debug "lib/oxidized/input/cli.rb: Running post_login command: #{command.inspect}, block: #{block.inspect} at #{node.name}"
+          block ? block.call : (cmd command)
+        end
       end
 
       def disconnect_cli
+        Oxidized.logger.debug "lib/oxidized/input/cli.rb Running pre_logout commands at #{node.name}"
         @pre_logout.each { |command, block| block ? block.call : (cmd command, nil) }
       end
 
diff --git a/lib/oxidized/input/ssh.rb b/lib/oxidized/input/ssh.rb
index fef20d6..db39a7e 100644
--- a/lib/oxidized/input/ssh.rb
+++ b/lib/oxidized/input/ssh.rb
@@ -37,6 +37,7 @@ module Oxidized
       ssh_opts[:kex] = vars(:ssh_kex).split(/,\s*/) if vars(:ssh_kex)
       ssh_opts[:encryption] = vars(:ssh_encryption).split(/,\s*/) if vars(:ssh_encryption)
 
+      Oxidized.logger.debug "lib/oxidized/input/ssh.rb: Connecting to #{@node.name}"
       @ssh = Net::SSH.start(@node.ip, @node.auth[:username], ssh_opts)
       unless @exec
         shell_open @ssh
@@ -54,7 +55,7 @@ module Oxidized
     end
 
     def cmd cmd, expect=node.prompt
-      Oxidized.logger.debug "SSH: #{cmd} @ #{node.name}"
+      Oxidized.logger.debug "lib/oxidized/input/ssh.rb #{cmd} @ #{node.name} with expect: #{expect.inspect}"
       if @exec
         @ssh.exec! cmd
       else
@@ -123,6 +124,7 @@ module Oxidized
     end
 
     def expect regexp
+      Oxidized.logger.debug "lib/oxidized/input/ssh.rb: expecting #{regexp.inspect} at #{node.name}"
       Timeout::timeout(Oxidized.config.timeout) do
         @ssh.loop(0.1) do
           sleep 0.1
@@ -130,6 +132,5 @@ module Oxidized
         end
       end
     end
-
   end
 end
diff --git a/lib/oxidized/job.rb b/lib/oxidized/job.rb
index 0a4a24b..924cd44 100644
--- a/lib/oxidized/job.rb
+++ b/lib/oxidized/job.rb
@@ -5,9 +5,11 @@ module Oxidized
       @node         = node
       @start        = Time.now.utc
       super do
+        Oxidized.logger.debug "lib/oxidized/job.rb: Starting fetching process for #{@node.name} at #{Time.now.utc}"
         @status, @config = @node.run
         @end             = Time.now.utc
         @time            = @end - @start
+        Oxidized.logger.debug "lib/oxidized/job.rb: Config fetched for #{@node.name} at #{@end}"
       end
     end
   end
diff --git a/lib/oxidized/model/model.rb b/lib/oxidized/model/model.rb
index 9185d43..4a15a45 100644
--- a/lib/oxidized/model/model.rb
+++ b/lib/oxidized/model/model.rb
@@ -35,6 +35,7 @@ module Oxidized
         else
           @cmd[:cmd] << [_cmd, block]
         end
+        Oxidized.logger.debug "lib/oxidized/model/model.rb Added #{_cmd} to the commands list"
       end
       def cmds
         @cmd
@@ -79,6 +80,7 @@ module Oxidized
     attr_accessor :input, :node
 
     def cmd string, &block
+      Oxidized.logger.debug "lib/oxidized/model/model.rb Executing #{string}"
       out = @input.cmd(string)
       return false unless out
       self.class.cmds[:all].each do |all_block|
@@ -127,6 +129,7 @@ module Oxidized
     end
 
     def get
+      Oxidized.logger.debug 'lib/oxidized/model/model.rb Collecting commands\' outputs'
       outputs = Outputs.new
       procs = self.class.procs
       self.class.cmds[:cmd].each do |command, block|
diff --git a/lib/oxidized/node.rb b/lib/oxidized/node.rb
index 35bcad9..cc1e406 100644
--- a/lib/oxidized/node.rb
+++ b/lib/oxidized/node.rb
@@ -38,9 +38,11 @@ module Oxidized
         next unless @model.cfg[cfg_name] and not @model.cfg[cfg_name].empty?
         @model.input = input = input.new
         if config=run_input(input)
+          Oxidized.logger.debug "lib/oxidized/node.rb: #{input.class.name} ran for #{name} successfully"
           status = :success
           break
         else
+          Oxidized.logger.debug "lib/oxidized/node.rb: #{input.class.name} failed for #{name}"
           status = :no_connection
         end
       end
@@ -165,6 +167,7 @@ module Oxidized
     def resolve_model opt
       model = (opt[:model] or Oxidized.config.model)
       if not Oxidized.mgr.model[model]
+        Oxidized.logger.debug "lib/oxidized/node.rb: Loading model #{model.inspect}"
         Oxidized.mgr.add_model model or raise ModelNotFound, "#{model} not found for node #{ip}"
       end
       Oxidized.mgr.model[model].new
diff --git a/lib/oxidized/nodes.rb b/lib/oxidized/nodes.rb
index 61d2d44..cd67007 100644
--- a/lib/oxidized/nodes.rb
+++ b/lib/oxidized/nodes.rb
@@ -11,6 +11,7 @@ module Oxidized
         new = []
         @source = Oxidized.config.source.default
         Oxidized.mgr.add_source @source
+        Oxidized.logger.info "lib/oxidized/nodes.rb: Loading nodes"
         Oxidized.mgr.source[@source].new.load.each do |node|
           # we want to load specific node(s), not all of them
           next unless node_want? node_want, node
@@ -24,7 +25,7 @@ module Oxidized
           end
         end
         size == 0 ? replace(new) : update_nodes(new)
-        Oxidized.logger.info "Loaded #{size} nodes"
+        Oxidized.logger.info "lib/oxidized/nodes.rb: Loaded #{size} nodes"
       end
     end
 
diff --git a/lib/oxidized/worker.rb b/lib/oxidized/worker.rb
index 48852ef..1952d01 100644
--- a/lib/oxidized/worker.rb
+++ b/lib/oxidized/worker.rb
@@ -14,7 +14,7 @@ module Oxidized
       ended.each      { |job| process job }
       @jobs.work
       while @jobs.size < @jobs.want
-        Oxidized.logger.debug "Jobs #{@jobs.size}, Want: #{@jobs.want}"
+        Oxidized.logger.debug "lib/oxidized/worker.rb: Jobs #{@jobs.size}, Want: #{@jobs.want}"
         # ask for next node in queue non destructive way
         nextnode = @nodes.first
         unless nextnode.last.nil?
@@ -26,7 +26,9 @@ module Oxidized
         node = @nodes.get
         node.running? ? next : node.running = true
         @jobs.push Job.new node
+        Oxidized.logger.debug "lib/oxidized/worker.rb: Added #{node.name} to the job queue"
       end
+      Oxidized.logger.debug("lib/oxidized/worker.rb: #{@jobs.size} jobs running in parallel") unless @jobs.empty?
     end
 
     def process job