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

Multiline output from local invoke gets chopped short #3770

Closed
IamFlowZ opened this issue Mar 23, 2022 · 16 comments
Closed

Multiline output from local invoke gets chopped short #3770

IamFlowZ opened this issue Mar 23, 2022 · 16 comments
Labels
stage/needs-investigation Requires a deeper investigation type/bug

Comments

@IamFlowZ
Copy link

Description:

When locally invoking lambdas via local invoke, multi-line console logs are typically cut short, causing them to be illegible.

Steps to reproduce:

  1. start a cdk TS project
  2. write lambda that produces multi line console log
  3. cdk synth project
  4. sam local invoke that lambda
  5. note that the multiline console log does not get formatted correctly

Observed result:

2022-03-23 10:22:25,016 | Telemetry endpoint configured to be https://aws-serverless-tools-telemetry.us-west-2.amazonaws.com/metrics
2022-03-23 10:22:25,016 | Using config file: samconfig.toml, config environment: default
2022-03-23 10:22:25,016 | Expand command line arguments to:
2022-03-23 10:22:25,016 | --template_file=/home/dakotal/Projects/QSR/myq_cloud_wfm/cdk.out/assembly-wfm-new-dev-pipeline-NewWfmStage/wfmnewdevpipelineNewWfmStageNewWfmStackIngestionStack5AC9C424.nested.template.json --function_logical_id=athenaHandler --layer_cache_basedir=/home/dakotal/.aws-sam/layers-pkg --container_host=localhost --container_host_interface=127.0.0.1 
2022-03-23 10:22:25,017 | local invoke command is called
2022-03-23 10:22:25,017 | No Parameters detected in the template
2022-03-23 10:22:25,028 | CDK Path for resource athenaResultsBucket77A2A720 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaResultsBucket', 'Resource']
2022-03-23 10:22:25,028 | CDK Path for resource athenaQueryFormatterServiceRole164919FA is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaQueryFormatter', 'ServiceRole', 'Resource']
2022-03-23 10:22:25,028 | CDK Path for resource athenaQueryFormatterServiceRoleDefaultPolicyD8E81B80 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaQueryFormatter', 'ServiceRole', 'DefaultPolicy', 'Resource']
2022-03-23 10:22:25,028 | CDK Path for resource athenaQueryFormatterD86A8A4A is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaQueryFormatter', 'Resource']
2022-03-23 10:22:25,028 | CDK Path for resource athenaHandlerServiceRole0BAF02D3 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaHandler', 'ServiceRole', 'Resource']
2022-03-23 10:22:25,028 | CDK Path for resource athenaHandler2182D0CE is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaHandler', 'Resource']
2022-03-23 10:22:25,028 | CDK Path for resource queryPrepRule73163A06 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'queryPrepRule', 'Resource']
2022-03-23 10:22:25,028 | CDK Path for resource queryPrepRuleAllowEventRulewfmnewdevpipelineNewWfmStageNewWfmStackIngestionStackathenaQueryFormatterE29DC9D75AA7B6E4 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'queryPrepRule', 'AllowEventRulewfmnewdevpipelineNewWfmStageNewWfmStackIngestionStackathenaQueryFormatterE29DC9D7']
2022-03-23 10:22:25,028 | CDK Path for resource athenaResultsRule3F12FB94 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaResultsRule', 'Resource']
2022-03-23 10:22:25,028 | CDK Path for resource athenaResultsRuleAllowEventRulewfmnewdevpipelineNewWfmStageNewWfmStackIngestionStackathenaHandler2A490B6C160F8596 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaResultsRule', 'AllowEventRulewfmnewdevpipelineNewWfmStageNewWfmStackIngestionStackathenaHandler2A490B6C']
2022-03-23 10:22:25,028 | CDK Path for resource CDKMetadata is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'CDKMetadata', 'Default']
2022-03-23 10:22:25,029 | 11 stacks found in the template
2022-03-23 10:22:25,029 | No Parameters detected in the template
2022-03-23 10:22:25,038 | CDK Path for resource athenaResultsBucket77A2A720 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaResultsBucket', 'Resource']
2022-03-23 10:22:25,038 | CDK Path for resource athenaQueryFormatterServiceRole164919FA is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaQueryFormatter', 'ServiceRole', 'Resource']
2022-03-23 10:22:25,038 | CDK Path for resource athenaQueryFormatterServiceRoleDefaultPolicyD8E81B80 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaQueryFormatter', 'ServiceRole', 'DefaultPolicy', 'Resource']
2022-03-23 10:22:25,038 | CDK Path for resource athenaQueryFormatterD86A8A4A is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaQueryFormatter', 'Resource']
2022-03-23 10:22:25,038 | CDK Path for resource athenaHandlerServiceRole0BAF02D3 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaHandler', 'ServiceRole', 'Resource']
2022-03-23 10:22:25,038 | CDK Path for resource athenaHandler2182D0CE is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaHandler', 'Resource']
2022-03-23 10:22:25,038 | CDK Path for resource queryPrepRule73163A06 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'queryPrepRule', 'Resource']
2022-03-23 10:22:25,039 | CDK Path for resource queryPrepRuleAllowEventRulewfmnewdevpipelineNewWfmStageNewWfmStackIngestionStackathenaQueryFormatterE29DC9D75AA7B6E4 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'queryPrepRule', 'AllowEventRulewfmnewdevpipelineNewWfmStageNewWfmStackIngestionStackathenaQueryFormatterE29DC9D7']
2022-03-23 10:22:25,039 | CDK Path for resource athenaResultsRule3F12FB94 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaResultsRule', 'Resource']
2022-03-23 10:22:25,039 | CDK Path for resource athenaResultsRuleAllowEventRulewfmnewdevpipelineNewWfmStageNewWfmStackIngestionStackathenaHandler2A490B6C160F8596 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaResultsRule', 'AllowEventRulewfmnewdevpipelineNewWfmStageNewWfmStackIngestionStackathenaHandler2A490B6C']
2022-03-23 10:22:25,039 | CDK Path for resource CDKMetadata is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'CDKMetadata', 'Default']
2022-03-23 10:22:25,039 | 11 resources found in the stack 
2022-03-23 10:22:25,039 | No Parameters detected in the template
2022-03-23 10:22:25,049 | CDK Path for resource athenaResultsBucket77A2A720 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaResultsBucket', 'Resource']
2022-03-23 10:22:25,049 | CDK Path for resource athenaQueryFormatterServiceRole164919FA is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaQueryFormatter', 'ServiceRole', 'Resource']
2022-03-23 10:22:25,049 | CDK Path for resource athenaQueryFormatterServiceRoleDefaultPolicyD8E81B80 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaQueryFormatter', 'ServiceRole', 'DefaultPolicy', 'Resource']
2022-03-23 10:22:25,049 | CDK Path for resource athenaQueryFormatterD86A8A4A is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaQueryFormatter', 'Resource']
2022-03-23 10:22:25,049 | CDK Path for resource athenaHandlerServiceRole0BAF02D3 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaHandler', 'ServiceRole', 'Resource']
2022-03-23 10:22:25,049 | CDK Path for resource athenaHandler2182D0CE is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaHandler', 'Resource']
2022-03-23 10:22:25,049 | CDK Path for resource queryPrepRule73163A06 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'queryPrepRule', 'Resource']
2022-03-23 10:22:25,049 | CDK Path for resource queryPrepRuleAllowEventRulewfmnewdevpipelineNewWfmStageNewWfmStackIngestionStackathenaQueryFormatterE29DC9D75AA7B6E4 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'queryPrepRule', 'AllowEventRulewfmnewdevpipelineNewWfmStageNewWfmStackIngestionStackathenaQueryFormatterE29DC9D7']
2022-03-23 10:22:25,049 | CDK Path for resource athenaResultsRule3F12FB94 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaResultsRule', 'Resource']
2022-03-23 10:22:25,049 | CDK Path for resource athenaResultsRuleAllowEventRulewfmnewdevpipelineNewWfmStageNewWfmStackIngestionStackathenaHandler2A490B6C160F8596 is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'athenaResultsRule', 'AllowEventRulewfmnewdevpipelineNewWfmStageNewWfmStackIngestionStackathenaHandler2A490B6C']
2022-03-23 10:22:25,049 | CDK Path for resource CDKMetadata is ['wfm-new-dev-pipeline', 'NewWfmStage', 'NewWfmStack', 'IngestionStack', 'CDKMetadata', 'Default']
2022-03-23 10:22:25,050 | Found Lambda function with name='athenaQueryFormatterD86A8A4A' and CodeUri='../asset.691dfa7b1cfa94ee92558d71b6aaf9fa4d0a4edd3d969794613ede5642e4617f'
2022-03-23 10:22:25,050 | --base-dir is not presented, adjusting uri ../asset.691dfa7b1cfa94ee92558d71b6aaf9fa4d0a4edd3d969794613ede5642e4617f relative to /home/dakotal/Projects/QSR/myq_cloud_wfm/cdk.out/assembly-wfm-new-dev-pipeline-NewWfmStage/wfmnewdevpipelineNewWfmStageNewWfmStackIngestionStack5AC9C424.nested.template.json
2022-03-23 10:22:25,050 | Found Lambda function with name='athenaHandler2182D0CE' and CodeUri='../asset.6d3f8650e2d8a66838f02bd14b54620193fa426d86b7e502ce686bf295e340c8'
2022-03-23 10:22:25,050 | --base-dir is not presented, adjusting uri ../asset.6d3f8650e2d8a66838f02bd14b54620193fa426d86b7e502ce686bf295e340c8 relative to /home/dakotal/Projects/QSR/myq_cloud_wfm/cdk.out/assembly-wfm-new-dev-pipeline-NewWfmStage/wfmnewdevpipelineNewWfmStageNewWfmStackIngestionStack5AC9C424.nested.template.json
2022-03-23 10:22:25,054 | Found one Lambda function with name 'athenaHandler'
2022-03-23 10:22:25,054 | Invoking index.handler (nodejs12.x)
2022-03-23 10:22:25,054 | Environment variables overrides data is standard format
2022-03-23 10:22:25,054 | Loading AWS credentials from session with profile 'None'
2022-03-23 10:22:25,433 | Resolving code path. Cwd=/home/dakotal/Projects/QSR/myq_cloud_wfm/cdk.out/assembly-wfm-new-dev-pipeline-NewWfmStage, CodeUri=/home/dakotal/Projects/QSR/myq_cloud_wfm/cdk.out/asset.6d3f8650e2d8a66838f02bd14b54620193fa426d86b7e502ce686bf295e340c8
2022-03-23 10:22:25,433 | Resolved absolute path to code is /home/dakotal/Projects/QSR/myq_cloud_wfm/cdk.out/asset.6d3f8650e2d8a66838f02bd14b54620193fa426d86b7e502ce686bf295e340c8
2022-03-23 10:22:25,434 | Code /home/dakotal/Projects/QSR/myq_cloud_wfm/cdk.out/asset.6d3f8650e2d8a66838f02bd14b54620193fa426d86b7e502ce686bf295e340c8 is not a zip/jar file
2022-03-23 10:22:25,469 | Skip pulling image and use local one: public.ecr.aws/sam/emulation-nodejs12.x:rapid-1.37.0-x86_64.

2022-03-23 10:22:25,469 | Mounting /home/dakotal/Projects/QSR/myq_cloud_wfm/cdk.out/asset.6d3f8650e2d8a66838f02bd14b54620193fa426d86b7e502ce686bf295e340c8 as /var/task:ro,delegated inside runtime container
2022-03-23 10:22:25,925 | Starting a timer for 3 seconds for function 'athenaHandler'
START RequestId: 39bd28f2-fc15-4b61-9fec-ba0811d295f1 Version: $LATEST
} retryDelay: 26.615532480739734aJhXlB/cEruDEVLWI+ATUg57Lj8glEuZnfkZVrRag53NRyN9vwxOJYmV7KtTrCptA=',e specified bucket does not exist
END RequestId: 39bd28f2-fc15-4b61-9fec-ba0811d295f1
REPORT RequestId: 39bd28f2-fc15-4b61-9fec-ba0811d295f1	Init Duration: 0.12 ms	Duration: 499.84 ms	Billed Duration: 500 ms	Memory Size: 128 MB	Max Memory Used: 128 MB	
false2022-03-23 10:22:26,890 | Cleaning all decompressed code dirs
2022-03-23 10:22:26,891 | Sending Telemetry: {'metrics': [{'commandRun': {'requestId': '7946e37e-d7b8-495b-acf8-909052d2b18c', 'installationId': '9ff40e4f-c23a-44de-a170-371601e7b95f', 'sessionId': 'e5f3bd27-9f63-4268-bd4c-3fb876a0391e', 'executionEnvironment': 'CLI', 'ci': False, 'pyversion': '3.7.10', 'samcliVersion': '1.37.0', 'awsProfileProvided': False, 'debugFlagProvided': True, 'region': '', 'commandName': 'sam local invoke', 'metricSpecificAttributes': {'projectType': 'CDK'}, 'duration': 1874, 'exitReason': 'success', 'exitCode': 0}}]}
2022-03-23 10:22:27,303 | Telemetry response: 200
2022-03-23 10:22:27,304 | Telemetry endpoint configured to be https://aws-serverless-tools-telemetry.us-west-2.amazonaws.com/metrics
2022-03-23 10:22:27,305 | Sending Telemetry: {'metrics': [{'runtimeMetric': {'requestId': '3e527121-4a24-473c-b65f-1579e350c105', 'installationId': '9ff40e4f-c23a-44de-a170-371601e7b95f', 'sessionId': 'e5f3bd27-9f63-4268-bd4c-3fb876a0391e', 'executionEnvironment': 'CLI', 'ci': False, 'pyversion': '3.7.10', 'samcliVersion': '1.37.0', 'runtimes': ['nodejs12.x']}}]}
2022-03-23 10:22:27,712 | HTTPSConnectionPool(host='aws-serverless-tools-telemetry.us-west-2.amazonaws.com', port=443): Read timed out. (read timeout=0.1)

Expected result:

lambda is invoked, and multiline console log is formatted correctly, i.e. all lines appear in terminal as intended. Note: the "specified bucket does not exist" line is expected, as i'm configuring environment variables. however the entire output of the console.error is being truncated which is the issue.

Additional environment details (Ex: Windows, Mac, Amazon Linux etc)

  1. OS:$ uname -a
    Linux xx 5.13.0-35-generic Missing Makefile? #40-Ubuntu SMP Mon Mar 7 08:03:10 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
  2. sam --version: SAM CLI, version 1.37.0
  3. AWS region: us-east-1
  4. CF template is a build artifact from CDK synth
@mildaniel mildaniel added the stage/bug-repro The issue/bug needs to be reproduced label Mar 23, 2022
@hawflau
Copy link
Contributor

hawflau commented Mar 31, 2022

I've reproduced the issue. Will bring this up with team and prioritize fixing it.

@hawflau hawflau added type/bug and removed stage/bug-repro The issue/bug needs to be reproduced labels Mar 31, 2022
@timotheecour4
Copy link

timotheecour4 commented May 30, 2022

Is there a workaround for this? this seriously hampers debugging.

EDIT: this doesn't seem specific to "sam local invoke", it also affects "aws lambda invoke" called locally (eg after a "am local start-lambda")

@IamFlowZ
Copy link
Author

Also for visibility, it seems like the bot removed what might be an important label?

@nweajoseph
Copy link

same behavior during sam local start-api

@jankammerath
Copy link

jankammerath commented Oct 23, 2022

I'd like to add that this behaviour appeared somewhere around mid 2021. Previous SAM versions didn't have this behaviour. It's a problem for the following reason: when running or building Lambda locally and an exception occurs, you're forced to always debug instead of getting the trace from the console.

@mndeveci
Copy link
Contributor

This behavior is fixed with this PR: #4563

Next SAM CLI release should resolve this isssue.

@mndeveci mndeveci added the stage/waiting-for-release Fix has been merged to develop and is waiting for a release label Jan 13, 2023
@mndeveci
Copy link
Contributor

Fix is released with v1.71.0

@github-actions
Copy link
Contributor

⚠️COMMENT VISIBILITY WARNING⚠️

Comments on closed issues are hard for our team to see.
If you need more assistance, please either tag a team member or open a new issue that references this one.
If you wish to keep having a conversation with other community members under this issue feel free to do so.

@teyou
Copy link

teyou commented Feb 2, 2023

@mndeveci

upgraded to v1.71.0 , It seems still only print the first line.

console.log(`multi line
		1
		2
		3
		4
		msg 
		end here`);

print out within single line like below:

2023-02-02T08:12end here        452707bb-539a-4e7c-a3b5-23986790a387    INFO    multi line

@samputer
Copy link

Also still experiencing this on 1.73.0.

tagging @mndeveci for visibility. Thanks

@samputer
Copy link

On a mac - used the following ugly workaround

#1359 (comment)

@mndeveci mndeveci reopened this Feb 21, 2023
@mndeveci mndeveci added stage/needs-investigation Requires a deeper investigation and removed stage/waiting-for-release Fix has been merged to develop and is waiting for a release labels Feb 21, 2023
@PavelJacobo
Copy link

PavelJacobo commented May 18, 2023

Hello, is there a workarround for linux base systems?

$ sam local invoke -e ./lambda/lambda_event.json LambdaDemoFunction
Invoking lambda.lambdaHandler (nodejs12.x)
Local image is up-to-date
Using local image: public.ecr.aws/lambda/nodejs:12-rapid-x86_64.
Mounting /home/xxx@xxx.local/Documents/tutorials/lambdas_locally/lambda_local/.aws-sam/build/LambdaDemoFunction as /var/task:ro,delegated, inside runtime container
START RequestId: 23072260-6e2b-49d3-9888-f829d3bddcbf Version: $LATEST
END RequestId: 23072260-6e2b-49d3-9888-f829d3bddcbf
REPORT RequestId: 23072260-6e2b-49d3-9888-f829d3bddcbf Init Duration: 0.09 ms Duration: 136.17 ms Billed Duration: 137 ms Memory Size: 128 MB Max Memory Used: 128 MB"this is the data"

$ sam --version
SAM CLI, version 1.84.0

@scerelli
Copy link

Did you guys find a workaround for this?

@samputer
Copy link

@scerelli - As per the following, apparently it is fixed? (I haven't tested)

#1359 (comment)

@hawflau
Copy link
Contributor

hawflau commented Feb 13, 2024

Hey all, it should be fixed as I tried to reproduce the issue just a moment ago:

2024-02-13 10:58:38,595 | Waiting to retrieve the lock (localhost-7282) to start invocation
START RequestId: a0b85e13-0d84-45b0-aaec-baf7b78c33cc Version: $LATEST
2024-02-13T18:58:38.952Z	5552f373-0383-4886-bfa1-1da77c9ecc1d	INFO	multi line
		1
		2
		3
		4
		msg
		end here
END RequestId: 5552f373-0383-4886-bfa1-1da77c9ecc1d

@hawflau hawflau closed this as completed Feb 13, 2024
Copy link
Contributor

⚠️COMMENT VISIBILITY WARNING⚠️

Comments on closed issues are hard for our team to see.
If you need more assistance, please either tag a team member or open a new issue that references this one.
If you wish to keep having a conversation with other community members under this issue feel free to do so.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
stage/needs-investigation Requires a deeper investigation type/bug
Projects
None yet
Development

No branches or pull requests