Debian9→10 MySQLが起動しないときの復旧までの記録
Debian9から10にアップグレードした際に，GogsというGitサーバが動かなくなった．
原因は，アップグレードの際にmysql-serverが削除されたからだった．
Debian 10からMySQLが使えなくなったようなので，MariaDBをインストールし，AppArmorの設定を変えることで解決した．
原因特定までの道のりが遠かったので，本記事に考え方とともに作業手順を記録する．
本記事では，サーバ上のユーザ名をusername，サーバ名（ホスト名）をservernameという文字列に置き換えている．
1. Gogs（Gitサーバ）が動かない原因
systemctlで状態を調べるとActive: failedって書いてあるので，gogsが起動してないことが分かる．
$ sudo systemctl status gogs
● gogs.service - Gogs (Go Git Service)
Loaded: loaded (/etc/systemd/system/gogs.service; enabled; vendor preset: enabled)
Active: failed (Result: exit-code) since Wed 2022-02-16 15:18:57 JST; 1 day 23h ago
Process: 339 ExecStart=/opt/gogs/gogs web (code=exited, status=1/FAILURE)
Main PID: 339 (code=exited, status=1/FAILURE)
Feb 16 15:18:57 servername systemd[1]: Started Gogs (Go Git Service).
Feb 16 15:18:57 servername gogs[339]: 2022/02/16 15:18:57 [TRACE] Custom path: /opt/gogs/custom
Feb 16 15:18:57 servername gogs[339]: 2022/02/16 15:18:57 [TRACE] Log path: /opt/gogs/log
Feb 16 15:18:57 servername gogs[339]: 2022/02/16 15:18:57 [TRACE] Log Mode: File (Trace)
Feb 16 15:18:57 servername gogs[339]: 2022/02/16 15:18:57 [ INFO] Gogs 0.11.4.0405
Feb 16 15:18:57 servername systemd[1]: gogs.service: Main process exited, code=exited, status=1/FAILURE
Feb 16 15:18:57 servername systemd[1]: gogs.service: Failed with result 'exit-code'.
エラーになっているので，エラーメッセージを調べる．表示の中にLog path: /opt/gogs/logと書いてあるので，このファイルの中を調べる．
$ ls /opt/gogs/log
gogs.log hooks xorm.log
$ sudo cat /opt/gogs/log/gogs.log
2022/02/18 14:46:55 [TRACE] Log Mode: File (Trace)
2022/02/18 14:46:55 [ INFO] Gogs 0.11.4.0405
2022/02/18 14:46:55 [ INFO] Cache Service Enabled
2022/02/18 14:46:55 [ INFO] Session Service Enabled
2022/02/18 14:46:55 [FATAL] [...s/routers/install.go:67 GlobalInit()] Fail to initialize ORM engine: migrate: sync: dial tcp 127.0.0.1:3306: getsockopt: connection refused
tcp 127.0.0.1:3306: getsockopt: connection refusedと書いてあるので，3306ポート（MySQL）へのアクセスが拒否されたことが分かる．Gogsが動かない原因はMySQLにある可能性が高い
2. MySQLが動かない原因
次にMySQLの状態を調べる．
$ sudo systemctl status mysql
● mysql.service - LSB: Start and stop the mysql database server daemon
Loaded: loaded (/etc/init.d/mysql; generated)
Active: active (exited) since Wed 2022-02-16 15:18:57 JST; 5min ago
Docs: man:systemd-sysv-generator(8)
Process: 342 ExecStart=/etc/init.d/mysql start (code=exited, status=0/SUCCESS)
Feb 16 15:18:57 servername systemd[1]: Starting LSB: Start and stop the mysql database server daemon...
Feb 16 15:18:57 servername systemd[1]: Started LSB: Start and stop the mysql database server daemon.
Active: activeって書いてあるので大丈夫というわけではない．netstat -naで調べても3306ポートをListenするプロセスなどなかった．後ろにexitedと書いてある．さらにstatus=0/SUCCESSと書いてある（正常終了ということになる）．/var/log/syslogを見てもエラーメッセージはなかった．また，MySQLのログファイルは空だった．
本来は，runningになっていて，ログを書き込みながら動作し続けなければならないのにかかわらず，「正常終了」することは異常である．
そこで，エラーメッセージを確認するため，journalctlを実行した．この結果を以下に示す．
$ sudo journalctl -e
Feb 16 15:24:30 servername sudo[905]: username : TTY=pts/0 ; PWD=/home/username ; USER=root ; COMMAND=/bin/systemctl status mysql
Feb 16 15:24:30 servername sudo[905]: pam_unix(sudo:session): session opened for user root by username(uid=0)
Feb 16 15:25:08 servername sudo[905]: pam_unix(sudo:session): session closed for user root
Feb 16 15:25:43 servername sudo[908]: username : TTY=pts/0 ; PWD=/home/username ; USER=root ; COMMAND=/bin/journalctl -e
Feb 16 15:25:43 servername sudo[908]: pam_unix(sudo:session): session opened for user root by username(uid=0)
systemdで起動したプロセスに異常が発生した場合，ここに載るはずであるものの，何も書かれていないことが分かる．
ぐぐってもstatus=0/SUCCESSの事例は見つからなかった．
そこでsystemdの起動スクリプトを調査する．
$ sudo systemctl status mysql
● mysql.service - LSB: Start and stop the mysql database server daemon
Loaded: loaded (/etc/init.d/mysql; generated)
Active: active (exited) since Wed 2022-02-16 15:18:57 JST; 5min ago
Docs: man:systemd-sysv-generator(8)
Process: 342 ExecStart=/etc/init.d/mysql start (code=exited, status=0/SUCCESS)
Feb 16 15:18:57 servername systemd[1]: Starting LSB: Start and stop the mysql database server daemon...
Feb 16 15:18:57 servername systemd[1]: Started LSB: Start and stop the mysql database server daemon.
もう一度systemctlでmysqlのstatusを見るとDocs: man:systemd-sysv-generator(8)と書いてあるため，man 8 systemd-sysv-generatorを実行してマニュアルを見た．
マニュアルには以下の記述があった．
systemd-sysv-generator is a generator that creates wrapper .service units for SysV init[1] scripts in /etc/init.d/* at boot and when configuration of the system manager is reloaded.
この表記から/etc/init.d/mysqlを見ればいいことが分かる．
バイナリではないことを祈りながら，このファイルを開いてみるとシェルスクリプトだった．
case "${1:-''}" in
'start')
sanity_checks;
# Start daemon
log_daemon_msg "Starting MySQL database server" "mysqld"
if mysqld_status check_alive nowarn; then
log_progress_msg "already running"
log_end_msg 0
else
# Could be removed during boot
test -e /var/run/mysqld || install -m 755 -o mysql -g root -d /var/run/mysqld
# Start MySQL!
/usr/bin/mysqld_safe > /dev/null 2>&1 &
# 6s was reported in #352070 to be too few when using ndbcluster
# 14s was reported in #736452 to be too few with large installs
for i in $(seq 1 30); do
sleep 1
if mysqld_status check_alive nowarn ; then break; fi
log_progress_msg "."
done
if mysqld_status check_alive warn; then
log_end_msg 0
# Now start mysqlcheck or whatever the admin wants.
output=$(/etc/mysql/debian-start)
[ -n "$output" ] && log_action_msg "$output"
else
log_end_msg 1
log_failure_msg "Please take a look at the syslog"
fi
fi
;;
上記のコードのうち，Start MySQL!の下にある/usr/bin/mysqld_safe > /dev/null 2>&1 &が起動スクリプトである可能性が高い．
標準出力と標準エラー出力がすべて/dev/nullに行って消えるようになっているので，エラーメッセージが見えないようになっている．
そこで，このスクリプトを直接起動する．
$ /usr/bin/mysqld_safe
-bash: /usr/bin/mysqld_safe: No such file or directory
結果はNo such file or directoryだった．スクリプトが無いことが分かる．
$ pwd
/usr/bin
$ ls mysql*
mysql mysqladmin mysqlbug mysql_client_test mysqldumpslow mysql_fix_extensions mysql_install_db mysql_plugin mysqlreport mysqlslap mysql_waitpid
mysqlaccess mysqlanalyze mysqlcheck mysqldump mysql_find_rows mysqlimport mysqloptimize mysqlrepair mysqlshow mysql_upgrade
MySQLはクライアントサーバモデルである．クライアントはmysql，サーバはmysqldである．
mysqldで始まるファイルが1つもない．
アップグレード前のバックアップでこのディレクトリの中身を調べたら，以下の通りだった．
$ ls mysql*
mysql mysqldump mysql_secure_installation
mysqlaccess mysqldumpslow mysql_setpermission
mysqladmin mysql_find_rows mysqlshow
mysqlanalyze mysql_fix_extensions mysqlslap
mysqlbinlog mysqlhotcopy mysqltest
mysqlbug mysqlimport mysql_tzinfo_to_sql
mysqlcheck mysql_install_db mysql_upgrade
mysql_client_test mysqloptimize mysql_waitpid
mysql_convert_table_format mysql_plugin mysql_zap
mysqld_multi mysqlrepair
mysqld_safe mysqlreport
Debian 9にはmysqldからはじまるファイル名のスクリプトが残っていて，Debian 10にアップデートした後には残っていない．
このことから，Debian 10 にあげるときにmysqld関連がすべて削除されてしまったことが分かった．
MySQLが動かない原因は，MySQLのサーバ（mysqld）が削除されたことである．
3. MySQLのサーバが削除された原因
Debian 9から10の間でMySQLのサーバが削除された．そこでアップグレード時のログを確認する．ログの取得手順は，Debianのマニュアルの通りである．
$ less upgrade-busterstep.script
lessで/mysqlと入力することでmysqlを検索すると以下の記述が見つかった．
Calculating upgrade... The following packages were automatically installed and are no longer required:
cpp-6 dh-python g++-4.9 gnupg-agent libaio1 libbind9-90
libdbd-mysql-perl libdbi-perl libdbus-glib-1-2
libdns-export162 libdns100 libevent-2.0-5 libintl-perl
libintl-xs-perl libisc-export160 libisc95 libisccc90
libisccfg90 libkdb5-7 liblwres90 libmariadb3
libmysqlclient18 libprocps6 libpth20
libpython3.5-minimal libpython3.5-stdlib
libregexp-common-perl libstdc++-4.9-dev
libterm-readkey-perl libtinfo-dev libunistring0
libxapian22 mariadb-common mysql-client-5.5 mysql-common
mysql-server-core-5.5 python-defusedxml python-pyasn1
python-soappy python-wstools python3-distutils
python3-lib2to3 python3.5 python3.5-minimal rename rsync
ruby2.3 sgml-base tcpd xml-core
Use 'apt-get autoremove' to remove them.
Done
The following packages will be REMOVED:
libcpan-meta-perl libcurl3 libcwidget3 libkadm5clnt-mit9
libkadm5srv-mit9 libreadline6-dev libsigc++-2.0-0c2a
libtirpc1 mysql-server mysql-server-5.5 perl-modules
The following packages will be REMOVED:にmysql-serverとmysql-server-5.5があるので，
MySQLサーバが削除された可能性が高い．
4. MySQLサーバのインストール
削除されたmysql-serverをインストールすることを試みた．
この結果，mysql-serverのかわりにmysql-server-5.5を使うように言われた．
$ sudo apt-get install mysql-server
Reading package lists... Done
Building dependency tree
Reading state information... Done
Package mysql-server is not available, but is referred to by another package.
This may mean that the package is missing, has been obsoleted, or
is only available from another source
However the following packages replace it:
mysql-server-5.5
次に，mysql-server-5.5のインストールを試みると，
mariadb-server-10.3とmysql-commonを入れるように言われた．
$ sudo apt-get install mysql-server5.5
Reading package lists... Done
Building dependency tree
Reading state information... Done
E: Unable to locate package mysql-server5.5
E: Couldn't find any package by glob 'mysql-server5.5'
E: Couldn't find any package by regex 'mysql-server5.5'
username@servername:~$ sudo apt-get install mysql-server-5.5
Reading package lists... Done
Building dependency tree
Reading state information... Done
Package mysql-server-5.5 is not available, but is referred to by another package.
This may mean that the package is missing, has been obsoleted, or
is only available from another source
However the following packages replace it:
mariadb-server-10.3 mysql-common
mariadb-serverのバージョンって10.3が普通なのか確かめるために，
apt searchで他のバージョンのパッケージが無いか探してみた．
$ sudo apt search mariadb-server-*
Sorting... Done
Full Text Search... Done
mariadb-server/oldstable 1:10.3.31-0+deb10u1 all
MariaDB database server (metapackage depending on the latest version)
mariadb-server-10.3/oldstable 1:10.3.31-0+deb10u1 amd64
MariaDB database server binaries
mariadb-server-core-10.3/oldstable 1:10.3.31-0+deb10u1 amd64
MariaDB database core server files
mariadb-serverは10.3しかなさそうであることが分かった．
そこで，mariadb-serverの10.3など，mysqlをインストールを試みた時に書かれていたものをインストールする．
$ sudo apt install mariadb-server-10.3 mysql-common
The following additional packages will be installed:
galera-3 libconfig-inifiles-perl libreadline5 libsnappy1v5 mariadb-client-10.3 mariadb-client-core-10.3
mariadb-server-core-10.3 socat
Suggested packages:
mariadb-test netcat-openbsd tinyca
The following packages will be REMOVED:
mysql-client-5.5 mysql-server-core-5.5
The following NEW packages will be installed:
galera-3 libconfig-inifiles-perl libreadline5 libsnappy1v5 mariadb-client-10.3 mariadb-client-core-10.3
mariadb-server-10.3 mariadb-server-core-10.3 socat
0 upgraded, 9 newly installed, 2 to remove and 0 not upgraded.
実行した結果，mysql関連のパッケージが自動で削除されて，mariadbがインストールされた．
systemctl statusで正しくインストールされたか確認する．
$ sudo systemctl status mysql
● mariadb.service - MariaDB 10.3.31 database server
Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
Active: active (exited) since Wed 2022-02-16 16:16:13 JST; 2 days ago
Docs: man:mysqld(8)
https://mariadb.com/kb/en/library/systemd/
Tasks: 0 (limit: 1149)
Memory: 0B
CGroup: /system.slice/mariadb.service
mysqlがmariadbになっただけで，何も変わってなさそう
そこで，試しにmariadb-serverを再起動した．
$ sudo systemctl restart mysql
Job for mariadb.service failed because the control process exited with error code.
See "systemctl status mariadb.service" and "journalctl -xe" for details.
再起動の結果，MariaDBが起動しないトラブルが発生した．
5. MariaDBが起動しない原因の調査
Feb 18 17:56:10 servername audit[10292]: AVC apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/etc/mysql/mariadb.conf.d/" pid=10292 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=109 ouid=0
Feb 18 17:56:10 servername mysqld[10292]: [99B blob data]
Feb 18 17:56:10 servername mysqld[10292]: Fatal error in defaults handling. Program aborted
Feb 18 17:56:10 servername kernel: audit: type=1400 audit(1645174570.034:11): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/etc/mysql/mariadb.conf.d/" pid=10292 comm="mysqld" requested_mask="r" denied_mask="r" fsu
Feb 18 17:56:10 servername systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
-- Subject: Unit process exited
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- An ExecStart= process belonging to unit mariadb.service has exited.
--
-- The process' exit code is 'exited' and its exit status is 1.
Feb 18 17:56:10 servername systemd[1]: mariadb.service: Failed with result 'exit-code'.
-- Subject: Unit failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- The unit mariadb.service has entered the 'failed' state with result 'exit-code'.
Feb 18 17:56:10 servername systemd[1]: Failed to start MariaDB 10.3.31 database server.
-- Subject: A start job for unit mariadb.service has failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
上記の記述の中に$ sudo systemctl restart mysql Job for mariadb.service failed because the control process exited with error code. See "systemctl status mariadb.service" and "journalctl -xe" for details.と書かれていて，AppArmorが拒否したためにMariaDBが起動していないことが分かった．
AppArmorは強制アクセス制御をするもので，Debian 10にアップグレードしたときにインストールされたものである．
/usr/sbin/mysqldのプロファイルがブロックしてしまったことが分かった．
6. AppArmorの設定の変更
次にAppArmorの設定を変更した．
AppArmorを触るのは初めてだったので以下のWebサイトを参考にした．
https://wiki.archlinux.jp/index.php/AppArmor
http://l.github.io/debian-handbook/html/ja-JP/sect.apparmor.html
まずはAppArmorが動作しているか確認したところ，動作していることがわかった．
$ aa-enabled
Yes
次に何が動作しているか確認した．/usr/sbin/mysqldがenforce modeで動いていることが分かる．
$ sudo apparmor_status
apparmor module is loaded.
6 profiles are loaded.
6 profiles are in enforce mode.
/usr/bin/man
/usr/sbin/mysqld
man_filter
man_groff
nvidia_modprobe
nvidia_modprobe//kmod
0 profiles are in complain mode.
0 processes have profiles defined.
0 processes are in enforce mode.
0 processes are in complain mode.
0 processes are unconfined but have a profile defined.
次に設定ファイルを見ると/etc/apparmor.d/usr.sbin.mysqldが存在した．そこで，このファイルの中身を確認した．#で始まる行がコメントアウトなので，実質，空のファイルであることが分かる．
$ ls /etc/apparmor.d/
abstractions disable force-complain local nvidia_modprobe tunables usr.bin.man usr.sbin.mysqld
$ cat /etc/apparmor.d/usr.sbin.mysqld
# This file is intensionally empty to disable apparmor by default for newer
# versions of MariaDB, while providing seamless upgrade from older versions
# and from mysql, where apparmor is used.
#
# By default, we do not want to have any apparmor profile for the MariaDB
# server. It does not provide much useful functionality/security, and causes
# several problems for users who often are not even aware that apparmor
# exists and runs on their system.
#
# Users can modify and maintain their own profile, and in this case it will
# be used.
#
# When upgrading from previous version, users who modified the profile
# will be promptet to keep or discard it, while for default installs
# we will automatically disable the profile.
AppArmorはプロファイルが無い場合はすべて許可され，プロファイルがある場合はデフォルトですべて拒否になるという噂が聞こえてきた（根拠なし）．それが本当であれば、/usr/sbin/mysqldのすべての動作がブロックされることになる．少なくとも空のプロファイルは不必要なので無効にする．この操作には再起動が必要になった．
$ sudo ln -s /etc/apparmor.d/usr.sbin.mysqld /etc/apparmor.d/disable/
$ sudo apparmor_parser -R /etc/apparmor.d/usr.sbin.mysqld
$ reboot
AppArmorのmysqldのプロファイルを無効にするとmysql（実態はMariaDB）が起動した．
$ sudo systemctl status mysql
● mariadb.service - MariaDB 10.3.31 database server
Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset:
Active: active (running) since Fri 2022-02-18 18:56:50 JST; 26s ago
Docs: man:mysqld(8)
https://mariadb.com/kb/en/library/systemd/
Process: 335 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run
Process: 368 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_
Process: 372 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR=
Process: 457 ExecStartPost=/bin/sh -c systemctl unset-environment _WSREP_START
Process: 459 ExecStartPost=/etc/mysql/debian-start (code=exited, status=0/SUCC
Main PID: 421 (mysqld)
Status: "Taking your SQL requests now..."
Tasks: 31 (limit: 1149)
Memory: 152.2M
CGroup: /system.slice/mariadb.service
mq421 /usr/sbin/mysqld
しかし，再起動直後にはGogsが動作していなかった．
● gogs.service - Gogs (Go Git Service)
Loaded: loaded (/etc/systemd/system/gogs.service; enabled; vendor preset: ena
Active: failed (Result: exit-code) since Fri 2022-02-18 18:56:50 JST; 1min 35
Process: 342 ExecStart=/opt/gogs/gogs web (code=exited, status=1/FAILURE)
Main PID: 342 (code=exited, status=1/FAILURE)
Feb 18 18:56:50 servername systemd[1]: Started Gogs (Go Git Service).
Feb 18 18:56:50 servername gogs[342]: 2022/02/18 18:56:50 [TRACE] Custom path:
Feb 18 18:56:50 servername gogs[342]: 2022/02/18 18:56:50 [TRACE] Log path: /op
Feb 18 18:56:50 servername gogs[342]: 2022/02/18 18:56:50 [TRACE] Log Mode: Fil
Feb 18 18:56:50 servername gogs[342]: 2022/02/18 18:56:50 [ INFO] Gogs 0.11.4.0
Feb 18 18:56:50 servername systemd[1]: gogs.service: Main process exited, code=
Feb 18 18:56:50 servername systemd[1]: gogs.service: Failed with result 'exit-c
そこで，sudo systemctl restart gogsを実行すると動作した．
$ sudo systemctl status gogs
● gogs.service - Gogs (Go Git Service)
Loaded: loaded (/etc/systemd/system/gogs.service; enabled; vendor preset: ena
Active: active (running) since Fri 2022-02-18 18:58:42 JST; 1s ago
Main PID: 829 (gogs)
Tasks: 7 (limit: 1149)
Memory: 30.5M
CGroup: /system.slice/gogs.service
mq829 /opt/gogs/gogs web
Feb 18 18:58:42 servername systemd[1]: Started Gogs (Go Git Service).
Feb 18 18:58:42 servername gogs[829]: 2022/02/18 18:58:42 [TRACE] Custom path:
Feb 18 18:58:42 servername gogs[829]: 2022/02/18 18:58:42 [TRACE] Log path: /op
Feb 18 18:58:42 servername gogs[829]: 2022/02/18 18:58:42 [TRACE] Log Mode: Fil
Feb 18 18:58:42 servername gogs[829]: 2022/02/18 18:58:42 [ INFO] Gogs 0.11.4.0
起動直後にsystemdによってgogsが起動される場合，gogsの起動に失敗する．
このままでは，起動後に手動でsudo systemctl restart gogsを実行する必要があり。面倒である．
7. Gogsの起動に失敗する問題の解決
systemdの設定ファイルを書き換えることで解決した．
参考にしたURLは以下
After=mysql.serviceが無かったので追記した．
/etc/systemd/system/gogs.service
[Unit]
Description=Gogs (Go Git Service)
After=syslog.target
After=network.target
After=postgresql.service
After=nginx.service
After=mysql.service
[Service]
Type=simple
User=git
Group=git
WorkingDirectory=/opt/gogs
ExecStart=/opt/gogs/gogs web
Restart=no
Environment=USER=git HOME=/home/git
[Install]
WantedBy=multi-user.target
MariaDBなのにmysqldで良いのか気になったので調べた．mysqld.serviceはMariaDBに対するシンボリックリンクになっていたので問題なかった．
lrwxrwxrwx 1 root root 35 Feb 18 17:31 mysqld.service -> /lib/systemd/system/mariadb.service
lrwxrwxrwx 1 root root 35 Feb 18 17:31 mysql.service -> /lib/systemd/system/mariadb.service
おわり
Debian 9から10にあげたときにMySQLが使えなくなった．また、AppArmorが有効になった．
MySQLのかわりにMariaDBを使用し，MariaDBに関連するAppArmorのプロファイルを無効化することで対処した．最後にGogsのsystemdの.serviceファイルを修正して，MariaDBが起動した後にGogsが起動するように修正した．これにより，サーバ起動時にGogsが自動で起動するようになった．