發現了一個關於 gin 1.3.0 框架的 bug

綠茶/發表於2020-12-03

gin 1.3.0 框架 http 響應資料錯亂問題排查

問題概述

客戶端同時發起多個http請求,gin接受到請求後,其中一個介面響應內容為空,另外一個介面響應內容包含介面1,介面2的響應內容,導致響應資料錯亂(偶現問題)

  • 圖1紅框標註部分為正常請求響應
  • 圖1藍框標註部分為異常請求響應(可以看到編號2531的響應資料只有一個狀態碼資訊,並沒有具體的返回內容)
  • 圖2 可以看到編號2533的響應資料包含兩組object物件資訊,其中第一條object資訊應該是2531的響應資料
  • 圖1:avatar
  • 圖2:avatar

問題分析

因為此問題是偶現問題,有時響應資料又是正常的,而且本次新版本這兩個介面程式碼也並沒有修改,所以排查問題花了很長時間,下面是我一步步排查問題的過程.

  1. 首先懷疑是程式碼邏輯問題,通過review介面程式碼邏輯後,這兩個介面邏輯都非常簡單,且沒有任何邏輯關聯,所以基本上排除了介面邏輯問題。
  2. 懷疑是否是併發請求導致的問題,通過golang並且開啟多個協程模擬併發發起http請求同時呼叫這兩個介面100次,並沒有復現出這種問題,所以可以排除併發請求導致的問題。
  3. 因為使用golang同時呼叫這兩個介面沒有復現此問題,懷疑是否是客戶端呼叫的問題,是否共用了一個http連線傳送請求,導致最終響應結果合併到了一起? review客戶端程式碼後,發現程式碼邏輯也沒有什麼問題,並且通過抓包後卻發現的確是後臺響應的資料就有問題,所以可以確認就是後端的問題。
  4. 此時有同事建議列印一下兩個介面後臺請求和響應的物件記憶體地址看一下,是否是共用了同一個物件導致,果然列印之後發現,當資料錯亂時,兩個介面使用的是同一個物件,兩個介面沒有任何邏輯關係,為什麼會使用同一個請求物件? 為什麼就兩個介面會出現資料錯亂的問題? 難道是gin框架的問題? 此時我們嘗試著除錯程式碼去驗證

實驗驗證

  1. 通過除錯發現,除錯資訊如圖3所示(第1部分為正常情況,可以觀察到物件指標地址不一樣,第2部分為異常情況,可以觀察到物件指標地址一樣):
  • 圖3:avatar
  1. 此時我觀察到每次這兩個介面請求後面,都跟著另外一個介面請求,如圖1所示的第2494條請求 /api/client/area/scenes 介面,並且本次新版本功能改動了這塊的邏輯,會不會是受這個介面的影響了,於是我嘗試恢復了這塊的程式碼,恢復後測試多次發現問題無法重現,所以可以斷定是受了這塊程式碼的影響.

  2. 然而本次修改的程式碼邏輯主要是為了相容老版本的客戶端,為此介面新增了一箇中介軟體,引入了gin框架的HandleContext(context) 方法,用來做一個統一的中介軟體,做路由的轉發,具體程式碼邏輯如圖4所示.

  • 圖4:avatar
  1. gin框架為golang web開發中,很常用的框架,使用人員非常多,這麼明顯的問題不可能沒人發現,雖然極力的認為不可能是框架的問題,但是事實表明就是這裡的問題,於是通過查詢資料發現,此方法的確可能出現問題,如圖5所示
  • 圖5:avatar
  1. 可以確認gin框架有問題了,可是原因是什麼了?網上並沒有詳細的說明,於是我打算通過除錯閱讀原始碼的方式來測試,在閱讀原始碼的時候我發現,原生程式碼和gin最新的官方原始碼已經不一致,於是我發現原生程式碼版本為1.3.0,而官方程式碼已經更新到1.6.3了, 如圖6所示: 1.6.3已經刪除了 engine.pool.Put(c) 此行程式碼
  • 圖6:avatar
  1. 於是我嘗試者把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 裡面。
  1. 通過如下圖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:avatar

小結

此次問題主要是使用了低版本的gin框架所致,所以可以看出即使再成熟的框架,也可能會存在bug,在實際開發過程中應該及時升級到框架的最新穩定版本, 這樣可以防止一些潛在的bug,當發現一些未知的問題,不要憑空猜測,要儘可能的除錯程式碼,找到問題的根本原因.

參考資料:

相關文章