Deferred functions sometimes resolve too late with preprocess_deferred=false

[bastelfreak]

Describe the Bug

After upgrading to Puppet 8 I noticed a problem with my elasticsearch_license type https://github.com/voxpupuli/puppet-elasticsearch/blob/master/lib/puppet/type/elasticsearch_license.rb -> https://github.com/voxpupuli/puppet-elasticsearch/blob/master/lib/puppet_x/elastic/elasticsearch_rest_resource.rb#L25-L27)

Roughly used like this:

class foo (
  $param, # set via Hiera
) {
  elasticsearch_license { 'xpack':
    password => $param.node_encrypt::secret,
    # and some more parameters
  }
}

This works fine with Puppet 7 or with Puppet 8 + preprocess_deferred=true. In with preprocess_deferred=false, the API authentication to elasticsearch fails. In the provider I added a Puppet.debug(password) and I get:

#<Puppet::Pops::Evaluator::DeferredValue:0x00007feadcbc5858>

It feels like the resolution or executed of the deferred function happens too late? But not all resources are broken. A simple file resource works:

class foo (
  $param, # set via Hiera
) {
  file { 'xpack':
    content => $param.node_encrypt::secret,
  }
}

This works, no matter if preprocess_deferred is true or false.

Expected Behavior

Deferred function should be evaluated before the type that uses the return value from the deferred function.

Steps to Reproduce

I don't have an easy to reproduce example at the moment. The Elasticsearch_license type requires a license and a working elasticsearch cluster.

Environment

• PE 2021.7.8 / PE 2023.7.0

Additional Context

• This was initially discussed at https://puppetcommunity.slack.com/archives/C0W298S9G/p1721232074454469
• Puppet 8 docs about preprocess_deferred are wrong: preprocess_deferred has the wrong default value for Puppet 8 puppet-docs#1166

[joshcooper]

@bastelfreak I think this is a variation of #9174 or #9384. The latter is fixed in 8.8.1. Could you include the stack trace from puppet agent -t --trace?

Also we're working on changing our doc automation so reference pages will be accurate for each puppet stream/branch. See #9312

[bastelfreak]

I'm only once a week at this customer, so the stack trace needs to wait a bit. But I think (not 100% sure) that I tried running with --trace and didn't see an error. Because it doesn't fail, the deferred function "just" isn't executed properly/too late. So the elasticsearch_license type/provider receives an Puppet::Pops::Evaluator::DeferredValue object instead of String.

[joshcooper]

@bastelfreak maybe this is triggered when setting a resource parameter to an array (multivalued) as discussed in #9438 (comment)?

[bastelfreak]

mhm in my case it's supposed to only return a single string. I will try to debug a bit next time when I'm with the customer.

[bastelfreak]

I'm back! here's the output from --trace. I assume this is only triggered because the http client fails to authenticate with the elastic API, not because of the deferred function itself:

Error: Could not prefetch elasticsearch_license provider 'xpack': Elasticsearch API responded with: unable to authenticate user [elastic] for REST request [/_license]
/opt/puppetlabs/puppet/cache/lib/puppet/provider/elastic_rest.rb:53:in `parse_http_response'
/opt/puppetlabs/puppet/cache/lib/puppet/provider/elastic_rest.rb:144:in `api_objects'
/opt/puppetlabs/puppet/cache/lib/puppet/provider/elastic_rest.rb:204:in `block in prefetch'
/opt/puppetlabs/puppet/cache/lib/puppet/provider/elastic_rest.rb:203:in `map'
/opt/puppetlabs/puppet/cache/lib/puppet/provider/elastic_rest.rb:203:in `prefetch'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:379:in `prefetch'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:260:in `prefetch_if_necessary'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:115:in `block in evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/graph/relationship_graph.rb:120:in `traverse'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction.rb:178:in `evaluate'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:238:in `block (2 levels) in apply'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:567:in `block in thinmark'
/opt/puppetlabs/puppet/lib/ruby/2.7.0/benchmark.rb:308:in `realtime'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:566:in `thinmark'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:237:in `block in apply'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/log.rb:165:in `with_destination'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/transaction/report.rb:151:in `as_logging_destination'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:236:in `apply'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:286:in `block (2 levels) in apply_catalog'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:567:in `block in thinmark'
/opt/puppetlabs/puppet/lib/ruby/2.7.0/benchmark.rb:308:in `realtime'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:566:in `thinmark'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:285:in `block in apply_catalog'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:245:in `block in benchmark'
/opt/puppetlabs/puppet/lib/ruby/2.7.0/benchmark.rb:308:in `realtime'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:244:in `benchmark'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:284:in `apply_catalog'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:500:in `run_internal'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/configurer.rb:339:in `run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/agent.rb:83:in `block (6 levels) in run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:62:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:289:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/agent.rb:82:in `block (5 levels) in run'
/opt/puppetlabs/puppet/lib/ruby/2.7.0/timeout.rb:78:in `timeout'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/agent.rb:81:in `block (4 levels) in run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/agent/locker.rb:21:in `lock'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/agent.rb:71:in `block (3 levels) in run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/agent.rb:162:in `with_client'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/agent.rb:67:in `block (2 levels) in run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/agent.rb:127:in `run_in_fork'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/agent.rb:66:in `block in run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application.rb:172:in `controlled_run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/agent.rb:47:in `run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/agent.rb:433:in `onetime'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/agent.rb:393:in `block in run_command'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/context.rb:62:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet.rb:289:in `override'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application/agent.rb:390:in `run_command'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application.rb:421:in `block in run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util.rb:756:in `exit_on_fail'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/application.rb:421:in `run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/command_line.rb:143:in `run'
/opt/puppetlabs/puppet/lib/ruby/vendor_ruby/puppet/util/command_line.rb:77:in `execute'
/opt/puppetlabs/puppet/bin/puppet:5:in `<main>'

and the elastic_rest.rb:

require 'json'
require 'net/http'
require 'openssl'

# Parent class encapsulating general-use functions for children REST-based
# providers.
# rubocop:disable Metrics/ClassLength
class Puppet::Provider::ElasticREST < Puppet::Provider
  class << self
    attr_accessor :api_discovery_uri
    attr_accessor :api_resource_style
    attr_accessor :api_uri
    attr_accessor :discrete_resource_creation
    attr_accessor :metadata
    attr_accessor :metadata_pipeline
    attr_accessor :query_string
  end

  # Fetch arbitrary metadata for the class from an instance object.
  #
  # @return String
  def metadata
    self.class.metadata
  end

  # Retrieve the class query_string variable
  #
  # @return String
  def query_string
    self.class.query_string
  end

  def self.parse_http_response(response)
    # Attempt to return useful error output
    unless response.code.to_i == 200
      Puppet.debug("Non-OK reponse: Body = #{response.body.inspect}")
      json = JSON.parse(response.body)

      err_msg = if json.key? 'error'
                  if json['error'].is_a? Hash \
                      and json['error'].key? 'root_cause'
                    # Newer versions have useful output
                    json['error']['root_cause'].first['reason']
                  else
                    # Otherwise fallback to old-style error messages
                    json['error']
                  end
                else
                  # As a last resort, return the response error code
                  "HTTP #{response.code}"
                end

      raise Puppet::Error, "Elasticsearch API responded with: #{err_msg}"
    end
  end

  # Perform a REST API request against the indicated endpoint.
  #
  # @return Net::HTTPResponse
  # rubocop:disable Metrics/CyclomaticComplexity
  # rubocop:disable Metrics/PerceivedComplexity
  def self.rest(http, \
                req, \
                validate_tls = true, \
                timeout = 10, \
                username = nil, \
                password = nil)

    if username and password
      req.basic_auth username, password
    elsif username or password
      Puppet.warning(
        'username and password must both be defined, skipping basic auth'
      )
    end

    req['Accept'] = 'application/json'

    http.read_timeout = timeout
    http.open_timeout = timeout
    http.verify_mode = OpenSSL::SSL::VERIFY_NONE unless validate_tls

    begin
      http.request req
    rescue EOFError => e
      # Because the provider attempts a best guess at API access, we
      # only fail when HTTP operations fail for mutating methods.
      unless %w[GET OPTIONS HEAD].include? req.method
        raise Puppet::Error,
              "Received '#{e}' from the Elasticsearch API. Are your API settings correct?"
      end
    end
  end
  # rubocop:enable Metrics/CyclomaticComplexity
  # rubocop:enable Metrics/PerceivedComplexity

  # Helper to format a remote URL request for Elasticsearch which takes into
  # account path ordering, et cetera.
  def self.format_uri(resource_path, property_flush = {})
    return api_uri if resource_path.nil? or api_resource_style == :bare
    if discrete_resource_creation and not property_flush[:ensure].nil?
      resource_path
    else
      case api_resource_style
      when :prefix
        resource_path + '/' + api_uri
      else
        api_uri + '/' + resource_path
      end
    end
  end

  # Fetch Elasticsearch API objects. Accepts a variety of argument functions
  # dictating how to connect to the Elasticsearch API.
  #
  # @return Array
  #   an array of Hashes representing the found API objects, whether they be
  #   templates, pipelines, et cetera.
  def self.api_objects(protocol = 'http', \
                       validate_tls = true, \
                       host = 'localhost', \
                       port = 9200, \
                       timeout = 10, \
                       username = nil, \
                       password = nil, \
                       ca_file = nil, \
                       ca_path = nil)

    uri = URI("#{protocol}://#{host}:#{port}/#{format_uri(api_discovery_uri)}")
    http = Net::HTTP.new uri.host, uri.port
    req = Net::HTTP::Get.new uri.request_uri

    http.use_ssl = uri.scheme == 'https'
    [[ca_file, :ca_file=], [ca_path, :ca_path=]].each do |arg, method|
      http.send method, arg if arg and http.respond_to? method
    end

    response = rest http, req, validate_tls, timeout, username, password
    Puppet.debug("api_objects response: #{response}")
    Puppet.debug("api_objects uri: #{uri.inspect}")
    Puppet.debug("api_objects username: #{password}")
    Puppet.debug("api_objects password: #{username}")
    # Attempt to return useful error output
    parse_http_response(response)

    results = []

    results = process_body(response.body)
    results
  end

  # Process the JSON response body
  def self.process_body(body)
    results = JSON.parse(body).map do |object_name, api_object|
      {
        :name     => object_name,
        :ensure   => :present,
        metadata  => process_metadata(api_object),
        :provider => name
      }
    end

    results
  end

  # Passes API objects through arbitrary Procs/lambdas in order to postprocess
  # API responses.
  def self.process_metadata(raw_metadata)
    if metadata_pipeline.is_a? Array and !metadata_pipeline.empty?
      metadata_pipeline.reduce(raw_metadata) do |md, processor|
        processor.call md
      end
    else
      raw_metadata
    end
  end

  # Fetch an array of provider objects from the Elasticsearch API.
  def self.instances
    api_objects.map { |resource| new resource }
  end

  # Unlike a typical #prefetch, which just ties discovered #instances to the
  # correct resources, we need to quantify all the ways the resources in the
  # catalog know about Elasticsearch API access and use those settings to
  # fetch any templates we can before associating resources and providers.
  def self.prefetch(resources)
    # Get all relevant API access methods from the resources we know about
    resources.map do |_, resource|
      p = resource.parameters
      [
        p[:protocol].value,
        p[:validate_tls].value,
        p[:host].value,
        p[:port].value,
        p[:timeout].value,
        (p.key?(:username) ? p[:username].value : nil),
        (p.key?(:password) ? p[:password].value : nil),
        (p.key?(:ca_file) ? p[:ca_file].value : nil),
        (p.key?(:ca_path) ? p[:ca_path].value : nil)
      ]
      # Deduplicate identical settings, and fetch templates
    end.uniq.map do |api|
      api_objects(*api)
      # Flatten and deduplicate the array, instantiate providers, and do the
      # typical association dance
    end.flatten.uniq.map { |resource| new resource }.each do |prov|
      if (resource = resources[[prov.name](http://prov.name/)])
        resource.provider = prov
      end
    end
  end

  def initialize(value = {})
    super(value)
    @property_flush = {}
  end

  # Generate a request body
  def generate_body
    JSON.generate(
      if metadata != :content and @property_flush[:ensure] == :present
        { metadata.to_s => resource[metadata] }
      else
        resource[metadata]
      end
    )
  end

  # Call Elasticsearch's REST API to appropriately PUT/DELETE/or otherwise
  # update any managed API objects.
  # rubocop:disable Metrics/CyclomaticComplexity
  # rubocop:disable Metrics/PerceivedComplexity
  def flush
    Puppet.debug('Got to flush')
    uri = URI(
      format(
        '%s://%s:%d/%s',
        resource[:protocol],
        resource[:host],
        resource[:port],
        self.class.format_uri(resource[:name], @property_flush)
      )
    )
    uri.query = URI.encode_www_form query_string if query_string

    Puppet.debug("Generated URI = #{uri.inspect}")

    case @property_flush[:ensure]
    when :absent
      req = Net::HTTP::Delete.new uri.request_uri
    else
      req = Net::HTTP::Put.new uri.request_uri
      req.body = generate_body
      Puppet.debug("Generated body looks like: #{req.body.inspect}")
      # As of Elasticsearch 6.x, required when requesting with a payload (so we
      # set it always to be safe)
      req['Content-Type'] = 'application/json' if req['Content-Type'].nil?
    end

    http = Net::HTTP.new uri.host, uri.port
    http.use_ssl = uri.scheme == 'https'
    [:ca_file, :ca_path].each do |arg|
      if !resource[arg].nil? and http.respond_to? arg
        http.send "#{arg}=".to_sym, resource[arg]
      end
    end

    response = self.class.rest(
      http,
      req,
      resource[:validate_tls],
      resource[:timeout],
      resource[:username],
      resource[:password]
    )

    # Attempt to return useful error output
    self.class.parse_http_response(response)
    # rubocop:enable Metrics/CyclomaticComplexity
    # rubocop:enable Metrics/PerceivedComplexity

    @property_hash = self.class.api_objects(
      resource[:protocol],
      resource[:validate_tls],
      resource[:host],
      resource[:port],
      resource[:timeout],
      resource[:username],
      resource[:password],
      resource[:ca_file],
      resource[:ca_path]
    ).detect do |t|
      t[:name] == resource[:name]
    end
  end

  # Set this provider's `:ensure` property to `:present`.
  def create
    @property_flush[:ensure] = :present
  end

  def exists?
    @property_hash[:ensure] == :present
  end

  # Set this provider's `:ensure` property to `:absent`.
  def destroy
    @property_flush[:ensure] = :absent
  end
end # of class

This is a copy of https://github.com/voxpupuli/puppet-elasticsearch/blob/master/lib/puppet/provider/elastic_rest.rb with some debug.

[joshcooper]

@bastelfreak for the short term, you could add a check to see if the password here

https://github.com/voxpupuli/puppet-elasticsearch/blob/543c5821bd9fa58f122443efa123e4a90381c63f/lib/puppet/provider/elastic_rest.rb#L158C43-L158C48

responds to resolve like the concat module did in puppetlabs/puppetlabs-concat@ab51760

The DeferredValue objects were never intended to leak into provider lifecycle methods, but that's where we are right now.

[bastelfreak]

Hi Josh, thanks for the perfect timing. I'm with the customer again tomorrow, so I hopefully have a chance to test it.

[joshcooper]

@bastelfreak any updates on this?

[bastelfreak]

I had no chance yet to implement this in the elasticsearch module :(

[joshcooper]

Friendly ping @bastelfreak