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が自動で起動するようになった．