From be66e84c9c9a318978adff249610f68b956f5439 Mon Sep 17 00:00:00 2001
From: Sebastian Miclea <sebastian.miclea@puppet.com>
Date: Mon, 19 Oct 2020 12:06:45 +0300
Subject: [PATCH] (FACT-2815) Added timing for cached facts (#2134)

---
 lib/facter/framework/benchmarking/timer.rb    |  6 ++--
 lib/facter/framework/core/cache_manager.rb    |  5 +++-
 spec/facter/cache_manager_spec.rb             | 28 +++++++++++++++++++
 .../framework/benchmarking/timer_spec.rb      |  8 +++++-
 4 files changed, 43 insertions(+), 4 deletions(-)

diff --git a/lib/facter/framework/benchmarking/timer.rb b/lib/facter/framework/benchmarking/timer.rb
index cf3221539a..b483bfdc8d 100644
--- a/lib/facter/framework/benchmarking/timer.rb
+++ b/lib/facter/framework/benchmarking/timer.rb
@@ -7,11 +7,13 @@ module Framework
     module Benchmarking
       class Timer
         class << self
-          def measure(fact_name)
+          def measure(fact_name, prefix_message = '')
             if Options[:timing]
               time = Benchmark.measure { yield }
 
-              puts "fact `#{fact_name}`, took: #{time.format('%r')} seconds"
+              log = "fact '#{fact_name}', took: #{time.format('%r')} seconds"
+              prefix_message = "#{prefix_message} " unless prefix_message.empty?
+              puts "#{prefix_message}#{log}"
             else
               yield
             end
diff --git a/lib/facter/framework/core/cache_manager.rb b/lib/facter/framework/core/cache_manager.rb
index 33b9a8d6d6..ec945a8109 100644
--- a/lib/facter/framework/core/cache_manager.rb
+++ b/lib/facter/framework/core/cache_manager.rb
@@ -74,7 +74,10 @@ def resolve_fact(searched_fact)
     end
 
     def read_fact(searched_fact, fact_group)
-      data = read_group_json(fact_group)
+      data = nil
+      Facter::Framework::Benchmarking::Timer.measure(searched_fact.name, 'cached') do
+        data = read_group_json(fact_group)
+      end
       return unless data
 
       @log.debug("loading cached values for #{searched_fact.name} facts")
diff --git a/spec/facter/cache_manager_spec.rb b/spec/facter/cache_manager_spec.rb
index b38366054c..c45b6cab81 100644
--- a/spec/facter/cache_manager_spec.rb
+++ b/spec/facter/cache_manager_spec.rb
@@ -32,6 +32,7 @@
     allow(LegacyFacter::Util::Config).to receive(:facts_cache_dir).and_return(cache_dir)
     allow(Facter::FactGroups).to receive(:new).and_return(fact_groups)
     allow(Facter::Options).to receive(:[]).with(:debug).and_return(false)
+    allow(Facter::Options).to receive(:[])
   end
 
   describe '#resolve_facts' do
@@ -135,6 +136,33 @@
         )
       end
     end
+
+    context 'with timer' do
+      before do
+        allow(File).to receive(:directory?).and_return(true)
+        allow(fact_groups).to receive(:get_fact_group).and_return(group_name)
+        allow(fact_groups).to receive(:get_group_ttls).and_return(nil)
+        allow(fact_groups).to receive(:get_fact).and_return(nil)
+        allow(File).to receive(:readable?)
+        allow(File).to receive(:mtime).with(cache_file_name).and_return(Time.now)
+        allow(Facter::Util::FileHelper).to receive(:safe_read).with(cache_file_name).and_return(cached_core_fact)
+        allow(Facter::Options).to receive(:[]).with(:cache).and_return(true)
+        allow(Facter::Framework::Benchmarking::Timer).to receive(:measure)
+      end
+
+      it 'returns cached external facts' do
+        allow(fact_groups).to receive(:get_fact).with('os').and_return(nil)
+        allow(fact_groups).to receive(:get_fact).with('my_custom_fact').and_return(nil)
+        allow(fact_groups).to receive(:get_fact).with('ext_file.txt').and_return(external_fact)
+        allow(Facter::Util::FileHelper).to receive(:safe_read).with(File.join(cache_dir, 'ext_file.txt'))
+                                                              .and_return(cached_external_fact)
+        allow(File).to receive(:mtime).with(File.join(cache_dir, 'ext_file.txt')).and_return(Time.now)
+
+        cache_manager.resolve_facts(searched_facts)
+
+        expect(Facter::Framework::Benchmarking::Timer).to have_received(:measure)
+      end
+    end
   end
 
   describe '#cache_facts' do
diff --git a/spec/facter/framework/benchmarking/timer_spec.rb b/spec/facter/framework/benchmarking/timer_spec.rb
index 9e314cb5ee..45eb026c39 100644
--- a/spec/facter/framework/benchmarking/timer_spec.rb
+++ b/spec/facter/framework/benchmarking/timer_spec.rb
@@ -14,7 +14,13 @@
       it 'prints fact name and time it took to resolve it' do
         expect do
           Facter::Framework::Benchmarking::Timer.measure('my_fact') {}
-        end.to output("fact `my_fact`, took: (0.123) seconds\n").to_stdout
+        end.to output("fact 'my_fact', took: (0.123) seconds\n").to_stdout
+      end
+
+      it 'adds prefix to printed message' do
+        expect do
+          Facter::Framework::Benchmarking::Timer.measure('my_fact', 'my_custom_prefix') {}
+        end.to output("my_custom_prefix fact 'my_fact', took: (0.123) seconds\n").to_stdout
       end
     end