-
Notifications
You must be signed in to change notification settings - Fork 3.9k
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
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*
- Loading branch information
Showing
8 changed files
with
249 additions
and
8 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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; | ||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
5 changes: 5 additions & 0 deletions
5
packages/aws-cdk/test/api/aws-auth/__snapshots__/sdk-logger.test.ts.snap
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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"`; |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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'); | ||
| }); |