(#7127) Stop puppet if a prerun command fails

Before this change there were several problems with pre and post run
commands, logging, and sending of reports.

1. If a prerun command failed, puppet would attempt to apply the
catalog. Now puppet will not apply the catalog, but it will run the
postrun command and send the report (as it did before).

2. If a postrun command failed, puppet would not send the report. Sending the
report is now in an outer ensure block from the postrun command, so
postrun failures won't prevent the report from being sent.

3. Errors, e.g. Puppet.err, occuring during the prepare step, which
which includes plugin/fact download and prerun commands were not
appended to the report. Now the report log destination is registered as
early as possible, and unregistered as late as possible to ensure
Configurer errors that occur in the run method are included in the report.

4. The transaction was closing the Configurer's report destination out
from underneath it. As a result, postrun errors were not included in the
report.

Paired-with: Nick Lewis <nick@puppetlabs.com>
Reviewed-by: Jacob Helwig <jacob@puppetlabs.com>

7 files changed, 198 insertions, 121 deletions

diff --git a/lib/puppet/application/apply.rb b/lib/puppet/application/apply.rb
index 717935640..f2bbcb99b 100644
--- a/lib/puppet/application/apply.rb
+++ b/lib/puppet/application/apply.rb
@@ -130,7 +130,13 @@ class Puppet::Application::Apply < Puppet::Application
       configurer = Puppet::Configurer.new
       report = configurer.run(:skip_plugin_download => true, :catalog => catalog)
 
-      exit( options[:detailed_exitcodes] ? report.exit_status : 0 )
+      if not report
+        exit(1)
+      elsif options[:detailed_exitcodes] then
+        exit(report.exit_status)
+      else
+        exit(0)
+      end
     rescue => detail
       puts detail.backtrace if Puppet[:trace]
       $stderr.puts detail.message
diff --git a/lib/puppet/configurer.rb b/lib/puppet/configurer.rb
index 596d2dc53..7f39a3853 100644
--- a/lib/puppet/configurer.rb
+++ b/lib/puppet/configurer.rb
@@ -5,8 +5,6 @@ require 'puppet/network/http_pool'
 require 'puppet/util'
 
 class Puppet::Configurer
-  class CommandHookError < RuntimeError; end
-
   require 'puppet/configurer/fact_handler'
   require 'puppet/configurer/plugin_handler'
 
@@ -79,8 +77,6 @@ class Puppet::Configurer
     download_plugins unless options[:skip_plugin_download]
 
     download_fact_plugins unless options[:skip_plugin_download]
-
-    execute_prerun_command
   end
 
   # Get the remote catalog, yo.  Returns nil if no catalog can be found.
@@ -109,67 +105,73 @@ class Puppet::Configurer
     catalog
   end
 
-  # The code that actually runs the catalog.
-  # This just passes any options on to the catalog,
-  # which accepts :tags and :ignoreschedules.
-  def run(options = {})
-    begin
-      prepare(options)
-    rescue SystemExit,NoMemoryError
-      raise
-    rescue Exception => detail
-      puts detail.backtrace if Puppet[:trace]
-      Puppet.err "Failed to prepare catalog: #{detail}"
+  # Retrieve (optionally) and apply a catalog. If a catalog is passed in
+  # the options, then apply that one, otherwise retrieve it.
+  def retrieve_and_apply_catalog(options, fact_options)
+    unless catalog = (options.delete(:catalog) || retrieve_catalog(fact_options))
+      Puppet.err "Could not retrieve catalog; skipping run"
+      return
     end
 
-    if Puppet::Resource::Catalog.indirection.terminus_class == :rest
-      # This is a bit complicated.  We need the serialized and escaped facts,
-      # and we need to know which format they're encoded in.  Thus, we
-      # get a hash with both of these pieces of information.
-      fact_options = facts_for_uploading
+    report = options[:report]
+    report.configuration_version = catalog.version
+
+    benchmark(:notice, "Finished catalog run") do
+      catalog.apply(options)
     end
 
+    report.finalize_report
+    report
+  end
+
+  # The code that actually runs the catalog.
+  # This just passes any options on to the catalog,
+  # which accepts :tags and :ignoreschedules.
+  def run(options = {})
     options[:report] ||= Puppet::Transaction::Report.new("apply")
     report = options[:report]
-    Puppet::Util::Log.newdestination(report)
 
-    if catalog = options[:catalog]
-      options.delete(:catalog)
-    elsif ! catalog = retrieve_catalog(fact_options)
-      Puppet.err "Could not retrieve catalog; skipping run"
-      return
-    end
+    Puppet::Util::Log.newdestination(report)
+    begin
+      prepare(options)
 
-    report.configuration_version = catalog.version
+      if Puppet::Resource::Catalog.indirection.terminus_class == :rest
+        # This is a bit complicated.  We need the serialized and escaped facts,
+        # and we need to know which format they're encoded in.  Thus, we
+        # get a hash with both of these pieces of information.
+        fact_options = facts_for_uploading
+      end
 
-    transaction = nil
+      # set report host name now that we have the fact
+      report.host = Puppet[:node_name_value]
 
-    begin
-      benchmark(:notice, "Finished catalog run") do
-        transaction = catalog.apply(options)
+      begin
+        execute_prerun_command or return nil
+        retrieve_and_apply_catalog(options, fact_options)
+      rescue SystemExit,NoMemoryError
+        raise
+      rescue => detail
+        puts detail.backtrace if Puppet[:trace]
+        Puppet.err "Failed to apply catalog: #{detail}"
+        return nil
+      ensure
+        execute_postrun_command or return nil
       end
-      report
-    rescue => detail
-      puts detail.backtrace if Puppet[:trace]
-      Puppet.err "Failed to apply catalog: #{detail}"
-      return
+    ensure
+      # Make sure we forget the retained module_directories of any autoload
+      # we might have used.
+      Thread.current[:env_module_directories] = nil
+
+      # Now close all of our existing http connections, since there's no
+      # reason to leave them lying open.
+      Puppet::Network::HttpPool.clear_http_instances
     end
   ensure
-    # Make sure we forget the retained module_directories of any autoload
-    # we might have used.
-    Thread.current[:env_module_directories] = nil
-
-    # Now close all of our existing http connections, since there's no
-    # reason to leave them lying open.
-    Puppet::Network::HttpPool.clear_http_instances
-    execute_postrun_command
-
     Puppet::Util::Log.close(report)
-    send_report(report, transaction)
+    send_report(report)
   end
 
-  def send_report(report, trans)
-    report.finalize_report if trans
+  def send_report(report)
     puts report.summary if Puppet[:summarize]
     save_last_run_summary(report)
     report.save if Puppet[:report]
@@ -207,12 +209,15 @@ class Puppet::Configurer
   end
 
   def execute_from_setting(setting)
-    return if (command = Puppet[setting]) == ""
+    return true if (command = Puppet[setting]) == ""
 
     begin
       Puppet::Util.execute([command])
+      true
     rescue => detail
-      raise CommandHookError, "Could not run command from #{setting}: #{detail}"
+      puts detail.backtrace if Puppet[:trace]
+      Puppet.err "Could not run command from #{setting}: #{detail}"
+      false
     end
   end
 
diff --git a/lib/puppet/resource/catalog.rb b/lib/puppet/resource/catalog.rb
index 8d4918bbf..0a63ff172 100644
--- a/lib/puppet/resource/catalog.rb
+++ b/lib/puppet/resource/catalog.rb
@@ -132,7 +132,9 @@ class Puppet::Resource::Catalog < Puppet::SimpleGraph
     expire
 
     Puppet::Util::Storage.load if host_config?
+
     transaction = Puppet::Transaction.new(self, options[:report])
+    register_report = options[:report].nil?
 
     transaction.tags = options[:tags] if options[:tags]
     transaction.ignoreschedules = true if options[:ignoreschedules]
@@ -140,7 +142,12 @@ class Puppet::Resource::Catalog < Puppet::SimpleGraph
     transaction.add_times :config_retrieval => self.retrieval_duration || 0
 
     begin
-      transaction.evaluate
+      Puppet::Util::Log.newdestination(transaction.report) if register_report
+      begin
+        transaction.evaluate
+      ensure
+        Puppet::Util::Log.close(transaction.report) if register_report
+      end
     rescue Puppet::Error => detail
       puts detail.backtrace if Puppet[:trace]
       Puppet.err "Could not apply complete catalog: #{detail}"
diff --git a/lib/puppet/transaction.rb b/lib/puppet/transaction.rb
index 16f201ec5..d6d50d410 100644
--- a/lib/puppet/transaction.rb
+++ b/lib/puppet/transaction.rb
@@ -123,31 +123,23 @@ class Puppet::Transaction
   # collects all of the changes, executes them, and responds to any
   # necessary events.
   def evaluate
-    # Start logging.
-    Puppet::Util::Log.newdestination(@report)
-
     prepare
 
     Puppet.info "Applying configuration version '#{catalog.version}'" if catalog.version
 
-    begin
-      @sorted_resources.each do |resource|
-        next if stop_processing?
-        if resource.is_a?(Puppet::Type::Component)
-          Puppet.warning "Somehow left a component in the relationship graph"
-          next
-        end
-        ret = nil
-        seconds = thinmark do
-          ret = eval_resource(resource)
-        end
-
-        resource.info "Evaluated in %0.2f seconds" % seconds if Puppet[:evaltrace] and @catalog.host_config?
-        ret
+    @sorted_resources.each do |resource|
+      next if stop_processing?
+      if resource.is_a?(Puppet::Type::Component)
+        Puppet.warning "Somehow left a component in the relationship graph"
+        next
+      end
+      ret = nil
+      seconds = thinmark do
+        ret = eval_resource(resource)
       end
-    ensure
-      # And then close the transaction log.
-      Puppet::Util::Log.close(@report)
+
+      resource.info "valuated in %0.2f seconds" % seconds if Puppet[:evaltrace] and @catalog.host_config?
+      ret
     end
 
     Puppet.debug "Finishing transaction #{object_id}"
diff --git a/lib/puppet/transaction/report.rb b/lib/puppet/transaction/report.rb
index 841c56968..77b9da833 100644
--- a/lib/puppet/transaction/report.rb
+++ b/lib/puppet/transaction/report.rb
@@ -10,8 +10,8 @@ class Puppet::Transaction::Report
 
   indirects :report, :terminus_class => :processor
 
-  attr_accessor :configuration_version
-  attr_reader :resource_statuses, :logs, :metrics, :host, :time, :kind, :status
+  attr_accessor :configuration_version, :host
+  attr_reader :resource_statuses, :logs, :metrics, :time, :kind, :status
 
   # This is necessary since Marshall doesn't know how to
   # dump hash with default proc (see below @records)
diff --git a/spec/unit/configurer_spec.rb b/spec/unit/configurer_spec.rb
index b825e3404..f96876b58 100755
--- a/spec/unit/configurer_spec.rb
+++ b/spec/unit/configurer_spec.rb
@@ -36,16 +36,16 @@ describe Puppet::Configurer do
 
     it "should execute any pre-run command provided via the 'prerun_command' setting" do
       Puppet.settings[:prerun_command] = "/my/command"
-      Puppet::Util.expects(:execute).with { |args| args[0] == "/my/command" }
+      Puppet::Util.expects(:execute).with(["/my/command"]).raises(Puppet::ExecutionFailure, "Failed")
 
       @agent.execute_prerun_command
     end
 
     it "should fail if the command fails" do
       Puppet.settings[:prerun_command] = "/my/command"
-      Puppet::Util.expects(:execute).raises Puppet::ExecutionFailure
+      Puppet::Util.expects(:execute).with(["/my/command"]).raises(Puppet::ExecutionFailure, "Failed")
 
-      lambda { @agent.execute_prerun_command }.should raise_error(Puppet::Configurer::CommandHookError)
+      @agent.execute_prerun_command.should be_false
     end
   end
 
@@ -59,16 +59,16 @@ describe Puppet::Configurer do
 
     it "should execute any post-run command provided via the 'postrun_command' setting" do
       Puppet.settings[:postrun_command] = "/my/command"
-      Puppet::Util.expects(:execute).with { |args| args[0] == "/my/command" }
+      Puppet::Util.expects(:execute).with(["/my/command"]).raises(Puppet::ExecutionFailure, "Failed")
 
       @agent.execute_postrun_command
     end
 
     it "should fail if the command fails" do
       Puppet.settings[:postrun_command] = "/my/command"
-      Puppet::Util.expects(:execute).raises Puppet::ExecutionFailure
+      Puppet::Util.expects(:execute).with(["/my/command"]).raises(Puppet::ExecutionFailure, "Failed")
 
-      lambda { @agent.execute_postrun_command }.should raise_error(Puppet::Configurer::CommandHookError)
+      @agent.execute_postrun_command.should be_false
     end
   end
 
@@ -85,8 +85,8 @@ describe Puppet::Configurer do
       Puppet::Resource::Catalog.terminus_class = :rest
       Puppet::Resource::Catalog.stubs(:find).returns(@catalog)
       @agent.stubs(:send_report)
+      @agent.stubs(:save_last_run_summary)
 
-      Puppet::Util::Log.stubs(:newdestination)
       Puppet::Util::Log.stubs(:close)
     end
 
@@ -98,7 +98,7 @@ describe Puppet::Configurer do
 
     it "should initialize a transaction report if one is not provided" do
       report = Puppet::Transaction::Report.new("apply")
-      Puppet::Transaction::Report.expects(:new).at_least_once.returns report
+      Puppet::Transaction::Report.expects(:new).returns report
 
       @agent.run
     end
@@ -128,9 +128,11 @@ describe Puppet::Configurer do
 
     it "should set the report as a log destination" do
       report = Puppet::Transaction::Report.new("apply")
-      Puppet::Transaction::Report.expects(:new).at_least_once.returns report
+      Puppet::Transaction::Report.expects(:new).returns report
 
       Puppet::Util::Log.expects(:newdestination).with(report)
+      Puppet::Util::Log.expects(:close).with(report)
+      Puppet::Util::Log.expects(:close).with([])
 
       @agent.run
     end
@@ -180,22 +182,10 @@ describe Puppet::Configurer do
 
     it "should send the report" do
       report = Puppet::Transaction::Report.new("apply")
-      Puppet::Transaction::Report.expects(:new).at_least_once.returns(report)
-      @agent.expects(:send_report).with { |r, trans| r == report }
-
-      @agent.run
-    end
-
-    it "should send the transaction report with a reference to the transaction if a run was actually made" do
-      report = Puppet::Transaction::Report.new("apply")
       Puppet::Transaction::Report.expects(:new).returns(report)
+      @agent.expects(:send_report).with(report)
 
-      trans = stub 'transaction'
-      @catalog.expects(:apply).returns trans
-
-      @agent.expects(:send_report).with { |r, t| t == trans }
-
-      @agent.run :catalog => @catalog
+      @agent.run
     end
 
     it "should send the transaction report even if the catalog could not be retrieved" do
@@ -215,12 +205,12 @@ describe Puppet::Configurer do
       Puppet::Transaction::Report.expects(:new).returns(report)
       @agent.expects(:send_report)
 
-      lambda { @agent.run }.should raise_error
+      @agent.run.should be_nil
     end
 
     it "should remove the report as a log destination when the run is finished" do
       report = Puppet::Transaction::Report.new("apply")
-      Puppet::Transaction::Report.expects(:new).at_least_once.returns(report)
+      Puppet::Transaction::Report.expects(:new).returns(report)
 
       Puppet::Util::Log.expects(:close).with(report)
 
@@ -229,11 +219,100 @@ describe Puppet::Configurer do
 
     it "should return the report as the result of the run" do
       report = Puppet::Transaction::Report.new("apply")
-      Puppet::Transaction::Report.expects(:new).at_least_once.returns(report)
+      Puppet::Transaction::Report.expects(:new).returns(report)
 
       @agent.run.should equal(report)
     end
 
+    it "should send the transaction report even if the pre-run command fails" do
+      report = Puppet::Transaction::Report.new("apply")
+      Puppet::Transaction::Report.expects(:new).returns(report)
+
+      Puppet.settings[:prerun_command] = "/my/command"
+      Puppet::Util.expects(:execute).with(["/my/command"]).raises(Puppet::ExecutionFailure, "Failed")
+      @agent.expects(:send_report)
+
+      @agent.run.should be_nil
+    end
+
+    it "should include the pre-run command failure in the report" do
+      report = Puppet::Transaction::Report.new("apply")
+      Puppet::Transaction::Report.expects(:new).returns(report)
+
+      Puppet.settings[:prerun_command] = "/my/command"
+      Puppet::Util.expects(:execute).with(["/my/command"]).raises(Puppet::ExecutionFailure, "Failed")
+
+      report.expects(:<<).with { |log| log.message.start_with?("Could not run command from prerun_command") }
+
+      @agent.run.should be_nil
+    end
+
+    it "should send the transaction report even if the post-run command fails" do
+      report = Puppet::Transaction::Report.new("apply")
+      Puppet::Transaction::Report.expects(:new).returns(report)
+
+      Puppet.settings[:postrun_command] = "/my/command"
+      Puppet::Util.expects(:execute).with(["/my/command"]).raises(Puppet::ExecutionFailure, "Failed")
+      @agent.expects(:send_report)
+
+      @agent.run.should be_nil
+    end
+
+    it "should include the post-run command failure in the report" do
+      report = Puppet::Transaction::Report.new("apply")
+      Puppet::Transaction::Report.expects(:new).returns(report)
+
+      Puppet.settings[:postrun_command] = "/my/command"
+      Puppet::Util.expects(:execute).with(["/my/command"]).raises(Puppet::ExecutionFailure, "Failed")
+
+      report.expects(:<<).with { |log| log.message.start_with?("Could not run command from postrun_command") }
+
+      @agent.run.should be_nil
+    end
+
+    it "should execute post-run command even if the pre-run command fails" do
+      Puppet.settings[:prerun_command] = "/my/precommand"
+      Puppet.settings[:postrun_command] = "/my/postcommand"
+      Puppet::Util.expects(:execute).with(["/my/precommand"]).raises(Puppet::ExecutionFailure, "Failed")
+      Puppet::Util.expects(:execute).with(["/my/postcommand"])
+
+      @agent.run.should be_nil
+    end
+
+    it "should finalize the report" do
+      report = Puppet::Transaction::Report.new("apply")
+      Puppet::Transaction::Report.expects(:new).returns(report)
+
+      report.expects(:finalize_report)
+      @agent.run
+    end
+
+    it "should not apply the catalog if the pre-run command fails" do
+      report = Puppet::Transaction::Report.new("apply")
+      Puppet::Transaction::Report.expects(:new).returns(report)
+
+      Puppet.settings[:prerun_command] = "/my/command"
+      Puppet::Util.expects(:execute).with(["/my/command"]).raises(Puppet::ExecutionFailure, "Failed")
+
+      @catalog.expects(:apply).never()
+      @agent.expects(:send_report)
+
+      @agent.run.should be_nil
+    end
+
+    it "should apply the catalog, send the report, and return nil if the post-run command fails" do
+      report = Puppet::Transaction::Report.new("apply")
+      Puppet::Transaction::Report.expects(:new).returns(report)
+
+      Puppet.settings[:postrun_command] = "/my/command"
+      Puppet::Util.expects(:execute).with(["/my/command"]).raises(Puppet::ExecutionFailure, "Failed")
+
+      @catalog.expects(:apply)
+      @agent.expects(:send_report)
+
+      @agent.run.should be_nil
+    end
+
     describe "when not using a REST terminus for catalogs" do
       it "should not pass any facts when retrieving the catalog" do
         Puppet::Resource::Catalog.terminus_class = :compiler
@@ -268,12 +347,6 @@ describe Puppet::Configurer do
       Puppet[:lastrunfile] = tmpfile('last_run_file')
 
       @report = Puppet::Transaction::Report.new("apply")
-      @trans = stub 'transaction'
-    end
-
-    it "should finalize the report" do
-      @report.expects(:finalize_report)
-      @configurer.send_report(@report, @trans)
     end
 
     it "should print a report summary if configured to do so" do
@@ -282,42 +355,42 @@ describe Puppet::Configurer do
       @report.expects(:summary).returns "stuff"
 
       @configurer.expects(:puts).with("stuff")
-      @configurer.send_report(@report, nil)
+      @configurer.send_report(@report)
     end
 
     it "should not print a report summary if not configured to do so" do
       Puppet.settings[:summarize] = false
 
       @configurer.expects(:puts).never
-      @configurer.send_report(@report, nil)
+      @configurer.send_report(@report)
     end
 
     it "should save the report if reporting is enabled" do
       Puppet.settings[:report] = true
 
       @report.expects(:save)
-      @configurer.send_report(@report, nil)
+      @configurer.send_report(@report)
     end
 
     it "should not save the report if reporting is disabled" do
       Puppet.settings[:report] = false
 
       @report.expects(:save).never
-      @configurer.send_report(@report, nil)
+      @configurer.send_report(@report)
     end
 
     it "should save the last run summary if reporting is enabled" do
       Puppet.settings[:report] = true
 
       @configurer.expects(:save_last_run_summary).with(@report)
-      @configurer.send_report(@report, nil)
+      @configurer.send_report(@report)
     end
 
     it "should save the last run summary if reporting is disabled" do
       Puppet.settings[:report] = false
 
       @configurer.expects(:save_last_run_summary).with(@report)
-      @configurer.send_report(@report, nil)
+      @configurer.send_report(@report)
     end
 
     it "should log but not fail if saving the report fails" do
@@ -326,7 +399,7 @@ describe Puppet::Configurer do
       @report.expects(:save).raises "whatever"
 
       Puppet.expects(:err)
-      lambda { @configurer.send_report(@report, nil) }.should_not raise_error
+      lambda { @configurer.send_report(@report) }.should_not raise_error
     end
   end
 
@@ -506,7 +579,6 @@ describe Puppet::Configurer do
       @agent.stubs(:dostorage)
       @agent.stubs(:download_fact_plugins)
       @agent.stubs(:download_plugins)
-      @agent.stubs(:execute_prerun_command)
       @facts = {"one" => "two", "three" => "four"}
     end
 
@@ -527,10 +599,5 @@ describe Puppet::Configurer do
 
       @agent.prepare({})
     end
-
-    it "should perform the pre-run commands" do
-      @agent.expects(:execute_prerun_command)
-      @agent.prepare({})
-    end
   end
 end
diff --git a/spec/unit/resource/catalog_spec.rb b/spec/unit/resource/catalog_spec.rb
index 942721464..a15a912ef 100755
--- a/spec/unit/resource/catalog_spec.rb
+++ b/spec/unit/resource/catalog_spec.rb
@@ -595,7 +595,7 @@ describe Puppet::Resource::Catalog, "when compiling" do
     before :each do
       @catalog = Puppet::Resource::Catalog.new("host")
 
-      @transaction = mock 'transaction'
+      @transaction = Puppet::Transaction.new(@catalog)
       Puppet::Transaction.stubs(:new).returns(@transaction)
       @transaction.stubs(:evaluate)
       @transaction.stubs(:add_times)