Skip to content

Reapply reduce requests necessary for log publishing from lambda to cloudwatch logs #12470

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.

Sign up for GitHub

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

Jump to bottom
Merged
merged 2 commits into from
Apr 3, 2025
Merged

Reapply reduce requests necessary for log publishing from lambda to cloudwatch logs #12470

merged 2 commits into from
Apr 3, 2025

Conversation

dfangl
Copy link
Member

@dfangl dfangl commented Apr 2, 2025

Motivation

With #10294 we had to revert increased performance for lambda cloudwatch logs, reduced requests necessary for every log storage from 3 to (on average) 1.

The root cause for this revert was the .splitlines() method used to split the logs, as it also splits on several other characters, like a carriage return, unlike the old log method.

Since the runtime interface clients patch the loggers (e.g. here: https://github.com/aws/aws-lambda-nodejs-runtime-interface-client/blob/2ea9a34b5c1b15621df132eb2d377ac54b330c8f/src/LogPatch.js#L82-L88), we need to leave carriage returns as is for now.

In the long term, to further increase logging parity, we need to:

  1. Properly log the INIT_START message (this should allow for proper snapshotting of logs as well then, as the count should align)
  2. Use the file descriptor based logging mechanism (counterpart to this: https://github.com/aws/aws-lambda-nodejs-runtime-interface-client/blob/2ea9a34b5c1b15621df132eb2d377ac54b330c8f/src/LogPatch.js#L102-L120). This should allow proper log line delimiters for logging as well, and avoid the replacement of newlines by carriage returns in some RIC patches.

The test added mostly assures normal carriage returns are not split into multiple messages - the main cause for the failing ext test.
In the future, with the improvements above, we need to add more tests for parity for different logging mechanisms.

Changes

  • Reduced load on LocalStack for every invocation, due to less requests.
  • Log events now have (correctly) trailing newlines, instead of stripping them out.

@dfangl dfangl added the semver: minor Non-breaking changes which can be included in minor releases, but not in patch releases label Apr 2, 2025
@dfangl dfangl self-assigned this Apr 2, 2025
@dfangl dfangl requested a review from gregfurman as a code owner April 2, 2025 12:57
@dfangl
Copy link
Member Author

dfangl commented Apr 2, 2025

Set the semver label to minor, as the changed log format (keeping newline endings) can be quite visible to the user, even though it is technically a parity improvement.

@dfangl dfangl marked this pull request as draft April 2, 2025 12:58
@github-actions GitHub Actions
Copy link

github-actions bot commented Apr 2, 2025

LocalStack Community integration with Pro

    2 files  ±    0      2 suites  ±0   1h 29m 7s ⏱️ - 20m 26s
3 144 tests  - 1 165  2 918 ✅  - 1 063  226 💤  - 102  0 ❌ ±0 
3 146 runs   - 1 165  2 918 ✅  - 1 063  228 💤  - 102  0 ❌ ±0 

Results for commit d1a87aa. ± Comparison against base commit e1f3422.

This pull request removes 1166 and adds 1 tests. Note that renamed tests count towards both. 
tests.aws.scenario.bookstore.test_bookstore.TestBookstoreApplication ‑ test_lambda_dynamodb
tests.aws.scenario.bookstore.test_bookstore.TestBookstoreApplication ‑ test_opensearch_crud
tests.aws.scenario.bookstore.test_bookstore.TestBookstoreApplication ‑ test_search_books
tests.aws.scenario.bookstore.test_bookstore.TestBookstoreApplication ‑ test_setup
tests.aws.scenario.kinesis_firehose.test_kinesis_firehose.TestKinesisFirehoseScenario ‑ test_kinesis_firehose_s3
tests.aws.scenario.lambda_destination.test_lambda_destination_scenario.TestLambdaDestinationScenario ‑ test_destination_sns
tests.aws.scenario.lambda_destination.test_lambda_destination_scenario.TestLambdaDestinationScenario ‑ test_infra
tests.aws.scenario.loan_broker.test_loan_broker.TestLoanBrokerScenario ‑ test_prefill_dynamodb_table
tests.aws.scenario.loan_broker.test_loan_broker.TestLoanBrokerScenario ‑ test_stepfunctions_input_recipient_list[step_function_input0-SUCCEEDED]
tests.aws.scenario.loan_broker.test_loan_broker.TestLoanBrokerScenario ‑ test_stepfunctions_input_recipient_list[step_function_input1-SUCCEEDED]
…

tests.aws.services.lambda_.test_lambda_runtimes.TestCloudwatchLogs ‑ test_multi_line_prints

@dfangl
Copy link
Member Author

dfangl commented Apr 2, 2025

Ext run: https://github.com/localstack/localstack-ext/actions/runs/14221427642

@dfangl dfangl marked this pull request as ready for review April 2, 2025 13:55
joe4dev
joe4dev approved these changes Apr 3, 2025
View reviewed changes
Copy link
Member

@joe4dev joe4dev left a comment

Choose a reason for hiding this comment

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

LGTM 🚀

Thanks for re-introducing this optimization and pointing out the next steps. I created a backlog item to capture these improvement suggestions.

Ext run is 🟢

localstack-core/localstack/services/lambda_/invocation/logs.py
@@ -50,10 +50,34 @@ def run_log_loop(self, *args, **kwargs) -> None:
log_item = self.log_queue.get()
if log_item is QUEUE_SHUTDOWN:
return
# we need to split by newline - but keep the newlines in the strings
# strips empty lines, as they are not accepted by cloudwatch
logs = [line + "\n" for line in log_item.logs.split("\n") if line]
Copy link
Member

Choose a reason for hiding this comment

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

Do we have a test for the empty lines case?

Copy link
Member Author

@dfangl dfangl Apr 3, 2025 •
edited
Loading

Choose a reason for hiding this comment

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

No, but cloud watch does not accept empty lines. The logic matches the one in store_cloudwatch_logs though, so we at least do not get worse in terms of parity. We should write tests for this though, when we rework the logging in general.

localstack-core/localstack/services/lambda_/invocation/logs.py
@@ -50,10 +50,34 @@ def run_log_loop(self, *args, **kwargs) -> None:
log_item = self.log_queue.get()
if log_item is QUEUE_SHUTDOWN:
return
# we need to split by newline - but keep the newlines in the strings
# strips empty lines, as they are not accepted by cloudwatch
logs = [line + "\n" for line in log_item.logs.split("\n") if line]
Copy link
Member

Choose a reason for hiding this comment

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

Following this discussion, do we have an intuition where these replacements came from?

log_output = log_output.replace("\\x1b", "\n\\x1b")
log_output = log_output.replace("\x1b", "\n\x1b")

I just wanted to add the reference in case we need to add them reactively because we removed them without knowing where they came from 😄

Copy link
Member Author

Choose a reason for hiding this comment

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

No, still no idea. Since those are ANSI escape sequences, I still think they stem from the time were we captured the lambda logs directly from docker running inside a full terminal instance.

@dfangl dfangl merged commit bb68b2e into master Apr 3, 2025
34 checks passed
@dfangl dfangl deleted the improve-lambda-log-efficiency branch April 3, 2025 11:54
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@joe4dev joe4dev joe4dev approved these changes

@dominikschubert dominikschubert Awaiting requested review from dominikschubert dominikschubert is a code owner

@gregfurman gregfurman Awaiting requested review from gregfurman gregfurman is a code owner

Assignees

@dfangl dfangl

Labels
semver: minor Non-breaking changes which can be included in minor releases, but not in patch releases
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@dfangl @joe4dev