【2020.01.14】【诡异问题】记一次奇葩的404经历

环境：

　　.net core 2.1.1 + docker

背景：

　　故事是这样的，最近在写一个新项目，新项目呢需要调用老项目的一些逻辑，于是我们把老项目的相关逻辑，包装成了web api，给新项目调用，于是乎调用接口清晰如下图：

 在我们的新项目中，有2个操作一个负责修改，一个负责获取，他们都是需要向老项目发起http请求来执行的，我们姑且把老项目中的2个请求称之为 edit_url 和 get_url。

接下来神器的事情发生了。

现象：

　　新项目中调用了edit_url之后，再调用get_url，你会catch到一个404的异常，但是你之后多次调用get_url都不会有问题。

基本排查：

　　为何称之为神奇的事情！

　　1. 我们先在本地，将2个asp.net core项目通过vs debug启动起来，重复上述的步骤，根本无法复现。。。。

通过这种方式，当时已经一脸懵逼了，心想，不应该啊，本地好好的啊，怎么把2程序往docker上一发就会出现404呢。。。mmp哟

心想是不是docker哪里问题啊。。。iamge镜像版本是不是不对啊。。。。老项目的路由模板配置是否有问题啊。。。。。

结果坑次坑次查了好多，还是找不出原因。。。

　　2. 接下来还是打开fiddler抓个包吧，于是乎我将新项目通过vs debug启动，然后依次调用已部署在docker中的老项目中的接口:

edit_url->get_url (get_url报404)

然后继续get_url(成功有返回)

get_url->get_url->.....若干次（都成功有返回）

然后edit_url->get_url（get_url报404）

然后继续get_url(成功有返回)

get_url->get_url->.....若干次（都成功有返回）

........

看似很奇怪的规律，下意识觉得，是不是报404那次请求是不是报文哪里不对，核实了fiddler所抓的包，发现，报404的那次get_url请求，和成功的get_url请求，

所有的请求参数、请求url、content-type等信息都是一模一样，强调下哈，真的是一模一样，我发誓我没有眼瞎。调查到这边，心里又是一阵草泥马在狂奔。。。。。

　　3. 通过第2步的调查，心想还是去核实下老项目包装的web api所配置的路由模板吧，发现路由并没有定制化的处理，也没有同名的。。。这。。。。。。。

　　4. 不信邪了，我修改了老项目的appsetting.json中日志的配置，启用了日志功能，然后重新发布了容器，然后vs debug启动了新项目，重复了第2步的执行步骤

当发生了404之后，我docker logs看了下产生的日志，发现了类似 “...action....not match....”的日志信息，看到这里也觉得不应该啊，回忆了mvc框架里action的选择策略，应该都满足啊（http方法谓词、路由模板、特性路由），怎么就找不到action呢。。。。。

　　5. 后来我怀疑是不是IHttpClientFactory的问题，于是我在新项目里，发起调用的地方，换回了using(var client = new HttpClient())的写法，问题奇迹般的解决了。。。。但是面对这个现象，我无法给自己一个满意的解释，

于是，我同事在github上搜到了一个类似的问题https://github.com/aspnet/HttpClientFactory/issues/120 细看中。。。。。。。

　　6. 通过issue中的相关资料，我在老项目的startup.configure方法中，加了一段日志代码

app.Use(async (context, next) => {
            if(context.Request.Method == "") {
                string method = context.Request.Method;
                string path = context.Request.Path;

                IHttpRequestFeature requestFeature = context.Features.Get<IHttpRequestFeature>();
                string kestralHttpMethod = requestFeature.Method;
                string stop = path;
            }
            await next();
        });

把他放在所有的中间件使用之前（mvc本身也是以中间件的方式来使用的）。然后打上断点，居然惊奇的发现，method和kestralHttpMethod都为“”空字符串，什么情况，请求还没进到mvc中间件里，请求的method都被吃掉了

你让mvc框架怎么帮你去找action（方法谓词匹配），所以理所应当的报404。接下来再次通过fiddler来验证，这个method是在新项目发起前就被吃掉了。于是操作第2步，细看下发现，请求谓词都是有的，并没有被“吃掉”，

所以肯定不是新项目使用IHttpClientFactory导致的，问题点定位到了老项目接口。

　　7. 回过头看github上的issue评论，我整理下来是这样子的：

　　在asp.net core 2.1.1(我出问题的版本，后来的版本，微软有修复)，我们获取httpcontext的方法是通过注入IHttpContextAccessor接口来访问

而他的实现类是：

 我圈起来的地方值得注意(AsyncLocal是干嘛的，戳这里)，在这个版本下，aspnetcore，是通过asyncLocal来在异步线程之间共享HttpContext对象的，所以你如果开启了一个异步线程，那么理论上你能在该异步线程中，获取到发起请求的线程所创建的httpcontext对象。

　　8. 继续，翻阅评论，

他们在2.1里做了些改动，当请求的connection关闭的时候，会重置httpcontext的相关属性，回归于相对初始的状态， 通过resharper F12看一下

 用户请求的时候，所能访问的Method属性，间接来自于

 那么我这个问题，请求Method为空，肯定是因为“this.Method” 为None所导致的

因为method工具方法，只支持解析[0,8]之间的http请求类型而None却是255

 所以Method属性返回空字符串，那么回过头来讲，只会是Reset方法被触发了。

至此我们可以下一个结论，在当前我用的版本下（注意哈，以后版本微软有修复优化），导致Method为空字符串，间接导致mvc找action没找到报404的根本原因，肯定是因为上面描述的原因，简易成一句话就是：

“有一个后台线程，在不恰当的时候‘触摸’了HttpContext对象”

　　9. 怀着忐忑的心情，我去老项目的edit_url和get_url接口去看看，有没有‘后台线程’的影子，结果在edit_url的代码中，发现了有创建一个task，并在里面获取了HttpContext对象，后续我将其改成了‘同步’，并重复验证步骤2，

再也没有出现404了。

　　

　　回过头，我的老项目里，edit_url接口实现里，有个地方启用了一个task去做某事，其中涉及到访问httpcontext.request, 而edit_url请求connection已经close，进而会reset()，因为HttpContext不是线程安全的，可能新的请求，在执行的时候，已经Method被重置过了，进而MVC在执行action选择的时候404

总结：

1. 尽量升级core到最新LTS版本（我项目现在还在2.1，计划升级到3.0）来避免不必要的问题

2. 尽量不要在异步线程中获取httpcontext, 如需要用他的数据，最好先取出来，再丢进异步线程中去处理

3. 尽量不要通过静态变量去存储IHttpContextAccessor 实例，应该使用di的形式

相关资料：

https://www.poppastring.com/blog/avoiding-threading-issues-in-aspnet-core

https://github.com/aspnet/KestrelHttpServer/issues/2591

https://twitter.com/davidfowl/status/907248318538903553

https://docs.microsoft.com/en-us/aspnet/core/migration/claimsprincipal-current?view=aspnetcore-3.1#retrieve-the-current-user-in-an-aspnet-core-app

https://docs.microsoft.com/en-us/aspnet/core/fundamentals/http-context?view=aspnetcore-2.1