aws / aws/aws-sam-cli

Bug: `sam local` commands sometimes miss the first few lines of container output

Open
#4,239 4 comments 1 reaction 0 assignees View on GitHub
area/local maintainer/need-followup type/bug
Dominant language
Python
Stars
6.7k
Forks
1.2k
Avg merge
1d 10h
Merged PRs (30d)
52

Description

### Description:

When invoking a function, SAM CLI won't always output the full container logs:
>Mounting /home/ec2-user/environment/lambda-nodejs12.x/hello-world as /var/task:ro,delegated inside runtime container
END RequestId: 37988e88-12c7-44be-86ae-787c697dfe8a
REPORT RequestId: 37988e88-12c7-44be-86ae-787c697dfe8a Init Duration: 1.52 ms Duration: 115.42 ms Billed Duration: 116 ms Memory Size: 128 MB Max Memory Used: 128 MB

I would expect to see `START RequestId: 37988e88-12c7-44be-86ae-787c697dfe8a Version: $LATEST` in the output but I do not. **This is important because the AWS Toolkit depends on certain output to know when to attach the debugger**. SAM CLI can miss something like `Debugger listening on ws://0.0.0.0:xxxx/yyyyyyy` which prevents the Toolkit from starting the debugging session.

I'm using `sam local invoke` + `nodejs12.x` though the bug probably applies to different combinations. This seems to primarily affect slower machines (e.g. a Cloud9 t2.micro instance).

### Steps to reproduce:

1. Use a sufficiently slow machine
2. Create a new SAM application (I'm using `nodejs12.x`)
3. Run `sam local invoke`

### Observed result:

> 2022-09-19 21:28:26,497 | Mounting /home/ec2-user/environment/lambda-nodejs12.x/hello-world as /var/task:ro,delegated inside runtime container
2022-09-19 21:28:27,691 | Starting a timer for 3 seconds for function 'HelloWorldFunction'
END RequestId: c7925ba1-16ed-4b95-8ed2-8d3bed436c40
REPORT RequestId: c7925ba1-16ed-4b95-8ed2-8d3bed436c40 Init Duration: 1.52 ms Duration: 285.53 ms Billed Duration: 286 ms Memory Size: 128 MB Max Memory Used: 128 MB

### Expected result:

> 2022-09-19 21:28:26,497 | Mounting /home/ec2-user/environment/lambda-nodejs12.x/hello-world as /var/task:ro,delegated inside runtime container
2022-09-19 21:28:27,691 | Starting a timer for 3 seconds for function 'HelloWorldFunction'
START RequestId: c7925ba1-16ed-4b95-8ed2-8d3bed436c40 Version: $LATEST
END RequestId: c7925ba1-16ed-4b95-8ed2-8d3bed436c40
REPORT RequestId: c7925ba1-16ed-4b95-8ed2-8d3bed436c40 Init Duration: 1.52 ms Duration: 285.53 ms Billed Duration: 286 ms Memory Size: 128 MB Max Memory Used: 128 MB

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

1. OS: Amazon Linux
4. `sam --version`: 1.57.0
5. AWS region: N/A

Contributor guide

Open the contributing guide

Research direction

Reproduce the issue with `sam local invoke --debug` on a slow machine using the `nodejs12.x` runtime, and compare the observed and expected container output. Trace how `sam local` captures and emits runtime logs; done means the initial `START` line and debugger-listening output are not missed.

Written by the indexing model from the issue text.

Assessment

Tech stack
docker, nodejs, python
Domain
cli, devtools
Issue type
Bug
Difficulty
3/5
Estimated time
1-2 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.