Cosmos DB Timeout and ServiceUnavailable Issue

[Monica-Ji]

Hi, we have db timeout and ServiceUnavailable issue, and have enabled the diagnotic setting, the exception is like this:

Microsoft.Azure.Cosmos.CosmosException : Response status code does not indicate success: ServiceUnavailable (503); Substatus: 20005; ActivityId: 873828f0-e41e-4626-b283-b73c12ca3bc5; Reason: (The request failed because the client was unable to establish connections to 1 endpoints across 1 regions. The client CPU has thread starvation.
ActivityId: 873828f0-e41e-4626-b283-b73c12ca3bc5, Microsoft.Azure.Cosmos.Tracing.TraceData.ClientSideRequestStatisticsTraceDatum, Windows/10.0.14393 cosmos-netstandard-sdk/3.28.1);
   at Microsoft.Azure.Documents.ShouldRetryResult.ThrowIfDoneTrying(ExceptionDispatchInfo capturedException)
   at Microsoft.Azure.Documents.RequestRetryUtility.ProcessRequestAsync[TRequest,IRetriableResponse
](Func`1 executeAsync, Func`1 prepareRequest, IRequestRetryPolicy`2 policy, CancellationToken cancellationToken, Func`1 inBackoffAlternateCallbackMethod, Nullable`1 minBackoffForInBackoffCallback)
   at Microsoft.Azure.Documents.StoreClient.ProcessMessageAsync(DocumentServiceRequest request, CancellationToken cancellationToken, IRetryPolicy retryPolicy, Func`2 prepareRequestAsyncDelegate)
   at Microsoft.Azure.Cosmos.Handlers.TransportHandler.ProcessMessageAsync(RequestMessage request, CancellationToken cancellationToken)
   at Microsoft.Azure.Cosmos.Handlers.TransportHandler.SendAsync(RequestMessage request, CancellationToken cancellationToken)
--- Cosmos Diagnostics ---{
    "Summary": {
        "DirectCalls": {
            "(404, 0)": 3,
            "(410, 20001)": 1
        },
        "RegionsContacted": 1
    },
    "name": "ReadItemAsync",
    "id": "ed557a55-7e40-45ed-85ad-4135c3030548",
    "start time": "08:00:54:069",
    "duration in milliseconds": 58531.2613,
    "data": {
        "Client Configuration": {
            "Client Created Time Utc": "2022-06-01T07:27:17.6897357Z",
            "MachineId": "hashedMachineName:7d2c37dd-d5d0-9dcd-65c0-c4d00186760f",
            "NumberOfClientsCreated": 2,
            "NumberOfActiveClients": 2,
            "User Agent": "cosmos-netstandard-sdk/3.27.1|2|X64|Microsoft Windows 10.0.14393|.NET Core 3.1.11|N|",
            "ConnectionConfig": {
                "gw": "(cps:50, urto:10, p:False, httpf: False)",
                "rntbd": "(cto: 5, icto: -1, mrpc: 30, mcpe: 65535, erd: True, pr: ReuseUnicastPort)",
                "other": "(ed:False, be:False)"
            },
            "ConsistencyConfig": "(consistency: NotSet, prgns:[], apprgn: )",
            "ProcessorCount": 0
        }
    },
    "children": [
        {
            "name": "Microsoft.Azure.Cosmos.Handlers.RequestInvokerHandler",
            "id": "13ad1077-c824-47e9-b544-30d9961ab789",
            "start time": "08:00:54:069",
            "duration in milliseconds": 58531.1562,
            "children": [
                {
                    "name": "Microsoft.Azure.Cosmos.Handlers.DiagnosticsHandler",
                    "id": "72e85095-0c71-454b-a1bd-58b9af1f0e33",
                    "start time": "08:00:54:069",
                    "duration in milliseconds": 58531.1317,
                    "data": {
                        "System Info": {
                            "systemHistory": [
                                {
                                    "dateUtc": "2022-06-08T08:00:32.0697452Z",
                                    "cpu": 6.836,
                                    "memory": 6565660.000,
                                    "threadInfo": {
                                        "isThreadStarving": "True",
                                        "threadWaitIntervalInMs": 31504.2279,
                                        "availableThreads": 32728,
                                        "minThreads": 4,
                                        "maxThreads": 32767
                                    },
                                    "numberOfOpenTcpConnection": 12
                                },
                                {
                                    "dateUtc": "2022-06-08T08:00:52.0661758Z",
                                    "cpu": 3.477,
                                    "memory": 6498208.000,
                                    "threadInfo": {
                                        "isThreadStarving": "True",
                                        "threadWaitIntervalInMs": 51500.6512,
                                        "availableThreads": 32708,
                                        "minThreads": 4,
                                        "maxThreads": 32767
                                    },
                                    "numberOfOpenTcpConnection": 12
                                },
                                {
                                    "dateUtc": "2022-06-08T08:01:12.0662877Z",
                                    "cpu": 7.344,
                                    "memory": 6495168.000,
                                    "threadInfo": {
                                        "isThreadStarving": "True",
                                        "threadWaitIntervalInMs": 71500.7214,
                                        "availableThreads": 32685,
                                        "minThreads": 4,
                                        "maxThreads": 32767
                                    },
                                    "numberOfOpenTcpConnection": 12
                                },
                                {
                                    "dateUtc": "2022-06-08T08:01:22.0683340Z",
                                    "cpu": 6.758,
                                    "memory": 6439828.000,
                                    "threadInfo": {
                                        "isThreadStarving": "True",
                                        "threadWaitIntervalInMs": 81502.7852,
                                        "availableThreads": 32675,
                                        "minThreads": 4,
                                        "maxThreads": 32767
                                    },
                                    "numberOfOpenTcpConnection": 12
                                },
                                {
                                    "dateUtc": "2022-06-08T08:01:33.5655346Z",
                                    "cpu": 4.654,
                                    "memory": 6414760.000,
                                    "threadInfo": {
                                        "isThreadStarving": "True",
                                        "threadWaitIntervalInMs": 92999.9555,
                                        "availableThreads": 32663,
                                        "minThreads": 4,
                                        "maxThreads": 32767
                                    },
                                    "numberOfOpenTcpConnection": 12
                                },
                                {
                                    "dateUtc": "2022-06-08T08:01:43.5811602Z",
                                    "cpu": 8.931,
                                    "memory": 6405784.000,
                                    "threadInfo": {
                                        "isThreadStarving": "True",
                                        "threadWaitIntervalInMs": 102125.7083,
                                        "availableThreads": 32735,
                                        "minThreads": 4,
                                        "maxThreads": 32767
                                    },
                                    "numberOfOpenTcpConnection": 15
                                }
                            ]
                        }
                    },"--TRUNCATED--

From this doc https://docs.microsoft.com/en-us/azure/cosmos-db/sql/troubleshoot-dot-net-sdk-request-timeout?tabs=cpu-new, I suppose it is a client side issue, I have two questions:

1. since the log is truncated, where can i find the log, like on the portal?
2. could this be a implement issue when we using cosmos db? if so, could you please provide some guidence on this about how to trouble shoot?

[chshihMSFT]

Thanks for asking.
Based on the CallStack you shared above, which says "isThreadStarving": "True".
It’s more related with client-side issue which blocked SDK create connection and communicate with Cosmos DB (server-side), thus you'll receive 408(Timeout), 503(ServiceUnavailable) errors.
The logs you shared have been truncated, it could be the log processing behavior in your code base (truncated after 8K characters maybe); so that we are unable to check detailed communication between client-side (Web App) and service-side (Cosmos DB) to narrow down the issue.

Please check the following suggestion and see if that works for you:

1. Check from App Service side.
   Review related Metrics to investigate platform health issue and see if there was High CPU / thread starvation, or SNAP Port exhaustion issue.
2. Review Application behavior:

• Ensure the application follows singleton pattern, prevent creating too many CosmosClient instances.
• Add parameters in CosmosClientOptions(), it could help you to identify the Application requests both on Log Analytics (Diagnostic Logs) and our backend telemetries.
• Add extra tracelog that you send to your team backend log store (Kusto), as well as reviewing where the TRUNCATED operation in your code base (log processing). Also ensure you can capture the full ResponseMessage.Diagnostics when handling this kind abnormal status codes.

3. Create a new support ticket to App service support team.
   They can help you to check platform issues and troubleshooting based on issue timestamp.

Some docs might help as well:
https://docs.microsoft.com/en-us/azure/cosmos-db/sql/troubleshoot-dot-net-sdk-request-timeout?tabs=cpu-new
https://docs.microsoft.com/en-us/azure/cosmos-db/sql/troubleshoot-service-unavailable
https://docs.microsoft.com/en-us/azure/cosmos-db/sql/troubleshoot-dot-net-sdk?tabs=diagnostics-v3