search

urllib3 / urllib3

urllib3 is a user-friendly HTTP client library for Python
https://urllib3.readthedocs.io
MIT License
3.76k stars 1.14k forks source link

Segfault in ssl_.ssl_wrap_socket #3155

Closed sidekick-eimantas closed 9 months ago

sidekick-eimantas commented 11 months ago

Subject

Python is segfaulting when trying to open a connection to AWS S3.

Environment

OS Linux-4.14.255-318-256.530.amzn2.x86_64-x86_64-with-glibc2.36 Python 3.10.12 OpenSSL 3.0.9 30 May 2023 urllib3 2.0.6

The service is running on AWS Lambda, in a Docker x86 container.

Steps to Reproduce

Unfortunately, wont be of much help here. I am unable to reproduce it on my local machine and therefore cannot reduce the code sample.

Its an asynchronous FastAPI + Uvicorn application. Soon after it starts up, it's invoking multiple AWS S3 API calls using boto3 with asyncio.to_thread. The calls are parallelized using asyncio.gather. Those API calls are the first outbound network connections that the service makes. The service segfaults as it's attempting to establish a connection.

Interestingly enough, adding the following code to execute after the server starts, before the AWS S3 API calls are made, "fixes" this problem:

async with httpx.AsyncClient() as client:
        await client.get("https://google.com")

Expected Behavior

No segfault

Actual Behavior

2023-10-10T18:23:23.949Z    Deleting object events-index/received-at/2023/10/10/18/23/23/06525969-bf1b-7665-8000-3ceb4260cb04
2023-10-10T18:23:24.060Z    Fatal Python error: Segmentation fault
2023-10-10T18:23:24.060Z    Thread 0x00007f77d0ea06c0 (most recent call first):
2023-10-10T18:23:24.060Z    File "/usr/local/lib/python3.10/site-packages/urllib3/util/ssl_.py", line 444 in ssl_wrap_socket
2023-10-10T18:23:24.060Z    File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 783 in _ssl_wrap_socket_and_match_hostname
2023-10-10T18:23:24.060Z    File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 642 in connect
2023-10-10T18:23:24.060Z    File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 1092 in _validate_conn
2023-10-10T18:23:24.060Z    File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 467 in _make_request
2023-10-10T18:23:24.061Z    File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 790 in urlopen
2023-10-10T18:23:24.061Z    File "/usr/local/lib/python3.10/site-packages/botocore/httpsession.py", line 465 in send
2023-10-10T18:23:24.061Z    File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 377 in _send
2023-10-10T18:23:24.061Z    File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 281 in _do_get_response
2023-10-10T18:23:24.061Z    File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 241 in _get_response
2023-10-10T18:23:24.061Z    File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 199 in _send_request
2023-10-10T18:23:24.061Z    File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 119 in make_request
2023-10-10T18:23:24.061Z    File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 986 in _make_request
2023-10-10T18:23:24.061Z    File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 963 in _make_api_call
2023-10-10T18:23:24.061Z    File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 535 in _api_call
2023-10-10T18:23:24.062Z    File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58 in run
2023-10-10T18:23:24.062Z    File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 83 in _worker
2023-10-10T18:23:24.062Z    File "/usr/local/lib/python3.10/threading.py", line 953 in run
2023-10-10T18:23:24.062Z    File "/usr/local/lib/python3.10/threading.py", line 1016 in _bootstrap_inner
2023-10-10T18:23:24.062Z    File "/usr/local/lib/python3.10/threading.py", line 973 in _bootstrap
2023-10-10T18:23:24.062Z    Current thread 0x00007f77d16a16c0 (most recent call first):
2023-10-10T18:23:24.062Z    File "/usr/local/lib/python3.10/ssl.py", line 1342 in do_handshake
2023-10-10T18:23:24.062Z    File "/usr/local/lib/python3.10/ssl.py", line 1071 in _create
2023-10-10T18:23:24.062Z    File "/usr/local/lib/python3.10/ssl.py", line 513 in wrap_socket
2023-10-10T18:23:24.062Z    File "/usr/local/lib/python3.10/site-packages/urllib3/util/ssl_.py", line 513 in _ssl_wrap_socket_impl
2023-10-10T18:23:24.062Z    File "/usr/local/lib/python3.10/site-packages/urllib3/util/ssl_.py", line 469 in ssl_wrap_socket
2023-10-10T18:23:24.063Z    File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 783 in _ssl_wrap_socket_and_match_hostname
2023-10-10T18:23:24.063Z    File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 642 in connect
2023-10-10T18:23:24.063Z    File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 1092 in _validate_conn
2023-10-10T18:23:24.063Z    File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 467 in _make_request
2023-10-10T18:23:24.063Z    File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 790 in urlopen
2023-10-10T18:23:24.063Z    File "/usr/local/lib/python3.10/site-packages/botocore/httpsession.py", line 465 in send
2023-10-10T18:23:24.063Z    File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 377 in _send
2023-10-10T18:23:24.063Z    File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 281 in _do_get_response
2023-10-10T18:23:24.063Z    File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 241 in _get_response
2023-10-10T18:23:24.063Z    File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 199 in _send_request
2023-10-10T18:23:24.064Z    File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 119 in make_request
2023-10-10T18:23:24.064Z    File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 986 in _make_request
2023-10-10T18:23:24.064Z    File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 963 in _make_api_call
2023-10-10T18:23:24.064Z    File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 535 in _api_call
2023-10-10T18:23:24.064Z    File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58 in run
2023-10-10T18:23:24.072Z    File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 83 in _worker
2023-10-10T18:23:24.073Z    File "/usr/local/lib/python3.10/threading.py", line 953 in run
2023-10-10T18:23:24.073Z    File "/usr/local/lib/python3.10/threading.py", line 1016 in _bootstrap_inner
2023-10-10T18:23:24.073Z    File "/usr/local/lib/python3.10/threading.py", line 973 in _bootstrap
2023-10-10T18:23:24.073Z    Thread 0x00007f77d7e51b80 (most recent call first):
2023-10-10T18:23:24.073Z    File "/usr/local/lib/python3.10/asyncio/runners.py", line 44 in run
2023-10-10T18:23:24.073Z    File "/usr/local/lib/python3.10/site-packages/uvicorn/server.py", line 61 in run
2023-10-10T18:23:24.073Z    File "/usr/local/lib/python3.10/site-packages/event_gateway/cli/commands/_run_ingest_api.py", line 31 in run_ingest_api
2023-10-10T18:23:24.073Z    File "/usr/local/lib/python3.10/site-packages/typer/main.py", line 683 in wrapper
2023-10-10T18:23:24.073Z    File "/usr/local/lib/python3.10/site-packages/click/core.py", line 783 in invoke
2023-10-10T18:23:24.073Z    File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1434 in invoke
2023-10-10T18:23:24.074Z    File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1688 in invoke
2023-10-10T18:23:24.074Z    File "/usr/local/lib/python3.10/site-packages/typer/core.py", line 216 in _main
2023-10-10T18:23:24.074Z    File "/usr/local/lib/python3.10/site-packages/typer/core.py", line 778 in main
2023-10-10T18:23:24.074Z    File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1157 in __call__
2023-10-10T18:23:24.074Z    File "/usr/local/lib/python3.10/site-packages/typer/main.py", line 311 in __call__
2023-10-10T18:23:24.074Z    File "/usr/local/lib/python3.10/site-packages/event_gateway/__main__.py", line 5 in main
2023-10-10T18:23:24.074Z    File "/usr/local/bin/event-gateway", line 8 in <module>
2023-10-10T18:23:24.075Z    Extension modules: psutil._psutil_linux, psutil._psutil_posix, setproctitle._setproctitle, _cffi_backend, uvloop.loop, httptools.parser.parser, httptools.parser.url_parser, websockets.speedups (total: 8)

I'm happy to help debug this further and give access to an AWS sandbox running this service if that helps.

sigmavirus24 commented 11 months ago

The line that is segfaulting on is a call to the standard library: https://github.com/urllib3/urllib3/blob/262e3e332209ee93ff70e2b13502c8f20c105ac8/src/urllib3/util/ssl_.py#L444

I'm not familiar with uvicorn but projects like that tend to monkey-patch things and I'm not sure which they're patching here, but it could be ssl or something else. Can you reproduce without uvicorn?

pquentin commented 11 months ago

I checked and uvicorn does not appear to do anything specific ssl patching. ~@Kludex can you please confirm?~ Thanks, confirmed below.

Anyway, what the error is telling us is that you have multiple threads reusing the same SSLContext object, doing two things at the same time with asyncio.to_thread and asyncio.gather:

My theory is that a bug in OpenSSL 3.0 means that those two operations are not thread-safe and cannot be executed together. The fact that making a single-threaded request solves the issue gives credit to that theory, even if I suppose it's not using the same SSLContext. Maybe there's some caching involved meaning that the next calls are super fast?

The other thing I don't understand is that since Thread 0x00007f77d16a16c0 was already doing the handshake, surely it has already called SSL_CTX_load_verify_locations?

@sidekick-eimantas How easy is it to extract the call invoking multiple AWS S3 API calls at startup? My hunch is that should fail the same way, eliminating Uvicorn and FastAPI altogether.

sidekick-eimantas commented 11 months ago

Thanks for looking into this @sigmavirus24 @pquentin

Can you reproduce without uvicorn?

I'll try this evening

How easy is it to extract the call invoking multiple AWS S3 API calls at startup? My hunch is that just that should fail the same way, eliminating Uvicorn and FastAPI altogether.

Should be easy enough. I'll get it done this evening and post results

In the meantime, here's the application logs before it segfaults, might be of some help (they always look the same):

2023-10-10T14:14:42.269Z    INFO: Started server process [13]
2023-10-10T14:14:42.269Z    INFO: Waiting for application startup.
2023-10-10T14:14:42.269Z    INFO: Application startup complete.
2023-10-10T14:14:42.273Z    INFO: Uvicorn running on http://localhost:8000 (Press CTRL+C to quit)
2023-10-10T14:14:42.278Z    INFO: 127.0.0.1:41154 - "GET /Healthz HTTP/1.1" 200 OK

2023-10-10T14:14:42.282Z    {"log_level": "INFO", "message": "Received event", "timestamp": "2023-10-10 14:14:42.282231+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": "/risk-subscriptions"}

2023-10-10T14:14:42.282Z    {"log_level": "DEBUG", "message": "Event", "timestamp": "2023-10-10 14:14:42.282417+00:00", "function_name": "__call__", "line_number": 58, "module_name": "_root", "module_path": "/usr/local/lib/python3.10/site-packages/event_gateway/ingest_api/routes/_root.py", "event": {"url": "/risk-subscriptions", "method": "POST", "headers": {"cloudfront-is-android-viewer": "false", "content-length": "838", "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 dc5ba6653148afa9504262089bb395dc.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": "18.135.181.193:48822", "x-forwarded-proto": "https", "cloudfront-is-ios-viewer": "false", "x-forwarded-for": "18.135.181.193", "cloudfront-is-smarttv-viewer": "false", "x-amzn-trace-id": "Root=1-65255c4f-18d3a63f0003360c506c1314;Parent=753514eb0b2b1662;Sampled=0;Lineage=bb56b18c:0", "cloudfront-is-tablet-viewer": "false", "cloudfront-forwarded-proto": "https", "accept-encoding": "gzip,deflate", "x-amz-cf-id": "4gDMjTbGQ6DxN3NsOZkaLf2EocDTULumB23pwCZgGDlmj7FZy4hKKw==", "cloudfront-is-mobile-viewer": "false", "user-agent": "Amazon/EventBridge/ApiDestinations", "x-amzn-request-context": "{\"routeKey\":\"$default\",\"accountId\":\"anonymous\",\"stage\":\"$default\",\"requestId\":\"acef2a5c-bf3a-4a99-a095-785c5a85e4a0\",\"authorizer\":null,\"apiId\":\"REDACTED\",\"domainName\":\"REDACTED.lambda-url.eu-west-2.on.aws\",\"domainPrefix\":\"REDACTED\",\"time\":\"10/Oct/2023:14:14:39 +0000\",\"timeEpoch\":1696947279645,\"http\":{\"method\":\"POST\",\"path\":\"/risk-subscriptions\",\"protocol\":\"HTTP/1.1\",\"sourceIp\":\"15.158.44.234\",\"userAgent\":\"Amazon/EventBridge/ApiDestinations\"},\"authentication\":null}", "x-amzn-lambda-context": "{\"request_id\":\"acef2a5c-bf3a-4a99-a095-785c5a85e4a0\",\"deadline\":1696947292280,\"invoked_function_arn\":\"arn:aws:lambda:eu-west-2:552085160264:function:internal-ingest-api\",\"xray_trace_id\":\"Root=1-65255c4f-18d3a63f0003360c506c1314;Parent=753514eb0b2b1662;Sampled=0;Lineage=bb56b18c:0\",\"client_context\":null,\"identity\":null,\"env_config\":{\"function_name\":\"internal-ingest-api\",\"memory\":1769,\"version\":\"$LATEST\",\"log_stream\":\"\",\"log_group\":\"\"}}"}, "query_params": {}, "body": "{\"version\":\"0\",\"id\":\"057e176e-42c2-5842-5cb8-5ee36040c1d7\",\"detail-type\":\"skm.customer_onboarding.customer.updated.v1\",\"source\":\"skm.customer_onboarding\",\"account\":\"545294100382\",\"time\":\"2023-10-10T14:14:39Z\",\"region\":\"eu-west-2\",\"resources\":[],\"detail\":{\"specversion\":\"1.0\",\"dataschema\":null,\"type\":\"skm.customer_onboarding.customer.updated.v1\",\"source\":\"skm.customer_onboarding\",\"id\":\"065255c4-f024-7ec5-8000-35cd99d529e4\",\"subject\":null,\"time\":\"2023-10-10 14:14:39.009049+00:00\",\"data\":{\"update_reasons\":[\"NICKNAME_CHANGED\"],\"customer\":{\"customer_id\":\"0651ab16-472d-71f1-8000-9fe5457c7be3\",\"owner_ref\":\"user-test-cf04e54c-8546-4425-b56d-e064bba55e1c\",\"owner_email\":\"egecas+2@pm.me\",\"nickname\":\"jfk\",\"created_at\":\"2023-10-02 12:02:44.448566+00:00\",\"updated_at\":\"2023-10-10 14:14:39.008955+00:00\"}},\"datacontenttype\":\"application/json\"}}", "sender_ip_address": "18.135.181.193", "sender_port": 0, "received_at": "2023-10-10 14:14:42.281826+00:00"}}

2023-10-10T14:14:42.283Z    {"log_level": "DEBUG", "message": "Event before-parameter-build.s3.DeleteObjects: calling handler <function validate_bucket_name at 0x7f0dbd3b77f0>", "timestamp": "2023-10-10 14:14:42.283491+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.284Z    {"log_level": "DEBUG", "message": "Event before-parameter-build.s3.DeleteObjects: calling handler <function remove_bucket_from_url_paths_from_model at 0x7f0dbd1d1630>", "timestamp": "2023-10-10 14:14:42.283965+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.284Z    {"log_level": "DEBUG", "message": "Event before-parameter-build.s3.DeleteObject: calling handler <function validate_bucket_name at 0x7f0dbd3b77f0>", "timestamp": "2023-10-10 14:14:42.284356+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.284Z    {"log_level": "DEBUG", "message": "Event before-parameter-build.s3.DeleteObjects: calling handler <bound method S3RegionRedirectorv2.annotate_request_context of <botocore.utils.S3RegionRedirectorv2 object at 0x7f0dba2ff340>>", "timestamp": "2023-10-10 14:14:42.284495+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.284Z    {"log_level": "DEBUG", "message": "Event before-parameter-build.s3.DeleteObjects: calling handler <function generate_idempotent_uuid at 0x7f0dbd3b7640>", "timestamp": "2023-10-10 14:14:42.284782+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.285Z    {"log_level": "DEBUG", "message": "Event before-parameter-build.s3.DeleteObject: calling handler <function remove_bucket_from_url_paths_from_model at 0x7f0dbd1d1630>", "timestamp": "2023-10-10 14:14:42.284632+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.285Z    {"log_level": "DEBUG", "message": "Event before-endpoint-resolution.s3: calling handler <function customize_endpoint_resolver_builtins at 0x7f0dbd1d17e0>", "timestamp": "2023-10-10 14:14:42.284952+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.285Z    {"log_level": "DEBUG", "message": "Event before-parameter-build.s3.DeleteObject: calling handler <bound method S3RegionRedirectorv2.annotate_request_context of <botocore.utils.S3RegionRedirectorv2 object at 0x7f0dba2ff340>>", "timestamp": "2023-10-10 14:14:42.285109+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.285Z    {"log_level": "DEBUG", "message": "Event before-endpoint-resolution.s3: calling handler <bound method S3RegionRedirectorv2.redirect_from_cache of <botocore.utils.S3RegionRedirectorv2 object at 0x7f0dba2ff340>>", "timestamp": "2023-10-10 14:14:42.285254+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.285Z    {"log_level": "DEBUG", "message": "Event before-parameter-build.s3.DeleteObject: calling handler <function generate_idempotent_uuid at 0x7f0dbd3b7640>", "timestamp": "2023-10-10 14:14:42.285371+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.286Z    {"log_level": "DEBUG", "message": "Calling endpoint provider with parameters: {'Bucket': 'events-internal-4k1', 'Region': 'eu-west-2', 'UseFIPS': False, 'UseDualStack': False, 'ForcePathStyle': False, 'Accelerate': False, 'UseGlobalEndpoint': False, 'DisableMultiRegionAccessPoints': False, 'UseArnRegion': True}", "timestamp": "2023-10-10 14:14:42.285693+00:00", "function_name": "construct_endpoint", "line_number": 498, "module_name": "regions", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/regions.py"}

2023-10-10T14:14:42.287Z    {"log_level": "DEBUG", "message": "Event before-endpoint-resolution.s3: calling handler <function customize_endpoint_resolver_builtins at 0x7f0dbd1d17e0>", "timestamp": "2023-10-10 14:14:42.285919+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.287Z    {"log_level": "DEBUG", "message": "Endpoint provider result: https://events-internal-4k1.s3.eu-west-2.amazonaws.com", "timestamp": "2023-10-10 14:14:42.287052+00:00", "function_name": "construct_endpoint", "line_number": 513, "module_name": "regions", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/regions.py"}

2023-10-10T14:14:42.287Z    {"log_level": "DEBUG", "message": "Event before-endpoint-resolution.s3: calling handler <bound method S3RegionRedirectorv2.redirect_from_cache of <botocore.utils.S3RegionRedirectorv2 object at 0x7f0dba2ff340>>", "timestamp": "2023-10-10 14:14:42.287223+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.287Z    {"log_level": "DEBUG", "message": "Selecting from endpoint provider's list of auth schemes: \"sigv4\". User selected auth scheme is: \"None\"", "timestamp": "2023-10-10 14:14:42.287365+00:00", "function_name": "auth_schemes_to_signing_ctx", "line_number": 660, "module_name": "regions", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/regions.py"}

2023-10-10T14:14:42.287Z    {"log_level": "DEBUG", "message": "Calling endpoint provider with parameters: {'Bucket': 'events-internal-4k1', 'Region': 'eu-west-2', 'UseFIPS': False, 'UseDualStack': False, 'ForcePathStyle': False, 'Accelerate': False, 'UseGlobalEndpoint': False, 'DisableMultiRegionAccessPoints': False, 'UseArnRegion': True}", "timestamp": "2023-10-10 14:14:42.287593+00:00", "function_name": "construct_endpoint", "line_number": 498, "module_name": "regions", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/regions.py"}

2023-10-10T14:14:42.287Z    {"log_level": "DEBUG", "message": "Selected auth type \"v4\" as \"v4\" with signing context params: {'region': 'eu-west-2', 'signing_name': 's3', 'disableDoubleEncoding': True}", "timestamp": "2023-10-10 14:14:42.287726+00:00", "function_name": "auth_schemes_to_signing_ctx", "line_number": 733, "module_name": "regions", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/regions.py"}

2023-10-10T14:14:42.288Z    {"log_level": "DEBUG", "message": "Endpoint provider result: https://events-internal-4k1.s3.eu-west-2.amazonaws.com", "timestamp": "2023-10-10 14:14:42.287881+00:00", "function_name": "construct_endpoint", "line_number": 513, "module_name": "regions", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/regions.py"}

2023-10-10T14:14:42.288Z    {"log_level": "DEBUG", "message": "Event before-call.s3.DeleteObjects: calling handler <function escape_xml_payload at 0x7f0dbd3b7370>", "timestamp": "2023-10-10 14:14:42.288637+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.289Z    {"log_level": "DEBUG", "message": "Selecting from endpoint provider's list of auth schemes: \"sigv4\". User selected auth scheme is: \"None\"", "timestamp": "2023-10-10 14:14:42.288802+00:00", "function_name": "auth_schemes_to_signing_ctx", "line_number": 660, "module_name": "regions", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/regions.py"}

2023-10-10T14:14:42.289Z    {"log_level": "DEBUG", "message": "Event before-call.s3.DeleteObjects: calling handler <function add_expect_header at 0x7f0dbd3b7b50>", "timestamp": "2023-10-10 14:14:42.288938+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.289Z    {"log_level": "DEBUG", "message": "Event before-call.s3.DeleteObjects: calling handler <function add_recursion_detection_header at 0x7f0dbd3b72e0>", "timestamp": "2023-10-10 14:14:42.289195+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.289Z    {"log_level": "DEBUG", "message": "Selected auth type \"v4\" as \"v4\" with signing context params: {'region': 'eu-west-2', 'signing_name': 's3', 'disableDoubleEncoding': True}", "timestamp": "2023-10-10 14:14:42.289089+00:00", "function_name": "auth_schemes_to_signing_ctx", "line_number": 733, "module_name": "regions", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/regions.py"}

2023-10-10T14:14:42.289Z    {"log_level": "DEBUG", "message": "Event before-call.s3.DeleteObjects: calling handler <function inject_api_version_header_if_needed at 0x7f0dbd1d0ee0>", "timestamp": "2023-10-10 14:14:42.289306+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.290Z    {"log_level": "DEBUG", "message": "Event before-call.s3.DeleteObject: calling handler <function add_expect_header at 0x7f0dbd3b7b50>", "timestamp": "2023-10-10 14:14:42.289754+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.290Z    {"log_level": "DEBUG", "message": "Making request for OperationModel(name=DeleteObjects) with params: {'url_path': '?delete', 'query_string': {}, 'method': 'POST', 'headers': {'User-Agent': 'Boto3/1.28.62 md/Botocore#1.31.62 ua/2.0 os/linux#4.14.255-318-256.530.amzn2.x86_64 md/arch#x86_64 lang/python#3.10.12 md/pyimpl#CPython exec-env/AWS_Lambda_Image cfg/retry-mode#legacy Botocore/1.31.62', 'Content-MD5': 'QOanHYlcq1i6fQEI6VnSxQ=='}, 'body': b'<Delete xmlns=\"http://s3.amazonaws.com/doc/2006-03-01/\"><Object><Key>events-index/status/VIABLE/065255c5-2485-7534-8000-8769c1500e6d</Key></Object><Object><Key>events-index/status/UNEXPECTED/065255c5-2485-7534-8000-8769c1500e6d</Key></Object><Object><Key>events-index/status/DISABLED/065255c5-2485-7534-8000-8769c1500e6d</Key></Object><Object><Key>events-index/status/INVALID/065255c5-2485-7534-8000-8769c1500e6d</Key></Object><Quiet>true</Quiet></Delete>', 'auth_path': '/events-internal-4k1/', 'url': 'https://events-internal-4k1.s3.eu-west-2.amazonaws.com/?delete', 'context': {'client_region': 'eu-west-2', 'client_config': <botocore.config.Config object at 0x7f0dba4c4f70>, 'has_streaming_input': False, 'auth_type': 'v4', 's3_redirect': {'redirected': False, 'bucket': 'events-internal-4k1', 'params': {'Bucket': 'events-internal-4k1', 'Delete': {'Objects': [{'Key': 'events-index/status/VIABLE/065255c5-2485-7534-8000-8769c1500e6d'}, {'Key': 'events-index/status/UNEXPECTED/065255c5-2485-7534-8000-8769c1500e6d'}, {'Key': 'events-index/status/DISABLED/065255c5-2485-7534-8000-8769c1500e6d'}, {'Key': 'events-index/status/INVALID/065255c5-2485-7534-8000-8769c1500e6d'}], 'Quiet': True}}}, 'signing': {'region': 'eu-west-2', 'signing_name': 's3', 'disableDoubleEncoding': True}, 'checksum': {'request_algorithm': 'conditional-md5'}}}", "timestamp": "2023-10-10 14:14:42.289963+00:00", "function_name": "make_request", "line_number": 114, "module_name": "endpoint", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py"}

2023-10-10T14:14:42.290Z    {"log_level": "DEBUG", "message": "Event before-call.s3.DeleteObject: calling handler <function add_recursion_detection_header at 0x7f0dbd3b72e0>", "timestamp": "2023-10-10 14:14:42.290098+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.290Z    {"log_level": "DEBUG", "message": "Event request-created.s3.DeleteObjects: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7f0dba4c4ee0>>", "timestamp": "2023-10-10 14:14:42.290518+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.290Z    {"log_level": "DEBUG", "message": "Event before-call.s3.DeleteObject: calling handler <function inject_api_version_header_if_needed at 0x7f0dbd1d0ee0>", "timestamp": "2023-10-10 14:14:42.290656+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.291Z    {"log_level": "DEBUG", "message": "Event choose-signer.s3.DeleteObjects: calling handler <function set_operation_specific_signer at 0x7f0dbd3b7520>", "timestamp": "2023-10-10 14:14:42.290874+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.291Z    {"log_level": "DEBUG", "message": "Making request for OperationModel(name=DeleteObject) with params: {'url_path': '/events-index/received-at/2023/10/10/14/14/42/065255c5-2485-7534-8000-8769c1500e6d', 'query_string': {}, 'method': 'DELETE', 'headers': {'User-Agent': 'Boto3/1.28.62 md/Botocore#1.31.62 ua/2.0 os/linux#4.14.255-318-256.530.amzn2.x86_64 md/arch#x86_64 lang/python#3.10.12 md/pyimpl#CPython exec-env/AWS_Lambda_Image cfg/retry-mode#legacy Botocore/1.31.62'}, 'body': b'', 'auth_path': '/events-internal-4k1/events-index/received-at/2023/10/10/14/14/42/065255c5-2485-7534-8000-8769c1500e6d', 'url': 'https://events-internal-4k1.s3.eu-west-2.amazonaws.com/events-index/received-at/2023/10/10/14/14/42/065255c5-2485-7534-8000-8769c1500e6d', 'context': {'client_region': 'eu-west-2', 'client_config': <botocore.config.Config object at 0x7f0dba4c4f70>, 'has_streaming_input': False, 'auth_type': 'v4', 's3_redirect': {'redirected': False, 'bucket': 'events-internal-4k1', 'params': {'Bucket': 'events-internal-4k1', 'Key': 'events-index/received-at/2023/10/10/14/14/42/065255c5-2485-7534-8000-8769c1500e6d'}}, 'signing': {'region': 'eu-west-2', 'signing_name': 's3', 'disableDoubleEncoding': True}}}", "timestamp": "2023-10-10 14:14:42.291020+00:00", "function_name": "make_request", "line_number": 114, "module_name": "endpoint", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py"}

2023-10-10T14:14:42.291Z    {"log_level": "DEBUG", "message": "Event before-sign.s3.DeleteObjects: calling handler <function remove_arn_from_signing_path at 0x7f0dbd1d1750>", "timestamp": "2023-10-10 14:14:42.291241+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.292Z    {"log_level": "DEBUG", "message": "Event request-created.s3.DeleteObject: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7f0dba4c4ee0>>", "timestamp": "2023-10-10 14:14:42.291626+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.292Z    {"log_level": "DEBUG", "message": "Calculating signature using v4 auth.", "timestamp": "2023-10-10 14:14:42.292222+00:00", "function_name": "add_auth", "line_number": 425, "module_name": "auth", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/auth.py"}

2023-10-10T14:14:42.292Z    {"log_level": "DEBUG", "message": "Event choose-signer.s3.DeleteObject: calling handler <function set_operation_specific_signer at 0x7f0dbd3b7520>", "timestamp": "2023-10-10 14:14:42.292520+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.293Z    {"log_level": "DEBUG", "message": "CanonicalRequest: POST / delete= content-md5:QOanHYlcq1i6fQEI6VnSxQ== host:events-internal-4k1.s3.eu-west-2.amazonaws.com x-amz-content-sha256:d89a9be32198e873f7188349e98938667fa2be823bf3f639e66d6f7110fdb482 x-amz-date:20231010T141442Z x-amz-security-token:REDACTED content-md5;host;x-amz-content-sha256;x-amz-date;x-amz-security-token REDACTED", "timestamp": "2023-10-10 14:14:42.292663+00:00", "function_name": "add_auth", "line_number": 426, "module_name": "auth", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/auth.py"}

2023-10-10T14:14:42.293Z    {"log_level": "DEBUG", "message": "Event before-sign.s3.DeleteObject: calling handler <function remove_arn_from_signing_path at 0x7f0dbd1d1750>", "timestamp": "2023-10-10 14:14:42.293058+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.293Z    {"log_level": "DEBUG", "message": "StringToSign:\nAWS4-HMAC-SHA256\n20231010T141442Z\n20231010/eu-west-2/s3/aws4_request\n821bfc45b0fcd19a263ef40279808b453decaac7d0dfe148f7b4b704f7ddb839", "timestamp": "2023-10-10 14:14:42.293247+00:00", "function_name": "add_auth", "line_number": 428, "module_name": "auth", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/auth.py"}

2023-10-10T14:14:42.293Z    {"log_level": "DEBUG", "message": "Calculating signature using v4 auth.", "timestamp": "2023-10-10 14:14:42.293607+00:00", "function_name": "add_auth", "line_number": 425, "module_name": "auth", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/auth.py"}

2023-10-10T14:14:42.294Z    {"log_level": "DEBUG", "message": "Signature:\na6ebf23c9cd4032b5c8eab0d20cef5725f54effdb0d24ec0a17b6a394db99ad0", "timestamp": "2023-10-10 14:14:42.293809+00:00", "function_name": "add_auth", "line_number": 430, "module_name": "auth", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/auth.py"}

2023-10-10T14:14:42.294Z    {"log_level": "DEBUG", "message": "CanonicalRequest: DELETE /events-index/received-at/2023/10/10/14/14/42/065255c5-2485-7534-8000-8769c1500e6d host:events-internal-4k1.s3.eu-west-2.amazonaws.com x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 x-amz-date:20231010T141442Z x-amz-security-token:REDACTED host;x-amz-content-sha256;x-amz-date;x-amz-security-token REDACTED", "timestamp": "2023-10-10 14:14:42.293924+00:00", "function_name": "add_auth", "line_number": 426, "module_name": "auth", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/auth.py"}

2023-10-10T14:14:42.294Z    {"log_level": "DEBUG", "message": "Event request-created.s3.DeleteObjects: calling handler <function add_retry_headers at 0x7f0dbd1d15a0>", "timestamp": "2023-10-10 14:14:42.294148+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.294Z    {"log_level": "DEBUG", "message": "StringToSign:\nAWS4-HMAC-SHA256\n20231010T141442Z\n20231010/eu-west-2/s3/aws4_request\n865c88e2310becadbc800f731887a491ddb4b71a33e47681242c9f6c876f23f1", "timestamp": "2023-10-10 14:14:42.294319+00:00", "function_name": "add_auth", "line_number": 428, "module_name": "auth", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/auth.py"}

2023-10-10T14:14:42.294Z    {"log_level": "DEBUG", "message": "Sending http request: <AWSPreparedRequest stream_output=False, method=POST, url=https://events-internal-4k1.s3.eu-west-2.amazonaws.com/?delete, headers={'User-Agent': b'Boto3/1.28.62 md/Botocore#1.31.62 ua/2.0 os/linux#4.14.255-318-256.530.amzn2.x86_64 md/arch#x86_64 lang/python#3.10.12 md/pyimpl#CPython exec-env/AWS_Lambda_Image cfg/retry-mode#legacy Botocore/1.31.62', 'Content-MD5': b'QOanHYlcq1i6fQEI6VnSxQ==', 'X-Amz-Date': b'20231010T141442Z', 'X-Amz-Security-Token': 'REDACTED', 'X-Amz-Content-SHA256': b'd89a9be32198e873f7188349e98938667fa2be823bf3f639e66d6f7110fdb482', 'Authorization': b'AWS4-HMAC-SHA256 Credential=REDACTED/20231010/eu-west-2/s3/aws4_request, SignedHeaders=content-md5;host;x-amz-content-sha256;x-amz-date;x-amz-security-token, Signature=a6ebf23c9cd4032b5c8eab0d20cef5725f54effdb0d24ec0a17b6a394db99ad0', 'amz-sdk-invocation-id': b'8edc16d0-2a00-4db7-bde6-5586af0da7ea', 'amz-sdk-request': b'attempt=1', 'Content-Length': '455'}>", "timestamp": "2023-10-10 14:14:42.294539+00:00", "function_name": "_do_get_response", "line_number": 265, "module_name": "endpoint", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py"}

2023-10-10T14:14:42.295Z    {"log_level": "DEBUG", "message": "Signature:\ne43f12d7f685b020d2b4f217ff2fc2722e9932d2c2440fda1f533cb6ab901cbc", "timestamp": "2023-10-10 14:14:42.294821+00:00", "function_name": "add_auth", "line_number": 430, "module_name": "auth", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/auth.py"}

2023-10-10T14:14:42.295Z    {"log_level": "DEBUG", "message": "Certificate path: /usr/local/lib/python3.10/site-packages/certifi/cacert.pem", "timestamp": "2023-10-10 14:14:42.295392+00:00", "function_name": "get_cert_path", "line_number": 97, "module_name": "httpsession", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/httpsession.py"}

2023-10-10T14:14:42.297Z    {"log_level": "DEBUG", "message": "Event request-created.s3.DeleteObject: calling handler <function add_retry_headers at 0x7f0dbd1d15a0>", "timestamp": "2023-10-10 14:14:42.295604+00:00", "function_name": "_emit", "line_number": 238, "module_name": "hooks", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/hooks.py"}

2023-10-10T14:14:42.297Z    {"log_level": "DEBUG", "message": "Starting new HTTPS connection (1): events-internal-4k1.s3.eu-west-2.amazonaws.com:443", "timestamp": "2023-10-10 14:14:42.297455+00:00", "function_name": "_new_conn", "line_number": 1048, "module_name": "connectionpool", "module_path": "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py"}

2023-10-10T14:14:42.298Z    {"log_level": "DEBUG", "message": "Sending http request: <AWSPreparedRequest stream_output=False, method=DELETE, url=https://events-internal-4k1.s3.eu-west-2.amazonaws.com/events-index/received-at/2023/10/10/14/14/42/065255c5-2485-7534-8000-8769c1500e6d, headers={'User-Agent': b'Boto3/1.28.62 md/Botocore#1.31.62 ua/2.0 os/linux#4.14.255-318-256.530.amzn2.x86_64 md/arch#x86_64 lang/python#3.10.12 md/pyimpl#CPython exec-env/AWS_Lambda_Image cfg/retry-mode#legacy Botocore/1.31.62', 'X-Amz-Date': b'20231010T141442Z', 'X-Amz-Security-Token': 'REDACTED', 'X-Amz-Content-SHA256': b'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855', 'Authorization': b'AWS4-HMAC-SHA256 Credential=REDACTED/20231010/eu-west-2/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date;x-amz-security-token, Signature=e43f12d7f685b020d2b4f217ff2fc2722e9932d2c2440fda1f533cb6ab901cbc', 'amz-sdk-invocation-id': b'd9a1ae14-c823-4306-a6f4-82e1dc3efcd3', 'amz-sdk-request': b'attempt=1', 'Content-Length': '0'}>", "timestamp": "2023-10-10 14:14:42.297788+00:00", "function_name": "_do_get_response", "line_number": 265, "module_name": "endpoint", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py"}

2023-10-10T14:14:42.298Z    {"log_level": "DEBUG", "message": "Certificate path: /usr/local/lib/python3.10/site-packages/certifi/cacert.pem", "timestamp": "2023-10-10 14:14:42.298559+00:00", "function_name": "get_cert_path", "line_number": 97, "module_name": "httpsession", "module_path": "/usr/local/lib/python3.10/site-packages/botocore/httpsession.py"}

2023-10-10T14:14:42.298Z    {"log_level": "DEBUG", "message": "Starting new HTTPS connection (2): events-internal-4k1.s3.eu-west-2.amazonaws.com:443", "timestamp": "2023-10-10 14:14:42.298855+00:00", "function_name": "_new_conn", "line_number": 1048, "module_name": "connectionpool", "module_path": "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py"}
sidekick-eimantas commented 11 months ago

Ok gents, I was able to reproduce it without uvicorn, or fastapi. Here's the code:

import faulthandler
faulthandler.enable()
import asyncio
import boto3

async def _sts() -> None:
    print("Start", flush=True)
    _sts_client = boto3.Session().client(service_name="sts")
    await asyncio.gather(
        asyncio.to_thread(_sts_client.get_caller_identity),
        asyncio.to_thread(_sts_client.get_caller_identity),
        asyncio.to_thread(_sts_client.get_caller_identity),
        asyncio.to_thread(_sts_client.get_caller_identity),
        asyncio.to_thread(_sts_client.get_caller_identity),
    )
    print("Done", flush=True)

asyncio.run(_sts())
  | 2023-10-11T22:19:10.365+01:00 | Start
  | 2023-10-11T22:19:10.822+01:00 | Fatal Python error: Segmentation fault
  | 2023-10-11T22:19:10.822+01:00 | Thread 0x00007f78deffd6c0 (most recent call first):
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 1342 in do_handshake
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 1071 in _create
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 513 in wrap_socket
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/util/ssl_.py", line 513 in _ssl_wrap_socket_impl
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/util/ssl_.py", line 469 in ssl_wrap_socket
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 783 in _ssl_wrap_socket_and_match_hostname
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 642 in connect
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 1092 in _validate_conn
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 467 in _make_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 790 in urlopen
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/httpsession.py", line 465 in send
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 377 in _send
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 281 in _do_get_response
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 241 in _get_response
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 199 in _send_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 119 in make_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 986 in _make_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 963 in _make_api_call
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 535 in _api_call
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58 in run
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 83 in _worker
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/threading.py", line 953 in run
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/threading.py", line 1016 in _bootstrap_inner
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/threading.py", line 973 in _bootstrap
  | 2023-10-11T22:19:10.822+01:00 | Thread 0x00007f78df7fe6c0 (most recent call first):
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 1342 in do_handshake
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 1071 in _create
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 513 in wrap_socket
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/util/ssl_.py", line 513 in _ssl_wrap_socket_impl
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/util/ssl_.py", line 469 in ssl_wrap_socket
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 783 in _ssl_wrap_socket_and_match_hostname
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 642 in connect
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 1092 in _validate_conn
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 467 in _make_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 790 in urlopen
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/httpsession.py", line 465 in send
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 377 in _send
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 281 in _do_get_response
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 241 in _get_response
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 199 in _send_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 119 in make_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 986 in _make_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 963 in _make_api_call
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 535 in _api_call
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58 in run
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 83 in _worker
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/threading.py", line 953 in run
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/threading.py", line 1016 in _bootstrap_inner
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/threading.py", line 973 in _bootstrap
  | 2023-10-11T22:19:10.822+01:00 | Thread 0x00007f78dffff6c0 (most recent call first):
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 1342 in do_handshake
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 1071 in _create
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 513 in wrap_socket
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/util/ssl_.py", line 513 in _ssl_wrap_socket_impl
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/util/ssl_.py", line 469 in ssl_wrap_socket
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 783 in _ssl_wrap_socket_and_match_hostname
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 642 in connect
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 1092 in _validate_conn
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 467 in _make_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 790 in urlopen
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/httpsession.py", line 465 in send
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 377 in _send
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 281 in _do_get_response
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 241 in _get_response
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 199 in _send_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 119 in make_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 986 in _make_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 963 in _make_api_call
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 535 in _api_call
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58 in run
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 83 in _worker
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/threading.py", line 953 in run
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/threading.py", line 1016 in _bootstrap_inner
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/threading.py", line 973 in _bootstrap
  | 2023-10-11T22:19:10.822+01:00 | Thread 0x00007f78e4f816c0 (most recent call first):
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 1342 in do_handshake
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 1071 in _create
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 513 in wrap_socket
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/util/ssl_.py", line 513 in _ssl_wrap_socket_impl
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/util/ssl_.py", line 469 in ssl_wrap_socket
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 783 in _ssl_wrap_socket_and_match_hostname
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 642 in connect
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 1092 in _validate_conn
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 467 in _make_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 790 in urlopen
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/httpsession.py", line 465 in send
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 377 in _send
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 281 in _do_get_response
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 241 in _get_response
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 199 in _send_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 119 in make_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 986 in _make_request
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 963 in _make_api_call
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 535 in _api_call
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58 in run
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 83 in _worker
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/threading.py", line 953 in run
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/threading.py", line 1016 in _bootstrap_inner
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/threading.py", line 973 in _bootstrap
  | 2023-10-11T22:19:10.822+01:00 | Current thread 0x00007f78e57826c0 (most recent call first):
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 1342 in do_handshake
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 1071 in _create
  | 2023-10-11T22:19:10.822+01:00 | File "/usr/local/lib/python3.10/ssl.py", line 513 in wrap_socket
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/util/ssl_.py", line 513 in _ssl_wrap_socket_impl
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/util/ssl_.py", line 469 in ssl_wrap_socket
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 783 in _ssl_wrap_socket_and_match_hostname
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connection.py", line 642 in connect
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 1092 in _validate_conn
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 467 in _make_request
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/urllib3/connectionpool.py", line 790 in urlopen
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/httpsession.py", line 465 in send
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 377 in _send
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 281 in _do_get_response
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 241 in _get_response
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 199 in _send_request
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/endpoint.py", line 119 in make_request
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 986 in _make_request
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 963 in _make_api_call
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/botocore/client.py", line 535 in _api_call
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58 in run
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 83 in _worker
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/threading.py", line 953 in run
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/threading.py", line 1016 in _bootstrap_inner
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/threading.py", line 973 in _bootstrap
  | 2023-10-11T22:19:10.823+01:00 | Thread 0x00007f78e733cb80 (most recent call first):
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/selectors.py", line 469 in select
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/asyncio/base_events.py", line 1871 in _run_once
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/asyncio/base_events.py", line 603 in run_forever
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/asyncio/base_events.py", line 636 in run_until_complete
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/asyncio/runners.py", line 44 in run
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/lib/python3.10/site-packages/event_gateway/__main__.py", line 23 in <module>
  | 2023-10-11T22:19:10.823+01:00 | File "<frozen importlib._bootstrap>", line 241 in _call_with_frames_removed
  | 2023-10-11T22:19:10.823+01:00 | File "<frozen importlib._bootstrap_external>", line 883 in exec_module
  | 2023-10-11T22:19:10.823+01:00 | File "<frozen importlib._bootstrap>", line 688 in _load_unlocked
  | 2023-10-11T22:19:10.823+01:00 | File "<frozen importlib._bootstrap>", line 1006 in _find_and_load_unlocked
  | 2023-10-11T22:19:10.823+01:00 | File "<frozen importlib._bootstrap>", line 1027 in _find_and_load
  | 2023-10-11T22:19:10.823+01:00 | File "/usr/local/bin/event-gateway", line 5 in <module>

I am unable to reproduce this locally neither on the machine itself, nor in Docker. I can only reproduce this in AWS Lambda. On top of that, I am only able reproduce it when AWS Lambda Web Adapter is enabled. It's a process separate to the service. The adapter is trying to hit /Healthz on the service around every 60ms. I suspected the adapter is pinning the CPU which causes this issue, so tried to reproduce it by pinning the CPU in python itself, with the adapter disabled:

import faulthandler

faulthandler.enable()

import asyncio
import threading

import boto3

def cpu_pinning_function():
    while True:
        x, y = 0, 1
        for _ in range(10000):
            x, y = y, x + y

async def _sts() -> None:
    print("Start", flush=True)
    _sts_client = boto3.Session().client(service_name="sts")
    await asyncio.gather(
        asyncio.to_thread(_sts_client.get_caller_identity),
        asyncio.to_thread(_sts_client.get_caller_identity),
        asyncio.to_thread(_sts_client.get_caller_identity),
        asyncio.to_thread(_sts_client.get_caller_identity),
        asyncio.to_thread(_sts_client.get_caller_identity),
    )
    print("Done", flush=True)

t1 = threading.Thread(target=cpu_pinning_function)
t1.daemon = True
t1.start()
asyncio.run(_sts())

Alas, that did not recreate the issue. Not sure if I'm pinning the CPU correctly here.

Before I found python was segfaulting, I had reported this as a potential adapter issue, for reference: https://github.com/awslabs/aws-lambda-web-adapter/issues/295

Let me know what else we should do to get more context.

Thank you

pquentin commented 11 months ago

Thanks! In this case interestingly all threads are in do_handshake, partially invalidating my previous theory. But having such a short reproducer is nice. The next step will be to remove boto3, requests, urllib3 and even http.client out of the picture I suspect.

How much memory do you allocate to your Lambda? It directly affects the vCPU-seconds available:

You can increase or decrease the memory and CPU power allocated to your function using the Memory (MB) setting. To configure the memory for your function, set a value between 128 MB and 10,240 MB in 1-MB increments. At 1,769 MB, a function has the equivalent of one vCPU (one vCPU-second of credits per second).

How easy is to test with OpenSSL 1.1.1?

(By the way we're not all gents.)

sidekick-eimantas commented 11 months ago

I am using a different api call here (sts.get_caller_identity, cheaper) than in the first post (s3.delete_object). Could that be affecting it? The segfault trace does look the same for each segfault, all terminating at do_handshake

I've reproduced this with 128MB, 512MB and 1769MB

I'm not versed in calling ssl directly. What is the closest function call we could make that might reproduce this?

I'll try and reproduce this with openssl 1.1.1 tonight.

Thanks !

sethmlarson commented 9 months ago

@sidekick-eimantas Has there been any progress on this front? Currently I'm not thinking this is an issue with urllib3 directly, instead with either CPython or OpenSSL and that an issue should be opened on one of those projects once we determine where it lays.

sethmlarson commented 9 months ago

Going to close this as no progress has been made and I think this isn't an issue in urllib3.