Merge pull request #458 from Shopify/master

Debug statements

14 files changed, 38 insertions, 18 deletions

diff --git a/.ruby-version b/.ruby-version
new file mode 100644
index 0000000..ebf14b4
--- /dev/null
+++ b/.ruby-version
@@ -0,0 +1 @@
+2.1.8
diff --git a/Gemfile.lock b/Gemfile.lock
index 6be5978..1188627 100644
--- a/Gemfile.lock
+++ b/Gemfile.lock
@@ -1,9 +1,9 @@
 PATH
   remote: .
   specs:
-    oxidized (0.12.2)
+    oxidized (0.14.3)
       asetus (~> 0.1)
-      net-ssh (~> 3.0, >= 3.0.2)
+      net-ssh (>= 3.0.0, < 3.1)
       rugged (~> 0.21, >= 0.21.4)
       slop (~> 3.5)
 
@@ -23,7 +23,7 @@ GEM
       method_source (~> 0.8.1)
       slop (~> 3.4)
     rake (10.4.2)
-    rugged (0.23.3)
+    rugged (0.24.0)
     slop (3.6.0)
 
 PLATFORMS
@@ -38,4 +38,4 @@ DEPENDENCIES
   rake (~> 10.0)
 
 BUNDLED WITH
-   1.11.2
+   1.12.4
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
diff --git a/spec/cli_spec.rb b/spec/cli_spec.rb
index 0a6c91b..eb9872e 100644
--- a/spec/cli_spec.rb
+++ b/spec/cli_spec.rb
@@ -2,23 +2,20 @@ require 'spec_helper'
 require 'oxidized/cli'
 
 describe Oxidized::CLI do
-  let(:asetus) { mock() }
-
-  after  { ARGV.replace @original }
   before { @original = ARGV }
+  after  { ARGV.replace @original }
 
   %w[-v --version].each do |option|
     describe option do
-      before { ARGV.replace [option] }
+      before { ARGV.replace([option]) }
 
       it 'prints the version and exits' do
         Oxidized::Config.expects(:load)
         Oxidized.expects(:setup_logger)
+        File.expects(:expand_path)
         Kernel.expects(:exit)
 
-        proc {
-          Oxidized::CLI.new
-        }.must_output "#{Oxidized::VERSION}\n"
+        assert_output("#{Oxidized::VERSION}\n") { Oxidized::CLI.new }
       end
     end
   end
diff --git a/spec/input/ssh_spec.rb b/spec/input/ssh_spec.rb
index c4210f2..2550d5c 100644
--- a/spec/input/ssh_spec.rb
+++ b/spec/input/ssh_spec.rb
@@ -4,6 +4,7 @@ require 'oxidized/input/ssh'
 describe Oxidized::SSH do
   before(:each) do
     Oxidized.asetus = Asetus.new
+    Oxidized.setup_logger
     Oxidized::Node.any_instance.stubs(:resolve_input)
     Oxidized::Node.any_instance.stubs(:resolve_output)
     @node = Oxidized::Node.new(name: 'example.com',
diff --git a/spec/node_spec.rb b/spec/node_spec.rb
index 21c6e34..1c38558 100644
--- a/spec/node_spec.rb
+++ b/spec/node_spec.rb
@@ -2,7 +2,8 @@ require 'spec_helper'
 
 describe Oxidized::Node do
   before(:each) do
-    Oxidized.stubs(:asetus).returns(Asetus.new)
+    Oxidized.asetus = Asetus.new
+    Oxidized.setup_logger
 
     Oxidized::Node.any_instance.stubs(:resolve_output)
     @node = Oxidized::Node.new(name: 'example.com',
diff --git a/spec/nodes_spec.rb b/spec/nodes_spec.rb
index 5f2ef95..4560bdb 100644
--- a/spec/nodes_spec.rb
+++ b/spec/nodes_spec.rb
@@ -3,7 +3,9 @@ require 'spec_helper'
 describe Oxidized::Nodes do
   before(:each) do
     Resolv.any_instance.stubs(:getaddress)
-    Oxidized.stubs(:asetus).returns(Asetus.new)
+    Oxidized.asetus = Asetus.new
+    Oxidized.setup_logger
+
     opts = {
       input: 'ssh',
       output: 'git',