refactor: Added more logs to datafile manager (#260)

* Added more logs to datafile manager

* fixed lint error

* added unit tests

* fixed lint error

Author: zashraf1985

lib/optimizely/config_manager/http_project_config_manager.rb

@@ -148,16 +148,18 @@ def fetch_datafile_config
     end
 
     def request_config
-      @logger.log(
-        Logger::DEBUG,
-        "Fetching datafile from #{@datafile_url}"
-      )
-      begin
-        headers = {}
-        headers['Content-Type'] = 'application/json'
-        headers['If-Modified-Since'] = @last_modified if @last_modified
-        headers['Authorization'] = "Bearer #{@access_token}" unless @access_token.nil?
+      @logger.log(Logger::DEBUG, "Fetching datafile from #{@datafile_url}")
+      headers = {}
+      headers['Content-Type'] = 'application/json'
+      headers['If-Modified-Since'] = @last_modified if @last_modified
+      headers['Authorization'] = "Bearer #{@access_token}" unless @access_token.nil?
+
+      # Cleaning headers before logging to avoid exposing authorization token
+      cleansed_headers = {}
+      headers.each { |key, value| cleansed_headers[key] = key == 'Authorization' ? '********' : value }
+      @logger.log(Logger::DEBUG, "Datafile request headers: #{cleansed_headers}")
 
+      begin
         response = Helpers::HttpUtils.make_request(
           @datafile_url, :get, nil, headers, Helpers::Constants::CONFIG_MANAGER['REQUEST_TIMEOUT']
         )
@@ -169,6 +171,9 @@ def request_config
         return nil
       end
 
+      response_code = response.code.to_i
+      @logger.log(Logger::DEBUG, "Datafile response status code #{response_code}")
+
       # Leave datafile and config unchanged if it has not been modified.
       if response.code == '304'
         @logger.log(
@@ -178,9 +183,14 @@ def request_config
         return
       end
 
-      @last_modified = response[Helpers::Constants::HTTP_HEADERS['LAST_MODIFIED']]
-
-      config = DatafileProjectConfig.create(response.body, @logger, @error_handler, @skip_json_validation) if response.body
+      if response_code >= 200 && response_code < 400
+        @logger.log(Logger::DEBUG, 'Successfully fetched datafile, generating Project config')
+        config = DatafileProjectConfig.create(response.body, @logger, @error_handler, @skip_json_validation)
+        @last_modified = response[Helpers::Constants::HTTP_HEADERS['LAST_MODIFIED']]
+        @logger.log(Logger::DEBUG, "Saved last modified header value from response: #{@last_modified}.")
+      else
+        @logger.log(Logger::DEBUG, "Datafile fetch failed, status: #{response.code}, message: #{response.message}")
+      end
 
       config
     end

spec/config_manager/http_project_config_manager_spec.rb

@@ -47,7 +47,7 @@
           'Content-Type' => 'application/json'
         }
       )
-      .to_return(status: 403, body: '', headers: {})
+      .to_return(status: [403, 'Forbidden'], body: '', headers: {})
   end
 
   after(:example) do
@@ -236,7 +236,7 @@
       sleep 0.3
 
       expect(spy_logger).to have_received(:log).with(Logger::DEBUG, 'Fetching datafile from https://cdn.optimizely.com/datafiles/valid_sdk_key.json').once
-
+      expect(spy_logger).to have_received(:log).with(Logger::DEBUG, 'Datafile response status code 200').once
       expect(spy_logger).to have_received(:log).with(Logger::DEBUG, 'Received new datafile and updated config. ' \
         'Old revision number: 42. New revision number: 81.').once
 
@@ -361,6 +361,17 @@
 
       expect(spy_logger).to have_received(:log).once.with(Logger::ERROR, 'Invalid url_template https://cdn.optimizely.com/datafiles/%d.json provided.')
     end
+
+    it 'Should log failure message with status code when failed to fetch datafile' do
+      @http_project_config_manager = Optimizely::HTTPProjectConfigManager.new(
+        url: 'https://cdn.optimizely.com/datafiles/invalid_sdk_key.json',
+        sdk_key: 'valid_sdk_key',
+        datafile_access_token: 'the-token',
+        logger: spy_logger
+      )
+      sleep 0.1
+      expect(spy_logger).to have_received(:log).with(Logger::DEBUG, 'Datafile fetch failed, status: 403, message: Forbidden').once
+    end
   end
 
   describe '.polling_interval' do
@@ -504,5 +515,16 @@
       sleep 0.1
       expect(Optimizely::Helpers::HttpUtils).to have_received(:make_request).with('http://awesomeurl', any_args)
     end
+
+    it 'should hide access token when printing logs' do
+      allow(Optimizely::Helpers::HttpUtils).to receive(:make_request)
+      @http_project_config_manager = Optimizely::HTTPProjectConfigManager.new(
+        sdk_key: 'valid_sdk_key',
+        datafile_access_token: 'the-token',
+        logger: spy_logger
+      )
+      sleep 0.1
+      expect(spy_logger).to have_received(:log).with(Logger::DEBUG, 'Datafile request headers: {"Content-Type"=>"application/json", "Authorization"=>"********"}').once
+    end
   end
 end