update debug logs to mask password (#1902)

* update debug logs to mask password. passing the object to be logged into the Utility method was causing change in context, so bloating object logs & causing tests to fail. to address this, text substitution is run on pre-defined log string in same context. Signed-off-by: Vikram Karve <vikram.karve@progress.com>
test-kitchen · Jul 4, 2022 · 01603b9 · 01603b9
1 parent 4fa99c3
commit 01603b9
Show file tree

Hide file tree

Showing 5 changed files with 59 additions and 15 deletions.
diff --git a/lib/kitchen/ssh.rb b/lib/kitchen/ssh.rb
@@ -23,6 +23,7 @@ module Net
 
 require_relative "errors"
 require_relative "login_command"
+require_relative "util"
 
 module Kitchen
   # Wrapped exception for any internally raised SSH-related errors.
@@ -75,7 +76,9 @@ def initialize(hostname, username, options = {})
     # @param cmd [String] command string to execute
     # @raise [SSHFailed] if the command does not exit with a 0 code
     def exec(cmd)
-      logger.debug("[SSH] #{self} (#{cmd})")
+      string_to_mask = "[SSH] #{self} (#{cmd})"
+      masked_string = Util.mask_values(string_to_mask, %w{password ssh_http_proxy_password})
+      logger.debug(masked_string)
       exit_code = exec_with_exit(cmd)
 
       if exit_code != 0
@@ -137,7 +140,9 @@ def upload_path(local, remote, options = {}, &progress)
     def shutdown
       return if @session.nil?
 
-      logger.debug("[SSH] closing connection to #{self}")
+      string_to_mask = "[SSH] closing connection to #{self}"
+      masked_string = Util.mask_values(string_to_mask, %w{password ssh_http_proxy_password})
+      logger.debug(masked_string)
       session.shutdown!
     ensure
       @session = nil
@@ -212,7 +217,9 @@ def establish_connection
       retries = options[:ssh_retries] || 3
 
       begin
-        logger.debug("[SSH] opening connection to #{self}")
+        string_to_mask = "[SSH] opening connection to #{self}"
+        masked_string = Util.mask_values(string_to_mask, %w{password ssh_http_proxy_password})
+        logger.debug(masked_string)
         Net::SSH.start(hostname, username, options)
       rescue *rescue_exceptions => e
         retries -= 1

diff --git a/lib/kitchen/transport/ssh.rb b/lib/kitchen/transport/ssh.rb
@@ -16,6 +16,7 @@
 # limitations under the License.
 
 require_relative "../../kitchen"
+require_relative "../util"
 
 require "fileutils" unless defined?(FileUtils)
 require "net/ssh" unless defined?(Net::SSH)
@@ -102,7 +103,9 @@ def connection(state, &block)
       # (see Base#cleanup!)
       def cleanup!
         if @connection
-          logger.debug("[SSH] shutting previous connection #{@connection}")
+          string_to_mask = "[SSH] shutting previous connection #{@connection}"
+          masked_string = Util.mask_values(string_to_mask, %w{password ssh_http_proxy_password})
+          logger.debug(masked_string)
           @connection.close
           @connection = @connection_options = nil
         end
@@ -125,7 +128,9 @@ def initialize(config = {})
         def close
           return if @session.nil?
 
-          logger.debug("[SSH] closing connection to #{self}")
+          string_to_mask = "[SSH] closing connection to #{self}"
+          masked_string = Util.mask_values(string_to_mask, %w{password ssh_http_proxy_password})
+          logger.debug(masked_string)
           session.close
         ensure
           @session = nil
@@ -135,7 +140,9 @@ def close
         def execute(command)
           return if command.nil?
 
-          logger.debug("[SSH] #{self} (#{command})")
+          string_to_mask = "[SSH] #{self} (#{command})"
+          masked_string = Util.mask_values(string_to_mask, %w{password ssh_http_proxy_password})
+          logger.debug(masked_string)
           exit_code = execute_with_exit_code(command)
 
           if exit_code != 0
@@ -352,7 +359,9 @@ def establish_connection(opts)
         def retry_connection(opts)
           log_msg = "[SSH] opening connection to #{self}"
           log_msg += " via #{ssh_gateway_username}@#{ssh_gateway}:#{ssh_gateway_port}" if ssh_gateway
-          logger.debug(log_msg)
+          masked_string = Util.mask_values(log_msg, %w{password ssh_http_proxy_password})
+
+          logger.debug(masked_string)
           yield
         rescue *RESCUE_EXCEPTIONS_ON_ESTABLISH => e
           if (opts[:retries] -= 1) > 0
@@ -541,7 +550,7 @@ def verify_host_key_value
       # Creates a new SSH Connection instance and save it for potential future
       # reuse.
       #
-      # @param options [Hash] conneciton options
+      # @param options [Hash] connection options
       # @return [Ssh::Connection] an SSH Connection instance
       # @api private
       def create_new_connection(options, &block)
@@ -555,7 +564,9 @@ def create_new_connection(options, &block)
       # @return [Ssh::Connection] an SSH Connection instance
       # @api private
       def reuse_connection
-        logger.debug("[SSH] reusing existing connection #{@connection}")
+        string_to_mask = "[SSH] reusing existing connection #{@connection}"
+        masked_string = Util.mask_values(string_to_mask, %w{password ssh_http_proxy_password})
+        logger.debug(masked_string)
         yield @connection if block_given?
         @connection
       end

diff --git a/lib/kitchen/transport/winrm.rb b/lib/kitchen/transport/winrm.rb
@@ -20,6 +20,7 @@
 require "rbconfig" unless defined?(RbConfig)
 require "uri" unless defined?(URI)
 require_relative "../../kitchen"
+require_relative "../util"
 require "winrm" unless defined?(WinRM::Connection)
 require "winrm/exceptions" unless defined?(WinRM::WinRMHTTPTransportError)
 
@@ -104,7 +105,9 @@ def close
         def execute(command)
           return if command.nil?
 
-          logger.debug("[WinRM] #{self} (#{command})")
+          string_to_mask = "[WinRM] #{self} (#{command})"
+          masked_string = Util.mask_values(string_to_mask, %w{password ssh_http_proxy_password})
+          logger.debug(masked_string)
 
           exit_code, stderr = execute_with_exit_code(command)
 
@@ -494,12 +497,14 @@ def additional_transport_args(data, transport_type)
       # Creates a new WinRM Connection instance and save it for potential
       # future reuse.
       #
-      # @param options [Hash] conneciton options
+      # @param options [Hash] connection options
       # @return [Ssh::Connection] a WinRM Connection instance
       # @api private
       def create_new_connection(options, &block)
         if @connection
-          logger.debug("[WinRM] shutting previous connection #{@connection}")
+          string_to_mask = "[WinRM] shutting previous connection #{@connection}"
+          masked_string = Util.mask_values(string_to_mask, %w{password ssh_http_proxy_password})
+          logger.debug(masked_string)
           @connection.close
         end
 
@@ -559,7 +564,9 @@ def host_os_windows?
       # @return [Winrm::Connection] a WinRM Connection instance
       # @api private
       def reuse_connection
-        logger.debug("[WinRM] reusing existing connection #{@connection}")
+        string_to_mask = "[WinRM] reusing existing connection #{@connection}"
+        masked_string = Util.mask_values(string_to_mask, %w{password ssh_http_proxy_password})
+        logger.debug(masked_string)
         yield @connection if block_given?
         @connection
       end

diff --git a/lib/kitchen/util.rb b/lib/kitchen/util.rb
@@ -88,6 +88,19 @@ def self.stringified_hash(obj)
       end
     end
 
+    # Returns a string with masked values for specified parameters.
+    #
+    # @param string_to_mask [String] the object whose string representation is parsed
+    # @param [Array] the list of keys whose values should be masked
+    # @return [String] the string representation of passed object with masked values
+    def self.mask_values(string_to_mask, keys)
+      masked_string = string_to_mask
+      keys.each do |key|
+        masked_string.gsub!(/:#{key}=>"([^"]*)"/, %{:#{key}=>"******"})
+      end
+      masked_string
+    end
+
     # Returns a formatted string representing a duration in seconds.
     #
     # @param total [Integer] the total number of seconds

diff --git a/spec/kitchen/transport/winrm_spec.rb b/spec/kitchen/transport/winrm_spec.rb
@@ -955,8 +955,11 @@ def fatal_line_with(msg)
       it "logger displays command on debug" do
         connection.execute("doit")
 
+        string_to_mask = "[WinRM] #{info} (doit)"
+        masked_string = Kitchen::Util.mask_values(string_to_mask, %w{password ssh_http_proxy_password})
+
         _(logged_output.string).must_match debug_line(
-          "[WinRM] #{info} (doit)"
+          masked_string
         )
       end
 
@@ -1092,8 +1095,11 @@ def self.common_failed_command_specs
             # the raise is not what is being tested here, rather its side-effect
           end
 
+          string_to_mask = "[WinRM] #{info} (doit)"
+          masked_string = Kitchen::Util.mask_values(string_to_mask, %w{password ssh_http_proxy_password})
+
           _(logged_output.string).must_match debug_line(
-            "[WinRM] #{info} (doit)"
+            masked_string
           )
         end