bug(curation api): 504 returned from GET collection and datasets

Bento007 commented 5 months ago

Describe the bug

When making requests to GET /v1/collection with and without an API Key, a 504 is returned about 50% of the time.

Error


Gateway Time-out

<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN" "http://www.w3.org/TR/html4/loose.dtd">
<HTML><HEAD><META HTTP-EQUIV="Content-Type" CONTENT="text/html; charset=iso-8859-1">
<TITLE>ERROR: The request could not be satisfied</TITLE>
</HEAD><BODY>
<H1>504 ERROR</H1>
<H2>The request could not be satisfied.</H2>
<HR noshade size="1px">
CloudFront attempted to establish a connection with the origin, but either the attempt failed or the origin closed the connection.
We can't connect to the server for this app or website at this time. There might be too much traffic or a configuration error. Try again later, or contact the app or website owner.
<BR clear="all">
If you provide content to customers through CloudFront, you can find steps to troubleshoot and help prevent this error by reviewing the CloudFront documentation.
<BR clear="all">
<HR noshade size="1px">
<PRE>
Generated by cloudfront (CloudFront)
Request ID: 2yXpvcNQKTOWmetxS34Ul-Vj8QK1J6TvOSvaVOx3THJOvMP2Y9ovzw==
</PRE>
<ADDRESS>
</ADDRESS>
</BODY></HTML>

x-request-id: None

To Reproduce

curl https://api.cellxgene.cziscience.com/curation/v1/collections

or curl https://api.cellxgene.cziscience.com/curation/v1/datasets

Expected behavior

the endpoints should never return a 504 under proper working conditions.

Environment

Curation API prod

Additional context

the cloudwatch request timeout is set to 60s
Looking at the logs in cloud watch, request to GET collection are taking up 78 second which is greater than the cloud watch timeout.
There is a keep-alive configuration in for the server set for 61 second which could be related
There were recent changes to the server configuration. Less CPU and memory. However looking at the CPU and memory activity there are no sign of running out of resources.
There was also a recent schema migration which would have added a lot more collections to our database.
in cloudwatch this filter was used to find slow endpoint {$.details.response_time > 60} and {$.request_id = "4c28ce0f-7ef5-402f-982a-b51c243b8aba"}. Here is one of the logs:

{
    "levelname": "INFO",
    "asctime": "2024-06-13T15:18:13.013Z",
    "name": "corpora-api-prod",
    "message": "",
    "lineno": 76,
    "pathname": "/single-cell-data-portal/backend/common/server/config.py",
    "request_id": "4c28ce0f-7ef5-402f-982a-b51c243b8aba",
    "type": "REQUEST",
    "details": {
        "url": "/curation/v1/collections",
        "method": "GET",
        "content_length": null
    }
}
{
    "levelname": "INFO",
    "asctime": "2024-06-13T15:19:20.013Z",
    "name": "corpora-api-prod",
    "message": "",
    "lineno": 88,
    "pathname": "/single-cell-data-portal/backend/common/server/config.py",
    "request_id": "4c28ce0f-7ef5-402f-982a-b51c243b8aba",
    "type": "RESPONSE",
    "details": {
        "status_code": 200,
        "content_length": 1617300,
        "response_time": 66.78523659706116
    }
}

Bento007 commented 5 months ago

The problem is still happening after the fixes. The metrics show that it's not the queries that are taking the longest. We should look closer at cloudfront to see if there is any caching we can do to improve the speed the same way we are doing it for the portal API.

Bento007 commented 5 months ago

After adding additional instrumentation to an rdev, the GET curation/v1/collections from the backend server returns in less than 10 seconds. This was after mirroring prod database to the rdev environment. Still 504 are returned and responses can take over 60 seconds to complete. The load balancer metrics do show a 504 is returned in the logs which should be our next target to investigate.

Bento007 commented 5 months ago

I've been using locust to test the system with this code. You'll need to grab the _oauth2_proxy token from the browser to run it if using an rdev.

from locust import HttpUser, task

class GetCollection(HttpUser):
    @task
    def hello_world(self):
        self.client.get(
            "/curation/v1/collections",
            cookies={"_oauth2_proxy": ""})

Bento007 commented 5 months ago

Here is an instance where is succeeded but still took upwards of 30 seconds from the browser.

    {
        "levelname": "INFO",
        "asctime": "2024-07-04T21:19:57.004Z",
        "name": "root",
        "message": "",
        "lineno": 89,
        "pathname": "/single-cell-data-portal/backend/common/utils/timer.py",
        "request_id": "5d37e959-f2e7-4416-be20-504f3663afed",
        "type": "METRIC",
        "details": {
            "group": "reshape_for_curation_api",
            "records": 223,
            "total_time": 5.167150974273682,
            "max_time": 0.42186570167541504,
            "min_time": 0.004987478256225586,
            "median_time": 0.012070894241333008,
            "_95th_percentile": 0.07090299129486065,
            "_99th_percentile": 0.18947099208831789,
            "unit": "seconds"
        }
    },
    {
        "levelname": "INFO",
        "asctime": "2024-07-04T21:19:58.004Z",
        "name": "corpora-api-rdev",
        "message": "",
        "lineno": 88,
        "pathname": "/single-cell-data-portal/backend/common/server/config.py",
        "request_id": "5d37e959-f2e7-4416-be20-504f3663afed",
        "type": "RESPONSE",
        "details": {
            "status_code": 200,
            "content_length": 2712878,
            "response_time": 6.117963790893555,
            "request": {
                "url": "/curation/v1/collections",
                "method": "GET"
            }
        }
    }

The logs show the backend server took 6 seconds to complete. This means that the load balancer is getting hung up on this response since rdev do not use cloudfront.

Request

GET https://pr-7217-backend.rdev.single-cell.czi.technology/curation/v1/collections?visibility=PUBLIC

Response Headers

Access-Control-Allow-Credentials: true
Access-Control-Allow-Origin: https://cellxgene.happy.dev.corpora.cziscience.com
Content-Length: 2712878
Content-Type: application/json
Date: Thu, 04 Jul 2024 21:25:04 GMT
Server: nginx/1.19.3
Vary: Origin
X-Request-Id: 4010cbfc-b112-4f5c-af8d-fd9c815ae65d

The response header shows that The returned payload was 2.7 MB and I don't think it is compressed.

chanzuckerberg / single-cell-data-portal