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>

.secrets.baseline

@@ -3,7 +3,7 @@
     "files": "package-lock.json|^.secrets.baseline$",
     "lines": null
   },
-  "generated_at": "2024-06-06T19:22:54Z",
+  "generated_at": "2024-08-29T14:54:57Z",
   "plugins_used": [
     {
       "name": "AWSKeyDetector"
@@ -96,7 +96,7 @@
         "hashed_secret": "bc2f74c22f98f7b6ffbc2f67453dbfa99bce9a32",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 174,
+        "line_number": 207,
         "type": "Secret Keyword",
         "verified_result": null
       }
@@ -106,7 +106,7 @@
         "hashed_secret": "32e8612d8ca77c7ea8374aa7918db8e5df9252ed",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 63,
+        "line_number": 62,
         "type": "Secret Keyword",
         "verified_result": null
       }
@@ -126,7 +126,7 @@
         "hashed_secret": "bbccdf2efb33b52e6c9d0a14dd70b2d415fbea6e",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 52,
+        "line_number": 53,
         "type": "Secret Keyword",
         "verified_result": null
       }
@@ -210,31 +210,31 @@
         "hashed_secret": "d5ff02fa48e492fac0a245ad63d1ae608e705c05",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 98,
+        "line_number": 99,
         "type": "Secret Keyword",
         "verified_result": null
       },
       {
         "hashed_secret": "8f4bfc22c4fd7cb884f94ec175ff4a3284a174a1",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 99,
+        "line_number": 100,
         "type": "Secret Keyword",
         "verified_result": null
       },
       {
         "hashed_secret": "45a15668db917c293f16e8add0f5d801889e5923",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 116,
+        "line_number": 117,
         "type": "Secret Keyword",
         "verified_result": null
       },
       {
         "hashed_secret": "65e622227634e8876cfa733000233fb80c6f0473",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 117,
+        "line_number": 118,
         "type": "Secret Keyword",
         "verified_result": null
       }
@@ -296,15 +296,15 @@
         "hashed_secret": "8f4bfc22c4fd7cb884f94ec175ff4a3284a174a1",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 79,
+        "line_number": 80,
         "type": "Secret Keyword",
         "verified_result": null
       },
       {
         "hashed_secret": "65e622227634e8876cfa733000233fb80c6f0473",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 95,
+        "line_number": 96,
         "type": "Secret Keyword",
         "verified_result": null
       }
@@ -442,15 +442,15 @@
         "hashed_secret": "1572bd30ac06678a82df42b5913e5e52e27f9a12",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 27,
+        "line_number": 32,
         "type": "Secret Keyword",
         "verified_result": null
       },
       {
         "hashed_secret": "16856d955c788df03735a24feb2e3ffefd91f3dc",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 28,
+        "line_number": 33,
         "type": "Secret Keyword",
         "verified_result": null
       }
@@ -522,7 +522,7 @@
         "hashed_secret": "a7ef1be18bb8d37af79f3d87761a203378bf26a2",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 169,
+        "line_number": 158,
         "type": "Secret Keyword",
         "verified_result": null
       }
@@ -542,7 +542,7 @@
         "hashed_secret": "f2e7745f43b0ef0e2c2faf61d6c6a28be2965750",
         "is_secret": false,
         "is_verified": false,
-        "line_number": 26,
+        "line_number": 31,
         "type": "Secret Keyword",
         "verified_result": null
       }
@@ -582,7 +582,7 @@
       }
     ]
   },
-  "version": "0.13.1+ibm.56.dss",
+  "version": "0.13.1+ibm.62.dss",
   "word_list": {
     "file": null,
     "hash": null

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,65 @@
+/**
+ * (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.
+/**
+ * Redacts secrets found in "input" so that the resulting string
+ * is suitable for debug logging.
+ * @param input - the string that potentially contains secrets
+ * @returns the input string with secrets replaced with "[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;
+}