CHEF-173: Now logs output of command immediately

mlandauer · Mar 11, 2009 · ed8b1b0 · ed8b1b0
1 parent c9d4ae7
commit ed8b1b0
Show file tree

Hide file tree

Showing 2 changed files with 22 additions and 13 deletions.
diff --git a/chef/lib/chef/mixin/command.rb b/chef/lib/chef/mixin/command.rb
@@ -117,19 +117,15 @@ def run_command(args={})
           stderr.sync = true
 
           Chef::Log.debug("---- Begin output of #{args[:command]} ----")
-          stdout_string = stdout.gets(nil)
-          if stdout_string
-            stdout_string.split.each do |line|
-              command_output << "STDOUT: #{line.strip}\n"
-              Chef::Log.debug("STDOUT: #{line.strip}")
-            end
-          end          
-          stderr_string = stderr.gets(nil)
-          if stderr_string
-            stderr_string.split.each do |line|
-              command_output << "STDERR: #{line.strip}\n"
-              Chef::Log.debug("STDERR: #{line.strip}")
-            end
+          while !stdout.eof? do
+            line = stdout.gets
+            command_output << "STDOUT: #{line.strip}\n"
+            Chef::Log.debug("STDOUT: #{line.strip}")
+          end
+          while !stderr.eof? do
+            line = stderr.gets
+            command_output << "STDERR: #{line.strip}\n"
+            Chef::Log.debug("STDERR: #{line.strip}")
           end
           Chef::Log.debug("---- End output of #{args[:command]} ----")
         end
@@ -142,6 +138,11 @@ def run_command(args={})
         Chef::Log.debug("Executing #{args[:command]}")
 
         status = nil
+
+        # I don't understand what this :waitlast argument is doing, but setting it to true is causing the block in popen4
+        # not to wait until the command is finished to execute, kind of the opposite of what I would guess from the name
+        args[:waitlast] ||= true
+
         Dir.chdir(args[:cwd]) do
           if args[:timeout]
             begin

diff --git a/chef/spec/unit/mixin/command_spec.rb b/chef/spec/unit/mixin/command_spec.rb
@@ -76,4 +76,12 @@
     Chef::Log.level :info
     lambda {Chef::Mixin::Command.run_command(:command => command)}.should raise_error(Chef::Exception::Exec, "#{command} returned 1, expected 0\n---- Begin output of #{command} ----\nSTDOUT: 1\n---- End output of #{command} ----\n")
   end
+
+  it "should log the output as the command is executing" do
+    command = "ruby -e 'STDOUT.sync = true; puts 1; sleep 2; puts 2'"
+    Chef::Log.should_receive(:debug).with("Executing #{command}").ordered
+    Chef::Log.should_receive(:debug).with("---- Begin output of #{command} ----").ordered
+    Chef::Log.should_receive(:debug).with("STDOUT: 1").ordered
+    lambda {Chef::Mixin::Command.run_command(:command => command, :timeout => 1)}.should raise_error(Timeout::Error)
+  end
 end