From 3e1357e9f89184a20dd2d79a59dbacd14f7caa60 Mon Sep 17 00:00:00 2001 From: Jacob Helwig Date: Fri, 13 Apr 2018 15:04:25 -0700 Subject: [PATCH] (PUP-6344) Always populate total time metric in reports Previously if anything raised during a run, the total time would be nil, as the thinmark wouldn't be able to return & set run_internal_time. To get around this we're now manually recording when the run_internal starts, and comparing that against Time.now at the end to record the total run time. --- lib/puppet/configurer.rb | 217 +++++++++++++++++------------------ spec/unit/configurer_spec.rb | 10 +- 2 files changed, 117 insertions(+), 110 deletions(-) diff --git a/lib/puppet/configurer.rb b/lib/puppet/configurer.rb index 0fe5d2f9730..48ba00a3bd4 100644 --- a/lib/puppet/configurer.rb +++ b/lib/puppet/configurer.rb @@ -244,135 +244,134 @@ def run_internal(options) report = options[:report] prerun_command_successful = false + run_internal_start_time = Time.now begin - run_internal_time = thinmark do - # If a cached catalog is explicitly requested, attempt to retrieve it. Skip the node request, - # don't pluginsync and switch to the catalog's environment if we successfully retrieve it. - if Puppet[:use_cached_catalog] - Puppet::GettextConfig.reset_text_domain('agent') - Puppet::ModuleTranslations.load_from_vardir(Puppet[:vardir]) - - if catalog = prepare_and_retrieve_catalog_from_cache(options) - options[:catalog] = catalog - @cached_catalog_status = 'explicitly_requested' - - if @environment != catalog.environment && !Puppet[:strict_environment_mode] - Puppet.notice _("Local environment: '%{local_env}' doesn't match the environment of the cached catalog '%{catalog_env}', switching agent to '%{catalog_env}'.") % { local_env: @environment, catalog_env: catalog.environment } - @environment = catalog.environment - end + # If a cached catalog is explicitly requested, attempt to retrieve it. Skip the node request, + # don't pluginsync and switch to the catalog's environment if we successfully retrieve it. + if Puppet[:use_cached_catalog] + Puppet::GettextConfig.reset_text_domain('agent') + Puppet::ModuleTranslations.load_from_vardir(Puppet[:vardir]) + + if catalog = prepare_and_retrieve_catalog_from_cache(options) + options[:catalog] = catalog + @cached_catalog_status = 'explicitly_requested' - report.environment = @environment - else - # Don't try to retrieve a catalog from the cache again after we've already - # failed to do so the first time. - Puppet[:use_cached_catalog] = false - Puppet[:usecacheonfailure] = false - options[:pluginsync] = Puppet::Configurer.should_pluginsync? + if @environment != catalog.environment && !Puppet[:strict_environment_mode] + Puppet.notice _("Local environment: '%{local_env}' doesn't match the environment of the cached catalog '%{catalog_env}', switching agent to '%{catalog_env}'.") % { local_env: @environment, catalog_env: catalog.environment } + @environment = catalog.environment end + + report.environment = @environment + else + # Don't try to retrieve a catalog from the cache again after we've already + # failed to do so the first time. + Puppet[:use_cached_catalog] = false + Puppet[:usecacheonfailure] = false + options[:pluginsync] = Puppet::Configurer.should_pluginsync? end + end - begin - unless Puppet[:node_name_fact].empty? - query_options = get_facts(options) - end + begin + unless Puppet[:node_name_fact].empty? + query_options = get_facts(options) + end - configured_environment = Puppet[:environment] if Puppet.settings.set_by_config?(:environment) - - # We only need to find out the environment to run in if we don't already have a catalog - unless (options[:catalog] || Puppet[:strict_environment_mode]) - begin - node = nil - node_retr_time = thinmark do - node = options[:node] || Puppet::Node.indirection.find(Puppet[:node_name_value], - :environment => Puppet::Node::Environment.remote(@environment), - :configured_environment => configured_environment, - :ignore_cache => true, - :transaction_uuid => @transaction_uuid, - :fail_on_404 => true) + configured_environment = Puppet[:environment] if Puppet.settings.set_by_config?(:environment) + + # We only need to find out the environment to run in if we don't already have a catalog + unless (options[:catalog] || Puppet[:strict_environment_mode]) + begin + node = nil + node_retr_time = thinmark do + node = options[:node] || Puppet::Node.indirection.find(Puppet[:node_name_value], + :environment => Puppet::Node::Environment.remote(@environment), + :configured_environment => configured_environment, + :ignore_cache => true, + :transaction_uuid => @transaction_uuid, + :fail_on_404 => true) + end + options[:report].add_times(:node_retrieval, node_retr_time) + + if node + # If we have deserialized a node from a rest call, we want to set + # an environment instance as a simple 'remote' environment reference. + if !node.has_environment_instance? && node.environment_name + node.environment = Puppet::Node::Environment.remote(node.environment_name) end - options[:report].add_times(:node_retrieval, node_retr_time) - - if node - # If we have deserialized a node from a rest call, we want to set - # an environment instance as a simple 'remote' environment reference. - if !node.has_environment_instance? && node.environment_name - node.environment = Puppet::Node::Environment.remote(node.environment_name) - end - - @node_environment = node.environment.to_s - - if node.environment.to_s != @environment - Puppet.notice _("Local environment: '%{local_env}' doesn't match server specified node environment '%{node_env}', switching agent to '%{node_env}'.") % { local_env: @environment, node_env: node.environment } - @environment = node.environment.to_s - report.environment = @environment - query_options = nil - else - Puppet.info _("Using configured environment '%{env}'") % { env: @environment } - end + + @node_environment = node.environment.to_s + + if node.environment.to_s != @environment + Puppet.notice _("Local environment: '%{local_env}' doesn't match server specified node environment '%{node_env}', switching agent to '%{node_env}'.") % { local_env: @environment, node_env: node.environment } + @environment = node.environment.to_s + report.environment = @environment + query_options = nil + else + Puppet.info _("Using configured environment '%{env}'") % { env: @environment } end - rescue StandardError => detail - Puppet.warning(_("Unable to fetch my node definition, but the agent run will continue:")) - Puppet.warning(detail) end + rescue StandardError => detail + Puppet.warning(_("Unable to fetch my node definition, but the agent run will continue:")) + Puppet.warning(detail) end + end - current_environment = Puppet.lookup(:current_environment) - if current_environment.name == @environment.intern - local_node_environment = current_environment - else - local_node_environment = Puppet::Node::Environment.create(@environment, - current_environment.modulepath, - current_environment.manifest, - current_environment.config_version) - end - Puppet.push_context({:current_environment => local_node_environment}, "Local node environment for configurer transaction") + current_environment = Puppet.lookup(:current_environment) + if current_environment.name == @environment.intern + local_node_environment = current_environment + else + local_node_environment = Puppet::Node::Environment.create(@environment, + current_environment.modulepath, + current_environment.manifest, + current_environment.config_version) + end + Puppet.push_context({:current_environment => local_node_environment}, "Local node environment for configurer transaction") - query_options = get_facts(options) unless query_options - query_options[:configured_environment] = configured_environment + query_options = get_facts(options) unless query_options + query_options[:configured_environment] = configured_environment - unless catalog = prepare_and_retrieve_catalog(options, query_options) - return nil - end + unless catalog = prepare_and_retrieve_catalog(options, query_options) + return nil + end - if Puppet[:strict_environment_mode] && catalog.environment != @environment - Puppet.err _("Not using catalog because its environment '%{catalog_env}' does not match agent specified environment '%{local_env}' and strict_environment_mode is set") % { catalog_env: catalog.environment, local_env: @environment } - return nil - end + if Puppet[:strict_environment_mode] && catalog.environment != @environment + Puppet.err _("Not using catalog because its environment '%{catalog_env}' does not match agent specified environment '%{local_env}' and strict_environment_mode is set") % { catalog_env: catalog.environment, local_env: @environment } + return nil + end - # Here we set the local environment based on what we get from the - # catalog. Since a change in environment means a change in facts, and - # facts may be used to determine which catalog we get, we need to - # rerun the process if the environment is changed. - tries = 0 - while catalog.environment and not catalog.environment.empty? and catalog.environment != @environment - if tries > 3 - raise Puppet::Error, _("Catalog environment didn't stabilize after %{tries} fetches, aborting run") % { tries: tries } - end - Puppet.notice _("Local environment: '%{local_env}' doesn't match server specified environment '%{catalog_env}', restarting agent run with environment '%{catalog_env}'") % { local_env: @environment, catalog_env: catalog.environment } - @environment = catalog.environment - report.environment = @environment + # Here we set the local environment based on what we get from the + # catalog. Since a change in environment means a change in facts, and + # facts may be used to determine which catalog we get, we need to + # rerun the process if the environment is changed. + tries = 0 + while catalog.environment and not catalog.environment.empty? and catalog.environment != @environment + if tries > 3 + raise Puppet::Error, _("Catalog environment didn't stabilize after %{tries} fetches, aborting run") % { tries: tries } + end + Puppet.notice _("Local environment: '%{local_env}' doesn't match server specified environment '%{catalog_env}', restarting agent run with environment '%{catalog_env}'") % { local_env: @environment, catalog_env: catalog.environment } + @environment = catalog.environment + report.environment = @environment - query_options = get_facts(options) - query_options[:configured_environment] = configured_environment + query_options = get_facts(options) + query_options[:configured_environment] = configured_environment - return nil unless catalog = prepare_and_retrieve_catalog(options, query_options) - tries += 1 - end + return nil unless catalog = prepare_and_retrieve_catalog(options, query_options) + tries += 1 + end - if execute_prerun_command - prerun_command_successful = true - options[:report].code_id = catalog.code_id - options[:report].catalog_uuid = catalog.catalog_uuid - options[:report].cached_catalog_status = @cached_catalog_status - apply_catalog(catalog, options) - end - rescue => detail - Puppet.log_exception(detail, _("Failed to apply catalog: %{detail}") % { detail: detail }) - return nil + if execute_prerun_command + prerun_command_successful = true + options[:report].code_id = catalog.code_id + options[:report].catalog_uuid = catalog.catalog_uuid + options[:report].cached_catalog_status = @cached_catalog_status + apply_catalog(catalog, options) end - end #thinmark + rescue => detail + Puppet.log_exception(detail, _("Failed to apply catalog: %{detail}") % { detail: detail }) + return nil + end ensure - report.add_times(:total, run_internal_time) + report.add_times(:total, Time.now - run_internal_start_time) report.finalize_report exit_status = report.exit_status if prerun_command_successful diff --git a/spec/unit/configurer_spec.rb b/spec/unit/configurer_spec.rb index 5c02fe0cc94..6377f3ccd2f 100644 --- a/spec/unit/configurer_spec.rb +++ b/spec/unit/configurer_spec.rb @@ -362,10 +362,18 @@ it "should record a total run time" do report = Puppet::Transaction::Report.new @catalog.stubs(:apply).with(:report => report) - report.expects(:add_times).with(:total, anything()) + report.expects(:add_times).with {|m,v| m == :total && !v.nil?} @agent.run({:report => report}) end + it "should record a total run time with failed catalog retrieval" do + report = Puppet::Transaction::Report.new + @catalog.stubs(:apply).with(:report => report) + report.expects(:add_times).with {|m,v| m == :total && !v.nil?} + @agent.stubs(:prepare_and_retrieve_catalog_from_cache).raises + @agent.run(:report => report) + end + it "should refetch the catalog if the server specifies a new environment in the catalog" do catalog = Puppet::Resource::Catalog.new("tester", Puppet::Node::Environment.remote('second_env')) @agent.expects(:retrieve_catalog).returns(catalog).twice