Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

bug: pre-signed POST to s3 does not trigger s3 object created event for lambda trigger #5554

Closed
1 task done
paulrobello opened this issue Feb 22, 2022 · 29 comments
Closed
1 task done
Assignees
Labels
area: integration/pulumi Issues related to Pulumi aws:lambda AWS Lambda aws:s3 Amazon Simple Storage Service status: triage needed Requires evaluation by maintainers type: bug Bug report type: usage Usage of LocalStack and Best Practices

Comments

@paulrobello
Copy link

Is there an existing issue for this?

  • I have searched the existing issues

Current Behavior

Using pre-signed POST to s3 does not trigger s3 object created event for lambda trigger.

Expected Behavior

Using pre-signed POST to s3 should trigger s3 object created event for lambda trigger.

How are you starting LocalStack?

With a docker-compose file

Steps To Reproduce

How are you starting localstack (e.g., bin/localstack command, arguments, or docker-compose.yml)

docker compose up -d

Client commands (e.g., AWS SDK code snippet, or sequence of "awslocal" commands)

Pulumi typescript:

export const uploadObjectCreateEvent = bucket.onObjectCreated(
'uploadObjectCreateEvent',
fuelUploadLambda,
{
event: '*',
filterPrefix: 'uploads/'
},
{ provider: PulumiUtil.awsProvider }
);

Environment

- OS: OSX and Windows 11
- LocalStack: latest

Anything else?

Event does trigger if I use cli s3 cp.
Maybe related to #4809 ?

@paulrobello paulrobello added type: bug Bug report status: triage needed Requires evaluation by maintainers labels Feb 22, 2022
@MarcelStranak MarcelStranak added aws:lambda AWS Lambda aws:s3 Amazon Simple Storage Service area: integration/pulumi Issues related to Pulumi labels Feb 24, 2022
@pinzon pinzon self-assigned this Feb 25, 2022
@pinzon
Copy link
Member

pinzon commented Mar 9, 2022

Hi @paulrobello, thank you for your patience. After triaging your issue it seems to be an usage error, I'm guessing because you're using POST instead of PUT as aws specifies here.

I took me some time to validate this due to Pulumi behaving very irrational some of the times with Localstack. Either way I'm attaching my stack config file, stack file and lambda code so you can validate my results.

index.ts

import * as pulumi from "@pulumi/pulumi";
import * as aws from "@pulumi/aws";
import { rootPulumiStackTypeName } from "@pulumi/pulumi/runtime";

const bucket = new aws.s3.Bucket("my-bucket");

const lambda = new aws.lambda.Function("lambda", {
	code: new pulumi.asset.FileArchive('function.zip'),
	runtime: "nodejs14.x",
	handler: "index.handler",
	role: "no-real-role"
})

const createdObjectEvent = bucket.onObjectCreated("uploadEvent", lambda, {
	event: '*',
	filterPrefix: '/'
});

Pulumi.pinzon.yaml

config:
  aws:accessKey: test
  aws:endpoints:
  - acm: http://localhost:4566
    amplify: http://localhost:4566
    apigateway: http://localhost:4566
    apigatewayv2: http://localhost:4566
    applicationautoscaling: http://localhost:4566
    appsync: http://localhost:4566
    athena: http://localhost:4566
    autoscaling: http://localhost:4566
    batch: http://localhost:4566
    cloudformation: http://localhost:4566
    cloudfront: http://localhost:4566
    cloudsearch: http://localhost:4566
    cloudtrail: http://localhost:4566
    cloudwatch: http://localhost:4566
    cloudwatchevents: http://localhost:4566
    cloudwatchlogs: http://localhost:4566
    codecommit: http://localhost:4566
    cognitoidentity: http://localhost:4566
    cognitoidp: http://localhost:4566
    docdb: http://localhost:4566
    dynamodb: http://localhost:4566
    ec2: http://localhost:4566
    ecr: http://localhost:4566
    ecs: http://localhost:4566
    eks: http://localhost:4566
    elasticache: http://localhost:4566
    elasticbeanstalk: http://localhost:4566
    elb: http://localhost:4566
    emr: http://localhost:4566
    es: http://localhost:4566
    firehose: http://localhost:4566
    glacier: http://localhost:4566
    glue: http://localhost:4566
    iam: http://localhost:4566
    iot: http://localhost:4566
    kafka: http://localhost:4566
    kinesis: http://localhost:4566
    kinesisanalytics: http://localhost:4566
    kms: http://localhost:4566
    lambda: http://localhost:4566
    mediastore: http://localhost:4566
    neptune: http://localhost:4566
    organizations: http://localhost:4566
    qldb: http://localhost:4566
    rds: http://localhost:4566
    redshift: http://localhost:4566
    route53: http://localhost:4566
    s3: http://localhost:4566
    sagemaker: http://localhost:4566
    secretsmanager: http://localhost:4566
    servicediscovery: http://localhost:4566
    ses: http://localhost:4566
    sns: http://localhost:4566
    sqs: http://localhost:4566
    ssm: http://localhost:4566
    stepfunctions: http://localhost:4566
    sts: http://localhost:4566
    swf: http://localhost:4566
    transfer: http://localhost:4566
    xray: http://localhost:4566
  aws:region: us-east-1
  aws:s3ForcePathStyle: 'true'
  aws:secretKey: test
  aws:skipCredentialsValidation: 'true'
  aws:skipRequestingAccountId: 'true'

lambda code

const https = require('https')
const url = 'https://webhook.site/043b22e6-8656-455e-b7cc-3420ee4d1221'
exports.handler = function (event, context, callback) {
	const promise = new Promise(function (resolve, reject) {
		https.get(url, (res) => {
			callback(null, res.statusCode)
		}).on('error', (e) => {
			callback(Error(e))
		})
	})
}

I'm closing this issue but if you feel that this is not the case please comment with more info about the error logs and your exact setup/stack-code.
Thank you.

@pinzon pinzon closed this as completed Mar 9, 2022
@paulrobello
Copy link
Author

The url I am generating is for POST not PUT and does work with AWS production env. Sample python boto code here:

def create_presigned_post(
    bucket_name: str, object_name: str, expiration: int = 3600, metadata: Dict = None
):
    """Generate a presigned URL to share an S3 object

    @param bucket_name: string
    @param object_name: string
    @param expiration: Time in seconds for the presigned URL to remain valid
    @param metadata: specify content type and any other metadata to be saved with object
    @return: Presigned URL as string. If error, returns None.
    """

    # Generate a presigned URL for the S3 object
    s3_client = get_client("s3", environment, None, region)

    metadata = metadata if metadata else {}
    conditions = [
        ["eq", "$key", object_name],  # key must match
        [
            "content-length-range",
            1,
            1000000000,
        ],  # file size not zero and no more than 1GB
    ]
    for key, value in metadata.items():
        conditions.append(
            ["eq", "$" + key, value]
        )  # require all other values from metadata be present
    return s3_client.generate_presigned_post(
        Bucket=bucket_name,
        Key=object_name,
        Fields=metadata,
        ExpiresIn=expiration,
        Conditions=conditions,
    )

@pinzon
Copy link
Member

pinzon commented Mar 9, 2022

ah ok, thanks for the promptly response. so can you confirm that the issue of Localstack is not with the notification but with the post request not being handled as aws would do?

@pinzon pinzon reopened this Mar 9, 2022
@paulrobello
Copy link
Author

The post request to s3 should trigger the s3 event which triggers a lambda, All i can really tell is that it works in AWS but the lambda is never triggered in localstack

@pinzon
Copy link
Member

pinzon commented Mar 10, 2022

@paulrobello , could you provide LOGS of your Localstack instance when encountering your issue? Just finished testing with the pulumi setup I shared before and code to test the upload with a generate_presigned_post, and the upload is triggering the lambda function.

code to upload with a generated_presigned_post

import boto3
import requests

s3 = boto3.client("s3", endpoint_url="http://localhost:4566")

bucket_name = "my-bucket-982bc46"
object_name = "text.txt"
file = open("text.txt", "r")

response = s3.generate_presigned_post(bucket_name, object_name)


files = {"file": (object_name, file)}
post(response["url"], data=response["fields"], files=files)

response = s3.get_object(Bucket=bucket_name, Key=object_name)

@pinzon
Copy link
Member

pinzon commented Mar 16, 2022

I'm closing this issue as usage, but if you feel that this is not the case please comment with more info about the error logs and your exact setup/stack-code.

@pinzon pinzon closed this as completed Mar 16, 2022
@pinzon pinzon added the type: usage Usage of LocalStack and Best Practices label Mar 16, 2022
@kingster307
Copy link

@pinzon See logs attached...all constants that @paulrobello states remains true, using localstack/localstack:1.0.0 issue still present even with put usage as specified. As you can see from the logs it receives the presigned url upload but never fires the corresponding lambda as it should to process the upload.

Screen Shot 2022-07-13 at 4 15 29 PM

Screen Shot 2022-07-13 at 4 13 46 PM

Screen Shot 2022-07-13 at 4 06 50 PM

@kingster307
Copy link

have tried with create_presigned_post func above && post request as @paulrobello stated above with v1 as well...see logs for that below
Screen Shot 2022-07-13 at 3 47 09 PM

@pinzon
Copy link
Member

pinzon commented Jul 13, 2022

@kingster307 thanks for the update. I'll take a look soon.

@pinzon pinzon reopened this Jul 13, 2022
@kingster307
Copy link

@pinzon just got clearance to release the full logs for v1 utilizing put not post....expected behavior - get presigned url - make put request to it - s3 onObjectCreated fires up lambda - lambda returns msgs via websockets

2022-07-18T15:25:33.284  INFO --- [  Thread-162] websockets.server          : connection open
2022-07-18T15:25:33.286 DEBUG --- [ Thread-2370] l.s.apigateway.authorizers : Processing API V2 invocation
2022-07-18T15:25:33.286 DEBUG --- [ Thread-2370] l.s.apigateway.authorizers : Running authorization for request to API Gateway ID 70724b90 - None /?p_id=640
2022-07-18T15:25:33.288  INFO --- [ Thread-2370] l.s.a.lambda_executors     : Running lambda: arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c
2022-07-18T15:25:33.288 DEBUG --- [ Thread-2370] l.s.a.lambda_launcher      : Executing docker-reuse Lambda container invocation
2022-07-18T15:25:33.288 DEBUG --- [ Thread-2370] l.s.a.lambda_executors     : Priming docker container with runtime "python3.7" and arn "arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c".
2022-07-18T15:25:33.297 DEBUG --- [ Thread-2370] l.s.a.lambda_executors     : Priming Docker container (status "1"): localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c
2022-07-18T15:25:33.306 DEBUG --- [  asgi_gw_10] l.s.apigateway.authorizers : Processing API V1 invocation
2022-07-18T15:25:33.306 DEBUG --- [  asgi_gw_10] l.s.apigateway.authorizers : Running authorization for request to API Gateway ID 2e3vwmclcg - GET /fuel_price_upload?job_id=69&action=fuel_price_file_upload&file_name=AVCD+3-22.csv&content_type=csv&company=XOJET+Aviation+LLC&effective_date=2022-03-20&vendor_id=AVCD&use_fos=0&p_id=640
2022-07-18T15:25:33.321 DEBUG --- [ Thread-2370] l.u.c.container_client     : Getting networks for container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c
2022-07-18T15:25:33.346 DEBUG --- [ Thread-2370] l.u.c.container_client     : Getting the entrypoint for image: localstack/lambda:python3.7
2022-07-18T15:25:33.354 DEBUG --- [ Thread-2370] l.s.a.lambda_executors     : Using entrypoint "/var/rapid/init --bootstrap /var/runtime/bootstrap" for container "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c" on network "devnet".
2022-07-18T15:25:33.373 DEBUG --- [ Thread-2370] l.s.a.lambda_executors     : Calling http://169.254.170.5:9001 to run invocation in docker-reuse Lambda container
2022-07-18T15:25:33.466 DEBUG --- [ Thread-2370] l.s.a.lambda_executors     : Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c result / log output:
{"principalId": "samlp|XOAAzure|pking@xojetaviation.com", "policyDocument": {"Version": "2012-10-17", "Statement": [{"Effect": "Allow", "Resource": ["arn:aws:execute-api:us-west-2:000000000000:70724b90/None/$default", "arn:aws:execute-api:us-west-2:000000000000:70724b90/None/$connect", "arn:aws:execute-api:us-west-2:000000000000:70724b90/None/$disconnect", "arn:aws:execute-api:us-west-2:000000000000:70724b90/None/ping", "arn:aws:execute-api:us-west-2:000000000000:70724b90/None/hello", "arn:aws:execute-api:us-west-2:000000000000:70724b90/None/chatMessage"], "Action": ["execute-api:Invoke"]}]}, "context": {"scope": "openid profile email", "permissions": "[\"chat.admin\", \"chat.user\", \"fuel_price.update\", \"reports.run\"]"}}
>{"level":"INFO","location":"lambda_handler:16","message":{"version":"1.0","type":"REQUEST","methodArn":"arn:aws:execute-api:us-west-2:000000000000:70724b90/None/$$connect","identitySource":"","authorizationToken":"","resource":"/","path":"/","httpMethod":null,"headers":{"host":"host.docker.internal:4510","upgrade":"websocket","connection":"Upgrade","sec-websocket-key":"8sI/E9bqDEDqY5uYZWNAvA==","sec-websocket-version":"13","sec-websocket-extensions":"permessage-deflate; client_max_window_bits","sec-websocket-protocol":"auth, eyJ0eXAiOiJqd3QiLCJhbGciOiJSUzI1NiIsImtpZCI6IkhLTExfaWRvVS1DWWR2ZUVYLUp1cnczUGMycGZ0Mks3NVo5dkIzbk1SLVkifQ.eyJpc3MiOiJodHRwOi8vYXV0aDBfbW9jazozMDAwLyIsInN1YiI6InNhbWxwfFhPQUF6dXJlfHBraW5nQHhvamV0YXZpYXRpb24uY29tIiwiYXVkIjpbInhvYV9kYXRhX3BvcnRhbCIsImh0dHA6Ly9hdXRoMF9tb2NrOjMwMDAvdXNlcmluZm8iXSwiaWF0IjoxNjU4MTU3OTMzLCJleHAiOjE2NTgyNDQzMzMsImF6cCI6IiIsInNjb3BlIjoib3BlbmlkIHByb2ZpbGUgZW1haWwiLCJwZXJtaXNzaW9ucyI6WyJjaGF0LmFkbWluIiwiY2hhdC51c2VyIiwiZnVlbF9wcmljZS51cGRhdGUiLCJyZXBvcnRzLnJ1biJdfQ.bbCgH48rexaL549d0m9TLwIJpqf5m6O4sT5naudd9e_07cbtQFGoSPRlDBVTo0olOTQUBKLewPC87LNdpWLD-93aJLSpKM9Y81gBxdqPfgYtUa2u2pZmUCst_l04wenpGatEtxdEPZFUBJEFFaB-gLcP7Vdz85LxDZD7r1KJ_7daa4TZLD83_aMMEvckBXqL4C36Ryy_aOFspnmbuAe-2KGILqozJ8RlPomOD_4vLRjn_JVH-UAeYPPp_TJT5_jwkmSO4tMXuGC6lGtGgf-erBbhmpPkdv9lCmuQJxSeQ5sUKT3ytKtR7ey6KmGI9vgsMgVHNJvoPMv-7ZOIbAVhSQ","user-agent":"Python/3.9 websockets/10.3"},"queryStringParameters":{"p_id":"640"},"pathParameters":{},"stageVariables":null,"requestContext":{"path":"/","accountId":"000000000000","apiId":"70724b90","resourcePath":"/","domainPrefix":"host","domainName":"host.docker.internal","resourceId":null,"requestId":"310cad98","identity":{"accountId":"000000000000","sourceIp":"","userAgent":"Python/3.9 websockets/10.3"},"stage":null,"httpMethod":null}},"timestamp":"2022-07-18 15:25:33,398+0000","service":"apiGwAuthorizerLambda","cold_start":false,"function_name":"fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c","function_memory_...
2022-07-18T15:25:33.497  INFO --- [  asgi_gw_10] l.s.a.lambda_executors     : Running lambda: arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c
2022-07-18T15:25:33.497 DEBUG --- [  asgi_gw_10] l.s.a.lambda_launcher      : Executing docker-reuse Lambda container invocation
2022-07-18T15:25:33.497 DEBUG --- [  asgi_gw_10] l.s.a.lambda_executors     : Priming docker container with runtime "python3.7" and arn "arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c".
2022-07-18T15:25:33.508  INFO --- [ Thread-2370] l.s.apigateway.authorizers : Received authorizer result: {"principalId": "samlp|XOAAzure|pking@xojetaviation.com", "policyDocument": {"Version": "2012-10-17", "Statement": [{"Effect": "Allow", "Resource": ["arn:aws:execute-api:us-west-2:000000000000:70724b90/None/$default", "arn:aws:execute-api:us-west-2:000000000000:70724b90/None/$connect", "arn:aws:execute-api:us-west-2:000000000000:70724b90/None/$disconnect", "arn:aws:execute-api:us-west-2:000000000000:70724b90/None/ping", "arn:aws:execute-api:us-west-2:000000000000:70724b90/None/hello", "arn:aws:execute-api:us-west-2:000000000000:70724b90/None/chatMessage"], "Action": ["execute-api:Invoke"]}]}, "context": {"scope": "openid profile email", "permissions": "[\"chat.admin\", \"chat.user\", \"fuel_price.update\", \"reports.run\"]"}}
2022-07-18T15:25:33.509 DEBUG --- [  asgi_gw_10] l.s.a.lambda_executors     : Priming Docker container (status "1"): localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c
2022-07-18T15:25:33.513 DEBUG --- [ Thread-2370] l.s.apigateway.invocations : Invoking Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-663ab76 for WebSocket integration of API ID 70724b90
2022-07-18T15:25:33.514  INFO --- [ Thread-2370] l.s.a.lambda_executors     : Running lambda: arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-663ab76
2022-07-18T15:25:33.514 DEBUG --- [ Thread-2370] l.s.a.lambda_launcher      : Executing docker-reuse Lambda container invocation
2022-07-18T15:25:33.529 DEBUG --- [  asgi_gw_10] l.u.c.container_client     : Getting networks for container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c
2022-07-18T15:25:33.547 DEBUG --- [  asgi_gw_10] l.u.c.container_client     : Getting the entrypoint for image: localstack/lambda:python3.7
2022-07-18T15:25:33.552 DEBUG --- [  asgi_gw_10] l.s.a.lambda_executors     : Using entrypoint "/var/rapid/init --bootstrap /var/runtime/bootstrap" for container "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c" on network "devnet".
2022-07-18T15:25:33.552 DEBUG --- [ Thread-2370] l.s.a.lambda_executors     : Priming docker container with runtime "python3.7" and arn "arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-663ab76".
2022-07-18T15:25:33.565 DEBUG --- [  asgi_gw_10] l.s.a.lambda_executors     : Calling http://169.254.170.5:9001 to run invocation in docker-reuse Lambda container
2022-07-18T15:25:33.574 DEBUG --- [ Thread-2370] l.s.a.lambda_executors     : Priming Docker container (status "1"): localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-663ab76
2022-07-18T15:25:33.596 DEBUG --- [  asgi_gw_10] l.s.a.lambda_executors     : Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c result / log output:
{"principalId": "samlp|XOAAzure|pking@xojetaviation.com", "policyDocument": {"Version": "2012-10-17", "Statement": [{"Effect": "Allow", "Resource": ["arn:aws:execute-api:us-west-2:000000000000/2e3vwmclcg/GET/tasks/", "arn:aws:execute-api:us-west-2:000000000000/2e3vwmclcg/GET/download/", "arn:aws:execute-api:us-west-2:000000000000/2e3vwmclcg/GET/etl_status/", "arn:aws:execute-api:us-west-2:000000000000/2e3vwmclcg/GET/reports/", "arn:aws:execute-api:us-west-2:000000000000/2e3vwmclcg/GET/fuel_price_upload/", "arn:aws:execute-api:us-west-2:000000000000/2e3vwmclcg/GET/ops_data_upload/", "arn:aws:execute-api:us-west-2:000000000000/2e3vwmclcg/*/fuel_pricing/"], "Action": ["execute-api:Invoke"]}]}, "context": {"scope": "openid profile email", "permissions": "[\"chat.admin\", \"chat.user\", \"fuel_price.update\", \"reports.run\"]"}}
>{"level":"INFO","location":"lambda_handler:16","message":{"type":"TOKEN","authorizationToken":"Bearer eyJ0eXAiOiJqd3QiLCJhbGciOiJSUzI1NiIsImtpZCI6IkhLTExfaWRvVS1DWWR2ZUVYLUp1cnczUGMycGZ0Mks3NVo5dkIzbk1SLVkifQ.eyJpc3MiOiJodHRwOi8vYXV0aDBfbW9jazozMDAwLyIsInN1YiI6InNhbWxwfFhPQUF6dXJlfHBraW5nQHhvamV0YXZpYXRpb24uY29tIiwiYXVkIjpbInhvYV9kYXRhX3BvcnRhbCIsImh0dHA6Ly9hdXRoMF9tb2NrOjMwMDAvdXNlcmluZm8iXSwiaWF0IjoxNjU4MTU3OTMzLCJleHAiOjE2NTgyNDQzMzMsImF6cCI6IiIsInNjb3BlIjoib3BlbmlkIHByb2ZpbGUgZW1haWwiLCJwZXJtaXNzaW9ucyI6WyJjaGF0LmFkbWluIiwiY2hhdC51c2VyIiwiZnVlbF9wcmljZS51cGRhdGUiLCJyZXBvcnRzLnJ1biJdfQ.bbCgH48rexaL549d0m9TLwIJpqf5m6O4sT5naudd9e_07cbtQFGoSPRlDBVTo0olOTQUBKLewPC87LNdpWLD-93aJLSpKM9Y81gBxdqPfgYtUa2u2pZmUCst_l04wenpGatEtxdEPZFUBJEFFaB-gLcP7Vdz85LxDZD7r1KJ_7daa4TZLD83_aMMEvckBXqL4C36Ryy_aOFspnmbuAe-2KGILqozJ8RlPomOD_4vLRjn_JVH-UAeYPPp_TJT5_jwkmSO4tMXuGC6lGtGgf-erBbhmpPkdv9lCmuQJxSeQ5sUKT3ytKtR7ey6KmGI9vgsMgVHNJvoPMv-7ZOIbAVhSQ","methodArn":"arn:aws:execute-api:us-west-2:000000000000:2e3vwmclcg/api/GET/fuel_price_upload"},"timestamp":"2022-07-18 15:25:33,569+0000","service":"apiGwAuthorizerLambda","cold_start":false,"function_name":"fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c","function_memory_size":"1536","function_arn":"arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-0ad8c6c","function_request_id":"fe515108-2f52-1f20-70d4-b36a4258246f","xray_trace_id":"21823157312160"}
2022-07-18T15:25:33.600 DEBUG --- [ Thread-2370] l.u.c.container_client     : Getting networks for container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-663ab76
2022-07-18T15:25:33.615 DEBUG --- [ Thread-2370] l.u.c.container_client     : Getting the entrypoint for image: localstack/lambda:python3.7
2022-07-18T15:25:33.620 DEBUG --- [ Thread-2370] l.s.a.lambda_executors     : Using entrypoint "/var/rapid/init --bootstrap /var/runtime/bootstrap" for container "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-663ab76" on network "devnet".
2022-07-18T15:25:33.632 DEBUG --- [ Thread-2370] l.s.a.lambda_executors     : Calling http://169.254.170.9:9001 to run invocation in docker-reuse Lambda container
2022-07-18T15:25:33.671  INFO --- [  asgi_gw_10] l.s.apigateway.integration : Method request body before transformations:
2022-07-18T15:25:33.672 DEBUG --- [  asgi_gw_10] l.s.awslambda.lambda_api   : Running Lambda function arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwFuelUploadLambda-ls_local-f546e35 from API Gateway invocation: GET /fuel_price_upload
2022-07-18T15:25:33.672  INFO --- [  asgi_gw_10] l.s.a.lambda_executors     : Running lambda: arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwFuelUploadLambda-ls_local-f546e35
2022-07-18T15:25:33.672 DEBUG --- [  asgi_gw_10] l.s.a.lambda_launcher      : Executing docker-reuse Lambda container invocation
2022-07-18T15:25:33.672 DEBUG --- [  asgi_gw_10] l.s.a.lambda_executors     : Priming docker container with runtime "python3.7" and arn "arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwFuelUploadLambda-ls_local-f546e35".
2022-07-18T15:25:33.679 DEBUG --- [  asgi_gw_10] l.s.a.lambda_executors     : Priming Docker container (status "1"): localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-f546e35
2022-07-18T15:25:33.706 DEBUG --- [  asgi_gw_10] l.u.c.container_client     : Getting networks for container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-f546e35
2022-07-18T15:25:33.730 DEBUG --- [  asgi_gw_10] l.u.c.container_client     : Getting the entrypoint for image: localstack/lambda:python3.7
2022-07-18T15:25:33.735 DEBUG --- [  asgi_gw_10] l.s.a.lambda_executors     : Using entrypoint "/var/rapid/init --bootstrap /var/runtime/bootstrap" for container "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-f546e35" on network "devnet".
2022-07-18T15:25:33.749 DEBUG --- [  asgi_gw_10] l.s.a.lambda_executors     : Calling http://169.254.170.6:9001 to run invocation in docker-reuse Lambda container
2022-07-18T15:25:33.794  INFO --- [  asgi_gw_13] localstack.request.aws     : AWS dynamodb.PutItem => 200
2022-07-18T15:25:33.834 DEBUG --- [ Thread-2370] l.s.a.lambda_executors     : Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-663ab76 result / log output:
{"statusCode": 200, "body": "$connect", "headers": {"Sec-WebSocket-Protocol": "auth"}}
>{"level":"INFO","location":"lambda_handler:22","message":{"version":"1.0","resource":"/","httpMethod":null,"path":"/?p_id=640","body":"{\"action\": \"$connect\"}","headers":{"host":"host.docker.internal:4510","upgrade":"websocket","connection":"Upgrade","sec-websocket-key":"8sI/E9bqDEDqY5uYZWNAvA==","sec-websocket-version":"13","sec-websocket-extensions":"permessage-deflate; client_max_window_bits","sec-websocket-protocol":"auth, eyJ0eXAiOiJqd3QiLCJhbGciOiJSUzI1NiIsImtpZCI6IkhLTExfaWRvVS1DWWR2ZUVYLUp1cnczUGMycGZ0Mks3NVo5dkIzbk1SLVkifQ.eyJpc3MiOiJodHRwOi8vYXV0aDBfbW9jazozMDAwLyIsInN1YiI6InNhbWxwfFhPQUF6dXJlfHBraW5nQHhvamV0YXZpYXRpb24uY29tIiwiYXVkIjpbInhvYV9kYXRhX3BvcnRhbCIsImh0dHA6Ly9hdXRoMF9tb2NrOjMwMDAvdXNlcmluZm8iXSwiaWF0IjoxNjU4MTU3OTMzLCJleHAiOjE2NTgyNDQzMzMsImF6cCI6IiIsInNjb3BlIjoib3BlbmlkIHByb2ZpbGUgZW1haWwiLCJwZXJtaXNzaW9ucyI6WyJjaGF0LmFkbWluIiwiY2hhdC51c2VyIiwiZnVlbF9wcmljZS51cGRhdGUiLCJyZXBvcnRzLnJ1biJdfQ.bbCgH48rexaL549d0m9TLwIJpqf5m6O4sT5naudd9e_07cbtQFGoSPRlDBVTo0olOTQUBKLewPC87LNdpWLD-93aJLSpKM9Y81gBxdqPfgYtUa2u2pZmUCst_l04wenpGatEtxdEPZFUBJEFFaB-gLcP7Vdz85LxDZD7r1KJ_7daa4TZLD83_aMMEvckBXqL4C36Ryy_aOFspnmbuAe-2KGILqozJ8RlPomOD_4vLRjn_JVH-UAeYPPp_TJT5_jwkmSO4tMXuGC6lGtGgf-erBbhmpPkdv9lCmuQJxSeQ5sUKT3ytKtR7ey6KmGI9vgsMgVHNJvoPMv-7ZOIbAVhSQ","user-agent":"Python/3.9 websockets/10.3"},"multiValueHeaders":{"host":["host.docker.internal:4510"],"upgrade":["websocket"],"connection":["Upgrade"],"sec-websocket-key":["8sI/E9bqDEDqY5uYZWNAvA=="],"sec-websocket-version":["13"],"sec-websocket-extensions":["permessage-deflate; client_max_window_bits"],"sec-websocket-protocol":["auth, eyJ0eXAiOiJqd3QiLCJhbGciOiJSUzI1NiIsImtpZCI6IkhLTExfaWRvVS1DWWR2ZUVYLUp1cnczUGMycGZ0Mks3NVo5dkIzbk1SLVkifQ.eyJpc3MiOiJodHRwOi8vYXV0aDBfbW9jazozMDAwLyIsInN1YiI6InNhbWxwfFhPQUF6dXJlfHBraW5nQHhvamV0YXZpYXRpb24uY29tIiwiYXVkIjpbInhvYV9kYXRhX3BvcnRhbCIsImh0dHA6Ly9hdXRoMF9tb2NrOjMwMDAvdXNlcmluZm8iXSwiaWF0IjoxNjU4MTU3OTMzLCJleHAiOjE2NTgyNDQzMzMsImF6cCI6IiIsInNjb3BlIjoib3BlbmlkIHByb2ZpbGUgZW1haWwi...
2022-07-18T15:25:33.885 DEBUG --- [  asgi_gw_10] l.s.a.lambda_executors     : Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwFuelUploadLambda-ls_local-f546e35 result / log output:
{"statusCode": 200, "headers": {"Access-Control-Allow-Origin": "*", "Access-Control-Allow-Credentials": "true", "Access-Control-Allow-Headers": "Content-Type,X-Amz-Date,Authorization,X-Api-Key,X-Amz-Security-Token"}, "body": "{\"status\": true, \"message\": null, \"data\": \"http://169.254.170.4:4566/self-serve-portal-20220718151114064200000004/fuel_pricing_upload/33fb622a-7388-49a6-a76f-7c117c2d47b5?AWSAccessKeyId=test&Signature=jswVeZ7OcDE6YOuj3fSYbF0KcGs%3D&x-amz-meta-content-type=csv&x-amz-meta-x-amz-meta-principal_id=640&x-amz-meta-x-amz-meta-job_id=69&x-amz-meta-x-amz-meta-action=fuel_price_file_upload&x-amz-meta-x-amz-meta-filename=AVCD%203-22.csv&x-amz-meta-x-amz-meta-effective_date=2022-03-20&x-amz-meta-x-amz-meta-use_fos=0&x-amz-meta-x-amz-meta-company=XOJET%20Aviation%20LLC&x-amz-meta-x-amz-meta-vendor_id=AVCD&Expires=1658161533\"}"}
>{"level":"INFO","location":"lambda_handler:17","message":{"path":"/fuel_price_upload","headers":{"Host":"2e3vwmclcg.execute-api.localhost.localstack.cloud:4566","User-Agent":"python-requests/2.27.1","accept-encoding":"gzip, deflate","accept":"*/*","Connection":"keep-alive","Authorization":"","x-localstack-tgt-api":"apigateway","x-localstack-request-url":"http://2e3vwmclcg.execute-api.localhost.localstack.cloud:4566/api/fuel_price_upload","X-Forwarded-For":"169.254.170.1, 2e3vwmclcg.execute-api.localhost.localstack.cloud:4566, 169.254.170.1, 2e3vwmclcg.execute-api.localhost.localstack.cloud:4566","x-localstack-edge":"http://2e3vwmclcg.execute-api.localhost.localstack.cloud:4566"},"multiValueHeaders":{"Host":["2e3vwmclcg.execute-api.localhost.localstack.cloud:4566"],"User-Agent":["python-requests/2.27.1"],"accept-encoding":["gzip, deflate"],"accept":["*/*"],"Connection":["keep-alive"],"Authorization":[""],"x-localstack-tgt-api":["apigateway"],"x-localstack-request-url":["http://2e3vwmclcg.execute-api.localhost.localstack.cloud:4566/api/fuel_price_upload"],"X-Forwarded-For":["169.254.170.1, 2e3vwmclcg.execute-api.localhost.localstack.cloud:4566, 169.254.170.1, 2e3vwmclcg.execute-api.localhost.localstack.cloud:4566"],"x-localstack-edge":["http://2e3vwmclcg.execute-api.localhost.localstack.cloud:4566"]},"body":"","isBase64Encoded":false,"httpMethod":"GET","queryStringParameters":{"job_id":"69","action":"fuel_price_file_upload","file_name":"AVCD 3-22.csv","content_type":"csv","company":"XOJET Aviation LLC","effective_date":"2022-03-20","vendor_id":"AVCD","use_fos":"0","p_id":"640"},"multiValueQueryStringParameters":{"job_id":["69"],"action":["fuel_price_file_upload"],"file_name":["AVCD 3-22.csv"],"content_type":["csv"],"company":["XOJET Aviation LLC"],"effective_date":["2022-03-20"],"vendor_id":["AVCD"],"use_fos":["0"],"p_id":["640"]},"pathParameters":{},"resource":"/fuel_price_upload","requestContext":{"accountId":"000000000000","apiId":"2e3vwmclcg","resourcePath":"/fuel...
2022-07-18T15:25:33.942  INFO --- [  asgi_gw_10] localstack.request.http    : GET /api/fuel_price_upload => 200
2022-07-18T15:25:36.465 DEBUG --- [  asgi_gw_15] l.services.s3.s3_utils     : Received presign S3 URL: http://localhost:4566/self-serve-portal-20220718151114064200000004/fuel_pricing_upload/33fb622a-7388-49a6-a76f-7c117c2d47b5?AWSAccessKeyId=test&Signature=jswVeZ7OcDE6YOuj3fSYbF0KcGs%3D&x-amz-meta-content-type=csv&x-amz-meta-x-amz-meta-principal_id=640&x-amz-meta-x-amz-meta-job_id=69&x-amz-meta-x-amz-meta-action=fuel_price_file_upload&x-amz-meta-x-amz-meta-filename=AVCD%203-22.csv&x-amz-meta-x-amz-meta-effective_date=2022-03-20&x-amz-meta-x-amz-meta-use_fos=0&x-amz-meta-x-amz-meta-company=XOJET%20Aviation%20LLC&x-amz-meta-x-amz-meta-vendor_id=AVCD&Expires=1658161533&Authorization=Bearer+eyJ0eXAiOiJqd3QiLCJhbGciOiJSUzI1NiIsImtpZCI6IkhLTExfaWRvVS1DWWR2ZUVYLUp1cnczUGMycGZ0Mks3NVo5dkIzbk1SLVkifQ.eyJpc3MiOiJodHRwOi8vYXV0aDBfbW9jazozMDAwLyIsInN1YiI6InNhbWxwfFhPQUF6dXJlfHBraW5nQHhvamV0YXZpYXRpb24uY29tIiwiYXVkIjpbInhvYV9kYXRhX3BvcnRhbCIsImh0dHA6Ly9hdXRoMF9tb2NrOjMwMDAvdXNlcmluZm8iXSwiaWF0IjoxNjU4MTU3OTMzLCJleHAiOjE2NTgyNDQzMzMsImF6cCI6IiIsInNjb3BlIjoib3BlbmlkIHByb2ZpbGUgZW1haWwiLCJwZXJtaXNzaW9ucyI6WyJjaGF0LmFkbWluIiwiY2hhdC51c2VyIiwiZnVlbF9wcmljZS51cGRhdGUiLCJyZXBvcnRzLnJ1biJdfQ.bbCgH48rexaL549d0m9TLwIJpqf5m6O4sT5naudd9e_07cbtQFGoSPRlDBVTo0olOTQUBKLewPC87LNdpWLD-93aJLSpKM9Y81gBxdqPfgYtUa2u2pZmUCst_l04wenpGatEtxdEPZFUBJEFFaB-gLcP7Vdz85LxDZD7r1KJ_7daa4TZLD83_aMMEvckBXqL4C36Ryy_aOFspnmbuAe-2KGILqozJ8RlPomOD_4vLRjn_JVH-UAeYPPp_TJT5_jwkmSO4tMXuGC6lGtGgf-erBbhmpPkdv9lCmuQJxSeQ5sUKT3ytKtR7ey6KmGI9vgsMgVHNJvoPMv-7ZOIbAVhSQ
2022-07-18T15:25:36.465  WARN --- [  asgi_gw_15] l.services.s3.s3_utils     : Signatures do not match, but not raising an error, as S3_SKIP_SIGNATURE_VALIDATION=1
2022-07-18T15:25:36.465 DEBUG --- [  asgi_gw_15] l.services.s3.s3_utils     : Valid presign url.
2022-07-18T15:26:18.679 DEBUG --- [ Thread-2337] l.s.a.lambda_executors     : Checking if there are idle containers ...
2022-07-18T15:26:23.348  INFO --- [  Thread-162] l.utils.websockets         : Connection from WebSocket closed: <websockets.legacy.server.WebSocketServerProtocol object at 0xffff08221d50>
2022-07-18T15:26:23.354 DEBUG --- [ Thread-2486] l.s.apigateway.authorizers : Processing API V2 invocation
2022-07-18T15:26:23.360 DEBUG --- [ Thread-2486] l.s.apigateway.invocations : Invoking Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-663ab76 for WebSocket integration of API ID 70724b90
2022-07-18T15:26:23.361  INFO --- [ Thread-2486] l.s.a.lambda_executors     : Running lambda: arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-663ab76
2022-07-18T15:26:23.361 DEBUG --- [ Thread-2486] l.s.a.lambda_launcher      : Executing docker-reuse Lambda container invocation
2022-07-18T15:26:23.362 DEBUG --- [ Thread-2486] l.s.a.lambda_executors     : Priming docker container with runtime "python3.7" and arn "arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-663ab76".
2022-07-18T15:26:23.380 DEBUG --- [ Thread-2486] l.s.a.lambda_executors     : Priming Docker container (status "1"): localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-663ab76
2022-07-18T15:26:23.393 DEBUG --- [ Thread-2486] l.u.c.container_client     : Getting networks for container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-663ab76
2022-07-18T15:26:23.434 DEBUG --- [ Thread-2486] l.u.c.container_client     : Getting the entrypoint for image: localstack/lambda:python3.7
2022-07-18T15:26:23.438 DEBUG --- [ Thread-2486] l.s.a.lambda_executors     : Using entrypoint "/var/rapid/init --bootstrap /var/runtime/bootstrap" for container "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-663ab76" on network "devnet".
2022-07-18T15:26:23.461 DEBUG --- [ Thread-2486] l.s.a.lambda_executors     : Calling http://169.254.170.9:9001 to run invocation in docker-reuse Lambda container
2022-07-18T15:26:23.544  INFO --- [  asgi_gw_20] localstack.request.aws     : AWS dynamodb.DeleteItem => 200
2022-07-18T15:26:23.568 DEBUG --- [ Thread-2486] l.s.a.lambda_executors     : Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-663ab76 result / log output:
{"statusCode": 200, "body": "$disconnect", "headers": {"Sec-WebSocket-Protocol": "auth"}}
>{"level":"INFO","location":"lambda_handler:22","message":{"version":"1.0","resource":"/","httpMethod":null,"path":"/?p_id=640","body":"{\"action\": \"$disconnect\"}","headers":{"host":"host.docker.internal:4510","upgrade":"websocket","connection":"Upgrade","sec-websocket-key":"8sI/E9bqDEDqY5uYZWNAvA==","sec-websocket-version":"13","sec-websocket-extensions":"permessage-deflate; client_max_window_bits","sec-websocket-protocol":"auth, eyJ0eXAiOiJqd3QiLCJhbGciOiJSUzI1NiIsImtpZCI6IkhLTExfaWRvVS1DWWR2ZUVYLUp1cnczUGMycGZ0Mks3NVo5dkIzbk1SLVkifQ.eyJpc3MiOiJodHRwOi8vYXV0aDBfbW9jazozMDAwLyIsInN1YiI6InNhbWxwfFhPQUF6dXJlfHBraW5nQHhvamV0YXZpYXRpb24uY29tIiwiYXVkIjpbInhvYV9kYXRhX3BvcnRhbCIsImh0dHA6Ly9hdXRoMF9tb2NrOjMwMDAvdXNlcmluZm8iXSwiaWF0IjoxNjU4MTU3OTMzLCJleHAiOjE2NTgyNDQzMzMsImF6cCI6IiIsInNjb3BlIjoib3BlbmlkIHByb2ZpbGUgZW1haWwiLCJwZXJtaXNzaW9ucyI6WyJjaGF0LmFkbWluIiwiY2hhdC51c2VyIiwiZnVlbF9wcmljZS51cGRhdGUiLCJyZXBvcnRzLnJ1biJdfQ.bbCgH48rexaL549d0m9TLwIJpqf5m6O4sT5naudd9e_07cbtQFGoSPRlDBVTo0olOTQUBKLewPC87LNdpWLD-93aJLSpKM9Y81gBxdqPfgYtUa2u2pZmUCst_l04wenpGatEtxdEPZFUBJEFFaB-gLcP7Vdz85LxDZD7r1KJ_7daa4TZLD83_aMMEvckBXqL4C36Ryy_aOFspnmbuAe-2KGILqozJ8RlPomOD_4vLRjn_JVH-UAeYPPp_TJT5_jwkmSO4tMXuGC6lGtGgf-erBbhmpPkdv9lCmuQJxSeQ5sUKT3ytKtR7ey6KmGI9vgsMgVHNJvoPMv-7ZOIbAVhSQ","user-agent":"Python/3.9 websockets/10.3"},"multiValueHeaders":{"host":["host.docker.internal:4510"],"upgrade":["websocket"],"connection":["Upgrade"],"sec-websocket-key":["8sI/E9bqDEDqY5uYZWNAvA=="],"sec-websocket-version":["13"],"sec-websocket-extensions":["permessage-deflate; client_max_window_bits"],"sec-websocket-protocol":["auth, eyJ0eXAiOiJqd3QiLCJhbGciOiJSUzI1NiIsImtpZCI6IkhLTExfaWRvVS1DWWR2ZUVYLUp1cnczUGMycGZ0Mks3NVo5dkIzbk1SLVkifQ.eyJpc3MiOiJodHRwOi8vYXV0aDBfbW9jazozMDAwLyIsInN1YiI6InNhbWxwfFhPQUF6dXJlfHBraW5nQHhvamV0YXZpYXRpb24uY29tIiwiYXVkIjpbInhvYV9kYXRhX3BvcnRhbCIsImh0dHA6Ly9hdXRoMF9tb2NrOjMwMDAvdXNlcmluZm8iXSwiaWF0IjoxNjU4MTU3OTMzLCJleHAiOjE2NTgyNDQzMzMsImF6cCI6IiIsInNjb3BlIjoib3BlbmlkIHByb2ZpbGUgZW1ha...
2022-07-18T15:26:23.626  INFO --- [  Thread-162] websockets.server          : connection closed
2022-07-18T15:27:18.682 DEBUG --- [ Thread-2476] l.s.a.lambda_executors     : Checking if there are idle containers ...
2022-07-18T15:28:18.686 DEBUG --- [ Thread-2607] l.s.a.lambda_executors     : Checking if there are idle containers ...

==============
issue - presigned url recieved but lambda never fired | trigger for lambda is onObjectCreated
=================================================

@pinzon
Copy link
Member

pinzon commented Jul 18, 2022

@kingster307 thanks for the logs, I'm working on this right now.

@kingster307
Copy link

Full logs for POST alternative - presigned POST & POST request to upload file

2022-07-18T18:19:27.817  INFO --- [  Thread-152] websockets.server          : connection open
2022-07-18T18:19:27.823 DEBUG --- [ Thread-1266] l.s.apigateway.authorizers : Processing API V2 invocation
2022-07-18T18:19:27.824 DEBUG --- [ Thread-1266] l.s.apigateway.authorizers : Running authorization for request to API Gateway ID b9c03efe - None /?p_id=134
2022-07-18T18:19:28.035 DEBUG --- [  asgi_gw_18] l.s.apigateway.authorizers : Processing API V1 invocation
2022-07-18T18:19:28.036 DEBUG --- [  asgi_gw_18] l.s.apigateway.authorizers : Running authorization for request to API Gateway ID 86e1zpj5yl - GET /fuel_price_upload?job_id=87&action=fuel_price_file_upload&file_name=AVCD+3-22.csv&content_type=csv&company=XOJET+Aviation+LLC&effective_date=2022-03-20&vendor_id=AVCD&use_fos=0&p_id=134
2022-07-18T18:19:28.074 DEBUG --- [ Thread-1266] l.u.c.container_client     : Getting ipv4 address for container localstack-fdp in network devnet.
2022-07-18T18:19:28.102  INFO --- [ Thread-1266] l.u.container_networking   : Determined main container target IP: 169.254.170.4
2022-07-18T18:19:28.102  INFO --- [ Thread-1266] l.s.a.lambda_executors     : Running lambda: arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5
2022-07-18T18:19:28.103 DEBUG --- [ Thread-1266] l.s.a.lambda_launcher      : Executing docker-reuse Lambda container invocation
2022-07-18T18:19:28.103 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Priming docker container with runtime "python3.7" and arn "arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5".
2022-07-18T18:19:28.119 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Priming Docker container (status "0"): localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5
2022-07-18T18:19:28.124 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Creating container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5
2022-07-18T18:19:28.125 DEBUG --- [ Thread-1266] l.s.a.lambda_launcher      : Executing docker reuse container creation hook for function arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5
2022-07-18T18:19:28.947 DEBUG --- [ Thread-1266] l.u.c.container_client     : Getting the entrypoint for image: localstack/lambda:python3.7
2022-07-18T18:19:28.986 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Creating docker-reuse Lambda container localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5 from image localstack/lambda:python3.7
2022-07-18T18:19:28.986 DEBUG --- [ Thread-1266] l.u.c.docker_sdk_client    : Creating container with attributes: {'mount_volumes': None, 'ports': None, 'cap_add': ['NET_ADMIN'], 'cap_drop': None, 'security_opt': None, 'dns': '127.0.0.1', 'additional_flags': None, 'workdir': None, 'command': ['lambda_function.lambda_handler'], 'detach': True, 'entrypoint': '/tmp/40ab178d.sh', 'env_vars': {'AUDIENCE': 'xoa_data_portal', 'ENV': 'ls_local', 'JWKS_URI': 'http://auth0_mock:3000/.well-known/jwks.json', 'POWERTOOLS_SERVICE_NAME': 'apiGwAuthorizerLambda', 'TOKEN_ISSUER': 'http://auth0_mock:3000/', 'AWS_ACCESS_KEY_ID': 'test', 'AWS_SECRET_ACCESS_KEY': 'test', 'AWS_REGION': 'us-west-2', 'LOCALSTACK_HOSTNAME': '169.254.170.4', 'AWS_ENDPOINT_URL': 'http://169.254.170.4:4566', 'EDGE_PORT': '443', '_HANDLER': 'lambda_function.lambda_handler', 'AWS_LAMBDA_FUNCTION_TIMEOUT': '4', 'AWS_LAMBDA_FUNCTION_NAME': 'fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5', 'AWS_LAMBDA_FUNCTION_VERSION': '$LATEST', 'AWS_LAMBDA_FUNCTION_INVOKED_ARN': 'arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5', '_LAMBDA_SERVER_PORT': '5000', 'DOCKER_LAMBDA_STAY_OPEN': '1', 'LOCALSTACK_DEBUG': '1'}, 'image_name': 'localstack/lambda:python3.7', 'interactive': False, 'name': 'localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5', 'network': 'devnet', 'remove': True, 'self': <localstack.utils.container_utils.docker_sdk_client.SdkDockerClient object at 0xffff8c2ea6b0>, 'tty': False, 'user': 'root'}
2022-07-18T18:19:29.032 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Copying "/var/lib/localstack/tmp/lambda-with-layers.7967d810/." to "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5:/var/task".
2022-07-18T18:19:29.032 DEBUG --- [ Thread-1266] l.u.c.docker_sdk_client    : Copying file /var/lib/localstack/tmp/lambda-with-layers.7967d810/. into localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5:/var/task
2022-07-18T18:19:45.171 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Copying "/var/lib/localstack/tmp/40ab178d.sh" to "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5:/tmp/40ab178d.sh".
2022-07-18T18:19:45.171 DEBUG --- [ Thread-1266] l.u.c.docker_sdk_client    : Copying file /var/lib/localstack/tmp/40ab178d.sh into localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5:/tmp/40ab178d.sh
2022-07-18T18:19:45.239 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Starting docker-reuse Lambda container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5
2022-07-18T18:19:45.239 DEBUG --- [ Thread-1266] l.u.c.docker_sdk_client    : Starting container localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5
2022-07-18T18:19:46.132 DEBUG --- [ Thread-1266] l.u.c.container_client     : Getting networks for container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5
2022-07-18T18:19:46.159 DEBUG --- [ Thread-1266] l.u.c.container_client     : Getting the entrypoint for image: localstack/lambda:python3.7
2022-07-18T18:19:46.164 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Using entrypoint "/var/rapid/init --bootstrap /var/runtime/bootstrap" for container "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5" on network "devnet".
2022-07-18T18:19:46.191 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Calling http://169.254.170.5:9001 to run invocation in docker-reuse Lambda container
2022-07-18T18:19:47.288 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5 result / log output:
{"principalId": "samlp|XOAAzure|pking@xojetaviation.com", "policyDocument": {"Version": "2012-10-17", "Statement": [{"Effect": "Allow", "Resource": ["arn:aws:execute-api:us-west-2:000000000000:b9c03efe/None/$default", "arn:aws:execute-api:us-west-2:000000000000:b9c03efe/None/$connect", "arn:aws:execute-api:us-west-2:000000000000:b9c03efe/None/$disconnect", "arn:aws:execute-api:us-west-2:000000000000:b9c03efe/None/ping", "arn:aws:execute-api:us-west-2:000000000000:b9c03efe/None/hello", "arn:aws:execute-api:us-west-2:000000000000:b9c03efe/None/chatMessage"], "Action": ["execute-api:Invoke"]}]}, "context": {"scope": "openid profile email", "permissions": "[\"chat.admin\", \"chat.user\", \"fuel_price.update\", \"reports.run\"]"}}
>{"level":"INFO","location":"lambda_handler:16","message":{"version":"1.0","type":"REQUEST","methodArn":"arn:aws:execute-api:us-west-2:000000000000:b9c03efe/None/$$connect","identitySource":"","authorizationToken":"","resource":"/","path":"/","httpMethod":null,"headers":{"host":"host.docker.internal:4510","upgrade":"websocket","connection":"Upgrade","sec-websocket-key":"a1z8HxrUs8VgaZCfJACkEA==","sec-websocket-version":"13","sec-websocket-extensions":"permessage-deflate; client_max_window_bits","sec-websocket-protocol":"auth, eyJ0eXAiOiJqd3QiLCJhbGciOiJSUzI1NiIsImtpZCI6Ildhb0NVQmV6R2JHanZIZzROQ1l2QmtxNnl1MEFsWktwZ0dqeS1mOTI4bDAifQ.eyJpc3MiOiJodHRwOi8vYXV0aDBfbW9jazozMDAwLyIsInN1YiI6InNhbWxwfFhPQUF6dXJlfHBraW5nQHhvamV0YXZpYXRpb24uY29tIiwiYXVkIjpbInhvYV9kYXRhX3BvcnRhbCIsImh0dHA6Ly9hdXRoMF9tb2NrOjMwMDAvdXNlcmluZm8iXSwiaWF0IjoxNjU4MTY4MzY3LCJleHAiOjE2NTgyNTQ3NjcsImF6cCI6IiIsInNjb3BlIjoib3BlbmlkIHByb2ZpbGUgZW1haWwiLCJwZXJtaXNzaW9ucyI6WyJjaGF0LmFkbWluIiwiY2hhdC51c2VyIiwiZnVlbF9wcmljZS51cGRhdGUiLCJyZXBvcnRzLnJ1biJdfQ.rHyM5J2VrlGXYvPBB5p7WanQzzSfLGARH9FJBvmcM6UwDXz2kmSHUt84uMFasviOnjRFK7NApMvVqsDPwdAkh5ESV7fsUUrrMvAIRrzeruPHGyXyBpPkfTXYKI1r4oy4dBEY1Weeb1wAQ5asxWfpVZ4lEvZpInwq1JfdaN05Eb6sQDATk-z9Ik_95hxwL26VQHUCZf_VywoXlguydgQMiw_0fRdJNFlna21Mci2znyhO3o054sZdENC18IVBTxVFe5TpodkHnZuQf9rxrhsv0MSSoSBNZrfFEuuXa-nbosWOdbFfY9EQs3nvfsxJNbuaSwRRbauFH-pch-iTJLuznQ","user-agent":"Python/3.9 websockets/10.3"},"queryStringParameters":{"p_id":"134"},"pathParameters":{},"stageVariables":null,"requestContext":{"path":"/","accountId":"000000000000","apiId":"b9c03efe","resourcePath":"/","domainPrefix":"host","domainName":"host.docker.internal","resourceId":null,"requestId":"2d94a69c","identity":{"accountId":"000000000000","sourceIp":"","userAgent":"Python/3.9 websockets/10.3"},"stage":null,"httpMethod":null}},"timestamp":"2022-07-18 18:19:46,977+0000","service":"apiGwAuthorizerLambda","cold_start":true,"function_name":"fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5","function_memory_s...
2022-07-18T18:19:47.307  INFO --- [  asgi_gw_18] l.s.a.lambda_executors     : Running lambda: arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5
2022-07-18T18:19:47.307 DEBUG --- [  asgi_gw_18] l.s.a.lambda_launcher      : Executing docker-reuse Lambda container invocation
2022-07-18T18:19:47.307 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Priming docker container with runtime "python3.7" and arn "arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5".
2022-07-18T18:19:47.313 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Priming Docker container (status "1"): localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5
2022-07-18T18:19:47.348 DEBUG --- [  asgi_gw_18] l.u.c.container_client     : Getting networks for container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5
2022-07-18T18:19:47.356 DEBUG --- [   asgi_gw_3] l.services.plugins         : checking service health cloudwatch:4566
2022-07-18T18:19:47.369  INFO --- [ Thread-1266] l.s.apigateway.authorizers : Received authorizer result: {"principalId": "samlp|XOAAzure|pking@xojetaviation.com", "policyDocument": {"Version": "2012-10-17", "Statement": [{"Effect": "Allow", "Resource": ["arn:aws:execute-api:us-west-2:000000000000:b9c03efe/None/$default", "arn:aws:execute-api:us-west-2:000000000000:b9c03efe/None/$connect", "arn:aws:execute-api:us-west-2:000000000000:b9c03efe/None/$disconnect", "arn:aws:execute-api:us-west-2:000000000000:b9c03efe/None/ping", "arn:aws:execute-api:us-west-2:000000000000:b9c03efe/None/hello", "arn:aws:execute-api:us-west-2:000000000000:b9c03efe/None/chatMessage"], "Action": ["execute-api:Invoke"]}]}, "context": {"scope": "openid profile email", "permissions": "[\"chat.admin\", \"chat.user\", \"fuel_price.update\", \"reports.run\"]"}}
2022-07-18T18:19:47.370 DEBUG --- [ Thread-1266] l.s.apigateway.invocations : Invoking Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-538a257 for WebSocket integration of API ID b9c03efe
2022-07-18T18:19:47.371  INFO --- [ Thread-1266] l.s.a.lambda_executors     : Running lambda: arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-538a257
2022-07-18T18:19:47.371 DEBUG --- [ Thread-1266] l.s.a.lambda_launcher      : Executing docker-reuse Lambda container invocation
2022-07-18T18:19:47.371 DEBUG --- [  asgi_gw_18] l.u.c.container_client     : Getting the entrypoint for image: localstack/lambda:python3.7
2022-07-18T18:19:47.375 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Using entrypoint "/var/rapid/init --bootstrap /var/runtime/bootstrap" for container "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5" on network "devnet".
2022-07-18T18:19:47.377 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Priming docker container with runtime "python3.7" and arn "arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-538a257".
2022-07-18T18:19:47.382 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Priming Docker container (status "0"): localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257
2022-07-18T18:19:47.387 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Creating container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257
2022-07-18T18:19:47.387 DEBUG --- [ Thread-1266] l.s.a.lambda_launcher      : Executing docker reuse container creation hook for function arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-538a257
2022-07-18T18:19:47.389 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Calling http://169.254.170.5:9001 to run invocation in docker-reuse Lambda container
2022-07-18T18:19:47.438 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5 result / log output:
{"principalId": "samlp|XOAAzure|pking@xojetaviation.com", "policyDocument": {"Version": "2012-10-17", "Statement": [{"Effect": "Allow", "Resource": ["arn:aws:execute-api:us-west-2:000000000000/86e1zpj5yl/GET/tasks/", "arn:aws:execute-api:us-west-2:000000000000/86e1zpj5yl/GET/download/", "arn:aws:execute-api:us-west-2:000000000000/86e1zpj5yl/GET/etl_status/", "arn:aws:execute-api:us-west-2:000000000000/86e1zpj5yl/GET/reports/", "arn:aws:execute-api:us-west-2:000000000000/86e1zpj5yl/GET/fuel_price_upload/", "arn:aws:execute-api:us-west-2:000000000000/86e1zpj5yl/GET/ops_data_upload/", "arn:aws:execute-api:us-west-2:000000000000/86e1zpj5yl/*/fuel_pricing/"], "Action": ["execute-api:Invoke"]}]}, "context": {"scope": "openid profile email", "permissions": "[\"chat.admin\", \"chat.user\", \"fuel_price.update\", \"reports.run\"]"}}
>{"level":"INFO","location":"lambda_handler:16","message":{"type":"TOKEN","authorizationToken":"Bearer eyJ0eXAiOiJqd3QiLCJhbGciOiJSUzI1NiIsImtpZCI6Ildhb0NVQmV6R2JHanZIZzROQ1l2QmtxNnl1MEFsWktwZ0dqeS1mOTI4bDAifQ.eyJpc3MiOiJodHRwOi8vYXV0aDBfbW9jazozMDAwLyIsInN1YiI6InNhbWxwfFhPQUF6dXJlfHBraW5nQHhvamV0YXZpYXRpb24uY29tIiwiYXVkIjpbInhvYV9kYXRhX3BvcnRhbCIsImh0dHA6Ly9hdXRoMF9tb2NrOjMwMDAvdXNlcmluZm8iXSwiaWF0IjoxNjU4MTY4MzY3LCJleHAiOjE2NTgyNTQ3NjcsImF6cCI6IiIsInNjb3BlIjoib3BlbmlkIHByb2ZpbGUgZW1haWwiLCJwZXJtaXNzaW9ucyI6WyJjaGF0LmFkbWluIiwiY2hhdC51c2VyIiwiZnVlbF9wcmljZS51cGRhdGUiLCJyZXBvcnRzLnJ1biJdfQ.rHyM5J2VrlGXYvPBB5p7WanQzzSfLGARH9FJBvmcM6UwDXz2kmSHUt84uMFasviOnjRFK7NApMvVqsDPwdAkh5ESV7fsUUrrMvAIRrzeruPHGyXyBpPkfTXYKI1r4oy4dBEY1Weeb1wAQ5asxWfpVZ4lEvZpInwq1JfdaN05Eb6sQDATk-z9Ik_95hxwL26VQHUCZf_VywoXlguydgQMiw_0fRdJNFlna21Mci2znyhO3o054sZdENC18IVBTxVFe5TpodkHnZuQf9rxrhsv0MSSoSBNZrfFEuuXa-nbosWOdbFfY9EQs3nvfsxJNbuaSwRRbauFH-pch-iTJLuznQ","methodArn":"arn:aws:execute-api:us-west-2:000000000000:86e1zpj5yl/api/GET/fuel_price_upload"},"timestamp":"2022-07-18 18:19:47,394+0000","service":"apiGwAuthorizerLambda","cold_start":false,"function_name":"fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5","function_memory_size":"1536","function_arn":"arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwAuthorizerLambda-ls_local-2bfa4e5","function_request_id":"496866d5-661f-17ee-ecb1-f0d5f532de7c","xray_trace_id":"62552376119407"}
2022-07-18T18:19:47.446 DEBUG --- [ Thread-1266] l.u.c.container_client     : Getting the entrypoint for image: localstack/lambda:python3.7
2022-07-18T18:19:47.470 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Creating docker-reuse Lambda container localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257 from image localstack/lambda:python3.7
2022-07-18T18:19:47.470 DEBUG --- [ Thread-1266] l.u.c.docker_sdk_client    : Creating container with attributes: {'mount_volumes': None, 'ports': None, 'cap_add': ['NET_ADMIN'], 'cap_drop': None, 'security_opt': None, 'dns': '127.0.0.1', 'additional_flags': None, 'workdir': None, 'command': ['lambda_function.lambda_handler'], 'detach': True, 'entrypoint': '/tmp/f7b90294.sh', 'env_vars': {'AUDIENCE': 'xoa_data_portal', 'CHAT_TABLE_NAME': 'fos-data-portal-wsChatDdbTable-ls_local-b62dff7', 'ENV': 'ls_local', 'JWKS_URI': 'http://auth0_mock:3000/.well-known/jwks.json', 'POWERTOOLS_SERVICE_NAME': 'wsChatLambda', 'TOKEN_ISSUER': 'http://auth0_mock:3000/', 'AWS_ACCESS_KEY_ID': 'test', 'AWS_SECRET_ACCESS_KEY': 'test', 'AWS_REGION': 'us-west-2', 'LOCALSTACK_HOSTNAME': '169.254.170.4', 'AWS_ENDPOINT_URL': 'http://169.254.170.4:4566', 'EDGE_PORT': '443', '_HANDLER': 'lambda_function.lambda_handler', 'AWS_LAMBDA_FUNCTION_TIMEOUT': '5', 'AWS_LAMBDA_FUNCTION_NAME': 'fos-data-portal-wsChatLambda-ls_local-538a257', 'AWS_LAMBDA_FUNCTION_VERSION': '$LATEST', 'AWS_LAMBDA_FUNCTION_INVOKED_ARN': 'arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-538a257', '_LAMBDA_SERVER_PORT': '5002', 'DOCKER_LAMBDA_STAY_OPEN': '1', 'LOCALSTACK_DEBUG': '1'}, 'image_name': 'localstack/lambda:python3.7', 'interactive': False, 'name': 'localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257', 'network': 'devnet', 'remove': True, 'self': <localstack.utils.container_utils.docker_sdk_client.SdkDockerClient object at 0xffff8c2ea6b0>, 'tty': False, 'user': 'root'}
2022-07-18T18:19:47.511 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Copying "/var/lib/localstack/tmp/lambda-with-layers.301f7c4c/." to "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257:/var/task".
2022-07-18T18:19:47.511 DEBUG --- [ Thread-1266] l.u.c.docker_sdk_client    : Copying file /var/lib/localstack/tmp/lambda-with-layers.301f7c4c/. into localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257:/var/task
2022-07-18T18:19:47.534  INFO --- [  asgi_gw_18] l.s.apigateway.integration : Method request body before transformations:
2022-07-18T18:19:47.534 DEBUG --- [  asgi_gw_18] l.s.awslambda.lambda_api   : Running Lambda function arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec from API Gateway invocation: GET /fuel_price_upload
2022-07-18T18:19:47.534  INFO --- [  asgi_gw_18] l.s.a.lambda_executors     : Running lambda: arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec
2022-07-18T18:19:47.534 DEBUG --- [  asgi_gw_18] l.s.a.lambda_launcher      : Executing docker-reuse Lambda container invocation
2022-07-18T18:20:04.076 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Copying "/var/lib/localstack/tmp/f7b90294.sh" to "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257:/tmp/f7b90294.sh".
2022-07-18T18:20:04.076 DEBUG --- [ Thread-1266] l.u.c.docker_sdk_client    : Copying file /var/lib/localstack/tmp/f7b90294.sh into localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257:/tmp/f7b90294.sh
2022-07-18T18:20:04.141 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Starting docker-reuse Lambda container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257
2022-07-18T18:20:04.141 DEBUG --- [ Thread-1266] l.u.c.docker_sdk_client    : Starting container localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257
2022-07-18T18:20:04.973 DEBUG --- [ Thread-1266] l.u.c.container_client     : Getting networks for container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257
2022-07-18T18:20:04.997 DEBUG --- [ Thread-1266] l.u.c.container_client     : Getting the entrypoint for image: localstack/lambda:python3.7
2022-07-18T18:20:05.002 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Using entrypoint "/var/rapid/init --bootstrap /var/runtime/bootstrap" for container "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257" on network "devnet".
2022-07-18T18:20:05.003 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Priming docker container with runtime "python3.7" and arn "arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec".
2022-07-18T18:20:05.009 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Priming Docker container (status "0"): localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec
2022-07-18T18:20:05.013 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Creating container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec
2022-07-18T18:20:05.013 DEBUG --- [  asgi_gw_18] l.s.a.lambda_launcher      : Executing docker reuse container creation hook for function arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec
2022-07-18T18:20:05.030 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Calling http://169.254.170.6:9001 to run invocation in docker-reuse Lambda container
2022-07-18T18:20:05.083 DEBUG --- [  asgi_gw_18] l.u.c.container_client     : Getting the entrypoint for image: localstack/lambda:python3.7
2022-07-18T18:20:05.099 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Creating docker-reuse Lambda container localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec from image localstack/lambda:python3.7
2022-07-18T18:20:05.099 DEBUG --- [  asgi_gw_18] l.u.c.docker_sdk_client    : Creating container with attributes: {'mount_volumes': None, 'ports': None, 'cap_add': ['NET_ADMIN'], 'cap_drop': None, 'security_opt': None, 'dns': '127.0.0.1', 'additional_flags': None, 'workdir': None, 'command': ['lambda_function.lambda_handler'], 'detach': True, 'entrypoint': '/tmp/fb6b1262.sh', 'env_vars': {'ENV': 'ls_local', 'FUEL_PRICE_UPLOAD_PREFIX': 'fuel_pricing_upload/', 'POWERTOOLS_SERVICE_NAME': 'apiGwFuelUploadLambda', 'REPORT_BUCKET': 'self-serve-portal-20220718180858858800000001', 'TASK_TABLE_NAME': 'fos-data-portal-wsTaskStatusDdbTable-ls_local-b9f0d33', 'AWS_ACCESS_KEY_ID': 'test', 'AWS_SECRET_ACCESS_KEY': 'test', 'AWS_REGION': 'us-west-2', 'LOCALSTACK_HOSTNAME': '169.254.170.4', 'AWS_ENDPOINT_URL': 'http://169.254.170.4:4566', 'EDGE_PORT': '443', '_HANDLER': 'lambda_function.lambda_handler', 'AWS_LAMBDA_FUNCTION_TIMEOUT': '29', 'AWS_LAMBDA_FUNCTION_NAME': 'fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec', 'AWS_LAMBDA_FUNCTION_VERSION': '$LATEST', 'AWS_LAMBDA_FUNCTION_INVOKED_ARN': 'arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec', 'AWS_LAMBDA_COGNITO_IDENTITY': '{"cognitoIdentityId": null, "cognitoIdentityPoolId": null}', '_LAMBDA_SERVER_PORT': '5003', 'DOCKER_LAMBDA_STAY_OPEN': '1', 'LOCALSTACK_DEBUG': '1'}, 'image_name': 'localstack/lambda:python3.7', 'interactive': False, 'name': 'localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec', 'network': 'devnet', 'remove': True, 'self': <localstack.utils.container_utils.docker_sdk_client.SdkDockerClient object at 0xffff8c2ea6b0>, 'tty': False, 'user': 'root'}
2022-07-18T18:20:05.133 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Copying "/var/lib/localstack/tmp/lambda-with-layers.7b1fd704/." to "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec:/var/task".
2022-07-18T18:20:05.133 DEBUG --- [  asgi_gw_18] l.u.c.docker_sdk_client    : Copying file /var/lib/localstack/tmp/lambda-with-layers.7b1fd704/. into localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec:/var/task
2022-07-18T18:20:07.429  INFO --- [  asgi_gw_16] localstack.request.aws     : AWS dynamodb.PutItem => 200
2022-07-18T18:20:07.522 DEBUG --- [ Thread-1266] l.s.a.lambda_executors     : Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-538a257 result / log output:
{"statusCode": 200, "body": "$connect", "headers": {"Sec-WebSocket-Protocol": "auth"}}
>{"level":"INFO","location":"lambda_handler:22","message":{"version":"1.0","resource":"/","httpMethod":null,"path":"/?p_id=134","body":"{\"action\": \"$connect\"}","headers":{"host":"host.docker.internal:4510","upgrade":"websocket","connection":"Upgrade","sec-websocket-key":"a1z8HxrUs8VgaZCfJACkEA==","sec-websocket-version":"13","sec-websocket-extensions":"permessage-deflate; client_max_window_bits","sec-websocket-protocol":"auth, eyJ0eXAiOiJqd3QiLCJhbGciOiJSUzI1NiIsImtpZCI6Ildhb0NVQmV6R2JHanZIZzROQ1l2QmtxNnl1MEFsWktwZ0dqeS1mOTI4bDAifQ.eyJpc3MiOiJodHRwOi8vYXV0aDBfbW9jazozMDAwLyIsInN1YiI6InNhbWxwfFhPQUF6dXJlfHBraW5nQHhvamV0YXZpYXRpb24uY29tIiwiYXVkIjpbInhvYV9kYXRhX3BvcnRhbCIsImh0dHA6Ly9hdXRoMF9tb2NrOjMwMDAvdXNlcmluZm8iXSwiaWF0IjoxNjU4MTY4MzY3LCJleHAiOjE2NTgyNTQ3NjcsImF6cCI6IiIsInNjb3BlIjoib3BlbmlkIHByb2ZpbGUgZW1haWwiLCJwZXJtaXNzaW9ucyI6WyJjaGF0LmFkbWluIiwiY2hhdC51c2VyIiwiZnVlbF9wcmljZS51cGRhdGUiLCJyZXBvcnRzLnJ1biJdfQ.rHyM5J2VrlGXYvPBB5p7WanQzzSfLGARH9FJBvmcM6UwDXz2kmSHUt84uMFasviOnjRFK7NApMvVqsDPwdAkh5ESV7fsUUrrMvAIRrzeruPHGyXyBpPkfTXYKI1r4oy4dBEY1Weeb1wAQ5asxWfpVZ4lEvZpInwq1JfdaN05Eb6sQDATk-z9Ik_95hxwL26VQHUCZf_VywoXlguydgQMiw_0fRdJNFlna21Mci2znyhO3o054sZdENC18IVBTxVFe5TpodkHnZuQf9rxrhsv0MSSoSBNZrfFEuuXa-nbosWOdbFfY9EQs3nvfsxJNbuaSwRRbauFH-pch-iTJLuznQ","user-agent":"Python/3.9 websockets/10.3"},"multiValueHeaders":{"host":["host.docker.internal:4510"],"upgrade":["websocket"],"connection":["Upgrade"],"sec-websocket-key":["a1z8HxrUs8VgaZCfJACkEA=="],"sec-websocket-version":["13"],"sec-websocket-extensions":["permessage-deflate; client_max_window_bits"],"sec-websocket-protocol":["auth, eyJ0eXAiOiJqd3QiLCJhbGciOiJSUzI1NiIsImtpZCI6Ildhb0NVQmV6R2JHanZIZzROQ1l2QmtxNnl1MEFsWktwZ0dqeS1mOTI4bDAifQ.eyJpc3MiOiJodHRwOi8vYXV0aDBfbW9jazozMDAwLyIsInN1YiI6InNhbWxwfFhPQUF6dXJlfHBraW5nQHhvamV0YXZpYXRpb24uY29tIiwiYXVkIjpbInhvYV9kYXRhX3BvcnRhbCIsImh0dHA6Ly9hdXRoMF9tb2NrOjMwMDAvdXNlcmluZm8iXSwiaWF0IjoxNjU4MTY4MzY3LCJleHAiOjE2NTgyNTQ3NjcsImF6cCI6IiIsInNjb3BlIjoib3BlbmlkIHByb2ZpbGUgZW1haWwi...
2022-07-18T18:20:08.470 DEBUG --- [ Thread-1221] l.s.a.lambda_executors     : Checking if there are idle containers ...
2022-07-18T18:20:17.858  INFO --- [  Thread-152] l.utils.websockets         : Connection from WebSocket closed: <websockets.legacy.server.WebSocketServerProtocol object at 0xfffee4bdedd0>
2022-07-18T18:20:17.861 DEBUG --- [ Thread-1409] l.s.apigateway.authorizers : Processing API V2 invocation
2022-07-18T18:20:17.862 DEBUG --- [ Thread-1409] l.s.apigateway.invocations : Invoking Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-538a257 for WebSocket integration of API ID b9c03efe
2022-07-18T18:20:17.863  INFO --- [ Thread-1409] l.s.a.lambda_executors     : Running lambda: arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-538a257
2022-07-18T18:20:17.863 DEBUG --- [ Thread-1409] l.s.a.lambda_launcher      : Executing docker-reuse Lambda container invocation
2022-07-18T18:20:21.606 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Copying "/var/lib/localstack/tmp/fb6b1262.sh" to "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec:/tmp/fb6b1262.sh".
2022-07-18T18:20:21.606 DEBUG --- [  asgi_gw_18] l.u.c.docker_sdk_client    : Copying file /var/lib/localstack/tmp/fb6b1262.sh into localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec:/tmp/fb6b1262.sh
2022-07-18T18:20:21.688 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Starting docker-reuse Lambda container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec
2022-07-18T18:20:21.688 DEBUG --- [  asgi_gw_18] l.u.c.docker_sdk_client    : Starting container localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec
2022-07-18T18:20:22.520 DEBUG --- [  asgi_gw_18] l.u.c.container_client     : Getting networks for container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec
2022-07-18T18:20:22.547 DEBUG --- [  asgi_gw_18] l.u.c.container_client     : Getting the entrypoint for image: localstack/lambda:python3.7
2022-07-18T18:20:22.554 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Using entrypoint "/var/rapid/init --bootstrap /var/runtime/bootstrap" for container "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec" on network "devnet".
2022-07-18T18:20:22.555 DEBUG --- [ Thread-1409] l.s.a.lambda_executors     : Priming docker container with runtime "python3.7" and arn "arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-538a257".
2022-07-18T18:20:22.575 DEBUG --- [ Thread-1409] l.s.a.lambda_executors     : Priming Docker container (status "1"): localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257
2022-07-18T18:20:22.585 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Calling http://169.254.170.7:9001 to run invocation in docker-reuse Lambda container
2022-07-18T18:20:22.617 DEBUG --- [ Thread-1409] l.u.c.container_client     : Getting networks for container: localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257
2022-07-18T18:20:22.643 DEBUG --- [ Thread-1409] l.u.c.container_client     : Getting the entrypoint for image: localstack/lambda:python3.7
2022-07-18T18:20:22.649 DEBUG --- [ Thread-1409] l.s.a.lambda_executors     : Using entrypoint "/var/rapid/init --bootstrap /var/runtime/bootstrap" for container "localstack-fdp_lambda_arn_aws_lambda_us-west-2_000000000000_function_fos-data-portal-wsChatLambda-ls_local-538a257" on network "devnet".
2022-07-18T18:20:22.670 DEBUG --- [ Thread-1409] l.s.a.lambda_executors     : Calling http://169.254.170.6:9001 to run invocation in docker-reuse Lambda container
2022-07-18T18:20:22.790  INFO --- [   asgi_gw_2] localstack.request.aws     : AWS dynamodb.DeleteItem => 200
2022-07-18T18:20:22.821 DEBUG --- [ Thread-1409] l.s.a.lambda_executors     : Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-wsChatLambda-ls_local-538a257 result / log output:
{"statusCode": 200, "body": "$disconnect", "headers": {"Sec-WebSocket-Protocol": "auth"}}
>{"level":"INFO","location":"lambda_handler:22","message":{"version":"1.0","resource":"/","httpMethod":null,"path":"/?p_id=134","body":"{\"action\": \"$disconnect\"}","headers":{"host":"host.docker.internal:4510","upgrade":"websocket","connection":"Upgrade","sec-websocket-key":"a1z8HxrUs8VgaZCfJACkEA==","sec-websocket-version":"13","sec-websocket-extensions":"permessage-deflate; client_max_window_bits","sec-websocket-protocol":"auth, eyJ0eXAiOiJqd3QiLCJhbGciOiJSUzI1NiIsImtpZCI6Ildhb0NVQmV6R2JHanZIZzROQ1l2QmtxNnl1MEFsWktwZ0dqeS1mOTI4bDAifQ.eyJpc3MiOiJodHRwOi8vYXV0aDBfbW9jazozMDAwLyIsInN1YiI6InNhbWxwfFhPQUF6dXJlfHBraW5nQHhvamV0YXZpYXRpb24uY29tIiwiYXVkIjpbInhvYV9kYXRhX3BvcnRhbCIsImh0dHA6Ly9hdXRoMF9tb2NrOjMwMDAvdXNlcmluZm8iXSwiaWF0IjoxNjU4MTY4MzY3LCJleHAiOjE2NTgyNTQ3NjcsImF6cCI6IiIsInNjb3BlIjoib3BlbmlkIHByb2ZpbGUgZW1haWwiLCJwZXJtaXNzaW9ucyI6WyJjaGF0LmFkbWluIiwiY2hhdC51c2VyIiwiZnVlbF9wcmljZS51cGRhdGUiLCJyZXBvcnRzLnJ1biJdfQ.rHyM5J2VrlGXYvPBB5p7WanQzzSfLGARH9FJBvmcM6UwDXz2kmSHUt84uMFasviOnjRFK7NApMvVqsDPwdAkh5ESV7fsUUrrMvAIRrzeruPHGyXyBpPkfTXYKI1r4oy4dBEY1Weeb1wAQ5asxWfpVZ4lEvZpInwq1JfdaN05Eb6sQDATk-z9Ik_95hxwL26VQHUCZf_VywoXlguydgQMiw_0fRdJNFlna21Mci2znyhO3o054sZdENC18IVBTxVFe5TpodkHnZuQf9rxrhsv0MSSoSBNZrfFEuuXa-nbosWOdbFfY9EQs3nvfsxJNbuaSwRRbauFH-pch-iTJLuznQ","user-agent":"Python/3.9 websockets/10.3"},"multiValueHeaders":{"host":["host.docker.internal:4510"],"upgrade":["websocket"],"connection":["Upgrade"],"sec-websocket-key":["a1z8HxrUs8VgaZCfJACkEA=="],"sec-websocket-version":["13"],"sec-websocket-extensions":["permessage-deflate; client_max_window_bits"],"sec-websocket-protocol":["auth, eyJ0eXAiOiJqd3QiLCJhbGciOiJSUzI1NiIsImtpZCI6Ildhb0NVQmV6R2JHanZIZzROQ1l2QmtxNnl1MEFsWktwZ0dqeS1mOTI4bDAifQ.eyJpc3MiOiJodHRwOi8vYXV0aDBfbW9jazozMDAwLyIsInN1YiI6InNhbWxwfFhPQUF6dXJlfHBraW5nQHhvamV0YXZpYXRpb24uY29tIiwiYXVkIjpbInhvYV9kYXRhX3BvcnRhbCIsImh0dHA6Ly9hdXRoMF9tb2NrOjMwMDAvdXNlcmluZm8iXSwiaWF0IjoxNjU4MTY4MzY3LCJleHAiOjE2NTgyNTQ3NjcsImF6cCI6IiIsInNjb3BlIjoib3BlbmlkIHByb2ZpbGUgZW1ha...
2022-07-18T18:20:22.886  INFO --- [  Thread-152] websockets.server          : connection closed
2022-07-18T18:20:24.368 DEBUG --- [  asgi_gw_18] l.s.a.lambda_executors     : Lambda arn:aws:lambda:us-west-2:000000000000:function:fos-data-portal-apiGwFuelUploadLambda-ls_local-1615cec result / log output:
{"statusCode": 200, "headers": {"Access-Control-Allow-Origin": "*", "Access-Control-Allow-Credentials": "true", "Access-Control-Allow-Headers": "Content-Type,X-Amz-Date,Authorization,X-Api-Key,X-Amz-Security-Token"}, "body": "{\"status\": true, \"message\": null, \"data\": {\"url\": \"http://169.254.170.4:4566/self-serve-portal-20220718180858858800000001\", \"fields\": {\"content-type\": \"csv\", \"x-amz-meta-principal_id\": \"134\", \"x-amz-meta-job_id\": \"87\", \"x-amz-meta-action\": \"fuel_price_file_upload\", \"x-amz-meta-filename\": \"AVCD 3-22.csv\", \"x-amz-meta-effective_date\": \"2022-03-20\", \"x-amz-meta-use_fos\": \"0\", \"x-amz-meta-company\": \"XOJET Aviation LLC\", \"x-amz-meta-vendor_id\": \"AVCD\", \"key\": \"fuel_pricing_upload/1649276b-407d-47a8-a4dd-c2db6a63d4d1\", \"AWSAccessKeyId\": \"test\", \"policy\": \"eyJleHBpcmF0aW9uIjogIjIwMjItMDctMThUMTk6MjA6MjRaIiwgImNvbmRpdGlvbnMiOiBbWyJlcSIsICIka2V5IiwgImZ1ZWxfcHJpY2luZ191cGxvYWQvMTY0OTI3NmItNDA3ZC00N2E4LWE0ZGQtYzJkYjZhNjNkNGQxIl0sIFsiY29udGVudC1sZW5ndGgtcmFuZ2UiLCAxLCAxMDAwMDAwMDAwXSwgWyJlcSIsICIkY29udGVudC10eXBlIiwgImNzdiJdLCBbImVxIiwgIiR4LWFtei1tZXRhLXByaW5jaXBhbF9pZCIsICIxMzQiXSwgWyJlcSIsICIkeC1hbXotbWV0YS1qb2JfaWQiLCAiODciXSwgWyJlcSIsICIkeC1hbXotbWV0YS1hY3Rpb24iLCAiZnVlbF9wcmljZV9maWxlX3VwbG9hZCJdLCBbImVxIiwgIiR4LWFtei1tZXRhLWZpbGVuYW1lIiwgIkFWQ0QgMy0yMi5jc3YiXSwgWyJlcSIsICIkeC1hbXotbWV0YS1lZmZlY3RpdmVfZGF0ZSIsICIyMDIyLTAzLTIwIl0sIFsiZXEiLCAiJHgtYW16LW1ldGEtdXNlX2ZvcyIsICIwIl0sIFsiZXEiLCAiJHgtYW16LW1ldGEtY29tcGFueSIsICJYT0pFVCBBdmlhdGlvbiBMTEMiXSwgWyJlcSIsICIkeC1hbXotbWV0YS12ZW5kb3JfaWQiLCAiQVZDRCJdLCB7ImJ1Y2tldCI6ICJzZWxmLXNlcnZlLXBvcnRhbC0yMDIyMDcxODE4MDg1ODg1ODgwMDAwMDAwMSJ9LCB7ImtleSI6ICJmdWVsX3ByaWNpbmdfdXBsb2FkLzE2NDkyNzZiLTQwN2QtNDdhOC1hNGRkLWMyZGI2YTYzZDRkMSJ9XX0=\", \"signature\": \"Hg4EugAWzTAsDheCL5kl006aFuo=\"}}}"}
>{"level":"INFO","location":"lambda_handler:17","message":{"path":"/fuel_price_upload","headers":{"Host":"86e1zpj5yl.execute-api.localhost.localstack.cloud:4566","User-Agent":"python-requests/2.27.1","accept-encoding":"gzip, deflate","accept":"*/*","Connection":"keep-alive","Authorization":"","x-localstack-tgt-api":"apigateway","x-localstack-request-url":"http://86e1zpj5yl.execute-api.localhost.localstack.cloud:4566/api/fuel_price_upload","X-Forwarded-For":"169.254.170.1, 86e1zpj5yl.execute-api.localhost.localstack.cloud:4566, 169.254.170.1, 86e1zpj5yl.execute-api.localhost.localstack.cloud:4566","x-localstack-edge":"http://86e1zpj5yl.execute-api.localhost.localstack.cloud:4566"},"multiValueHeaders":{"Host":["86e1zpj5yl.execute-api.localhost.localstack.cloud:4566"],"User-Agent":["python-requests/2.27.1"],"accept-encoding":["gzip, deflate"],"accept":["*/*"],"Connection":["keep-alive"],"Authorization":[""],"x-localstack-tgt-api":["apigateway"],"x-localstack-request-url":["http://86e1zpj5yl.execute-api.localhost.localstack.cloud:4566/api/fuel_price_upload"],"X-Forwarded-For":["169.254.170.1, 86e1zpj5yl.execute-api.localhost.localstack.cloud:4566, 169.254.170.1, 86e1zpj5yl.execute-api.localhost.localstack.cloud:4566"],"x-localstack-edge":["http://86e1zpj5yl.execute-api.localhost.localstack.cloud:4566"]},"body":"","isBase64Encoded":false,"httpMethod":"GET","queryStringParameters":{"job_id":"87","action":"fuel_price_file_upload","file_name":"AVCD 3-22.csv","content_type":"csv","company":"XOJET Aviation LLC","effective_date":"2022-03-20","vendor_id":"AVCD","use_fos":"0","p_id":"134"},"multiValueQueryStringParameters":{"job_id":["87"],"action":["fuel_price_file_upload"],"file_name":["AVCD 3-22.csv"],"content_type":["csv"],"company":["XOJET Aviation LLC"],"effective_date":["2022-03-20"],"vendor_id":["AVCD"],"use_fos":["0"],"p_id":["134"]},"pathParameters":{},"resource":"/fuel_price_upload","requestContext":{"accountId":"000000000000","apiId":"86e1zpj5yl","resourcePath":"/fuel...
2022-07-18T18:20:24.385  INFO --- [  asgi_gw_18] localstack.request.http    : GET /api/fuel_price_upload => 200
2022-07-18T18:20:25.762 ERROR --- [   asgi_gw_0] l.aws.handlers.logging     : exception during call chain
Traceback (most recent call last):
  File "/opt/code/localstack/localstack/aws/protocol/parser.py", line 586, in parse
    operation, uri_params = self._operation_router.match(request)
  File "/opt/code/localstack/localstack/aws/protocol/op_router.py", line 287, in match
    rule, args = matcher.match(get_raw_path(request), method=method, return_rule=True)
  File "/opt/code/localstack/.venv/lib/python3.10/site-packages/werkzeug/routing.py", line 2047, in match
    raise NotFound()
werkzeug.exceptions.NotFound: 404 Not Found: The requested URL was not found on the server. If you entered the URL manually please check your spelling and try again.

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/opt/code/localstack/localstack/aws/chain.py", line 57, in handle
    handler(self, self.context, response)
  File "/opt/code/localstack/localstack/aws/handlers/service.py", line 62, in __call__
    return self.parse_and_enrich(context)
  File "/opt/code/localstack/localstack/aws/handlers/service.py", line 75, in parse_and_enrich
    operation, instance = parser.parse(context.request)
  File "/opt/code/localstack/localstack/aws/protocol/parser.py", line 174, in wrapper
    return func(*args, **kwargs)
  File "/opt/code/localstack/localstack/aws/protocol/parser.py", line 588, in parse
    raise OperationNotFoundParserError(
localstack.aws.protocol.parser.OperationNotFoundParserError: Unable to find operation for request to service apigateway: POST /self-serve-portal-20220718180858858800000001
2022-07-18T18:20:25.771  INFO --- [   asgi_gw_0] localstack.request.http    : POST /self-serve-portal-20220718180858858800000001 => 500
2022-07-18T18:21:08.477 DEBUG --- [ Thread-1387] l.s.a.lambda_executors     : Checking if there are idle containers ...

@pinzon
Copy link
Member

pinzon commented Jul 18, 2022

hi again @kingster307 I tested again this problem but everything seems fine for both PUT and POST requests, and both trigger the lambda function. Could you provide exactly how are you setting your lambda to be triggered by the s3 upload?

By the way I'm attaching the scripts for how I'm testing this feature
reproducers.zip

@kingster307
Copy link

kingster307 commented Jul 18, 2022

@pinzon .... same as @paulrobello we are working on this project together. All our iac is built within Pulumi. I believe this could possible be a localstack x Pulumi integration issue

Pulumi typescript - IAC:

defining s3 env vars

export const fuelPriceUploadPrefix = normalizeS3Prefix('fuel_pricing_upload/');

Creating lambda function

export const fuelUploadLambda = new aws.lambda.Function(
  mkItemName('fuelUploadLambda'),
  {
    code: buildAssetArchive('../../fuel_price_upload_lambda', false, false, /\.py$/, new RegExp(DefaultCustomBuildResourceHashOptions.excludePattern || '')),
    role: fuelUploadLambdaRole.arn,
    handler: 'lambda_function.lambda_handler',
    runtime: 'python3.7',
    layers: [sharedLambdaUtilsLayer.arn],
    memorySize: 512,
    timeout: 15 * 60,
    vpcConfig: {
      subnetIds: dbSubnets,
      securityGroupIds: [
        anyOutboundSg.id, // allow connection to internet
        fosRdsClientSgId  // allow connection to rds
        // defaultVpcSg.id // allow access to s3 vpc attachment
      ]
    },
    environment: {
      variables: {
        RDS_SECRET: rdsProxyConnStringSecret, // apply ensures a value is always returned
        PROXY_HOST: rdsProxyEndpoint,
        FUEL_PRICE_UPLOAD_PREFIX: fuelPriceUploadPrefix,
        REPORT_BUCKET: siteBucket.bucket,
        REPORT_BUCKET_PREFIX: reportsOutputPrefix,
        TASK_TABLE_NAME: wsTaskStatusDdbTableName,
        S3_TRACKING_TABLE_NAME: s3NotifyTrackingDbName,
        ENV: stackEnv,
        POWERTOOLS_SERVICE_NAME: 'fuelUploadLambda'
      }
    },
    tags: mkTagsWithName('fuelUploadLambda')
  },
  {
    provider: PulumiUtil.awsProvider,
    dependsOn: [
      fuelUploadLambdaLoggingRoleAttachment,
      fuelUploadLambdaExecPolicyRoleAttachment,
      fuelUploadLambdaWriteReportS3RoleAttachment,
      fuelUploadLambdaDynamoDBRoleAttachment
    ]
  }
);

Setting up event

export const fuelUploadObjectCreateEvent = siteBucket.onObjectCreated(
  mkItemName('fuelUploadObjectCreateEvent'),
  fuelUploadLambda,
  {
    event: '*',
    filterPrefix: fuelPriceUploadPrefix
  },
  { provider: PulumiUtil.awsProvider }
);

creating presigned url function used within lambda

PUT flavor

def create_presigned_put(
    bucket_name: str, object_name: str, expiration: int = 3600, metadata: Dict = None
):
    """Generate a presigned put URL to share an S3 object

    @param bucket_name: string
    @param object_name: string
    @param expiration: Time in seconds for the presigned URL to remain valid
    @param metadata: specify content type and any other metadata to be saved with object
    @return: Presigned URL as string. If error, returns None.
    """

    s3_client = boto3.client("s3", region_name=region)

    params = {
        "Bucket": bucket_name,
        "Key": object_name,
        "Metadata": metadata if metadata is not None else {},
    }

    return s3_client.generate_presigned_url(
        ClientMethod="put_object",
        Params=params,
        ExpiresIn=expiration,
    )

POST flavor

def create_presigned_post(
    bucket_name: str, object_name: str, expiration: int = 3600, metadata: Dict = None
):
    """Generate a presigned URL to share an S3 object

    @param bucket_name: string
    @param object_name: string
    @param expiration: Time in seconds for the presigned URL to remain valid
    @param metadata: specify content type and any other metadata to be saved with object
    @return: Presigned URL as string. If error, returns None.
    """

    s3_client = boto3.client("s3", region_name=region)

    metadata = metadata if metadata else {}
    conditions = [
        ["eq", "$key", object_name],  # key must match
        [
            "content-length-range",
            1,
            1000000000,
        ],  # file size not zero and no more than 1GB
    ]
    for key, value in metadata.items():
        conditions.append(
            ["eq", "$" + key, value]
        )  # require all other values from metadata be present
    return s3_client.generate_presigned_post(
        Bucket=bucket_name,
        Key=object_name,
        Fields=metadata,
        ExpiresIn=expiration,
        Conditions=conditions,
    )

@kingster307
Copy link

kingster307 commented Jul 18, 2022

essentially this is our workflow

  1. hit endpoint to get presigned url
  2. client posts or puts data to presigned url
  3. s3 post/put triggers fuelUploadLambda
  4. fuelUploadLambda processes s3 data & returns status messages via websockets

@pinzon
Copy link
Member

pinzon commented Jul 19, 2022

Hi @kingster307. The reason your PUT request is not activating the Lambda Function is because you're setting a Prefix filter("uploads/") in your notification configuration and when you send your request, the key is missing the prefix.

Url from your PUT request:

... : Received presign S3 URL: http://localhost:4566/self-serve-portal-20220718151114064200000004/fuel_pricing_upload/33fb622a-7388-49a6-a76f-7c117c2d47b5?AWSAccessKeyId=test&...

it should be:

... : Received presign S3 URL: http://localhost:4566/self-serve-portal-20220718151114064200000004/uploads/fuel_pricing_upload/33fb622a-7388-49a6-a76f-7c117c2d47b5?AWSAccessKeyId=test&...

For the POST request, my best guest for that 404 response is that you're using the URL from generate_presign_post without sending the data of the Fields attribute like an HTML Form.

Here is my reproducer, notice that both my keys have the "uploads/" prefix, the URL of each method is used differently and both trigger my Lambda Function:

import boto3
import requests

with open('file.txt', 'r') as object_file:
    object_text = object_file.read()

s3 = boto3.client('s3', endpoint_url="http://localhost:4566")
bucket_name = "my-bucket-13d6bec"

put_url = s3.generate_presigned_url(
    ClientMethod="put_object", 
    Params={"Bucket": bucket_name,  "Key": "uploads/file.txt"}
)
print(requests.put(put_url, data=object_text))

presigned_post = s3.generate_presigned_post(Bucket=bucket_name, Key='uploads/file2.txt')
print(requests.post(
    presigned_post['url'], 
    data=presigned_post['fields'],
    files={'file': open('file.txt', 'r')}))

Here is my pulumi stack using TS:

import * as aws from "@pulumi/aws";
import { FileArchive } from "@pulumi/pulumi/asset";

// Create an AWS resource (S3 Bucket)
const bucket = new aws.s3.Bucket("my-bucket");
const fuelUploadLambda = new aws.lambda.Function(
  'fuelUploadLambda',
  {
    code: new FileArchive('../function.zip'),
    role: "arn:aws:iam::074255357339:role/lambda-ex",
    handler: 'index.handler',
    runtime: 'nodejs14.x',
    memorySize: 512,
    timeout: 15 * 60,
  }
);

const uploadObjectCreateEvent = bucket.onObjectCreated('uploadObjectCreateEvent',
    fuelUploadLambda,
    {
        event: '*',
        filterPrefix: 'uploads/'
    }
);

@kingster307
Copy link

kingster307 commented Jul 19, 2022

@pinzon apologies....the onObjectCreated code snippet that I took from previous comments was out of date with our project. I have updated it in the code snippet above.

Our key when creating presigned url's is prefixed with fuelPriceUploadPrefix but then has additional data appended to it. After reviewing your code I suspect the issue could be that localstack is looking for an exact match for the key instead of just the prefix for the onObjectCreated event

Everything works in prod & sb account in AWS environments, its just localstack we are having issues with

@pinzon
Copy link
Member

pinzon commented Jul 19, 2022

@kingster307 could you give me an example of the final prefix you're setting on the lambda trigger and the key name you're sending?
I understand from what you say that Localstack should match differently the prefix and the key name but even when using "fuel_pricing_upload/" as prefix filter and for my key names Localstack still triggers my Function.

By the way, how normalizeS3Prefix alters the prefix?

@kingster307
Copy link

@pinzon

final lambda trigger would look like this

export const fuelUploadObjectCreateEvent = siteBucket.onObjectCreated(
  mkItemName('fuelUploadObjectCreateEvent'),
  fuelUploadLambda,
  {
    event: '*',
    filterPrefix: 'fuel_pricing_upload/'
  },
  { provider: PulumiUtil.awsProvider }
);

Key Name example - fuel_pricing_upload/33fb622a-7388-49a6-a76f-7c117c2d47b5

Bucket Name Example - self-serve-portal-20220718151114064200000004

normalizeS3Prefix - strips any leading slash in a string & ensures that string has a trailing slash

@pinzon
Copy link
Member

pinzon commented Jul 19, 2022

@kingster307 with your parameters I get the same results, even with multiple regions.

@kingster307
Copy link

kingster307 commented Jul 20, 2022

@pinzon

added a little demo project here to better present the issue. We are utilizing post pre-signed url. It seems as though the onObjectCreated lambda is never hit, as the logs/prints from within it never show && the logs never show the lambda being spun up
localstack_onObjectCreated_bug

@pinzon
Copy link
Member

pinzon commented Jul 21, 2022

Thank you very much @kingster307. I'm taking a look right now.

@pinzon
Copy link
Member

pinzon commented Jul 21, 2022

@kingster307 your reproducer showed a clearer picture of what's happening with LocalStack:

in your pytest you send your file like this:

presigned_post['fields']['file'] = open("file.txt",'r')
print(requests.post(
    presigned_post['url'], 
    data=presigned_post['fields']

and I do it like this:

requests.post(
    presigned_post['url'], 
    data=presigned_post['fields']
    files={"file": open("file.txt",'r')})

Both ways are valid and upload the file into the bucket but only my way activates the Lambda in LocalStack. For a temporal solution you could try to use my method, either way I'm working on fixing this.

Note: in the future please consider writing a reproducer from the beginning. 😅

@pinzon
Copy link
Member

pinzon commented Jul 22, 2022

hi @kingster307, upon further testing it seems to me that the method you use to upload your file is not valid, one cannot just simply add the file to the files dictionary and send it.

Using your method with AWS returns a 405 due to requests sending the data with the header 'Content-Type': 'application/x-www-form-urlencoded', in contrast, adding the file through the files parameter sends request with 'Content-Type': multipart/form-data; boundary=---- witch is then accepted by AWS.

here is the code I use to test it:

import boto3
import requests

s3 = boto3.client('s3')

bucket_name = "test-crist-bucket"
key = "test-file"

s3.create_bucket(Bucket=bucket_name)
cors_configuration = {
    'CORSRules': [{
        'AllowedHeaders': ['*'],
        'AllowedMethods': ['PUT','POST'],
        'AllowedOrigins': ['*'],
        'ExposeHeaders': ['ETag', 'x-amz-request-id'],
        'MaxAgeSeconds': 3000
    }]
}

s3.put_bucket_cors(Bucket=bucket_name, CORSConfiguration=cors_configuration)
s3.put_bucket_acl(ACL='public-read-write',Bucket=bucket_name)

presigned_post = s3.generate_presigned_post(
    Bucket=bucket_name,
    Key=key
)

presigned_post['fields']['file'] = open("file.txt",'r')

response = requests.post(
    presigned_post['url'], 
    data=presigned_post['fields']
    )

print(response) # <Response [405]>
print(response.content) # b'<?xml version="1.0" encoding="UTF-8"?>\n<Error><Code>MethodNotAllowed</Code><Message>The specified method is not allowed against this resource.</Message><Method>POST</Method><ResourceType>BUCKETPOLICY</ResourceType><RequestId>S3TFN88Y64H7ZHTE</RequestId><HostId>+BS4q74kic+Vlt0IRJe6/Sm62xijAEEanGXQzi9wpwdBKn/zRuPlQTejhYozOkPqaU82c4suavE=</HostId></Error>'

Please let me know if there any other setting I should add to make the previous code work as we desire, if not I'll just finish the tests that validate that Localstack is working as expected.

@kingster307
Copy link

kingster307 commented Jul 22, 2022

@pinzon Appreciate your work on this! ....Wrote an extra test case for adding headers for content type restrictions...Neither adding headers nor utilizing the files param seem to work completely. - see tests here

When adding the files param I can see the lambda fire but no log output show. see logs here

When adding headers to request for content type I do not see the lambda fire nor the log output

@pinzon
Copy link
Member

pinzon commented Jul 22, 2022

AWS returns a 400 response when adding the line headers = { "Content-Type": "multipart/form-data; boundary=----" } to the test.

@pinzon
Copy link
Member

pinzon commented Jul 25, 2022

Hi @kingster307 I made a pull request to your reproducer repo with the changes I made so the tests work with LocalStack. As I mention in my last comments I corroborate that the way you POST your file (adding it to the fields dictionary) doesn't work with AWS.

I made a PULL request that makes your reproducer trigger the Lambda function and I added an integration test to LocalStack (#6498) that shows that a Lambda is being triggered by an S3 object created through a presign PUT and a presign POST request. Also the test is AWS Validated which means that the exact code will also work with AWS.

@kingster307
Copy link

@pinzon see comments on PR

@kingster307
Copy link

@pinzon appreciate your work on this. Feel free to close at will...Can confirm when utilizing the new POST url structure & using files param the post & integration succeeds

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area: integration/pulumi Issues related to Pulumi aws:lambda AWS Lambda aws:s3 Amazon Simple Storage Service status: triage needed Requires evaluation by maintainers type: bug Bug report type: usage Usage of LocalStack and Best Practices
Projects
None yet
Development

No branches or pull requests

4 participants