ことのはじまり
MySQL5.5からMariaDB10.0にデータベースを変更した際、エラーログにこんなワーニングを連発で出力するようになった・・
140819 21:02:28 [Warning] Aborted connection 1447404 to db: 'database1' user: 'dbuser' host: '192.168.123.208' (Unknown error)
140819 21:02:29 [Warning] Aborted connection 1447482 to db: 'database1' user: 'dbuser' host: '192.168.123.207' (Unknown error)
140819 21:02:33 [Warning] Aborted connection 1448266 to db: 'database1' user: 'dbuser' host: '192.168.123.207' (Unknown error)
140819 21:02:38 [Warning] Aborted connection 1448053 to db: 'database1' user: 'dbuser' host: '192.168.123.206' (Unknown error)
140819 21:02:39 [Warning] Aborted connection 1447983 to db: 'database1' user: 'dbuser' host: '192.168.123.233' (Unknown error)
実際このワーニングが、どれだけまずいのかよくわからない・・・
まずこのワーニングがどんなケースで起こるのか調べてみた。
調査
いくつか、原因はあるようです。でもバージョンアップしてからこの問題が発生しているのでもしかして、MariaDB 10.0のバグか？と考えてしまいました。
クライアントプログラムが終了前に mysql_close() を呼び出さなかった。
どうもこれっぽいなとは思ったのですが、MySQL5.5の時にこのエラーが発生したことをない。。。
クライアントが何の要求もせずに、wait_timeout または interactive_timeout より多くの時間スリープ状態であった
クライアントプログラムが、転送中に突然終了した。
上記のことが発生した場合、サーバ変数 Aborted_clients の値が増えますとのことで調べてみたところ、確かに値は増えていました
ネットワークが不安定なのか？
MariaDB [(none)]> show status like '%Aborted_clients%' ;
+-----------------+--------+
| Variable_name | Value |
+-----------------+--------+
| Aborted_clients | 120916 |
+-----------------+--------+
1 row in set (0.00 sec)
↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓↓
+-----------------+--------+
| Variable_name | Value |
+-----------------+--------+
| Aborted_clients | 120926 |
+-----------------+--------+
1 row in set (0.00 sec)
以下の場合、サーバ変数 Aborted_connects の値が増えます。
- 接続パケットに正しい情報が含まれていない場合
- ユーザにデータベースに接続する権限がない場合
- ユーザが間違ったパスワードを使用した場合
こちらは特に増えていない模様
+------------------+-------+
| Variable_name | Value |
+------------------+-------+
| Aborted_connects | 8565 |
+------------------+-------+
対応
上記を踏まえて、効果がありそうなパラメータを修正してみました。
net_read_timeout の値を変更
読み込みを中断するまでデータ追加を待機する秒数。タイムアウトは TCP/IP 接続にだけ適用すると書いてあったのでデフォルトの30秒から60秒に変更してみましたがワーニングの改善はありませんでした。
MariaDB [(none)]> show global variables like '%net_read_timeout%' ;
+------------------+-------+
| Variable_name | Value |
+------------------+-------+
| net_read_timeout | 30 |
+------------------+-------+
1 row in set (0.01 sec)
mysql> set global net_read_timeout = 60 ;
net_write_timeout の値を変更
書き込みを中断するまでデータ追加を待機する秒数。タイムアウトは TCP/IP 接続にだけ適用すると書いてあったのでデフォルトの60秒から120秒に変更してみましたがワーニングの改善はありませんでした。
MariaDB [(none)]> show global variables like '%net_write_timeout%' ;
+-------------------+-------+
| Variable_name | Value |
+-------------------+-------+
| net_write_timeout | 60 |
+-------------------+-------+
mysql> set global net_write_timeout = 120 ;
アプリケーション側の調査
アプリケーション側の接続設定を確認してもらったところ、php系のアプリケーションで、データベースをクローズしていない処理が多々見られた、これは、ミスではなく、永続的接続(pconnect)の設定だったため、クローズしていなかった模様でした。ワーニングの原因は、これだったのですが、それだったにしても、MySQL5.5にはワーニングは発生していないし。MariaDB10.0にバージョンアップはしたけど、別にphp側のソースを改修したわけでもない・・・ということで・・・
もしかして・・・
もしかして・・・・ MySQL5.5からMaria10.0にバージョンアップした際、何かグローバル変数のデフォルトが変わったりしていない？？？ってことで真っ先に怪しいと思われるログの設定を調べてみました
MySQL5.5
mysql> show global variables like '%warn%' ;
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_warnings | 1 |
| sql_warnings | OFF |
+---------------+-------+
2 rows in set (0.00 sec)
MariaDB10.0
MariaDB [(none)]> show global variables like '%warn%' ;
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_warnings | 2 |
| sql_warnings | OFF |
+---------------+-------+
値を 1 (デフォルト) にすると、有効化し、0 にすると無効化します。値を 1 より大きな値にすると、中断した接続についてもエラーログを記録します
うぉ。。。まじか・・・ってことは、MySQL5.5の時も、log_warnings=2で設定すると、ワーニングは出てたのかーーーー！！ってことで
MariaDBのlog_warningsを1に変更したみたところ当たり前といえば当たり前なのですが、鬱陶しい Aborted connectionのワーニングは消えました。という、まったく根本の解決には至っていないメモでした。（デフォルト変えないでよ・・・）