reading communication packets

 

在使用mysql5.7的時候，發現了不少在mysql5.6上不曾見過的日志，級別為note, 最常見的note日志以下三種，下面我們來逐個解釋。

第一種，Aborted connection . 如上圖，信息如下：

2020-08-17T14:44:24.102542Z 59 [Note] Aborted connection 59 to db: ‘unconnected’ user: ‘mha’ host: ‘10.xx.xx.xx’ (Got an error reading communication packets)

2020-08-17T14:44:31.273897Z 61 [Note] Aborted connection 61 to db: ‘unconnected’ user: ‘mha’ host: ‘10.xx.xx.xx(Got an error reading communication packets)

2020-08-17T14:44:31.273897Z 61 [Note] Aborted connection 61 to db: ‘unconnected’ user: ‘mha’ host: ‘10.xx.xx.xx(Got an error reading communication packets)

 

2020-08-17T14:44:31.273897Z 61 [Note] Aborted connection 61 to db: ‘unconnected’ user: ‘mha’ host: ‘10.xx.xx.xx(Got  timeout  reading communication packets)

 

上面兩個是連接中斷的錯誤信息，原因不一樣，

Got an error reading communication packets  的原因是因為網絡等原因導致。

Got  timeout  reading communication packets 這個錯誤的原因是會話的idle時間達到了數據庫指定的timeout時間。

 

 

關於Aborted connection告警日志的分析

2020-05-19閱讀 3470

 

前言：

有時候，連接MySQL的會話經常會異常退出，錯誤日志里會看到"Got an error reading communication packets"類型的告警。本篇文章我們一起來討論下該錯誤可能的原因以及如何來規避。

1.狀態變量Aborted_clients和Aborted_connects

首先我們來了解下Aborted_clients和Aborted_connects這兩個狀態變量的含義，當出現會話異常退出時，這兩個狀態值會有變化。根據官方文檔描述，總結如下：

造成Aborted_connects狀態變量增加的可能原因：

1. 客戶端試圖訪問數據庫，但沒有數據庫的權限。
2. 客戶端使用了錯誤的密碼。
3. 連接包不包含正確的信息。
4. 獲取一個連接包需要的時間超過connect_timeout秒。

造成Aborted_clients狀態變量增加的可能原因：

1. 程序退出前，客戶機程序沒有調用mysql_close()。
2. 客戶端睡眠時間超過了wait_timeout或interactive_timeout參數的秒數。
3. 客戶端程序在數據傳輸過程中突然終止。

簡單來說即：數據庫會話未能正常連接到數據庫，會造成Aborted_connects變量增加。數據庫會話已正常連接到數據庫但未能正常退出，會造成Aborted_clients變量增加。

2.Got an error reading communication packets原因分析

哪種情況會導致error log中出現“Aborted connection xxxx to db: 'db' user: 'dbuser' host: 'hostname' (Got an error reading communication packets)”類似告警呢？

下面我們根據上面可能的原因來做下具體測試。每次測試要注意狀態變量Aborted_clients和Aborted_connects的變化及錯誤日志記錄。

• 測試一：錯誤密碼，錯誤用戶

1.測試前查看狀態變量值:

mysql> show global status like 'abort%';

+------------------+-------+| Variable_name    | Value |+------------------+-------+| Aborted_clients  | 0     |
| Aborted_connects | 0     |+------------------+-------+
2.測試過程# mysql -uroot -pwrongpassmysql: [Warning] Using a password on the command line interface can be insecure.ERROR 1045 (28000):
 Access denied for user 'root'@'localhost' (using password: YES)# mysql -uroot1 -pwrongpassmysql:
 [Warning] Using a password on the command line interface can be insecure.ERROR 1045 (28000): 
Access denied for user 'root1'@'localhost' (using password: YES)

 

 3.查看狀態變化及錯誤日志:

mysql> show global status like 'abort%';

+------------------+-------+| Variable_name    | Value |+------------------+-------+| 
Aborted_clients  | 0     || Aborted_connects | 2     |+------------------+-------+
錯誤日志記錄：2020-03-16T17:58:35.318819+08:00 6 [Note] 
Access denied for user 'root'@'localhost' (using password: YES)

2020-03-16T17:59:04.153753+08:00 7 [Note] Access denied for user 'root1'@'localhost' (using password: YES)
結果：Aborted_connects有增加 error log無Aborted connection相關記錄

 

• 測試二：睡眠時間超時或手動殺會話

1.測試前查看狀態變量值:

mysql> show global status like 'abort%';

+------------------+-------+| Variable_name    | Value |+------------------+-------+| 
Aborted_clients  | 0     || Aborted_connects | 2     |+------------------+-------+

 

 2.手動殺會話測試:

mysql> show processlist;

+----+------+-----------+------+---------+------+----------+------------------+| Id | User | Host      | db   | Command | Time | State    | Info            
 |+----+------+-----------+------+---------+------+----------+------------------+|  9 | root | localhost | NULL | Query   |    0 

| starting | 
show processlist 

|| 10 | root | localhost | NULL | Sleep   |    7 |          | NULL             

|+----+------+-----------+------+---------+------+----------+------------------+

2 rows in set (0.00 sec)mysql> kill 10;Query OK, 0 rows affected (0.00 sec)

 

 3.查看狀態變化及錯誤日志:

mysql> show global status like 'abort%';

+------------------+-------+| Variable_name    | Value |+------------------+-------+| 
Aborted_clients  | 1     || Aborted_connects | 2     |+------------------+-------+

結果：Aborted_clients有增加 error log無記錄 ,類似的，睡眠時間超時后Aborted_clients有增加 error log中有Aborted connection相關記錄。

 

會話異常退出一般會造成Aborted connection告警，即我們可以通過Aborted_clients狀態變量的變化來反映出是否存在異常會話，

那么出現“Got an error reading communication packets” 類似告警的原因就很明了了，查詢相關資料，總結出造成Aborted connection告警的可能原因如下：

• 會話鏈接未正常關閉，程序沒有調用mysql_close()。
• 睡眠時間超過wait_timeout或interactive_timeout參數的秒數。
• 查詢數據包大小超過max_allowed_packet數值，造成鏈接中斷。
• 其他網絡或者硬件層面的問題。

3.問題避免與總結

其實Aborted connection告警是很難避免的，error log里或多或少會有少量Aborted connection信息，這種情況是可以忽略的，但是當你的error log里頻繁出現Aborted connection告警，這時候就應該注意了，可能會對業務產生較大的影響。下面列舉出幾點避免錯誤的建議，希望對你有所幫助。

• 建議業務操作結束后，應用程序邏輯會正確關閉連接，以短連接替代長連接。
• 檢查以確保max_allowed_packet的值足夠高，並且客戶端沒有收到“數據包太大”消息。
• 確保客戶端應用程序不中止連接，例如，如果PHP設置了max_execution_time為5秒，增加connect_timeout並不會起到作用，因為PHP會kill腳本。其他程序語言和環境也有類似的安全選項。
• 確保事務提交（begin和commit）都正確提交以保證一旦應用程序完成以后留下的連接是處於干凈的狀態。
• 檢查是否啟用了skip-name-resolve，檢查主機根據其IP地址而不是其主機名進行身份驗證。
• 嘗試增加MySQL的net_read_timeout和net_write_timeout值，看看是否減少了錯誤的數量。

參考：

• https://dev.mysql.com/doc/refman/5.7/en/communication-errors.html