refactor(cli): localize SDK tracing (#33273)

### Reason for this change

The CLI has a global method call tracing feature that is currently only used for SDK calls.
Eventually this feature needs to support logging through the IoHost. While this PR doesn't achieve this, it co-locates the tracing feature with SDK logs and explicitly calls out its limitations.

We will need a better, different approach once we are looking at the SDK Provider in more detail.

### Description of changes

Move the feature to `aws-auth` module.
Limit exports and renames for clarity.
Limit tracing to member methods as these can add a class logger.
Add a manual trace to the one static method this was currently tracig

### Describe any new or updated permissions being added

n/a

### Description of how you validated changes

Existing unit & integ tests, manual verification

### Checklist
- [x] My code adheres to the [CONTRIBUTING GUIDE](https://github.com/aws/aws-cdk/blob/main/CONTRIBUTING.md) and [DESIGN GUIDELINES](https://github.com/aws/aws-cdk/blob/main/docs/DESIGN_GUIDELINES.md)

----

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

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

@@ -1,17 +1,33 @@
-import { inspect } from 'util';
+import { inspect, format } from 'util';
 import { Logger } from '@smithy/types';
-import { trace } from '../../logging';
 import { replacerBufferWithInfo } from '../../serialize';
+import type { IIoHost } from '../../toolkit/cli-io-host';
 
 export class SdkToCliLogger implements Logger {
+  private readonly ioHost: IIoHost;
+
+  public constructor(ioHost: IIoHost) {
+    this.ioHost = ioHost;
+  }
+
+  private notify(level: 'debug' | 'info' | 'warn' | 'error', ...content: any[]) {
+    void this.ioHost.notify({
+      time: new Date(),
+      level,
+      action: 'none' as any,
+      code: 'CDK_SDK_I0000',
+      message: format('[SDK %s] %s', level, formatSdkLoggerContent(content)),
+    });
+  }
+
   public trace(..._content: any[]) {
     // This is too much detail for our logs
-    // trace('[SDK trace] %s', fmtContent(content));
+    // this.notify('trace', ...content);
   }
 
   public debug(..._content: any[]) {
     // This is too much detail for our logs
-    // trace('[SDK debug] %s', fmtContent(content));
+    // this.notify('debug', ...content);
   }
 
   /**
@@ -42,11 +58,11 @@ export class SdkToCliLogger implements Logger {
    * ```
    */
   public info(...content: any[]) {
-    trace('[sdk info] %s', formatSdkLoggerContent(content));
+    this.notify('info', ...content);
   }
 
   public warn(...content: any[]) {
-    trace('[sdk warn] %s', formatSdkLoggerContent(content));
+    this.notify('warn', ...content);
   }
 
   /**
@@ -71,7 +87,7 @@ export class SdkToCliLogger implements Logger {
    * ```
    */
   public error(...content: any[]) {
-    trace('[sdk error] %s', formatSdkLoggerContent(content));
+    this.notify('info', ...content);
   }
 }
 

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

@@ -10,10 +10,10 @@ import { cached } from './cached';
 import { CredentialPlugins } from './credential-plugins';
 import { makeCachingProvider } from './provider-caching';
 import { SDK } from './sdk';
+import { callTrace, traceMemberMethods } from './tracing';
 import { debug, warning } from '../../logging';
 import { AuthenticationError } from '../../toolkit/error';
 import { formatErrorMessage } from '../../util/error';
-import { traceMethods } from '../../util/tracing';
 import { Mode } from '../plugin/mode';
 
 export type AssumeRoleAdditionalOptions = Partial<Omit<AssumeRoleCommandInput, 'ExternalId' | 'RoleArn'>>;
@@ -111,7 +111,7 @@ export interface SdkForEnvironment {
  *     - Seeded terminal with `ReadOnly` credentials in order to do `cdk diff`--the `ReadOnly`
  *       role doesn't have `sts:AssumeRole` and will fail for no real good reason.
  */
-@traceMethods
+@traceMemberMethods
 export class SdkProvider {
   /**
    * Create a new SdkProvider which gets its defaults in a way that behaves like the AWS CLI does
@@ -120,6 +120,7 @@ export class SdkProvider {
    * class `AwsCliCompatible` for the details.
    */
   public static async withAwsCliCompatibleDefaults(options: SdkProviderOptions = {}) {
+    callTrace(SdkProvider.withAwsCliCompatibleDefaults.name, SdkProvider.constructor.name, options.logger);
     const credentialProvider = await AwsCliCompatible.credentialChainBuilder({
       profile: options.profile,
       httpOptions: options.httpOptions,

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

@@ -317,11 +317,11 @@ import { WaiterResult } from '@smithy/util-waiter';
 import { AccountAccessKeyCache } from './account-cache';
 import { cachedAsync } from './cached';
 import { Account } from './sdk-provider';
+import { traceMemberMethods } from './tracing';
 import { defaultCliUserAgent } from './user-agent';
 import { debug } from '../../logging';
 import { AuthenticationError } from '../../toolkit/error';
 import { formatErrorMessage } from '../../util/error';
-import { traceMethods } from '../../util/tracing';
 
 export interface S3ClientOptions {
   /**
@@ -521,14 +521,16 @@ export interface IStepFunctionsClient {
 /**
  * Base functionality of SDK without credential fetching
  */
-@traceMethods
+@traceMemberMethods
 export class SDK {
   private static readonly accountCache = new AccountAccessKeyCache();
 
   public readonly currentRegion: string;
 
   public readonly config: ConfigurationOptions;
 
+  protected readonly logger?: Logger;
+
   /**
    * STS is used to check credential validity, don't do too many retries.
    */
@@ -557,6 +559,7 @@ export class SDK {
       customUserAgent: defaultCliUserAgent(),
       logger,
     };
+    this.logger = logger;
     this.currentRegion = region;
   }
 

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

@@ -0,0 +1,59 @@
+import type { Logger } from '@smithy/types';
+
+let ENABLED = false;
+let INDENT = 0;
+
+export function setSdkTracing(enabled: boolean) {
+  ENABLED = enabled;
+}
+
+/**
+ * Method decorator to trace a single static or member method, any time it's called
+ */
+export function callTrace(fn: string, className?: string, logger?: Logger) {
+  if (!ENABLED || !logger) {
+    return;
+  }
+
+  logger.info(`[trace] ${' '.repeat(INDENT)}${className || '(anonymous)'}#${fn}()`);
+}
+
+/**
+ * Method decorator to trace a single member method any time it's called
+ */
+function traceCall(receiver: object, _propertyKey: string, descriptor: PropertyDescriptor, parentClassName?: string) {
+  const fn = descriptor.value;
+  const className = typeof receiver === 'function' ? receiver.name : parentClassName;
+
+  descriptor.value = function (...args: any[]) {
+    const logger = (this as any).logger;
+    if (!ENABLED || typeof logger?.info !== 'function') { return fn.apply(this, args); }
+
+    logger.info.apply(logger, [`[trace] ${' '.repeat(INDENT)}${className || this.constructor.name || '(anonymous)'}#${fn.name}()`]);
+    INDENT += 2;
+
+    const ret = fn.apply(this, args);
+    if (ret instanceof Promise) {
+      return ret.finally(() => {
+        INDENT -= 2;
+      });
+    } else {
+      INDENT -= 2;
+      return ret;
+    }
+  };
+  return descriptor;
+}
+
+/**
+ * Class decorator, enable tracing for all member methods on this class
+ * @deprecated this doesn't work well with localized logging instances, don't use
+ */
+export function traceMemberMethods(constructor: Function) {
+  // Instance members
+  for (const [name, descriptor] of Object.entries(Object.getOwnPropertyDescriptors(constructor.prototype))) {
+    if (typeof descriptor.value !== 'function') { continue; }
+    const newDescriptor = traceCall(constructor.prototype, name, descriptor, constructor.name) ?? descriptor;
+    Object.defineProperty(constructor.prototype, name, newDescriptor);
+  }
+}

packages/aws-cdk/lib/cli/cli.ts

@@ -8,6 +8,7 @@ import { checkForPlatformWarnings } from './platform-warnings';
 import * as version from './version';
 import { SdkProvider } from '../api/aws-auth';
 import { SdkToCliLogger } from '../api/aws-auth/sdk-logger';
+import { setSdkTracing } from '../api/aws-auth/tracing';
 import { BootstrapSource, Bootstrapper } from '../api/bootstrap';
 import { StackSelector } from '../api/cxapp/cloud-assembly';
 import { CloudExecutable, Synthesizer } from '../api/cxapp/cloud-executable';
@@ -28,7 +29,6 @@ import { Notices } from '../notices';
 import { Command, Configuration } from './user-configuration';
 import { IoMessageLevel, CliIoHost } from '../toolkit/cli-io-host';
 import { ToolkitError } from '../toolkit/error';
-import { enableTracing } from '../util/tracing';
 
 /* eslint-disable max-len */
 /* eslint-disable @typescript-eslint/no-shadow */ // yargs
@@ -66,7 +66,10 @@ export async function exec(args: string[], synthesizer?: Synthesizer): Promise<n
 
   // Debug should always imply tracing
   if (argv.debug || argv.verbose > 2) {
-    enableTracing(true);
+    setSdkTracing(true);
+  } else {
+    // cli-lib-alpha needs to explicitly set in case it was enabled before
+    setSdkTracing(false);
   }
 
   try {
@@ -104,7 +107,7 @@ export async function exec(args: string[], synthesizer?: Synthesizer): Promise<n
       proxyAddress: argv.proxy,
       caBundlePath: argv['ca-bundle-path'],
     },
-    logger: new SdkToCliLogger(),
+    logger: new SdkToCliLogger(ioHost),
   });
 
   let outDirLock: ILock | undefined;

packages/aws-cdk/lib/legacy-exports-source.ts

@@ -19,7 +19,7 @@ export { execProgram } from './api/cxapp/exec';
 export { RequireApproval } from './diff';
 export { leftPad } from './api/util/string-manipulation';
 export { formatAsBanner } from './cli/util/console-formatters';
-export { enableTracing } from './util/tracing';
+export { setSdkTracing as enableTracing } from './api/aws-auth/tracing';
 export { aliases, command, describe } from './commands/docs';
 export { lowerCaseFirstCharacter } from './api/hotswap/common';
 export { deepMerge } from './util/objects';

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

@@ -1,22 +1,24 @@
 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');
+  const ioHost = {
+    notify: jest.fn(),
+    requestResponse: jest.fn(),
+  };
+  const logger = new SdkToCliLogger(ioHost);
 
   beforeEach(() => {
-    trace.mockReset();
+    ioHost.notify.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(['trace', 'debug'] as Array<keyof SdkToCliLogger>)('%s method does not call notify', (method) => {
+    logger[method]('test');
+    expect(ioHost.notify).not.toHaveBeenCalled();
   });
 
-  test.each(['info', 'warn', 'error'] as Array<keyof SdkToCliLogger>)('%s method logs to trace', (meth) => {
-    logger[meth]('test');
-    expect(trace).toHaveBeenCalled();
+  test.each(['info', 'warn', 'error'] as Array<keyof SdkToCliLogger>)('%s method logs to notify', (method) => {
+    logger[method]('test');
+    expect(ioHost.notify).toHaveBeenCalled();
   });
 });