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): change logging to use stdout #748

Merged
merged 5 commits into from Apr 14, 2022
Merged

Conversation

dreamorosi
Copy link
Contributor

@dreamorosi dreamorosi commented Apr 8, 2022

Description of your changes

As reported by user @olanb7 on the community Slack and in #747 before this PR Logger would output logs like this:

2022-04-08T10:58:44.811Z	b6511ee9-4873-404e-b60c-a23cb45d3ff2	INFO {"cold_start":false,"function_arn":"arn:aws:lambda:eu-west-2:12345:function:test","function_memory_size":1024,"function_name":"test","function_request_id":"b6511ee9-4873-404e-b60c-a23cb45d3ff2","level":"INFO","message":"test message","service":"test","timestamp":"2022-04-08T10:58:44.811Z"}

These logs, although containing a structured JSON, are not JSON as they are always prefixed by 2022-04-08T10:58:44.811Z b6511ee9-4873-404e-b60c-a23cb45d3ff2 INFO.

This also confirmed by a line in the Lambda docs (emphasis mine):

The Node.js runtime logs the START, END, and REPORT lines for each invocation. It adds a timestamp, request ID, and log level to each entry logged by the function.

This behaviour works well with CloudWatch but the presence of these prefixes was an issue for customers wanting to use these structured logs elsewhere (both 3rd party services and AWS Managed Grafana).

From this PR onwards Logger will be using its own internal and private version of the Console class that only outputs the structured JSON log without any prefix:

{"cold_start":false,"function_arn":"arn:aws:lambda:eu-west-2:12345:function:test","function_memory_size":1024,"function_name":"test","function_request_id":"b6511ee9-4873-404e-b60c-a23cb45d3ff2","level":"INFO","message":"test message","service":"test","timestamp":"2022-04-08T10:58:44.811Z"}

Aside from 3-lines change in the Logger class, all the rest of the changes in this PR are related to the unit and integration tests.

How to verify this change

See the results of checks inside this PR and e2e tests (to be run).

Also see screenshot below:
image

Related issues, RFCs

#747

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
  • 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 Apr 8, 2022
@dreamorosi dreamorosi added this to Pull Requests - Work in progress in Pull Requests via automation Apr 8, 2022
@dreamorosi dreamorosi added this to the production-ready-release milestone Apr 8, 2022
@dreamorosi dreamorosi linked an issue Apr 8, 2022 that may be closed by this pull request
@github-actions github-actions bot added the bug Something isn't working label Apr 8, 2022
@dreamorosi dreamorosi added the logger This item relates to the Logger Utility label Apr 13, 2022
@dreamorosi dreamorosi marked this pull request as ready for review April 13, 2022 17:11
@dreamorosi
Copy link
Contributor Author

@dreamorosi dreamorosi requested a review from flochaz April 14, 2022 09:53
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.

Thanks for cleaning up those small things.

I have one question just to double check.


describe('Middy middleware', () => {

const ENVIRONMENT_VARIABLES = process.env;

beforeEach(() => {
jest.resetModules();
// eslint-disable-next-line @typescript-eslint/no-empty-function
jest.spyOn(console, 'log').mockImplementation(() => {});
jest.spyOn(process.stdout, 'write').mockImplementation(() => null as unknown as boolean);
Copy link
Contributor

Choose a reason for hiding this comment

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

Why double cast? Is this intentional?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

It's only to please the TypeScript compiler.

If doing null as boolean it would give me this error:

error TS2352: Conversion of type 'null' to type 'boolean' may be a mistake because neither type sufficiently overlaps with the other. If this was intentional, convert the expression to 'unknown' first.

jest.spyOn(process.stdout, 'write').mockImplementation(() => null as boolean);

Copy link
Contributor

Choose a reason for hiding this comment

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

Got it. Thanks.

Copy link
Contributor

@flochaz flochaz left a comment

Choose a reason for hiding this comment

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

LGTM

Pull Requests automation moved this from Pull Requests - Work in progress to Pull Requests - Approved and ready to be merged Apr 14, 2022
@dreamorosi dreamorosi merged commit 0781a47 into main Apr 14, 2022
Pull Requests automation moved this from Pull Requests - Approved and ready to be merged to Pull Requests - Merged or Closed Apr 14, 2022
@dreamorosi dreamorosi deleted the fix/logger/use_stdout branch April 14, 2022 11:00
@mrerichoffman
Copy link

mrerichoffman commented Sep 21, 2022

I'm curious does this change break tracing in cloudwatch? I thought that the default console log formatting is used to correlate logs across requests in cloudwatch tracing and x-ray.

@dreamorosi
Copy link
Contributor Author

Hi @mrerichoffman, thanks for the message. I think I have an idea of what you're referring to but I'd like to make sure we are on the same page.

Would you mind please opening and elaborating on what you're (not) seeing and what you're expecting to see and where? This would also help others find the same issue in the future since this is an old PR.

Thank you!

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
No open projects
Pull Requests
Pull Requests - Merged or Closed
Development

Successfully merging this pull request may close these issues.

Feature request: logger should write to stdout directly
4 participants