MariaDBの [Warning] Aborted connection

ふとDebian上のMariaDBのエラーログを見たところ、次のようなワーニングが記録されているのに気づきました。

[Warning] Aborted connection 3315 to db: 'server' user: 'user' host: '127.0.0.1' (Got an error reading communication packets)

[Warning] Aborted connection 3010 to db: 'unconnected' user: 'repl' host: '192.168.1.1' (A slave with the same server_uuid/server_id as this slave has co)

ワーニングといえども気持ちが悪いので、エラーログや一般ログを確認しながら対処していきたいと思います。（最終的には旧バージョンのMariaDBをビルドすることになりました)

上のふたつはどちらも Aborted connection ですが、最後のメッセージ部が違います。意訳すると前者は接続が途切れた、後者はidが重複している(あとで説明しますがレプリケーション周辺の設定です)ということです。

順に対処していきたいと思います。

Got an error reading communication packets

こちらはODBCドライバなどを使ってオープンした接続を閉じずにアプリケーションを終了すると出現するメッセージだそうです。

メッセージには時刻やデータベース名、ユーザー、ホスト情報が表示されますので、これらを頼りにワーニングを引き起こしているアプリケーションを探し、そのコード内でちゃんと接続を閉じるように修正します。

ただ、筆者の場合がそうだったように、多くの情報を保持しているデータベースではこれだけの情報では目的のアプリケーションを見つけにくいと思います。

その際は、general_log (一般ログ)を利用します。

general log

MariaDBの general log は通常のDBのログを記録しておくもので、膨大な量になるのでデフォルトでは出力されないようになっていると思います。

出力の設定は、my.ini、50-server.cnfといった設定ファイルに書くか、グローバル変数を操作することで変更可能です。

まず、出力方法を設定します。general logは専用のDBテーブルに出力するか、ファイルに出力することができます。

log_output 変数に'TABLE'を指定すると、mysql.general_log テーブル内にログを保存します。'FILE'を指定すると他のログ同様にファイルに保存します。

試しに、TABLE を指定してログ出力を開始してみます。ログを開始するには general_log 変数に 1 をセットします。また 0 をセットするとログ出力を終えます。

SET GLOBAL log_output='TABLE';
SET GLOBAL general_log=1;

環境によってはあっという間にレコードが溜まっていきますので注意してください。

select * from mysql.general_log limit 1 \G
*************************** 1. row ***************************
  event_time: 2023-03-21 23:47:32.376757
   user_host: [user] @  [127.0.0.1]
   thread_id: 5337
   server_id: 1001
command_type: Connect
    argument: user@127.0.0.1 as anonymous on server

カラムは次のようになっています。

event_time
時刻です
user_host
ユーザーとホストの情報です
thread_id
この値が、エラーログの connection id の値と一致するものになります。
command_type
この値が Connect だと接続ログ、Query ならクエリログとなります。他には Binlog Dump や Quit などもあります。
argument
クエリログの場合はここに発行したSQLが入ります。

これで、ワーニングを発生させたコネクションが発行したSQL文がわかりますので、先ほどよりは目的のアプリケーションを絞り込みやすくなります。

利用が終わったらログを切り捨てておきましょう。

次にファイルを選択する場合です。log_output に FILE に変更してして、general_log_file にファイル名かファイルパスを渡します。筆者の環境では相対パス時は /var/lib/mysql からのパスとなりました。

SET GLOBAL log_output='FILE';
SET GLOBAL general_log_file='/var/log/mysql/general.log';
SET GLOBAL general_log=1;

ログファイルのレイアウトは次のようになっていました。

general.log

/usr/sbin/mysqld, Version: 10.3.36-MariaDB-0+deb10u2-log (Debian 10). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                Id Command  Argument
230321 14:45:57   6657 Query    SELECT * FROM...

ファイルの方が若干出力項目が少ないようです。

A slave with the same server_uuid/server_id

こちらのエラーはレプリケーションのserver_uuidやserver_idが他と重複したりしていると出現するようです。ちなみにserver_uuidはMySQLに存在するリードオンリーのグローバル変数で、MariaDBのシステム変数には存在しません。

server_uuidの重複の場合は、MySQLでの対処方法はすこぶる.net：「スレーブサーバのイメージから2台目のスレーブサーバを作成する際の注意点」によると auto.cnf を削除したら回復したそうです。

MySQLにおける auto.cnfファイルはMySQLの管理機構がサーバーの uuid を管理するために自動生成するファイルで、生成時に一意な値になるはずなので、本来なら手動で修正しないもののようです。

話をMariaDBに戻すと、50-server.cnf に設定する server_id に重複はありませんでした。そこで、詳しくプライマリ（マスター）側のエラーログを見てみると、次のようにbinlogを出力した後に中断されていることがわかりました。

2023-03-21 14:08:29 6245 [Note] Start binlog_dump to slave_server(1002), pos(mysql-bin.010668, 90528188), using_gtid(0), gtid('')
2023-03-21 14:08:29 6236 [Warning] Aborted connection 6236 to db: 'unconnected' user: 'repl' host: '192.168.2.1' (A slave with the same server_uuid/server_id as this slave has co)
2023-03-21 14:20:36 6389 [Note] Start binlog_dump to slave_server(1002), pos(mysql-bin.010668, 96436133), using_gtid(0), gtid('')
2023-03-21 14:20:36 6245 [Warning] Aborted connection 6245 to db: 'unconnected' user: 'repl' host: '192.168.2.1' (A slave with the same server_uuid/server_id as this slave has co)
2023-03-21 14:21:37 6397 [Note] Start binlog_dump to slave_server(1002), pos(mysql-bin.010668, 96436133), using_gtid(0), gtid('')
2023-03-21 14:21:37 6389 [Warning] Aborted connection 6389 to db: 'unconnected' user: 'repl' host: '192.168.2.1' (A slave with the same server_uuid/server_id as this slave has co)

レプリカ側をみると、プライマリに出力されるワーニングと同じタイミングで、イベントの読み出しに失敗していました。

2023-03-21 14:08:29 5 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'mysql-bin.010668' at position 90528188
2023-03-21 14:20:36 5 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'mysql-bin.010668' at position 96436133
2023-03-21 14:21:36 5 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'mysql-bin.010668' at position 96436133

Failed reading log event

Failed reading log event はプライマリとレプリカのMariaDBのバージョンの違いやネットワークの輻輳、レプリカ側のディスク容量不足、バイナリログの破損、などで起きるようです。

今回は、アップグレードの評価中だったため、プライマリ側のMariaDBがレプリカより古い状態でした。(10.5.18 vs 10.3.36)

新旧のMariaDBバージョン間で同期の問題が起きるのは、評価したかった部分から外れているどうしようかと考えてながら、mysql_upgrade を実行したり、そろっていなかった 50-client.cnf の default-character-setをutf8mb4にしてみたり、いろいろやったのですがうまくいきませんでした。

結局、バージョン差による同期の失敗であることを証明できないので、新しいバージョンをアンインストール後、古いバージョンをインストールし、再度レプリケーションを構築しました。

今回はプライマリが古いバージョンのためそこから再度データを取得することができますが、通常MariaDBやMySQLはマイナーバージョンでもダウングレードはサポートされおらず障害が発生した例もあるようなので注意してください。

まず、既存のバイナリをアンインストールします。既存の設定ファイルが不要なら purge 残すなら remove を指定します。

# systemctl stop mariadb
...
# apt remove mariadb-server-10.5
...

公式のビルドガイドによると、DebianでMariaDBをBuildするには built-essensital と bison が必要です。

他にソースを取得するための、git や cmake 、gnutls-devなども必要なようです。

# apt update
...
# apt install build-essential bison cmake git
...

続けて apt build-dep で mariadb-server のビルドに必要な環境をインストールします。これはsources.listにdeb-srcの行が必要です。

# apt build-dep mariadb-server
...

ソースコード一覧から目的のバージョンのgitレポジトリを探しクローンします。

各バージョンはブランチとして管理されているようなので、ブランチを指定してクローンします。そうしないと最新版がビルドされてしまいます。

# git clone -b 10.3 https://github.com/MariaDB/server.git

クローンでできたディレクトリに入って、公式ガイドに従って次のコマンドを入力します。リモートでbuildするような時はコネクション切断時に終了tmuxなどを利用した方がいいと思います。

# cmake . -DBUILD_CONFIG=mysql_release && make -j8

makeにおける-j8オプションは、ジョブの数の指定だそうです。Quiita：「make時にオプションを付けたら超絶高速になった」によると、ジョブの数を指定するものだで、目安はコア数の2倍の値だそうです。

ちなみにCPUのコア数の確認は cat /proc/cpuinfo で確認できます。

必須ではないですが、ビルト時に警告がでていたのでテストをします。parallelオプションに渡す値は先と同じでいいと思います。

# cd mysql-test
# mtr --parallel=8 --force

Logging: ./mtr  --parallel=8 --force
VS config:
vardir: /usr/local/src/server/mysql-test/var
Removing old var directory...
Creating var directory '/usr/local/src/server/mysql-test/var'...
Checking supported features...
MariaDB Version 10.3.39-MariaDB
 - SSL connections supported
 - binaries built with wsrep patch
Using suites: main-,archive-,binlog-,binlog_encryption-,csv-,compat/oracle-,compat/maxdb-,encryption-,federated-,funcs_1-,funcs_2-,gcol-,handler-,heap-,innodb-,innodb_fts-,innodb_gis-,innodb_zip-,json-...

インストールします。デフォルトでは/usr/local/mysqlへインストールされました。

# make install
# mv data /usr/local/mysql

mysqlディレクトリ以下のファイルとディレクトリ所有権をすべてmysql:mysqlにします。

管理用のテーブル作成といったデータベースの初期化を行います。/usr/local/mysqlに移動してコマンドを実行します。スクリプトは相対パスを基準にしているので、mysqlディレクトリ直下にいないとうまくいきません。

# cd /usr/local/mysql
# ./scripts/mysql_install_db --user=mysql --basedir=./ --datadir=/usr/local/mysql/data

このスクリプトは新しいバージョンだと ./scripts/mariadb-install-db ...に代わっています。

また、このコマンドは、my.cnfファイルの影響を受けます。既に設定ファイルが、/etc や /etc/mysql またはユーザーホームに配置してある場合は、スクリプト実行前にそれらの設定を修正してください。

# chown mysql:mysql /usr/local/mysql -R

/usr/local/mysql/support-files/systemdに、.serviceファイルが入っているのでコピーします。

余談ですが将来mysqldコマンドは、mysqld ではなく mariadbd となるようです。

それに合わせて、サービスも mysql.service(mysqld.service) と mariadb.service がありますが、両方設定します。mariadb.service が実態となっていて他はシンボリックリンクなので、mysqlの方は自作します。

コピー先は/etc/sysetmd/systemディレクトリです。コピーが終わったら、systemctl daemon-reload コマンドで更新します。

最後にsystemctl enable でOS起動時にMariaDBも起動するようにします。

# cp /usr/local/mysql/support-files/systemd/mariadb.service /etc/systemd/system/
# cd /etc/systemd/system
# ln -s  ./mariadb.service mysqld.service
# ln -s  ./mariadb.service mysql.service
# systemctl daemon-reload
# systemctl enable mariadb

mysqlのバイナリ群にパスを通します。方法は一通りではないと思いますが、ここでは/etc/profile を編集して /usr/local/mysql/bin にパスを通します。

/etc/profile

...
if [ "$(id -u)" -eq 0 ]; then
  PATH="/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/local/mysql/bin"
else
  PATH="/usr/local/bin:/usr/bin:/bin:/usr/local/mysql/bin"
fi
export PATH
...

Debianにおける設定ファイルの管理理念は、小さな複数ファイルに分割するというもので、aptでインストールすると、includedir を駆使した設定ファイル群が /etc/mysqlに配置されますが。ソースからビルドした場合はそれらの設定ファイル群は作成されません。

そのため新規インストールで設定をいちから書くなら my.cnf ファイルに集約し、/etc/mysql/my.cnf へ配置します。

ただ、DebianにおけるMariaDBの設定ファイル群のロジックは/etc/mysql/my.cnf からincludedir で連結されているだけですので、aptでインストールしたMariaDBの設定ファイル群があるならそのまま使えます。ただし、データファイルの場所等の修正は必要だと思います。

その場合のルートとなるmy.cnfでは[client-server]というサーバーでもクライアントでも読み込むセクション内で、次のように設定ファイルディレクトリを読み込んでいます。

/etc/mysql/my.cnf

[client-server]
!includedir /etc/mysql/conf.d/
!includedir /etc/mysql/mariadb.conf.d/

ビルドしたMariaDBが起動しない場合

サーバー起動しない場合には「 systemctl status mysql 」や「 journalctl -xe 」、/var/log/mysql/error.log などを参考解決していくのですが、筆者が経験した例でいくと次のような不具合でした。

datadirディレクトリの存在と権限
aptでのインストール時データディレクトリは/var/lib/mysql/dataとなっており、mysqlディレクトリの所有権はroot:root その下にあるdataディレクトリの所有権はmysql:rootとなっています。

また、InnoDB構成時は innodb_data_home_dir でのデータディレクトリにたいしても同様のチェックをします。

今回はdataディレクトリを/usr/local/mysql/dataとして、mysqlディレクトリ以下の所有権を mysql:mysql としています。
PIDファイルの出力ディレクトリの存在と権限
手っ取り早い対処法は、pid-fileの行をファイルを書かない(コメントアウトする)方法です。 PIDファイルは data ディレクトリに生成されますが、気にならないようならこの方法でもいいと思います。

aptでインストールした際と同様に /var/run/mysqld ディレクトリ内にPIDファイルを出力したいなら、mysqldディレクトリを作成する必要がありますが、その際の所有権は mysqlユーザーが書き込めるようにしないといけません(mysql:root等)。

また、/var/run(/run) ディレクトリ内に mysqld ディレクトリを手動で作成すると、情シス - 雑多メモ「CentOS 7ではまったこと：/var/run直下のディレクトリが消える」の記事にあるように、tmpfsファイルシステムとして存在する /run ディレクトリは再起動時に削除されてしまいます。伴って /run/mysql ディレクトリは存在しなくなり、再起動後はPIDファイルが生成できなくなります。

なので、aptでインストールした時の設定 pid-file=/var/run/mysqld/mysqld.pid を生かしたいならば、serviceファイルに次のような記述をします。記述する前に一度MariaDBを停止させてください。
/etc/systemd/system/mariadb.service
```
# Serviceセクションに追加します。
[Service]

# 既存のExecStartPreがあるあたりに記述するといいと思います。

# ディレクトリ作成（サービス起動前の実行）
ExecStartPre=mkdir -p /run/mysqld
# 所有権の変更
ExecStartPre=/bin/chown mysql:root /run/mysqld

# PIDファイルの指定(systemdがプロセスを追跡するためのもので記述は任意）
PIDFile=/run/mysqld/mysqld.pid
```
ちなみに、aptインストール時のサービスファイルでは上記のmysqldディレクトリ生成を次のようにして処理していました。

ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run/mysqld

記述変更後、systemctl daemon-reload を実行してサービスを再び起動させます。
ソケットファイルの設定
ソケットファイルもPIDと同様に出力ディレクトリの権限が問題になります。

また、ビルドした場合だとソケットファイルのデフォルトのパスが /tmp/mysql.sock となっているようです。そのため、旧来の50-server.cnfを再利用すると、[mysqld]セクションのsocketのエントリーでサーバー側だけソケットファイルの出力場所を変えてしまうことになり、サーバーが起動できてもmysqlコマンドから接続ができなかったりします。

50-server.cnfの[mysqld]セクションのsocketのエントリーをコメントアウトするか、50-client.cnfにsocketの場所を設定すればエラーは解消できます。ただ、それだとサーバーとクライアントの同期を人的に管理しないといけないので、ソケットファイルを明示するならmy.cnfの[server-client]セクションに統合するのがいいと思います。

aptインストール時と同様に /var/run/mysqld に出力したい場合は先ほどのPIDファイルで説明したようにサービスファイルの修正が必要です。
ログディレクトリの存在と権限
aptインストール時は /var/log/mysql となっていると思いますが、ビルドした場合はディレクトリが存在しません。これも所有権を mysql にする必要があります。ちなみにaptでインストールした際はmysql:admとなっていました。
複数の設定ファイル
編集している設定ファイルより優先順位の高い設定ファイルが既に配置しており、その設定を読み込むためうまくいかない可能性もあります。

Debianにおいての優先順位は、/etc 、 /etc/mysql 、ユーザーホームの順のようです。

ちなみに、mysqli等、PHPとの連携をしている場合は、php.ini 側もソケット設定が必要です。この情報はKUBOGEN:「mysqliでエラー「No such file or directory」が出る【PHP】」を参考にさせていただきました。
php.ini
```
...
mysqli.default_socket = /var/run/mysqld/mysqld.sock
pdo_mysql.default_socket = /var/run/mysqld/mysqld.sock
...
```

この後、レプリケーションを構築しなおしたのですが、 MariaDBでレプリ―ケーションの設定の方法は以前の記事で紹介していますので省略します。

ダウングレードに使ったバージョンは　10.3.39 で元の10.3.36とはリビジョンが違いますが安定したようです。

もうひとつ気になっていたのは利用していたサーバーが32bit機(i386)だったことで、試しに64bit機(amd64)で新たにバージョン10.5.18のサーバーを作ってレプリケーションを稼働させてみたのですが、こちらではエラーがおきませんでした。i386だといけないのかもしれませんし、このあとの更新でワーニングは起きなくなるかもしれません。(もともと切断が途切れるだけで、リトライで復旧していましたので完全に使えないわけではありません)

最後に、もしビルドしたMariaDBを使い続けるなら、ログローテーションの設定もしておきましょう。リンク先でMariaDBのログファイルを例にlogrotateの設定を紹介しています。

また、cronはユーザーの環境変数の値を考慮しませんので、cronで定期的にmysqldumpなどのMariaDBのコマンドを実行する場合は、crontabにも/usr/local/mysql/binディレクトリへのパスを通す必要があります。ユーザー別のcrontab上にPATHを設定します。

crontab -e

...
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/mysql/bin

# db dump
0 0 * * * dbdump.sh
...

参考にさせていただきましたサイトの皆様、ありがとうございました。

投稿:2023/03/21 - 更新: