feat: provided opt-in debug logging

.rubocop.yml

@@ -6,10 +6,14 @@ AllCops:
     - "integration/**/*"
     - "spec/**/*"
     - "test/**/*"
+Metrics/BlockLength:
+  Exclude:
+    - "googleauth.gemspec"
 Metrics/ClassLength:
   Max: 200
+Metrics/CyclomaticComplexity:
+  Max: 12
 Metrics/ModuleLength:
   Max: 110
-Metrics/BlockLength:
-  Exclude:
-    - "googleauth.gemspec"
+Metrics/PerceivedComplexity:
+  Max: 12

googleauth.gemspec

@@ -23,7 +23,8 @@ Gem::Specification.new do |gem|
   gem.required_ruby_version = ">= 2.7"
 
   gem.add_dependency "faraday", ">= 1.0", "< 3.a"
-  gem.add_dependency "google-cloud-env", "~> 2.1"
+  gem.add_dependency "google-cloud-env", "~> 2.2"
+  gem.add_dependency "google-logging-utils", "~> 0.1"
   gem.add_dependency "jwt", ">= 1.4", "< 3.0"
   gem.add_dependency "multi_json", "~> 1.11"
   gem.add_dependency "os", ">= 0.9", "< 2.0"

lib/googleauth/base_client.rb

@@ -12,6 +12,8 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+require "google/logging/message"
+
 module Google
   # Module Auth provides classes that provide Google-specific authorization
   # used to access Google APIs.
@@ -29,7 +31,12 @@ def apply! a_hash, opts = {}
         # fetch the access token there is currently not one, or if the client
         # has expired
         fetch_access_token! opts if needs_access_token?
-        a_hash[AUTH_METADATA_KEY] = "Bearer #{send token_type}"
+        token = send token_type
+        a_hash[AUTH_METADATA_KEY] = "Bearer #{token}"
+        logger&.debug do
+          hash = Digest::SHA256.hexdigest token
+          Google::Logging::Message.from message: "Sending auth token. (sha256:#{hash})"
+        end
       end
 
       # Returns a clone of a_hash updated with the authentication token
@@ -66,6 +73,8 @@ def expires_within?
         raise NoMethodError, "expires_within? not implemented"
       end
 
+      attr_accessor :logger
+
       private
 
       def token_type

lib/googleauth/compute_engine.rb

@@ -91,35 +91,71 @@ def initialize options = {}
       # Overrides the super class method to change how access tokens are
       # fetched.
       def fetch_access_token _options = {}
-        if token_type == :id_token
-          query = { "audience" => target_audience, "format" => "full" }
-          entry = "service-accounts/default/identity"
-        else
-          query = {}
-          entry = "service-accounts/default/token"
-        end
+        query, entry =
+          if token_type == :id_token
+            [{ "audience" => target_audience, "format" => "full" }, "service-accounts/default/identity"]
+          else
+            [{}, "service-accounts/default/token"]
+          end
         query[:scopes] = Array(scope).join "," if scope
         begin
+          log_fetch_query
           resp = Google::Cloud.env.lookup_metadata_response "instance", entry, query: query
+          log_fetch_resp resp
           case resp.status
           when 200
             build_token_hash resp.body, resp.headers["content-type"], resp.retrieval_monotonic_time
           when 403, 500
-            msg = "Unexpected error code #{resp.status} #{UNEXPECTED_ERROR_SUFFIX}"
-            raise Signet::UnexpectedStatusError, msg
+            raise Signet::UnexpectedStatusError, "Unexpected error code #{resp.status} #{UNEXPECTED_ERROR_SUFFIX}"
           when 404
             raise Signet::AuthorizationError, NO_METADATA_SERVER_ERROR
           else
-            msg = "Unexpected error code #{resp.status} #{UNEXPECTED_ERROR_SUFFIX}"
-            raise Signet::AuthorizationError, msg
+            raise Signet::AuthorizationError, "Unexpected error code #{resp.status} #{UNEXPECTED_ERROR_SUFFIX}"
           end
         rescue Google::Cloud::Env::MetadataServerNotResponding => e
+          log_fetch_err e
           raise Signet::AuthorizationError, e.message
         end
       end
 
       private
 
+      def log_fetch_query
+        if token_type == :id_token
+          logger&.info do
+            Google::Logging::Message.from(
+              message: "Querying MDS for id token with aud=#{target_audience}",
+              "credentialsId" => object_id
+            )
+          end
+        else
+          logger&.info do
+            Google::Logging::Message.from(
+              message: "Querying MDS for auth token",
+              "credentialsId" => object_id
+            )
+          end
+        end
+      end
+
+      def log_fetch_resp resp
+        logger&.info do
+          Google::Logging::Message.from(
+            message: "Received #{resp.status} from MDS",
+            "credentialsId" => object_id
+          )
+        end
+      end
+
+      def log_fetch_err _err
+        logger&.info do
+          Google::Logging::Message.from(
+            message: "MDS did not respond to token request",
+            "credentialsId" => object_id
+          )
+        end
+      end
+
       def build_token_hash body, content_type, retrieval_time
         hash =
           if ["text/html", "application/text"].include? content_type

lib/googleauth/credentials.rb

@@ -331,10 +331,13 @@ def self.lookup_local_constant name
       # @!attribute [rw] universe_domain
       #   @return [String] The universe domain issuing these credentials.
       #
+      # @!attribute [rw] logger
+      #   @return [Logger] A logger.
+      #
       def_delegators :@client,
                      :token_credential_uri, :audience,
                      :scope, :issuer, :signing_key, :updater_proc, :target_audience,
-                     :universe_domain, :universe_domain=
+                     :universe_domain, :universe_domain=, :logger, :logger=
 
       ##
       # Creates a new Credentials instance with the provided auth credentials, and with the default
@@ -367,8 +370,8 @@ def initialize keyfile, options = {}
         else
           update_from_filepath keyfile, options
         end
+        setup_logging logger: options.fetch(:logger, :default)
         @project_id ||= CredentialsLoader.load_gcloud_project_id
-        @client.fetch_access_token! if @client.needs_access_token?
         @env_vars = nil
         @paths = nil
         @scope = nil
@@ -543,6 +546,22 @@ def update_from_filepath path, options
         @quota_project_id ||= json["quota_project_id"]
         @client = init_client json, options
       end
+
+      def setup_logging logger: :default
+        logging_env = ENV["GOOGLE_SDK_DEBUG_LOGGING"].to_s.downcase
+        return if !logger || !@client.respond_to?(:logger=) || logging_env == "false"
+        if logger == :default
+          return unless logging_env == "true"
+          gems = ENV["GOOGLE_SDK_DEBUG_LOGGING_RUBYGEMS"]
+          return if gems && !gems.split(",").include?("googleauth")
+          level = ENV["GOOGLE_SDK_DEBUG_LOGGING_RUBY_LEVEL"] || "DEBUG"
+          level = "DEBUG" unless Logger.const_defined? level
+          level = Logger.const_get level
+          formatter = Google::Logging::StructuredFormatter.new if Google::Cloud::Env.get.logging_agent_expected?
+          logger = Logger.new $stderr, progname: "googleauth", level: level, formatter: formatter
+        end
+        @client.logger = logger
+      end
     end
   end
 end

lib/googleauth/service_account.rb

@@ -12,6 +12,7 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+require "google/logging/message"
 require "googleauth/signet"
 require "googleauth/credentials_loader"
 require "googleauth/json_key_reader"
@@ -123,6 +124,7 @@ def apply_self_signed_jwt! a_hash
         }
         key_io = StringIO.new MultiJson.dump(cred_json)
         alt = ServiceAccountJwtHeaderCredentials.make_creds json_key_io: key_io, scope: scope
+        alt.logger = logger
         alt.apply! a_hash
       end
     end
@@ -147,6 +149,7 @@ class ServiceAccountJwtHeaderCredentials
       attr_reader :project_id
       attr_reader :quota_project_id
       attr_accessor :universe_domain
+      attr_accessor :logger
 
       # Create a ServiceAccountJwtHeaderCredentials.
       #
@@ -187,10 +190,14 @@ def apply! a_hash, opts = {}
         return a_hash if jwt_aud_uri.nil? && @scope.nil?
         jwt_token = new_jwt_token jwt_aud_uri, opts
         a_hash[AUTH_METADATA_KEY] = "Bearer #{jwt_token}"
+        logger&.debug do
+          hash = Digest::SHA256.hexdigest jwt_token
+          Google::Logging::Message.from message: "Sending JWT auth token. (sha256:#{hash})"
+        end
         a_hash
       end
 
-      # Returns a clone of a_hash updated with the authoriation header
+      # Returns a clone of a_hash updated with the authorization header
       def apply a_hash, opts = {}
         a_copy = a_hash.clone
         apply! a_copy, opts
@@ -219,6 +226,10 @@ def new_jwt_token jwt_aud_uri = nil, options = {}
         assertion["scope"] = Array(@scope).join " " if @scope
         assertion["aud"] = jwt_aud_uri if jwt_aud_uri
 
+        logger&.debug do
+          Google::Logging::Message.from message: "JWT assertion: #{assertion}"
+        end
+
         JWT.encode assertion, @signing_key, SIGNING_ALGORITHM
       end
 

lib/googleauth/signet.rb

@@ -61,6 +61,24 @@ def fetch_access_token! options = {}
         info
       end
 
+      alias googleauth_orig_generate_access_token_request generate_access_token_request
+      def generate_access_token_request options = {}
+        parameters = googleauth_orig_generate_access_token_request options
+        logger&.info do
+          Google::Logging::Message.from(
+            message: "Requesting auth token from #{parameters['grant_type']}",
+            "credentialsId" => object_id
+          )
+        end
+        logger&.debug do
+          Google::Logging::Message.from(
+            message: "Token fetch params: #{parameters}",
+            "credentialsId" => object_id
+          )
+        end
+        parameters
+      end
+
       def build_default_connection
         if !defined?(@connection_info)
           nil
@@ -75,20 +93,70 @@ def retry_with_error max_retry_count = 5
         retry_count = 0
 
         begin
-          yield
+          yield.tap { |resp| log_response resp }
         rescue StandardError => e
-          raise e if e.is_a?(Signet::AuthorizationError) || e.is_a?(Signet::ParseError)
+          if e.is_a?(Signet::AuthorizationError) || e.is_a?(Signet::ParseError)
+            log_auth_error e
+            raise e
+          end
 
           if retry_count < max_retry_count
+            log_transient_error e
             retry_count += 1
             sleep retry_count * 0.3
             retry
           else
+            log_retries_exhausted e
             msg = "Unexpected error: #{e.inspect}"
             raise Signet::AuthorizationError, msg
           end
         end
       end
+
+      private
+
+      def log_response token_response
+        response_hash = JSON.parse token_response rescue {}
+        if response_hash["access_token"]
+          digest = Digest::SHA256.hexdigest response_hash["access_token"]
+          response_hash["access_token"] = "(sha256:#{digest})"
+        end
+        if response_hash["id_token"]
+          digest = Digest::SHA256.hexdigest response_hash["id_token"]
+          response_hash["id_token"] = "(sha256:#{digest})"
+        end
+        Google::Logging::Message.from(
+          message: "Received auth token response: #{response_hash}",
+          "credentialsId" => object_id
+        )
+      end
+
+      def log_auth_error err
+        logger&.info do
+          Google::Logging::Message.from(
+            message: "Auth error when fetching auth token: #{err}",
+            "credentialsId" => object_id
+          )
+        end
+      end
+
+      def log_transient_error err
+        logger&.info do
+          Google::Logging::Message.from(
+            message: "Transient error when fetching auth token: #{err}",
+            "credentialsId" => object_id
+          )
+        end
+      end
+
+      def log_retries_exhausted err
+        logger&.info do
+          Google::Logging::Message.from(
+            message: "Exhausted retries when fetching auth token: #{err}",
+            "credentialsId" => object_id
+          )
+        end
+      end
     end
   end
 end

spec/googleauth/compute_engine_spec.rb

@@ -81,10 +81,11 @@ def make_auth_stubs opts
     it "returns a consistent expiry using cached data" do
       make_auth_stubs access_token: "1/abcde"
       @client.fetch_access_token!
-      expiry = @client.expires_at
-      sleep 1
+      expiry1 = @client.expires_at.to_f
+      sleep 3
       @client.fetch_access_token!
-      expect(@client.expires_at.to_f).to be_within(0.1).of(expiry.to_f)
+      expiry2 = @client.expires_at.to_f
+      expect(expiry2).to be_within(1.0).of(expiry1)
     end
   end