Blazor Server应用部署后首次登录因HttpMessageHandler清理挂起4分钟

问题概述 #

我们的Blazor Server应用部署完成后，首次有用户登录时偶尔会挂起约4分钟。运行环境包含两台带内部负载均衡的IIS服务器、数据库服务器以及Identity Server。从日志中仅能定位到疑似HttpMessageHandler清理流程导致该问题的线索。

相关日志信息 #

11:26:03.928 ServerName TRACE 授权过滤器：开始执行Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.AutoValidateAntiforgeryTokenAuthorizationFilter的OnAuthorizationAsync方法。
11:26:03.930 ServerName TRACE 授权过滤器：完成执行Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.AutoValidateAntiforgeryTokenAuthorizationFilter的OnAuthorizationAsync方法。
11:26:03.930 ServerName TRACE 资源过滤器：开始执行Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter的OnResourceExecuting方法。
11:26:03.931 ServerName TRACE 资源过滤器：完成执行Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter的OnResourceExecuting方法。
11:26:03.936 ServerName DEBUG 正在执行页面ServerProjectName.Pages.Pages__Host的页面模型工厂（ServerProjectName）
11:26:03.937 ServerName DEBUG 已完成页面ServerProjectName.Pages.Pages__Host的页面模型工厂执行（ServerProjectName）
11:26:03.942 ServerName TRACE 页面过滤器：开始执行Microsoft.AspNetCore.Mvc.Filters.PageHandlerPageFilter的OnPageHandlerSelectionAsync方法。
此处出现两分钟空白无日志
BEGIN: 4分钟间隔
11:28:04.198 ServerName DEBUG 客户端'HttpClientName'的HttpMessageHandler已过期，时长120000ms
11:28:14.212 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:28:14.218 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.1051ms - 已处理：0个项 - 剩余：1个项
11:28:24.232 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.0081ms - 已处理：0个项 - 剩余：1个项
11:28:24.232 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:28:34.248 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:28:34.248 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.0077ms - 已处理：0个项 - 剩余：1个项
11:28:44.264 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.0206ms - 已处理：0个项 - 剩余：1个项
11:28:44.264 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:28:54.279 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.0067ms - 已处理：0个项 - 剩余：1个项
11:28:54.279 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:29:04.295 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:29:04.300 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.0073ms - 已处理：0个项 - 剩余：1个项
11:29:14.295 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.0071ms - 已处理：0个项 - 剩余：1个项
11:29:14.295 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:29:24.310 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:29:24.311 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.0068ms - 已处理：0个项 - 剩余：1个项
11:29:34.311 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.0064ms - 已处理：0个项 - 剩余：1个项
11:29:34.311 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:29:44.326 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:29:44.326 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.0074ms - 已处理：0个项 - 剩余：1个项
11:29:54.342 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:29:54.342 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.0072ms - 已处理：0个项 - 剩余：1个项
11:30:04.357 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:30:04.361 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.006ms - 已处理：0个项 - 剩余：1个项
11:30:14.373 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:30:14.373 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.0069ms - 已处理：0个项 - 剩余：1个项
11:30:24.373 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
11:30:24.373 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.0064ms - 已处理：0个项 - 剩余：1个项
11:30:34.389 ServerName DEBUG HttpMessageHandler清理周期结束，耗时0.0071ms - 已处理：0个项 - 剩余：1个项
11:30:34.389 ServerName DEBUG 启动HttpMessageHandler清理周期，共1个项
END: 4分钟间隔
11:30:34.411 ServerName INFORMATION 请求开始 HTTP/1.1 GET https://site/welcome - -
11:30:34.412 ServerName TRACE 允许所有主机访问。
11:30:34.413 ServerName DEBUG 请求匹配到端点'/_Host'

排查建议 #

• 检查HttpClientName对应的HttpClient配置，确认HttpMessageHandler的生命周期设置是否合理，排查清理时是否存在阻塞逻辑
• 验证负载均衡环境下，首次请求时的HttpClient初始化或Handler清理是否存在跨服务器资源竞争、锁等待情况
• 梳理Identity Server与应用间的请求链路，确认首次登录的token获取流程中，HttpClient的Handler是否存在未正确释放的问题
• 查看IIS应用池的回收、空闲超时设置，确认是否与Handler过期时间（120000ms即2分钟）存在关联

内容的提问来源于stack exchange，提问作者Mohaaron