Aws-sam-cli: Layer cache not persistent

[neo-headz]

Description

Local layer cache Docker image is not persistent.

Steps to reproduce

Running sam local start-api and executing an api requests will successfully find a local layer, build the cache image, and store it in ~/.aws-sam/layers-pkg. However, after the request completes, the layers-pkg folder is cleaned out. This results in a new cache image being built for every api request and making a single call 30+ sec in my case.

Observed result

~/.aws-sam/layers-pkg is cleaned out after every api request

Expected result

Docker image for layers should persist until layer code changes

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

1. OS: MacOS 10.14.6
2. sam --version: 0.19.0
3. aws --version: aws-cli/1.16.210 Python/3.7.4 Darwin/18.7.0 botocore/1.12.200

[jfuss]

@neo-headz Can you provide debug logs for this? From memory, this is not the behavior and logs will help in initial investigations.

[neo-headz]

@jfuss Here ya go...

2019-08-09 12:49:00 Constructed String representation of Event to invoke Lambda. Event: {"httpMethod": "GET", "body": null, "resource": "/{proxy+}", "requestContext": {"resourceId": "123456", "apiId": "1234567890", "resourcePath": "/{proxy+}", "httpMethod": "GET", "requestId": "c6af9ac6-7b61-11e6-9a41-93e8deadbeef", "accountId": "123456789012", "stage": "dev", "identity": {"apiKey": null, "userArn": null, "cognitoAuthenticationType": null, "caller": null, "userAgent": "Custom User Agent String", "user": null, "cognitoIdentityPoolId": null, "cognitoAuthenticationProvider": null, "sourceIp": "127.0.0.1", "accountId": null}, "extendedRequestId": null, "path": "/{proxy+}"}, "queryStringParameters": null, "multiValueQueryStringParameters": null, "headers": {"Content-Type": "application/json", "Accept-Encoding": "*", "User-Agent": "PostmanRuntime/7.15.0", "Accept": "*/*", "Cache-Control": "no-cache", "Postman-Token": "e18e872a-5fdc-4c06-982c-ff558c5a9bb6", "Host": "localhost:3000", "Connection": "keep-alive", "X-Forwarded-Proto": "http", "X-Forwarded-Port": "3000"}, "multiValueHeaders": {"Content-Type": ["application/json"], "Accept-Encoding": ["*"], "User-Agent": ["PostmanRuntime/7.15.0"], "Accept": ["*/*"], "Cache-Control": ["no-cache"], "Postman-Token": ["e18e872a-5fdc-4c06-982c-ff558c5a9bb6"], "Host": ["localhost:3000"], "Connection": ["keep-alive"], "X-Forwarded-Proto": ["http"], "X-Forwarded-Port": ["3000"]}, "pathParameters": {"proxy": "user"}, "stageVariables": null, "path": "/user", "isBase64Encoded": false}
2019-08-09 12:49:00 Found one Lambda function with name 'GatewayHandler'
2019-08-09 12:49:00 Invoking api.handler (nodejs8.10)
2019-08-09 12:49:00 Environment variables overrides data is standard format
2019-08-09 12:49:00 Loading AWS credentials from session with profile 'None'
2019-08-09 12:49:00 Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
2019-08-09 12:49:00 Changing event name from before-call.apigateway to before-call.api-gateway
2019-08-09 12:49:00 Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
2019-08-09 12:49:00 Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
2019-08-09 12:49:00 Changing event name from before-parameter-build.route53 to before-parameter-build.route-53
2019-08-09 12:49:00 Changing event name from request-created.cloudsearchdomain.Search to request-created.cloudsearch-domain.Search
2019-08-09 12:49:00 Changing event name from docs.*.autoscaling.CreateLaunchConfiguration.complete-section to docs.*.auto-scaling.CreateLaunchConfiguration.complete-section
2019-08-09 12:49:00 Changing event name from before-parameter-build.logs.CreateExportTask to before-parameter-build.cloudwatch-logs.CreateExportTask
2019-08-09 12:49:00 Changing event name from docs.*.logs.CreateExportTask.complete-section to docs.*.cloudwatch-logs.CreateExportTask.complete-section
2019-08-09 12:49:00 Changing event name from before-parameter-build.cloudsearchdomain.Search to before-parameter-build.cloudsearch-domain.Search
2019-08-09 12:49:00 Changing event name from docs.*.cloudsearchdomain.Search.complete-section to docs.*.cloudsearch-domain.Search.complete-section
2019-08-09 12:49:00 Looking for credentials via: env
2019-08-09 12:49:00 Looking for credentials via: assume-role
2019-08-09 12:49:00 Looking for credentials via: shared-credentials-file
2019-08-09 12:49:00 Found credentials in shared credentials file: ~/.aws/credentials
2019-08-09 12:49:00 Resolving code path. Cwd=/Users/james/Documents/Projects/Metaprise/backend, CodeUri=dist/api
2019-08-09 12:49:00 Resolved absolute path to code is /Users/james/Documents/Projects/Metaprise/backend/dist/api
2019-08-09 12:49:00 Code /Users/james/Documents/Projects/Metaprise/backend/dist/api is not a zip/jar file
2019-08-09 12:49:00 DepsLayer is a local Layer in the template
2019-08-09 12:49:00 Resolving code path. Cwd=/Users/james/Documents/Projects/Metaprise/backend, CodeUri=layers/deps/
2019-08-09 12:49:00 http://localhost:None "GET /v1.35/images/samcli/lambda:nodejs8.10-e8344756deb788880399273fe/json HTTP/1.1" 200 None
2019-08-09 12:49:00 Building image...
2019-08-09 12:49:34 Looking for auth config
2019-08-09 12:49:35 Sending auth config ()
2019-08-09 12:49:51 http://localhost:None "POST /v1.35/build?t=samcli%2Flambda%3Anodejs8.10-e8344756deb788880399273fe&q=False&nocache=False&rm=True&forcerm=False&pull=True HTTP/1.1" 200 None
2019-08-09 12:50:10 http://localhost:None "GET /v1.35/images/187957280597/json HTTP/1.1" 200 None
2019-08-09 12:50:10 Trying paths: ['/Users/james/.docker/config.json', '/Users/james/.dockercfg']
2019-08-09 12:50:10 Found file at path: /Users/james/.docker/config.json
2019-08-09 12:50:10 Found 'credsStore' section
2019-08-09 12:50:10 http://localhost:None "GET /v1.35/images/samcli/lambda:nodejs8.10-e8344756deb788880399273fe/json HTTP/1.1" 200 None
2019-08-09 12:50:10 Requested to skip pulling images ...

2019-08-09 12:50:10 Mounting /Users/james/Documents/Projects/Metaprise/backend/dist/api as /var/task:ro,delegated inside runtime container
2019-08-09 12:50:10 http://localhost:None "POST /v1.35/containers/create HTTP/1.1" 201 88
2019-08-09 12:50:10 http://localhost:None "GET /v1.35/containers/3dec7897831f687b1558a22d4ae230c6210842270cf6dbec84fb1bda00da4058/json HTTP/1.1" 200 None
2019-08-09 12:50:10 http://localhost:None "GET /v1.35/containers/3dec7897831f687b1558a22d4ae230c6210842270cf6dbec84fb1bda00da4058/json HTTP/1.1" 200 None
2019-08-09 12:50:11 http://localhost:None "POST /v1.35/containers/3dec7897831f687b1558a22d4ae230c6210842270cf6dbec84fb1bda00da4058/start HTTP/1.1" 204 0
2019-08-09 12:50:11 Starting a timer for 120 seconds for function 'GatewayHandler'
2019-08-09 12:50:11 http://localhost:None "GET /v1.35/containers/3dec7897831f687b1558a22d4ae230c6210842270cf6dbec84fb1bda00da4058/json HTTP/1.1" 200 None
2019-08-09 12:50:11 http://localhost:None "POST /containers/3dec7897831f687b1558a22d4ae230c6210842270cf6dbec84fb1bda00da4058/attach?stdout=1&stderr=1&logs=1&stream=1&stdin=0 HTTP/1.1" 101 0
START RequestId: 53d10229-0b90-1b1d-af73-f3faecfdcc5f Version: $LATEST

……… API RESPONSE…………

END RequestId: 53d10229-0b90-1b1d-af73-f3faecfdcc5f
REPORT RequestId: 53d10229-0b90-1b1d-af73-f3faecfdcc5f  Duration: 1792.47 ms    Billed Duration: 1800 ms    Memory Size: 3008 MB    Max Memory Used: 117 MB
2019-08-09 12:50:13 http://localhost:None "GET /v1.35/containers/3dec7897831f687b1558a22d4ae230c6210842270cf6dbec84fb1bda00da4058/json HTTP/1.1" 200 None
2019-08-09 12:50:13 http://localhost:None "DELETE /v1.35/containers/3dec7897831f687b1558a22d4ae230c6210842270cf6dbec84fb1bda00da4058?v=False&link=False&force=True HTTP/1.1" 204 0
2019-08-09 12:50:13 127.0.0.1 - - [09/Aug/2019 12:50:13] "GET /user HTTP/1.1" 200 -
2019-08-09 12:50:11 http://localhost:None "POST /containers/3dec7897831f687b1558a22d4ae230c6210842270cf6dbec84fb1bda00da4058/attach?stdout=1&stderr=1&logs=1&stream=1&stdin=0 HTTP/1.1" 101 0

[jfuss]

@neo-headz The issue here is 2019-08-09 12:49:00 DepsLayer is a local Layer in the template. The layer-cache directory holds layers that we download for the Lambda service. We can safely cache these because a layer is not mutable. When you start referencing locally layers, we always build. This is to ensure the files that get overlaid into the image are represented correctly. We do not have a way to 'watch' files and therefore smartly update, so what you are seeing is the expected behavior.

[neo-headz]

@jfuss ok. Makes sense. It would be a nice feature to have a flag for local layer caching 😁