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

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,15 @@ def error(msg, colorize = false)
     def colorize(msg, color)
       "\e[#{color}m#{msg}\e[0m"
     end
+
+    private
+
+    def debugging_active?
+      if Facter.respond_to?(:debugging?)
+        Facter.debugging?
+      else
+        true
+      end
+    end
   end
 end

lib/util/file_helper.rb

@@ -10,12 +10,14 @@ class << self
         def safe_read(path, result_if_not_readable = '')
           return File.read(path) if File.readable?(path)
 
+          @log.debug(DEBUG_MESSAGE % path)
           result_if_not_readable
         end
 
         def safe_readlines(path, result_if_not_readable = [])
           return File.readlines(path) if File.readable?(path)
 
+          @log.debug(DEBUG_MESSAGE % path)
           result_if_not_readable
         end
       end

spec/facter/util/file_helper_spec.rb

@@ -80,11 +80,11 @@
         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(logger).to have_received(:debug).with(error_message)
+      end
     end
   end
 
@@ -142,11 +142,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(logger).to have_received(:debug).with(error_message)
+      end
     end
   end
 end

spec/framework/logging/logger_spec.rb

@@ -3,91 +3,125 @@
 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)
-
-    allow(file_logger_double).to receive(:formatter=)
   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