Sam local invoke (go) not honoring timeout in context

[dgoradia]

Description:

When running a golang lambda function with sam local invoke, and making a request (in the function) using the context results in RequestCanceled: request context canceled caused by: context deadline exceeded.

When using ListBuckets (without WithContext) results in a successful result.

Steps to reproduce:

hello.go

type Response events.APIGatewayProxyResponse

func Handler(ctx context.Context) (Response, error) {
	fmt.Printf("%+v\n", ctx)
	var buf bytes.Buffer

	sess := session.Must(session.NewSession(&aws.Config{Region: aws.String("us-west-2")}))
	svc := s3.New(sess)

	// Using the WithContext version of ListBuckets makes it apparent that the context isn't set to honor the function timeout
	b, err := svc.ListBucketsWithContext(ctx, &s3.ListBucketsInput{})
	if err != nil {
		fmt.Println(err)
	}
	fmt.Println(b)

	body, err := json.Marshal(map[string]interface{}{
		"message": "Go Serverless v1.0! Your function executed successfully!",
	})
	if err != nil {
		return Response{StatusCode: 404}, err
	}
	json.HTMLEscape(&buf, body)

	resp := Response{
		StatusCode:      200,
		IsBase64Encoded: false,
		Body:            buf.String(),
		Headers: map[string]string{
			"Content-Type":           "application/json",
			"X-MyCompany-Func-Reply": "hello-handler",
		},
	}

	return resp, nil
}

func main() {
	lambda.Start(Handler)
}

template.yml

AWSTemplateFormatVersion: "2010-09-09"
Transform: "AWS::Serverless-2016-10-31"
Description: "Demo SAM Template"
Resources:
  Demo:
    Type: "AWS::Serverless::Function"
    Properties:
      Handler: bin/hello
      Runtime: go1.x
      MemorySize: 128
      Timeout: 30
      Environment:
        Variables:
          AWS_ACCESS_KEY_ID: myaccesskey
          AWS_SECRET_ACCESS_KEY: mysecretkey
          AWS_SESSION_TOKEN: mytoken
      Policies:
        - Version: "2012-10-17"
          Statement:
            - Effect: Allow
              Action:
                - "s3:*"
              Resource: "*"

Observed result:

RequestCanceled: request context canceled caused by: context deadline exceeded

Expected result:

{
  Buckets: [
    {
      CreationDate: 2020-04-21 00:00:00 +0000 UTC,
      Name: "bucket-names"
    }
  ],
  Owner: {
    DisplayName: "...",
    ID: "..."
  }
}

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

1. OS: macOS 10.15.7
2. sam --version: SAM CLI, version 1.15.

Add --debug flag to command you are running

[momotaro98]

I've got the same issue too.

OS: macOS 10.15.7
sam --version: SAM CLI, version 1.15.

hello.go

package main

import (
        "context"
        "fmt"
        "time"

        "github.com/aws/aws-lambda-go/events"
        "github.com/aws/aws-lambda-go/lambda"
)

type Response events.APIGatewayProxyResponse

func Handler(ctx context.Context) (Response, error) {
        fmt.Printf("%+v\n", ctx)

        deadline, _ := ctx.Deadline()
        fmt.Printf("now:      %+v\n", time.Now().Format(time.RFC3339Nano))
        fmt.Printf("deadline: %+v\n", deadline.Format(time.RFC3339Nano))

        select {
        case <-ctx.Done():
                fmt.Printf("ctx.Err(): %+v\n", ctx.Err())
        default:
        }

        return Response{
                StatusCode:      200,
                IsBase64Encoded: false,
                Headers: map[string]string{
                        "Content-Type": "application/json",
                },
        }, nil
}

func main() {
        lambda.Start(Handler)
}

I found that github.com/aws/aws-lambda-go/lambda gives my code an expired ctx with Deadline.

Here's the result of the code above. It shows the context deadline had been expired then it outputs context deadline exceeded.

$ GOOS=linux GOARCH=amd64 go build -o bin/hello; sam local start-api
.
.
START RequestId: 24518744-6eed-4f27-a747-cc680ad01a0d Version: $LATEST
context.Background.WithDeadline(2021-01-05 05:18:44.8019596 +0000 UTC [-328.8µs]).WithValue(type *lambdacontext.key, val <not Stringer>).WithValue(type string, val )
now:      2021-01-05T05:18:44.8023357Z
deadline: 2021-01-05T05:18:44.8019596Z
ctx.Err(): context deadline exceeded
END RequestId: 24518744-6eed-4f27-a747-cc680ad01a0d
REPORT RequestId: 24518744-6eed-4f27-a747-cc680ad01a0d  Init Duration: 0.17 ms  Duration: 168.08 ms     Billed Duration: 200 ms Memory Size: 128 MB     Max Memory Used: 128 MB
.
.

I looked up the cause. It seems that the newly updated AWS Lambda runtime API has become different as before.
Lambda runtime API is a Docker container which sam local command pulls.

I didn't set the option below. (ref: https://docs.aws.amazon.com/serverless-application-model/latest/developerguide/sam-cli-command-reference-sam-local-start-api.html )

--skip-pull-image Specifies whether the CLI should skip pulling down the latest Docker image for the Lambda runtime.

I found the value of Lambda-Runtime-Deadline-Ms runtime API returns to program runtime affects the deadline value. So, I believe the newly updated Lambda runtime API has something wrong.

(ref: https://docs.aws.amazon.com/lambda/latest/dg/runtimes-api.html )

[mousedownmike]

Could this be related to PR #2383 that resolved issue #239? I'm seeing the same context deadline exceeded error when running through the latest SAM CLI. I have not been running locally because of the startup time for each request. I was hoping that would be resolved with #2383 but it looks like there might still be a little more work to do.

$ sam --version
SAM CLI, version 1.15.0
$ cat /etc/issue
Ubuntu 20.04.1 LTS \n \l

[mousedownmike]

To further the investigation, I ran with both EAGER and LAZY warm containers and both still had the context deadline exceeded error.

sam local start-api --warm-containers EAGER
sam local start-api --warm-containers LAZY

I can't figure out if there's a way to disable the warm containers to see if it starts working without it.

@moelasmar is there a way to invoke with your "warm container" improvement disabled?

[awood45]

If you do not set warm containers, they aren't used. This is likely related to #2519

[hoffa]

Cleaning up duplicates; this was narrowed down in #2519 as being introduced in v1.13.0.

[mnugter]

I'm experiencing this issue as well while it was working earlier on when I had v1.15. I've tried upgrading to v1.18.1 but that didn't help.
I have the exact same problem as @momotaro98 described.

[tebruno99]

I've just spent quite a bit of time trying to debug this since locally none of my mysql queries that use PrepareContext() were working. After some searching came across this bug. Sam local 1.18.2, Ubuntu 20.04 with latest docker repo.

[mousedownmike]

I rolled back to SAM CLI, version 1.12.0 to get this working again.

[rsbethke]

It appears that SAM CLI, version 1.18.0 will execute properly

[MicahParks]

SAM CLI version 1.18.2 appears to be affected by this issue.

[drwxmrrs]

For anyone wanting to know how to downgrade, you can use Pip3:

pip3 install --user 'aws-sam-cli==1.12.0'

This version seems to be working for me.

[hutchy2570]

Any updates on this please? It's an issue for us and downgrading to 1.12.0 is unfortunate as the lazy stuff in newer SAM CLI local is really useful for us.

[mousedownmike]

I now have to switch between CLI versions because nodejs14.x is not supported until 1.17.
Error: The runtime nodejs14.x requires a minimum SAM CLI version of 1.17.0

This would be a great issue to get repaired.

Here are the commands that I use to switch between versions in case it's useful to anyone (on Ubuntu).

Dowgnrade
pip3 install --user 'aws-sam-cli<=1.13.0' --force-reinstall
Upgrade
pip3 install --user aws-sam-cli -U

[KatamariJr]

Experienced this bug today in SAM v1.29.0

[hiruna]

++, got same bug now

[MicahParks]

This issue appears to be fixed in the latest version: 1.37.0

Or at least my use case appears to be bug free. A non-expired context.Context is given to my Lambda with the correct timeout.

Go code:

package main

import (
	"context"
	"log"
	"os"

	"github.com/aws/aws-lambda-go/lambda"
)

type handler struct {
	logger *log.Logger
}

// Invoke implements the lambda.Handler interface and shows context.Context information.
func (h handler) Invoke(ctx context.Context, _ []byte) (response []byte, err error) {
	h.logger.Printf("%+v", ctx)

	select {
	case <-ctx.Done():
		h.logger.Println("Context expired.")
		err := ctx.Err()
		h.logger.Printf("Error: %s", err.Error())
		response = []byte(`{"statusCode":200,"headers":null,"multiValueHeaders":null,"body":"Failed due to expired context on invocation."}`)
	default:
		h.logger.Println("Context not expired.")
		response = []byte(`{"statusCode":200,"headers":null,"multiValueHeaders":null,"body":"Successfully returned response."}`)
	}

	return response, nil
}

func main() {
	logger := log.New(os.Stdout, "", log.LstdFlags)

	ctx, cancel := context.WithCancel(context.Background())
	defer cancel()

	h := handler{
		logger: logger,
	}

	lambda.StartHandlerWithContext(ctx, h)
}

template.yml:

AWSTemplateFormatVersion: "2010-09-09"
Description: "An example Golang AWS SAM Lambda project."
Transform: "AWS::Serverless-2016-10-31"


Parameters:
  VaultToken:
    Type: "String"


Globals:
  Function:
    Handler: "main"
    Timeout: 10
    Runtime: "go1.x"


Resources:

  exampleOne:
    Type: "AWS::Serverless::Function"
    Properties:
      CodeUri: "cmd/one"
      Events:
        ApiEvent:
          Type: "HttpApi"
        Api:
          Type: "Api"
          Properties:
            Path: "/one"
            Method: "get"

Output:

$ sam --version && date && sam build && sam local invoke
SAM CLI, version 1.37.0
Sat 15 Jan 2022 04:19:18 PM EST
Building codeuri: /home/micah/GolandProjects/go-aws-sam-lambda-example/cmd/one runtime: go1.x metadata: {} architecture: x86_64 functions: ['exampleOne']
Running GoModulesBuilder:Build

Build Succeeded

Built Artifacts  : .aws-sam/build
Built Template   : .aws-sam/build/template.yaml

Commands you can use next
=========================
[*] Invoke Function: sam local invoke
[*] Test Function in the Cloud: sam sync --stack-name {stack-name} --watch
[*] Deploy: sam deploy --guided
        
Invoking main (go1.x)
Skip pulling image and use local one: public.ecr.aws/sam/emulation-go1.x:rapid-1.37.0-x86_64.

Mounting /home/micah/GolandProjects/go-aws-sam-lambda-example/.aws-sam/build/exampleOne as /var/task:ro,delegated inside runtime container
START RequestId: ab0e8d22-adfb-4b9f-9d0e-bccea54000b9 Version: $LATEST
2022/01/15 21:19:22 context.Background.WithCancel.WithDeadline(2022-01-15 21:19:32.075598487 +0000 UTC [9.998813556s]).WithValue(type *lambdacontext.key, val <not Stringer>).WithValue(type string, val )
2022/01/15 21:19:22 Context not expired.
{"statusCode":200,"headers":null,"multiValueHeaders":null,"body":"Successfully returned response."}END RequestId: ab0e8d22-adfb-4b9f-9d0e-bccea54000b9
REPORT RequestId: ab0e8d22-adfb-4b9f-9d0e-bccea54000b9  Init Duration: 0.20 ms  Duration: 7.44 ms       Billed Duration: 8 ms   Memory Size: 128 MB     Max Memory Used: 128 MB

Notice the date is Sat 15 Jan 2022 04:19:18 PM EST and the context expires: 2022-01-15 21:19:32.075598487 +0000 UTC. The extra couple seconds are because of the time it took the sam build command to run.

This is the same behavior with sam local start-api and the Lambda is stopped early if the timeout in template.yml is reached.

[jfuss]

This was already fixed in RIE and integrated with SAM CLI. Looks like we just forgot to close this out and therefore closing.