fix(logging): improve node core's debug logging

This commit includes the following changes:
1. some additional debug logging in various components
2. HTTP message tracing was improved by adding specific
   interceptors to display request/response messages much
   the same way the Go and Java cores do.

Signed-off-by: Phil Adams <phil_adams@us.ibm.com>

auth/authenticators/basic-authenticator.ts

@@ -1,5 +1,5 @@
 /**
- * (C) Copyright IBM Corp. 2019, 2023.
+ * (C) Copyright IBM Corp. 2019, 2024.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -18,6 +18,7 @@ import extend from 'extend';
 import { computeBasicAuthHeader, validateInput } from '../utils/helpers';
 import { Authenticator } from './authenticator';
 import { AuthenticateOptions } from './authenticator-interface';
+import logger from '../../lib/logger';
 
 /** Configuration options for basic authentication. */
 export type Options = {
@@ -72,6 +73,7 @@ export class BasicAuthenticator extends Authenticator {
   public authenticate(requestOptions: AuthenticateOptions): Promise<void> {
     return new Promise((resolve) => {
       requestOptions.headers = extend(true, {}, requestOptions.headers, this.authHeader);
+      logger.debug(`Authenticated outbound request (type=${this.authenticationType()})`);
       resolve();
     });
   }

auth/authenticators/bearer-token-authenticator.ts

@@ -18,6 +18,7 @@ import extend from 'extend';
 import { validateInput } from '../utils/helpers';
 import { Authenticator } from './authenticator';
 import { AuthenticateOptions } from './authenticator-interface';
+import logger from '../../lib/logger';
 
 /** Configuration options for bearer authentication. */
 export type Options = {
@@ -76,6 +77,7 @@ export class BearerTokenAuthenticator extends Authenticator {
     return new Promise((resolve) => {
       const authHeader = { Authorization: `Bearer ${this.bearerToken}` };
       requestOptions.headers = extend(true, {}, requestOptions.headers, authHeader);
+      logger.debug(`Authenticated outbound request (type=${this.authenticationType()})`);
       resolve();
     });
   }

auth/authenticators/token-request-based-authenticator.ts

@@ -19,6 +19,7 @@ import { OutgoingHttpHeaders } from 'http';
 import { JwtTokenManager } from '../token-managers/jwt-token-manager';
 import { Authenticator } from './authenticator';
 import { AuthenticateOptions } from './authenticator-interface';
+import logger from '../../lib/logger';
 
 /** Configuration options for token-based authentication. */
 export type BaseOptions = {
@@ -118,6 +119,7 @@ export class TokenRequestBasedAuthenticator extends Authenticator {
     return this.tokenManager.getToken().then((token) => {
       const authHeader = { Authorization: `Bearer ${token}` };
       requestOptions.headers = extend(true, {}, requestOptions.headers, authHeader);
+      logger.debug(`Authenticated outbound request (type=${this.authenticationType()})`);
     });
   }
 }

auth/token-managers/cp4d-token-manager.ts

@@ -18,6 +18,7 @@ import extend from 'extend';
 import { validateInput } from '../utils/helpers';
 import { buildUserAgent } from '../../lib/build-user-agent';
 import { JwtTokenManager, JwtTokenManagerOptions } from './jwt-token-manager';
+import logger from '../../lib/logger';
 
 /** Configuration options for CP4D token retrieval. */
 interface Options extends JwtTokenManagerOptions {
@@ -121,6 +122,10 @@ export class Cp4dTokenManager extends JwtTokenManager {
         rejectUnauthorized: !this.disableSslVerification,
       },
     };
-    return this.requestWrapperInstance.sendRequest(parameters);
+    logger.debug(`Invoking CP4D token service operation: ${parameters.options.url}`);
+    return this.requestWrapperInstance.sendRequest(parameters).then((response) => {
+      logger.debug('Returned from CP4D token service operation');
+      return response;
+    });
   }
 }

auth/token-managers/iam-request-based-token-manager.ts

@@ -180,7 +180,11 @@ export class IamRequestBasedTokenManager extends JwtTokenManager {
       },
     };
 
-    return this.requestWrapperInstance.sendRequest(parameters);
+    logger.debug(`Invoking IAM get_token operation: ${parameters.options.url}`);
+    return this.requestWrapperInstance.sendRequest(parameters).then((response) => {
+      logger.debug('Returned from IAM get_token operation');
+      return response;
+    });
   }
 
   /**

auth/token-managers/mcsp-token-manager.ts

@@ -18,6 +18,7 @@ import extend from 'extend';
 import { validateInput } from '../utils/helpers';
 import { buildUserAgent } from '../../lib/build-user-agent';
 import { JwtTokenManager, JwtTokenManagerOptions } from './jwt-token-manager';
+import logger from '../../lib/logger';
 
 /**
  * Configuration options for MCSP token retrieval.
@@ -99,6 +100,10 @@ export class McspTokenManager extends JwtTokenManager {
         rejectUnauthorized: !this.disableSslVerification,
       },
     };
-    return this.requestWrapperInstance.sendRequest(parameters);
+    logger.debug(`Invoking MCSP token service operation: ${parameters.options.url}`);
+    return this.requestWrapperInstance.sendRequest(parameters).then((response) => {
+      logger.debug('Returned from MCSP token service operation');
+      return response;
+    });
   }
 }

auth/token-managers/token-manager.ts

@@ -102,10 +102,13 @@ export class TokenManager {
   public getToken(): Promise<any> {
     if (!this.accessToken || this.isTokenExpired()) {
       // 1. request a new token
+      logger.debug('Performing synchronous token refresh');
       return this.pacedRequestToken().then(() => this.accessToken);
     }
+
     // If refresh needed, kick one off
     if (this.tokenNeedsRefresh()) {
+      logger.debug('Performing background asynchronous token fetch');
       this.requestToken().then(
         (tokenResponse) => {
           this.saveTokenInfo(tokenResponse);
@@ -123,7 +126,9 @@ export class TokenManager {
         }
       );
     }
+
     // 2. use valid, managed token
+    logger.debug('Using cached access token');
     return Promise.resolve(this.accessToken);
   }
 

auth/token-managers/vpc-instance-token-manager.ts

@@ -141,8 +141,10 @@ export class VpcInstanceTokenManager extends JwtTokenManager {
     };
 
     logger.debug(`Invoking VPC 'create_iam_token' operation: ${parameters.options.url}`);
-
-    return this.requestWrapperInstance.sendRequest(parameters);
+    return this.requestWrapperInstance.sendRequest(parameters).then((response) => {
+      logger.debug(`Returned from VPC 'create_iam_token' operation`);
+      return response;
+    });
   }
 
   private async getInstanceIdentityToken(): Promise<string> {

auth/utils/read-external-sources.ts

@@ -48,6 +48,8 @@ function getProperties(serviceName: string): any {
   // only get properties from one source, return null if none found
   let properties = null;
 
+  logger.debug(`Retrieving config properties for service '${serviceName}'`);
+
   properties = filterPropertiesByServiceName(readCredentialsFile(), serviceName);
 
   if (isEmptyObject(properties)) {
@@ -58,6 +60,7 @@ function getProperties(serviceName: string): any {
     properties = getPropertiesFromVCAP(serviceName);
   }
 
+  logger.debug(`Retrieved ${Object.keys(properties).length} properties`);
   return properties;
 }
 

lib/base-service.ts

@@ -156,6 +156,7 @@ export class BaseService {
   public setServiceUrl(url: string): void {
     if (url) {
       this.baseOptions.serviceUrl = stripTrailingSlash(url);
+      logger.debug(`Set service URL: ${this.baseOptions.serviceUrl}`);
     }
   }
 
@@ -238,6 +239,8 @@ export class BaseService {
    * configuration.
    */
   protected configureService(serviceName: string): void {
+    logger.debug(`Configuring BaseService instance with service name: ${serviceName}`);
+
     if (!serviceName) {
       const err = 'Error configuring service. Service name is required.';
       logger.error(err);

lib/private-helpers.ts

@@ -0,0 +1,59 @@
+/**
+ * (C) Copyright IBM Corp. 2024.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+// Keywords that should be redacted.
+const redactedKeywords = [
+  'apikey',
+  'api_key',
+  'passcode',
+  'password',
+  'token',
+
+  'aadClientId',
+  'aadClientSecret',
+  'auth',
+  'auth_provider_x509_cert_url',
+  'auth_uri',
+  'client_email',
+  'client_id',
+  'client_x509_cert_url',
+  'key',
+  'project_id',
+  'secret',
+  'subscriptionId',
+  'tenantId',
+  'thumbprint',
+  'token_uri',
+];
+
+const redactedTokens = redactedKeywords.join('|');
+
+// Pre-compiled regular expressions used by redactSecrets().
+const reAuthHeader = new RegExp(`^(Authorization|X-Auth\\S*): .*$`, 'gim');
+const rePropertySetting = new RegExp(`(${redactedTokens})=[^&]*(&|$)`, 'gi');
+const reJsonField = new RegExp(`"([^"]*(${redactedTokens})[^"_]*)":\\s*"[^\\,]*"`, 'gi');
+
+// RedactSecrets() returns the input string with secrets redacted.
+export function redactSecrets(input: string): string {
+  const redacted = '[redacted]';
+
+  let redactedString = input;
+  redactedString = redactedString.replace(reAuthHeader, `$1: ${redacted}`);
+  redactedString = redactedString.replace(rePropertySetting, `$1=${redacted}$2`);
+  redactedString = redactedString.replace(reJsonField, `"$1":"${redacted}"`);
+
+  return redactedString;
+}