復元失敗:Data Explorer の問題の可能性

動作しているフォーラムがあり、数日前に問題が発生した内容を確認したいと考えています。AWS を使用しているため、動作中のフォーラムの AMI を作成し、新しいインスタンスを起動して、数日前のバックアップを復元しようとしましたが、以下のメッセージで失敗しました。

サーバーは動作中のフォーラムの新しいイメージから構築されているため、バージョンやスキーマの不整合が原因であるはずがありません。

再構築を試みました。

1 日前の別のバックアップからの復元を試みましたが、同じ結果でした。

私が行った唯一の奇妙な操作は、空き容量を確保するためにアップロードディレクトリ(…/uploads/original/1X/*.pdf)から PDF ファイルを削除したことです。このステップを省いて再度試してみますが、これが原因である可能性は低いと思われます。

> [2019-11-30 01:17:44] 'admin' has started the restore!
> [2019-11-30 01:17:44] Marking restore as running...
> [2019-11-30 01:17:44] Making sure /var/www/discourse/tmp/restores/default/2019-11-30-011744 exists...
> [2019-11-30 01:17:44] Downloading archive to tmp directory...
> [2019-11-30 01:23:24] Unzipping archive, this may take a while...
> [2019-11-30 01:27:52] No metadata file to extract.
> [2019-11-30 01:27:52] Validating metadata...
> [2019-11-30 01:27:52]   Current version: 20191129144706
> [2019-11-30 01:27:52]   Restored version: 20191120015344
> [2019-11-30 01:27:52] Extracting dump file...
> [2019-11-30 01:50:57] invalid command \N
> [2019-11-30 01:50:57] invalid command \N
> 
> < 約 100 回繰り返される >
> 
> [2019-11-30 01:51:07] invalid command \N
> [2019-11-30 01:54:13] invalid command \N
> [2019-11-30 01:54:13] EXCEPTION: psql failed
> [2019-11-30 01:54:14] /var/www/discourse/lib/backup_restore/restorer.rb:331:in `restore_dump'
> /var/www/discourse/lib/backup_restore/restorer.rb:75:in `run'
> /var/www/discourse/lib/backup_restore.rb:166:in `block in start!'
> /var/www/discourse/lib/backup_restore.rb:163:in `fork'
> /var/www/discourse/lib/backup_restore.rb:163:in `start!'
> /var/www/discourse/lib/backup_restore.rb:22:in `restore!'
> /var/www/discourse/app/controllers/admin/backups_controller.rb:119:in `restore'
> など...

それでもなお、invalid command \N エラーは、Postgres のバージョン不整合に典型的なものです。

root@example:/var/www/discourse# psql --version
psql (PostgreSQL) 10.10 (Debian 10.10-1.pgdg100+1)

新しいサーバーと動作しているフォーラムでも同じバージョンです。

私はそのエラーを PostgreSQL のバージョン不一致に関連付けようとしていましたが、先日、ディスク容量が不足していたシステムで \N エラーが発生しているのを目にしました(バックアップを作成した同じシステムにリストアしていました)。問題の診断は完了していません(当時、私が直面していた別の奇妙な問題であり、バックアップを別のサーバーにリストアすることで解決しました。同じサーバーにリストアしても解決したかどうかは疑問です)。

あなたはディスク容量が不足していると述べられていました。おそらく、それが原因だと思われます。リストア時には、バックアップを解凍するため、バックアップの完全なコピーが 2 つ存在する状態になり、さらにリストアに必要なスペースと、失敗時にロールバックできるためのスペースも必要となります。

つまり、失敗するまでに23分かかるということですか?

状況はさらに悪化しますが、もしかすると真の問題に近づいているかもしれません…ディスク容量が不足しているという仮説に基づき、以前は 50 GB だったものを今回は 100 GB にして、イメージから新しいインスタンスを作成しました。(バックアップは各 5 GB で S3 に保存されています。)今回は「No space left on device(デバイスに空き領域がありません)」という明確なエラーが表示されました。しかし、df コマンドを見ると空き容量はたっぷりあります。

> [2019-11-29 22:42:58] Making sure /var/www/discourse/tmp/restores/default/2019-11-29-224258 exists...
> [2019-11-29 22:42:58] Downloading archive to tmp directory...
> [2019-11-29 22:45:46] Unzipping archive, this may take a while...
> [2019-11-29 22:51:46] No metadata file to extract.
> [2019-11-29 22:51:46] Validating metadata...
> [2019-11-29 22:51:46]   Current version: 20191129144706
> [2019-11-29 22:51:46]   Restored version: 20191108000414
> [2019-11-29 22:51:46] Extracting dump file...
> [2019-11-29 22:53:47] EXCEPTION: No space left on device @ io_write - /shared/tmp/restores/default/2019-11-29-224258/dump.sql

> [ec2-user@ip-172-31-47-237 discourse]$ df / -h
> Filesystem      Size  Used Avail Use% Mounted on
> /dev/xvda1       99G   28G   71G  28% /

興味深いことに、参照されているディレクトリには何も存在しません。

> /var/www/discourse# ls /shared/tmp/*
> /shared/tmp/backups:
> < empty >
> /shared/tmp/restores:
> < empty >

スワップファイルに問題があるのでしょうか?EC2 インスタンスはメモリ 2 GB の t2.small であるため、動作しているフォーラムでは以前から スワップファイルを作成 していました。新しいインスタンスにもスワップファイルが複製されていると推測されます。私は専門家ではありませんが、新しいスワップファイルを作成できないこと、および以下の出力から、スワップファイルは存在していると考えています。

> /var/www/discourse# swapon -s
> Filename                                Type            Size    Used    Priority
> /swapfile                               file            2097148 1024    -2

inode の問題かもしれません。df -i の出力結果はどうなっていますか?

df -i
ファイルシステム イノード 使用数 空き数 使用率 マウント先
devtmpfs 252562 437 252125 1% /dev
tmpfs 255203 1 255202 1% /dev/shm
/dev/xvda1 6553600 737194 5816406 12% /

専門外のことですが、これは問題ないと思われますか?

いいえ、大丈夫です。

「No space left on device(デバイスに空き領域がありません)」というエラーは、ギガバイト単位の容量が尽きたときだけでなく、ファイルシステムが inode を使い果たしたときにも発生します。ただし、今回のケースでは明らかにそれが原因ではありません(その場合、iUse% は 100% になっていたはずです)。

まだうまくいきません。動作している EC2 インスタンスの AMI を起動する代わりに、新しい Lightsail インスタンスでリストアを試してみようと思いました。それでも失敗しますが、エラーメッセージは少し異なります。

古いインスタンスも新しいインスタンスも最新の状態であり、どちらも 標準的な Docker インストール で、同じ PostgreSQL バージョンを実行しています。

psql --version
psql (PostgreSQL) 10.10 (Debian 10.10-1.pgdg100+1)

これは正常でしょうか。

Creating missing functions in the discourse_functions schema
Cannot restore into different schema, restoring in-place

プラグインが原因でしょうか?「ソース」サイトには、サポートされているプラグインとカスタムプラグインの両方を含む複数のプラグインがインストールされています。いくつかのカスタムユーザーフィールドを使用するものもあります。「ソース」サイトとは別に、プラグインあり・なしのクリーンな「宛先」サイトへのリストアを試みました。

スキーマを比較し始めるためのヒントはありますか?

> [2019-12-07 04:51:36] 'admin' has started the restore!
> [2019-12-07 04:51:36] Marking restore as running...
> [2019-12-07 04:51:36] Making sure /var/www/discourse/tmp/restores/default/2019-12-07-045136 exists...
> [2019-12-07 04:51:36] Downloading archive to tmp directory...
> [2019-12-07 04:53:49] Unzipping archive, this may take a while...
> [2019-12-07 04:57:12] No metadata file to extract.
> [2019-12-07 04:57:12] Validating metadata...
> [2019-12-07 04:57:12]   Current version: 20191129144706
> [2019-12-07 04:57:12]   Restored version: 20191120015344
> [2019-12-07 04:57:12] Extracting dump file...
> [2019-12-07 04:59:10] Creating missing functions in the discourse_functions schema
> [2019-12-07 04:59:11] Cannot restore into different schema, restoring in-place
> [2019-12-07 05:05:02] ERROR:  current transaction is aborted, commands ignored until end of transaction block
> [2019-12-07 05:05:03] ERROR:  current transaction is aborted, commands ignored until end of transaction block
> < 約 100 回繰り返される >
> [2019-12-07 05:05:03] ERROR:  current transaction is aborted, commands ignored until end of transaction block
> [2019-12-07 05:05:03] EXCEPTION: psql failed
> [2019-12-07 05:05:03] /var/www/discourse/lib/backup_restore/restorer.rb:331:in `restore_dump'
> /var/www/discourse/lib/backup_restore/restorer.rb:75:in `run'
> /var/www/discourse/lib/backup_restore.rb:166:in `block in start!'
> /var/www/discourse/lib/backup_restore.rb:163:in `fork'
> /var/www/discourse/lib/backup_restore.rb:163:in `start!'
> /var/www/discourse/lib/backup_restore.rb:22:in `restore!'
> /var/www/discourse/app/controllers/admin/backups_controller.rb:119:in `restore'
> < 以降のトレースバック >

はい、それは正常です。

PostgreSQL の内部で明らかに何かが問題を起こしています。ログを確認されましたか?

可能性は低いですが、メモリに関連する問題でしょうか?リストア中に free -m の出力を監視し、(仮想)メモリが枯渇していないか確認してみてください。

問題が何なのか分からないので難しい質問ですが、一般的にプラグインは復元を試みる前に対象サイトへインストールすべきでしょうか?それとも復元時にプラグインを自動的に取得して構築してくれるのでしょうか?

はい、インストールすべきです。復元処理では自動的には行われません。

ただし、これはあなたの問題の原因ではないと思います。なぜなら、復元処理は正しいデータベース構造(プラグイン固有の設定を含む)を自動的に整えてくれるからです。

4GB のメモリを搭載した新しい $20 の Lightsail インスタンスを作成しました。復元中に ‘free -m’ を監視しましたが、常に十分な空きメモリと利用可能なメモリがありました。

発生する具体的なエラーは、プラグインがインストールされているかどうかによって異なりますが、おそらく同じ根本原因によるものです。今回の場合、バックアップ前にプラグインはインストールしていませんでした。エラーには以下の 2 つのタイプがあります。

  1. PostgreSQL ログには、以下のようなエラーが多数表示されます。場合によっては文字位置 34、またはいくつかの場合では文字位置 41 で発生します。

discourse@discourse ERROR: relation “user_auth_tokens” does not exist at character 34

これらのエラーは、管理画面 > バックアップ > ログページには対応する出力が表示されず、これらのエラーが発生しても復元は数分間続きます。

  1. 2 つ目のエラーは、プラグインがインストールされているかどうかによって異なります。今回はプラグインをインストールしなかったため、Data Explorer に関するエラーが発生し、そこで完全に状況が悪化しました。

管理画面 > バックアップ > ログ:

[2019-12-07 07:38:34] CREATE INDEX
[2019-12-07 07:38:34] CREATE INDEX
[2019-12-07 07:38:34] ERROR: could not create unique index “index_plugin_store_rows_on_plugin_name_and_key”
[2019-12-07 07:38:34] DETAIL: Key (plugin_name, key)=(discourse-data-explorer, q:-6) is duplicated.
[2019-12-07 07:38:34] ERROR: current transaction is aborted, commands ignored until end of transaction block
[2019-12-07 07:38:34] ERROR: current transaction is aborted, commands ignored until end of transaction block
< 1000 回繰り返されて終了 >

また、PostgreSQL ログには以下のような対応する出力があります:

2019-12-07 07:38:34.718 UTC [8991] discourse@discourse LOG: duration: 165.427 ms statement: CREATE INDEX index_notifications_on_user_
id_and_topic_id_and_post_number ON public.notifications USING btree (user_id, topic_id, post_number);
2019-12-07 07:38:34.767 UTC [8991] discourse@discourse ERROR: could not create unique index “index_plugin_store_rows_on_plugin_name_an
d_key”
2019-12-07 07:38:34.767 UTC [8991] discourse@discourse DETAIL: Key (plugin_name, key)=(discourse-data-explorer, q:-6) is duplicated.
2019-12-07 07:38:34.767 UTC [8991] discourse@discourse STATEMENT: CREATE UNIQUE INDEX index_plugin_store_rows_on_plugin_name_and_key O
N public.plugin_store_rows USING btree (plugin_name, key);
2019-12-07 07:38:34.984 UTC [8991] discourse@discourse ERROR: current transaction is aborted, commands ignored until end of transactio
n block
2019-12-07 07:38:34.984 UTC [8991] discourse@discourse STATEMENT: CREATE INDEX index_policy_users_on_post_policy_id_and_user_id ON pub
lic.policy_users USING btree (post_policy_id, user_id);

#1 は致命的ではなく、インプレース復元による副作用だと考えられます。

バックアップを作成する前に、データエクスプローラーのクエリをすべて(エクスポートして)削除し、データエクスプローラープラグインを削除することを検討してください。

あるいは、plugin_store_rows テーブルの関連する内容を投稿してもらえますか?

実際には、(plugin_name, key) のペアが重複しているクエリが存在します。例えば q:-11 と q:-2 などですが、ID は一意です。これらの重複に特定のパターンは見当たりません。お気に入りのクエリであるなどという傾向もありません。

そのため、次のステップとして重複を削除し、バックアップを作成してから、そのバックアップから復元を試みる予定です。

SELECT id, plugin_name, key from plugin_store_rows
WHERE plugin_name = ‘discourse-data-explorer’
ORDER BY key

id plugin_name key
1138 discourse-data-explorer q:-1
1136 discourse-data-explorer q:-10
813 discourse-data-explorer q:10
1142 discourse-data-explorer q:-11
1397 discourse-data-explorer q:-11
825 discourse-data-explorer q:11
889 discourse-data-explorer q:13
1004 discourse-data-explorer q:14
1005 discourse-data-explorer q:15
1043 discourse-data-explorer q:17
1044 discourse-data-explorer q:18
514 discourse-data-explorer q:-2
1249 discourse-data-explorer q:-2
764 discourse-data-explorer q:2
1053 discourse-data-explorer q:21
1066 discourse-data-explorer q:22
1082 discourse-data-explorer q:23
1097 discourse-data-explorer q:24
1131 discourse-data-explorer q:26
1132 discourse-data-explorer q:27
1134 discourse-data-explorer q:28
1135 discourse-data-explorer q:29
775 discourse-data-explorer q:3
1137 discourse-data-explorer q:30
1140 discourse-data-explorer q:31
1141 discourse-data-explorer q:32
1143 discourse-data-explorer q:33
1149 discourse-data-explorer q:34
1155 discourse-data-explorer q:35
1156 discourse-data-explorer q:36
1157 discourse-data-explorer q:37
1158 discourse-data-explorer q:38
1161 discourse-data-explorer q:39
513 discourse-data-explorer q:-4
777 discourse-data-explorer q:4
1211 discourse-data-explorer q:40
1215 discourse-data-explorer q:41
1223 discourse-data-explorer q:42
1224 discourse-data-explorer q:43
1225 discourse-data-explorer q:44
1226 discourse-data-explorer q:45
1269 discourse-data-explorer q:46
1272 discourse-data-explorer q:47
1273 discourse-data-explorer q:48
1274 discourse-data-explorer q:49
1279 discourse-data-explorer q:50
1281 discourse-data-explorer q:51
1282 discourse-data-explorer q:52
1301 discourse-data-explorer q:53
1349 discourse-data-explorer q:54
1369 discourse-data-explorer q:55
1373 discourse-data-explorer q:56
1384 discourse-data-explorer q:57
1387 discourse-data-explorer q:58
1396 discourse-data-explorer q:59
1222 discourse-data-explorer q:-6
1348 discourse-data-explorer q:-6
781 discourse-data-explorer q:6
763 discourse-data-explorer q:-7
782 discourse-data-explorer q:7
515 discourse-data-explorer q:-8
791 discourse-data-explorer q:8
1139 discourse-data-explorer q:-9
798 discourse-data-explorer q:9
507 discourse-data-explorer q:_id

実際、重複を削除するにはどうすればよいですか?3つすべてが「system」に所有されているため、編集や削除ができません。

パターンが見つかりました。システム所有のクエリを実行すると重複が作成され、それが復元を破損させるようです。

クリーンなテストサイトでは再現できませんが、本番サイトでは一貫して発生します。本番環境のすべてのプラグインをテストサイトにインストールしましたが、依然として再現しません。

  1. 本番サイトの問題点を特定するにはどうすればよいですか?

  2. 重複クエリはシステムが所有しているため、どのように削除すればよいですか?sudo -u postgres psql discourse...を実行する必要がありますか?少し恐ろしく感じます。

バックアップを復元可能にするには、バックアップされた SQL ファイルから重複行を削除するとよいでしょう。

何らかの理由で開発用データベースにそのインデックスが欠落している可能性がありますか?