gin 1.3.0 框架 http 响应数据错乱问题排查
问题概述
客户端同时发起多个http请求,gin接受到请求后,其中一个接口响应内容为空,另外一个接口响应内容包含接口1,接口2的响应内容,导致响应数据错乱(偶现问题)
- 图1红框标注部分为正常请求响应
- 图1蓝框标注部分为异常请求响应(可以看到编号2531的响应数据只有一个状态码信息,并没有具体的返回内容)
- 图2 可以看到编号2533的响应数据包含两组object对象信息,其中第一条object信息应该是2531的响应数据
- 图1:
- 图2:
问题分析
因为此问题是偶现问题,有时响应数据又是正常的,而且本次新版本这两个接口代码也并没有修改,所以排查问题花了很长时间,下面是我一步步排查问题的过程.
- 首先怀疑是代码逻辑问题,通过review接口代码逻辑后,这两个接口逻辑都非常简单,且没有任何逻辑关联,所以基本上排除了接口逻辑问题。
- 怀疑是否是并发请求导致的问题,通过golang并且开启多个协程模拟并发发起http请求同时调用这两个接口100次,并没有复现出这种问题,所以可以排除并发请求导致的问题。
- 因为使用golang同时调用这两个接口没有复现此问题,怀疑是否是客户端调用的问题,是否共用了一个http连接发送请求,导致最终响应结果合并到了一起? review客户端代码后,发现代码逻辑也没有什么问题,并且通过抓包后却发现的确是后台响应的数据就有问题,所以可以确认就是后端的问题。
- 此时有同事建议打印一下两个接口后台请求和响应的对象内存地址看一下,是否是共用了同一个对象导致,果然打印之后发现,当数据错乱时,两个接口使用的是同一个对象,两个接口没有任何逻辑关系,为什么会使用同一个请求对象? 为什么就两个接口会出现数据错乱的问题? 难道是gin框架的问题? 此时我们尝试着调试代码去验证
实验验证
- 通过调试发现,调试信息如图3所示(第1部分为正常情况,可以观察到对象指针地址不一样,第2部分为异常情况,可以观察到对象指针地址一样):
- 图3:
-
此时我观察到每次这两个接口请求后面,都跟着另外一个接口请求,如图1所示的第2494条请求 /api/client/area/scenes 接口,并且本次新版本功能改动了这块的逻辑,会不会是受这个接口的影响了,于是我尝试恢复了这块的代码,恢复后测试多次发现问题无法重现,所以可以断定是受了这块代码的影响.
-
然而本次修改的代码逻辑主要是为了兼容老版本的客户端,为此接口添加了一个中间件,引入了gin框架的HandleContext(context) 方法,用来做一个统一的中间件,做路由的转发,具体代码逻辑如图4所示.
- 图4:
- gin框架为golang web开发中,很常用的框架,使用人员非常多,这么明显的问题不可能没人发现,虽然极力的认为不可能是框架的问题,但是事实表明就是这里的问题,于是通过查询资料发现,此方法的确可能出现问题,如图5所示
- 图5:
- 可以确认gin框架有问题了,可是原因是什么了?网上并没有详细的说明,于是我打算通过调试阅读源码的方式来测试,在阅读源码的时候我发现,本地代码和gin最新的官方源码已经不一致,于是我发现本地代码版本为1.3.0,而官方代码已经更新到1.6.3了, 如图6所示: 1.6.3已经删除了 engine.pool.Put(c) 此行代码
- 图6:
- 于是我尝试者把gin版本从1.3.0升级到1.6.3,看看问题是否已经解决,果然gin版本升级后,连续测试多次未能重现问题,所以可以确定就是这里的问题,并且问题已经解决
虽然问题已经解决了,但是为什么删除了这一行就可以了? 好像并没有搞清楚具体的原理是什么? 于是我尝试着继续分析原理
- engine.pool.Put(c) 函数使用的是 golang的 sync.Pool 类,sync.Pool设计的目的是用来保存和复用临时对象,以减少内存分配,降低CG压力,Pool对外暴露的主要有三个接口:get(),put(),new()
- Get 返回 Pool 中的任意一个对象。如果 Pool 为空,则调用 New 返回一个新创建的对象。
- sync.Pool 是一个临时对象池。一句话来概括,sync.Pool 管理了一组临时对象,当需要时从池中获取,使用完毕后从再放回池中,以供他人使用。
- Put的过程就是将临时对象放进 Pool 里面。
- 通过如下图7也可以看到 HandleContext 方法上面有一个 ServeHTTP 方法,可以明显看到此方法也调用了 engine.pool.Put(c) 方法,并且也调用了 engine.pool.Get().(Context) 方法,通过调试发现 ServeHTTP 为http请求通用的方法,所有请求都会先调用 ServeHTTP ,如果调用了 HandleContext 则会再调用 HandleContext ,具体执行顺序如下图7所示,如图可以看出来 engine.pool.Put(c) 会执行两次,这样就会导致在sync.Pool存在两个同样的对象,在后面的请求中通过 engine.pool.Get().(Context) 获取context对象时就会获取到相同的context对象,导致ResponseWriter指针一样,从而导致响应数据输出到同一个接口中.
- 图7:
小结
此次问题主要是使用了低版本的gin框架所致,所以可以看出即使再成熟的框架,也可能会存在bug,在实际开发过程中应该及时升级到框架的最新稳定版本, 这样可以防止一些潜在的bug,当发现一些未知的问题,不要凭空猜测,要尽可能的调试代码,找到问题的根本原因.