context canceled,谁是罪魁祸首?

nanjingfm · · 2658 次点击 · · 开始浏览    
这是一个创建于 的文章,其中的信息可能已经有所发展或是发生改变。

灵魂三问: 1. 客户端请求超时,取消了请求,服务端还会继续执行么? 2. 客户端请求超时,取消了请求,服务端还会返回结果么? 3. 客户端请求超时,取消了请求,服务端会报错么? # 问题现象 告警群里有告警,定位到报错的微服务看到如下报错:`Post http://ms-user-go.mp.online/user/listByIDs: context canceled`。 ![image-20211223104344170](https://bbk-images.oss-cn-shanghai.aliyuncs.com/typora/20211223104344.png) 项目中没有发现`cancel context`的代码,那么`context canceled`的错误是哪里来的? > 特别说明,这里讨论的`context`是指`gin Context`中的`Request Context` ![image-20211223164714302](https://bbk-images.oss-cn-shanghai.aliyuncs.com/typora/20211223164714.png) # 问题复现 ![image-20211223120759735](https://bbk-images.oss-cn-shanghai.aliyuncs.com/typora/20211223120759.png) - `client`请求`server1`时设置5s超时 - `server1`收到请求时先`sleep` 3秒,然后请求`server2`并设置5s超时 - `server2`收到请求时`sleep5`秒 画个时序图看的更直观(看完文章你会发现这是错的): ![image-20211223121138694](https://bbk-images.oss-cn-shanghai.aliyuncs.com/typora/20211223121138.png) 代码如下: client: ``` // client func main() { ctx, cancelFun := context.WithTimeout(context.Background(), time.Second*5) defer cancelFun() req, err := http.NewRequestWithContext(ctx, http.MethodGet, "http://127.0.0.1:8887/sleep/3", nil) if err != nil { panic(err) } do, err := http.DefaultClient.Do(req) spew.Dump(do, err) } ``` server 1: ``` // server 1 func main() { server := gin.New() server.GET("/sleep/:time", func(c *gin.Context) { t := c.Param("time") t1, _ := strconv.Atoi(t) time.Sleep(time.Duration(t1) * time.Second) ctx, cancelFun := context.WithTimeout(c.Request.Context(), time.Second*5) defer cancelFun() req, err := http.NewRequestWithContext(ctx, http.MethodGet, "http://127.0.0.1:8888/sleep/5", nil) if err != nil { panic(err) } do, err := http.DefaultClient.Do(req) spew.Dump(do, err) c.String(http.StatusOK, "sleep "+t) }) server.Run(":8887") } ``` Server 2: ``` func main() { server := gin.New() server.GET("/sleep/:time", func(context *gin.Context) { t := context.Param("time") t1, _ := strconv.Atoi(t) time.Sleep(time.Duration(t1) * time.Second) context.String(http.StatusOK, "sleep "+t) }) server.Run(":8888") } ``` # 抓包分析 ## client请求server 1 过程:(58533是客户端请求时的随机端口,8887是server 1的服务端口) ![image-20211223131051156](https://bbk-images.oss-cn-shanghai.aliyuncs.com/typora/20211223163158.png) 1. 首先是三次握手,`client`和`server1`建立链接(好基友,来牵牵手) 2. 客户端请求接口(5s超时),服务端返回了`ACK`(client:我有5s时间,但是只睡你3秒,server 1:好嘞!) 3. 客户端设置的超时间(5s)时间到了,发送`FIN`取消请求(client:服务还没好?等不了了,我走了,server 1:好嘞!) 4. 服务端返回`response`,但是客户端返回`FIN`(server 1:我好了,client:我都已经走了,👋) > 客户端取消请求之后,服务端居然还返回了结果! **简单总结下:**第5秒客户端因为超时时间到,取消了请求。而随后服务端立即返回了结果。***重点是服务端结果是在客户端请求之后返回的*** ## server 1请求server 2 过程:(58535是server 1请求时的随机端口,8888是server 2的服务端口) 1. `server 1` `sleep3`秒之后,开始对`server 2`发起请求(server1:我要睡你5s,server2:好嘞!) 2. 2秒过后,因为`client`取消了请求,`server1`也取消了对`server2`的请求(server1:client不要我了,我们的交易也取消,server2:好嘞!) 3. 又过了3秒,`server2`终于完成了睡眠,返回了结果(server2:您的服务已完成,server 1:交易早已取消,滚!) ![image-20211223131332123](https://bbk-images.oss-cn-shanghai.aliyuncs.com/typora/20211223131332.png) > `server1`取消了请求,`server 2`居然还在继续sleep **`server 2`好像有点笨,`server 1`都取消了请求,server 2还在`sleep`** ## 报错信息 - `client`在第5秒报错`context deadline exceeded` - `server 1`在第5秒报错`context canceled` - `server 2`没有报错 # 事件回顾 ## 正确的时序图 通过抓包分析发现刚开始画的时序图有问题: 错误的: ![image-20211223140510937](https://bbk-images.oss-cn-shanghai.aliyuncs.com/typora/20211223140510.png) 正确的: ![image-20211223120948836](https://bbk-images.oss-cn-shanghai.aliyuncs.com/typora/20211223120948.png) 两个时序图的差别就在于`server 1`处理请求所花费的时间。 `server 1`提前返回是因为server 1请求的时候绑定了`request context`。而`reqeust context`在`client`超时之后立即被`cancel`掉了,从而导致`server 1`请求`server 2`的`http`请求被迫停止。 ## context什么时候cancel的 接下来看下源代码:(go.1.17 & gin.1.3.0,可以跳过代码看小结部分) `server`端接受新请求时会起一个协程`go c.serve(connCtx)` ``` func (srv *Server) Serve(l net.Listener) error { // ... for { rw, err := l.Accept() connCtx := ctx // ... go c.serve(connCtx) } } ``` 协程里面for循环从链接中读取请求,重点是这里每次读取到请求的时候都会启动后台协程(`w.conn.r.startBackgroundRead()`)继续从链接中读取。 ``` // Serve a new connection. func (c *conn) serve(ctx context.Context) { // ... // HTTP/1.x from here on. ctx, cancelCtx := context.WithCancel(ctx) c.cancelCtx = cancelCtx defer cancelCtx() // ... for { // 从链接中读取请求 w, err := c.readRequest(ctx) if c.r.remain != c.server.initialReadLimitSize() { // If we read any bytes off the wire, we're active. c.setState(c.rwc, StateActive, runHooks) } // .... // 启动协程后台读取链接 if requestBodyRemains(req.Body) { registerOnHitEOF(req.Body, w.conn.r.startBackgroundRead) } else { w.conn.r.startBackgroundRead() } // ... // 这里转到gin里面的serverHttp方法 serverHandler{c.server}.ServeHTTP(w, w.req) // 请求结束之后cancel掉context w.cancelCtx() // ... } } ``` `gin`中执行ServeHttp方法 ``` // ServeHTTP conforms to the http.Handler interface. func (engine *Engine) ServeHTTP(w http.ResponseWriter, req *http.Request) { // ... // 执行我们写的handle方法 engine.handleHTTPRequest(c) // ... } ``` 目前为止,我们看到是**请求结束之后才会cancel掉`context`**,而不是cancel掉`context`导致的请求结束。 > 那是什么时候cancel掉`context`的呢? 秘密就在`w.conn.r.startBackgroundRead()`这个后台读取的协程里了。 ``` func (cr *connReader) startBackgroundRead() { // ... go cr.backgroundRead() } func (cr *connReader) backgroundRead() { n, err := cr.conn.rwc.Read(cr.byteBuf[:]) // ... if ne, ok := err.(net.Error); ok && cr.aborted && ne.Timeout() { // Ignore this error. It's the expected error from // another goroutine calling abortPendingRead. } else if err != nil { cr.handleReadError(err) } // ... } func (cr *connReader) handleReadError(_ error) { // 这里cancel了context cr.conn.cancelCtx() cr.closeNotify() } ``` `startBackgroundRead` -> `backgroundRead` -> `handleReadError`。代码一顿跟踪,最终发现在`handleReadError`函数里面会把`context` `cancel`掉。 > 原来如此,**当服务端在处理业务的同时,后台有个协程监控链接的状态,如果链接有问题就会把context cancel掉。**(cancel的目的就是**快速失败**——业务不用处理了,就算服务端返回结果了,客户端也不处理了) 那当客户端超时的时候,`backgroundRead`协程序会收到`EOF`的错误。抓包看对应的就是FIN报文。 ![image-20211223160513420](https://bbk-images.oss-cn-shanghai.aliyuncs.com/typora/20211223160513.png) ![image-20211223160602783](https://bbk-images.oss-cn-shanghai.aliyuncs.com/typora/20211223160602.png) 从业务代码中看到的`context`就是`context canceled` 状态 ![image-20211223160824497](https://bbk-images.oss-cn-shanghai.aliyuncs.com/typora/20211223160824.png) # 总结 ## 客户端超时 客户端超时场景总结如下 - 客户端本身会收到`context deadline exceeded`错误 - 服务端对应的请求中的`request context`被`cancel`掉 - 服务端业务可以继续执行业务代码,如果有绑定`request context`(比如`http`请求),那么会收到context canceled错误 - **尽管客户端请求取消了,服务端依然会返回结果** ## context 生命周期 下面再来看看`request context`的生命周期 ![image-20211223162851921](https://bbk-images.oss-cn-shanghai.aliyuncs.com/typora/20211223162851.png) - 大多数情况下,`context`一直能持续到请求结束 - 当请求发生错误的时候,`context`会立刻被`cancel`掉 ## ctx避坑 - http请求中不要使用`gin.Context`,而要使用c.Request.Context()(其他框架类似) - http请求中如果启动了协程,并且在`response`之前不能结束的,不能使用`request context`(因为`response`之后`context`就会被`cancel`掉了),应当使用独立的`context`(比如`context.Background()`) - 如果业务代码执行时间长、占用资源多,那么去感知`context` 被`cancel`,从而中断执行是很有意义的。(快速失败,节省资源)

有疑问加站长微信联系(非本文作者))

入群交流(和以上内容无关):加入Go大咖交流群,或添加微信:liuxiaoyan-s 备注:入群;或加QQ群:701969077

2658 次点击  ∙  1 赞  
加入收藏 微博
2 回复  |  直到 2022-01-12 19:40:10
暂无回复
添加一条新回复 (您需要 登录 后才能回复 没有账号 ?)
  • 请尽量让自己的回复能够对别人有帮助
  • 支持 Markdown 格式, **粗体**、~~删除线~~、`单行代码`
  • 支持 @ 本站用户;支持表情(输入 : 提示),见 Emoji cheat sheet
  • 图片支持拖拽、截图粘贴等方式上传