[PUP-2927] Facter logs should be surfaced during Puppet runs Created: 2014/07/11  Updated: 2016/10/19  Resolved: 2014/12/03

Status: Closed
Project: Puppet
Component/s: None
Affects Version/s: PUP 3.6.2
Fix Version/s: PUP 4.0.0

Type: New Feature Priority: Major
Reporter: Charlie Sharpsteen Assignee: Unassigned
Resolution: Fixed Votes: 0
Labels: customer, facter, logging
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Blocks
is blocked by FACT-750 Add pluggable logging Closed
Duplicate
is duplicated by PUP-3518 Configure facter to log using the pup... Closed
Relates
Template:
Epic Link: JSON All The Things!
Story Points: 2
Sprint: Platform Client 2014-12-17
QA Contact: Erik Dasher

 Description   

Information logged by Hiera is forwarded to Puppet loggers when Hiera is running as part of a Puppet process. Facter should do the same thing.

For Facter, this is especially critical since custom facts contain arbitrary user-written code that can have a variety of side effects — including halting the entire process. Without access to Facter logging info, even when Puppet is running with --debug verbosity, all the user can determine is that the Puppet agent died with doing... something.



 Comments   
Comment by Charlie Sharpsteen [ 2014/07/30 ]

Kylo Ginsberg: Any thoughts about getting this one into Facter 2.2? Not getting log output during Puppet runs makes it really difficult to track down some classes of bugs.

Comment by Andrew Parker [ 2014/10/27 ]

Shouldn't this be a facter ticket? And then have a ticket for Puppet to use the new facility?

Comment by Kylo Ginsberg [ 2014/10/27 ]

I agree, sounds like this needs a matching facter ticket.

Why is this in the 'JSON All the Things!' epic? I'm missing something.

Comment by Andrew Parker [ 2014/10/27 ]

I added it to "JSON All the Things" because I noticed that the message the facter produces when it hits non-UTF-8 facts doesn't go through puppet's logging system, which means that it wouldn't make it into a report. I was thinking that part of making a good user experience for "JSON All the Things" would be to include logs about when non-UTF-8 data is hit. Can't do this for the master side, but it should be doable for the agent side.

Comment by Kylo Ginsberg [ 2014/10/27 ]

Adding a little more context about how hiera handles pluggable logging:
1) Hiera can be told what logger to use: https://github.com/puppetlabs/hiera/blob/1.3.4/lib/hiera.rb#L16-L36
2 ) Hiera has a few, including a puppet logger: https://github.com/puppetlabs/hiera/blob/master/lib/hiera/puppet_logger.rb
3) Puppet tells hiera to use itself as logger: https://github.com/puppetlabs/puppet/blob/master/lib/hiera_puppet.rb#L65

Peter Huene any thoughts on the cleanest way to add pluggable logging to facter in such a way that it will also work with facter 3 (cfacter)?

(Yes, the facter side of this should ultimately be farmed out to a facter ticket once we sort out when we can do what.)

Comment by Peter Huene [ 2014/10/27 ]

I'd like us to avoid making Puppet calls from Facter (ugh!). I think Facter::Core::Logging should be extended to register a callback interface that has methods corresponding to the log levels (in facter it's just debug and warn; in cfacter it's trace, debug, warn, error, and fatal). Puppet would implement this interface and pass through the calls into the corresponding Puppet methods and register it with Facter. That's something we can easily implement in Ruby and C++.

Comment by Peter Huene [ 2014/11/17 ]

As I now have Facter logging going through Puppet's log, do we want Puppet's --debug to enable Facter's debug output? Facter 2.x doesn't have the most useful debug messages, but cfacter has lots of potentially useful information in debug messages (but it might get pretty verbose).

Kylo Ginsberg Eric Sorenson thoughts?

Comment by Peter Huene [ 2014/11/17 ]

Should we set Facter's trace option with Puppet's --trace?

Comment by Peter Huene [ 2014/11/17 ]

Kylo Ginsberg by the way, I started work on this ticket for testing out the Facter ticket; it's under my pup/2927 branch.

If we decide to enable debugging/trace, I'll add the corresponding methods to cfacter's Ruby API.

Comment by Kylo Ginsberg [ 2014/11/17 ]

Yes, offhand I'd think:

  • if puppet is emitting warning messages, then it emits facter warning messages (and higher)
  • if puppet is emitting debug messages, then it emits facter debug messages (and higher)

Re native facter verbosity, I'm inclined to try it this way and then tweak it if we find it's just too chatty.

Re trace, I'm less sure. I think it'd be valuable to set trace for facter if it's set for puppet. But not sure what that would mean for native facter .... Thoughts?

Comment by Peter Huene [ 2014/11/17 ]

For native facter, I think we can make it mean what it currently means for Ruby facter: Ruby stack traces are printed. Currently native facter's Ruby API will always log stack traces, so it's treating this option as always on. We don't print stack traces for native exceptions currently since there's no good cross-platform way I know of doing so.

Native facter currently supports a "--trace" option, but it means "enable trace level output" (highest verbosity). I think we should rename that option to something else and treat "--trace" as "print stack traces for custom fact exceptions" for parity with Ruby facter.

Comment by Eric Sorenson [ 2014/11/17 ]

Yes, setting debug on Puppet ought to invoke facter with debugging enabled.

If it didn't, how else would you enable it?

Comment by Eric Sorenson [ 2014/11/21 ]

Kylo Ginsberg could you add a point estimate to this please? From the comments, it seems like it's underway already too, should it be past "ready for engineering"?

Comment by Kylo Ginsberg [ 2014/11/21 ]

Peter Huene since you demo'd this I'm going to consider this "In Progress" and assign it to you

Comment by Peter Huene [ 2014/12/02 ]

For FR:

With a facter or cfacter out of their respective master, ensure that --debug and --trace are respected when passed to Puppet.

I used a custom fact that logs debug/warning messages and also throws exceptions to test.

Note with testing with facter: the easiest way to activate Puppet with Facter out of master is to point the bundle at facter's source directory:

$ export FACTER_LOCATION='file:///<path_to_facter_directory>'
$ bundle install
$ bundle exec puppet ...

Note for testing with cfacter: cfacter needs to be installed into the system (make install) and the gem needs to be present for Puppet. The easiest way to do the latter is to create a Gemfile.local for Puppet containing the following:

gem 'cfacter', :path => '<full_path_to_cfacter_directory>/gem'

Then:

$ bundle install
$ bundle exec puppet apply --cfacter ...

Comment by Michael Smith [ 2014/12/03 ]

Tried various combinations of custom facts

Facter.add('test') do
  setcode do
    'foo'
  end
end
 
Facter.add('err') do
  setcode do
    raise "Because I can"
  end
end
 
Facter.add('nil') do
  setcode do
    nil
  end
end
 
Facter.add('

Warnings and errors were always displayed, and --trace showed the backtrace when raising an exception.

Could also use --debug output to track down why nothing appeared on stdout when trying to echo facts. Looks good.

Generated at Sat Feb 22 15:11:19 PST 2020 using JIRA 7.7.1#77002-sha1:e75ca93d5574d9409c0630b81c894d9065296414.