Jira (FACT-3170) Debug output on Windows nodes shows the same Facter logs repeated

21 views
Skip to first unread message

Taika Augustaitis (Jira)

unread,
Dec 15, 2022, 3:58:02 PM12/15/22
to puppe...@googlegroups.com
Taika Augustaitis updated an issue
 
Facter / Improvement FACT-3170
Debug output on Windows nodes shows the same Facter logs repeated
Change By: Taika Augustaitis
Summary: Debug output on Windows nodes shows the same Facter logs repeated
Add Comment Add Comment
 
This message was sent by Atlassian Jira (v8.20.11#820011-sha1:0629dd8)
Atlassian logo

Selvakumar Azhagarsami (Jira)

unread,
Dec 28, 2022, 10:01:03 PM12/28/22
to puppe...@googlegroups.com
Selvakumar Azhagarsami updated an issue
Change By: Selvakumar Azhagarsami
Attachment: agent720.log

Alvin Rodis (Jira)

unread,
Dec 28, 2022, 10:02:01 PM12/28/22
to puppe...@googlegroups.com
Alvin Rodis updated an issue
Change By: Alvin Rodis
Zendesk Ticket Count: 1
Zendesk Ticket IDs: 50176

Selvakumar Azhagarsami (Jira)

unread,
Dec 28, 2022, 10:02:02 PM12/28/22
to puppe...@googlegroups.com
Selvakumar Azhagarsami updated an issue
Change By: Selvakumar Azhagarsami
Attachment: agent720.log

Alvin Rodis (Jira)

unread,
Dec 28, 2022, 10:02:03 PM12/28/22
to puppe...@googlegroups.com
Alvin Rodis updated an issue
Change By: Alvin Rodis
Labels: jira_escalated

Alvin Rodis (Jira)

unread,
Dec 28, 2022, 10:04:03 PM12/28/22
to puppe...@googlegroups.com
Alvin Rodis updated an issue
Change By: Alvin Rodis
Zendesk Ticket Count: 1 2
Zendesk Ticket IDs: 50176 ,50537

Morgan Rhodes (Jira)

unread,
Jan 3, 2023, 4:28:01 PM1/3/23
to puppe...@googlegroups.com
Morgan Rhodes updated an issue
Change By: Morgan Rhodes
Team: Phoenix

Josh Cooper (Jira)

unread,
Jan 4, 2023, 12:15:02 PM1/4/23
to puppe...@googlegroups.com
Josh Cooper updated an issue
Change By: Josh Cooper
Epic Link: PUP-11658

Josh Cooper (Jira)

unread,
Jan 4, 2023, 5:48:02 PM1/4/23
to puppe...@googlegroups.com
Josh Cooper commented on Improvement FACT-3170
 
Re: Debug output on Windows nodes shows the same Facter logs repeated

This issue is due a change in behavior in Facter 4's implementation of Facter.value(:name). Previously, fact value were only resolved once (until Facter.flush or Facter.clear are next called). But now facts are resolved each time the Facter.value method is called. Facter 4 has behaved this way for a long time, likely since 4.0. But the problem is only really noticeable when managing a large number of resources whose providers are confined based on facts.

This greatly affects Windows, since file, exec, service, package, registry_*, etc are all confined based on the "operatingsystem" fact. But it also affects user, group, service, package for AIX, macOS, Solaris, SLES, as can be seen by these builtin providers:

$ git grep -r -E 'confine\s*:?(osfamily|operatingsystem)' lib/puppet/provider
 
lib/puppet/provider/exec/windows.rb:  confine    :operatingsystem => :windows
 
lib/puppet/provider/file/windows.rb:  confine :operatingsystem => :windows
 
lib/puppet/provider/group/aix.rb:  confine :operatingsystem => :aix
 
lib/puppet/provider/group/directoryservice.rb:  confine :operatingsystem => :darwin
 
lib/puppet/provider/group/pw.rb:  confine    :operatingsystem => [:freebsd, :dragonfly]
 
lib/puppet/provider/group/windows_adsi.rb:  confine    :operatingsystem => :windows
 
lib/puppet/provider/nameservice/directoryservice.rb:  confine :operatingsystem => :darwin
 
lib/puppet/provider/package/aix.rb:  confine  :operatingsystem => [ :aix ]
 
lib/puppet/provider/package/appdmg.rb:  confine :operatingsystem => :darwin
 
lib/puppet/provider/package/apple.rb:  confine :operatingsystem => :darwin
 
lib/puppet/provider/package/blastwave.rb:  confine :osfamily => :solaris
 
lib/puppet/provider/package/freebsd.rb:  confine :operatingsystem => :freebsd
 
lib/puppet/provider/package/hpux.rb:  confine :operatingsystem => "hp-ux"
 
lib/puppet/provider/package/macports.rb:  confine :operatingsystem => :darwin
 
lib/puppet/provider/package/openbsd.rb:  confine :operatingsystem => :openbsd
 
lib/puppet/provider/package/opkg.rb:  confine     :operatingsystem => :openwrt
 
lib/puppet/provider/package/pacman.rb:  confine     :operatingsystem => [:archlinux, :manjarolinux]
 
lib/puppet/provider/package/pkg.rb:  confine :osfamily => :solaris
 
lib/puppet/provider/package/pkgdmg.rb:  confine :operatingsystem => :darwin
 
lib/puppet/provider/package/pkgng.rb:  confine :operatingsystem => [:freebsd, :dragonfly]
 
lib/puppet/provider/package/pkgutil.rb:  confine :osfamily => :solaris
 
lib/puppet/provider/package/portage.rb:  confine :osfamily => :gentoo
 
lib/puppet/provider/package/rug.rb:  confine    :operatingsystem => [:suse, :sles]
 
lib/puppet/provider/package/sun.rb:  confine :osfamily => :solaris
 
lib/puppet/provider/package/sunfreeware.rb:  confine :osfamily => :solaris
 
lib/puppet/provider/package/up2date.rb:  confine    :osfamily => :redhat
 
lib/puppet/provider/package/windows.rb:  confine    :operatingsystem => :windows
 
lib/puppet/provider/package/zypper.rb:  confine    :operatingsystem => [:suse, :sles, :sled, :opensuse]
 
lib/puppet/provider/service/bsd.rb:  confine :operatingsystem => [:freebsd, :dragonfly]
 
lib/puppet/provider/service/freebsd.rb:  confine :operatingsystem => [:freebsd, :dragonfly]
 
lib/puppet/provider/service/gentoo.rb:  confine :operatingsystem => :gentoo
 
lib/puppet/provider/service/launchd.rb:  confine :operatingsystem    => :darwin
 
lib/puppet/provider/service/openbsd.rb:  confine :operatingsystem => :openbsd
 
lib/puppet/provider/service/openwrt.rb:  confine :operatingsystem => :openwrt
 
lib/puppet/provider/service/rcng.rb:  confine :operatingsystem => [:netbsd, :cargos]
 
lib/puppet/provider/service/smf.rb:  confine :osfamily => :solaris
 
lib/puppet/provider/service/src.rb:  confine :operatingsystem => :aix
 
lib/puppet/provider/service/windows.rb:  confine    :operatingsystem => :windows
 
lib/puppet/provider/user/aix.rb:  confine :operatingsystem => :aix
 
lib/puppet/provider/user/directoryservice.rb:  confine    :operatingsystem => :darwin
 
lib/puppet/provider/user/hpux.rb:  confine :operatingsystem => "hp-ux"
 
lib/puppet/provider/user/openbsd.rb:  confine    :operatingsystem => :openbsd
 
lib/puppet/provider/user/pw.rb:  confine    :operatingsystem => [:freebsd, :dragonfly]
 
lib/puppet/provider/user/windows_adsi.rb:  confine    :operatingsystem => :windows

It also affects modules with custom providers, for example:

puppetlabs-acl/lib/puppet/provider/acl/windows.rb:  confine operatingsystem: :windows
 
puppetlabs-apt/lib/puppet/provider/apt_key/apt_key.rb:  confine    osfamily: :debian
 
puppetlabs-cem_linux/lib/puppet/provider/cem_authselect_manage_profile/default.rb:  confine operatingsystemmajrelease: '8'
 
puppetlabs-chocolatey/lib/puppet/provider/package/chocolatey.rb:  confine     operatingsystem: :windows
 
puppetlabs-chocolatey/lib/puppet/provider/chocolateyfeature/windows.rb:  confine operatingsystem: :windows
 
puppetlabs-chocolatey/lib/puppet/provider/chocolateysource/windows.rb:  confine operatingsystem: :windows
 
puppetlabs-chocolatey/lib/puppet/provider/chocolateyconfig/windows.rb:  confine operatingsystem: :windows
 
puppetlabs-registry/lib/puppet/provider/registry_key/registry.rb:  confine    operatingsystem: :windows
 
puppetlabs-registry/lib/puppet/provider/registry_value/registry.rb:  confine    operatingsystem: :windows
 
puppetlabs-sqlserver/lib/puppet/provider/sqlserver.rb:  confine operatingsystem: :windows
 
puppet-network/lib/puppet/provider/network_config/interfaces.rb:  confine osfamily: :debian
 
puppet-network/lib/puppet/provider/network_config/redhat.rb:  confine osfamily: :redhat
 
puppet-network/lib/puppet/provider/network_route/redhat.rb:  confine osfamily: :redhat
 
puppet-network/lib/puppet/provider/network_route/routes.rb:  confine osfamily: :debian
 
puppet-windows_firewall/lib/puppet/provider/windowsfirewall/powershell.rb:  confine operatingsystem: :windows

Note Facter.to_hash and Facter.resolve also behave differently. In Facter 3.x, facts are only resolved once:

irb(main):007:0> Facter.to_hash(); nil
 
2023-01-04 22:28:18.727024 DEBUG puppetlabs.facter - loading external fact directories from config file
 
2023-01-04 22:28:18.727145 DEBUG leatherman.file_util:65 - Error reading file: No such file or directory
 
=> nil
 
irb(main):008:0> Facter.to_hash(); nil
 
2023-01-04 22:28:22.558322 DEBUG puppetlabs.facter - loading external fact directories from config file
 
2023-01-04 22:28:22.558393 DEBUG leatherman.file_util:65 - Error reading file: No such file or directory
 
=> nil
 
irb(main):009:0> Facter.resolve(''); nil
 
2023-01-04 22:28:31.646363 DEBUG puppetlabs.facter - loading external fact directories from config file
 
2023-01-04 22:28:31.646443 DEBUG leatherman.file_util:65 - Error reading file: No such file or directory
 
=> nil
 
irb(main):010:0> Facter.resolve(''); nil
 
2023-01-04 22:28:33.285717 DEBUG puppetlabs.facter - loading external fact directories from config file
 
2023-01-04 22:28:33.285813 DEBUG leatherman.file_util:65 - Error reading file: No such file or directory
 
=> nil

Whereas Facter 4 resolves all facts each time:

irb(main):013:0> Facter.to_hash; nil
 
D, [2023-01-04T22:31:53.742708 #9711] DEBUG -- : Facter - Facter version: 4.2.14
 
D, [2023-01-04T22:31:53.742829 #9711] DEBUG -- : Facter::FactLoader - Loading all internal facts
 
D, [2023-01-04T22:31:53.742917 #9711] DEBUG -- : Facter::FactLoader - Loading custom facts
 
D, [2023-01-04T22:31:53.742941 #9711] DEBUG -- : Facter::FactLoader - Loading external facts
 
D, [2023-01-04T22:31:53.743710 #9711] DEBUG -- : Facts::Linux::Hypervisors::Vmware - Vmware hypervisor detected
 
D, [2023-01-04T22:31:53.743763 #9711] DEBUG -- : Facts::Linux::Hypervisors::Xen - No Xen hypervisor detected.
 
D, [2023-01-04T22:31:53.743796 #9711] DEBUG -- : Facts::Linux::Hypervisors::Kvm - Detected product name: VMware Virtual Platform
 
D, [2023-01-04T22:31:53.743815 #9711] DEBUG -- : Facts::Linux::Hypervisors::Kvm - Detected hypervisor vmware
 
D, [2023-01-04T22:31:53.743831 #9711] DEBUG -- : Facts::Linux::Hypervisors::Kvm - Detected product name: VMware Virtual Platform
 
D, [2023-01-04T22:31:53.743846 #9711] DEBUG -- : Facts::Linux::Hypervisors::Kvm - Detected bios vendor: Phoenix Technologies LTD
 
D, [2023-01-04T22:31:53.744944 #9711] DEBUG -- : Facts::Linux::Virtual - Linux Virtual Resolver
 
D, [2023-01-04T22:31:53.744979 #9711] DEBUG -- : Facts::Linux::Virtual - Fact value is: vmware
 
D, [2023-01-04T22:31:53.745130 #9711] DEBUG -- : Facter::FactManager - fact "os.family" has resolved to: RedHat
 
D, [2023-01-04T22:31:53.745151 #9711] DEBUG -- : Facter::FactManager - fact "osfamily" has resolved to: RedHat
 
D, [2023-01-04T22:31:53.745173 #9711] DEBUG -- : Facter::FactManager - fact "os.distro.release" has resolved to: {"full"=>"8.0", "major"=>"8", "minor"=>"0"}
 
.. many lines deleted ..
 
 
 
irb(main):014:0> Facter.to_hash; nil
 
D, [2023-01-04T22:32:21.293120 #9711] DEBUG -- : Facter - Facter version: 4.2.14
 
D, [2023-01-04T22:32:21.293261 #9711] DEBUG -- : Facter::FactLoader - Loading all internal facts
 
D, [2023-01-04T22:32:21.293351 #9711] DEBUG -- : Facter::FactLoader - Loading custom facts
 
D, [2023-01-04T22:32:21.293376 #9711] DEBUG -- : Facter::FactLoader - Loading external facts
 
D, [2023-01-04T22:32:21.294203 #9711] DEBUG -- : Facts::Linux::Hypervisors::Vmware - Vmware hypervisor detected
 
D, [2023-01-04T22:32:21.294268 #9711] DEBUG -- : Facts::Linux::Hypervisors::Xen - No Xen hypervisor detected.
 
D, [2023-01-04T22:32:21.294309 #9711] DEBUG -- : Facts::Linux::Hypervisors::Kvm - Detected product name: VMware Virtual Platform
 
D, [2023-01-04T22:32:21.294328 #9711] DEBUG -- : Facts::Linux::Hypervisors::Kvm - Detected hypervisor vmware
 
D, [2023-01-04T22:32:21.294344 #9711] DEBUG -- : Facts::Linux::Hypervisors::Kvm - Detected product name: VMware Virtual Platform
 
D, [2023-01-04T22:32:21.294361 #9711] DEBUG -- : Facts::Linux::Hypervisors::Kvm - Detected bios vendor: Phoenix Technologies LTD
 
D, [2023-01-04T22:32:21.295550 #9711] DEBUG -- : Facts::Linux::Virtual - Linux Virtual Resolver
 
D, [2023-01-04T22:32:21.295582 #9711] DEBUG -- : Facts::Linux::Virtual - Fact value is: vmware
 
D, [2023-01-04T22:32:21.295740 #9711] DEBUG -- : Facter::FactManager - fact "os.family" has resolved to: RedHat
 
D, [2023-01-04T22:32:21.295760 #9711] DEBUG -- : Facter::FactManager - fact "osfamily" has resolved to: RedHat
 
D, [2023-01-04T22:32:21.295782 #9711] DEBUG -- : Facter::FactManager - fact "os.distro.release" has resolved to: {"full"=>"8.0", "major"=>"8", "minor"=>"0"}
 
.. many lines deleted ..

Also note, when resolving legacy facts, Facter 4 calls the resolver for the structured fact, e.g. ruby.platform, and again for each legacy alias, e.g. rubyplatform

D, [2023-01-04T22:28:03.180249 #9711] DEBUG -- : Facter::FactManager - fact "ruby.platform" has resolved to: x86_64-linux
 
D, [2023-01-04T22:28:03.180263 #9711] DEBUG -- : Facter::FactManager - fact "rubyplatform" has resolved to: x86_64-linux

Josh Cooper (Jira)

unread,
Jan 4, 2023, 5:57:03 PM1/4/23
to puppe...@googlegroups.com
Josh Cooper commented on Improvement FACT-3170

This can also be verified using:

# cat bug.rb 
require 'facter'
 
 
 
set_trace_func proc { |event, file, line, id, binding, classname|
 
  if event == 'call' && classname == Facts::Rhel::Os::Name
 
    printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname
 
  end
 
}
 
 
 
[0, 1, 2].each do |i|
 
  puts Facter.value(:operatingsystem)  
end
 
 
 
# /opt/puppetlabs/puppet/bin/ruby bug.rb 
    call /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/facter/facts/rhel/os/name.rb:10 call_the_resolver Facts::Rhel::Os::Name
 
RedHat
 
    call /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/facter/facts/rhel/os/name.rb:10 call_the_resolver Facts::Rhel::Os::Name
 
RedHat
 
    call /opt/puppetlabs/puppet/lib/ruby/vendor_ruby/facter/facts/rhel/os/name.rb:10 call_the_resolver Facts::Rhel::Os::Name
 
RedHat

Josh Cooper (Jira)

unread,
Jan 9, 2023, 12:36:02 PM1/9/23
to puppe...@googlegroups.com
Josh Cooper updated an issue
Change By: Josh Cooper
Labels: jira_escalated regression
Reply all
Reply to author
Forward
0 new messages