search

awslabs / aws-lambda-web-adapter

Run web applications on AWS Lambda
Apache License 2.0
1.94k stars 118 forks source link

Intermittent Segfault due to IncompleteMessage and ConnectionRefused errors #295

Closed sidekick-eimantas closed 1 year ago

sidekick-eimantas commented 1 year ago

Hi

We are intermittently seeing the following errors:

ERROR Lambda runtime invoke{requestId="216b4cee-c278-4024-a11c-9819cc2d0ef0" xrayTraceId="Root=1-651ee4a0-098743bf1da96ae904d4d422;Parent=31c1e21b232f3046;Sampled=0;Lineage=9f52c89d:0"}: lambda_runtime: hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 111, kind: ConnectionRefused, message: "Connection refused" }))

ERROR Lambda runtime invoke{requestId="5b6739af-3e46-428d-a292-cde608a9b127" xrayTraceId="Root=1-6516be75-44d0f4c771b1ae3b47d56c74;Parent=728b446c27292ae9;Sampled=0;Lineage=bb56b18c:0"}: lambda_runtime: hyper::Error(IncompleteMessage)

We're encountering this quite rarely, and have seen one burst where 20~ requests in the span of a second all resulted in these errors.

Versions:

We're running behind a Lambda Function URL. The URL is public with a Route53 DNS record with authentication disabled. We're seeing these errors specifically just on two public URLs both running the same software.

Not sure where to start troubleshooting this.

Any help would be highly appreciated. Please let me know if any additional info is required.

sidekick-eimantas commented 1 year ago

Found more logs: image

Will try to catch RUST_BACKTRACE

sidekick-eimantas commented 1 year ago

Tried bumping up the memory, no change:

image
bnusunny commented 1 year ago

Hi, did these errors happen after a new Lambda execution environment starts up? The adapter seems not able to send requests to FastAPI. Are the FastAPI server working properly?

You could add the environment variable RUST_LOG=debug to turn on debug log for the adapter.

sidekick-eimantas commented 1 year ago

Hey, thanks for looking into this.

Sometimes it happens on a fresh environment, sometimes on one that's already successfully handled a previous request.

Log for failed invocation (repeat app is not ready messages trimmed down):

DEBUG hyper::client::connect::http: connecting to 127.0.0.1:8000
DEBUG hyper::client::connect::http: connecting to 127.0.0.1:9001
DEBUG hyper::client::connect::http: connected to 127.0.0.1:9001
DEBUG lambda_web_adapter: app is not ready
DEBUG hyper::proto::h1::io: flushed 145 bytes
DEBUG hyper::proto::h1::io: parsed 4 headers
DEBUG hyper::proto::h1::conn: incoming body is content-length (80 bytes)
DEBUG hyper::proto::h1::conn: incoming body completed
DEBUG hyper::client::pool: pooling idle connection for (""http"", 127.0.0.1:9001)
DEBUG hyper::client::pool: reuse idle connection for (""http"", 127.0.0.1:9001)
DEBUG hyper::proto::h1::io: flushed 138 bytes
DEBUG hyper::client::connect::http: connecting to 127.0.0.1:8000
DEBUG lambda_web_adapter: app is not ready
{""log_level"": ""INFO"", ""message"": ""Found credentials in environment variables."", ""timestamp"": ""2023-10-10 12:47:29.595449+00:00"", ""filename"": ""credentials.py"", ""function_name"": ""load"", ""line_number"": 1124, ""module_name"": ""credentials"", ""module_path"": ""/usr/local/lib/python3.10/site-packages/botocore/credentials.py"", ""process_id"": 12, ""process_name"": ""MainProcess"", ""thread_id"": 139977471134592, ""thread_name"": ""MainThread"", ""python_sdk_version"": ""0.12.0""}
DEBUG hyper::client::connect::http: connecting to 127.0.0.1:8000
DEBUG lambda_web_adapter: app is not ready
{""log_level"": ""INFO"", ""message"": ""Found credentials in environment variables."", ""timestamp"": ""2023-10-10 12:47:29.791802+00:00"", ""filename"": ""credentials.py"", ""function_name"": ""load"", ""line_number"": 1124, ""module_name"": ""credentials"", ""module_path"": ""/usr/local/lib/python3.10/site-packages/botocore/credentials.py"", ""process_id"": 12, ""process_name"": ""MainProcess"", ""thread_id"": 139977471134592, ""thread_name"": ""MainThread"", ""python_sdk_version"": ""0.12.0""}
DEBUG hyper::client::connect::http: connecting to 127.0.0.1:8000
DEBUG lambda_web_adapter: app is not ready
DEBUG hyper::client::connect::http: connecting to 127.0.0.1:8000
DEBUG hyper::client::connect::http: connected to 127.0.0.1:8000
DEBUG hyper::proto::h1::io: flushed 47 bytes
{""log_level"": ""INFO"", ""message"": ""127.0.0.1:36082 - \""GET /Healthz HTTP/1.1\"" 200"", ""timestamp"": ""2023-10-10 12:47:29.931396+00:00"", ""filename"": ""httptools_impl.py"", ""function_name"": ""send"", ""line_number"": 496, ""module_name"": ""httptools_impl"", ""module_path"": ""/usr/local/lib/python3.10/site-packages/uvicorn/protocols/http/httptools_impl.py"", ""process_id"": 12, ""process_name"": ""MainProcess"", ""thread_id"": 139977471134592, ""thread_name"": ""MainThread"", ""python_sdk_version"": ""0.12.0""}
DEBUG hyper::proto::h1::io: parsed 3 headers
DEBUG hyper::proto::h1::conn: incoming body is content-length (44 bytes)
DEBUG hyper::proto::h1::conn: incoming body completed
DEBUG hyper::client::pool: pooling idle connection for (""http"", 127.0.0.1:8000)
DEBUG hyper::client::connect::http: connecting to 127.0.0.1:9001
DEBUG hyper::client::connect::http: connected to 127.0.0.1:9001
DEBUG hyper::proto::h1::io: flushed 128 bytes
EXTENSION   Name: lambda-adapter    State: Ready    Events: []
START RequestId: 957cd2f9-07fe-4e27-bdbc-d7ef6ae91122 Version: $LATEST
DEBUG hyper::proto::h1::io: parsed 7 headers
DEBUG hyper::proto::h1::conn: incoming body is chunked encoding
DEBUG hyper::proto::h1::decode: incoming chunked header: 0xB26 (2854 bytes)
DEBUG hyper::proto::h1::conn: incoming body completed
DEBUG hyper::client::pool: pooling idle connection for (""http"", 127.0.0.1:9001)
DEBUG Lambda runtime invoke{requestId=""957cd2f9-07fe-4e27-bdbc-d7ef6ae91122"" xrayTraceId=""Root=1-652547df-118a05195430e4d449c2ddd2;Parent=3c4b26d85eaf880f;Sampled=0;Lineage=bb56b18c:0""}: lambda_web_adapter: sending request to app server app_url=http://127.0.0.1:8000/rudderstack-subscriptions req_headers={""cloudfront-is-android-viewer"": ""false"", ""content-length"": ""850"", ""cloudfront-viewer-country"": ""GB"", ""x-amzn-tls-version"": ""TLSv1.2"", ""cloudfront-viewer-tls"": ""TLSv1.3:TLS_AES_128_GCM_SHA256:sessionResumed"", ""x-forwarded-port"": ""443"", ""via"": ""1.1 829762c3f42db9d1ea41f24010e3ac9e.cloudfront.net (CloudFront)"", ""authorization"": ""REDACTED"", ""x-amzn-tls-cipher-suite"": ""ECDHE-RSA-AES128-GCM-SHA256"", ""cloudfront-is-desktop-viewer"": ""true"", ""cloudfront-viewer-asn"": ""16509"", ""host"": ""REDACTED.lambda-url.eu-west-2.on.aws"", ""content-type"": ""application/json; charset=utf-8"", ""cloudfront-viewer-http-version"": ""1.1"", ""cloudfront-viewer-address"": ""52.56.247.150:44499"", ""x-forwarded-proto"": ""https"", ""cloudfront-is-ios-viewer"": ""false"", ""x-forwarded-for"": ""52.56.247.150"", ""cloudfront-is-smarttv-viewer"": ""false"", ""x-amzn-trace-id"": ""Root=1-652547df-118a05195430e4d449c2ddd2;Parent=3c4b26d85eaf880f;Sampled=0;Lineage=bb56b18c:0"", ""cloudfront-is-tablet-viewer"": ""false"", ""cloudfront-forwarded-proto"": ""https"", ""accept-encoding"": ""gzip,deflate"", ""x-amz-cf-id"": ""4ucG2p2qqeuX-boYox2VQcgVqXeQ45M4Mm1xWfjtO8kx0xw4O1M3GQ=="", ""cloudfront-is-mobile-viewer"": ""false"", ""user-agent"": ""Amazon/EventBridge/ApiDestinations"", ""x-amzn-request-context"": ""{\""routeKey\"":\""$default\"",\""accountId\"":\""anonymous\"",\""stage\"":\""$default\"",\""requestId\"":\""957cd2f9-07fe-4e27-bdbc-d7ef6ae91122\"",\""authorizer\"":null,\""apiId\"":\""REDACTED\"",\""domainName\"":\""REDACTED.lambda-url.eu-west-2.on.aws\"",\""domainPrefix\"":\""REDACTED\"",\""time\"":\""10/Oct/2023:12:47:27 +0000\"",\""timeEpoch\"":1696942047934,\""http\"":{\""method\"":\""POST\"",\""path\"":\""/rudderstack-subscriptions\"",\""protocol\"":\""HTTP/1.1\"",\""sourceIp\"":\""15.158.44.234\"",\""userAgent\"":\""Amazon/EventBridge/ApiDestinations\""},\""authentication\"":null}""}
DEBUG Lambda runtime invoke{requestId=""957cd2f9-07fe-4e27-bdbc-d7ef6ae91122"" xrayTraceId=""Root=1-652547df-118a05195430e4d449c2ddd2;Parent=3c4b26d85eaf880f;Sampled=0;Lineage=bb56b18c:0""}: hyper::client::pool: reuse idle connection for (""http"", 127.0.0.1:8000)
DEBUG hyper::proto::h1::io: flushed 2711 bytes
{""log_level"": ""INFO"", ""message"": ""Received event"", ""timestamp"": ""2023-10-10 12:47:29.936786+00:00"", ""function_name"": ""__call__"", ""line_number"": 43, ""module_name"": ""_root"", ""module_path"": ""/usr/local/lib/python3.10/site-packages/event_gateway/ingest_api/routes/_root.py"", ""endpoint"": ""/rudderstack-subscriptions""}
DEBUG hyper::proto::h1::conn: parse error (connection closed before message completed) with 0 bytes
DEBUG hyper::proto::h1::dispatch: read_head error: connection closed before message completed
ERROR Lambda runtime invoke{requestId=""957cd2f9-07fe-4e27-bdbc-d7ef6ae91122"" xrayTraceId=""Root=1-652547df-118a05195430e4d449c2ddd2;Parent=3c4b26d85eaf880f;Sampled=0;Lineage=bb56b18c:0""}: lambda_runtime: hyper::Error(IncompleteMessage)
DEBUG Lambda runtime invoke{requestId=""957cd2f9-07fe-4e27-bdbc-d7ef6ae91122"" xrayTraceId=""Root=1-652547df-118a05195430e4d449c2ddd2;Parent=3c4b26d85eaf880f;Sampled=0;Lineage=bb56b18c:0""}: hyper::client::pool: reuse idle connection for (""http"", 127.0.0.1:9001)
DEBUG hyper::proto::h1::io: flushed 395 bytes
DEBUG hyper::proto::h1::io: parsed 3 headers
DEBUG hyper::proto::h1::conn: incoming body is content-length (16 bytes)
DEBUG hyper::proto::h1::conn: incoming body completed
DEBUG hyper::client::connect::http: connecting to 127.0.0.1:9001
DEBUG hyper::client::pool: reuse idle connection for (""http"", 127.0.0.1:9001)
DEBUG hyper::client::connect::http: connected to 127.0.0.1:9001
DEBUG hyper::proto::h1::io: flushed 128 bytes
END RequestId: 957cd2f9-07fe-4e27-bdbc-d7ef6ae91122
REPORT RequestId: 957cd2f9-07fe-4e27-bdbc-d7ef6ae91122  Duration: 234.95 ms Billed Duration: 1969 ms    Memory Size: 1769 MB    Max Memory Used: 203 MB Init Duration: 1733.13 ms   
START RequestId: d3c21c5e-b859-4b02-b873-c4c03f9f1491 Version: $LATEST
DEBUG hyper::client::pool: pooling idle connection for (""http"", 127.0.0.1:9001)
DEBUG hyper::proto::h1::io: parsed 7 headers
DEBUG hyper::proto::h1::conn: incoming body is content-length (75 bytes)
DEBUG hyper::proto::h1::conn: incoming body completed
DEBUG hyper::client::pool: pooling idle connection for (""http"", 127.0.0.1:9001)
RequestId: d3c21c5e-b859-4b02-b873-c4c03f9f1491 Error: Runtime exited with error: signal: segmentation fault
Runtime.ExitError
END RequestId: d3c21c5e-b859-4b02-b873-c4c03f9f1491
REPORT RequestId: d3c21c5e-b859-4b02-b873-c4c03f9f1491  Duration: 1.83 ms   Billed Duration: 2 ms   Memory Size: 1769 MB    Max Memory Used: 203 MB
sidekick-eimantas commented 1 year ago

Succesful invocation:

DEBUG hyper::client::connect::http: connecting to 127.0.0.1:8000
DEBUG lambda_web_adapter: app is not ready
DEBUG hyper::client::connect::http: connecting to 127.0.0.1:9001
DEBUG hyper::client::connect::http: connected to 127.0.0.1:9001
DEBUG hyper::proto::h1::io: flushed 145 bytes
DEBUG hyper::proto::h1::io: parsed 4 headers
DEBUG hyper::proto::h1::conn: incoming body is content-length (80 bytes)
DEBUG hyper::proto::h1::conn: incoming body completed
DEBUG hyper::client::pool: pooling idle connection for (""http"", 127.0.0.1:9001)
DEBUG hyper::client::pool: reuse idle connection for (""http"", 127.0.0.1:9001)
DEBUG hyper::proto::h1::io: flushed 138 bytes
DEBUG hyper::client::connect::http: connecting to 127.0.0.1:8000
DEBUG lambda_web_adapter: app is not ready
{""log_level"": ""INFO"", ""message"": ""Found credentials in environment variables."", ""timestamp"": ""2023-10-10 12:47:31.587104+00:00"", ""filename"": ""credentials.py"", ""function_name"": ""load"", ""line_number"": 1124, ""module_name"": ""credentials"", ""module_path"": ""/usr/local/lib/python3.10/site-packages/botocore/credentials.py"", ""process_id"": 13, ""process_name"": ""MainProcess"", ""thread_id"": 139674320079744, ""thread_name"": ""MainThread"", ""python_sdk_version"": ""0.12.0""}
{""log_level"": ""INFO"", ""message"": ""Found credentials in environment variables."", ""timestamp"": ""2023-10-10 12:47:31.741978+00:00"", ""filename"": ""credentials.py"", ""function_name"": ""load"", ""line_number"": 1124, ""module_name"": ""credentials"", ""module_path"": ""/usr/local/lib/python3.10/site-packages/botocore/credentials.py"", ""process_id"": 13, ""process_name"": ""MainProcess"", ""thread_id"": 139674320079744, ""thread_name"": ""MainThread"", ""python_sdk_version"": ""0.12.0""}
DEBUG hyper::client::connect::http: connecting to 127.0.0.1:8000
DEBUG hyper::client::connect::http: connected to 127.0.0.1:8000
DEBUG hyper::proto::h1::io: flushed 47 bytes
{""log_level"": ""INFO"", ""message"": ""127.0.0.1:49222 - \""GET /Healthz HTTP/1.1\"" 200"", ""timestamp"": ""2023-10-10 12:47:31.830840+00:00"", ""filename"": ""httptools_impl.py"", ""function_name"": ""send"", ""line_number"": 496, ""module_name"": ""httptools_impl"", ""module_path"": ""/usr/local/lib/python3.10/site-packages/uvicorn/protocols/http/httptools_impl.py"", ""process_id"": 13, ""process_name"": ""MainProcess"", ""thread_id"": 139674320079744, ""thread_name"": ""MainThread"", ""python_sdk_version"": ""0.12.0""}
DEBUG hyper::proto::h1::io: parsed 3 headers
DEBUG hyper::proto::h1::conn: incoming body is content-length (44 bytes)
DEBUG hyper::proto::h1::conn: incoming body completed
DEBUG hyper::client::pool: pooling idle connection for (""http"", 127.0.0.1:8000)
DEBUG hyper::client::connect::http: connecting to 127.0.0.1:9001
DEBUG hyper::client::connect::http: connected to 127.0.0.1:9001
DEBUG hyper::proto::h1::io: flushed 128 bytes
EXTENSION   Name: lambda-adapter    State: Ready    Events: []
START RequestId: e337bf02-dfa7-4235-9d3e-ce46ad76a6e2 Version: $LATEST
DEBUG hyper::proto::h1::io: parsed 7 headers
DEBUG hyper::proto::h1::conn: incoming body is chunked encoding
DEBUG hyper::proto::h1::decode: incoming chunked header: 0xB1F (2847 bytes)
DEBUG hyper::proto::h1::conn: incoming body completed
DEBUG hyper::client::pool: pooling idle connection for (""http"", 127.0.0.1:9001)
DEBUG Lambda runtime invoke{requestId=""e337bf02-dfa7-4235-9d3e-ce46ad76a6e2"" xrayTraceId=""Root=1-652547e2-116ed41447067cd752ca7be5;Parent=0ce200b35d97b24f;Sampled=0;Lineage=bb56b18c:0""}: lambda_web_adapter: sending request to app server app_url=http://127.0.0.1:8000/rudderstack-subscriptions req_headers={""cloudfront-is-android-viewer"": ""false"", ""content-length"": ""848"", ""cloudfront-viewer-country"": ""GB"", ""x-amzn-tls-version"": ""TLSv1.2"", ""cloudfront-viewer-tls"": ""TLSv1.3:TLS_AES_128_GCM_SHA256:fullHandshake"", ""x-forwarded-port"": ""443"", ""via"": ""1.1 163cab6be16ba1fb5ee75dd6beeee0e2.cloudfront.net (CloudFront)"", ""authorization"": ""REDACTED"", ""x-amzn-tls-cipher-suite"": ""ECDHE-RSA-AES128-GCM-SHA256"", ""cloudfront-is-desktop-viewer"": ""true"", ""cloudfront-viewer-asn"": ""16509"", ""host"": ""REDACTED.lambda-url.eu-west-2.on.aws"", ""content-type"": ""application/json; charset=utf-8"", ""cloudfront-viewer-http-version"": ""1.1"", ""cloudfront-viewer-address"": ""3.10.46.136:15218"", ""x-forwarded-proto"": ""https"", ""cloudfront-is-ios-viewer"": ""false"", ""x-forwarded-for"": ""3.10.46.136"", ""cloudfront-is-smarttv-viewer"": ""false"", ""x-amzn-trace-id"": ""Root=1-652547e2-116ed41447067cd752ca7be5;Parent=0ce200b35d97b24f;Sampled=0;Lineage=bb56b18c:0"", ""cloudfront-is-tablet-viewer"": ""false"", ""cloudfront-forwarded-proto"": ""https"", ""accept-encoding"": ""gzip,deflate"", ""x-amz-cf-id"": ""Aq_qO8EmylAR2pGztDVYd2ihFNNb7JPADtmVuJ30Qjs5Aa0iw-HZ5Q=="", ""cloudfront-is-mobile-viewer"": ""false"", ""user-agent"": ""Amazon/EventBridge/ApiDestinations"", ""x-amzn-request-context"": ""{\""routeKey\"":\""$default\"",\""accountId\"":\""anonymous\"",\""stage\"":\""$default\"",\""requestId\"":\""e337bf02-dfa7-4235-9d3e-ce46ad76a6e2\"",\""authorizer\"":null,\""apiId\"":\""REDACTED\"",\""domainName\"":\""REDACTED.lambda-url.eu-west-2.on.aws\"",\""domainPrefix\"":\""REDACTED\"",\""time\"":\""10/Oct/2023:12:47:30 +0000\"",\""timeEpoch\"":1696942050406,\""http\"":{\""method\"":\""POST\"",\""path\"":\""/rudderstack-subscriptions\"",\""protocol\"":\""HTTP/1.1\"",\""sourceIp\"":\""15.158.44.246\"",\""userAgent\"":\""Amazon/EventBridge/ApiDestinations\""},\""authentication\"":null}""}
DEBUG Lambda runtime invoke{requestId=""e337bf02-dfa7-4235-9d3e-ce46ad76a6e2"" xrayTraceId=""Root=1-652547e2-116ed41447067cd752ca7be5;Parent=0ce200b35d97b24f;Sampled=0;Lineage=bb56b18c:0""}: hyper::client::pool: reuse idle connection for (""http"", 127.0.0.1:8000)
DEBUG hyper::proto::h1::io: flushed 2704 bytes
{""log_level"": ""INFO"", ""message"": ""Received event"", ""timestamp"": ""2023-10-10 12:47:31.833164+00:00"", ""function_name"": ""__call__"", ""line_number"": 43, ""module_name"": ""_root"", ""module_path"": ""/usr/local/lib/python3.10/site-packages/event_gateway/ingest_api/routes/_root.py"", ""endpoint"": ""/rudderstack-subscriptions""}
{""log_level"": ""INFO"", ""message"": ""Event delivered successfully"", ""timestamp"": ""2023-10-10 12:47:32.899144+00:00"", ""function_name"": ""_handle_delivery_attempt_outcome"", ""line_number"": 320, ""module_name"": ""_event_delivery_job_processor"", ""module_path"": ""/usr/local/lib/python3.10/site-packages/event_gateway/event_delivery_job_processor/_event_delivery_job_processor.py""}
{""log_level"": ""INFO"", ""message"": ""3.10.46.136:0 - \""POST /rudderstack-subscriptions HTTP/1.1\"" 200"", ""timestamp"": ""2023-10-10 12:47:32.966520+00:00"", ""function_name"": ""send"", ""line_number"": 496, ""module_name"": ""httptools_impl"", ""module_path"": ""/usr/local/lib/python3.10/site-packages/uvicorn/protocols/http/httptools_impl.py""}
DEBUG hyper::proto::h1::io: parsed 2 headers
DEBUG hyper::proto::h1::conn: incoming body is empty
DEBUG Lambda runtime invoke{requestId=""e337bf02-dfa7-4235-9d3e-ce46ad76a6e2"" xrayTraceId=""Root=1-652547e2-116ed41447067cd752ca7be5;Parent=0ce200b35d97b24f;Sampled=0;Lineage=bb56b18c:0""}: hyper::client::pool: pooling idle connection for (""http"", 127.0.0.1:8000)
DEBUG Lambda runtime invoke{requestId=""e337bf02-dfa7-4235-9d3e-ce46ad76a6e2"" xrayTraceId=""Root=1-652547e2-116ed41447067cd752ca7be5;Parent=0ce200b35d97b24f;Sampled=0;Lineage=bb56b18c:0""}: lambda_web_adapter: responding to lambda event status=200 OK body_size=0 app_headers={""date"": ""Tue, 10 Oct 2023 12:47:31 GMT"", ""content-length"": ""0""}
DEBUG Lambda runtime invoke{requestId=""e337bf02-dfa7-4235-9d3e-ce46ad76a6e2"" xrayTraceId=""Root=1-652547e2-116ed41447067cd752ca7be5;Parent=0ce200b35d97b24f;Sampled=0;Lineage=bb56b18c:0""}: hyper::client::pool: reuse idle connection for (""http"", 127.0.0.1:9001)
DEBUG hyper::proto::h1::io: flushed 414 bytes
DEBUG hyper::proto::h1::io: parsed 3 headers
DEBUG hyper::proto::h1::conn: incoming body is content-length (16 bytes)
DEBUG hyper::proto::h1::conn: incoming body completed
DEBUG Lambda runtime invoke{requestId=""e337bf02-dfa7-4235-9d3e-ce46ad76a6e2"" xrayTraceId=""Root=1-652547e2-116ed41447067cd752ca7be5;Parent=0ce200b35d97b24f;Sampled=0;Lineage=bb56b18c:0""}: hyper::client::pool: pooling idle connection for (""http"", 127.0.0.1:9001)
DEBUG hyper::client::pool: reuse idle connection for (""http"", 127.0.0.1:9001)
DEBUG hyper::proto::h1::io: flushed 128 bytes
END RequestId: e337bf02-dfa7-4235-9d3e-ce46ad76a6e2
REPORT RequestId: e337bf02-dfa7-4235-9d3e-ce46ad76a6e2  Duration: 2478.17 ms    Billed Duration: 2479 ms    Memory Size: 1769 MB    Max Memory Used: 78 MB
sidekick-eimantas commented 1 year ago

Example of this happening on an environment that has successfully handled 1 request:

image
bnusunny commented 1 year ago 
DEBUG Lambda runtime invoke{requestId=""957cd2f9-07fe-4e27-bdbc-d7ef6ae91122"" xrayTraceId=""Root=1-652547df-118a05195430e4d449c2ddd2;Parent=3c4b26d85eaf880f;Sampled=0;Lineage=bb56b18c:0""}: hyper::client::pool: reuse idle connection for (""http"", 127.0.0.1:8000)
DEBUG hyper::proto::h1::io: flushed 2711 bytes
{""log_level"": ""INFO"", ""message"": ""Received event"", ""timestamp"": ""2023-10-10 12:47:29.936786+00:00"", ""function_name"": ""__call__"", ""line_number"": 43, ""module_name"": ""_root"", ""module_path"": ""/usr/local/lib/python3.10/site-packages/event_gateway/ingest_api/routes/_root.py"", ""endpoint"": ""/rudderstack-subscriptions""}
DEBUG hyper::proto::h1::conn: parse error (connection closed before message completed) with 0 bytes
DEBUG hyper::proto::h1::dispatch: read_head error: connection closed before message completed

From this log, it seems FastAPI dropped the connection before sending the response. Did FastAPI crash?

bnusunny commented 1 year ago

I suspect the FastAPI server is not fully ready to process requests. You may want to adjust the readiness check to ensure the FastAPI is fully ready.

bnusunny commented 1 year ago

Even for the one with 1 request processed, that request actually failed.

image

sidekick-eimantas commented 1 year ago

From this log, it seems FastAPI dropped the connection before sending the response. Did FastAPI crash?

Just added more logs to the application. Indeed it seems that FastAPI or Uvicorn are flat out quietly crashing.

Even for the one with 1 request processed, that request actually failed.

Good catch, completely missed that

sidekick-eimantas commented 1 year ago

You may want to adjust the readiness check to ensure the FastAPI is fully ready.

What can be adjusted for the readiness check?

sidekick-eimantas commented 1 year ago

Finally found out what's going on. Python is segfaulting for some reason. Definitely nothing to do with this library. Thank you for all your help @bnusunny