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

Bug #8341

Loading facts repeatedly

Added by Trevor Vaughan about 3 years ago. Updated over 1 year ago.

Status:ClosedStart date:07/09/2011
Priority:NormalDue date:
Assignee:Patrick Carlisle% Done:

0%

Category:facter
Target version:2.7.10
Affected Puppet version: Branch:https://github.com/pcarlisle/puppet/tree/8341_facts_load_once
Keywords:custom fact, repeated customer

We've Moved!

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

This issue is currently not available for export. If you are experiencing the issue described below, please file a new ticket in JIRA. Once a new ticket has been created, please add a link to it that points back to this Redmine ticket.


Description

Puppet seems to be getting overzealous when loading custom facts.

Example:

Loading facts in custom_fact_1
Loading facts in custom_fact_2
Loading facts in custom_fact_3
Loading facts in custom_fact_5
Loading facts in custom_fact_7
Loading facts in custom_fact_8
Loading facts in custom_fact_9
Loading facts in custom_fact_10
Loading facts in custom_fact_11
Loading facts in custom_fact_12
Loading facts in custom_fact_13
Loading facts in custom_fact_14
Loading facts in custom_fact_5
Loading facts in custom_fact_7
Loading facts in custom_fact_2
Loading facts in custom_fact_3
Loading facts in custom_fact_12
Loading facts in custom_fact_11
Loading facts in custom_fact_10
Loading facts in custom_fact_8
Loading facts in custom_fact_13
Loading facts in custom_fact_6
Loading facts in custom_fact_14
Loading facts in custom_fact_9
Loading facts in custom_fact_1
Loading facts in custom_fact_1
Loading facts in custom_fact_2
Loading facts in custom_fact_3
Loading facts in custom_fact_5
Loading facts in custom_fact_6
Loading facts in custom_fact_7
Loading facts in custom_fact_8
Loading facts in custom_fact_9
Loading facts in custom_fact_10
Loading facts in custom_fact_11
Loading facts in custom_fact_12
Loading facts in custom_fact_13
Loading facts in custom_fact_14
Loading facts in custom_fact_5
Loading facts in custom_fact_7
Loading facts in custom_fact_2
Loading facts in custom_fact_3
Loading facts in custom_fact_12
Loading facts in custom_fact_11
Loading facts in custom_fact_10
Loading facts in custom_fact_8
Loading facts in custom_fact_13
Loading facts in custom_fact_6
Loading facts in custom_fact_14
Loading facts in custom_fact_9
Loading facts in custom_fact_1

Related issues

Related to Puppet - Bug #3741: Custom facts loaded multiple times Closed 05/07/2010
Related to Puppet - Bug #12464: puppet apply looks up facts twice Closed 02/06/2012
Related to Puppet - Bug #12310: Significant slow down in 2.7.10 apply Closed 01/30/2012
Related to Puppet - Bug #16570: puppet apply loading facts twice Accepted 09/25/2012

History

#1 Updated by Luke Kanies about 3 years ago

There appears to be an erroneous call to ‘loadfacts’ in lib/puppet/provider/nameservice/directoryservice.rb, but that’s probably been around for a while.

#2 Updated by Luke Kanies about 3 years ago

Hmm, and in the launchd provider.

#3 Updated by Jacob Helwig about 3 years ago

  • Status changed from Unreviewed to Investigating

Trevor,

Don’t suppose you have a minimal setup you could share that’s showing the loading four times problem? It’s loading facts twice for me, but I’d like to make sure I’m actually seeing the same thing you are. What platform is this on, by the way?

#4 Updated by Trevor Vaughan about 3 years ago

I apologize, but I don’t at the moment.

I’ll see what I can work out.

CentOS5.5

Thanks,

Trevor

On Wed, Jul 13, 2011 at 1:28 PM, tickets@puppetlabs.com wrote:

Issue #8341 has been updated by Jacob Helwig.

Status changed from Unreviewed to Investigating

Trevor,

Don’t suppose you have a minimal setup you could share that’s showing the loading four times problem? It’s loading facts twice for me, but I’d like to make sure I’m actually seeing the same thing you are. What platform is this on, by the way?


#5 Updated by Jacob Helwig about 3 years ago

After talking things through with Nick, it looks like loading facts twice on agent start up is almost unavoidable.

We need to load the facts to bootstrap the agent itself, then we need to reload them after pluginsync.

We could avoid the reload if we made pluginsync smarter about detecting when it was a no-op.

We definitely shouldn’t be seeing facts loaded >2 times on initial start-up though.

#6 Updated by Jacob Helwig about 3 years ago

  • Assignee changed from Nigel Kersten to Jacob Helwig

#7 Updated by Jacob Helwig about 3 years ago

  • Branch set to https://github.com/jhelwig/puppet/tree/ticket/master/8341-do-not-explicitly-load-all-facts/

Trevor,

I’ve got a branch that removes all of the extra explicit calls to Facter.loadfacts that were in Puppet. They’re no longer needed with Facter >= 1.6.0, since they were trying to make sure that facts that didn’t match their file name were available.

It’s a bit of a shot in the dark, but you can try it out in my branch up on GitHub.

git://github.com/jhelwig/puppet.git ticket/master/8341-do-not-explicitly-load-all-facts

#8 Updated by Trevor Vaughan about 3 years ago

Thanks, I’ll give it a shot as soon as I can get Facter 1.6.0 to RPM-ify successfully (your spec file is broken).

Trevor

On Wed, Jul 13, 2011 at 5:46 PM, tickets@puppetlabs.com wrote:

Issue #8341 has been updated by Jacob Helwig.

Branch set to https://github.com/jhelwig/puppet/tree/ticket/master/8341-do-not-explicitly-load-all-facts/

Trevor,

I’ve got a branch that removes all of the extra explicit calls to Facter.loadfacts that were in Puppet. They’re no longer needed with Facter

= 1.6.0, since they were trying to make sure that facts that didn’t match their file name were available.

It’s a bit of a shot in the dark, but you can try it out in my branch up on GitHub.

#9 Updated by Trevor Vaughan about 3 years ago

Two issues so far:

1) It requires the ‘.sign’ file and you don’t use it anywhere. 2) README and COPYING are not in the tarball.

Also, since when is facter architecture dependent? It didn’t seem to build any native extensions.

Trevor

On Wed, Jul 13, 2011 at 5:55 PM, Trevor Vaughan tvaughan@onyxpoint.com wrote:

Thanks, I’ll give it a shot as soon as I can get Facter 1.6.0 to RPM-ify successfully (your spec file is broken).

Trevor

On Wed, Jul 13, 2011 at 5:46 PM,  tickets@puppetlabs.com wrote:

Issue #8341 has been updated by Jacob Helwig.

Branch set to https://github.com/jhelwig/puppet/tree/ticket/master/8341-do-not-explicitly-load-all-facts/

Trevor,

I’ve got a branch that removes all of the extra explicit calls to Facter.loadfacts that were in Puppet. They’re no longer needed with Facter

= 1.6.0, since they were trying to make sure that facts that didn’t match their file name were available.

It’s a bit of a shot in the dark, but you can try it out in my branch up on GitHub.

#10 Updated by James Turnbull about 3 years ago

Trevor – I’ve added Mike to the ticket as he handles our release management and packaging.

#11 Updated by Michael Stahnke about 3 years ago

I’ve made facter 1.6 rpms available at the following URL.

http://downloads.puppetlabs.com/tmp/

They won’t be there for very long (a few days hopefully at most)

I’ve updated the spec (see patch on list).

The arch dependent bit is tricky. If we attempt to use the same spec file for EL4 and SLES, then it actually is arch dependent. Modern EL/Fedora abstract that with a patch to core ruby, IIRC. That being said, the rpms I put up are noarch ;)

#12 Updated by Jacob Helwig about 3 years ago

Updates from Trevor via email that haven’t seemed to make it in to the ticket:

No difference with the patch set.

I’m now wondering if this is an artifact of calling facts from inside other facts.

Thanks for the RPM, I compiled it myself though.

Trevor

and

It didn’t seem to be facts inside of facts.

I’m back to where I started with this. Not quite sure why it’s happening. I’ll tinker about a bit and see if I can pinpoint it.

Thanks,

Trevor

#13 Updated by Jacob Helwig about 3 years ago

Trevor,

Dunno if you’ve already tried this, but applying a patch like the following should help us figure out what’s bringing us into load_fact_plugins multiple times, since there are a couple of different code paths that will get us there. It should only be needed on the agent.

diff --git i/lib/puppet/indirector/facts/facter.rb w/lib/puppet/indirector/facts/facter.rb
index ab7378a..311dff5 100644
--- i/lib/puppet/indirector/facts/facter.rb
+++ w/lib/puppet/indirector/facts/facter.rb
@@ -8,6 +8,9 @@ class Puppet::Node::Facts::Facter < Puppet::Indirector::Code


   def self.load_fact_plugins
+    require 'pp'
+    pp caller
+
     # Add any per-module fact directories to the factpath
     module_fact_dirs = Puppet[:modulepath].split(":").collect do |d|
       ["lib", "plugins"].map do |subdirectory|

#14 Updated by Trevor Vaughan about 3 years ago

Additional information:

  • The facts are definitely getting loaded 4 times
  • This does not happen in 0.24.X

The following call stack is printed before each call to the fact loader:

/usr/lib/ruby/site_ruby/1.8/puppet/indirector/facts/facter.rb:31:in `load_facts_in_dir'
/usr/lib/ruby/site_ruby/1.8/puppet/indirector/facts/facter.rb:27:in `each'
/usr/lib/ruby/site_ruby/1.8/puppet/indirector/facts/facter.rb:27:in `load_facts_in_dir'
/usr/lib/ruby/site_ruby/1.8/puppet/indirector/facts/facter.rb:26:in `chdir'
/usr/lib/ruby/site_ruby/1.8/puppet/indirector/facts/facter.rb:26:in `load_facts_in_dir'
/usr/lib/ruby/site_ruby/1.8/puppet/indirector/facts/facter.rb:19:in `load_fact_plugins'
/usr/lib/ruby/site_ruby/1.8/puppet/indirector/facts/facter.rb:18:in `each'
/usr/lib/ruby/site_ruby/1.8/puppet/indirector/facts/facter.rb:18:in `load_fact_plugins'
/usr/lib/ruby/site_ruby/1.8/puppet/indirector/facts/facter.rb:67:in `initialize'
/usr/lib/ruby/site_ruby/1.8/puppet/indirector/indirection.rb:314:in `new'
/usr/lib/ruby/site_ruby/1.8/puppet/indirector/indirection.rb:314:in `make_terminus'
/usr/lib/ruby/site_ruby/1.8/puppet/indirector/indirection.rb:123:in `terminus'
/usr/lib/ruby/site_ruby/1.8/puppet/indirector/indirection.rb:302:in `prepare'
/usr/lib/ruby/site_ruby/1.8/puppet/indirector/indirection.rb:181:in `find'
/usr/lib/ruby/site_ruby/1.8/puppet/configurer/fact_handler.rb:19:in `find_facts'
/usr/lib/ruby/site_ruby/1.8/puppet/configurer/fact_handler.rb:34:in `facts_for_uploading'
/usr/lib/ruby/site_ruby/1.8/puppet/configurer.rb:142:in `run'
/usr/lib/ruby/site_ruby/1.8/puppet/agent.rb:39:in `run'
/usr/lib/ruby/site_ruby/1.8/puppet/agent/locker.rb:21:in `lock'
/usr/lib/ruby/site_ruby/1.8/puppet/agent.rb:39:in `run'
/usr/lib/ruby/1.8/sync.rb:230:in `synchronize'
/usr/lib/ruby/site_ruby/1.8/puppet/agent.rb:39:in `run'
/usr/lib/ruby/site_ruby/1.8/puppet/agent.rb:103:in `with_client'
/usr/lib/ruby/site_ruby/1.8/puppet/agent.rb:37:in `run'
/usr/lib/ruby/site_ruby/1.8/puppet/application.rb:172:in `call'
/usr/lib/ruby/site_ruby/1.8/puppet/application.rb:172:in `controlled_run'
/usr/lib/ruby/site_ruby/1.8/puppet/agent.rb:35:in `run'
/usr/lib/ruby/site_ruby/1.8/puppet/application/agent.rb:336:in `onetime'
/usr/lib/ruby/site_ruby/1.8/puppet/application/agent.rb:310:in `run_command'
/usr/lib/ruby/site_ruby/1.8/puppet/application.rb:307:in `run'
/usr/lib/ruby/site_ruby/1.8/puppet/application.rb:411:in `hook'
/usr/lib/ruby/site_ruby/1.8/puppet/application.rb:307:in `run'
/usr/lib/ruby/site_ruby/1.8/puppet/application.rb:402:in `exit_on_fail'
/usr/lib/ruby/site_ruby/1.8/puppet/application.rb:307:in `run'
/usr/sbin/puppetd:4

#15 Updated by Jacob Helwig about 3 years ago

Is it actually the same stack trace all four times? That’s surprising.

When I was getting the expected two loads of the facts due to pluginsync, I was getting two differing stack traces on the way to load_facts_in_dir.

#16 Updated by Michael Stahnke about 3 years ago

  • Status changed from Investigating to Needs More Information

We have been unable to reproduce this issue. Rather than continue to hold up the release of 2.7.2, we are planning to move forward. If you can provide more information that will allow us to reproduce this issue, we’ll be more than happy to look into it.

#17 Updated by Trevor Vaughan about 3 years ago

No problem. I’m trying to figure out how to pinpoint it and will provide more information if I can figure it out.

#18 Updated by Nigel Kersten about 3 years ago

You mention 0.24.x, you don’t have factsync and pluginsync both on do you?

#19 Updated by Trevor Vaughan about 3 years ago

Update with actual information!

Nigel – No, only pluginsync is set to true, factsync isn’t defined at all.

It looks like I put my check in the wrong place last time which is why I was seeing the same data for the caller. Sorry about that.

What seems to be actually happening is that, once the facts are sync’d, Puppet is looking in both the module space and the local fact space and loading all modules.

The culprit seems to be line 17 of facter.rb referenced above.

dirs = module_fact_dirs + Puppet[:factpath].split(“:”)

Should the code be loading items with the same name twice, or should the local facts win over the module facts.

I think the second is the correct method since you could have a PM controlled by a higher level PM that potentially provides different local facts with the same name as the facts in the module space in the lower level PM.

So, not a huge bug, but a potential cause of non-deterministic behavior in stacked PM’s.

#20 Updated by Jeff McCune about 3 years ago

  • Affected Puppet version deleted (2.7.2rc1)

Hi, I’m running into facts loading 4 times with some work I’m doing and matti pinged me about this problem on #puppet as well.

What exactly is the additional information that is needed, and who should be providing it? I’m asking because I’m trying to determine if this ticket has traction and if not what the missing information is. Perhaps I can provide it if possible.

-Jeff

#21 Updated by Michael Stahnke about 3 years ago

we are looking for a scenario that can reproduce this.

#22 Updated by Jeff McCune almost 3 years ago

Reproduction

I’m able to get facts to load N times where N is equal to the number of module path elements containing modules with custom facts times two, plus two. =)

[root@centos ~]# puppet agent --test
info: Retrieving plugin
info: Loading facts in facter_dot_d
info: Loading facts in facter_dot_d
info: Loading facts in facter_dot_d
info: Loading facts in facter_dot_d
info: Loading facts in facter_dot_d
info: Loading facts in facter_dot_d
info: Caching catalog for agent01
info: Applying configuration version '1315948791'
notice: Finished catalog run in 0.03 seconds
[root@centos puppet]# puppet agent --configprint modulepath
/etc/puppetlabs/puppet/modules:/opt/puppet/share/puppet/modules:/opt/puppet/share/puppet/modulesfoo

Note that there are two directories that each have “stdlib” in them:

  1. /opt/puppet/share/puppet/modules
  2. /opt/puppet/share/puppet/modulesfoo

I suspect what’s happening is that the Agent is reloading facter facts the following times: (Not necessarily in this order)

  1. Twice for /var/opt/lib/pe-puppet/lib/facter
  2. Twice for /opt/puppet/share/puppet/modules/stdlib/lib/facter
  3. Twice for /opt/puppet/share/puppet/modulesfoo/stdlib/lib/facter

#23 Updated by Anonymous almost 3 years ago

Ken, Adrien. Can you take a look at this ticket and let us know if you expect that the problem will be resolved by the work you are doing around Facter?

#24 Updated by Ken Barber almost 3 years ago

The TTL work in #2157 will simply cache the result of setcode – that is all. It won’t remove the messages and stop multiple loading like this. It might speed up things though if you used a ttl – but your fixing the symptom not the problem.

#25 Updated by Adrien Thebo almost 3 years ago

Facter itself will not reload a ruby file until Facter.clear has been called, however lib/puppet/indirector/facts/facter.rb:32 calls Kernel.load, which bypasses the fix introduced to resolve #8491. This could be easily resolved by modifying the factpath with Facter.search instead of calling Kernel.load, and I’ll work on writing a patch to do so shortly.

#26 Updated by Adrien Thebo almost 3 years ago

  • Status changed from Needs More Information to In Topic Branch Pending Review
  • Assignee changed from Jacob Helwig to Adrien Thebo
  • Target version set to 2.7.x
  • Branch changed from https://github.com/jhelwig/puppet/tree/ticket/master/8341-do-not-explicitly-load-all-facts/ to https://github.com/adrienthebo/puppet/tree/ticket/2.7.x/8341-prevent_duplicate_loading_of_facts

The simple fix for this is to simply unique the paths to look for and load facts from. I would prefer to use Facter’s loading mechanisms to delegate that outside of puppet, but this is faster and solves the immediate issue. See https://github.com/puppetlabs/puppet/pull/127

#27 Updated by Stefan Schulte almost 3 years ago

Hi Adrien, I dont really undestand how your fix actually works. If I understand this correctly it will help if

  • you have the same directory multiple times in your modulepath (and I mean the absolute path to the directory)
  • modulepath and factpath overlap

I dont see that any of the above apply to the examples?

#28 Updated by Adrien Thebo almost 3 years ago

Without this fix, if you had a modulepath like modulepath=/example/puppet/modules:/example/puppet/modules:/example/puppet/modules then you would load the any facts in that directory three times. I think that this is the most that we can really do to avoid loading fact files multiple times, unless we want to ensure that we only load the facts out of the first module with any given name.

#29 Updated by Stefan Schulte almost 3 years ago

Yes I can see how your example would cause puppet to load facts multiple times, but I cannot see multiple paths in the example Jeff described. So to put it another way: Your code makes sense but after merging it one cannot close the whole issue or am I still missing something?

#30 Updated by Adrien Thebo almost 3 years ago

This may require feedback from Jeff as to what the desired behavior for loading facter plugins. And you’re right in point this out that I hadn’t considered, that this does solve a problem, but admittedly it may not be Jeff’s problem. It could solve Trevor’s problem though.

#31 Updated by James Turnbull almost 3 years ago

  • Category set to facter
  • Assignee changed from Adrien Thebo to Anonymous

Daniel is going to grab Adrien to discuss.

#32 Updated by James Turnbull almost 3 years ago

  • Status changed from In Topic Branch Pending Review to Needs More Information

#33 Updated by Trevor Vaughan almost 3 years ago

What additional information is needed?

#34 Updated by Adrien Thebo over 2 years ago

Pardon the slow update. I attached a branch to this that should uniq the list of modules to check for facts, could you see if it solves the issue that you’re having with duplicate fact loading?

#35 Updated by Anonymous over 2 years ago

  • Status changed from Needs More Information to Merged - Pending Release
  • Target version changed from 2.7.x to 2.7.10

This has been reviewed, finally, and merged. Thanks.

#36 Updated by Matt Robinson over 2 years ago

  • Status changed from Merged - Pending Release to Needs More Information

From what I can tell the patch you just merged doesn’t actually fix the problem described. I just replicated the multiple loading of the facts with a similar setup to what Jeff described. The problem isn’t duplication in the module or fact paths. I tried this with just one directory in the modulepath (where I put the stdlib module) and STILL get multiple loads of the same path.

% puppet agent --test --modulepath=/tmp/facts1
The interpreter parameter to 'setcode' is deprecated and will be removed in a future version.
info: Loading facts in facter_dot_d
info: Loading facts in root_home
info: Loading facts in facter_dot_d
info: Loading facts in root_home
Could not retrieve root_home: private method `split' called for nil:NilClass
Could not retrieve root_home: private method `split' called for nil:NilClass
info: Caching catalog for facts
info: Applying configuration version '1326239227'
notice: Finished catalog run in 0.02 seconds

If I have stdlib in multiple directories in my modulepath I get two loads per dir in the path.

I looked into this because the code that was merged didn’t include any tests, and it wasn’t clear how it solved the problem. It obviously doesn’t.

#37 Updated by Matt Robinson over 2 years ago

Patrick and I were looking at this and came up with this quick patch (in attached branch) that seems to fix the issue – but it hasn’t been tested or thoroughly researched to look for side effects. All the specs pass, but I haven’t run the acceptance tests yet or done much manual testing besides a quick puppet run with nothing interesting in the manifest.

It basically boils down to not calling Puppet::Node::Facts::Facter.load_fact_plugins twice in two adjacent lines (indirectly on one line), and using require instead of load. This does have implications on order, but so did load and I’m not sure it was a conscious decision about what order to load things in.

#38 Updated by Jacob Helwig over 2 years ago

I’m guessing that https://github.com/mmrobins/puppet/tree/ticket/2.7.x/8341_multiple_facter_load is the branch you meant, Matt?

Looking at it, I don’t think using require to load the facts is what we want to do here. Pretty sure that would prevent the loaded fact’s code from updating if a new version is deployed via pluginsync, and would force restarting the agent to notice the change (pretty sure this was the original reason for using load).

#39 Updated by Matt Robinson over 2 years ago

  • Assignee changed from Anonymous to Patrick Carlisle

Yes, that’s the branch, thanks for updating.

I’m not entirely sure that require is right either, but it does make the multiple loads go away if you have the same fact in multiple places (modulepath, factspath, libdir). I think those directories that can contain facts should have some precedence order, and we should log when a plugin is either loaded multiple times or not loaded because it already has been from a different location. Also, I don’t think that the require vs load in lib/puppet/indirector/facts/facter.rb affects pluginsync since it has it’s method to load plugins after being synced lib/puppet/configurer/plugin_handler.rb:29.

I think more significant is fixing the multiple loading when you DON’T have a fact in multiple places, which is the the removal of the reload_facter call in the fact_handler.

I’m assigning this to Patrick since he was working with me on this yesterday and I have to get back to other code.

#40 Updated by Patrick Carlisle over 2 years ago

Even using load this code doesn’t work. Apparently the deleted code (reload_facter) was necessary to make sure facts are properly updated when your agent is a daemon.

#41 Updated by Patrick Carlisle over 2 years ago

  • Branch changed from https://github.com/adrienthebo/puppet/tree/ticket/2.7.x/8341-prevent_duplicate_loading_of_facts to https://github.com/pcarlisle/puppet/tree/8341_facts_load_once

I’ve just submitted a pull request at https://github.com/puppetlabs/puppet/pull/330 with an implementation that I think avoids those issues.

#42 Updated by Patrick Carlisle over 2 years ago

  • Status changed from Needs More Information to In Topic Branch Pending Review

#43 Updated by Anonymous over 2 years ago

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

#44 Updated by Michael Stahnke over 2 years ago

  • Status changed from Merged - Pending Release to Closed

released as part of 2.7.10rc1

#45 Updated by Charlie Sharpsteen over 1 year ago

  • Keywords changed from custom fact, repeated to custom fact, repeated customer

Also available in: Atom PDF