The Puppet Labs Issue Tracker has Moved: https://tickets.puppetlabs.com

This issue tracker is now in read-only archive mode and automatic ticket export has been disabled. Redmine users will need to create a new JIRA account to file tickets using https://tickets.puppetlabs.com. See the following page for information on filing tickets with JIRA:

Bug #22944

External facts are evaluated many times

Added by Matthias Baur over 2 years ago. Updated over 2 years ago.

Status:ClosedStart date:
Priority:NormalDue date:
Assignee:-% Done:

0%

Category:-
Target version:1.7.4
Keywords: Affected Facter version:1.7.3
Branch:https://github.com/puppetlabs/facter/pull/570

We've Moved!

Ticket tracking is now hosted in JIRA: https://tickets.puppetlabs.com

This ticket is now tracked at: https://tickets.puppetlabs.com/browse/FACT-90


Description

Reproduction

  • Drop script /etc/facter/facts.d/test.sh:
#!/bin/bash
echo "SCRIPT CALLED" >&2
echo "test=value"
  • Make script executeable
chmod +x /etc/facter/facts.d/test.sh
  • Call ‘facter’, the following output is shown:
root@puppet:~# facter
SCRIPT CALLED
SCRIPT CALLED
SCRIPT CALLED
SCRIPT CALLED
SCRIPT CALLED
SCRIPT CALLED
...
Regular facter output
...

I don’t see a reason why the script is called 6 times.

System information

  • Ubuntu 12.04.3
  • Facter 1.7.3

Related issues

Related to Facter - Bug #23368: Script based external facts fail on Windows 2003 Closed
Duplicated by Puppet - Bug #23335: external facts cause puppet apply to take inordinately lo... Duplicate

History

#1 Updated by Josh Cooper over 2 years ago

  • Description updated (diff)
  • Status changed from Unreviewed to Accepted

#2 Updated by Josh Cooper over 2 years ago

  • Subject changed from External fact is called 6 times to External facts are evaluated many times
  • Target version set to 1.7.4

When you run facter it will start by trying to load all facts, e.g. Facter::Util::Collection.load_all. This walks facter’s search path, calling Kernel.load(file) on each *.rb file. When facter loads simple facts of the form:

Facter.add(:factname) do
  ...
end

it registers a Facter::Util::Fact object, and appends to its list of resolutions for that fact. In other words, we don’t actually try to evaluate the fact.

However, some facts resolve other facts outside of their add block. For example, in ec2.rb, we effectively do:

if !!(Facter.value(:macaddress) =~ %r{^[dD]0:0[dD]:})
  Facter.add(:ec2) do
    ...
  end

The key issue here, is that we try to resolve the macaddress fact before we’ve loaded the macaddress.rb file and registered a Facter::Util::Fact for it (because ec2.rb comes before macaddress.rb).

As a result, in Facter::Util::Collection.load(name), we call:

    # Try to load the fact if necessary
    load(name) unless @facts[name]

where load(name) causes all external facts to be evaluated:

  def load(name)
    internal_loader.load(name)
    external_loader.load(self) # <---- HERE

But the fun doesn’t stop there. The :macaddress fact has multiple resolutions, some confined by :osfamily, others :operatingsystem, each of which triggers all external facts to be evaluated. And actually :osfamily depends on :operatingsystem, so that adds another round of evaluating external facts.

The same issue also occurs when evaluating blockdevices.rb as that depends on the :kernel fact:

if Facter.value(:kernel) == 'Linux'
  ...
  Facter.add(:blockdevices) do

In the short-term, we should ensure we only load external facts once.

#3 Updated by Glenn Poston over 2 years ago

I think that the title of this ticket undermines it’s serverity, so I just wanted to add some research that I did.

I have an external fact (script) that takes 5s to evaluate. This causes my puppet runs to take 2x longer than they do without the fact evaluation. This doubles our run time. We use puppet to provision new instances for auto-scaling purposes, so puppet run times are critical for us. Here’s some data:

I was curious how much of an effect the long running external fact was effecting the timing, so I updated the external fact script to simply echo the content (instead of fetching it from s3). The facts it produced were the same as if it had fetched the facts from S3.

I then introduced a ‘sleep x’ before the echo statement in the script. Now we see some compounding delays. I think this adds a bit of support to the theory that puppet is unnecessarily re-evaluating facts, but it appears that facter may have some compounding delays as well.

Bottom Line:

When the script resolves instantaneously (echo statment only) script takes .004s facter takes .754s puppet takes 1m

When the script takes 1s (sleep 1, then echo) script takes 1s facter takes 6s puppet takes 1m12s

When the script takes 5s (sleep 5, then echo) script takes 5s facter takes 30s puppet takes 2m38s

#4 Updated by Josh Cooper over 2 years ago

Puppet also runs facter twice, which is why you’re seeing 6s facter run causing 1m12s puppet runs.

#5 Updated by Josh Cooper over 2 years ago

  • Status changed from Accepted to In Topic Branch Pending Review
  • Branch set to https://github.com/puppetlabs/facter/pull/570

#6 Updated by Ethan Brown over 2 years ago

  • Status changed from In Topic Branch Pending Review to Merged - Pending Release

#7 Updated by Melissa Stone over 2 years ago

  • Status changed from Merged - Pending Release to Closed

Release in Facter 1.7.4-rc1

#8 Updated by Charlie Sharpsteen over 2 years ago

Redmine Issue #22944 has been migrated to JIRA:

https://tickets.puppetlabs.com/browse/FACT-90

Also available in: Atom PDF