diff --git a/packages/aws-cdk/lib/api/aws-auth/sdk-logger.ts b/packages/aws-cdk/lib/api/aws-auth/sdk-logger.ts new file mode 100644 index 0000000000000..a3d0b803db388 --- /dev/null +++ b/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; + metadata?: { + httpStatusCode?: number; + requestId?: string; + extendedRequestId?: string; + cfId?: string; + attempts?: number; + totalRetryDelay?: number; + }; +} + +type SdkApiCallSuccess = SdkApiCallBase & { output: Record }; +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; +} \ No newline at end of file diff --git a/packages/aws-cdk/lib/api/aws-auth/sdk-provider.ts b/packages/aws-cdk/lib/api/aws-auth/sdk-provider.ts index e1d631672d39e..4a5e968260afe 100644 --- a/packages/aws-cdk/lib/api/aws-auth/sdk-provider.ts +++ b/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; diff --git a/packages/aws-cdk/lib/api/aws-auth/sdk.ts b/packages/aws-cdk/lib/api/aws-auth/sdk.ts index 4924a6a1e5fef..7d60c1aa287b4 100644 --- a/packages/aws-cdk/lib/api/aws-auth/sdk.ts +++ b/packages/aws-cdk/lib/api/aws-auth/sdk.ts @@ -545,6 +545,7 @@ export class SDK { private readonly _credentials: AwsCredentialIdentity, region: string, requestHandler: NodeHttpHandlerOptions, + logger?: Logger, ) { this.config = { region, @@ -552,6 +553,7 @@ export class SDK { requestHandler, retryStrategy: new ConfiguredRetryStrategy(7, (attempt) => 300 * (2 ** attempt)), customUserAgent: defaultCliUserAgent(), + logger, }; this.currentRegion = region; } diff --git a/packages/aws-cdk/lib/cli.ts b/packages/aws-cdk/lib/cli.ts index 267124db42de2..c4c1912830826 100644 --- a/packages/aws-cdk/lib/cli.ts +++ b/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 { - 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()}]`); } diff --git a/packages/aws-cdk/test/api/aws-auth/__snapshots__/sdk-logger.test.ts.snap b/packages/aws-cdk/test/api/aws-auth/__snapshots__/sdk-logger.test.ts.snap new file mode 100644 index 0000000000000..8fb0d999e1994 --- /dev/null +++ b/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"`; diff --git a/packages/aws-cdk/test/api/aws-auth/sdk-logger.test.ts b/packages/aws-cdk/test/api/aws-auth/sdk-logger.test.ts new file mode 100644 index 0000000000000..0217cba8d2248 --- /dev/null +++ b/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)('%s method does not call trace', (meth) => { + logger[meth]('test'); + expect(trace).not.toHaveBeenCalled(); + }); + + test.each(['info', 'warn', 'error'] as Array)('%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'); +}); \ No newline at end of file