Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix(logger): wait for decorated method return before clearing out state #1087

Merged
merged 3 commits into from
Sep 29, 2022

Conversation

dreamorosi
Copy link
Contributor

Description of your changes

As reported in #1085 the injectLambdaContext decorator, when used on async methods, was not awaiting the method to return before performing other clean-up/post-exec logic.

This PR introduces an async/await in the decorator logic so that the decorated method is always awaited. This should appears to fix #1085.

Note to reviewers/readers:
It should be noted that the decorator will now always await the decorated method regardless of it being an async function or not. Based on what I was able to find online awaiting a non-promise should be a no-op and should not have a performance impact. If this is not the case please point this out during review and we'll try to implement a conditional logic. At the moment I went with always awaiting for the reason above and also because this is how the decorator is implemented in Tracer.

How to verify this change

See results of checks below the PR, or check the result of the integration tests here:
https://github.com/awslabs/aws-lambda-powertools-typescript/actions/runs/3032214494

Optionally, run npm pack -w packages/logger & test the change in the repo mentioned in the comment.

Related issues, RFCs

Issue number: #1085

PR status

Is this ready for review?: YES
Is it a breaking change?: NO

Checklist

  • My changes meet the tenets criteria
  • I have performed a self-review of my own code
  • I have commented my code where necessary, particularly in areas that should be flagged with a TODO, or hard-to-understand areas
  • I have made corresponding changes to the documentation
  • I have made corresponding changes to the examples
  • My changes generate no new warnings
  • The code coverage hasn't decreased
  • I have added tests that prove my change is effective and works
  • New and existing unit tests pass locally and in Github Actions
  • Any dependent changes have been merged and published in downstream module
  • The PR title follows the conventional commit semantics

Breaking change checklist

N/A


By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

@dreamorosi dreamorosi self-assigned this Sep 12, 2022
@dreamorosi dreamorosi linked an issue Sep 12, 2022 that may be closed by this pull request
@github-actions github-actions bot added the bug Something isn't working label Sep 12, 2022
@dreamorosi dreamorosi added the logger This item relates to the Logger Utility label Sep 12, 2022
Copy link
Contributor

@ijemmy ijemmy left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice finding. How did you figure out this is where the bug is?

await will wrap non-promise item in promise. It does change execution order. But that's the correct behavior in this case. (See Jonas Wilms' answer)

A few questions:

  1. Is it possible to add unit test to cover this case?
  2. I see the same issue in Tracer.ts 's captureMethod and captureLambdaHandler. Could we also fix that in this PR or log an issue for this (could be a good first issue) if not urgent.

@dreamorosi
Copy link
Contributor Author

Hello, I have added a unit test case for this feature.

I have detailed this in the comments inside the tests, but in order to test the fix I am asserting the call order between the cleanup function of the decorator (that should always be called after handler returns) and something inside the handler that is placed after an await. The correct order in this case should be: 1/ whatever is inside handler, 2/ the cleanup function.

This relies on an implementation detail of the decorator so it might not be the best solution formally speaking, but the only other alternative that I was able to test on was adding an artificial delay of at least 5000ms to the awaited method, so I went with this one.

If anyone has a better idea I'm open to adopt it.

@dreamorosi
Copy link
Contributor Author

@ijemmy I have opened an issue for Tracer like you suggested: #1091

Since I'm planning on using the same method to test the fix in the unit tests I'll wait till this PR is approved before starting to work on that PR.

@@ -275,7 +275,7 @@ class Logger extends Utility implements ClassThatLogs {
* @returns {HandlerMethodDecorator}
*/
public injectLambdaContext(options?: HandlerOptions): HandlerMethodDecorator {
return (target, _propertyKey, descriptor) => {
return (_target, _propertyKey, descriptor) => {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Housekeeping. The target param is never used so I'm prefixing it with underscore to tell the IDE that this is intended.


// Assess
expect(consoleSpy).toBeCalledTimes(1);
// Here we assert that the logger.info method is called before the cleanup function that should awlays
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit

Suggested change
// Here we assert that the logger.info method is called before the cleanup function that should awlays
// Here we assert that the logger.info method is called before the cleanup function that should always

@saragerion saragerion merged commit 133ed3c into main Sep 29, 2022
@saragerion saragerion deleted the 1085-bug-logger-decorator-clears-states-too-early branch September 29, 2022 09:49
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working logger This item relates to the Logger Utility
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Bug: Decorator clears states too early
4 participants