mysqld の [Warning] Aborted connection to db: 対処方法の一例！

MariaDB Galera Cluster

OS は Lubuntu 14.04 で MariaDB Galera Cluster 10.0.22 を利用しているのですが、ふとテーブルを確認するとレコード数が想定していたよりも足りず、syslog を確認したところ Aborted connection なる警告がログされていました。
対処方法を調べてみると、読み書き時のセッションタイムアウト値を伸ばす方法などが記載されているが、私の場合単純に接続したまま close 処理をしていなかったことが原因だったので恥ずかしながら対処方法を晒します。。

環境

OS: Lubuntu 14.04
MariaDB Calera Cluster 10.0.22: 10.0.22-MariaDB-1~trusty-wsrep-log mariadb.org binary distribution, wsrep_25.11.r21a2415

事象

$ sudo less /var/log/syslog
Dec 16 08:06:58 tk-tam-hostname mysqld: 151216  8:06:58 [Warning] Aborted connection 13230 to db: 'dbname' user: 'ruby' host: '1.2.3.4' (Unknown error)
Dec 16 08:17:01 tk-tam-hostname CRON[7438]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Dec 16 09:07:05 tk-tam-hostname mysqld: 151216  9:07:05 [Warning] Aborted connection 13315 to db: 'dbname' user: 'ruby' host: '1.2.3.4' (Unknown error)
Dec 16 09:17:01 tk-tam-hostname CRON[7450]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Dec 16 10:07:06 tk-tam-hostname mysqld: 151216 10:07:06 [Warning] Aborted connection 13458 to db: 'dbname' user: 'ruby' host: '1.2.3.4' (Unknown error)
Dec 16 10:17:01 tk-tam-hostname CRON[7460]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Dec 16 11:06:41 tk-tam-hostname mysqld: 151216 11:06:41 [Warning] Aborted connection 13623 to db: 'dbname' user: 'ruby' host: '1.2.3.4' (Unknown error)
Dec 16 11:17:01 tk-tam-hostname CRON[7471]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Dec 16 12:06:42 tk-tam-hostname mysqld: 151216 12:06:42 [Warning] Aborted connection 13778 to db: 'dbname' user: 'ruby' host: '1.2.3.4' (Unknown error)
Dec 16 12:17:01 tk-tam-hostname CRON[7483]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
...skipping...

MariaDB の設定状況調査

Qiita の記事で紹介されていたクエリで設定確認を行ないます。

・Aborted connection がどのくらい発生しているか？
show status like ‘%Aborted_clients%’;

・Aborted connection をログに記録する設定になっているのか？
show global variables like ‘%warn%’;
※ log_warnings の値が 0 だと無効、1 だと有効、2 だと Aborted Connection もログされる

・Aborted connection が読み取り時に発生する条件は何秒か？
show global variables like ‘%net_read_timeout%’

・Aborted connection が書き込みに発生する条件は何秒か？
show global variables like ‘%net_write_timeout%’;

毎時、cron で ruby のスクリプトを動かしてテーブルへの書き込みを行なっているのですがその際に発生しているのでどうもそのスクリプトが怪しい。影響する値としては、net_write_timeout の 60 秒だがこの値を変更する前に、対象のスクリプト側での接続方法を見直すこととした。
以下の例は、MariaDB Galera Cluster 側の設定変更はせず、初期値のままの状態です。

$ mysql -uroot -p
Enter password: 
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 13880
Server version: 10.0.22-MariaDB-1~trusty-wsrep-log mariadb.org binary distribution, wsrep_25.11.r21a2415

Copyright (c) 2000, 2015, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]> show status like '%Aborted_clients%';
+-----------------+-------+
| Variable_name   | Value |
+-----------------+-------+
| Aborted_clients | 14    |
+-----------------+-------+
1 row in set (0.00 sec)

MariaDB [(none)]> show global variables like '%warn%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_warnings  | 2     |
| sql_warnings  | OFF   |
+---------------+-------+
2 rows in set (0.00 sec)

MariaDB [(none)]> show global variables like '%net_read_timeout%'
    -> ;
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| net_read_timeout | 30    |
+------------------+-------+
1 row in set (0.00 sec)

MariaDB [(none)]> show global variables like '%net_write_timeout%';
+-------------------+-------+
| Variable_name     | Value |
+-------------------+-------+
| net_write_timeout | 60    |
+-------------------+-------+
1 row in set (0.00 sec)

MariaDB [(none)]> quit
Bye

対処

mysql2 モジュールでスクリプト実行後すぐに接続をしていた。そして、その間 HTML のパース処理やらなにやら様々な処理を行い、結果を MariaDB Galera Cluster に書き込んでいる。
つまり、実際の処理前に接続を開始してしまっていた。（これは接続情報をスクリプトの最初に書いておいたほうがテストなどがしやすいという理由からなのだが）
そして、close してない！という。これが原因でしょ。。なので、こまめにちょこちょこと接続してはクローズするように変更したところ Aborted connection は出力されなくなりました。

気づけて良かった。ある意味この警告は出す設定にしておいたほうが良いと思います。我ながらイケてないですなぁ（笑）

対策前の接続方式

# -*- coding: utf-8 -*-
require 'anemone'
require 'nokogiri'
require 'kconv'
require 'mysql2'

client = Mysql2::Client.new(:username => 'ruby', :password => 'hogehoge', :host => '1.2.3.4', :database => 'db')
urls = []
urls.push("http://www.amazon.co.jp/gp/bestsellers/music/xxxxxx/")

Anemone.crawl(urls, opts) do |anemone|
  anemone.on_every_page do |page|

  doc = Nokogiri::HTML.parse(page.body.toutf8)
  
  # 様々な処理
  ・・・
  
  # MySQL への書き込み
  client.query("insert into tb_amazon_bs_ranking (asin,category_cd,sub_category_cd,rank,update_t) values (\"#{asin}\",\"#{category_cd}\",\"#{sub_category_cd}\",\"#{rank}\",\"#{DateTime.now}\")")
  }
  end
end

対策後の接続方式

# -*- coding: utf-8 -*-
require 'anemone'
require 'nokogiri'
require 'kconv'
require 'mysql2'

urls = []
urls.push("http://www.amazon.co.jp/gp/bestsellers/music/xxxxxx/")

Anemone.crawl(urls, opts) do |anemone|
  anemone.on_every_page do |page|

  doc = Nokogiri::HTML.parse(page.body.toutf8)
  
  # 様々な処理
  ・・・
  
    # MySQL への書き込み
    client = Mysql2::Client.new(:username => 'ruby', :password => 'hogehoge', :host => '1.2.3.4', :database => 'db')
    client.query("insert into tb_amazon_bs_ranking (asin,category_cd,sub_category_cd,rank,update_t) values (\"#{asin}\",\"#{category_cd}\",\"#{sub_category_cd}\",\"#{rank}\",\"#{DateTime.now}\")")
    client.close
  }
  end
end
MariaDB&MySQL全機能バイブル
スポンサーリンク