feat: provided opt-in debug logging (#490)

dazuma · web-flow · commit 5f97a26ca315 · 2024-12-05T11:51:14.000-08:00
diff --git a/googleauth.gemspec b/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"
diff --git a/lib/googleauth/base_client.rb b/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,9 @@ def expires_within?
         raise NoMethodError, "expires_within? not implemented"
       end
 
+      # The logger used to log operations on this client, such as token refresh.
+      attr_accessor :logger
+
       private
 
       def token_type
diff --git a/lib/googleauth/compute_engine.rb b/lib/googleauth/compute_engine.rb
@@ -96,35 +96,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: "Requesting id token from MDS with aud=#{target_audience}",
+              "credentialsId" => object_id
+            )
+          end
+        else
+          logger&.info do
+            Google::Logging::Message.from(
+              message: "Requesting access token from MDS",
+              "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
diff --git a/lib/googleauth/credentials.rb b/lib/googleauth/credentials.rb
@@ -337,10 +337,13 @@ def disable_universe_domain_check
       # @!attribute [rw] universe_domain
       #   @return [String] The universe domain issuing these credentials.
       #
+      # @!attribute [rw] logger
+      #   @return [Logger] The logger used to log credential operations such as token refresh.
+      #
       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
@@ -349,16 +352,17 @@ def disable_universe_domain_check
       # @param [String, Hash, Signet::OAuth2::Client] keyfile
       #   The keyfile can be provided as one of the following:
       #
-      #   * The path to a JSON keyfile (as a +String+)
-      #   * The contents of a JSON keyfile (as a +Hash+)
-      #   * A +Signet::OAuth2::Client+ object
+      #   * The path to a JSON keyfile (as a `String`)
+      #   * The contents of a JSON keyfile (as a `Hash`)
+      #   * A `Signet::OAuth2::Client` object
       # @param [Hash] options
       #   The options for configuring the credentials instance. The following is supported:
       #
-      #   * +:scope+ - the scope for the client
-      #   * +"project_id"+ (and optionally +"project"+) - the project identifier for the client
-      #   * +:connection_builder+ - the connection builder to use for the client
-      #   * +:default_connection+ - the default connection to use for the client
+      #   * `:scope` - the scope for the client
+      #   * `project_id` (and optionally `project`) - the project identifier for the client
+      #   * `:connection_builder` - the connection builder to use for the client
+      #   * `:default_connection` - the default connection to use for the client
+      #   * `:logger` - the logger used to log credential operations such as token refresh.
       #
       def initialize keyfile, options = {}
         verify_keyfile_provided! keyfile
@@ -373,8 +377,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
@@ -468,7 +472,8 @@ def self.from_io io, options
           audience:               options[:audience] || audience
         }
         client = Google::Auth::DefaultCredentials.make_creds creds_input
-        new client
+        options = options.select { |k, _v| k == :logger }
+        new client, options
       end
 
       private_class_method :from_env_vars,
@@ -549,6 +554,23 @@ def update_from_filepath path, options
         @quota_project_id ||= json["quota_project_id"]
         @client = init_client json, options
       end
+
+      def setup_logging logger: :default
+        return unless @client.respond_to? :logger=
+        logging_env = ENV["GOOGLE_SDK_RUBY_LOGGING_GEMS"].to_s.downcase
+        if ["false", "none"].include? logging_env
+          logger = nil
+        elsif @client.logger
+          logger = @client.logger
+        elsif logger == :default
+          logger = nil
+          if ["true", "all"].include?(logging_env) || logging_env.split(",").include?("googleauth")
+            formatter = Google::Logging::StructuredFormatter.new if Google::Cloud::Env.get.logging_agent_expected?
+            logger = Logger.new $stderr, progname: "googleauth", formatter: formatter
+          end
+        end
+        @client.logger = logger
+      end
     end
   end
 end
diff --git a/lib/googleauth/external_account/base_credentials.rb b/lib/googleauth/external_account/base_credentials.rb
@@ -129,18 +129,39 @@ def exchange_token
           if @client_id.nil? && @workforce_pool_user_project
             additional_options = { userProject: @workforce_pool_user_project }
           end
-          @sts_client.exchange_token(
+          token_request = {
             audience: @audience,
             grant_type: STS_GRANT_TYPE,
             subject_token: retrieve_subject_token!,
             subject_token_type: @subject_token_type,
             scopes: @service_account_impersonation_url ? IAM_SCOPE : @scope,
             requested_token_type: STS_REQUESTED_TOKEN_TYPE,
             additional_options: additional_options
-          )
+          }
+          log_token_request token_request
+          @sts_client.exchange_token token_request
+        end
+
+        def log_token_request token_request
+          logger&.info do
+            Google::Logging::Message.from(
+              message: "Requesting access token from #{token_request[:grant_type]}",
+              "credentialsId" => object_id
+            )
+          end
+          logger&.debug do
+            digest = Digest::SHA256.hexdigest token_request[:subject_token].to_s
+            loggable_request = token_request.merge subject_token: "(sha256:#{digest})"
+            Google::Logging::Message.from(
+              message: "Request data",
+              "request" => loggable_request,
+              "credentialsId" => object_id
+            )
+          end
         end
 
         def get_impersonated_access_token token, _options = {}
+          log_impersonated_token_request token
           response = connection.post @service_account_impersonation_url do |req|
             req.headers["Authorization"] = "Bearer #{token}"
             req.headers["Content-Type"] = "application/json"
@@ -153,6 +174,16 @@ def get_impersonated_access_token token, _options = {}
 
           MultiJson.load response.body
         end
+
+        def log_impersonated_token_request original_token
+          logger&.info do
+            digest = Digest::SHA256.hexdigest original_token
+            Google::Logging::Message.from(
+              message: "Requesting impersonated access token with original token (sha256:#{digest})",
+              "credentialsId" => object_id
+            )
+          end
+        end
       end
     end
   end
diff --git a/lib/googleauth/service_account.rb b/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
 
diff --git a/lib/googleauth/signet.rb b/lib/googleauth/signet.rb
diff --git a/spec/googleauth/apply_auth_examples.rb b/spec/googleauth/apply_auth_examples.rb
diff --git a/spec/googleauth/credentials_spec.rb b/spec/googleauth/credentials_spec.rb
