feat: add debug logging support (#1903)

* feat: add debug logging support

* build: add google-logging-utils in a temporary fashion

* build: undo unintentional package.json changes

* fix: move makeLog calls into shared classes for the most part

* fix: update to anticipated release version of logger

* fix: fix possible merging errors from earlier

* fix: more potential merging issues

* fix: more rearranging to match the older ordering

* fix: merging two months of changes is sometimes trying

* fix: very work in progress for switching to using interceptor and symbol based logs

* fix: catch all exceptions, finish piping in method names

* fix: various self-review updates

* chore: put back missing comma

* fix: update log name back to the original

* fix: rejection interceptors must re-throw errors

* chore: fix various reversions

* chore: fix more linter issues

* chore: remove extraneous makeLog

* tests: add interceptor response shared tests

* tests: add logging tests to interceptors

* tests: lint fixes

Author: feywind

package.json

@@ -21,6 +21,7 @@
     "ecdsa-sig-formatter": "^1.0.11",
     "gaxios": "^7.0.0-rc.4",
     "gcp-metadata": "^7.0.0-rc.1",
+    "google-logging-utils": "^1.0.0",
     "gtoken": "^8.0.0-rc.1",
     "jws": "^4.0.0"
   },

src/auth/authclient.ts

@@ -17,9 +17,17 @@ import {Gaxios, GaxiosOptions, GaxiosPromise, GaxiosResponse} from 'gaxios';
 
 import {Credentials} from './credentials';
 import {OriginalAndCamel, originalOrCamelOptions} from '../util';
+import {log as makeLog} from 'google-logging-utils';
 
 import {PRODUCT_NAME, USER_AGENT} from '../shared.cjs';
 
+/**
+ * Easy access to symbol-indexed strings on config objects.
+ */
+export type SymbolIndexString = {
+  [key: symbol]: string | undefined;
+};
+
 /**
  * Base auth configurations (e.g. from JWT or `.json` files) with conventional
  * camelCased options.
@@ -210,6 +218,16 @@ export abstract class AuthClient
   forceRefreshOnFailure = false;
   universeDomain = DEFAULT_UNIVERSE;
 
+  /**
+   * Symbols that can be added to GaxiosOptions to specify the method name that is
+   * making an RPC call, for logging purposes, as well as a string ID that can be
+   * used to correlate calls and responses.
+   */
+  static readonly RequestMethodNameSymbol: unique symbol = Symbol(
+    'request method name',
+  );
+  static readonly RequestLogIdSymbol: unique symbol = Symbol('request log id');
+
   constructor(opts: AuthClientOptions = {}) {
     super();
 
@@ -229,6 +247,9 @@ export abstract class AuthClient
       this.transporter.interceptors.request.add(
         AuthClient.DEFAULT_REQUEST_INTERCEPTOR,
       );
+      this.transporter.interceptors.response.add(
+        AuthClient.DEFAULT_RESPONSE_INTERCEPTOR,
+      );
     }
 
     if (opts.eagerRefreshThresholdMillis) {
@@ -322,6 +343,7 @@ export abstract class AuthClient
     return target;
   }
 
+  static log = makeLog('auth');
   static readonly DEFAULT_REQUEST_INTERCEPTOR: Parameters<
     Gaxios['interceptors']['request']['add']
   >[0] = {
@@ -340,10 +362,104 @@ export abstract class AuthClient
         config.headers.set('User-Agent', `${userAgent} ${USER_AGENT}`);
       }
 
+      try {
+        const symbols: SymbolIndexString =
+          config as unknown as SymbolIndexString;
+        const methodName = symbols[AuthClient.RequestMethodNameSymbol];
+
+        // This doesn't need to be very unique or interesting, it's just an aid for
+        // matching requests to responses.
+        const logId = `${Math.floor(Math.random() * 1000)}`;
+        symbols[AuthClient.RequestLogIdSymbol] = logId;
+
+        // Boil down the object we're printing out.
+        const logObject = {
+          url: config.url,
+          headers: config.headers,
+        };
+        if (methodName) {
+          AuthClient.log.info(
+            '%s [%s] request %j',
+            methodName,
+            logId,
+            logObject,
+          );
+        } else {
+          AuthClient.log.info('[%s] request %j', logId, logObject);
+        }
+      } catch (e) {
+        // Logging must not create new errors; swallow them all.
+      }
+
       return config;
     },
   };
 
+  static readonly DEFAULT_RESPONSE_INTERCEPTOR: Parameters<
+    Gaxios['interceptors']['response']['add']
+  >[0] = {
+    resolved: async response => {
+      try {
+        const symbols: SymbolIndexString =
+          response.config as unknown as SymbolIndexString;
+        const methodName = symbols[AuthClient.RequestMethodNameSymbol];
+        const logId = symbols[AuthClient.RequestLogIdSymbol];
+        if (methodName) {
+          AuthClient.log.info(
+            '%s [%s] response %j',
+            methodName,
+            logId,
+            response.data,
+          );
+        } else {
+          AuthClient.log.info('[%s] response %j', logId, response.data);
+        }
+      } catch (e) {
+        // Logging must not create new errors; swallow them all.
+      }
+
+      return response;
+    },
+    rejected: async error => {
+      try {
+        const symbols: SymbolIndexString =
+          error.config as unknown as SymbolIndexString;
+        const methodName = symbols[AuthClient.RequestMethodNameSymbol];
+        const logId = symbols[AuthClient.RequestLogIdSymbol];
+        if (methodName) {
+          AuthClient.log.info(
+            '%s [%s] error %j',
+            methodName,
+            logId,
+            error.response?.data,
+          );
+        } else {
+          AuthClient.log.error('[%s] error %j', logId, error.response?.data);
+        }
+      } catch (e) {
+        // Logging must not create new errors; swallow them all.
+      }
+
+      // Re-throw the error.
+      throw error;
+    },
+  };
+
+  /**
+   * Sets the method name that is making a Gaxios request, so that logging may tag
+   * log lines with the operation.
+   * @param config A Gaxios request config
+   * @param methodName The method name making the call
+   */
+  static setMethodName(config: GaxiosOptions, methodName: string) {
+    try {
+      const symbols: SymbolIndexString = config as unknown as SymbolIndexString;
+      symbols[AuthClient.RequestMethodNameSymbol] = methodName;
+    } catch (e) {
+      // Logging must not create new errors; swallow them all.
+    }
+  }
+
   /**
    * Retry config for Auth-related requests.
    *

src/auth/baseexternalclient.ts

@@ -472,11 +472,13 @@ export abstract class BaseExternalAccountClient extends AuthClient {
     } else if (projectNumber) {
       // Preferable not to use request() to avoid retrial policies.
       const headers = await this.getRequestHeaders();
-      const response = await this.transporter.request<ProjectInfo>({
+      const opts: GaxiosOptions = {
         ...BaseExternalAccountClient.RETRY_CONFIG,
         headers,
         url: `${this.cloudResourceManagerURL.toString()}${projectNumber}`,
-      });
+      };
+      AuthClient.setMethodName(opts, 'getProjectId');
+      const response = await this.transporter.request<ProjectInfo>(opts);
       this.projectId = response.data.projectId;
       return this.projectId;
     }
@@ -667,6 +669,7 @@ export abstract class BaseExternalAccountClient extends AuthClient {
         lifetime: this.serviceAccountImpersonationLifetime + 's',
       },
     };
+    AuthClient.setMethodName(opts, 'getImpersonatedAccessToken');
     const response =
       await this.transporter.request<IamGenerateAccessTokenResponse>(opts);
     const successResponse = response.data;

src/auth/defaultawssecuritycredentialssupplier.ts

@@ -16,6 +16,7 @@ import {ExternalAccountSupplierContext} from './baseexternalclient';
 import {Gaxios, GaxiosOptions} from 'gaxios';
 import {AwsSecurityCredentialsSupplier} from './awsclient';
 import {AwsSecurityCredentials} from './awsrequestsigner';
+import {AuthClient} from './authclient';
 
 /**
  * Interface defining the AWS security-credentials endpoint response.
@@ -128,6 +129,7 @@ export class DefaultAwsSecurityCredentialsSupplier
       method: 'GET',
       headers: metadataHeaders,
     };
+    AuthClient.setMethodName(opts, 'getAwsRegion');
     const response = await context.transporter.request<string>(opts);
     // Remove last character. For example, if us-east-2b is returned,
     // the region would be us-east-2.
@@ -191,6 +193,7 @@ export class DefaultAwsSecurityCredentialsSupplier
       method: 'PUT',
       headers: {'x-aws-ec2-metadata-token-ttl-seconds': '300'},
     };
+    AuthClient.setMethodName(opts, '#getImdsV2SessionToken');
     const response = await transporter.request<string>(opts);
     return response.data;
   }
@@ -217,6 +220,7 @@ export class DefaultAwsSecurityCredentialsSupplier
       method: 'GET',
       headers: headers,
     };
+    AuthClient.setMethodName(opts, '#getAwsRoleName');
     const response = await transporter.request<string>(opts);
     return response.data;
   }
@@ -235,11 +239,14 @@ export class DefaultAwsSecurityCredentialsSupplier
     headers: Headers,
     transporter: Gaxios,
   ): Promise<AwsSecurityCredentialsResponse> {
-    const response = await transporter.request<AwsSecurityCredentialsResponse>({
+    const opts = {
       ...this.additionalGaxiosOptions,
       url: `${this.securityCredentialsUrl}/${roleName}`,
       headers: headers,
-    });
+    } as GaxiosOptions;
+    AuthClient.setMethodName(opts, '#retrieveAwsSecurityCredentials');
+    const response =
+      await transporter.request<AwsSecurityCredentialsResponse>(opts);
     return response.data;
   }
 

src/auth/externalAccountAuthorizedUserClient.ts

@@ -121,6 +121,7 @@ class ExternalAccountAuthorizedUserHandler extends OAuthClientAuthHandler {
         refresh_token: refreshToken,
       }),
     };
+    AuthClient.setMethodName(opts, 'refreshToken');
 
     // Apply OAuth client authentication.
     this.applyClientAuthenticationOptions(opts);

src/auth/oauth2client.ts

@@ -749,13 +749,16 @@ export class OAuth2Client extends AuthClient {
     if (this.clientAuthentication === ClientAuthentication.ClientSecretPost) {
       values.client_secret = this._clientSecret;
     }
-    const res = await this.transporter.request<CredentialRequest>({
+
+    const opts = {
       ...OAuth2Client.RETRY_CONFIG,
       method: 'POST',
       url,
       data: new URLSearchParams(values as {}),
       headers,
-    });
+    };
+    AuthClient.setMethodName(opts, 'getTokenAsync');
+    const res = await this.transporter.request<CredentialRequest>(opts);
     const tokens = res.data as Credentials;
     if (res.data && res.data.expires_in) {
       tokens.expiry_date = new Date().getTime() + res.data.expires_in * 1000;
@@ -813,13 +816,16 @@ export class OAuth2Client extends AuthClient {
     let res: GaxiosResponse<CredentialRequest>;
 
     try {
-      // request for new token
-      res = await this.transporter.request<CredentialRequest>({
+      const opts: GaxiosOptions = {
         ...OAuth2Client.RETRY_CONFIG,
         method: 'POST',
         url,
         data: new URLSearchParams(data),
-      });
+      };
+      AuthClient.setMethodName(opts, 'refreshTokenNoCache');
+
+      // request for new token
+      res = await this.transporter.request<CredentialRequest>(opts);
     } catch (e) {
       if (
         e instanceof GaxiosError &&
@@ -1041,6 +1047,7 @@ export class OAuth2Client extends AuthClient {
       url: this.getRevokeTokenURL(token).toString(),
       method: 'POST',
     };
+    AuthClient.setMethodName(opts, 'revokeToken');
     if (callback) {
       this.transporter
         .request<RevokeCredentialsResult>(opts)
@@ -1306,10 +1313,12 @@ export class OAuth2Client extends AuthClient {
         throw new Error(`Unsupported certificate format ${format}`);
     }
     try {
-      res = await this.transporter.request({
+      const opts = {
         ...OAuth2Client.RETRY_CONFIG,
         url,
-      });
+      };
+      AuthClient.setMethodName(opts, 'getFederatedSignonCertsAsync');
+      res = await this.transporter.request(opts);
     } catch (e) {
       if (e instanceof Error) {
         e.message = `Failed to retrieve verification certificates: ${e.message}`;
@@ -1377,10 +1386,12 @@ export class OAuth2Client extends AuthClient {
     const url = this.endpoints.oauth2IapPublicKeyUrl.toString();
 
     try {
-      res = await this.transporter.request({
+      const opts = {
         ...OAuth2Client.RETRY_CONFIG,
         url,
-      });
+      };
+      AuthClient.setMethodName(opts, 'getIapPublicKeysAsync');
+      res = await this.transporter.request(opts);
     } catch (e) {
       if (e instanceof Error) {
         e.message = `Failed to retrieve verification certificates: ${e.message}`;

src/auth/refreshclient.ts

@@ -19,6 +19,8 @@ import {
   OAuth2Client,
   OAuth2ClientOptions,
 } from './oauth2client';
+import {AuthClient} from './authclient';
+import {GaxiosOptions} from 'gaxios';
 
 export const USER_REFRESH_ACCOUNT_TYPE = 'authorized_user';
 
@@ -96,7 +98,7 @@ export class UserRefreshClient extends OAuth2Client {
   }
 
   async fetchIdToken(targetAudience: string): Promise<string> {
-    const res = await this.transporter.request<CredentialRequest>({
+    const opts: GaxiosOptions = {
       ...UserRefreshClient.RETRY_CONFIG,
       url: this.endpoints.oauth2TokenUrl,
       method: 'POST',
@@ -107,8 +109,10 @@ export class UserRefreshClient extends OAuth2Client {
         refresh_token: this._refreshToken,
         target_audience: targetAudience,
       } as {}),
-    });
+    };
+    AuthClient.setMethodName(opts, 'fetchIdToken');
 
+    const res = await this.transporter.request<CredentialRequest>(opts);
     return res.data.id_token!;
   }
 

src/auth/stscredentials.ts

@@ -13,7 +13,7 @@
 // limitations under the License.
 
 import {GaxiosError, GaxiosOptions, GaxiosResponse} from 'gaxios';
-import {HeadersInit} from './authclient';
+import {AuthClient, HeadersInit} from './authclient';
 import {
   ClientAuthentication,
   OAuthClientAuthHandler,
@@ -218,6 +218,8 @@ export class StsCredentials extends OAuthClientAuthHandler {
       headers,
       data: new URLSearchParams(payload),
     };
+    AuthClient.setMethodName(opts, 'exchangeToken');
+
     // Apply OAuth client authentication.
     this.applyClientAuthenticationOptions(opts);
 

src/auth/urlsubjecttokensupplier.ts

@@ -19,6 +19,7 @@ import {
   SubjectTokenJsonResponse,
   SubjectTokenSupplier,
 } from './identitypoolclient';
+import {AuthClient} from './authclient';
 
 /**
  * Interface that defines options used to build a {@link UrlSubjectTokenSupplier}
@@ -88,6 +89,8 @@ export class UrlSubjectTokenSupplier implements SubjectTokenSupplier {
       method: 'GET',
       headers: this.headers,
     };
+    AuthClient.setMethodName(opts, 'getSubjectToken');
+
     let subjectToken: string | undefined;
     if (this.formatType === 'text') {
       const response = await context.transporter.request<string>(opts);
@@ -102,6 +105,7 @@ export class UrlSubjectTokenSupplier implements SubjectTokenSupplier {
         'Unable to parse the subject_token from the credential_source URL',
       );
     }
+
     return subjectToken;
   }
 }