chore(cli): log SDK calls when using -vvv (#32308)

(This work came out of the proxy issue research)

The logging of what SDK calls were being performed was lost during the migration of SDKv2 -> SDKv3.  Add it back.

Also in this PR:

- Set a timeout on `npm view`; if for network isolation reasons NPM can't connect to the server, it will make the CLI hang for a minute.
- Work around an issue where the CLI entirely fails if it is run as a user that doesn't have a home directory.

Closes #32306.

----

*By submitting this pull request, I confirm that my contribution is made under the terms of the Apache-2.0 license*

Author: rix0rrr

packages/aws-cdk/lib/api/aws-auth/sdk-logger.ts

@@ -0,0 +1,142 @@
+import { inspect } from 'util';
+import { Logger } from '@smithy/types';
+import { trace } from '../../logging';
+
+export class SdkToCliLogger implements Logger {
+  public trace(..._content: any[]) {
+    // This is too much detail for our logs
+    // trace('[SDK trace] %s', fmtContent(content));
+  }
+
+  public debug(..._content: any[]) {
+    // This is too much detail for our logs
+    // trace('[SDK debug] %s', fmtContent(content));
+  }
+
+  /**
+   * Info is called mostly (exclusively?) for successful API calls
+   *
+   * Payload:
+   *
+   * (Note the input contains entire CFN templates, for example)
+   *
+   * ```
+   * {
+   *   clientName: 'S3Client',
+   *   commandName: 'GetBucketLocationCommand',
+   *   input: {
+   *     Bucket: '.....',
+   *     ExpectedBucketOwner: undefined
+   *   },
+   *   output: { LocationConstraint: 'eu-central-1' },
+   *   metadata: {
+   *     httpStatusCode: 200,
+   *     requestId: '....',
+   *     extendedRequestId: '...',
+   *     cfId: undefined,
+   *     attempts: 1,
+   *     totalRetryDelay: 0
+   *   }
+   * }
+   * ```
+   */
+  public info(...content: any[]) {
+    trace('[sdk info] %s', formatSdkLoggerContent(content));
+  }
+
+  public warn(...content: any[]) {
+    trace('[sdk warn] %s', formatSdkLoggerContent(content));
+  }
+
+  /**
+   * Error is called mostly (exclusively?) for failing API calls
+   *
+   * Payload (input would be the entire API call arguments).
+   *
+   * ```
+   * {
+   *   clientName: 'STSClient',
+   *   commandName: 'GetCallerIdentityCommand',
+   *   input: {},
+   *   error: AggregateError [ECONNREFUSED]:
+   *       at internalConnectMultiple (node:net:1121:18)
+   *       at afterConnectMultiple (node:net:1688:7) {
+   *     code: 'ECONNREFUSED',
+   *     '$metadata': { attempts: 3, totalRetryDelay: 600 },
+   *     [errors]: [ [Error], [Error] ]
+   *   },
+   *   metadata: { attempts: 3, totalRetryDelay: 600 }
+   * }
+   * ```
+   */
+  public error(...content: any[]) {
+    trace('[sdk error] %s', formatSdkLoggerContent(content));
+  }
+}
+
+/**
+ * This can be anything.
+ *
+ * For debug, it seems to be mostly strings.
+ * For info, it seems to be objects.
+ *
+ * Stringify and join without separator.
+ */
+export function formatSdkLoggerContent(content: any[]) {
+  if (content.length === 1) {
+    const apiFmt = formatApiCall(content[0]);
+    if (apiFmt) {
+      return apiFmt;
+    }
+  }
+  return content.map((x) => typeof x === 'string' ? x : inspect(x)).join('');
+}
+
+function formatApiCall(content: any): string | undefined {
+  if (!isSdkApiCallSuccess(content) && !isSdkApiCallError(content)) {
+    return undefined;
+  }
+
+  const service = content.clientName.replace(/Client$/, '');
+  const api = content.commandName.replace(/Command$/, '');
+
+  const parts = [];
+  if ((content.metadata?.attempts ?? 0) > 1) {
+    parts.push(`[${content.metadata?.attempts} attempts, ${content.metadata?.totalRetryDelay}ms retry]`);
+  }
+
+  parts.push(`${service}.${api}(${JSON.stringify(content.input)})`);
+
+  if (isSdkApiCallSuccess(content)) {
+    parts.push('-> OK');
+  } else {
+    parts.push(`-> ${content.error}`);
+  }
+
+  return parts.join(' ');
+}
+
+interface SdkApiCallBase {
+  clientName: string;
+  commandName: string;
+  input: Record<string, unknown>;
+  metadata?: {
+    httpStatusCode?: number;
+    requestId?: string;
+    extendedRequestId?: string;
+    cfId?: string;
+    attempts?: number;
+    totalRetryDelay?: number;
+  };
+}
+
+type SdkApiCallSuccess = SdkApiCallBase & { output: Record<string, unknown> };
+type SdkApiCallError = SdkApiCallBase & { error: Error };
+
+function isSdkApiCallSuccess(x: any): x is SdkApiCallSuccess {
+  return x && typeof x === 'object' && x.commandName && x.output;
+}
+
+function isSdkApiCallError(x: any): x is SdkApiCallError {
+  return x && typeof x === 'object' && x.commandName && x.error;
+}

packages/aws-cdk/lib/api/aws-auth/sdk-provider.ts

@@ -126,7 +126,7 @@ export class SdkProvider {
 
     const region = await AwsCliCompatible.region(options.profile);
     const requestHandler = AwsCliCompatible.requestHandlerBuilder(options.httpOptions);
-    return new SdkProvider(credentialProvider, region, requestHandler);
+    return new SdkProvider(credentialProvider, region, requestHandler, options.logger);
   }
 
   private readonly plugins = new CredentialPlugins();
@@ -138,6 +138,7 @@ export class SdkProvider {
      */
     public readonly defaultRegion: string,
     private readonly requestHandler: NodeHttpHandlerOptions = {},
+    private readonly logger?: Logger,
   ) {}
 
   /**
@@ -169,7 +170,7 @@ export class SdkProvider {
 
       // Our current credentials must be valid and not expired. Confirm that before we get into doing
       // actual CloudFormation calls, which might take a long time to hang.
-      const sdk = new SDK(baseCreds.credentials, env.region, this.requestHandler);
+      const sdk = new SDK(baseCreds.credentials, env.region, this.requestHandler, this.logger);
       await sdk.validateCredentials();
       return { sdk, didAssumeRole: false };
     }
@@ -201,7 +202,7 @@ export class SdkProvider {
           `${fmtObtainedCredentials(baseCreds)} could not be used to assume '${options.assumeRoleArn}', but are for the right account. Proceeding anyway.`,
         );
         return {
-          sdk: new SDK(baseCreds.credentials, env.region, this.requestHandler),
+          sdk: new SDK(baseCreds.credentials, env.region, this.requestHandler, this.logger),
           didAssumeRole: false,
         };
       }
@@ -221,7 +222,7 @@ export class SdkProvider {
     if (baseCreds.source === 'none') {
       return undefined;
     }
-    return (await new SDK(baseCreds.credentials, env.region, this.requestHandler).currentAccount()).partition;
+    return (await new SDK(baseCreds.credentials, env.region, this.requestHandler, this.logger).currentAccount()).partition;
   }
 
   /**
@@ -273,7 +274,7 @@ export class SdkProvider {
           throw new Error('Unable to resolve AWS credentials (setup with "aws configure")');
         }
 
-        return await new SDK(credentials, this.defaultRegion, this.requestHandler).currentAccount();
+        return await new SDK(credentials, this.defaultRegion, this.requestHandler, this.logger).currentAccount();
       } catch (e: any) {
         // Treat 'ExpiredToken' specially. This is a common situation that people may find themselves in, and
         // they are complaining about if we fail 'cdk synth' on them. We loudly complain in order to show that
@@ -376,10 +377,12 @@ export class SdkProvider {
         clientConfig: {
           region,
           requestHandler: this.requestHandler,
+          customUserAgent: 'aws-cdk',
+          logger: this.logger,
         },
       })();
 
-      return new SDK(credentials, region, this.requestHandler);
+      return new SDK(credentials, region, this.requestHandler, this.logger);
     } catch (err: any) {
       if (err.name === 'ExpiredToken') {
         throw err;

packages/aws-cdk/lib/api/aws-auth/sdk.ts

@@ -545,13 +545,15 @@ export class SDK {
     private readonly _credentials: AwsCredentialIdentity,
     region: string,
     requestHandler: NodeHttpHandlerOptions,
+    logger?: Logger,
   ) {
     this.config = {
       region,
       credentials: _credentials,
       requestHandler,
       retryStrategy: new ConfiguredRetryStrategy(7, (attempt) => 300 * (2 ** attempt)),
       customUserAgent: defaultCliUserAgent(),
+      logger,
     };
     this.currentRegion = region;
   }

packages/aws-cdk/lib/cli.ts

@@ -26,6 +26,7 @@ import { data, debug, error, print, setCI, setLogLevel, LogLevel } from '../lib/
 import { Notices } from '../lib/notices';
 import { Command, Configuration, Settings } from '../lib/settings';
 import * as version from '../lib/version';
+import { SdkToCliLogger } from './api/aws-auth/sdk-logger';
 
 /* eslint-disable max-len */
 /* eslint-disable @typescript-eslint/no-shadow */ // yargs
@@ -101,6 +102,7 @@ export async function exec(args: string[], synthesizer?: Synthesizer): Promise<n
       proxyAddress: argv.proxy,
       caBundlePath: argv['ca-bundle-path'],
     },
+    logger: new SdkToCliLogger(),
   });
 
   let outDirLock: ILock | undefined;

packages/aws-cdk/lib/util/directories.ts

@@ -17,7 +17,13 @@ export function cdkHomeDir() {
   const tmpDir = fs.realpathSync(os.tmpdir());
   let home;
   try {
-    home = path.join((os.userInfo().homedir ?? os.homedir()).trim(), '.cdk');
+    let userInfoHome: string | undefined = os.userInfo().homedir;
+    // Node returns this if the user doesn't have a home directory
+    /* istanbul ignore if: will not happen in normal setups */
+    if (userInfoHome == '/var/empty') {
+      userInfoHome = undefined;
+    }
+    home = path.join((userInfoHome ?? os.homedir()).trim(), '.cdk');
   } catch {}
   return process.env.CDK_HOME
     ? path.resolve(process.env.CDK_HOME)

packages/aws-cdk/lib/util/npm.ts

@@ -6,7 +6,7 @@ import { debug } from '../../lib/logging';
 const exec = promisify(_exec);
 
 export async function getLatestVersionFromNpm(): Promise<string> {
-  const { stdout, stderr } = await exec('npm view aws-cdk version');
+  const { stdout, stderr } = await exec('npm view aws-cdk version', { timeout: 3000 });
   if (stderr && stderr.trim().length > 0) {
     debug(`The 'npm view' command generated an error stream with content [${stderr.trim()}]`);
   }

packages/aws-cdk/test/api/aws-auth/__snapshots__/sdk-logger.test.ts.snap

@@ -0,0 +1,5 @@
+// Jest Snapshot v1, https://goo.gl/fbAQLP
+
+exports[`formatting a failing SDK call looks broadly reasonable 1`] = `"[2 attempts, 30ms retry] S3.GetBucketLocation({"Bucket":"....."}) -> Error: it failed"`;
+
+exports[`formatting a successful SDK call looks broadly reasonable 1`] = `"[2 attempts, 30ms retry] S3.GetBucketLocation({"Bucket":"....."}) -> OK"`;

packages/aws-cdk/test/api/aws-auth/sdk-logger.test.ts

@@ -0,0 +1,81 @@
+import { formatSdkLoggerContent, SdkToCliLogger } from '../../../lib/api/aws-auth/sdk-logger';
+import * as logging from '../../../lib/logging';
+
+describe(SdkToCliLogger, () => {
+  const logger = new SdkToCliLogger();
+  const trace = jest.spyOn(logging, 'trace');
+
+  beforeEach(() => {
+    trace.mockReset();
+  });
+
+  test.each(['trace', 'debug'] as Array<keyof SdkToCliLogger>)('%s method does not call trace', (meth) => {
+    logger[meth]('test');
+    expect(trace).not.toHaveBeenCalled();
+  });
+
+  test.each(['info', 'warn', 'error'] as Array<keyof SdkToCliLogger>)('%s method logs to trace', (meth) => {
+    logger[meth]('test');
+    expect(trace).toHaveBeenCalled();
+  });
+});
+
+const SUCCESS_CALL = {
+  clientName: 'S3Client',
+  commandName: 'GetBucketLocationCommand',
+  input: {
+    Bucket: '.....',
+    ExpectedBucketOwner: undefined,
+  },
+  output: { LocationConstraint: 'eu-central-1' },
+  metadata: {
+    httpStatusCode: 200,
+    requestId: '....',
+    extendedRequestId: '...',
+    cfId: undefined,
+    attempts: 2,
+    totalRetryDelay: 30,
+  },
+};
+
+const ERROR_CALL = {
+  clientName: 'S3Client',
+  commandName: 'GetBucketLocationCommand',
+  input: {
+    Bucket: '.....',
+    ExpectedBucketOwner: undefined,
+  },
+  error: new Error('it failed'),
+  metadata: {
+    httpStatusCode: 200,
+    attempts: 2,
+    totalRetryDelay: 30,
+  },
+};
+
+test('formatting a successful SDK call looks broadly reasonable', () => {
+  const output = formatSdkLoggerContent([SUCCESS_CALL]);
+  expect(output).toMatchSnapshot();
+});
+
+test('formatting a failing SDK call looks broadly reasonable', () => {
+  const output = formatSdkLoggerContent([ERROR_CALL]);
+  expect(output).toMatchSnapshot();
+});
+
+test('formatting a successful SDK call includes attempts and retries if greater than 1', () => {
+  const output = formatSdkLoggerContent([SUCCESS_CALL]);
+  expect(output).toContain('2 attempts');
+  expect(output).toContain('30ms');
+});
+
+test('formatting a failing SDK call includes attempts and retries if greater than 1', () => {
+  const output = formatSdkLoggerContent([ERROR_CALL]);
+  expect(output).toContain('2 attempts');
+  expect(output).toContain('30ms');
+});
+
+test('formatting a failing SDK call includes the error', () => {
+  const output = formatSdkLoggerContent([ERROR_CALL]);
+  expect(output).toContain('it failed');
+});