この記事は新歓ブログリレー2020の23日目(3/31)の記事です。
19のSysAd班の翠(sappi_red)です。

時間が巻き戻ってる…？

3月2日のことでした。
「2月15日～今日の18時ごろの変更だけがすべて消えてるみたい」
正直、全然意味が分からなかったです。
すべてのデータが消えたり特定のページ・ユーザーのデータが消えたりするのは百歩譲ってわかるんですが、特定の期間のデータだけが消えるというのは腑に落ちない事態でした。

思い当たることをあげるとすれば、この日あるディレクトリを削除したことです。そのディレクトリは前回のAnsibleの記事で言及したように、WikiのDockerイメージをGitHub Packagesから取得する変更をした際にバックアップとして一時的につくったものです。

具体的には、/srv/crowiというパス以下に保存されていたWiki用のデータやソースを/srv/crowi-oldに移した後、/srv/crowi-oldから一部のファイルを、作り直した/srv/crowiディレクトリにコピーしました。

ファイルがない

とりあえずWikiで利用しているMongoDBのエラーを見たところ以下のようにファイルが存在しないというエラーが3/2の19時ごろに出ていることが確認できました^[1]。

$ sudo docker logs 7f005fdef8a8 | grep error
2020-03-02T10:15:47.709+0000 E STORAGE  [thread292] WiredTiger error (2) [1583144147:698912][1:0x7fd2eeeb9700], log-server: /data/db/journal: directory-list: opendir: No such file or directory
2020-03-02T10:15:47.711+0000 E STORAGE  [thread292] WiredTiger error (2) [1583144147:711019][1:0x7fd2eeeb9700], log-server: log pre-alloc server error: No such file or directory
2020-03-02T10:15:47.712+0000 E STORAGE  [thread292] WiredTiger error (2) [1583144147:712037][1:0x7fd2eeeb9700], log-server: log server error: No such file or directory
2020-03-02T10:15:47.712+0000 E STORAGE  [thread292] WiredTiger error (-31804) [1583144147:712389][1:0x7fd2eeeb9700], log-server: the process must exit and restart: WT_PANIC: WiredTiger library panic

/data/dbというのはWikiで利用しているMongoDBのデータが保存されているDockerイメージ内でのパスです。ここがホストマシン側の/srv/crowi/dataに露出されています。

時系列の整理

AnsibleのスクリプトがあるGitリポジトリのマージ記録によると、WikiでGitHub Packagesを利用するようにしたAnsibleを実行したのは、2/15の20時～22時あたりであることがわかりました。
また、自分が/srv/crowi-oldを削除したのは、3/2の19時～20時あたりだった記憶が残ってました。
ファイルが存在しないエラーが出ていたのが3/2の19時で、データが失われた期間は2/15～3/2ということを照らし合わせると、「なんらかの要因でDockerコンテナの/data/dbが/srv/crowi-oldを参照していて、自分が/srv/crowi-oldを消したあと、上記のエラーでコンテナが落ち、コンテナが自動で再起動したタイミングで/data/dbが/srv/crowiを参照するようになった」ということが考えられます。

復旧

とりあえず仮説は立ったのでデータが消えたタイミングで止めておいたWikiを復旧する作業をしました。
旧インスタンスで@takashi_trapさんが動かしてくれていた毎朝DBのバックアップをとるスクリプトを@temmaくんが新インスタンスでも動くように書き換えてくれていたので、そのデータを利用してその日の4時の段階のデータまで復旧をした上でその日の19時以降の変更を適用しました^[2]。
結果として3/2の4時～19時のデータは失われてしまったのですが、その間はそこまで変更がなかったため大半のデータは救い出すことができました。

仮説の検証

GitHub Packagesから取得するようにした際のコマンドの履歴をhistoryコマンドで取得したものが次の通りです。

$ sudo docker ps # Dockerコンテナの確認
$ sudo docker stop 82346097f2df # Crowi本体のコンテナの停止
$ sudo docker stop d7e705b35bff # CrowiのMongoDBコンテナの停止
$ sudo docker ps # 停止したことを確認
$ ls /srv/crowi
$ sudo mv /srv/crowi /srv/crowi-old # 一旦すべてのデータを移動
$ sudo mkdir /srv/crowi # 新しく作り直し
$ sudo mkdir /srv/crowi/data
$ ls /srv/crowi-old/data
$ sudo cp -R /srv/crowi-old/data/monogodb /srv/crowi/data # データをコピー
$ ls /srv/crowi

ここで注目したいのがmvを利用して移動している箇所です。
Linuxではそれぞれのファイルやディレクトリの実体と場所をリンクするために、inodeというものを利用しています。例えば、ハードリンクという複数の場所から同じ実体を参照させられるようにする機能を利用すると、別々の場所に同じinode番号が記録されます^[3]。逆にシンボリックリンクという同じような機能を利用した場合は、ある場所にある場所への短縮経路みたいなものが作られます。
cpを利用してコピーをして元のディレクトリを削除した場合は、もちろん実体がコピーされるので別の実体になります。それに対してmvを利用して移動した場合は、同じ実体になります。

lsの際にiオプションをつけるとinode番号を取得できるのでそれを利用してmvする前後のinode番号を確認すると、下記のように一致していることがわかります。dataディレクトリのinode番号が1708821でmonogodbディレクトリ^[4]のinode番号が1708822です。

$ ls -lia data
total 12
1708821 drwxr-xr-x 3 root root 4096 Feb 12 19:59 .
1708820 drwxr-xr-x 4 root root 4096 Mar 10 20:57 ..
1708822 drwxr-xr-x 4  999 root 4096 Mar 20 16:18 monogodb
$ sudo mv data data2
$ ls -lia data2
total 12
1708821 drwxr-xr-x 3 root root 4096 Feb 12 19:59 .
1708820 drwxr-xr-x 4 root root 4096 Mar 20 16:19 ..
1708822 drwxr-xr-x 4  999 root 4096 Mar 20 16:18 monogodb

docker-compose upしている状態でディレクトリを移動する

$ ls -lia data
total 12
1708821 drwxr-xr-x 3 root root 4096 Feb 12 19:59 .
1708820 drwxr-xr-x 4 root root 4096 Mar 10 20:57 ..
1708822 drwxr-xr-x 4  999 root 4096 Mar 20 16:18 monogodb
$ sudo mv data data2
$ ls -lia data2
total 12
1708821 drwxr-xr-x 3 root root 4096 Feb 12 19:59 .
1708820 drwxr-xr-x 4 root root 4096 Mar 20 16:19 ..
1708822 drwxr-xr-x 4  999 root 4096 Mar 20 16:18 monogodb

移動後もdataディレクトリは作成されずdata2のデータが参照されていました。

docker-compose upしている状態でディレクトリを削除する

$ sudo docker-compose up -d
Creating network "crowi_default" with the default driver
Creating crowi_crowi_1   ... done
Creating crowi_redis_1   ... done
Creating crowi_mongodb_1 ... done
$ ls -lia data
total 12
1808907 drwxr-xr-x 3 root root 4096 Mar 20 16:26 .
1708820 drwxr-xr-x 5 root root 4096 Mar 20 16:26 ..
1808908 drwxr-xr-x 2 root root 4096 Mar 20 16:26 monogodb
$ sudo rm -r data
$ ls -lia data
ls: cannot access 'data': No such file or directory
$ # ここでwikiにアクセスをする
$ ls -lia data
total 12
1808907 drwxr-xr-x 3 root root 4096 Mar 20 16:26 .
1708820 drwxr-xr-x 5 root root 4096 Mar 20 16:26 ..
1808908 drwxr-xr-x 4  999 root 4096 Mar 20 16:26 monogodb

docker-composeで起動した状態でデータの入っているディレクトリを消すとデータは消失せずディレクトリが復活しました。
プロセスがファイルを参照している場合はファイルの実体は消えず参照だけが消えるらしいので、正常にアクセスできることはそこまで不思議ではないのですが、復活するというのは不思議な挙動です。

$ sudo docker inspect fdec9362cbbd
                "MergedDir": "/var/lib/docker/overlay2/7dd037473b0baf8e8f11c30b2b19e690ca1582d1ab9921eae45cbd201a9b7b6d/merged",
                "UpperDir": "/var/lib/docker/overlay2/7dd037473b0baf8e8f11c30b2b19e690ca1582d1ab9921eae45cbd201a9b7b6d/diff",
                "WorkDir": "/var/lib/docker/overlay2/7dd037473b0baf8e8f11c30b2b19e690ca1582d1ab9921eae45cbd201a9b7b6d/work"
            },
            "Name": "overlay2"
        },
        "Mounts": [
            {
                "Type": "bind",
                "Source": "/srv/crowi/data/monogodb",
                "Destination": "/data/db",
                "Mode": "rw",
                "RW": true,
                "Propagation": "rprivate"
            },
$ sudo ls -lia /var/lib/docker/overlay2/7dd037473b0baf8e8f11c30b2b19e690ca1582d1ab9921eae45cbd201a9b7b6d/merged/data
total 16
1575385 drwxr-xr-x 4 root root 4096 Mar 14  2018 .
 391969 drwxr-xr-x 1 root root 4096 Mar 20 16:31 ..
1575386 drwxr-xr-x 2  999 adm  4096 Mar 14  2018 configdb
1575387 drwxr-xr-x 2  999 adm  4096 Mar 14  2018 db

docker-compose upする前に別のinode番号のディレクトリを置く

$ ls -lia
total 28
1708820 drwxr-xr-x 5 root root 4096 Mar 20 16:26 .
1703937 drwxr-xr-x 6 root root 4096 Feb 12 19:58 ..
1808907 drwxr-xr-x 3 root root 4096 Mar 20 16:26 data
1708821 drwxr-xr-x 3 root root 4096 Feb 12 19:59 data2
1259927 -rwxr-xr-x 1 root root  179 Mar 10 20:52 deploy.sh
1810454 -rw-r--r-- 1 root root  847 Feb 26 02:52 docker-compose.yml
1807530 drwxr-xr-x 6 root root 4096 Mar  4 17:13 public
$ sudo rm -r data
$ ls -lia
total 24
1708820 drwxr-xr-x 4 root root 4096 Mar 20 16:31 .
1703937 drwxr-xr-x 6 root root 4096 Feb 12 19:58 ..
1708821 drwxr-xr-x 3 root root 4096 Feb 12 19:59 data2
1259927 -rwxr-xr-x 1 root root  179 Mar 10 20:52 deploy.sh
1810454 -rw-r--r-- 1 root root  847 Feb 26 02:52 docker-compose.yml
1807530 drwxr-xr-x 6 root root 4096 Mar  4 17:13 public
$ sudo mv data2 data
$ ls
data  deploy.sh  docker-compose.yml  public
$ sudo docker-compose up -d
Creating network "crowi_default" with the default driver
Creating crowi_redis_1   ... done
Creating crowi_mongodb_1 ... done
Creating crowi_crowi_1   ... done

wikiにアクセスをするとdata2のデータが入っていました(inode番号が変わっていても同じパスのデータが読み込めていた)。

検証のまとめ

これらの結果からおそらくdocker start/docker stopで行う(つまり、docker-composeを経由しない)場合は、dockerがinode番号でディレクトリのマウントを保持しているため、今回のようなことが発生するのではないかなと思います。逆にdocker-composeはディレクトリをパスで保持(?)するためdocker-compose downとdocker-compose upで行う場合はinode番号の再取得みたいなことが起こり発生しないと予想してます。コンテナの作成時にその処理が走ると思われるのでdocker-compose stopとdocker-compose startで行うと同じようなことが発生するかもしれません。

感想

バックアップは非常に大切なので、こまめなバックアップを心がけましょう。
ファイルを削除する前にファイルの変更日時のチェックをするとよいかもしれません。

明日は @Facish さんの記事です。お楽しみに！