(maint) Fix trace acceptance test (#405)

* (maint) Fix trace acceptance test
* (maint) Move logging of arguments to cli_launcher.
* (maint) Include first argument when printing facter arguments.
* (maint) Read trace from options

Co-authored-by: Bogdan Irimie <bogdan.irimie@puppet.com>

lib/custom_facts/core/resolvable.rb

@@ -62,26 +62,23 @@ def flush
       def value
         result = nil
 
-        @logger = Facter::Log.new(self)
         with_timing do
           Timeout.timeout(limit) do
             result = resolve_value
           end
         end
 
         LegacyFacter::Util::Normalization.normalize(result)
-      rescue Timeout::Error
-        @logger.error("Timed out after #{limit} seconds while resolving #{qualified_name}")
+      rescue Timeout::Error => e
+        Facter.log_exception(e, "Timed out after #{limit} seconds while resolving #{qualified_name}")
 
         nil
       rescue LegacyFacter::Util::Normalization::NormalizationError => e
-        @logger.error("Fact resolution #{qualified_name} resolved to an invalid value: #{e.message}")
+        Facter.log_exception(e, "Fact resolution #{qualified_name} resolved to an invalid value: #{e.message}")
 
         nil
       rescue StandardError => e
-        puts @logger.inspect
-
-        @logger.error("Error while resolving custom fact #{qualified_name}: #{e.message}")
+        Facter.log_exception(e, "Error while resolving custom fact #{qualified_name}: #{e.message}")
 
         raise Facter::ResolveCustomFactError
       end

lib/facter.rb

@@ -14,6 +14,7 @@ class ResolveCustomFactError < StandardError; end
   Log.add_legacy_logger(STDOUT)
   @logger = Log.new(self)
   @already_searched = {}
+  @trace = false
 
   class << self
     def clear_messages
@@ -201,7 +202,7 @@ def to_hash
     #
     # @api public
     def trace?
-      LegacyFacter.trace?
+      @trace
     end
 
     # Enable or disable trace
@@ -212,6 +213,7 @@ def trace?
     # @api public
     def trace(bool)
       LegacyFacter.trace(bool)
+      @trace = bool
     end
 
     # Gets the value for a fact. Returns `nil` if no such fact exists.
@@ -256,6 +258,21 @@ def to_user_output(cli_options, *args)
       [fact_formatter.format(resolved_facts), status || 0]
     end
 
+    def log_exception(exception, message = :default)
+      arr = []
+      if message == :default
+        arr << exception.message
+      elsif message
+        arr << message
+      end
+      if @trace
+        arr << 'backtrace:'
+        arr.concat(exception.backtrace)
+      end
+
+      @logger.error(arr.flatten.join("\n"))
+    end
+
     private
 
     def add_fact_to_searched_facts(user_query, value)

lib/framework/core/options/helper_options.rb

@@ -16,7 +16,7 @@ def augment_with_helper_options!(user_query)
       validate_log_level
 
       Log.level = @options[:log_level]
-      LegacyFacter.trace(@options[:trace])
+      Facter.trace(@options[:trace])
     end
 
     private

spec/custom_facts/core/resolvable_spec.rb

@@ -15,8 +15,6 @@ def initialize(name)
 
   subject(:resolvable) { ResolvableClass.new('resolvable') }
 
-  let(:logger) { instance_double(Facter::Log) }
-
   it 'has a default timeout of 0 seconds' do
     expect(resolvable.limit).to eq 0
   end
@@ -39,13 +37,10 @@ def initialize(name)
       expect(resolvable.value).to eq('stuff')
     end
 
-    it 'logs a warning if an exception was raised' do
-      allow(Facter::Log).to receive(:new).and_return(logger)
-      resolvable.instance_variable_set(:@logger, logger)
-
-      expect(resolvable).to receive(:resolve_value).and_raise RuntimeError, 'kaboom!'
-      expect(resolvable.logger).to receive(:error)
-        .with("Error while resolving custom fact fact='stub fact', " \
+    it 'logs a error if an exception was raised' do
+      allow(resolvable).to receive(:resolve_value).and_raise RuntimeError, 'kaboom!'
+      expect(Facter).to receive(:log_exception)
+        .with(RuntimeError, "Error while resolving custom fact fact='stub fact', " \
           "resolution='resolvable': kaboom!")
       expect { resolvable.value }.to raise_error(Facter::ResolveCustomFactError)
     end
@@ -61,10 +56,7 @@ def initialize(name)
     end
 
     it 'returns nil if the timeout was reached' do
-      allow(Facter::Log).to receive(:new).and_return(logger)
-      resolvable.instance_variable_set(:@logger, logger)
-
-      expect(resolvable.logger).to receive(:error).with(/Timed out after 0\.1 seconds while resolving/)
+      expect(Facter).to receive(:log_exception).with(Timeout::Error, /Timed out after 0\.1 seconds while resolving/)
       expect(Timeout).to receive(:timeout).and_raise Timeout::Error
 
       resolvable.timeout = 0.1

spec/facter/facter_spec.rb

@@ -12,8 +12,10 @@
     fact_collection
   end
   let(:empty_fact_collection) { Facter::FactCollection.new }
+  let(:logger) { instance_spy(Facter::Log) }
 
   before do
+    Facter.instance_variable_set(:@logger, logger)
     Facter.clear
     allow(Facter::CacheManager).to receive(:invalidate_all_caches)
   end
@@ -79,6 +81,8 @@
       end
 
       it 'returns no fact and status 1' do
+        allow(logger).to receive(:error).with('fact "os.name" does not exist.', true)
+
         user_query = 'os.name'
         expected_json_output = '{}'
 
@@ -286,17 +290,19 @@
     end
   end
 
-  describe '#trace' do
-    it 'sends call to LegacyFacter' do
-      expect(LegacyFacter).to receive(:trace).with(true).once
-      Facter.trace(true)
+  describe '#trace?' do
+    it 'returns trace variable' do
+      expect(Facter).not_to be_trace
     end
   end
 
-  describe '#trace?' do
-    it 'sends call to LegacyFacter' do
-      expect(LegacyFacter).to receive(:trace?).once
-      Facter.trace?
+  describe '#trace' do
+    after do
+      Facter.trace(false)
+    end
+
+    it 'trace variable is true' do
+      expect(Facter.trace(true)).to be_truthy
     end
   end
 
@@ -311,7 +317,7 @@
       let(:is_debug) { true }
 
       it 'logs a debug message' do
-        expect_any_instance_of(Facter::Log).to receive(:debug).with(message)
+        allow(logger).to receive(:debug).with('test')
         expect(Facter.debug(message)).to be(nil)
       end
     end
@@ -345,4 +351,26 @@
       Facter.debugging?
     end
   end
+
+  describe '#log_exception' do
+    context 'when trace options is true' do
+      before do
+        Facter.trace(true)
+      end
+
+      after do
+        Facter.trace(false)
+      end
+
+      let(:message) { 'Some error message' }
+      let(:exception) { FlushFakeError.new }
+      let(:expected_message) { "Some error message\nbacktrace:\nprog.rb:2:in `a'" }
+
+      it 'format exception to display backtrace' do
+        exception.set_backtrace("prog.rb:2:in `a'")
+        Facter.log_exception(exception, message)
+        expect(logger).to have_received(:error).with(expected_message)
+      end
+    end
+  end
 end