Skip to content

AWS Lambda times out because endless HttpMessageHandler cleanup #47672

@moravas

Description

@moravas

Hi,

I have a .net core 3.1 based AWS Lambda function with 5 min timeout, that performs some http download & data transform & db write.
The problem is that in same cases, and it is very nondeterministic, an HttpMessageHandler clean-up cycle is fired and the AWS Lambda will time-out. Below is the most recent running where the clean-up takes about 4 minute:

2021-01-30 05:14:58,902 [4] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - HttpMessageHandler expired after 120000ms for client ''
2021-01-30 05:15:08,903 [4] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:15:08,903 [4] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.002ms - processed: 0 items - remaining: 1 items
2021-01-30 05:15:18,904 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:15:18,905 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.002ms - processed: 0 items - remaining: 1 items
2021-01-30 05:15:28,922 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:15:28,923 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0024ms - processed: 0 items - remaining: 1 items
2021-01-30 05:15:38,925 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:15:38,926 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0022ms - processed: 0 items - remaining: 1 items
2021-01-30 05:15:48,926 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:15:48,927 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0021ms - processed: 0 items - remaining: 1 items
2021-01-30 05:15:58,927 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:15:58,927 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0023ms - processed: 0 items - remaining: 1 items
2021-01-30 05:16:08,927 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:16:08,927 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0018ms - processed: 0 items - remaining: 1 items
2021-01-30 05:16:18,928 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:16:18,928 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0023ms - processed: 0 items - remaining: 1 items
2021-01-30 05:16:28,929 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:16:28,929 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.002ms - processed: 0 items - remaining: 1 items
2021-01-30 05:16:38,927 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:16:38,927 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0019ms - processed: 0 items - remaining: 1 items
2021-01-30 05:16:48,928 [7] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:16:48,928 [7] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0021ms - processed: 0 items - remaining: 1 items
2021-01-30 05:16:58,928 [7] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:16:58,929 [7] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0021ms - processed: 0 items - remaining: 1 items
2021-01-30 05:17:08,929 [7] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:17:08,930 [7] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0022ms - processed: 0 items - remaining: 1 items
2021-01-30 05:17:18,931 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:17:18,931 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0023ms - processed: 0 items - remaining: 1 items
2021-01-30 05:17:28,931 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:17:28,931 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0024ms - processed: 0 items - remaining: 1 items
2021-01-30 05:17:38,933 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:17:38,934 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0024ms - processed: 0 items - remaining: 1 items
2021-01-30 05:17:48,934 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:17:48,935 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.002ms - processed: 0 items - remaining: 1 items
2021-01-30 05:17:58,943 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:17:58,943 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0018ms - processed: 0 items - remaining: 1 items
2021-01-30 05:18:08,945 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:18:08,946 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0023ms - processed: 0 items - remaining: 1 items
2021-01-30 05:18:18,947 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:18:18,947 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0021ms - processed: 0 items - remaining: 1 items
2021-01-30 05:18:28,948 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:18:28,949 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.002ms - processed: 0 items - remaining: 1 items
2021-01-30 05:18:38,950 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:18:38,950 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0026ms - processed: 0 items - remaining: 1 items
2021-01-30 05:18:48,951 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:18:48,951 [9] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0027ms - processed: 0 items - remaining: 1 items
2021-01-30 05:18:58,955 [7] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Starting HttpMessageHandler cleanup cycle with 1 items
2021-01-30 05:18:58,955 [7] DEBUG Microsoft.Extensions.Http.DefaultHttpClientFactory [(null)] - Ending HttpMessageHandler cleanup cycle after 0.0023ms - processed: 0 items - remaining: 1 items
END RequestId: 9af6e269-5aa7-5515-b32d-bae7b7fe2e95
REPORT RequestId: 9af6e269-5aa7-5515-b32d-bae7b7fe2e95	Duration: 300087.98 ms	Billed Duration: 300000 ms	Memory Size: 1024 MB	Max Memory Used: 261 MB

Below I try to collect the relevant part of my code how I use HTTPClient and IHTTPClientFactory:
I tried to disable HTTPMessageHandler rotation, as you see without success. Due to would be a short running AWS LAmbda function, I shouldn't lost any relevant functionlaty (DNS update)

Setting up DI:

      services.AddLogging();
      // Set LifeTime to infinite will disable handler rotation -> don't respond to DNS changes
      services.AddHttpClient<IDownloader, Downloader>().SetHandlerLifetime(Timeout.InfiniteTimeSpan);
      services.AddSingleton<ILoggerFactory>(loggerFactory);
      services.AddTransient<IDownloader, Downloader>();
      services.AddTransient<IReportParser, ReportParser>();

The Downloader's source:

    public class Downloader : IDownloader
    {
        private readonly ILogger<Downloader> _logger;
        private readonly IHttpClientFactory _clientFactory;
        public Downloader(ILogger<Downloader> logger, IHttpClientFactory clientFactory)
        {
            _logger = logger;
            _clientFactory = clientFactory;
        }
        public async Task<Stream> DownloadStream(Uri uri)
        {
            _logger.LogTrace(uri.ToString());
            var client = _clientFactory.CreateClient();
            return await client.GetStreamAsync(uri);
        }
    }

And it's usage:

    private readonly IDownloader _downloader;
    private readonly ILogger<ReportParser> _logger;
    public ReportParser(ILogger<ReportParser> logger, IDownloader downloader)
    {
        _logger = logger;
        _downloader = downloader;
    }

The environment:
Ubuntu 18.04
VS Code 1.52.1
.NET Core:
dotnet --info
.NET Core SDK (reflecting any global.json):
Version: 3.1.405
Commit: 3fae16e62e

Runtime Environment:
OS Name: ubuntu
OS Version: 18.04
OS Platform: Linux
RID: ubuntu.18.04-x64
Base Path: /usr/share/dotnet/sdk/3.1.405/

Host (useful for support):
Version: 3.1.11
Commit: f5eceb8105

.NET Core SDKs installed:
3.1.405 [/usr/share/dotnet/sdk]

.NET Core runtimes installed:
Microsoft.AspNetCore.App 3.1.11 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.NETCore.App 3.1.11 [/usr/share/dotnet/shared/Microsoft.NETCore.App]

To install additional .NET Core runtimes or SDKs:
https://aka.ms/dotnet-download

I see in another issues, that you askd for path-to-root diagrams and as I see it, it requires Windows environment. If this is required, please describe the how-to on Linux.
Can anybody help me what did I wrong? How to avoid this timeout?

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions