(FACT-2559) Fix Facter.debugging? call when Facter not fully loaded (#…

…455)

* (FACT-2559) added check if Facter.debugging? is loaded
* (FACT-2559) Fixed some tests leakage in logger_spec.rb
Added tests for when Facter is not fully loaded
* (FACT-2559) Created a context for when debugging is set to false
* (FACT-2559) refactored debugging_active?
* (FACT-2559) refactored file_helper.rb and file_helper_spec.rb
Added in logger_spec.rb removal of multi_logger_double
Co-authored-by: Andrei Filipovici <andrei.filipovici@andreis-mbp.eth.tsr.corp.puppet.net>
Co-authored-by: Bogdan Irimie <bogdan.irimie@puppet.com>

lib/framework/logging/logger.rb

@@ -65,7 +65,7 @@ def self.set_format_for_legacy_logger
     end
 
     def debug(msg)
-      return unless Facter.debugging?
+      return unless debugging_active?
 
       if msg.nil? || msg.empty?
         invoker = caller(1..1).first.slice(/.*:\d+/)
@@ -94,5 +94,13 @@ def error(msg, colorize = false)
     def colorize(msg, color)
       "\e[#{color}m#{msg}\e[0m"
     end
+
+    private
+
+    def debugging_active?
+      return true unless Facter.respond_to?(:debugging?)
+
+      Facter.debugging?
+    end
   end
 end

lib/util/file_helper.rb

@@ -4,19 +4,28 @@ module Facter
   module Util
     class FileHelper
       @log = Log.new(self)
+
       class << self
         DEBUG_MESSAGE = 'File at: %s is not accessible.'
 
-        def safe_read(path, result_if_not_readable = '')
+        def safe_read(path, default_return = '')
           return File.read(path) if File.readable?(path)
 
-          result_if_not_readable
+          log_failed_to_read(path)
+          default_return
         end
 
-        def safe_readlines(path, result_if_not_readable = [])
+        def safe_readlines(path, default_return = [])
           return File.readlines(path) if File.readable?(path)
 
-          result_if_not_readable
+          log_failed_to_read(path)
+          default_return
+        end
+
+        private
+
+        def log_failed_to_read(path)
+          @log.debug(DEBUG_MESSAGE % path)
         end
       end
     end

spec/facter/util/file_helper_spec.rb

@@ -3,15 +3,19 @@
 describe Facter::Util::FileHelper do
   subject(:file_helper) { Facter::Util::FileHelper }
 
-  let(:logger) { instance_spy(Facter::Log) }
   let(:path) { '/Users/admin/file.txt' }
   let(:content) { 'file content' }
-  let(:error_message) { 'File at: /Users/admin/file.txt is not accessible.' }
+  let(:error_message) { 'Facter::Util::FileHelper - File at: /Users/admin/file.txt is not accessible.' }
   let(:array_content) { ['line 1', 'line 2', 'line 3'] }
+  let(:multi_logger_double) { instance_spy(Facter::MultiLogger, level: :warn) }
 
   before do
-    file_helper.instance_variable_set(:@log, logger)
-    allow(logger).to receive(:debug).with(error_message)
+    Facter::Log.class_variable_set(:@@logger, multi_logger_double)
+    allow(Facter).to receive(:debugging?).and_return(true)
+  end
+
+  after do
+    Facter::Log.class_variable_set(:@@logger, Facter::MultiLogger.new([]))
   end
 
   shared_context 'when file is readable' do
@@ -53,7 +57,7 @@
       it "doesn't log anything" do
         file_helper.safe_read(path)
 
-        expect(logger).not_to have_received(:debug)
+        expect(multi_logger_double).not_to have_received(:debug)
       end
     end
 
@@ -80,11 +84,12 @@
         expect(File).not_to have_received(:read)
       end
 
-      # it 'logs a debug message' do
-      #   file_helper.safe_read(path)
-      #
-      #   expect(logger).to have_received(:debug).with(error_message)
-      # end
+      it 'logs a debug message' do
+        file_helper.safe_read(path)
+
+        expect(multi_logger_double).to have_received(:debug)
+          .with(error_message)
+      end
     end
   end
 
@@ -115,7 +120,7 @@
       it "doesn't log anything" do
         file_helper.safe_readlines(path)
 
-        expect(logger).not_to have_received(:debug)
+        expect(multi_logger_double).not_to have_received(:debug)
       end
     end
 
@@ -142,11 +147,11 @@
         expect(File).not_to have_received(:readlines)
       end
 
-      # it 'logs a debug message' do
-      #   file_helper.safe_read(path)
-      #
-      #   expect(logger).to have_received(:debug).with(error_message)
-      # end
+      it 'logs a debug message' do
+        file_helper.safe_read(path)
+
+        expect(multi_logger_double).to have_received(:debug).with(error_message)
+      end
     end
   end
 end

spec/framework/logging/logger_spec.rb

@@ -3,91 +3,129 @@
 describe Logger do
   subject(:log) { Facter::Log.new(Class) }
 
-  let(:file_logger_double) { instance_spy(Logger) }
   let(:multi_logger_double) { instance_spy(Facter::MultiLogger, level: :warn) }
 
   before do
-    Facter::Log.class_variable_set(:@@file_logger, file_logger_double)
     Facter::Log.class_variable_set(:@@logger, multi_logger_double)
+  end
 
-    allow(file_logger_double).to receive(:formatter=)
+  after do
+    Facter::Log.class_variable_set(:@@logger, Facter::MultiLogger.new([]))
   end
 
   describe '#debug' do
     before do
       allow(Facter).to receive(:debugging?).and_return(true)
     end
 
-    let(:handler) { instance_spy(Logger) }
+    context 'when debugging is set to false' do
+      it 'no debug messages are sent' do
+        allow(Facter).to receive(:debugging?).and_return(false)
+
+        log.debug('info_message')
 
-    it 'noops of debugging is not set' do
-      allow(Facter).to receive(:debugging?).and_return(false)
-      log.debug('info_message')
-      expect(multi_logger_double).not_to have_received(:debug)
+        expect(multi_logger_double).not_to have_received(:debug)
+      end
     end
 
     it 'logs a warn if message is nil' do
       log.debug(nil)
+
       expect(multi_logger_double).to have_received(:warn).with(/debug invoked with invalid message/)
     end
 
     it 'logs a warn if message is empty' do
       log.debug('')
+
       expect(multi_logger_double).to have_received(:warn).with(/debug invoked with invalid message/)
     end
 
-    it 'writes debug message' do
-      log.debug('debug_message')
-      expect(multi_logger_double).to have_received(:debug).with('Class - debug_message')
+    shared_examples 'writes debug message' do
+      it 'calls debug on multi_logger' do
+        log.debug('debug_message')
+
+        expect(multi_logger_double).to have_received(:debug).with('Class - debug_message')
+      end
     end
 
-    it 'provides on_message hook' do
-      Facter.on_message do |level, message|
-        handler.debug("on_message called with level: #{level}, message: #{message}")
+    it_behaves_like 'writes debug message'
+
+    context 'when message callback is provided' do
+      after do
+        Facter::Log.class_variable_set(:@@message_callback, nil)
       end
 
-      log.debug('test')
+      it 'provides on_message hook' do
+        logger_double = instance_spy(Logger)
+        Facter.on_message do |level, message|
+          logger_double.debug("on_message called with level: #{level}, message: #{message}")
+        end
+
+        log.debug('test')
 
-      expect(handler).to have_received(:debug).with('on_message called with level: debug, message: test')
+        expect(logger_double).to have_received(:debug).with('on_message called with level: debug, message: test')
+      end
+    end
+
+    context 'when call is made during os detection in os_detector.rb and facter.rb is not fully loaded' do
+      before do
+        allow(Facter).to receive(:respond_to?).with(:debugging?).and_return(false)
+      end
+
+      it_behaves_like 'writes debug message'
+
+      it 'does not call Facter.debugging?' do
+        log.debug('debug_message')
+
+        expect(Facter).not_to have_received(:debugging?)
+      end
     end
   end
 
   describe '#info' do
     it 'writes info message' do
       log.info('info_message')
+
       expect(multi_logger_double).to have_received(:info).with('Class - info_message')
     end
   end
 
   describe '#warn' do
     it 'writes warn message' do
       log.warn('warn_message')
+
       expect(multi_logger_double).to have_received(:warn).with('Class - warn_message')
     end
   end
 
   describe '#error' do
     it 'writes error message with color on macosx' do
       allow(OsDetector.instance).to receive(:detect).and_return(:macosx)
+
       log.error('error_message', true)
+
       expect(multi_logger_double).to have_received(:error).with("Class - \e[31merror_message\e[0m")
     end
 
     it 'writes error message not colorized on Windows' do
       allow(OsDetector.instance).to receive(:detect).and_return(:windows)
+
       log.error('error_message', true)
+
       expect(multi_logger_double).to have_received(:error).with('Class - error_message')
     end
 
     it 'writes error message' do
       log.error('error_message')
+
       expect(multi_logger_double).to have_received(:error).with('Class - error_message')
     end
   end
 
   describe '#level=' do
     it 'sets the log level' do
       Facter::Log.level = :error
+
       expect(multi_logger_double).to have_received(:level=).with(:error)
     end
   end