曹工改bug--本來以為很簡單的資料庫欄位長度不足的問題,最後竟然靠抓包才解決
阿新 • • 發佈:2020-07-15
# 問題描述
這兩天本來忙著新功能開發,結果之前的一個專案最近要上了,然後又在測試,然後就喜提bug一枚(not mine),看bug描述,很簡單,而且本地環境也重現了,只要輸入2000個英文字元就可以復現。
核心就是:
> 當任務描述輸入最大字元2000時,報未知異常
#問題定位
這種字元數限制的,一般就是資料庫的欄位長度短了,於是我直接找到ssh,找到對應的日誌看了一下,果然是這個問題。
```shell
com.mysql.jdbc.MysqlDataTruncation: Data truncation: Data too long for column 'feedback_content' at row 1
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3931)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3869)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2524)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2675)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2465)
```
還能說啥,直接上去改唄,於是連上資料庫,開啟表,查看錶結構,發現好像沒啥問題:
![](https://img2020.cnblogs.com/blog/519126/202007/519126-20200714204613089-1061546974.png)
這不就是設定的2000嗎,難道後面的字符集有問題嗎,因為表是用的utf8mb4,難道有影響?然後改成了下面這樣:
```sql
`feedback_content` varchar(2000) COLLATE utf8mb4_unicode_ci DEFAULT NULL COMMENT '反饋內容',
```
結果並沒有用,果然不應該懷疑這個的,utf8 和 utf8mb4,差距也沒那麼大,這裡又沒有特殊字元。
另外就是,中途也試了直接用工具改表,好像沒啥問題。
中途甚至懷疑連錯庫了,用命令查看了java程序(開發環境,java程序和資料庫在同一臺機器)的連線,確認庫沒連錯。
```shell
netstat -ntp|grep 1279
```
![](https://img2020.cnblogs.com/blog/519126/202007/519126-20200714205527889-2125739912.png)
然後我嘗試著用1999、1998字元去驗證,還是有問題,想著哥見過的bug多了,還能栽在這兒嗎,實在不行就開idea,本地debug一下吧。
這樣想著,到了午飯時間,就去吃飯了。
# 再次定位
吃完飯後,中午並沒有看bug,不過有個大概思路準備試一下。
思路就是,伺服器上用tcpdump抓應用程式和mysql之間的包,然後看看情況,看看到底是哪裡有問題吧。
然後下午空了一會,就在伺服器上開了抓包:
```shell
tcpdump -i lo tcp port 3306 -Ann
```
* -i 抓環回網絡卡,因為我java服務和mysql在一臺上
* tcp port 3306 這個是捕獲表示式,意思是,抓的包,其埠(不管是source還是destination,其埠需要是3306)
* -A Print each packet (minus its link level header) in ASCII. Handy for capturing web pages. 意為直接asicc列印包的內容,因為mysql不是完全看不懂的二進位制協議,所以可以直接列印
* -nn Don't convert protocol and port numbers etc. to names either. 埠顯示數字就好,不用把知名埠轉換為可讀的文字
開了抓包後,然後馬上去操作了一把,然後這邊馬上看到,包已經打印出來了(包如果很多,記得趕快ctrl c中斷抓包):
![](https://img2020.cnblogs.com/blog/519126/202007/519126-20200714210856103-178547794.png)
可以看到,確實是mysql 伺服器報錯了,和我們客戶端沒半毛錢關係。
但是,還是很奇怪,不知道為啥報錯。
於是,我重新抓了一次包。
```shell
tcpdump -i lo tcp port 3306 -w test.pcap
```
這裡沒指定-Ann了,因為我們這次是要儲存下來,到test.pcap這個檔案。
然後再去測了一下,然後回來ctrl c,可以看到如下資訊:
![](https://img2020.cnblogs.com/blog/519126/202007/519126-20200714211134440-1111697604.png)
(這裡僅供演示,沒再去測試了,我把下午抓的包給大家看)
# wireshark分析
用wireshark開啟該test.pcap,可以看到:
![](https://img2020.cnblogs.com/blog/519126/202007/519126-20200714211354136-1506401414.png)
可以發現,wireshark直接內建了mysql的解析協議,很方便,我們這裡隱去了一些表資訊。大家學著用一下,很簡單。
但是現在還沒看出來問題,我仔細觀察了一下,
![](https://img2020.cnblogs.com/blog/519126/202007/519126-20200714211611833-1460468890.png)
上圖中,我發現,每一列後,都會跟個逗號來分隔;但是,我們反饋內容那一列,前面怎麼那麼多個點呢?
然後基本可以肯定,是程式在裡面加料了,然後去看了程式碼邏輯,果然,程式裡,對前端傳過來的內容,前面還拼了一些東西進去,然後基本就這樣找到問題了。
實際上,我們也可以這樣看,對著這個包,點右鍵,follow stream,就會把這個socket 四元組的通訊都過濾出來。
![](https://img2020.cnblogs.com/blog/519126/202007/519126-20200714211923468-440548403.png)
注意,上圖是asicc顯示的,我們切換為utf8看一下,就很明顯了。
![](https://img2020.cnblogs.com/blog/519126/202007/519126-20200714212004101-270930412.png)
# 總結
問題本身很簡單,因為慣性思維,我也沒有第一時間去看業務邏輯,本能地開始懷疑mysql那邊的問題去了,其實還是應該先看看業務。
另外,tcpdump、wireshark這類神器,大家一定要掌握,縮小問題邊界、不同服務間問題甩鍋啥的,就靠它了。
對了,這裡分享下最近畫的JVM腦圖一張,有用的話,大家給腦圖點個贊哈。
https://www.processon.com/view/link/5f0ad405f346fb3f