Move mixlib-auth debugging to trace level

Gemfile

@@ -3,5 +3,5 @@ gemspec
 
 group(:development) do
   gem "pry"
-  gem "mixlib-log"
+  gem "mixlib-log", '~> 2'
 end

lib/mixlib/authentication/http_authentication_request.rb

@@ -72,7 +72,7 @@ def request_signature
         unless @request_signature
           @request_signature = headers.find_all { |h| h[0].to_s =~ /^x_ops_authorization_/ }
             .sort { |x, y| x.to_s[/\d+/].to_i <=> y.to_s[/\d+/].to_i }.map { |i| i[1] }.join("\n")
-          Mixlib::Authentication::Log.debug "Reconstituted (user-supplied) request signature: #{@request_signature}"
+          Mixlib::Authentication::Log.trace "Reconstituted (user-supplied) request signature: #{@request_signature}"
         end
         @request_signature
       end

lib/mixlib/authentication/null_logger.rb

@@ -4,15 +4,15 @@ module NullLogger
 
       attr_accessor :level
 
-      %i{debug info warn error fatal}.each do |method_name|
+      %i{trace debug info warn error fatal}.each do |method_name|
         class_eval(<<-METHOD_DEFN, __FILE__, __LINE__)
           def #{method_name}(msg=nil, &block)
             true
           end
         METHOD_DEFN
       end
 
-      %i{debug? info? warn? error? fatal?}.each do |method_name|
+      %i{trace? debug? info? warn? error? fatal?}.each do |method_name|
         class_eval(<<-METHOD_DEFN, __FILE__, __LINE__)
           def #{method_name}
             false

lib/mixlib/authentication/signatureverification.rb

@@ -76,7 +76,7 @@ def authenticate_user_request(request, user_lookup, time_skew = (15 * 60))
       # X-Ops-Content-Hash:
       # X-Ops-Authorization-#{line_number}
       def authenticate_request(user_secret, time_skew = (15 * 60))
-        Mixlib::Authentication.logger.debug "Initializing header auth : #{request.inspect}"
+        Mixlib::Authentication.logger.trace "Initializing header auth : #{request.inspect}"
 
         @user_secret       = user_secret
         @allowed_time_skew = time_skew # in seconds
@@ -149,15 +149,15 @@ def verify_signature(algorithm, version)
                              (request_decrypted_block == candidate_block)
                            end
 
-        # Keep the debug messages lined up so it's easy to scan them
-        Mixlib::Authentication.logger.debug("Verifying request signature:")
-        Mixlib::Authentication.logger.debug(" Expected Block is: '#{candidate_block}'")
-        Mixlib::Authentication.logger.debug("Decrypted block is: '#{request_decrypted_block}'")
-        Mixlib::Authentication.logger.debug("Signatures match? : '#{@valid_signature}'")
+        # Keep the trace messages lined up so it's easy to scan them
+        Mixlib::Authentication.logger.trace("Verifying request signature:")
+        Mixlib::Authentication.logger.trace(" Expected Block is: '#{candidate_block}'")
+        Mixlib::Authentication.logger.trace("Decrypted block is: '#{request_decrypted_block}'")
+        Mixlib::Authentication.logger.trace("Signatures match? : '#{@valid_signature}'")
 
         @valid_signature
       rescue => e
-        Mixlib::Authentication.logger.debug("Failed to verify request signature: #{e.class.name}: #{e.message}")
+        Mixlib::Authentication.logger.trace("Failed to verify request signature: #{e.class.name}: #{e.message}")
         @valid_signature = false
       end
 
@@ -168,10 +168,10 @@ def verify_timestamp
       def verify_content_hash
         @valid_content_hash = (content_hash == hashed_body)
 
-        # Keep the debug messages lined up so it's easy to scan them
-        Mixlib::Authentication.logger.debug("Expected content hash is: '#{hashed_body}'")
-        Mixlib::Authentication.logger.debug(" Request Content Hash is: '#{content_hash}'")
-        Mixlib::Authentication.logger.debug("           Hashes match?: #{@valid_content_hash}")
+        # Keep the trace messages lined up so it's easy to scan them
+        Mixlib::Authentication.logger.trace("Expected content hash is: '#{hashed_body}'")
+        Mixlib::Authentication.logger.trace(" Request Content Hash is: '#{content_hash}'")
+        Mixlib::Authentication.logger.trace("           Hashes match?: #{@valid_content_hash}")
 
         @valid_content_hash
       end
@@ -211,11 +211,11 @@ def hashed_body(digest = Digest::SHA1)
           # Any file that's included in the request is hashed if it's there. Otherwise,
           # we hash the body.
           if file_param
-            Mixlib::Authentication.logger.debug "Digesting file_param: '#{file_param.inspect}'"
+            Mixlib::Authentication.logger.trace "Digesting file_param: '#{file_param.inspect}'"
             @hashed_body = digester.hash_file(file_param, digest)
           else
             body = request.raw_post
-            Mixlib::Authentication.logger.debug "Digesting body: '#{body}'"
+            Mixlib::Authentication.logger.trace "Digesting body: '#{body}'"
             @hashed_body = digester.hash_string(body, digest)
           end
         end
@@ -232,7 +232,7 @@ def hashed_body(digest = Digest::SHA1)
       def timestamp_within_bounds?(time1, time2)
         time_diff = (time2 - time1).abs
         is_allowed = (time_diff < @allowed_time_skew)
-        Mixlib::Authentication.logger.debug "Request time difference: #{time_diff}, within #{@allowed_time_skew} seconds? : #{!!is_allowed}"
+        Mixlib::Authentication.logger.trace "Request time difference: #{time_diff}, within #{@allowed_time_skew} seconds? : #{!!is_allowed}"
         is_allowed
       end
     end

lib/mixlib/authentication/signedheaderauth.rb

@@ -115,7 +115,7 @@ def sign(private_key, sign_algorithm = algorithm, sign_version = proto_version)
           header_hash[key] = signature_lines[idx]
         end
 
-        Mixlib::Authentication.logger.debug "Header hash: #{header_hash.inspect}"
+        Mixlib::Authentication.logger.trace "Header hash: #{header_hash.inspect}"
 
         header_hash
       end
@@ -236,7 +236,7 @@ def parse_signing_description
           memo[field_name.to_sym] = field_value.strip
           memo
         end
-        Mixlib::Authentication.logger.debug "Parsed signing description: #{parts.inspect}"
+        Mixlib::Authentication.logger.trace "Parsed signing description: #{parts.inspect}"
         parts
       end
 
@@ -247,7 +247,7 @@ def digester
       # private
       def do_sign(private_key, digest, sign_algorithm, sign_version)
         string_to_sign = canonicalize_request(sign_algorithm, sign_version)
-        Mixlib::Authentication.logger.debug "String to sign: '#{string_to_sign}'"
+        Mixlib::Authentication.logger.trace "String to sign: '#{string_to_sign}'"
         case sign_version
         when "1.3"
           private_key.sign(digest.new, string_to_sign)

spec/mixlib/authentication/mixlib_authentication_spec.rb

@@ -63,7 +63,7 @@ def read(len, out_str)
 end
 
 # Uncomment this to get some more info from the methods we're testing.
-#Mixlib::Authentication.logger.level = :debug
+#Mixlib::Authentication.logger.level = :trace
 
 describe "Mixlib::Authentication::SignedHeaderAuth" do
 

spec/mixlib/authentication/mixlib_log_missing_spec.rb

@@ -25,7 +25,7 @@
       expect(Mixlib::Authentication::Log.level).to eq(:error)
     end
 
-    %w{debug info warn error fatal}.each do |level|
+    %w{trace debug info warn error fatal}.each do |level|
       it "logs at level #{level}" do
         expect(Mixlib::Authentication::Log).to receive(level).with("foo")
 
@@ -44,9 +44,9 @@
         .to include(Mixlib::Log)
     end
 
-    %w{debug info warn error fatal}.each do |level|
+    %w{trace debug info warn error fatal}.each do |level|
       it "forward #{level} to mixlib-log" do
-        expect(Mixlib::Authentication::Log.logger).to receive(level).with("foo")
+        expect_any_instance_of(Mixlib::Log).to receive(level).with("foo")
 
         Mixlib::Authentication.logger.send(level, "foo")
       end