getRemainingTimeInMillis is returning a unix time

[danjordan]

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)

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

[awood45]

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

[eunomie]

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]

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

[hoffa]

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]

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]

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

[intptr-t]

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)