Skip to content

Commit e32021c

Browse files
Merge pull request #11 from eduardomourar/feature/0010-improve-error-logging
Improve error logging
2 parents f879739 + 4e4309d commit e32021c

File tree

10 files changed

+355
-98
lines changed

10 files changed

+355
-98
lines changed

package-lock.json

Lines changed: 14 additions & 3 deletions
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

package.json

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,7 @@
3434
"homepage": "https://github.com/eduardomourar/cloudformation-cli-typescript-plugin#readme",
3535
"dependencies": {
3636
"autobind-decorator": "^2.4.0",
37+
"promise-sequential": "^1.1.1",
3738
"reflect-metadata": "^0.1.13",
3839
"tombok": "https://github.com/eduardomourar/tombok/releases/download/v0.0.1/tombok-0.0.1.tgz",
3940
"uuid": "^7.0.2"
@@ -42,6 +43,7 @@
4243
"@types/aws-sdk": "^2.7.0",
4344
"@types/jest": "^25.2.1",
4445
"@types/node": "^12.0.0",
46+
"@types/promise-sequential": "^1.1.0",
4547
"@types/uuid": "^7.0.0",
4648
"@typescript-eslint/eslint-plugin": "^2.29.0",
4749
"@typescript-eslint/parser": "^2.19.2",
@@ -54,12 +56,12 @@
5456
"eslint-plugin-prettier": "^3.1.3",
5557
"jest": "^25.5.2",
5658
"minimist": ">=1.2.5",
57-
"prettier": "2.0.5",
59+
"prettier": "^2.0.5",
5860
"ts-jest": "^25.4.0",
5961
"typescript": "^3.7.0"
6062
},
6163
"optionalDependencies": {
62-
"aws-sdk": "^2.656.0"
64+
"aws-sdk": "~2.631.0"
6365
},
6466
"prettier": {
6567
"parser": "typescript",

python/rpdk/typescript/codegen.py

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@
2020
SUPPORT_LIB_VERSION = "0.1.1"
2121
MAIN_HANDLER_FUNCTION = "TypeFunction"
2222
REPO_URL = "https://github.com/eduardomourar/cloudformation-cli-typescript-plugin"
23+
REPO_RELEASE_SUFFIX = f"v{SUPPORT_LIB_VERSION}/cfn-rpdk-{SUPPORT_LIB_VERSION}.tgz"
2324

2425

2526
def validate_no(value):
@@ -33,7 +34,7 @@ class TypescriptLanguagePlugin(LanguagePlugin):
3334
ENTRY_POINT = "dist/handlers.entrypoint"
3435
TEST_ENTRY_POINT = "dist/handlers.testEntrypoint"
3536
CODE_URI = "./"
36-
SUPPORT_LIB_URI = f"{REPO_URL}/releases/download/v{SUPPORT_LIB_VERSION}/cfn-rpdk-{SUPPORT_LIB_VERSION}.tgz"
37+
SUPPORT_LIB_URI = f"{REPO_URL}/releases/download/{REPO_RELEASE_SUFFIX}"
3738

3839
def __init__(self):
3940
self.env = self._setup_jinja_env(

python/rpdk/typescript/templates/README.md

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -35,3 +35,5 @@ const progress: ProgressEvent = ProgressEvent.builder()
3535
```
3636

3737
While importing the [{{ lib_name }}](https://github.com/eduardomourar/cloudformation-cli-typescript-plugin) library, failures can be passed back to CloudFormation by either raising an exception from `exceptions`, or setting the ProgressEvent's `status` to `OperationStatus.Failed` and `errorCode` to one of `HandlerErrorCode`. There is a static helper function, `ProgressEvent.failed`, for this common case.
38+
39+
Keep in mind, during runtime all logs will be delivered to CloudWatch except those used with `debug` method.

python/rpdk/typescript/templates/handlers.ts

Lines changed: 41 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,14 @@ const LOGGER = console;
1818

1919
class Resource extends BaseResource<ResourceModel> {
2020

21+
/**
22+
* CloudFormation invokes this handler when the resource is initially created
23+
* during stack create operations.
24+
*
25+
* @param session Current AWS session passed through from caller
26+
* @param request The request object for the provisioning request passed to the implementor
27+
* @param callbackContext Custom context object to enable handlers to process re-invocation
28+
*/
2129
@handlerEvent(Action.Create)
2230
public async create(
2331
session: Optional<SessionProxy>,
@@ -48,6 +56,14 @@ class Resource extends BaseResource<ResourceModel> {
4856
return progress;
4957
}
5058

59+
/**
60+
* CloudFormation invokes this handler when the resource is updated
61+
* as part of a stack update operation.
62+
*
63+
* @param session Current AWS session passed through from caller
64+
* @param request The request object for the provisioning request passed to the implementor
65+
* @param callbackContext Custom context object to enable handlers to process re-invocation
66+
*/
5167
@handlerEvent(Action.Update)
5268
public async update(
5369
session: Optional<SessionProxy>,
@@ -64,6 +80,15 @@ class Resource extends BaseResource<ResourceModel> {
6480
return progress;
6581
}
6682

83+
/**
84+
* CloudFormation invokes this handler when the resource is deleted, either when
85+
* the resource is deleted from the stack as part of a stack update operation,
86+
* or the stack itself is deleted.
87+
*
88+
* @param session Current AWS session passed through from caller
89+
* @param request The request object for the provisioning request passed to the implementor
90+
* @param callbackContext Custom context object to enable handlers to process re-invocation
91+
*/
6792
@handlerEvent(Action.Delete)
6893
public async delete(
6994
session: Optional<SessionProxy>,
@@ -80,6 +105,14 @@ class Resource extends BaseResource<ResourceModel> {
80105
return progress;
81106
}
82107

108+
/**
109+
* CloudFormation invokes this handler as part of a stack update operation when
110+
* detailed information about the resource's current state is required.
111+
*
112+
* @param session Current AWS session passed through from caller
113+
* @param request The request object for the provisioning request passed to the implementor
114+
* @param callbackContext Custom context object to enable handlers to process re-invocation
115+
*/
83116
@handlerEvent(Action.Read)
84117
public async read(
85118
session: Optional<SessionProxy>,
@@ -95,6 +128,14 @@ class Resource extends BaseResource<ResourceModel> {
95128
return progress;
96129
}
97130

131+
/**
132+
* CloudFormation invokes this handler when summary information about multiple
133+
* resources of this resource provider is required.
134+
*
135+
* @param session Current AWS session passed through from caller
136+
* @param request The request object for the provisioning request passed to the implementor
137+
* @param callbackContext Custom context object to enable handlers to process re-invocation
138+
*/
98139
@handlerEvent(Action.List)
99140
public async list(
100141
session: Optional<SessionProxy>,

src/callback.ts

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -37,6 +37,7 @@ export async function reportProgress(options: ProgressOptions): Promise<void> {
3737
}
3838
if (currentOperationStatus) {
3939
request.CurrentOperationStatus = currentOperationStatus;
40+
LOGGER.debug('Record Handler Progress Request:', request);
4041
const response: { [key: string]: any } = await client
4142
.recordHandlerProgress(request)
4243
.promise();
@@ -45,8 +46,8 @@ export async function reportProgress(options: ProgressOptions): Promise<void> {
4546
requestId = response.ResponseMetadata.RequestId;
4647
}
4748
LOGGER.debug(
48-
`Record Handler Progress with Request Id ${requestId} and Request:`,
49-
request
49+
`Record handler progress with Request Id ${requestId} and response:`,
50+
response
5051
);
5152
}
5253
}

src/log-delivery.ts

Lines changed: 83 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -1,16 +1,20 @@
11
import { boundMethod } from 'autobind-decorator';
22
import { EventEmitter } from 'events';
33
import CloudWatchLogs, {
4+
DescribeLogStreamsResponse,
5+
LogStream,
46
InputLogEvent,
57
PutLogEventsRequest,
68
PutLogEventsResponse,
79
} from 'aws-sdk/clients/cloudwatchlogs';
810
import S3, { PutObjectRequest, PutObjectOutput } from 'aws-sdk/clients/s3';
11+
import promiseSequential from 'promise-sequential';
912

1013
import { SessionProxy } from './proxy';
11-
import { HandlerRequest, runInSequence } from './utils';
14+
import { delay, HandlerRequest } from './utils';
1215

1316
type Console = globalThis.Console;
17+
type PromiseFunction = () => Promise<any>;
1418

1519
interface LogOptions {
1620
groupName: string;
@@ -26,13 +30,14 @@ export class ProviderLogHandler {
2630
private static instance: ProviderLogHandler;
2731
public emitter: LogEmitter;
2832
public client: CloudWatchLogs;
29-
public sequenceToken = '';
33+
public sequenceToken: string = null;
3034
public accountId: string;
3135
public groupName: string;
3236
public stream: string;
3337
public logger: Console;
3438
public clientS3: S3;
35-
private stack: Array<Promise<any>> = [];
39+
private stack: Array<PromiseFunction> = [];
40+
private isProcessing = false;
3641

3742
/**
3843
* The ProviderLogHandler's constructor should always be private to prevent direct
@@ -50,28 +55,50 @@ export class ProviderLogHandler {
5055
const logger = options.logger || global.console;
5156
this.logger = logger;
5257
this.emitter.on('log', (...args: any[]) => {
53-
this.stack.push(this.deliverLog(args));
58+
// this.logger.debug('Emitting log event...');
5459
});
5560
// Create maps of each logger method and then alias that.
5661
Object.entries(this.logger).forEach(([key, val]) => {
5762
if (typeof val === 'function') {
5863
if (['log', 'error', 'warn', 'info'].includes(key)) {
59-
this.logger[key as 'log' | 'error' | 'warn' | 'info'] = function (
64+
this.logger[key as 'log' | 'error' | 'warn' | 'info'] = (
6065
...args: any[]
61-
): void {
62-
// For adding other event watchers later.
63-
setImmediate(() => emitter.emit('log', ...args));
66+
): void => {
67+
if (!this.isProcessing) {
68+
const logLevel = key.toUpperCase();
69+
// Add log level when not present
70+
if (
71+
args.length &&
72+
(typeof args[0] !== 'string' ||
73+
args[0]
74+
.substring(0, logLevel.length)
75+
.toUpperCase() !== logLevel)
76+
) {
77+
args.unshift(logLevel);
78+
}
79+
this.stack.push(() =>
80+
this.deliverLog(args).catch(this.logger.debug)
81+
);
82+
// For adding other event watchers later.
83+
setImmediate(() => {
84+
this.emitter.emit('log', ...args);
85+
});
86+
} else {
87+
this.logger.debug(
88+
'Logs are being delivered at the moment...'
89+
);
90+
}
6491

6592
// Calls the logger method.
66-
val.apply(this, args);
93+
val.apply(this.logger, args);
6794
};
6895
}
6996
}
7097
});
7198
}
7299

73100
private async initialize(): Promise<void> {
74-
this.sequenceToken = '';
101+
this.sequenceToken = null;
75102
this.stack = [];
76103
try {
77104
await this.deliverLogCloudWatch(['Initialize CloudWatch']);
@@ -142,11 +169,13 @@ export class ProviderLogHandler {
142169

143170
@boundMethod
144171
public async processLogs(): Promise<void> {
172+
this.isProcessing = true;
145173
if (this.stack.length > 0) {
146-
this.stack.push(this.deliverLog(['Log delivery finalized.']));
174+
this.stack.push(() => this.deliverLog(['Log delivery finalized.']));
147175
}
148-
await runInSequence(this.stack);
176+
await promiseSequential(this.stack);
149177
this.stack = [];
178+
this.isProcessing = false;
150179
}
151180

152181
private async createLogGroup(): Promise<void> {
@@ -199,27 +228,48 @@ export class ProviderLogHandler {
199228
const response: PutLogEventsResponse = await this.client
200229
.putLogEvents(logEventsParams)
201230
.promise();
202-
this.sequenceToken = response?.nextSequenceToken;
231+
this.sequenceToken = response?.nextSequenceToken || null;
203232
this.logger.debug('Response from "putLogEvents"', response);
204233
return response;
205234
} catch (err) {
206235
const errorCode = err.code || err.name;
207-
this.logger.debug('Error from "deliverLogCloudWatch"', err);
208-
this.logger.debug(`Error from 'putLogEvents' ${JSON.stringify(err)}`);
236+
this.logger.debug(
237+
`Error from "putLogEvents" with sequence token ${this.sequenceToken}`,
238+
err
239+
);
209240
if (
210241
errorCode === 'DataAlreadyAcceptedException' ||
211242
errorCode === 'InvalidSequenceTokenException'
212243
) {
213-
this.sequenceToken = (err.message || '').split(' ').pop();
214-
this.putLogEvents(record);
244+
this.sequenceToken = null;
245+
// Delay to avoid throttling
246+
await delay(1);
247+
try {
248+
const response: DescribeLogStreamsResponse = await this.client
249+
.describeLogStreams({
250+
logGroupName: this.groupName,
251+
logStreamNamePrefix: this.stream,
252+
limit: 1,
253+
})
254+
.promise();
255+
this.logger.debug('Response from "describeLogStreams"', response);
256+
if (response.logStreams && response.logStreams.length) {
257+
const logStream = response.logStreams[0] as LogStream;
258+
this.sequenceToken = logStream.uploadSequenceToken;
259+
}
260+
} catch (err) {
261+
this.logger.debug('Error from "describeLogStreams"', err);
262+
}
215263
} else {
216264
throw err;
217265
}
218266
}
219267
}
220268

221269
@boundMethod
222-
private async deliverLogCloudWatch(messages: any[]): Promise<PutLogEventsResponse> {
270+
private async deliverLogCloudWatch(
271+
messages: any[]
272+
): Promise<PutLogEventsResponse | void> {
223273
const currentTime = new Date(Date.now());
224274
const record: InputLogEvent = {
225275
message: JSON.stringify({ messages }),
@@ -236,8 +286,20 @@ export class ProviderLogHandler {
236286
await this.createLogGroup();
237287
}
238288
await this.createLogStream();
239-
return this.putLogEvents(record);
240-
} else {
289+
} else if (
290+
errorCode !== 'DataAlreadyAcceptedException' &&
291+
errorCode !== 'InvalidSequenceTokenException'
292+
) {
293+
throw err;
294+
}
295+
try {
296+
const response = await this.putLogEvents(record);
297+
return response;
298+
} catch (err) {
299+
// Additional retry for sequence token error
300+
if (this.sequenceToken) {
301+
return this.putLogEvents(record);
302+
}
241303
throw err;
242304
}
243305
}
@@ -316,7 +378,7 @@ export class ProviderLogHandler {
316378
@boundMethod
317379
private async deliverLog(
318380
messages: any[]
319-
): Promise<PutLogEventsResponse | PutObjectOutput> {
381+
): Promise<PutLogEventsResponse | PutObjectOutput | void> {
320382
if (this.clientS3) {
321383
return this.deliverLogS3(messages);
322384
}

0 commit comments

Comments
 (0)