getRemainingTimeInMillis is returning a unix time #2519

danjordan · 2021-01-06T14:31:03Z

Description:

Since v1.13.1 context.getRemainingTimeInMillis() is returning an integer that represents a recent date, rather than the remaining time in milliseconds.

This also occurs in Ruby lambdas, however Python 2 lambdas give us 0. All three work correctly in v1.12.0.

Steps to reproduce:

# template.yaml

Transform: AWS::Serverless-2016-10-31

Resources:
  Index:
    Type: AWS::Serverless::Function
    Properties:
      Handler: index.handler
      Runtime: nodejs12.x
      Timeout: 5
      Events:
        Api:
          Type: Api
          Properties:
            Path: /
            Method: GET

// index.js

exports.handler = async (event, context) => {
  return {
    body: JSON.stringify({
      remainingTimeInMillis: context.getRemainingTimeInMillis(),
      date: new Date(context.getRemainingTimeInMillis()),
    }),
  };
};

Observed result:

Running the following command with v1.13.1
sam local invoke Index --debug

2021-01-06 14:18:28,422 | Telemetry endpoint configured to be https://aws-serverless-tools-telemetry.us-west-2.amazonaws.com/metrics
2021-01-06 14:18:28,510 | local invoke command is called
2021-01-06 14:18:28,513 | No Parameters detected in the template
2021-01-06 14:18:28,534 | 2 resources found in the template
2021-01-06 14:18:28,534 | Found Serverless function with name='Index' and CodeUri='.'
2021-01-06 14:18:28,540 | Found one Lambda function with name 'Index'
2021-01-06 14:18:28,541 | Invoking index.handler (nodejs12.x)
2021-01-06 14:18:28,541 | No environment variables found for function 'Index'
2021-01-06 14:18:28,541 | Environment variables overrides data is standard format
2021-01-06 14:18:28,541 | Loading AWS credentials from session with profile 'None'
2021-01-06 14:18:28,553 | Resolving code path. Cwd=/Users/danjordan/Sites/misc/sam-cli-test, CodeUri=.
2021-01-06 14:18:28,553 | Resolved absolute path to code is /Users/danjordan/Sites/misc/sam-cli-test
2021-01-06 14:18:28,553 | Code /Users/danjordan/Sites/misc/sam-cli-test is not a zip/jar file
2021-01-06 14:18:28,574 | Skip pulling image and use local one: amazon/aws-sam-cli-emulation-image-nodejs12.x:rapid-1.13.1.

2021-01-06 14:18:28,574 | Mounting /Users/danjordan/Sites/misc/sam-cli-test as /var/task:ro,delegated inside runtime container
2021-01-06 14:18:28,901 | Starting a timer for 5 seconds for function 'Index'
START RequestId: 46414975-e270-45d2-9c24-5ae61b25cd30 Version: $LATEST
END RequestId: 46414975-e270-45d2-9c24-5ae61b25cd30
REPORT RequestId: 46414975-e270-45d2-9c24-5ae61b25cd30	Init Duration: 0.15 ms	Duration: 85.89 ms	Billed Duration: 100 ms	Memory Size: 128 MB	Max Memory Used: 128 MB
2021-01-06 14:18:29,186 | Sending Telemetry: {'metrics': [{'commandRun': {'awsProfileProvided': False, 'debugFlagProvided': True, 'region': '', 'commandName': 'sam local invoke', 'duration': 764, 'exitReason': 'success', 'exitCode': 0, 'requestId': 'c6c57255-762e-42af-a8a5-599eee573190', 'installationId': '190b0744-f13d-4279-84cd-860b54d9c540', 'sessionId': '8a9c4bb4-7609-4a78-9705-ff32bd726835', 'executionEnvironment': 'CLI', 'pyversion': '3.8.7', 'samcliVersion': '1.13.1'}}]}
2021-01-06 14:18:29,858 | HTTPSConnectionPool(host='aws-serverless-tools-telemetry.us-west-2.amazonaws.com', port=443): Read timed out. (read timeout=0.1)

{"body":"{\"remainingTimeInMillis\":1609931569204,\"date\":\"2021-01-06T11:12:49.204Z\"}"}%

Expected result:

Running the following command with v1.12.0
sam local invoke Index --debug

2021-01-06 14:21:14,642 | Telemetry endpoint configured to be https://aws-serverless-tools-telemetry.us-west-2.amazonaws.com/metrics
2021-01-06 14:21:15,249 | local invoke command is called
2021-01-06 14:21:15,252 | No Parameters detected in the template
2021-01-06 14:21:15,281 | 2 resources found in the template
2021-01-06 14:21:15,281 | Found Serverless function with name='Index' and CodeUri='.'
2021-01-06 14:21:15,288 | Found one Lambda function with name 'Index'
2021-01-06 14:21:15,288 | Invoking index.handler (nodejs12.x)
2021-01-06 14:21:15,288 | No environment variables found for function 'Index'
2021-01-06 14:21:15,288 | Environment variables overrides data is standard format
2021-01-06 14:21:15,288 | Loading AWS credentials from session with profile 'None'
2021-01-06 14:21:15,299 | Resolving code path. Cwd=/Users/danjordan/Sites/misc/sam-cli-test, CodeUri=.
2021-01-06 14:21:15,299 | Resolved absolute path to code is /Users/danjordan/Sites/misc/sam-cli-test
2021-01-06 14:21:15,299 | Code /Users/danjordan/Sites/misc/sam-cli-test is not a zip/jar file
2021-01-06 14:21:15,309 | Skip pulling image and use local one: amazon/aws-sam-cli-emulation-image-nodejs12.x:rapid-1.12.0.

2021-01-06 14:21:15,309 | Mounting /Users/danjordan/Sites/misc/sam-cli-test as /var/task:ro,delegated inside runtime container
2021-01-06 14:21:15,672 | Starting a timer for 5 seconds for function 'Index'
START RequestId: 033cd921-a9e4-1351-c5a5-aae6c40794ae Version: $LATEST
END RequestId: 033cd921-a9e4-1351-c5a5-aae6c40794ae
REPORT RequestId: 033cd921-a9e4-1351-c5a5-aae6c40794ae	Init Duration: 151.36 ms	Duration: 3.38 ms	Billed Duration: 100 ms	Memory Size: 128 MB	Max Memory Used: 41 MB
2021-01-06 14:21:15,934 | Sending Telemetry: {'metrics': [{'commandRun': {'awsProfileProvided': False, 'debugFlagProvided': True, 'region': '', 'commandName': 'sam local invoke', 'duration': 1290, 'exitReason': 'success', 'exitCode': 0, 'requestId': '2949a164-fb1e-4eeb-a11c-a8ef3d8c09dc', 'installationId': '190b0744-f13d-4279-84cd-860b54d9c540', 'sessionId': '4ccaf64c-8096-4db9-b4fb-b28c728927e5', 'executionEnvironment': 'CLI', 'pyversion': '3.8.7', 'samcliVersion': '1.12.0'}}]}
2021-01-06 14:21:16,624 | HTTPSConnectionPool(host='aws-serverless-tools-telemetry.us-west-2.amazonaws.com', port=443): Read timed out. (read timeout=0.1)

{"body":"{\"remainingTimeInMillis\":4882,\"date\":\"1970-01-01T00:00:04.882Z\"}"}

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

OS: Mac OS Big Sur
sam --version: discovered in v1.15.0, but narrowed down to being introduced in v1.13.1

The text was updated successfully, but these errors were encountered:

awood45 · 2021-01-08T00:26:36Z

Thanks for the report, looking in to why this is happening in the emulation environment.

eunomie · 2021-01-12T15:16:30Z

sam --version: discovered in v1.15.0, but narrowed down to being introduced in v1.13.1

I have the same kind of issue (same kind as #2510 linked to this issue) and tried different versions. I needed to go back to v1.12.0 to have something working (so without the context to be cancelled at start), v1.13.0 doesn't work either.

hoffa · 2021-01-18T06:00:28Z

Closing this in favor of the older #2510 with more traction. Thanks @danjordan and @eunomie for narrowing down when this was introduced!

hoffa · 2021-01-18T16:49:16Z

Reopening as I'm seeing some inconsistency between issues. #2535 using Python reports the returned value is (what seems to be) a Unix timestamp in milliseconds, while here I see

however Python lambdas give us 0

@danjordan are you able to confirm you consistently get 0 when calling context.get_remaining_time_in_millis() with Python? I tried reproducing with the default Python sam init app and got:

{"statusCode": 200, "body": "{\"message\": 1610982354379}"}

danjordan · 2021-01-18T17:45:49Z

Using the following on version 1.15.0...

Transform: AWS::Serverless-2016-10-31
Resources: 
  Python:
    Type: AWS::Serverless::Function
    Properties:
      Handler: src/python.handler
      Runtime: python2.7
      Timeout: 5
      Events:
        Api:
          Type: Api
          Properties:
            Path: /python
            Method: GET

import json
import datetime

def handler(event, context):
  return {
    'body': json.dumps({
      'remaining_time_in_millis': context.get_remaining_time_in_millis(),
      'date': datetime.date.fromtimestamp(context.get_remaining_time_in_millis()).ctime()
    })
  }

I get

2021-01-18 17:38:24,774 | Telemetry endpoint configured to be https://aws-serverless-tools-telemetry.us-west-2.amazonaws.com/metrics
2021-01-18 17:38:24,774 | local invoke command is called
2021-01-18 17:38:24,779 | No Parameters detected in the template
2021-01-18 17:38:24,801 | 4 resources found in the template
2021-01-18 17:38:24,801 | Found Serverless function with name='Node' and CodeUri='.'
2021-01-18 17:38:24,801 | Found Serverless function with name='Python' and CodeUri='.'
2021-01-18 17:38:24,801 | Found Serverless function with name='Ruby' and CodeUri='.'
2021-01-18 17:38:24,810 | Found one Lambda function with name 'Python'
2021-01-18 17:38:24,810 | Invoking src/python.handler (python2.7)
2021-01-18 17:38:24,810 | No environment variables found for function 'Python'
2021-01-18 17:38:24,810 | Environment variables overrides data is standard format
2021-01-18 17:38:24,810 | Loading AWS credentials from session with profile 'None'
2021-01-18 17:38:24,820 | Resolving code path. Cwd=/Users/danjordan/Sites/misc/sam-cli-test, CodeUri=.
2021-01-18 17:38:24,821 | Resolved absolute path to code is /Users/danjordan/Sites/misc/sam-cli-test
2021-01-18 17:38:24,821 | Code /Users/danjordan/Sites/misc/sam-cli-test is not a zip/jar file
2021-01-18 17:38:24,838 | Skip pulling image and use local one: amazon/aws-sam-cli-emulation-image-python2.7:rapid-1.15.0.

2021-01-18 17:38:24,838 | Mounting /Users/danjordan/Sites/misc/sam-cli-test as /var/task:ro,delegated inside runtime container
2021-01-18 17:38:25,261 | Starting a timer for 5 seconds for function 'Python'
START RequestId: 0fb3f39c-3719-4598-bb52-8b49ebc8e5ff Version: $LATEST
END RequestId: 0fb3f39c-3719-4598-bb52-8b49ebc8e5ff
REPORT RequestId: 0fb3f39c-3719-4598-bb52-8b49ebc8e5ff	Init Duration: 0.81 ms	Duration: 83.45 ms	Billed Duration: 100 ms	Memory Size: 128 MB	Max Memory Used: 128 MB
2021-01-18 17:38:25,578 | Cleaning all decompressed code dirs
2021-01-18 17:38:25,578 | Sending Telemetry: {'metrics': [{'commandRun': {'awsProfileProvided': False, 'debugFlagProvided': True, 'region': '', 'commandName': 'sam local invoke', 'duration': 803, 'exitReason': 'success', 'exitCode': 0, 'requestId': 'b1bbc74a-d75f-4ff0-a3d9-201c1b361fba', 'installationId': '190b0744-f13d-4279-84cd-860b54d9c540', 'sessionId': 'd8f623c8-df50-4a52-a263-6c100f255c43', 'executionEnvironment': 'CLI', 'pyversion': '3.8.7', 'samcliVersion': '1.15.0'}}]}
2021-01-18 17:38:26,269 | HTTPSConnectionPool(host='aws-serverless-tools-telemetry.us-west-2.amazonaws.com', port=443): Read timed out. (read timeout=0.1)

{"body": "{\"date\": \"Thu Jan  1 00:00:00 1970\", \"remaining_time_in_millis\": 0}"}

Seems to be a difference between Python 2 and 3, because sam init and the above using 3.8 give me a timestamp

mousedownmike · 2021-02-20T19:04:16Z

Any updates on this? sam local invoke has been unusable since 1.13 and we're now at 1.18.2

intptr-t · 2021-03-01T21:33:25Z

It's still not resolved at 1.19.1

I think the response value Lambda-Runtime-Deadline-Ms from the API runtime(sam local => rapid-1.19.1?) is too large.

Is there any way to make the API runtime read the timeout time in template.yaml?
@awood45

"lambda-runtime-deadline-ms":"3228130696703"

// print `Lambda-Runtime-Deadline-Ms`.
//     https://docs.aws.amazon.com/lambda/latest/dg/runtimes-api.html
> new Date(3228130696703).toISOString()
'2072-04-17T14:58:16.703Z'

// It will be roughly the same as `context.getRemainingTimeInMillis()`.
>new Date(3228130696703 - Date.now()).toISOString()
'2021-02-16T17:34:57.002Z'

template.yaml

---
  Description: ""
  Resources:
    test:
      Type: "AWS::Lambda::Function"
      Properties:
        Handler: "index.handler"
        Runtime: "nodejs12.x"
        FunctionName: "test"
        MemorySize: 192
        Timeout: 900

Code for verification

const http = require('http');
const hostname = '127.0.0.1';
const port = 9001;
const agent = http.Agent({
    keepAlive: true,
    maxSockets: 1
});

exports.handler = async(event, context) => {
    const body = JSON.stringify({
        remainingTimeInMillis: context.getRemainingTimeInMillis(),
        date: new Date(context.getRemainingTimeInMillis()),
    });
    console.log(`body === ${body}`);

    const options = {
        agent,
        hostname,
        port,
        path: '/2018-06-01/runtime/invocation/next',
        method: 'GET',
    };
    const promise = new Promise((resolve, reject) => {
        const request = http.request(options, response => {
            let data = "";
            response.setEncoding("utf-8");
            response.on("data", chunk => {
                data += chunk;
            });
            response.on("end", () => {
                resolve({
                    bodyJson: data,
                    headers: response.headers
                });
            });
        });
        request.on("error", e => {
            reject(e);
        });
        request.end();
    });
    const response = await promise;
    console.log(`response === ${JSON.stringify(response)}`);
};

detail logs

% sam local invoke --debug                    
2021-03-02 06:04:37,218 | Telemetry endpoint configured to be https://aws-serverless-tools-telemetry.us-west-2.amazonaws.com/metrics
2021-03-02 06:04:37,218 | local invoke command is called
2021-03-02 06:04:37,220 | No Parameters detected in the template
2021-03-02 06:04:37,239 | 1 resources found in the stack 
2021-03-02 06:04:37,239 | No Parameters detected in the template
2021-03-02 06:04:37,256 | No Parameters detected in the template
2021-03-02 06:04:37,284 | Found Lambda function with name='test' and CodeUri='.'
2021-03-02 06:04:37,295 | Found one Lambda function with name 'test'
2021-03-02 06:04:37,295 | Invoking index.handler (nodejs12.x)
2021-03-02 06:04:37,295 | No environment variables found for function 'test'
2021-03-02 06:04:37,295 | Environment variables overrides data is standard format
2021-03-02 06:04:37,295 | Loading AWS credentials from session with profile 'None'
2021-03-02 06:04:37,306 | Resolving code path. Cwd=/Users/tomono/tmp/__test/1.19.1/__test, CodeUri=/Users/tomono/tmp/__test/1.19.1/__test/.
2021-03-02 06:04:37,306 | Resolved absolute path to code is /Users/tomono/tmp/__test/1.19.1/__test/.
2021-03-02 06:04:37,306 | Code /Users/tomono/tmp/__test/1.19.1/__test/. is not a zip/jar file
2021-03-02 06:04:37,324 | Skip pulling image and use local one: amazon/aws-sam-cli-emulation-image-nodejs12.x:rapid-1.19.1.

2021-03-02 06:04:37,324 | Mounting /Users/tomono/tmp/__test/1.19.1/__test/. as /var/task:ro,delegated inside runtime container
2021-03-02 06:04:37,757 | Starting a timer for 900 seconds for function 'test'
START RequestId: dc9dfef4-c2c1-4984-9966-7a115f0e4439 Version: $LATEST
2021-03-01T21:04:37.938Z	dc9dfef4-c2c1-4984-9966-7a115f0e4439	INFO	body === {"remainingTimeInMillis":1613498018765,"date":"2021-02-16T17:53:38.765Z"}
2021-03-01T21:04:37.958Z	dc9dfef4-c2c1-4984-9966-7a115f0e4439	INFO	response === {"bodyJson":"{}","headers":{"content-type":"application/json","lambda-runtime-aws-request-id":"dc9dfef4-c2c1-4984-9966-7a115f0e4439","lambda-runtime-deadline-ms":"3228130696703","date":"Mon, 01 Mar 2021 21:04:37 GMT","content-length":"2"}}
END RequestId: dc9dfef4-c2c1-4984-9966-7a115f0e4439
REPORT RequestId: dc9dfef4-c2c1-4984-9966-7a115f0e4439	Init Duration: 0.21 ms	Duration: 178.45 ms	Billed Duration: 200 ms	Memory Size: 192 MB	Max Memory Used: 192 MB	
2021-03-02 06:04:38,149 | Cleaning all decompressed code dirs
2021-03-02 06:04:38,150 | Sending Telemetry: {'metrics': [{'commandRun': {'requestId': '98702436-837f-41da-b891-4949748eb0ea', 'installationId': 'd4189183-146b-49ca-9e99-773af5d17efb', 'sessionId': 'c757ba75-09dd-4d61-8f0a-67580ff7b84c', 'executionEnvironment': 'CLI', 'pyversion': '3.8.2', 'samcliVersion': '1.19.1', 'awsProfileProvided': False, 'debugFlagProvided': True, 'region': '', 'commandName': 'sam local invoke', 'duration': 931, 'exitReason': 'success', 'exitCode': 0}}]}
2021-03-02 06:04:38,831 | HTTPSConnectionPool(host='aws-serverless-tools-telemetry.us-west-2.amazonaws.com', port=443): Read timed out. (read timeout=0.1)
null2021-03-02 06:04:38,831 | Telemetry endpoint configured to be https://aws-serverless-tools-telemetry.us-west-2.amazonaws.com/metrics
2021-03-02 06:04:38,832 | Sending Telemetry: {'metrics': [{'runtimeMetric': {'requestId': 'cff16b76-a8fe-44e8-85db-1b229d885e87', 'installationId': 'd4189183-146b-49ca-9e99-773af5d17efb', 'sessionId': 'c757ba75-09dd-4d61-8f0a-67580ff7b84c', 'executionEnvironment': 'CLI', 'pyversion': '3.8.2', 'samcliVersion': '1.19.1', 'runtimes': ['nodejs12.x']}}]}
2021-03-02 06:04:39,358 | HTTPSConnectionPool(host='aws-serverless-tools-telemetry.us-west-2.amazonaws.com', port=443): Read timed out. (read timeout=0.1)

tjdavey · 2021-04-20T06:38:23Z

Confirming that this issue also does not appear to be resolved with 1.22.0. sam local invoke is unusable for golang binaries utilising contexts due to the deadline being incorrectly set by this bug.

intptr-t · 2021-12-18T07:02:24Z

I checked it in the next version and it looks like it's working properly.

SAM CLI, version 1.36.0
public.ecr.aws/sam/emulation-nodejs14.x:rapid-1.36.0-x86_64

danjordan · 2022-01-07T15:13:45Z

Looks good to me in JS, Ruby and Python (2.7 & 3.8) using SAM CLI 1.36.0 🎉

jfuss · 2022-08-30T21:19:36Z

This was patched already but not closed. If that is not accurate, please create a new issue (closed ones are hard to track).

awood45 added area/docker area/local/invoke sam local invoke command type/bug labels Jan 8, 2021

awood45 mentioned this issue Jan 9, 2021

Sam local invoke (go) not honoring timeout in context #2510

Closed

hoffa mentioned this issue Jan 17, 2021

context.get_remaining_time_in_millis() returns different value when running with sam local #2535

Closed

hoffa added the type/duplicate label Jan 18, 2021

hoffa closed this as completed Jan 18, 2021

hoffa reopened this Jan 18, 2021

imjoehaines mentioned this issue Mar 4, 2021

Automatically notify when a lambda may timeout bugsnag/bugsnag-js#1324

Merged

drwxmrrs mentioned this issue Apr 27, 2021

Context deadline exceeded at start locally aws/aws-lambda-go#361

Open

wchengru mentioned this issue Jun 10, 2021

fix: context object method get_remaining_time_in_millis aws/aws-lambda-runtime-interface-emulator#38

Closed

This was referenced Jun 25, 2021

Pull upstream changes 2021/06 aws/aws-lambda-runtime-interface-emulator#39

Merged

Merge from aws-lambda-runtime-interface-emulator/develop aws/aws-lambda-runtime-interface-emulator#40

Merged

mgrandis added the stage/pr Has a PR ready for review label Jun 29, 2021

luke-belton mentioned this issue Aug 19, 2021

[SUP-1281] AWS Lambda example app bugsnag/bugsnag-js#1517

Draft

aws-sam-cli-bot added maintainer/need-followup and removed maintainer/need-followup labels Oct 7, 2021

aws-sam-cli-bot added maintainer/need-followup and removed maintainer/need-followup labels Dec 19, 2021

aws-sam-cli-bot added maintainer/need-followup and removed maintainer/need-followup labels Jan 8, 2022

jfuss closed this as completed Aug 30, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

getRemainingTimeInMillis is returning a unix time #2519

getRemainingTimeInMillis is returning a unix time #2519

danjordan commented Jan 6, 2021 •

edited by hoffa

Loading

awood45 commented Jan 8, 2021

eunomie commented Jan 12, 2021

hoffa commented Jan 18, 2021 •

edited

Loading

hoffa commented Jan 18, 2021

danjordan commented Jan 18, 2021

mousedownmike commented Feb 20, 2021

intptr-t commented Mar 1, 2021

tjdavey commented Apr 20, 2021 •

edited

Loading

intptr-t commented Dec 18, 2021

danjordan commented Jan 7, 2022

jfuss commented Aug 30, 2022

getRemainingTimeInMillis is returning a unix time #2519

getRemainingTimeInMillis is returning a unix time #2519

Comments

danjordan commented Jan 6, 2021 • edited by hoffa Loading

Description:

Steps to reproduce:

Observed result:

Expected result:

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

awood45 commented Jan 8, 2021

eunomie commented Jan 12, 2021

hoffa commented Jan 18, 2021 • edited Loading

hoffa commented Jan 18, 2021

danjordan commented Jan 18, 2021

mousedownmike commented Feb 20, 2021

intptr-t commented Mar 1, 2021

template.yaml

Code for verification

detail logs

tjdavey commented Apr 20, 2021 • edited Loading

intptr-t commented Dec 18, 2021

danjordan commented Jan 7, 2022

jfuss commented Aug 30, 2022

danjordan commented Jan 6, 2021 •

edited by hoffa

Loading

hoffa commented Jan 18, 2021 •

edited

Loading

tjdavey commented Apr 20, 2021 •

edited

Loading